spurious errors on pod termination

[danwinship]

There's some sort of race/bad coordination in kubelet when pods are terminated, such that it keeps trying to do status checks even after it has started terminating the pod, often resulting in:

Feb 01 18:20:44 ci-prtest-5a37c28-15429-ig-n-qzmw origin-node[10940]: I0201 18:20:44.622016   10940 kubelet.go:1852] SyncLoop (DELETE, "api"): "dns-test-8a31e45e-077c-11e8-9376-0e8c3420a542_e2e-tests-dns-g9vhj(8a3a5941-077c-11e8-b172-42010a8e0005)"                                                                   
Feb 01 18:20:44 ci-prtest-5a37c28-15429-ig-n-qzmw origin-node[10940]: I0201 18:20:44.622162   10940 kubelet.go:1846] SyncLoop (REMOVE, "api"): "dns-test-8a31e45e-077c-11e8-9376-0e8c3420a542_e2e-tests-dns-g9vhj(8a3a5941-077c-11e8-b172-42010a8e0005)"                                                                   
Feb 01 18:20:44 ci-prtest-5a37c28-15429-ig-n-qzmw origin-node[10940]: W0201 18:20:44.688273   10940 docker_sandbox.go:340] failed to read pod IP from plugin/docker: NetworkPlugin cni failed on the status hook for pod "dns-test-8a31e45e-077c-11e8-9376-0e8c3420a542_e2e-tests-dns-g9vhj": Unexpected command output nsenter: cannot open /proc/49301/ns/net: No such file or directory
Feb 01 18:20:44 ci-prtest-5a37c28-15429-ig-n-qzmw origin-node[10940]: with error: exit status 1                                                                                                                                                                                                                           

While this doesn't seem to cause any actual problems, the log messages are spammy, and make it look like something has gone wrong.

Clayton says "Can you open a bug for that and assign it to Seth? I think it happens on every pod termination now."

[pravisankar]

This looks like existing bug: https://bugzilla.redhat.com/show_bug.cgi?id=1434950
cc: @dcbw

[dcbw]

Yeah, and it shouldn't be happening. Any way to get better node logs here? I tried to reproduce yesterday but could not.

[danwinship]

"Better node logs" as compared to what?

Note that you can click "View job in Jenkins" at the top of a test run and then "S3 artifacts" from there to get to the full origin-node.service logs. Eg, all 4 nodes on https://ci.openshift.redhat.com/jenkins/job/test_branch_origin_extended_conformance_gce/2380/s3/ are full of "failed to read pod IP" errors.

[dcbw]

Ah I was looking at the extended networking test logs which don't appear to have the node journals.

But also, we apparently run with --loglevel=4 now, not 5, so we lose a lot of useful log messages.

[dcbw]

So this is Kubelet being stupid. It will run StopPodSandbox() multiple times in parallel for the same sandbox. And dockershim's StopPodSanbox() itself calls GetPodSandboxStatus() which checks the IP and that's where the error is coming from. That's because there's a race where the first StopPodSandbox is in TearDownPod() (and thus the networkReady suppression code isn't triggered yet) and the second StopPodSandbox() then asks for the pod IP. Before that can run nsenter, TearDownPod() completes and the first StopPodSandbox() stops the sandbox container and destroys the netns. Then the second StopPodSanbox()'s GetPodSandboxStatus() finally gets around to running nsenter and fails.

[dcbw]

upstream fix: kubernetes/kubernetes#59301

[danwinship]

Ah I was looking at the extended networking test logs which don't appear to have the node journals.

They do, it's just not obvious where: artifacts/scripts/networking/logs/{subnet,multitenant,networkpolicy}/{nettest-master,nettest-node-1,nettest-node-2}/systemd.log.gz