Fix Container exit message lost due to FallbackToLogsOnError is not compatible with ContainerCannotRun #81280

yqwang-ms · 2019-08-12T08:08:30Z

What type of PR is this?
/kind bug

What this PR does / why we need it:
Bug: FallbackToLogsOnError is not compatiable with ContainerCannotRun.
If a container cannot even be started, such as due to docker run parameters incorrect (like below example, unknown linux capability), it certainly does not have logs, so in this case, we should not override the exit message got from dockerd (like below example, "unknown linux capability"), to be "Error on reading termination message from logs". Otherwise, the truely useful exit message will be lost.

Reproduce Steps:
Submit below Pod:

apiVersion: v1
kind: Pod
metadata:
  name: pe12
spec:
  restartPolicy: Never
  containers:
  - name: ubuntu
    image: ubuntu:trusty
    command: ["sh", "-c", "sleep 1 && exit 0"]
    securityContext:
      capabilities:
        add:
        - CAP_DAC_READ_SEARCHXXX
    terminationMessagePolicy: FallbackToLogsOnError

Pod failed without useful info:
We only have info "Error on reading termination message from logs"

{
  "kind": "Pod",
  "apiVersion": "v1",
  "metadata": {
    "name": "pe12",
    "namespace": "default",
    "selfLink": "/api/v1/namespaces/default/pods/pe12",
    "uid": "8918753c-bcd6-11e9-bcf8-000d3af801a9",
    "resourceVersion": "20357386",
    "creationTimestamp": "2019-08-12T07:55:22Z"
  },
  "spec": {
    "volumes": [
      {
        "name": "default-token-kqww5",
        "secret": {
          "secretName": "default-token-kqww5",
          "defaultMode": 420
        }
      }
    ],
    "containers": [
      {
        "name": "ubuntu",
        "image": "ubuntu:trusty",
        "command": [
          "sh",
          "-c",
          "sleep 1 \u0026\u0026 exit 0"
        ],
        "resources": {
          
        },
        "volumeMounts": [
          {
            "name": "default-token-kqww5",
            "readOnly": true,
            "mountPath": "/var/run/secrets/kubernetes.io/serviceaccount"
          }
        ],
        "terminationMessagePath": "/dev/termination-log",
        "terminationMessagePolicy": "FallbackToLogsOnError",
        "imagePullPolicy": "IfNotPresent",
        "securityContext": {
          "capabilities": {
            "add": [
              "CAP_DAC_READ_SEARCHXXX"
            ]
          },
          "procMount": "Default"
        }
      }
    ],
    "restartPolicy": "Never",
    "terminationGracePeriodSeconds": 30,
    "dnsPolicy": "ClusterFirst",
    "serviceAccountName": "default",
    "serviceAccount": "default",
    "nodeName": "minikube",
    "securityContext": {
      
    },
    "schedulerName": "default-scheduler",
    "tolerations": [
      {
        "key": "node.kubernetes.io/not-ready",
        "operator": "Exists",
        "effect": "NoExecute",
        "tolerationSeconds": 300
      },
      {
        "key": "node.kubernetes.io/unreachable",
        "operator": "Exists",
        "effect": "NoExecute",
        "tolerationSeconds": 300
      }
    ],
    "priority": 0,
    "enableServiceLinks": true
  },
  "status": {
    "phase": "Failed",
    "conditions": [
      {
        "type": "Initialized",
        "status": "True",
        "lastProbeTime": null,
        "lastTransitionTime": "2019-08-12T07:55:22Z"
      },
      {
        "type": "Ready",
        "status": "False",
        "lastProbeTime": null,
        "lastTransitionTime": "2019-08-12T07:55:22Z",
        "reason": "ContainersNotReady",
        "message": "containers with unready status: [ubuntu]"
      },
      {
        "type": "ContainersReady",
        "status": "False",
        "lastProbeTime": null,
        "lastTransitionTime": "2019-08-12T07:55:22Z",
        "reason": "ContainersNotReady",
        "message": "containers with unready status: [ubuntu]"
      },
      {
        "type": "PodScheduled",
        "status": "True",
        "lastProbeTime": null,
        "lastTransitionTime": "2019-08-12T07:55:22Z"
      }
    ],
    "hostIP": "10.169.8.232",
    "podIP": "172.17.0.6",
    "startTime": "2019-08-12T07:55:22Z",
    "containerStatuses": [
      {
        "name": "ubuntu",
        "state": {
          "terminated": {
            "exitCode": 128,
            "reason": "ContainerCannotRun",
            "message": "Error on reading termination message from logs: failed to open log file \"/var/log/pods/default_pe12_8918753c-bcd6-11e9-bcf8-000d3af801a9/ubuntu/0.log\": open /var/log/pods/default_pe12_8918753c-bcd6-11e9-bcf8-000d3af801a9/ubuntu/0.log: no such file or directory",
            "startedAt": "2019-08-12T07:55:23Z",
            "finishedAt": "2019-08-12T07:55:23Z",
            "containerID": "docker://b457ceac28cf1ea70b1699ada8c684e73b62f535bf4abf2f7ad08e5f567f51d5"
          }
        },
        "lastState": {
          
        },
        "ready": false,
        "restartCount": 0,
        "image": "ubuntu:trusty",
        "imageID": "docker-pullable://ubuntu@sha256:f961d3d101e66017fc6f0a63ecc0ff15d3e7b53b6a0ac500cd1619ded4771bd6",
        "containerID": "docker://b457ceac28cf1ea70b1699ada8c684e73b62f535bf4abf2f7ad08e5f567f51d5"
      }
    ],
    "qosClass": "BestEffort"
  }
}

If the FallbackToLogsOnError is removed, and submit the Pod again, then we can get useful info:
"Linux spec capabilities: Unknown capability to add"

{
  "kind": "Pod",
  "apiVersion": "v1",
  "metadata": {
    "name": "pe4",
    "namespace": "default",
    "selfLink": "/api/v1/namespaces/default/pods/pe4",
    "uid": "3d52669f-bcc7-11e9-bcf8-000d3af801a9",
    "resourceVersion": "20348936",
    "creationTimestamp": "2019-08-12T06:05:52Z"
  },
  "spec": {
    "volumes": [
      {
        "name": "default-token-kqww5",
        "secret": {
          "secretName": "default-token-kqww5",
          "defaultMode": 420
        }
      }
    ],
    "containers": [
      {
        "name": "ubuntu",
        "image": "ubuntu:trusty",
        "command": [
          "sh",
          "-c",
          "sleep 1 \u0026\u0026 exit 0"
        ],
        "resources": {
          
        },
        "volumeMounts": [
          {
            "name": "default-token-kqww5",
            "readOnly": true,
            "mountPath": "/var/run/secrets/kubernetes.io/serviceaccount"
          }
        ],
        "terminationMessagePath": "/dev/termination-log",
        "terminationMessagePolicy": "File",
        "imagePullPolicy": "IfNotPresent",
        "securityContext": {
          "capabilities": {
            "add": [
              "CAP_DAC_READ_SEARCHXXX"
            ]
          },
          "procMount": "Default"
        }
      }
    ],
    "restartPolicy": "Never",
    "terminationGracePeriodSeconds": 30,
    "dnsPolicy": "ClusterFirst",
    "serviceAccountName": "default",
    "serviceAccount": "default",
    "nodeName": "minikube",
    "securityContext": {
      
    },
    "schedulerName": "default-scheduler",
    "tolerations": [
      {
        "key": "node.kubernetes.io/not-ready",
        "operator": "Exists",
        "effect": "NoExecute",
        "tolerationSeconds": 300
      },
      {
        "key": "node.kubernetes.io/unreachable",
        "operator": "Exists",
        "effect": "NoExecute",
        "tolerationSeconds": 300
      }
    ],
    "priority": 0,
    "enableServiceLinks": true
  },
  "status": {
    "phase": "Failed",
    "conditions": [
      {
        "type": "Initialized",
        "status": "True",
        "lastProbeTime": null,
        "lastTransitionTime": "2019-08-12T06:05:52Z"
      },
      {
        "type": "Ready",
        "status": "False",
        "lastProbeTime": null,
        "lastTransitionTime": "2019-08-12T06:05:52Z",
        "reason": "ContainersNotReady",
        "message": "containers with unready status: [ubuntu]"
      },
      {
        "type": "ContainersReady",
        "status": "False",
        "lastProbeTime": null,
        "lastTransitionTime": "2019-08-12T06:05:52Z",
        "reason": "ContainersNotReady",
        "message": "containers with unready status: [ubuntu]"
      },
      {
        "type": "PodScheduled",
        "status": "True",
        "lastProbeTime": null,
        "lastTransitionTime": "2019-08-12T06:05:52Z"
      }
    ],
    "hostIP": "10.169.8.232",
    "podIP": "172.17.0.6",
    "startTime": "2019-08-12T06:05:52Z",
    "containerStatuses": [
      {
        "name": "ubuntu",
        "state": {
          "terminated": {
            "exitCode": 128,
            "reason": "ContainerCannotRun",
            "message": "linux spec capabilities: Unknown capability to add: \"CAP_CAP_DAC_READ_SEARCHXXX\"",
            "startedAt": "2019-08-12T06:05:53Z",
            "finishedAt": "2019-08-12T06:05:53Z",
            "containerID": "docker://a3375cbb0eb16f40f47624b394313128d92da847e528e16705c0fe0d034b6c61"
          }
        },
        "lastState": {
          
        },
        "ready": false,
        "restartCount": 0,
        "image": "ubuntu:trusty",
        "imageID": "docker-pullable://ubuntu@sha256:f961d3d101e66017fc6f0a63ecc0ff15d3e7b53b6a0ac500cd1619ded4771bd6",
        "containerID": "docker://a3375cbb0eb16f40f47624b394313128d92da847e528e16705c0fe0d034b6c61"
      }
    ],
    "qosClass": "BestEffort"
  }
}

Which issue(s) this PR fixes:

Fixes # NO See issue above.

Special notes for your reviewer:

Does this PR introduce a user-facing change?:

If container fails because ContainerCannotRun, do not utilize the FallbackToLogsOnError TerminationMessagePolicy, as it masks more useful logs.

Additional documentation e.g., KEPs (Kubernetes Enhancement Proposals), usage docs, etc.:

k8s-ci-robot · 2019-08-12T08:08:37Z

Hi @yqwang-ms. Thanks for your PR.

I'm waiting for a kubernetes member to verify that this patch is reasonable to test. If it is, they should reply with /ok-to-test on its own line. Until that is done, I will not automatically test new commits in this PR, but the usual testing commands by org members will still work. Regular contributors should join the org to skip this step.

Once the patch is verified, the new status will be reflected by the ok-to-test label.

I understand the commands that are listed here.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

…ompatible with ContainerCannotRun

yqwang-ms · 2019-08-12T08:19:53Z

/assign @dchen1107

yqwang-ms · 2019-08-12T08:44:33Z

/assign @sjenning
/assign @derekwaynecarr

Could you please take a look at this small fix when you free? :)
Or could you please tell me what should I do next?
Thanks!

mattjmcnaughton

Thanks for your detailed pr - especially the detailed reproduction use case :)

This change makes sense to me :)
/lgtm

Could I trouble you to update your release note? I don't find ContainerCannotRun should not FallbackToLogsOnError to be particularly descriptive of the change you're making. What about something like If container fails because ContainerCannotRun, do not utilize the FallbackToLogsOnError TerminationMessagePolicy, as it masks more useful logs.

mattjmcnaughton · 2019-08-12T12:46:54Z

pkg/kubelet/kuberuntime/kuberuntime_container.go

 			if len(tMessage) != 0 {
-				cStatus.Message = tMessage
+				if len(cStatus.Message) != 0 {


Can you explain a little more about this change? I'm not totally following how it relates to the overall change you are describing in your pr.

Thanks for your review.
You are right, strictly speaking, it should not belong to this PR, however, in more general sense, it can prevent future useful info being lost.

For example, kubelet failed to read the termination file which may due to a reason described in dockerd's container error message.

So the principle here is that, discard exit info ONLY if we can ensure it is useless or duplicated.

For this case, we cannot ensure that dockerd's container error message is useless given "failed to read the termination file" or even we successfully read the file (because we also donot know if the dockerd's container error message is the root cause of the just read content).

So, for simplicity, I just append the error message, instead of one replace another.

It is just my preference, and TBD, we can disscus on it. :)

(Release note also updated)

mattjmcnaughton · 2019-08-12T12:50:03Z

/ok-to-test

yqwang-ms · 2019-08-12T15:06:19Z

/retest

yqwang-ms · 2019-08-14T08:35:12Z

@sjenning @derekwaynecarr Could you please take a look at this small fix? :)

yqwang-ms · 2019-08-16T11:41:37Z

Pinging @sjenning @derekwaynecarr , PTAL

yqwang-ms · 2019-08-26T05:54:56Z

/unassign @dchen1107
/unassign @sjenning
/unassign @derekwaynecarr

/assign @Random-Liu
/assign @tallclair
/assign @yujuhong

Because no responses from bot suggested approvers, could you please kindly take a look at this small fix when you free? :)
This issues really cause the failed pod hard to debug.
Thanks!

yqwang-ms · 2019-09-06T07:01:02Z

Pinging @Random-Liu and @tallclair , PTAL

tallclair · 2019-09-11T22:49:27Z

pkg/kubelet/kuberuntime/kuberuntime_container.go

+				if len(cStatus.Message) != 0 {
+					cStatus.Message += ": "
+				}
+				cStatus.Message += tMessage


Is it possible for cStatus.Message to grow infinitely, or do we reset it each time this function is called?

Thanks for the review.

I can confirm that cStatus.Message will NOT grow infinitely, given that getPodContainerStatuses is not stateful for the cStatus.Message (and it is by design should not be stateful), so that cStatus.Message will NOT accumulated.

We can prove this in details, please check:

The background is that cStatus.Message will only be updated in 2 places:

Note the cStatus.Message is just string instead of *string

kubernetes/pkg/kubelet/container/runtime.go

Line 314 in f82be3d

Message string

cStatus.Message in line 421 can only come from above toKubeContainerStatus in the same getPodContainerStatuses func:

kubernetes/pkg/kubelet/kuberuntime/kuberuntime_container.go

Line 401 in f82be3d

cStatus := toKubeContainerStatus(status, m.runtimeName)

In the getPodContainerStatuses, it will only init the cStatus.Message from runtime container message:

kubernetes/pkg/kubelet/kuberuntime/kuberuntime_container.go

Line 459 in f82be3d

cStatus.Message = status.Message

The runtime container message can only come directly from the underlay runtime:

kubernetes/pkg/kubelet/dockershim/docker_container.go

Line 400 in f82be3d

message = r.State.Error

The runtime container message will NOT from the cStatus.Message. So, the cStatus.Message will only be appended at most once by:

kubernetes/pkg/kubelet/kuberuntime/kuberuntime_container.go

Lines 421 to 426 in f82be3d

if len(tMessage) != 0 {

if len(cStatus.Message) != 0 {

cStatus.Message += ": "

}

cStatus.Message += tMessage

}

So the cStatus.Message will NOT grow infinitely.

Overall, the cStatus.Message is composed from 2 parts, first part is the runtime container message, see steps 2-4, and second part is TerminationMessage from:

kubernetes/pkg/kubelet/kuberuntime/kuberuntime_container.go

Line 408 in f82be3d

tMessage, checkLogs := getTerminationMessage(status, annotatedInfo.TerminationMessagePath, fallbackToLogs)

So, no more chars in the cStatus.Message.

Kindly ping @tallclair , PTAL

Any comments for this? :)

tallclair · 2019-10-08T20:54:37Z

/lgtm
/approve

k8s-ci-robot · 2019-10-08T20:55:10Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: tallclair, yqwang-ms

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

~~pkg/kubelet/OWNERS~~ [tallclair]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

Fix Container exit message lost due to FallbackToLogsOnError is not compatible with ContainerCannotRun

k8s-ci-robot added the needs-ok-to-test Indicates a PR that requires an org member to verify it is safe to test. label Aug 12, 2019

k8s-ci-robot requested review from derekwaynecarr and sjenning August 12, 2019 08:09

k8s-ci-robot added area/kubelet sig/node Categorizes an issue or PR as relevant to SIG Node. and removed needs-sig Indicates an issue or PR lacks a `sig/foo` label and requires one. labels Aug 12, 2019

Fix Container exit message lost due to FallbackToLogsOnError is not c…

f82be3d

…ompatible with ContainerCannotRun

yqwang-ms force-pushed the yqwang/exitmsglost branch from d450e35 to f82be3d Compare August 12, 2019 08:16

k8s-ci-robot assigned dchen1107 Aug 12, 2019

k8s-ci-robot assigned derekwaynecarr and sjenning Aug 12, 2019

mattjmcnaughton approved these changes Aug 12, 2019

View reviewed changes

k8s-ci-robot assigned mattjmcnaughton Aug 12, 2019

k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Aug 12, 2019

k8s-ci-robot added ok-to-test Indicates a non-member PR verified by an org member that is safe to test. and removed needs-ok-to-test Indicates a PR that requires an org member to verify it is safe to test. labels Aug 12, 2019

k8s-ci-robot assigned Random-Liu, tallclair and yujuhong and unassigned sjenning, derekwaynecarr and dchen1107 Aug 26, 2019

tallclair reviewed Sep 11, 2019

View reviewed changes

k8s-ci-robot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Oct 8, 2019

k8s-ci-robot merged commit 4cff1c3 into kubernetes:master Oct 8, 2019

k8s-ci-robot added this to the v1.17 milestone Oct 8, 2019

yqwang-ms deleted the yqwang/exitmsglost branch October 9, 2019 02:29

ohsewon pushed a commit to ohsewon/kubernetes that referenced this pull request Oct 16, 2019

Merge pull request kubernetes#81280 from yqwang-ms/yqwang/exitmsglost

41c2a0a

Fix Container exit message lost due to FallbackToLogsOnError is not compatible with ContainerCannotRun

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix Container exit message lost due to FallbackToLogsOnError is not compatible with ContainerCannotRun #81280

Fix Container exit message lost due to FallbackToLogsOnError is not compatible with ContainerCannotRun #81280

yqwang-ms commented Aug 12, 2019 •

edited

Loading

k8s-ci-robot commented Aug 12, 2019

yqwang-ms commented Aug 12, 2019

yqwang-ms commented Aug 12, 2019

mattjmcnaughton left a comment

mattjmcnaughton Aug 12, 2019

yqwang-ms Aug 12, 2019 •

edited

Loading

mattjmcnaughton commented Aug 12, 2019

yqwang-ms commented Aug 12, 2019

yqwang-ms commented Aug 14, 2019

yqwang-ms commented Aug 16, 2019

yqwang-ms commented Aug 26, 2019

yqwang-ms commented Sep 6, 2019

tallclair Sep 11, 2019

yqwang-ms Sep 12, 2019 •

edited

Loading

yqwang-ms Sep 16, 2019

yqwang-ms Sep 19, 2019

tallclair commented Oct 8, 2019

k8s-ci-robot commented Oct 8, 2019

	if len(tMessage) != 0 {
	if len(cStatus.Message) != 0 {
	cStatus.Message += ": "
	}
	cStatus.Message += tMessage
	}

Fix Container exit message lost due to FallbackToLogsOnError is not compatible with ContainerCannotRun #81280

Fix Container exit message lost due to FallbackToLogsOnError is not compatible with ContainerCannotRun #81280

Conversation

yqwang-ms commented Aug 12, 2019 • edited Loading

k8s-ci-robot commented Aug 12, 2019

yqwang-ms commented Aug 12, 2019

yqwang-ms commented Aug 12, 2019

mattjmcnaughton left a comment

Choose a reason for hiding this comment

mattjmcnaughton Aug 12, 2019

Choose a reason for hiding this comment

yqwang-ms Aug 12, 2019 • edited Loading

Choose a reason for hiding this comment

mattjmcnaughton commented Aug 12, 2019

yqwang-ms commented Aug 12, 2019

yqwang-ms commented Aug 14, 2019

yqwang-ms commented Aug 16, 2019

yqwang-ms commented Aug 26, 2019

yqwang-ms commented Sep 6, 2019

tallclair Sep 11, 2019

Choose a reason for hiding this comment

yqwang-ms Sep 12, 2019 • edited Loading

Choose a reason for hiding this comment

yqwang-ms Sep 16, 2019

Choose a reason for hiding this comment

yqwang-ms Sep 19, 2019

Choose a reason for hiding this comment

tallclair commented Oct 8, 2019

k8s-ci-robot commented Oct 8, 2019

yqwang-ms commented Aug 12, 2019 •

edited

Loading

yqwang-ms Aug 12, 2019 •

edited

Loading

yqwang-ms Sep 12, 2019 •

edited

Loading