Twice on PR #2936, I've had a failure with only the TRAVIS_GOOS=linux TEST_RUNTIME=io.containerd.runtime.v1.linux TRAVIS_CGO_ENABLED=1 variant in Travis:
Summarizing 1 Failure:
[Fail] [k8s.io] Streaming runtime should support streaming interfaces [AfterEach] runtime should support attach [Conformance]
/home/travis/gopath/src/github.com/kubernetes-sigs/cri-tools/pkg/validate/streaming.go:308
Ran 66 of 72 Specs in 50.270 seconds
FAIL! -- 65 Passed | 1 Failed | 0 Pending | 6 Skipped
Complete test log from that streaming test:
Jan 16 19:17:00.148: INFO: Created container "0a37f9c02d36bc65f16d17a089e49c6f4ff0e71d9aaa5948221f7441cbfe3d13"
STEP: start container
STEP: Start container for containerID: 0a37f9c02d36bc65f16d17a089e49c6f4ff0e71d9aaa5948221f7441cbfe3d13
Jan 16 19:17:00.624: INFO: Started container "0a37f9c02d36bc65f16d17a089e49c6f4ff0e71d9aaa5948221f7441cbfe3d13"
STEP: attach container: 0a37f9c02d36bc65f16d17a089e49c6f4ff0e71d9aaa5948221f7441cbfe3d13
Jan 16 19:17:00.667: INFO: Get attach url: http://127.0.0.1:35744/attach/X2VGBvJj
STEP: check the output of attach
Jan 16 19:17:00.702: INFO: Parse url "http://127.0.0.1:35744/attach/X2VGBvJj" succeed
Jan 16 19:17:00.897: INFO: Unexpected error occurred: Internal error occurred: error attaching to container: failed to load task: no running task found: task 0a37f9c02d36bc65f16d17a089e49c6f4ff0e71d9aaa5948221f7441cbfe3d13 not found: not found
[AfterEach] runtime should support streaming interfaces
/home/travis/gopath/src/github.com/kubernetes-sigs/cri-tools/pkg/validate/streaming.go:61
STEP: stop PodSandbox
STEP: delete PodSandbox
[AfterEach] [k8s.io] Streaming
/home/travis/gopath/src/github.com/kubernetes-sigs/cri-tools/pkg/framework/framework.go:51
• Failure in Spec Teardown (AfterEach) [5.064 seconds]
[k8s.io] Streaming
/home/travis/gopath/src/github.com/kubernetes-sigs/cri-tools/pkg/framework/framework.go:72
runtime should support streaming interfaces
/home/travis/gopath/src/github.com/kubernetes-sigs/cri-tools/pkg/validate/streaming.go:57
runtime should support attach [Conformance] [AfterEach]
/home/travis/gopath/src/github.com/kubernetes-sigs/cri-tools/pkg/validate/streaming.go:111
failed to open streamer for "http://127.0.0.1:35744/attach/X2VGBvJj"
Expected error:
<*errors.errorString | 0xc000335350>: {
s: "Internal error occurred: error attaching to container: failed to load task: no running task found: task 0a37f9c02d36bc65f16d17a089e49c6f4ff0e71d9aaa5948221f7441cbfe3d13 not found: not found",
}
Internal error occurred: error attaching to container: failed to load task: no running task found: task 0a37f9c02d36bc65f16d17a089e49c6f4ff0e71d9aaa5948221f7441cbfe3d13 not found: not found
not to have occurred
Log from containerd surrounding the "task not found" issue:
time="2019-01-16T19:17:00.587854233Z" level=info msg="StartContainer for \"0a37f9c02d36bc65f16d17a089e49c6f4ff0e71d9aaa5948221f7441cbfe3d13\" returns successfully"
time="2019-01-16T19:17:00.604509748Z" level=debug msg="event published" ns=k8s.io topic=/snapshot/commit type=containerd.events.SnapshotCommit
time="2019-01-16T19:17:00.611665296Z" level=info msg="Kill container \"2caeea51c7aa95cf021f5e902f1abe0f9a1a36e59f8d544b924041265f8a2131\""
time="2019-01-16T19:17:00.611803861Z" level=debug msg="event published" ns=k8s.io topic=/snapshot/prepare type=containerd.events.SnapshotPrepare
time="2019-01-16T19:17:00.624785933Z" level=info msg="StopPodSandbox for \"e40a5b1aee88905e637a6b9be2dfcec88d77b0c1ac12ac0e3e11476ba0dfc168\""
time="2019-01-16T19:17:00.645141070Z" level=debug msg="event published" ns=k8s.io topic=/tasks/exit type=containerd.events.TaskExit
time="2019-01-16T19:17:00.645294770Z" level=debug msg="Received containerd event timestamp - 2019-01-16 19:17:00.645130172 +0000 UTC, namespace - \"k8s.io\", topic - \"/tasks/exit\""
time="2019-01-16T19:17:00.645376657Z" level=info msg="TaskExit event &TaskExit{ContainerID:0a37f9c02d36bc65f16d17a089e49c6f4ff0e71d9aaa5948221f7441cbfe3d13,ID:0a37f9c02d36bc65f16d17a089e49c6f4ff0e71d9aaa5948221f7441cbfe3d13,Pid:18052,ExitStatus:0,ExitedAt:2019-01-16 19:17:00.528067275 +0000 UTC,}"
time="2019-01-16T19:17:00.645678430Z" level=info msg="Attach for \"0a37f9c02d36bc65f16d17a089e49c6f4ff0e71d9aaa5948221f7441cbfe3d13\" with tty false and stdin true"
time="2019-01-16T19:17:00.645770043Z" level=info msg="Attach for \"0a37f9c02d36bc65f16d17a089e49c6f4ff0e71d9aaa5948221f7441cbfe3d13\" returns URL \"http://127.0.0.1:35744/attach/X2VGBvJj\""
time="2019-01-16T19:17:00.646060567Z" level=debug msg="fetch response received" response.headers="map[Content-Type:[application/vnd.docker.distribution.manifest.v2+json] Content-Length:[734] Docker-Content-Digest:[sha256:4d556817d2eee5e9c6d8c4a51fb77ca5e7fab99c8570d52b87950bbd86bdfef7] Date:[Wed, 16 Jan 2019 19:17:00 GMT] Server:[Docker Registry] X-Xss-Protection:[1; mode=block] X-Frame-Options:[SAMEORIGIN] Docker-Distribution-Api-Version:[registry/2.0]]" status="200 OK" url="https://gcr.io/v2/cri-tools/test-image-tags/manifests/1"
time="2019-01-16T19:17:00.646154722Z" level=debug msg=resolved desc.digest="sha256:4d556817d2eee5e9c6d8c4a51fb77ca5e7fab99c8570d52b87950bbd86bdfef7"
time="2019-01-16T19:17:00.648135273Z" level=debug msg=resolving
time="2019-01-16T19:17:00.648162805Z" level=debug msg="do request" request.headers="map[Accept:[application/vnd.docker.distribution.manifest.v2+json, application/vnd.docker.distribution.manifest.list.v2+json, application/vnd.oci.image.manifest.v1+json, application/vnd.oci.image.index.v1+json, *] User-Agent:[containerd/v1.2.0-203-g99b47f8]]" request.method=HEAD url="https://gcr.io/v2/cri-tools/test-image-tags/manifests/1"
time="2019-01-16T19:17:00.667036081Z" level=info msg="Finish piping stdout of container \"2caeea51c7aa95cf021f5e902f1abe0f9a1a36e59f8d544b924041265f8a2131\""
time="2019-01-16T19:17:00.667079891Z" level=info msg="Finish piping stderr of container \"2caeea51c7aa95cf021f5e902f1abe0f9a1a36e59f8d544b924041265f8a2131\""
time="2019-01-16T19:17:00.684968675Z" level=info msg="Kill container \"ceec13ec546e0b16fe60d77fb37e219dd9c46c9d13acd7b4fc69999bace74c0a\""
time="2019-01-16T19:17:00.719114843Z" level=debug msg="fetch response received" response.headers="map[Content-Type:[application/vnd.docker.distribution.manifest.v2+json] Content-Length:[734] Docker-Content-Digest:[sha256:4d556817d2eee5e9c6d8c4a51fb77ca5e7fab99c8570d52b87950bbd86bdfef7] Date:[Wed, 16 Jan 2019 19:17:00 GMT] Server:[Docker Registry] X-Xss-Protection:[1; mode=block] X-Frame-Options:[SAMEORIGIN] Docker-Distribution-Api-Version:[registry/2.0]]" status="200 OK" url="https://gcr.io/v2/cri-tools/test-image-tags/manifests/1"
time="2019-01-16T19:17:00.719202090Z" level=debug msg=resolved desc.digest="sha256:4d556817d2eee5e9c6d8c4a51fb77ca5e7fab99c8570d52b87950bbd86bdfef7"
time="2019-01-16T19:17:00.719258842Z" level=debug msg=fetch digest="sha256:4d556817d2eee5e9c6d8c4a51fb77ca5e7fab99c8570d52b87950bbd86bdfef7" mediatype=application/vnd.docker.distribution.manifest.v2+json size=734
time="2019-01-16T19:17:00.728028567Z" level=debug msg="do request" base="https://gcr.io/v2/cri-tools/test-image-tags" digest="sha256:4d556817d2eee5e9c6d8c4a51fb77ca5e7fab99c8570d52b87950bbd86bdfef7" mediatype=application/vnd.docker.distribution.manifest.v2+json request.headers="map[Accept:[application/vnd.docker.distribution.manifest.v2+json, *]]" request.method=GET size=734 url="https://gcr.io/v2/cri-tools/test-image-tags/manifests/sha256:4d556817d2eee5e9c6d8c4a51fb77ca5e7fab99c8570d52b87950bbd86bdfef7"
time="2019-01-16T19:17:00.745351768Z" level=info msg="Finish piping stderr of container \"ceec13ec546e0b16fe60d77fb37e219dd9c46c9d13acd7b4fc69999bace74c0a\""
time="2019-01-16T19:17:00.745412038Z" level=info msg="Finish piping stdout of container \"ceec13ec546e0b16fe60d77fb37e219dd9c46c9d13acd7b4fc69999bace74c0a\""
time="2019-01-16T19:17:00.819623059Z" level=debug msg="fetch response received" base="https://gcr.io/v2/cri-tools/test-image-tags" digest="sha256:4d556817d2eee5e9c6d8c4a51fb77ca5e7fab99c8570d52b87950bbd86bdfef7" mediatype=application/vnd.docker.distribution.manifest.v2+json response.headers="map[X-Frame-Options:[SAMEORIGIN] Docker-Distribution-Api-Version:[registry/2.0] Content-Type:[application/vnd.docker.distribution.manifest.v2+json] Docker-Content-Digest:[sha256:4d556817d2eee5e9c6d8c4a51fb77ca5e7fab99c8570d52b87950bbd86bdfef7] Content-Length:[734] Date:[Wed, 16 Jan 2019 19:17:00 GMT] Server:[Docker Registry] X-Xss-Protection:[1; mode=block]]" size=734 status="200 OK" url="https://gcr.io/v2/cri-tools/test-image-tags/manifests/sha256:4d556817d2eee5e9c6d8c4a51fb77ca5e7fab99c8570d52b87950bbd86bdfef7"
time="2019-01-16T19:17:00.826068743Z" level=debug msg=fetch digest="sha256:658ab7fdfcb5d49f43d25b9d13149520e48eddee602ce693e05f73e05a85abc3" mediatype=application/vnd.docker.image.rootfs.diff.tar.gzip size=100
time="2019-01-16T19:17:00.840516421Z" level=debug msg="do request" base="https://gcr.io/v2/cri-tools/test-image-tags" digest="sha256:658ab7fdfcb5d49f43d25b9d13149520e48eddee602ce693e05f73e05a85abc3" mediatype=application/vnd.docker.image.rootfs.diff.tar.gzip request.headers="map[Accept:[application/vnd.docker.image.rootfs.diff.tar.gzip, *]]" request.method=GET size=100 url="https://gcr.io/v2/cri-tools/test-image-tags/blobs/sha256:658ab7fdfcb5d49f43d25b9d13149520e48eddee602ce693e05f73e05a85abc3"
time="2019-01-16T19:17:00.841007518Z" level=debug msg="event published" ns=k8s.io topic=/tasks/exit type=containerd.events.TaskExit
time="2019-01-16T19:17:00.841120054Z" level=debug msg=fetch digest="sha256:2c31aa28ab3cddfb04944d018e03ee198cbf94773f4bd881e292a6e298b17017" mediatype=application/vnd.docker.container.image.v1+json size=1808
time="2019-01-16T19:17:00.848740603Z" level=debug msg="do request" base="https://gcr.io/v2/cri-tools/test-image-tags" digest="sha256:2c31aa28ab3cddfb04944d018e03ee198cbf94773f4bd881e292a6e298b17017" mediatype=application/vnd.docker.container.image.v1+json request.headers="map[Accept:[application/vnd.docker.container.image.v1+json, *]]" request.method=GET size=1808 url="https://gcr.io/v2/cri-tools/test-image-tags/blobs/sha256:2c31aa28ab3cddfb04944d018e03ee198cbf94773f4bd881e292a6e298b17017"
time="2019-01-16T19:17:00.849482430Z" level=debug msg=fetch digest="sha256:65fc92611f38c5c3e31d5c0faec078c60f41103f2ad4a3700fff122c49aab358" mediatype=application/vnd.docker.image.rootfs.diff.tar.gzip size=699165
time="2019-01-16T19:17:00.861940817Z" level=debug msg="do request" base="https://gcr.io/v2/cri-tools/test-image-tags" digest="sha256:65fc92611f38c5c3e31d5c0faec078c60f41103f2ad4a3700fff122c49aab358" mediatype=application/vnd.docker.image.rootfs.diff.tar.gzip request.headers="map[Accept:[application/vnd.docker.image.rootfs.diff.tar.gzip, *]]" request.method=GET size=699165 url="https://gcr.io/v2/cri-tools/test-image-tags/blobs/sha256:65fc92611f38c5c3e31d5c0faec078c60f41103f2ad4a3700fff122c49aab358"
time="2019-01-16T19:17:00.896789215Z" level=debug msg="event published" ns=k8s.io topic=/tasks/exit type=containerd.events.TaskExit
E0116 19:17:00.897321 14236 attach.go:52] error attaching to container: failed to load task: no running task found: task 0a37f9c02d36bc65f16d17a089e49c6f4ff0e71d9aaa5948221f7441cbfe3d13 not found: not found
time="2019-01-16T19:17:00.927481009Z" level=debug msg="fetch response received" base="https://gcr.io/v2/cri-tools/test-image-tags" digest="sha256:65fc92611f38c5c3e31d5c0faec078c60f41103f2ad4a3700fff122c49aab358" mediatype=application/vnd.docker.image.rootfs.diff.tar.gzip response.headers="map[Last-Modified:[Tue, 20 Feb 2018 18:32:28 GMT] X-Goog-Generation:[1519151548075266] Accept-Ranges:[bytes] Cache-Control:[public, max-age=3600] Expires:[Wed, 16 Jan 2019 20:16:47 GMT] X-Goog-Stored-Content-Encoding:[identity] X-Goog-Hash:[crc32c=tNx56g== md5=SkiuHh28dCSk6qumT6AMbA==] Content-Length:[699165] Age:[13] X-Guploader-Uploadid:[AEnB2Uo9sL4UlfEuRbPdcuPFk7pBT0X2cpeHrnK-73Yj-hRX7Rq30iBL9AKNDbROOxyWD4gWTcPJ1rZ65fPzLc-dZ-9kpWnwfvgFy2-lBy9toJJQ7Ay8YQw] Etag:[\"4a48ae1e1dbc7424a4eaaba64fa00c6c\"] X-Goog-Stored-Content-Length:[699165] Content-Type:[application/octet-stream] Date:[Wed, 16 Jan 2019 19:16:47 GMT] X-Goog-Metageneration:[1] X-Goog-Storage-Class:[STANDARD] Server:[UploadServer]]" size=699165 status="200 OK" url="https://gcr.io/v2/cri-tools/test-image-tags/blobs/sha256:65fc92611f38c5c3e31d5c0faec078c60f41103f2ad4a3700fff122c49aab358"
time="2019-01-16T19:17:00.943535942Z" level=info msg="StopPodSandbox for \"bf5ce14abe885fcbd2ab7c2fd6deeadbac3862ae0e8c9ac1827acfb82d874b29\""
time="2019-01-16T19:17:00.960133120Z" level=info msg="shim reaped" id=0a37f9c02d36bc65f16d17a089e49c6f4ff0e71d9aaa5948221f7441cbfe3d13
time="2019-01-16T19:17:00.975830557Z" level=debug msg="event published" ns=k8s.io topic=/tasks/delete type=containerd.events.TaskDelete
time="2019-01-16T19:17:00.979383243Z" level=debug msg="Received containerd event timestamp - 2019-01-16 19:17:00.84100101 +0000 UTC, namespace - \"k8s.io\", topic - \"/tasks/exit\""
time="2019-01-16T19:17:00.979479460Z" level=info msg="TaskExit event &TaskExit{ContainerID:2caeea51c7aa95cf021f5e902f1abe0f9a1a36e59f8d544b924041265f8a2131,ID:2caeea51c7aa95cf021f5e902f1abe0f9a1a36e59f8d544b924041265f8a2131,Pid:17680,ExitStatus:137,ExitedAt:2019-01-16 19:17:00.652061976 +0000 UTC,}"
If I'm reading it properly, then it looks like the container and task immediately exited at 19:17:00.645?
time="2019-01-16T19:17:00.645376657Z" level=info msg="TaskExit event &TaskExit{ContainerID:0a37f9c02d36bc65f16d17a089e49c6f4ff0e71d9aaa5948221f7441cbfe3d13,ID:0a37f9c02d36bc65f16d17a089e49c6f4ff0e71d9aaa5948221f7441cbfe3d13,Pid:18052,ExitStatus:0,ExitedAt:2019-01-16 19:17:00.528067275 +0000 UTC,}"
such that ~250ms later (@ 19:17:00.897) when the attach call was executed, there was no task with that ID:
E0116 19:17:00.897321 14236 attach.go:52] error attaching to container: failed to load task: no running task found: task 0a37f9c02d36bc65f16d17a089e49c6f4ff0e71d9aaa5948221f7441cbfe3d13 not found: not found
@Random-Liu @mikebrow any ideas?
Twice on PR #2936, I've had a failure with only the
TRAVIS_GOOS=linux TEST_RUNTIME=io.containerd.runtime.v1.linux TRAVIS_CGO_ENABLED=1variant in Travis:Complete test log from that streaming test:
Log from containerd surrounding the "task not found" issue:
If I'm reading it properly, then it looks like the container and task immediately exited at 19:17:00.645?
such that ~250ms later (@ 19:17:00.897) when the attach call was executed, there was no task with that ID:
@Random-Liu @mikebrow any ideas?