Skip to content

flaky CRI test: [AfterEach] runtime should support attach [Conformance] #2937

@estesp

Description

@estesp

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?

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions