Previous occurrence #13690

@gmarek is this in a normal e2e? In a soak env?

It's normal e2e.

@gmarek I mean, the context in which the failure was discovered -- previously this happened only in a soak env.

I'm trying to reproduce now.

Yup, I understand. It happened in our main test suite.

Ran this about 500 times so far in a loop w/o a failure

Wasn't able to repro today, will continue tomorrow.

Can we decorate logs (in a non-horrible way) to make a failure more visible? That is a viable answer

@thockin I was doing just that and found that the information is present in the logs in a log message related to the hosts file mount. Analyzing now, it looks like on the node where the flake happened, a little over of half the containers started with the podIP unknown.

I0201 06:19:08.157017    3382 kubelet.go:1157] Will create hosts mount for container:"dapi-container", podIP:: false

^^ example message

So, it looks like the underlying issue here is happening much more often than I personally thought. Will try to debug.

Nevermind, it looks like most of the containers without pod IP are infracontainers. I remember now that this is expected for the infra container.

Looks like it happened 4 times to actual containers on this node that flaked during e2e.

$ grep "hosts mount" ~/pod-flake.log  | grep "podIP::" | grep -v POD
I0201 06:17:53.642291    3382 kubelet.go:1157] Will create hosts mount for container:"kube-proxy", podIP:: false
I0201 06:19:08.157017    3382 kubelet.go:1157] Will create hosts mount for container:"dapi-container", podIP:: false
I0201 06:19:49.106935    3382 kubelet.go:1157] Will create hosts mount for container:"c", podIP:: false
I0201 06:20:49.107846    3382 kubelet.go:1157] Will create hosts mount for container:"hostexec", podIP:: false

This just happened again:

https://pantheon.corp.google.com/storage/browser/kubernetes-jenkins/logs/kubernetes-e2e-gce/10931/?project=kubernetes-jenkins

It happened again:
http://kubekins.dls.corp.google.com:8081/job/kubernetes-pull-build-test-e2e-gce/26572/testReport/junit/(root)/Kubernetes%20e2e%20suite/Downward_API_should_provide_pod_IP_as_an_env_var/

This is flaking 1 or 2 times per day on kubernetes-e2e-gce.

new occurrence: https://cloud.google.com/console/storage/kubernetes-jenkins/logs/kubernetes-e2e-gce/11020/

bumping to p0

@pmorie status on this?

@thockin fix PR has lgtm; running through jenkins now.

@thockin correction, PR has a regression for kube-managed /etc/hosts :-( we'll need to update it

I think I've figured out why this is flaking. Here's what I'm seeing locally and also what I've noticed from 1 of the GCE flakes:

1. Kubelet sync loop processes a new pod
2. Infra container is created
3. Actual container is created (and it has the pod IP available correctly)
4. Actual container fails to start for some reason
5. Next sync loop iteration results in a new container
6. New container is passed a pod IP of ""

This looks something like this in the logs (with lots of snipping):

kubelet.go:1203] container: e2e-tests-downward-api-57jz3/downward-api-53637d5a-db3a-11e5-8cef-001c42de2c3c/dapi-container podIP: "172.17.0.3" creating hosts mount: true
[snip]
manager.go:1881] Error running pod "downward-api-53637d5a-db3a-11e5-8cef-001c42de2c3c_e2e-tests-downward-api-57jz3(5363a626-db3a-11e5-82e5-001c42de2c3c)" container "dapi-container": runContainer: API error (500): Cannot start container 90cffa61d617ab4f98a3dc72f7549c5a5cb85487957a167e180f1747571a8b43: [8] System error: open /sys/fs/cgroup/cpu,cpuacct/system.slice/docker-90cffa61d617ab4f98a3dc72f7549c5a5cb85487957a167e180f1747571a8b43.scope/cpu.shares: no such file or directory
[snip]
kubelet.go:1203] container: e2e-tests-downward-api-57jz3/downward-api-53637d5a-db3a-11e5-8cef-001c42de2c3c/dapi-container podIP: "" creating hosts mount: false

@pmorie @ncdc - what's the status of this?

@wojtek-t I'm working on an e2e that captures the existing failure, hope to have a PR in the next day or so.

I was testing Paul's fix for this on Friday, but unfortunately the lack of #22607 in the tree resulted in a different error condition. Instead of failing because POD_IP was blank, it failed because the pod was marked as Failed and the container never ran.

@ncdc I think the problem was originated by relying on passing the pod IP to downstream functions through modifying the api.Pod object

The api.Pod object should be treated as read-only in most kubelet functions, and you cannot assume the object wouldn't be updated if you write to it.

@pmorie's PR (#22666) builds on top of this hack, so the getPodIP() function won't always return the correct IP. Having a one-line hack is one thing, but wrapping it to be a seemingly proper function makes me uncomfortable. Since DockerManager.SyncPod has the most up-to-date information about the pod IP, I think we should just pass that down the call stack. (Alternatively, we can always query the container runtime for the correct IP address, but IMO, that's too expensive)

The call stack that needs to be modified:

  -> containerRuntime.SyncPod
    -> dm.runContainerInPod
      -> kubelet.GenerateRunContainerOptions
        -> kubelet.makeMounts
          -> kubelet.makeHostsMount
        -> kubelet.makeEnvironmentVariables
          -> kubelet.podFieldSelectorRuntimeValue

/cc @kubernetes/sig-node, FYI.

@yujuhong cool, thanks for the detailed explanation. Where in SyncPod does the pod IP exist other than the line you linked above, which only gets called when the infra container is created?

If the infra container was not created in the same sync iteration, you should be able to get the pod IP from podStatus *kubecontainer.PodStatus, which was passed to the SyncPod()

Ok, so if we put if/else logic in for that check, then we can pass the pod IP around as needed, right?

Has anyone hit this recently? Afaik, it can be closed. I haven't seen it linked to anything recently.