Bug 1885717 - activeDeadlineSeconds DeadlineExceeded does not show terminated container statuses
Summary: activeDeadlineSeconds DeadlineExceeded does not show terminated container sta...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: OpenShift Container Platform
Classification: Red Hat
Component: Node
Version: 3.11.0
Hardware: Unspecified
OS: Unspecified
unspecified
low
Target Milestone: ---
: 4.8.0
Assignee: Harshal Patil
QA Contact: MinLi
URL:
Whiteboard:
Depends On:
Blocks: 1933094
TreeView+ depends on / blocked
 
Reported: 2020-10-06 19:33 UTC by W. Trevor King
Modified: 2021-07-27 22:33 UTC (History)
5 users (show)

Fixed In Version:
Doc Type: No Doc Update
Doc Text:
Clone Of:
Environment:
Last Closed: 2021-07-27 22:33:41 UTC
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)
oc adm node-logs ci-ln-5q356bk-f76d1-kggfd-worker-d-v9zxp # 4.6.0-fc.9 node logs (9.85 MB, text/plain)
2020-10-06 19:37 UTC, W. Trevor King
no flags Details
test.sh (reproducer, packaged as a script) (1.22 KB, text/plain)
2020-10-06 20:49 UTC, W. Trevor King
no flags Details


Links
System ID Private Priority Status Summary Last Updated
Github kubernetes kubernetes issues 88611 0 None open Container status is shown as running for SIGKILL-ed container 2021-02-03 09:08:59 UTC
Github openshift kubernetes pull 593 0 None open Bug 1885717: UPSTREAM: Sync completed pods until their containers have been terminated 2021-02-25 06:42:11 UTC
Red Hat Product Errata RHSA-2021:2438 0 None None None 2021-07-27 22:33:58 UTC

Description W. Trevor King 2020-10-06 19:33:06 UTC
Description of problem:

When a pod passes activeDeadlineSeconds and enters DeadlineExceeded, the pod status should list the terminated container statuses.

Version-Release number of selected component (if applicable):

Reproduced in 3.11 and 4.6.0-fc.9.

How reproducible: 100%

Steps to Reproduce:

  $ oc version
  Client Version: 4.5.11
  Server Version: 4.6.0-fc.9
  Kubernetes Version: v1.19.0+1fc699e
  $ cat test-pod.yaml
  apiVersion: v1
  kind: Pod
  metadata:
    name: test
  spec:
    activeDeadlineSeconds: 200
    terminationGracePeriodSeconds: 300
    containers:
    - args:
      - "600"
      command:
      - sleep
      image: docker.io/library/busybox
      imagePullPolicy: IfNotPresent
      name: test
      resources:
        requests:
          cpu: 10m
          memory: 10Mi
  $ oc -n wking apply -f test-pod.yaml
  pod/test created
  $ oc -n wking get -o yaml pod test | grep -A1000 '^status:'
  status:
    conditions:
    - lastProbeTime: null
      lastTransitionTime: "2020-10-06T18:06:08Z"
      status: "True"
      type: Initialized
    - lastProbeTime: null
      lastTransitionTime: "2020-10-06T18:06:13Z"
      status: "True"
      type: Ready
    - lastProbeTime: null
      lastTransitionTime: "2020-10-06T18:06:13Z"
      status: "True"
      type: ContainersReady
    - lastProbeTime: null
      lastTransitionTime: "2020-10-06T18:06:08Z"
      status: "True"
      type: PodScheduled
    containerStatuses:
    - containerID: cri-o://1605744cd4424473693efadd5400b483eda3ef11a4274fe49989d98df28dc266
      image: docker.io/library/busybox:latest
      imageID: docker.io/library/busybox@sha256:2ca5e69e244d2da7368f7088ea3ad0653c3ce7aaccd0b8823d11b0d5de956002
      lastState: {}
      name: test
      ready: true
      restartCount: 0
      started: true
      state:
        running:
          startedAt: "2020-10-06T18:06:12Z"
    hostIP: 10.0.32.2
    phase: Running
    podIP: 10.129.2.14
    podIPs:
    - ip: 10.129.2.14
    qosClass: Burstable
    startTime: "2020-10-06T18:06:08Z"
  $ # wait for a while
  $ oc -n wking get -o yaml pod test | grep -A1000 '^status:'
  status:
    containerStatuses:
    - containerID: cri-o://1605744cd4424473693efadd5400b483eda3ef11a4274fe49989d98df28dc266
      image: docker.io/library/busybox:latest
      imageID: docker.io/library/busybox@sha256:2ca5e69e244d2da7368f7088ea3ad0653c3ce7aaccd0b8823d11b0d5de956002
      lastState: {}
      name: test
      ready: false
      restartCount: 0
      state:
        running:
          startedAt: "2020-10-06T18:06:12Z"
    message: Pod was active on the node longer than the specified deadline
    phase: Failed
    podIP: 10.129.2.14
    podIPs:
    - ip: 10.129.2.14
    qosClass: Burstable
    reason: DeadlineExceeded
    startTime: "2020-10-06T18:06:08Z"

Expected results:

I expected to have a terminated state for the container, not:

      state:
        running:

On 3.11, the behavior is similar, but there are no status.containers at all:

  $ oc -n wking get -o yaml pod test | grep -A1000 '^status:'
  status:
    message: Pod was active on the node longer than the specified deadline
    phase: Failed
    reason: DeadlineExceeded
    startTime: "2020-10-06T17:21:49Z"

The addition of containers in more recent kubelets may be due to [1], but no version seems to expose the terminated container status.

Additional info:

Seems to be tracked upstream in [2].

[1]: https://github.com/kubernetes/kubernetes/pull/65567
[2]: https://github.com/kubernetes/kubernetes/issues/88611

Comment 1 W. Trevor King 2020-10-06 19:37:07 UTC
Created attachment 1719481 [details]
oc adm node-logs ci-ln-5q356bk-f76d1-kggfd-worker-d-v9zxp # 4.6.0-fc.9 node logs

Comment 2 Ryan Phillips 2020-10-06 20:14:06 UTC
I tested this with an upstream local-up-cluster [master f30d6a463d], and can reproduce the issue. The pod goes into DeadlineExceeded and did not go into Terminated state after 15 minutes. Notably, the process has been terminated on the machine; however, the state of the pod does not get updated.

Comment 3 W. Trevor King 2020-10-06 20:49:40 UTC
Created attachment 1719502 [details]
test.sh (reproducer, packaged as a script)

In case it helps, here's comment 0's reproducer packaged up as a script with more precise timing on the polling.  For example:

$ ./test.sh
namespace/timeout-test created
pod/test created
2020-10-06T20:39:22Z pod=Running container=running
...
2020-10-06T20:41:55Z pod=Running container=running
2020-10-06T20:42:26Z pod=Failed container=running
...
2020-10-06T20:47:33Z pod=Failed container=running
pod "test" deleted
namespace "timeout-test" deleted

That's transitioning to Failed between 3m and 3.5m post-creation, so between 180s and 210s, which matches the 200 default for the script's activeDeadlineSeconds.  Then it runs for another 5+m, past any remaining terminationGracePeriodSeconds with no further changes (although 'sleep' should respond quickly to TERM and not exercise terminationGracePeriodSeconds).

Comment 5 Ryan Phillips 2020-10-07 21:51:28 UTC
I looked at this more today. ActiveDeadline is an internal eviction handler. It works by setting the API PodStatus to failed and lets the kubelet syncpod reconcile loop kill the pod. The way that it is written, it skips over entire sections of container eventing logic, which would include the termination events.

In my testing, the pod does terminate within the configured grace period, and it does set a status to DeadlineExceeded. DeadlineExceeded is extremely similar to an evicted pods. 

This is something we can certainly improve; however, I do not believe this is blocking anything right now and may get pushed back.

Comment 6 W. Trevor King 2020-10-07 22:31:43 UTC
> ...I do not believe this is blocking anything right now and may get pushed back.

What it blocks is any attempt to explain the final container statuses.  Which containers failed?  What were their exit codes?  That makes it hard for consumers like ci-operator to say things like "the test container timed out".  All it can say today is [1]:

  DeadlineExceeded Pod was active on the node longer than the specified deadline

[1]: https://github.com/openshift/ci-tools/pull/1257/files#diff-1fdcddf6e165a35cfcd5978c7596ababR30

Comment 7 Ryan Phillips 2020-10-23 16:29:23 UTC
Harshal: Could you take a look?

Comment 15 W. Trevor King 2021-02-04 03:35:04 UTC
Hours after Harshal opened an upstream bug [1], we already have an upstream PR [2].  Love it :)

[1]: https://github.com/kubernetes/kubernetes/issues/98718
[2]: https://github.com/kubernetes/kubernetes/pull/98742

Comment 18 MinLi 2021-03-02 09:54:05 UTC
verified on version : 4.8.0-0.nightly-2021-03-01-143026

status:
  containerStatuses:
  - containerID: cri-o://0b9f86da4fb455553673c558d7f6b5332aa9920ef68b3e694d5f02ad5cbf31e5
    image: docker.io/library/busybox:latest
    imageID: docker.io/library/busybox@sha256:74e4a68dfba6f40b01787a3876cc1be0fb1d9025c3567cf8367c659f2187234f
    lastState: {}
    name: test
    ready: false
    restartCount: 0
    state:
      terminated:
        containerID: cri-o://0b9f86da4fb455553673c558d7f6b5332aa9920ef68b3e694d5f02ad5cbf31e5
        exitCode: 137
        finishedAt: "2021-03-02T09:23:49Z"
        reason: Error
        startedAt: "2021-03-02T09:15:34Z"
  message: Pod was active on the node longer than the specified deadline
  phase: Failed
  podIP: 10.128.2.153
  podIPs:
  - ip: 10.128.2.153
  qosClass: Burstable
  reason: DeadlineExceeded
  startTime: "2021-03-02T09:15:29Z"

Comment 21 errata-xmlrpc 2021-07-27 22:33:41 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (Moderate: OpenShift Container Platform 4.8.2 bug fix and security update), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHSA-2021:2438


Note You need to log in before you can comment on or make changes to this bug.