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
Created attachment 1719481 [details] oc adm node-logs ci-ln-5q356bk-f76d1-kggfd-worker-d-v9zxp # 4.6.0-fc.9 node logs
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.
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).
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.
> ...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
Harshal: Could you take a look?
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
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"
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