Flakey sidecar container test

[bobcatfish]

Expected Behavior

TestSidecarTaskSupport/A_sidecar_that_runs_forever_is_terminated_when_Steps_complete should reliably pass unless there is a bug

Actual Behavior

TestSidecarTaskSupport/A_sidecar_that_runs_forever_is_terminated_when_Steps_complete failed on #2652 with this error in the logs:

=== RUN   TestSidecarTaskSupport/A_sidecar_that_runs_forever_is_terminated_when_Steps_complete
    TestSidecarTaskSupport/A_sidecar_that_runs_forever_is_terminated_when_Steps_complete: sidecar_test.go:82: Creating Task "sidecar-test-task-0"
    TestSidecarTaskSupport/A_sidecar_that_runs_forever_is_terminated_when_Steps_complete: sidecar_test.go:87: Creating TaskRun "sidecar-test-task-run-0"
    TestSidecarTaskSupport/A_sidecar_that_runs_forever_is_terminated_when_Steps_complete: sidecar_test.go:111: Error waiting for Pod "sidecar-test-task-run-0-pod-f47gv" to terminate both the primary and sidecar containers: timed out waiting for the condition
    TestSidecarTaskSupport/A_sidecar_that_runs_forever_is_terminated_when_Steps_complete: sidecar_test.go:132: Sidecar container has a nil Terminated status but non-nil is expected.
    TestSidecarTaskSupport/A_sidecar_that_runs_forever_is_terminated_when_Steps_complete: sidecar_test.go:140: Either the primary or sidecar containers did not terminate
=== RUN   TestSidecarTaskSupport/A_sidecar_that_terminates_early_does_not_cause_problems_running_Steps
    TestSidecarTaskSupport/A_sidecar_that_terminates_early_does_not_cause_problems_running_Steps: sidecar_test.go:82: Creating Task "sidecar-test-task-1"
    TestSidecarTaskSupport/A_sidecar_that_terminates_early_does_not_cause_problems_running_Steps: sidecar_test.go:87: Creating TaskRun "sidecar-test-task-run-1"
--- FAIL: TestSidecarTaskSupport (610.28s)

In the k8s events you can see:

arendelle-mtdlj    27m         Normal    Scheduled                 pod/sidecar-test-task-run-0-pod-f47gv                                     Successfully assigned arendelle-mtdlj/sidecar-test-task-run-0-pod-f47gv to gke-tpipeline-e2e-cls126-default-pool-c2eb233a-b7p5
arendelle-mtdlj    27m         Normal    Pulled                    pod/sidecar-test-task-run-0-pod-f47gv                                     Container image "gcr.io/tekton-prow-9/tpipeline-e2e-img/entrypoint-bff0a22da108bc2f16c818c97641a296@sha256:4442c3261e3cdadd00c9d3581cccd00a8d68af741767611d405f2e4c0f36a660" already present on machine
arendelle-mtdlj    27m         Normal    Created                   pod/sidecar-test-task-run-0-pod-f47gv                                     Created container place-tools
arendelle-mtdlj    27m         Normal    Started                   pod/sidecar-test-task-run-0-pod-f47gv                                     Started container place-tools
arendelle-mtdlj    27m         Normal    Pulling                   pod/sidecar-test-task-run-0-pod-f47gv                                     Pulling image "busybox:1.31.0-musl"
arendelle-mtdlj    27m         Normal    Pulled                    pod/sidecar-test-task-run-0-pod-f47gv                                     Successfully pulled image "busybox:1.31.0-musl"
arendelle-mtdlj    27m         Normal    Created                   pod/sidecar-test-task-run-0-pod-f47gv                                     Created container step-primary
arendelle-mtdlj    27m         Normal    Started                   pod/sidecar-test-task-run-0-pod-f47gv                                     Started container step-primary
arendelle-mtdlj    27m         Normal    Pulled                    pod/sidecar-test-task-run-0-pod-f47gv                                     Container image "busybox:1.31.0-musl" already present on machine
arendelle-mtdlj    26m         Normal    Created                   pod/sidecar-test-task-run-0-pod-f47gv                                     Created container sidecar-sidecar-container
arendelle-mtdlj    27m         Normal    Started                   pod/sidecar-test-task-run-0-pod-f47gv                                     Started container sidecar-sidecar-container
arendelle-mtdlj    27m         Normal    Killing                   pod/sidecar-test-task-run-0-pod-f47gv                                     Container sidecar-sidecar-container definition changed, will be restarted
arendelle-mtdlj    26m         Normal    Pulling                   pod/sidecar-test-task-run-0-pod-f47gv                                     Pulling image "tianon/true@sha256:009cce421096698832595ce039aa13fa44327d96beedb84282a69d3dbcf5a81b"
arendelle-mtdlj    26m         Normal    Pulled                    pod/sidecar-test-task-run-0-pod-f47gv                                     Successfully pulled image "tianon/true@sha256:009cce421096698832595ce039aa13fa44327d96beedb84282a69d3dbcf5a81b"
arendelle-mtdlj    26m         Warning   Failed                    pod/sidecar-test-task-run-0-pod-f47gv                                     Error: failed to start container "sidecar-sidecar-container": Error response from daemon: OCI runtime create failed: container_linux.go:349: starting container process caused "exec: \"sh\": executable file not found in $PATH": unknown

Particularly interesting:

Error: failed to start container "sidecar-sidecar-container": Error response from daemon: OCI runtime create failed: container_linux.go:349: starting container process caused "exec: \"sh\": executable file not found in $PATH": unknown

Additional Info

Looks like #1253 had this same problem - looks like it's some kind of race condition related to switching to the nop image perhaps? (Or this is a red herring and this is just what happens when we kill the sidecar)

[jlpettersson]

Also #1819

[GregDritschler]

I looked at some build logs where this test failed and noticed that the sidecar test pod has a status of RunContainerError:

arendelle-lvq6p    pod/sidecar-test-task-run-0-pod-knt5v                                0/2     RunContainerError    1          30m

In logs where the test passed, the pod has a status of Error. The difference is that RunContainerError appears to be used with container status waiting rather than terminated.

There isn't a lot of information out there about these different reasons and why you might get one vs another. I tried looking at the Kubernetes code but I'm not familiar enough with it to understand what might cause one vs the other.

I've not been able to reproduce this problem myself after running the test on my own clusters dozens of times. When I run it on my IBM cluster, the pod has status StartError instead of Error but the container status still is terminated. When I run it on my GKE cluster, the pod has status ContainerCannotRun but the container status still is terminated.

If someone is able to reproduce it, it would be interesting to display the pod and confirm the sidecar container is in waiting state. Also wait and see if Kubernetes does anything with the pod or it just sits there like that.

P.S. The message

Error: failed to start container "sidecar-sidecar-container": Error response from daemon: OCI runtime create failed: container_linux.go:349: starting container process caused "exec: \"sh\": executable file not found in $PATH": unknown

appears when the test passes as well. Somehow Kubernetes is reacting differently to it sometimes.

[vincent-pli]

Error: failed to start container "sidecar-sidecar-container": Error response from daemon: OCI runtime create failed: container_linux.go:349: starting container process caused "exec: \"sh\": executable file not found in $PATH": unknown

Will always be there, try any command with tianon/true will cause similar exception, since there is nothing in that image, no $PATH, no filesystem.

[vdemeester]

@bobcatfish is this still an issue ?
/kind flake

[bobcatfish]

I'm not sure, let's close it and we can re-open if/when it happens again

[jerop]

The test flaked again in #3135 -- https://tekton-releases.appspot.com/build/tekton-prow/pr-logs/pull/tektoncd_pipeline/3135/pull-tekton-pipeline-integration-tests/1301144752749547520/

/reopen