search

containerd / containerd

An open and reliable container runtime
https://containerd.io
Apache License 2.0
17.36k stars 3.44k forks source link

[test] Flaky testcase TestRestartMonitor/Always #8028

Open fuweid opened 1 year ago

fuweid commented 1 year ago

Description

https://github.com/containerd/containerd/actions/runs/3986308559/jobs/6834893977

From #7977

Click to check details ``` === Failed === FAIL: . TestRestartMonitor/Always (0.16s) time="2023-01-23T12:58:36Z" level=error msg="failed to accept stdin connection on \\\\.\\pipe\\ctr-TestRestartMonitor_Always-stdin" error="use of closed network connection" restart_monitor_test.go:189: failed to start shim: mkdir C:\Users\RUNNER~1\AppData\Local\Temp\TestRestartMonitor708044512\001\state\io.containerd.runtime.v2.task\testing\TestRestartMonitor_Always: Cannot create a file when that file already exists.: unknown time="2023-01-23T12:58:36Z" level=error msg="failed to accept stdout connection on \\\\.\\pipe\\ctr-TestRestartMonitor_Always-stdout" error="use of closed network connection" --- FAIL: TestRestartMonitor/Always (0.16s) === FAIL: . TestRestartMonitor (27.90s) log_hook.go:47: time="2023-01-23T12:58:16.586333300Z" level=debug msg=resolving func="docker.(*dockerResolver).Resolve" file="D:/a/containerd/containerd/src/github.com/containerd/containerd/remotes/docker/resolver.go:284" host=mcr.microsoft.com log_hook.go:47: time="2023-01-23T12:58:16.586854900Z" level=debug msg="do request" func="docker.(*request).do" file="D:/a/containerd/containerd/src/github.com/containerd/containerd/remotes/docker/resolver.go:559" host=mcr.microsoft.com request.header.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, */*" request.header.user-agent=containerd/1.7.0-beta.2+unknown request.method=HEAD url="https://mcr.microsoft.com/v2/windows/nanoserver/manifests/ltsc2022" log_hook.go:47: time="2023-01-23T12:58:16.637768700Z" level=debug msg="fetch response received" func="docker.(*request).do" file="D:/a/containerd/containerd/src/github.com/containerd/containerd/remotes/docker/resolver.go:591" host=mcr.microsoft.com response.header.access-control-expose-headers=Docker-Content-Digest response.header.access-control-expose-headers.1=WWW-Authenticate response.header.access-control-expose-headers.2=Link response.header.access-control-expose-headers.3=X-Ms-Correlation-Request-Id response.header.content-length=[35](https://github.com/containerd/containerd/actions/runs/3986308559/jobs/6834893977#step:16:36)0 response.header.content-type=application/vnd.docker.distribution.manifest.list.v2+json response.header.date="Mon, 23 Jan 2023 12:58:15 GMT" response.header.docker-content-digest="sha256:b42488[36](https://github.com/containerd/containerd/actions/runs/3986308559/jobs/6834893977#step:16:37)dea118c48481b821d9fbb40daf7e207b48f5e6edc9da68[37](https://github.com/containerd/containerd/actions/runs/3986308559/jobs/6834893977#step:16:38)050b0f65" response.header.docker-distribution-api-version=registry/2.0 response.header.etag="\"sha256:b4248836dea118c48481b821d9fbb40daf7e207b48f5e6edc9da6837050b0f65\"" response.header.strict-transport-security="max-age=31536000; includeSubDomains" response.header.strict-transport-security.1="max-age=31536000; includeSubDomains" response.header.x-cache=CONFIG_NOCACHE response.header.x-content-type-options=nosniff response.header.x-mcr-env=prod response.header.x-mcr-privacy="https://privacy.microsoft.com/en-us/privacystatement" response.header.x-ms-client-request-id= response.header.x-ms-correlation-request-id=ea301afe-8057-4d08-ab64-9ddabdecdc64 response.header.x-ms-request-id=e463d9cc-a6e1-4e51-94bf-cceec340b9c1 response.header.x-msedge-ref="Ref A: AC22D73600D8467DB590FED00B9FC2C7 Ref B: LAXEDGE2007 Ref C: 2023-01-23T12:58:16Z" response.status="200 OK" url="https://mcr.microsoft.com/v2/windows/nanoserver/manifests/ltsc2022" log_hook.go:47: time="2023-01-23T12:58:16.6[38](https://github.com/containerd/containerd/actions/runs/3986308559/jobs/6834893977#step:16:39)834900Z" level=debug msg=resolved func="docker.(*dockerResolver).Resolve" file="D:/a/containerd/containerd/src/github.com/containerd/containerd/remotes/docker/resolver.go:[39](https://github.com/containerd/containerd/actions/runs/3986308559/jobs/6834893977#step:16:40)1" desc.digest="sha256:b4248836dea118c48481b821d9fbb[40](https://github.com/containerd/containerd/actions/runs/3986308559/jobs/6834893977#step:16:41)daf7e207b48f5e6edc9da6837050b0f65" host=mcr.microsoft.com log_hook.go:47: time="2023-01-23T12:58:16.639362500Z" level=debug msg=fetch func=remotes.Fetch file="D:/a/containerd/containerd/src/github.com/containerd/containerd/remotes/handlers.go:114" digest="sha256:b4248836dea118c48481b821d9fbb40daf7e207b48f5e6edc9da6837050b0f65" mediatype=application/vnd.docker.distribution.manifest.list.v2+json size=350 log_hook.go:47: time="2023-01-23T12:58:16.657298500Z" level=debug msg="do request" func="docker.(*request).do" file="D:/a/containerd/containerd/src/github.com/containerd/containerd/remotes/docker/resolver.go:559" digest="sha256:b4248836dea118c48481b821d9fbb40daf7e207b48f5e6edc9da6837050b0f65" mediatype=application/vnd.docker.distribution.manifest.list.v2+json request.header.accept="application/vnd.docker.distribution.manifest.list.v2+json, */*" request.header.user-agent=containerd/1.7.0-beta.2+unknown request.method=GET size=350 url="https://mcr.microsoft.com/v2/windows/nanoserver/manifests/sha256:b4248836dea118c48481b821d9fbb40daf7e207b48f5e6edc9da6837050b0f65" log_hook.go:47: time="2023-01-23T12:58:16.710152400Z" level=debug msg="fetch response received" func="docker.(*request).do" file="D:/a/containerd/containerd/src/github.com/containerd/containerd/remotes/docker/resolver.go:591" digest="sha256:b4248836dea118c48481b821d9fbb40daf7e207b48f5e6edc9da6837050b0f65" mediatype=application/vnd.docker.distribution.manifest.list.v2+json response.header.access-control-expose-headers=Docker-Content-Digest response.header.access-control-expose-headers.1=WWW-Authenticate response.header.access-control-expose-headers.2=Link response.header.access-control-expose-headers.3=X-Ms-Correlation-Request-Id response.header.content-length=350 response.header.content-type=application/vnd.docker.distribution.manifest.list.v2+json response.header.date="Mon, 23 Jan 2023 12:58:15 GMT" response.header.docker-content-digest="sha256:b4248836dea118c48481b821d9fbb40daf7e207b48f5e6edc9da6837050b0f65" response.header.docker-distribution-api-version=registry/2.0 response.header.etag="\"sha256:b4248836dea118c48481b821d9fbb40daf7e207b48f5e6edc9da6837050b0f65\"" response.header.strict-transport-security="max-age=31536000; includeSubDomains" response.header.strict-transport-security.1="max-age=31536000; includeSubDomains" response.header.x-cache=CONFIG_NOCACHE response.header.x-content-type-options=nosniff response.header.x-mcr-env=prod response.header.x-mcr-privacy="https://privacy.microsoft.com/en-us/privacystatement" response.header.x-ms-client-request-id= response.header.x-ms-correlation-request-id=f12abfaf-8efd-456e-9ee5-e259c556c93a response.header.x-ms-request-id=d1cf9384-00d1-4e8d-8f8a-6c6299c0f80c response.header.x-msedge-ref="Ref A: 03B27FB3DDE240E2AE8C8B29E621FF1E Ref B: LAXEDGE2007 Ref C: 2023-01-23T12:58:16Z" response.status="200 OK" size=350 url="https://mcr.microsoft.com/v2/windows/nanoserver/manifests/sha256:b4248836dea118c48481b821d9fbb40daf7e207b48f5e6edc9da6837050b0f65" log_hook.go:47: time="2023-01-23T12:58:16.766432800Z" level=debug msg=fetch func=remotes.Fetch file="D:/a/containerd/containerd/src/github.com/containerd/containerd/remotes/handlers.go:114" digest="sha256:3c078dce916ed3f67207c120ead28db500cd14389c27f451cd215e144c5143e8" mediatype=application/vnd.docker.distribution.manifest.v2+json size=574 log_hook.go:47: time="2023-01-23T12:58:16.785864800Z" level=debug msg="do request" func="docker.(*request).do" file="D:/a/containerd/containerd/src/github.com/containerd/containerd/remotes/docker/resolver.go:559" digest="sha256:3c078dce916ed3f67207c120ead28db500cd14389c27f451cd215e144c5143e8" mediatype=application/vnd.docker.distribution.manifest.v2+json request.header.accept="application/vnd.docker.distribution.manifest.v2+json, */*" request.header.user-agent=containerd/1.7.0-beta.2+unknown request.method=GET size=574 url="https://mcr.microsoft.com/v2/windows/nanoserver/manifests/sha256:3c078dce916ed3f67207c120ead28db500cd14389c27f451cd215e144c5143e8" log_hook.go:47: time="2023-01-23T12:58:16.869834300Z" level=debug msg="fetch response received" func="docker.(*request).do" file="D:/a/containerd/containerd/src/github.com/containerd/containerd/remotes/docker/resolver.go:591" digest="sha256:3c078dce916ed3f67207c120ead28db500cd14389c27f451cd215e144c5143e8" mediatype=application/vnd.docker.distribution.manifest.v2+json response.header.access-control-expose-headers=Docker-Content-Digest response.header.access-control-expose-headers.1=WWW-Authenticate response.header.access-control-expose-headers.2=Link response.header.access-control-expose-headers.3=X-Ms-Correlation-Request-Id response.header.content-length=574 response.header.content-type=application/vnd.docker.distribution.manifest.v2+json response.header.date="Mon, 23 Jan 2023 12:58:16 GMT" response.header.docker-content-digest="sha256:3c078dce916ed3f67207c120ead28db500cd14389c27f451cd215e144c5143e8" response.header.docker-distribution-api-version=registry/2.0 response.header.etag="\"sha256:3c078dce916ed3f67207c120ead28db500cd14389c27f451cd215e144c5143e8\"" response.header.strict-transport-security="max-age=31536000; includeSubDomains" response.header.strict-transport-security.1="max-age=31536000; includeSubDomains" response.header.x-cache=CONFIG_NOCACHE response.header.x-content-type-options=nosniff response.header.x-mcr-env=prod response.header.x-mcr-privacy="https://privacy.microsoft.com/en-us/privacystatement" response.header.x-ms-client-request-id= response.header.x-ms-correlation-request-id=2248a4f5-cda3-4864-a203-62b8d84fb8e1 response.header.x-ms-request-id=869def65-0c93-4594-8f9a-93[41](https://github.com/containerd/containerd/actions/runs/3986308559/jobs/6834893977#step:16:42)8e1d689f response.header.x-msedge-ref="Ref A: 6DB9641604934CDFAB237CBDDCA5962A Ref B: LAXEDGE2007 Ref C: 2023-01-23T12:58:16Z" response.status="200 OK" size=574 url="https://mcr.microsoft.com/v2/windows/nanoserver/manifests/sha256:3c078dce916ed3f67207c120ead28db500cd14389c27f451cd215e144c5143e8" log_hook.go:47: time="2023-01-23T12:58:16.922[42](https://github.com/containerd/containerd/actions/runs/3986308559/jobs/6834893977#step:16:43)0000Z" level=debug msg=fetch func=remotes.Fetch file="D:/a/containerd/containerd/src/github.com/containerd/containerd/remotes/handlers.go:114" digest="sha256:ab6b2955d60afd3c9e79a9787a0ce6e69d1ff3a3f32f704ded3c307c4b29c746" mediatype=application/vnd.docker.container.image.v1+json size=638 log_hook.go:47: time="2023-01-23T12:58:16.9[43](https://github.com/containerd/containerd/actions/runs/3986308559/jobs/6834893977#step:16:44)311000Z" level=debug msg="do request" func="docker.(*request).do" file="D:/a/containerd/containerd/src/github.com/containerd/containerd/remotes/docker/resolver.go:559" digest="sha256:ab6b2955d60afd3c9e79a9787a0ce6e69d1ff3a3f32f704ded3c307c4b29c746" mediatype=application/vnd.docker.container.image.v1+json request.header.accept="application/vnd.docker.container.image.v1+json, */*" request.header.user-agent=containerd/1.7.0-beta.2+unknown request.method=GET size=638 url="https://mcr.microsoft.com/v2/windows/nanoserver/blobs/sha256:ab6b2955d60afd3c9e79a9787a0ce6e69d1ff3a3f32f704ded3c307c4b29c746" log_hook.go:47: time="2023-01-23T12:58:16.987660100Z" level=debug msg="fetch response received" func="docker.(*request).do" file="D:/a/containerd/containerd/src/github.com/containerd/containerd/remotes/docker/resolver.go:591" digest="sha256:ab6b2955d60afd3c9e79a9787a0ce6e69d1ff3a3f32f704ded3c307c4b29c746" mediatype=application/vnd.docker.container.image.v1+json response.header.accept-ranges=bytes response.header.content-length=638 response.header.content-type=application/octet-stream response.header.date="Mon, 23 Jan 2023 12:58:16 GMT" response.header.etag="\"0x8DAF29FA0E2A25D\"" response.header.last-modified="Tue, 10 Jan 2023 00:14:23 GMT" response.header.server="Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0" response.header.x-azure-ref-originshield="Ref A: 19EFCA19A7E5453CB8C7383A6057C6D4 Ref B: SN1EDGE2920 Ref C: 2023-01-22T20:01:27Z" response.header.x-cache=TCP_HIT response.header.x-mcr-env=preview response.header.x-ms-blob-committed-block-count=1 response.header.x-ms-blob-type=AppendBlob response.header.x-ms-copy-completion-time="Tue, 10 Jan 2023 00:14:23 GMT" response.header.x-ms-copy-id=1dcf779e-6bff-453f-a255-a27563a40170 response.header.x-ms-copy-progress=638/638 response.header.x-ms-copy-source=mcr-wus response.header.x-ms-copy-status=success response.header.x-ms-lease-state=available response.header.x-ms-lease-status=unlocked response.header.x-ms-request-id=822dac66-101e-0012-7f1f-2d0c75000000 response.header.x-ms-server-encrypted=true response.header.x-ms-version=2016-05-31 response.header.x-msedge-ref="Ref A: 0BFB1780F8D846EEB932A694F700AEBE Ref B: LAXEDGE1807 Ref C: 2023-01-23T12:58:16Z" response.status="200 OK" size=638 url="https://mcr.microsoft.com/v2/windows/nanoserver/blobs/sha256:ab6b2955d60afd3c9e79a9787a0ce6e69d1ff3a3f32f704ded3c307c4b29c746" log_hook.go:47: time="2023-01-23T12:58:17.089595600Z" level=debug msg=fetch func=remotes.Fetch file="D:/a/containerd/containerd/src/github.com/containerd/containerd/remotes/handlers.go:114" digest="sha256:25550ca2a1c5d341a996152b565fbecf6742f2e123642a941212c6100c3dfb7d" mediatype=application/vnd.docker.image.rootfs.foreign.diff.tar.gzip size=118308467 log_hook.go:47: time="2023-01-23T12:58:17.111013400Z" level=info msg=request func=docker.dockerFetcher.Fetch.func1 file="D:/a/containerd/containerd/src/github.com/containerd/containerd/remotes/docker/fetcher.go:66" digest="sha256:25550ca2a1c5d341a996152b565fbecf6742f2e123642a941212c6100c3dfb7d" mediatype=application/vnd.docker.image.rootfs.foreign.diff.tar.gzip size=118308467 url="https://mcr.microsoft.com/v2/windows/nanoserver/blobs/sha256:25550ca2a1c5d341a996152b565fbecf6742f2e123642a941212c6100c3dfb7d" log_hook.go:47: time="2023-01-23T12:58:17.111530100Z" level=debug msg="do request" func="docker.(*request).do" file="D:/a/containerd/containerd/src/github.com/containerd/containerd/remotes/docker/resolver.go:559" digest="sha256:25550ca2a1c5d341a996152b565fbecf6742f2e123642a941212c6100c3dfb7d" mediatype=application/vnd.docker.image.rootfs.foreign.diff.tar.gzip request.header.accept="application/vnd.docker.image.rootfs.foreign.diff.tar.gzip, */*" request.header.user-agent=containerd/1.7.0-beta.2+unknown request.method=GET size=118308467 url="https://mcr.microsoft.com/v2/windows/nanoserver/blobs/sha256:25550ca2a1c5d341a996152b565fbecf6742f2e123642a941212c6100c3dfb7d" log_hook.go:47: time="2023-01-23T12:58:17.142883000Z" level=debug msg="fetch response received" func="docker.(*request).do" file="D:/a/containerd/containerd/src/github.com/containerd/containerd/remotes/docker/resolver.go:591" digest="sha256:25550ca2a1c5d341a996152b565fbecf6742f2e123642a941212c6100c3dfb7d" mediatype=application/vnd.docker.image.rootfs.foreign.diff.tar.gzip response.header.accept-ranges=bytes response.header.content-length=118308467 response.header.content-type=application/octet-stream response.header.date="Mon, 23 Jan 2023 12:58:16 GMT" response.header.etag="\"0x8DAF29F972C706E\"" response.header.last-modified="Tue, 10 Jan 2023 00:14:07 GMT" response.header.server="Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0" response.header.x-azure-ref-originshield="Ref A: E620FBC340A54F9CA16EB627F7F461FB Ref B: SN1EDGE2011 Ref C: 2023-01-22T06:40:32Z" response.header.x-cache=TCP_HIT response.header.x-mcr-env=preview response.header.x-ms-blob-committed-block-count=29 response.header.x-ms-blob-type=AppendBlob response.header.x-ms-copy-completion-time="Tue, 10 Jan 2023 00:14:07 GMT" response.header.x-ms-copy-id=87b86c49-cd95-4c6f-9143-696a56ab110e response.header.x-ms-copy-progress=118308467/118308467 response.header.x-ms-copy-source=mcr-wus response.header.x-ms-copy-status=success response.header.x-ms-lease-state=available response.header.x-ms-lease-status=unlocked response.header.x-ms-request-id=7dc2a6b7-c01e-00d7-01dc-2d724e000000 response.header.x-ms-server-encrypted=true response.header.x-ms-version=2016-05-31 response.header.x-msedge-ref="Ref A: 6B9DAE46CF314957A8936BDD99FFBEE3 Ref B: LAXEDGE1807 Ref C: 2023-01-23T12:58:17Z" response.status="200 OK" size=118308467 url="https://mcr.microsoft.com/v2/windows/nanoserver/blobs/sha256:25550ca2a1c5d341a996152b565fbecf6742f2e123642a941212c6100c3dfb7d" log_hook.go:47: time="2023-01-23T12:58:36.083763700Z" level=debug msg="image unpacked" func="unpack.(*Unpacker).unpack" file="D:/a/containerd/containerd/src/github.com/containerd/containerd/pkg/unpack/unpacker.go:[44](https://github.com/containerd/containerd/actions/runs/3986308559/jobs/6834893977#step:16:45)3" chainID="sha256:52bc99b0216f00755ce90018cc5dc88a9aca7a72ecdbcaf63a30b34db18c8025" config="sha256:ab6b2955d60afd3c9e79a9787a0ce6e69d1ff3a3f32f704ded3c307c4b29c746" restart_monitor_test.go:112: Daemon output: time="2023-01-23T12:58:16.093170900Z" level=info msg="starting containerd" revision=bd3bd57044db58dae5097a0cb719f1dfaeca6928 version=bd3bd57 time="2023-01-23T12:58:16.1[45](https://github.com/containerd/containerd/actions/runs/3986308559/jobs/6834893977#step:16:46)455400Z" level=info msg="loading plugin \"io.containerd.content.v1.content\"..." type=io.containerd.content.v1 time="2023-01-23T12:58:16.1[46](https://github.com/containerd/containerd/actions/runs/3986308559/jobs/6834893977#step:16:47)482500Z" level=info msg="loading plugin \"io.containerd.snapshotter.v1.windows-lcow\"..." type=io.containerd.snapshotter.v1 time="2023-01-23T12:58:16.146842600Z" level=info msg="loading plugin \"io.containerd.snapshotter.v1.windows\"..." type=io.containerd.snapshotter.v1 time="2023-01-23T12:58:16.1[47](https://github.com/containerd/containerd/actions/runs/3986308559/jobs/6834893977#step:16:48)873500Z" level=info msg="loading plugin \"io.containerd.metadata.v1.bolt\"..." type=io.containerd.metadata.v1 time="2023-01-23T12:58:16.1[48](https://github.com/containerd/containerd/actions/runs/3986308559/jobs/6834893977#step:16:49)096600Z" level=info msg="metadata content store policy set" policy=shared time="2023-01-23T12:58:16.185530400Z" level=info msg="loading plugin \"io.containerd.differ.v1.walking\"..." type=io.containerd.differ.v1 time="2023-01-23T12:58:16.185530400Z" level=info msg="loading plugin \"io.containerd.event.v1.exchange\"..." type=io.containerd.event.v1 time="2023-01-23T12:58:16.185530400Z" level=info msg="loading plugin \"io.containerd.gc.v1.scheduler\"..." type=io.containerd.gc.v1 time="2023-01-23T12:58:16.185530400Z" level=info msg="loading plugin \"io.containerd.lease.v1.manager\"..." type=io.containerd.lease.v1 time="2023-01-23T12:58:16.185530400Z" level=info msg="loading plugin \"io.containerd.nri.v1.nri\"..." type=io.containerd.nri.v1 time="2023-01-23T12:58:16.185530400Z" level=info msg="NRI interface is disabled by configuration." time="2023-01-23T12:58:16.185530400Z" level=info msg="loading plugin \"io.containerd.sandbox.store.v1.local\"..." type=io.containerd.sandbox.store.v1 time="2023-01-23T12:58:16.185530400Z" level=info msg="loading plugin \"io.containerd.streaming.v1.manager\"..." type=io.containerd.streaming.v1 time="2023-01-23T12:58:16.185530400Z" level=info msg="loading plugin \"io.containerd.transfer.v1.local\"..." type=io.containerd.transfer.v1 time="2023-01-23T12:58:16.185530400Z" level=info msg="loading plugin \"io.containerd.service.v1.introspection-service\"..." type=io.containerd.service.v1 time="2023-01-23T12:58:16.185530400Z" level=info msg="loading plugin \"io.containerd.service.v1.containers-service\"..." type=io.containerd.service.v1 time="2023-01-23T12:58:16.185530400Z" level=info msg="loading plugin \"io.containerd.service.v1.content-service\"..." type=io.containerd.service.v1 time="2023-01-23T12:58:16.185530400Z" level=info msg="loading plugin \"io.containerd.differ.v1.windows-lcow\"..." type=io.containerd.differ.v1 time="2023-01-23T12:58:16.185530400Z" level=info msg="loading plugin \"io.containerd.differ.v1.windows\"..." type=io.containerd.differ.v1 time="2023-01-23T12:58:16.185530400Z" level=info msg="loading plugin \"io.containerd.service.v1.diff-service\"..." type=io.containerd.service.v1 time="2023-01-23T12:58:16.185530400Z" level=info msg="loading plugin \"io.containerd.service.v1.images-service\"..." type=io.containerd.service.v1 time="2023-01-23T12:58:16.186053200Z" level=info msg="loading plugin \"io.containerd.service.v1.namespaces-service\"..." type=io.containerd.service.v1 time="2023-01-23T12:58:16.186053200Z" level=info msg="loading plugin \"io.containerd.runtime.v2.task\"..." type=io.containerd.runtime.v2 time="2023-01-23T12:58:16.186569900Z" level=info msg="loading plugin \"io.containerd.runtime.v2.shim\"..." type=io.containerd.runtime.v2 time="2023-01-23T12:58:16.186569900Z" level=info msg="loading plugin \"io.containerd.service.v1.sandbox-controller-service\"..." type=io.containerd.service.v1 time="2023-01-23T12:58:16.186569900Z" level=info msg="loading plugin \"io.containerd.service.v1.snapshots-service\"..." type=io.containerd.service.v1 time="2023-01-23T12:58:16.186569900Z" level=info msg="loading plugin \"io.containerd.service.v1.tasks-service\"..." type=io.containerd.service.v1 time="2023-01-23T12:58:16.186569900Z" level=info msg="loading plugin \"io.containerd.grpc.v1.introspection\"..." type=io.containerd.grpc.v1 time="2023-01-23T12:58:16.186569900Z" level=info msg="loading plugin \"io.containerd.internal.v1.restart\"..." type=io.containerd.internal.v1 time="2023-01-23T12:58:16.187086400Z" level=info msg="loading plugin \"io.containerd.grpc.v1.containers\"..." type=io.containerd.grpc.v1 time="2023-01-23T12:58:16.187086400Z" level=info msg="loading plugin \"io.containerd.grpc.v1.content\"..." type=io.containerd.grpc.v1 time="2023-01-23T12:58:16.187086400Z" level=info msg="loading plugin \"io.containerd.grpc.v1.diff\"..." type=io.containerd.grpc.v1 time="2023-01-23T12:58:16.187086400Z" level=info msg="loading plugin \"io.containerd.grpc.v1.events\"..." type=io.containerd.grpc.v1 time="2023-01-23T12:58:16.187086400Z" level=info msg="loading plugin \"io.containerd.grpc.v1.healthcheck\"..." type=io.containerd.grpc.v1 time="2023-01-23T12:58:16.187086400Z" level=info msg="loading plugin \"io.containerd.grpc.v1.images\"..." type=io.containerd.grpc.v1 time="2023-01-23T12:58:16.187086400Z" level=info msg="loading plugin \"io.containerd.grpc.v1.leases\"..." type=io.containerd.grpc.v1 time="2023-01-23T12:58:16.187086400Z" level=info msg="loading plugin \"io.containerd.grpc.v1.namespaces\"..." type=io.containerd.grpc.v1 time="2023-01-23T12:58:16.187086400Z" level=info msg="loading plugin \"io.containerd.internal.v1.opt\"..." type=io.containerd.internal.v1 time="2023-01-23T12:58:16.187086400Z" level=info msg="loading plugin \"io.containerd.grpc.v1.sandbox-controllers\"..." type=io.containerd.grpc.v1 time="2023-01-23T12:58:16.187086400Z" level=info msg="loading plugin \"io.containerd.grpc.v1.sandboxes\"..." type=io.containerd.grpc.v1 time="2023-01-23T12:58:16.187086400Z" level=info msg="loading plugin \"io.containerd.grpc.v1.snapshots\"..." type=io.containerd.grpc.v1 time="2023-01-23T12:58:16.187086400Z" level=info msg="loading plugin \"io.containerd.grpc.v1.streaming\"..." type=io.containerd.grpc.v1 time="2023-01-23T12:58:16.187590600Z" level=info msg="loading plugin \"io.containerd.grpc.v1.tasks\"..." type=io.containerd.grpc.v1 time="2023-01-23T12:58:16.187607000Z" level=info msg="loading plugin \"io.containerd.grpc.v1.transfer\"..." type=io.containerd.grpc.v1 time="2023-01-23T12:58:16.187607000Z" level=info msg="loading plugin \"io.containerd.grpc.v1.version\"..." type=io.containerd.grpc.v1 time="2023-01-23T12:58:16.187607000Z" level=info msg="loading plugin \"io.containerd.grpc.v1.cri\"..." type=io.containerd.grpc.v1 time="2023-01-23T12:58:16.187607000Z" level=info msg="Start cri plugin with config {PluginConfig:{ContainerdConfig:{Snapshotter:windows DefaultRuntimeName:runhcs-wcow-process DefaultRuntime:{Type: Path: Engine: PodAnnotations:[] ContainerAnnotations:[] Root: Options:map[] PrivilegedWithoutHostDevices:false PrivilegedWithoutHostDevicesAllDevicesAllowed:false BaseRuntimeSpec: NetworkPluginConfDir: NetworkPluginMaxConfNum:0 Snapshotter: SandboxMode:} UntrustedWorkloadRuntime:{Type: Path: Engine: PodAnnotations:[] ContainerAnnotations:[] Root: Options:map[] PrivilegedWithoutHostDevices:false PrivilegedWithoutHostDevicesAllDevicesAllowed:false BaseRuntimeSpec: NetworkPluginConfDir: NetworkPluginMaxConfNum:0 Snapshotter: SandboxMode:} Runtimes:map[runhcs-wcow-hypervisor:{Type:io.containerd.runhcs.v1 Path: Engine: PodAnnotations:[io.microsoft.virtualmachine.*] ContainerAnnotations:[io.microsoft.container.*] Root: Options:map[SandboxIsolation:1 ScaleCpuLimitsToSandbox:true] PrivilegedWithoutHostDevices:false PrivilegedWithoutHostDevicesAllDevicesAllowed:false BaseRuntimeSpec: NetworkPluginConfDir: NetworkPluginMaxConfNum:0 Snapshotter: SandboxMode:podsandbox} runhcs-wcow-process:{Type:io.containerd.runhcs.v1 Path: Engine: PodAnnotations:[] ContainerAnnotations:[io.microsoft.container.*] Root: Options:map[] PrivilegedWithoutHostDevices:false PrivilegedWithoutHostDevicesAllDevicesAllowed:false BaseRuntimeSpec: NetworkPluginConfDir: NetworkPluginMaxConfNum:0 Snapshotter: SandboxMode:podsandbox}] NoPivot:false DisableSnapshotAnnotations:false DiscardUnpackedLayers:false IgnoreBlockIONotEnabledErrors:false IgnoreRdtNotEnabledErrors:false} CniConfig:{NetworkPluginBinDir:C:\\Program Files\\containerd\\cni\\bin NetworkPluginConfDir:C:\\Program Files\\containerd\\cni\\conf NetworkPluginMaxConfNum:1 NetworkPluginSetupSerially:false NetworkPluginConfTemplate: IPPreference:} Registry:{ConfigPath: Mirrors:map[] Configs:map[] Auths:map[] Headers:map[]} ImageDecryption:{KeyModel:node} DisableTCPService:true StreamServerAddress:127.0.0.1 StreamServerPort:0 StreamIdleTimeout:4h0m0s EnableSelinux:false SelinuxCategoryRange:0 SandboxImage:registry.k8s.io/pause:3.8 StatsCollectPeriod:10 SystemdCgroup:false EnableTLSStreaming:false X509KeyPairStreaming:{TLSCertFile: TLSKeyFile:} MaxContainerLogLineSize:16384 DisableCgroup:false DisableApparmor:false RestrictOOMScoreAdj:false MaxConcurrentDownloads:3 DisableProcMount:false UnsetSeccompProfile: TolerateMissingHugetlbController:false DisableHugetlbController:false DeviceOwnershipFromSecurityContext:false IgnoreImageDefinedVolumes:false NetNSMountsUnderStateDir:false EnableUnprivilegedPorts:false EnableUnprivilegedICMP:false EnableCDI:false CDISpecDirs:[] ImagePullProgressTimeout:1m0s} ContainerdRootDir:C:\\Users\\RUNNER~1\\AppData\\Local\\Temp\\TestRestartMonitor708044512\\001\\root ContainerdEndpoint:\\\\.\\pipe\\containerd-containerd-test-001 RootDir:C:\\Users\\RUNNER~1\\AppData\\Local\\Temp\\TestRestartMonitor708044512\\001\\root\\io.containerd.grpc.v1.cri StateDir:C:\\Users\\RUNNER~1\\AppData\\Local\\Temp\\TestRestartMonitor708044512\\001\\state\\io.containerd.grpc.v1.cri}" time="2023-01-23T12:58:16.187607000Z" level=info msg="Connect containerd service" time="2023-01-23T12:58:16.187607000Z" level=info msg="using legacy CRI server" time="2023-01-23T12:58:16.187607000Z" level=info msg="Get image filesystem path \"C:\\\\Users\\\\RUNNER~1\\\\AppData\\\\Local\\\\Temp\\\\TestRestartMonitor708044512\\\\001\\\\root\\\\io.containerd.snapshotter.v1.windows\"" time="2023-01-23T12:58:16.188644700Z" level=info msg="using experimental NRI integration - disable nri plugin to prevent this" time="2023-01-23T12:58:16.188644700Z" level=info msg="loading plugin \"io.containerd.tracing.processor.v1.otlp\"..." type=io.containerd.tracing.processor.v1 time="2023-01-23T12:58:16.188644700Z" level=info msg="skip loading plugin \"io.containerd.tracing.processor.v1.otlp\"..." error="no OpenTelemetry endpoint: skip plugin" type=io.containerd.tracing.processor.v1 time="2023-01-23T12:58:16.188644700Z" level=info msg="loading plugin \"io.containerd.internal.v1.tracing\"..." type=io.containerd.internal.v1 time="2023-01-23T12:58:16.188644700Z" level=info msg="skipping tracing processor initialization (no tracing plugin)" error="no OpenTelemetry endpoint: skip plugin" time="2023-01-23T12:58:16.189160000Z" level=info msg="Start subscribing containerd event" time="2023-01-23T12:58:16.189160000Z" level=info msg=serving... address="\\\\.\\pipe\\containerd-containerd-test-001.ttrpc" time="2023-01-23T12:58:16.189160000Z" level=info msg="Start recovering state" time="2023-01-23T12:58:16.189160000Z" level=info msg=serving... address="\\\\.\\pipe\\containerd-containerd-test-001" time="2023-01-23T12:58:16.189160000Z" level=info msg="containerd successfully booted in 0.098046s" time="2023-01-23T12:58:16.189667800Z" level=info msg="Start event monitor" time="2023-01-23T12:58:16.189667800Z" level=info msg="Start snapshots syncer" time="2023-01-23T12:58:16.189667800Z" level=info msg="Start cni network conf syncer for default" time="2023-01-23T12:58:16.189667800Z" level=info msg="Start streaming server" time="2023-01-23T12:58:36.200566700Z" level=error msg=monitor error="no running task found: task TestRestartMonitor_Always not found: not found" time="2023-01-23T12:58:36.275220800Z" level=info msg=Span duration=30.561ms endTime="2023-01-23 12:58:36.3057818 +0000 GMT m=+0.055936101" name="hcsshim::ActivateLayer" parentSpanID=dd4b54b1d415de6c path="C:\\Users\\RUNNER~1\\AppData\\Local\\Temp\\TestRestartMonitor708044512\\001\\root\\io.containerd.snapshotter.v1.windows\\snapshots\\2" spanID=34f7c048d3e5fb9a startTime="2023-01-23 12:58:36.2752208 +0000 GMT m=+0.025375101" traceID=7cea767b0607fdbd30d0ed3eb2045b0a time="2023-01-23T12:58:36.344019100Z" level=info msg=Span duration=1.017ms endTime="2023-01-23 12:58:36.3450361 +0000 GMT m=+0.095189201" guid=65ed1907-894d-50ff-bdcb-cc63fb515966 name="hcsshim::NameToGuid" objectName=1 parentSpanID=e24d9a77d08537f7 spanID=39f9060fcf555525 startTime="2023-01-23 12:58:36.3440191 +0000 GMT m=+0.094172201" traceID=7cea767b0607fdbd30d0ed3eb2045b0a time="2023-01-23T12:58:36.344019100Z" level=info msg=Span duration=1.0794ms endTime="2023-01-23 12:58:36.3450985 +0000 GMT m=+0.095251601" name="hcsshim::LayerID" parentSpanID=8ba22de0d1b519c9 path="C:\\Users\\RUNNER~1\\AppData\\Local\\Temp\\TestRestartMonitor708044512\\001\\root\\io.containerd.snapshotter.v1.windows\\snapshots\\1" spanID=e24d9a77d08537f7 startTime="2023-01-23 12:58:36.3440191 +0000 GMT m=+0.094172201" traceID=7cea767b0607fdbd30d0ed3eb2045b0a time="2023-01-23T12:58:36.344019100Z" level=error msg=Span duration=90.0069ms endTime="2023-01-23 12:58:36.434026 +0000 GMT m=+0.184179101" error="hcsshim::PrepareLayer failed in Win32: Access is denied. (0x5)" name="hcsshim::PrepareLayer" parentLayerPaths="C:\\Users\\RUNNER~1\\AppData\\Local\\Temp\\TestRestartMonitor708044512\\001\\root\\io.containerd.snapshotter.v1.windows\\snapshots\\1" parentSpanID=dd4b54b1d415de6c path="C:\\Users\\RUNNER~1\\AppData\\Local\\Temp\\TestRestartMonitor708044512\\001\\root\\io.containerd.snapshotter.v1.windows\\snapshots\\2" spanID=8ba22de0d1b519c9 startTime="2023-01-23 12:58:36.3440191 +0000 GMT m=+0.094172201" traceID=7cea767b0607fdbd30d0ed3eb2045b0a time="2023-01-23T12:58:36.434027500Z" level=info msg=Span duration=12.8255ms endTime="2023-01-23 12:58:36.446853 +0000 GMT m=+0.197004601" name="hcsshim::DeactivateLayer" parentSpanID=dd4b54b1d415de6c path="C:\\Users\\RUNNER~1\\AppData\\Local\\Temp\\TestRestartMonitor708044512\\001\\root\\io.containerd.snapshotter.v1.windows\\snapshots\\2" spanID=90a473a6cd257353 startTime="2023-01-23 12:58:36.4340275 +0000 GMT m=+0.184179101" traceID=7cea767b0607fdbd30d0ed3eb2045b0a time="2023-01-23T12:58:36.274097200Z" level=error msg=Span bundle="C:\\Users\\RUNNER~1\\AppData\\Local\\Temp\\TestRestartMonitor708044512\\001\\state\\io.containerd.runtime.v2.task\\testing\\TestRestartMonitor_Always" checkpoint= duration=173.2594ms endTime="2023-01-23 12:58:36.4473566 +0000 GMT m=+0.197510901" error="failed to mount container storage: hcsshim::PrepareLayer failed in Win32: Access is denied. (0x5)" name=Create parentSpanID=86a0e719d645c03e parentcheckpoint= spanID=dd4b54b1d415de6c startTime="2023-01-23 12:58:36.2740972 +0000 GMT m=+0.024251501" stderr= stdin= stdout= terminal=false tid=TestRestartMonitor_Always traceID=7cea767b0607fdbd30d0ed3eb2045b0a time="2023-01-23T12:58:36.274097200Z" level=info msg=Span duration=173.3365ms endTime="2023-01-23 12:58:36.4474337 +0000 GMT m=+0.197588001" name=containerd.task.v2.Task.Create parentSpanID=0000000000000000 spanID=86a0e719d645c03e startTime="2023-01-23 12:58:36.2740972 +0000 GMT m=+0.024251501" traceID=7cea767b0607fdbd30d0ed3eb2045b0a time="2023-01-23T12:58:36.448096600Z" level=error msg=Span duration=0s eid= endTime="2023-01-23 12:58:36.4480966 +0000 GMT m=+0.198248001" error="rpc error: code = NotFound desc = task with id: 'TestRestartMonitor_Always' not found: not found" name=Delete parentSpanID=e74fe03dccf59081 spanID=3efb4cd5cac5aeaf startTime="2023-01-23 12:58:36.4480966 +0000 GMT m=+0.198248001" tid=TestRestartMonitor_Always traceID=b71dd9d22750428ff989c04dfcaec5f2 time="2023-01-23T12:58:36.448096600Z" level=info msg=Span duration=0s endTime="2023-01-23 12:58:36.4480966 +0000 GMT m=+0.198248001" name=containerd.task.v2.Task.Delete parentSpanID=0000000000000000 spanID=e74fe03dccf59081 startTime="2023-01-23 12:58:36.4480966 +0000 GMT m=+0.198248001" traceID=b71dd9d22750428ff989c04dfcaec5f2 time="2023-01-23T12:58:36.448648400Z" level=info msg=Span duration=0s endTime="2023-01-23 12:58:36.4486484 +0000 GMT m=+0.198799701" name=Shutdown parentSpanID=95a6b96cc995ccdd spanID=ec512604c865ea0b startTime="2023-01-23 12:58:36.4486484 +0000 GMT m=+0.198799701" tid=TestRestartMonitor_Always traceID=5eae45fc465ea23c5b111bb8a920544a time="2023-01-23T12:58:36.448648400Z" level=info msg=Span duration=0s endTime="2023-01-23 12:58:36.4486484 +0000 GMT m=+0.198799701" name=containerd.task.v2.Task.Shutdown parentSpanID=0000000000000000 spanID=95a6b96cc995ccdd startTime="2023-01-23 12:58:36.4486484 +0000 GMT m=+0.198799701" traceID=5eae45fc465ea23c5b111bb8a920544a time="2023-01-23T12:58:36.4[49](https://github.com/containerd/containerd/actions/runs/3986308559/jobs/6834893977#step:16:50)154400Z" level=info msg="shim disconnected" id=TestRestartMonitor_Always namespace=testing time="2023-01-23T12:58:36.449154400Z" level=warning msg="cleaning up after shim disconnected" id=TestRestartMonitor_Always namespace=testing time="2023-01-23T12:58:36.449154400Z" level=info msg="cleaning up dead shim" namespace=testing time="2023-01-23T12:58:36.448648400Z" level=fatal msg="containerd-shim: ttrpc server failure" error="ttrpc: server closed" time="2023-01-23T12:58:36.510477[50](https://github.com/containerd/containerd/actions/runs/3986308559/jobs/6834893977#step:16:51)0Z" level=warning msg="cleanup warnings time=\"2023-01-23T12:58:36Z\" level=error msg=Span duration=3.1471ms endTime=\"2023-01-23 12:58:36.4657278 +0000 GMT m=+0.008440201\" error=\"A virtual machine or container with the specified identifier does not exist.\" name=HcsOpenComputeSystem parentSpanID=96c3263c055f274d spanID=83dc3db5d0a6784e startTime=\"2023-01-23 12:58:36.4625807 +0000 GMT m=+0.005293101\" traceID=80c760e6081dc769adf3d81731c22f62\ntime=\"2023-01-23T12:58:36Z\" level=info msg=Span duration=37.6528ms endTime=\"2023-01-23 12:58:36.5002335 +0000 GMT m=+0.042945901\" name=delete parentSpanID=0000000000000000 spanID=96c3263c055f274d startTime=\"2023-01-23 12:58:36.4625807 +0000 GMT m=+0.005293101\" traceID=80c760e6081dc769adf3d81731c22f62\n" namespace=testing time="2023-01-23T12:58:36.[51](https://github.com/containerd/containerd/actions/runs/3986308559/jobs/6834893977#step:16:52)2343300Z" level=error msg="apply change" error="failed to create shim task: failed to mount container storage: hcsshim::PrepareLayer failed in Win32: Access is denied. (0x5): unknown" time="2023-01-23T12:58:36.475388300Z" level=info msg=Span duration=21.5849ms endTime="2023-01-23 12:58:36.4969732 +0000 GMT m=+0.060077801" name="hcsshim::ActivateLayer" parentSpanID=34d2cb2a99a038f5 path="C:\\Users\\RUNNER~1\\AppData\\Local\\Temp\\TestRestartMonitor708044512\\001\\root\\io.containerd.snapshotter.v1.windows\\snapshots\\3" spanID=3fbd12c37ea964c7 startTime="2023-01-23 12:58:36.4753883 +0000 GMT m=+0.038492901" traceID=3e402d8b886026858c97c3aac9d46007 time="2023-01-23T12:58:36.535677600Z" level=info msg=Span duration="[52](https://github.com/containerd/containerd/actions/runs/3986308559/jobs/6834893977#step:16:53)3.4µs" endTime="2023-01-23 12:58:36.[53](https://github.com/containerd/containerd/actions/runs/3986308559/jobs/6834893977#step:16:54)6201 +0000 GMT m=+0.099304501" guid=65ed1907-894d-50ff-bdcb-cc63fb515966 name="hcsshim::NameToGuid" objectName=1 parentSpanID=5593a0f349bbbc6b spanID=607ee78b2fc4e83d startTime="2023-01-23 12:58:36.5356776 +0000 GMT m=+0.098781101" traceID=3e402d8b886026858c97c3aac9d46007 time="2023-01-23T12:58:36.535677600Z" level=info msg=Span duration="523.4µs" endTime="2023-01-23 12:58:36.536201 +0000 GMT m=+0.099304501" name="hcsshim::LayerID" parentSpanID=4aa8595b64b29099 path="C:\\Users\\RUNNER~1\\AppData\\Local\\Temp\\TestRestartMonitor708044512\\001\\root\\io.containerd.snapshotter.v1.windows\\snapshots\\1" spanID=5593a0f349bbbc6b startTime="2023-01-23 12:58:36.5356776 +0000 GMT m=+0.098781101" traceID=3e402d8b886026858c97c3aac9d46007 time="2023-01-23T12:58:36.535677600Z" level=info msg=Span duration=52.6497ms endTime="2023-01-23 12:58:36.5883273 +0000 GMT m=+0.151430801" name="hcsshim::PrepareLayer" parentLayerPaths="C:\\Users\\RUNNER~1\\AppData\\Local\\Temp\\TestRestartMonitor708044512\\001\\root\\io.containerd.snapshotter.v1.windows\\snapshots\\1" parentSpanID=34d2cb2a99a038f5 path="C:\\Users\\RUNNER~1\\AppData\\Local\\Temp\\TestRestartMonitor708044512\\001\\root\\io.containerd.snapshotter.v1.windows\\snapshots\\3" spanID=4aa8595b64b29099 startTime="2023-01-23 12:58:36.5356776 +0000 GMT m=+0.098781101" traceID=3e402d8b886026858c97c3aac9d46007 time="2023-01-23T12:58:36.596083400Z" level=info msg=Span duration="531.1µs" endTime="2023-01-23 12:58:36.5966145 +0000 GMT m=+0.159717001" mountPath="\\\\?\\Volume{d0080c3c-e68e-46[54](https://github.com/containerd/containerd/actions/runs/3986308559/jobs/6834893977#step:16:55)-923f-373f0b2754cd}" name="hcsshim::GetLayerMountPath" parentSpanID=34d2cb2a99a038f5 path="C:\\Users\\RUNNER~1\\AppData\\Local\\Temp\\TestRestartMonitor708044512\\001\\root\\io.containerd.snapshotter.v1.windows\\snapshots\\3" spanID=6b692e2415cd1410 startTime="2023-01-23 12:58:36.5960834 +0000 GMT m=+0.159185901" traceID=3e402d8b886026858c97c3aac9d46007 time="2023-01-23T12:58:36.597133700Z" level=info msg=Span duration=0s endTime="2023-01-23 12:58:36.5971337 +0000 GMT m=+0.160236201" guid=65ed1907-894d-50ff-bdcb-cc63fb515966 name="hcsshim::NameToGuid" objectName=1 parentSpanID=765475bcfad540e2 spanID=813fbc54e0de6cb4 startTime="2023-01-23 12:58:36.5971337 +0000 GMT m=+0.160236201" traceID=3e402d8b886026858c97c3aac9d46007 time="2023-01-23T12:58:36.597133700Z" level=info msg=Span duration=0s endTime="2023-01-23 12:58:36.5971337 +0000 GMT m=+0.160236201" name="hcsshim::LayerID" parentSpanID=34d2cb2a99a038f5 path="C:\\Users\\RUNNER~1\\AppData\\Local\\Temp\\TestRestartMonitor708044512\\001\\root\\io.containerd.snapshotter.v1.windows\\snapshots\\1" spanID=765475bcfad540e2 startTime="2023-01-23 12:58:36.5971337 +0000 GMT m=+0.160236201" traceID=3e402d8b886026858c97c3aac9d46007 time="2023-01-23T12:58:36.598165900Z" level=info msg=Span configuration="{\"Owner\":\"containerd-shim-runhcs-v1.exe\",\"SchemaVersion\":{\"Major\":2,\"Minor\":1},\"Container\":{\"Storage\":{\"Layers\":[{\"Id\":\"65ed1907-894d-50ff-bdcb-cc63fb515966\",\"Path\":\"C:\\\\Users\\\\RUNNER~1\\\\AppData\\\\Local\\\\Temp\\\\TestRestartMonitor708044512\\\\001\\\\root\\\\io.containerd.snapshotter.v1.windows\\\\snapshots\\\\1\"}],\"Path\":\"\\\\\\\\?\\\\Volume{d0080c3c-e68e-4654-923f-373f0b2754cd}\\\\\"},\"Processor\":{},\"RegistryChanges\":{\"AddValues\":[{\"Key\":{\"Hive\":\"System\",\"Name\":\"ControlSet001\\\\Control\"},\"Name\":\"WaitToKillServiceTimeout\",\"Type\":\"String\",\"StringValue\":\"2147483647\"}]}},\"ShouldTerminateOnLastHandleClosed\":true}" duration=1.[55](https://github.com/containerd/containerd/actions/runs/3986308559/jobs/6834893977#step:16:56)44ms endTime="2023-01-23 12:58:36.5997203 +0000 GMT m=+0.162822801" id=TestRestartMonitor_Failure_Policy name=HcsCreateComputeSystem parentSpanID=8c2a03edc5e79886 spanID=97154a85abf0c458 startTime="2023-01-23 12:58:36.5981659 +0000 GMT m=+0.161268401" traceID=3e402d8b886026858c97c3aac9d46007 time="2023-01-23T12:58:36.599720400Z" level=info msg=Span duration=0s endTime="2023-01-23 12:58:36.5997204 +0000 GMT m=+0.162822801" name=HcsRegisterComputeSystemCallback parentSpanID=8c2a03edc5e79886 spanID=a200911d91f9f02a startTime="2023-01-23 12:58:36.5997204 +0000 GMT m=+0.162822801" traceID=3e402d8b886026858c97c3aac9d46007 time="2023-01-23T12:58:36.673319500Z" level=info msg=Span duration=0s endTime="2023-01-23 12:58:36.6733195 +0000 GMT m=+0.236420701" name=HcsGetComputeSystemProperties parentSpanID=8c2a03edc5e79886 propertyQuery="{}" spanID=adebd7b576021dfd startTime="2023-01-23 12:58:36.6733195 +0000 GMT m=+0.236420701" traceID=3e402d8b886026858c97c3aac9d46007 time="2023-01-23T12:58:36.597133700Z" level=info msg=Span cid=TestRestartMonitor_Failure_Policy duration=76.7116ms endTime="2023-01-23 12:58:36.6738453 +0000 GMT m=+0.236947801" name="hcs::CreateComputeSystem" parentSpanID=34d2cb2a99a038f5 spanID=8c2a03edc5e79886 startTime="2023-01-23 12:58:36.5971337 +0000 GMT m=+0.160236201" traceID=3e402d8b886026858c97c3aac9d46007 time="2023-01-23T12:58:36.673846600Z" level=info msg=Span duration="527µs" endTime="2023-01-23 12:58:36.6743736 +0000 GMT m=+0.237474801" event="&TaskCreate{ContainerID:TestRestartMonitor_Failure_Policy,Bundle:C:\\Users\\RUNNER~1\\AppData\\Local\\Temp\\TestRestartMonitor708044512\\001\\state\\io.containerd.runtime.v2.task\\testing\\TestRestartMonitor_Failure_Policy,Rootfs:[]*Mount{&types.Mount{Type:windows-layer,Source:C:\\Users\\RUNNER~1\\AppData\\Local\\Temp\\TestRestartMonitor708044512\\001\\root\\io.containerd.snapshotter.v1.windows\\snapshots\\3,Target:,Options:[rw parentLayerPaths=[\"C:\\\\Users\\\\RUNNER~1\\\\AppData\\\\Local\\\\Temp\\\\TestRestartMonitor708044512\\\\001\\\\root\\\\io.containerd.snapshotter.v1.windows\\\\snapshots\\\\1\"]],XXX_unrecognized:[],},},IO:&TaskIO{Stdin:\\\\.\\pipe\\ctr-TestRestartMonitor_Failure_Policy-stdin,Stdout:\\\\.\\pipe\\ctr-TestRestartMonitor_Failure_Policy-stdout,Stderr:,Terminal:true,XXX_unrecognized:[],},Checkpoint:,Pid:0,XXX_unrecognized:[],}" name=publishEvent parentSpanID=34d2cb2a99a038f5 spanID=b8d61e4e5c0b49cf startTime="2023-01-23 12:58:36.6738466 +0000 GMT m=+0.236947801" topic=/tasks/create traceID=3e402d8b886026858c97c3aac9d46007 time="2023-01-23T12:58:36.474880100Z" level=info msg=Span bundle="C:\\Users\\RUNNER~1\\AppData\\Local\\Temp\\TestRestartMonitor708044512\\001\\state\\io.containerd.runtime.v2.task\\testing\\TestRestartMonitor_Failure_Policy" checkpoint= duration=199.4901ms endTime="2023-01-23 12:58:36.6743702 +0000 GMT m=+0.237474801" name=Create parentSpanID=29e78492b3970c23 parentcheckpoint= pid=0 spanID=34d2cb2a99a038f5 startTime="2023-01-23 12:58:36.4748801 +0000 GMT m=+0.037984701" stderr= stdin="\\\\.\\pipe\\ctr-TestRestartMonitor_Failure_Policy-stdin" stdout="\\\\.\\pipe\\ctr-TestRestartMonitor_Failure_Policy-stdout" terminal=true tid=TestRestartMonitor_Failure_Policy traceID=3e402d8b886026858c97c3aac9d46007 time="2023-01-23T12:58:36.474880100Z" level=info msg=Span duration=199.4901ms endTime="2023-01-23 12:58:36.6743702 +0000 GMT m=+0.237474801" name=containerd.task.v2.Task.Create parentSpanID=0000000000000000 spanID=29e78492b3970c23 startTime="2023-01-23 12:58:36.4748801 +0000 GMT m=+0.037984701" traceID=3e402d8b886026858c97c3aac9d46007 time="2023-01-23T12:58:36.674905700Z" level=info msg=Span duration=0s endTime="2023-01-23 12:58:36.6749057 +0000 GMT m=+0.238006901" name=Connect parentSpanID=e4823aaff22ef917 shimPid=2988 spanID=ef6d8147d83725ea startTime="2023-01-23 12:58:36.6749057 +0000 GMT m=+0.238006901" taskPid=2988 tid=TestRestartMonitor_Failure_Policy traceID=d7f14e276f788001ceb2378f848fd969 version= time="2023-01-23T12:58:36.674905700Z" level=info msg=Span duration=0s endTime="2023-01-23 12:58:36.6749057 +0000 GMT m=+0.238006901" name=containerd.task.v2.Task.Connect parentSpanID=0000000000000000 spanID=e4823aaff22ef917 startTime="2023-01-23 12:58:36.6749057 +0000 GMT m=+0.238006901" traceID=d7f14e276f788001ceb2378f848fd969 time="2023-01-23T12:58:36.676462700Z" level=info msg=Span duration="62.5µs" endTime="2023-01-23 12:58:36.6765252 +0000 GMT m=+0.239626301" name=HcsStartComputeSystem options= parentSpanID=102f[56](https://github.com/containerd/containerd/actions/runs/3986308559/jobs/6834893977#step:16:57)108952a960 spanID=1b1a9da86e5bd532 startTime="2023-01-23 12:58:36.6764627 +0000 GMT m=+0.239563801" traceID=46c581bdc00c11ec4cebfb8e5f6ef826 time="2023-01-23T12:58:36.676462700Z" level=info msg=Span cid=TestRestartMonitor_Failure_Policy duration=1.0465512s endTime="2023-01-23 12:58:37.7230139 +0000 GMT m=+1.286115001" name="hcs::System::Start" parentSpanID=05440f78a3497d8e spanID=102f56108952a960 startTime="2023-01-23 12:58:36.6764627 +0000 GMT m=+0.239563801" traceID=46c581bdc00c11ec4cebfb8e5f6ef826 time="2023-01-23T12:58:37.723031300Z" level=info msg=Span duration=141.6145ms endTime="2023-01-23 12:58:37.8646458 +0000 GMT m=+1.427729501" name=HcsCreateProcess parentSpanID=0000000000000000 processParameters="{\"CommandLine\":\"cmd /c exit 1\",\"User\":\"ContainerUser\",\"CreateStdInPipe\":true,\"CreateStdOutPipe\":true}" spanID=2605e44054640105 startTime="2023-01-23 12:58:37.7230313 +0000 GMT m=+1.286115001" traceID=fb97e76b860c3e2c4333c34e3d2f45d2 time="2023-01-23T12:58:37.864648100Z" level=info msg=Span duration=0s endTime="2023-01-23 12:58:37.8646481 +0000 GMT m=+1.427729501" name=HcsRegisterProcessCallback parentSpanID=0000000000000000 spanID=31f02ad9396d2dd7 startTime="2023-01-23 12:58:37.8646481 +0000 GMT m=+1.427729501" traceID=eee903b2ddf43bd742b5ae7cf8393bb4 time="2023-01-23T12:58:37.874141700Z" level=info msg=Span duration="510.3µs" endTime="2023-01-23 12:58:37.874652 +0000 GMT m=+1.437733201" name=HcsGetProcessProperties parentSpanID=47c6b8090[57](https://github.com/containerd/containerd/actions/runs/3986308559/jobs/6834893977#step:16:58)f857b spanID=52b1ffa1ea87b14d startTime="2023-01-23 12:[58](https://github.com/containerd/containerd/actions/runs/3986308559/jobs/6834893977#step:16:59):37.8741417 +0000 GMT m=+1.437222901" traceID=390d3fa7dd5d86f918f29e6a808e5c97 time="2023-01-23T12:58:37.874141700Z" level=info msg=Span cid=TestRestartMonitor_Failure_Policy duration="510.3µs" endTime="2023-01-23 12:58:37.874652 +0000 GMT m=+1.437733201" name="hcs::Process::waitBackground" parentSpanID=0000000000000000 pid=1804 spanID=47c6b809057f857b startTime="2023-01-23 12:58:37.8741417 +0000 GMT m=+1.437222901" traceID=390d3fa7dd5d86f918f29e6a808e5c97 time="2023-01-23T12:58:37.874652000Z" level=info msg=Span cid=TestRestartMonitor_Failure_Policy duration=0s endTime="2023-01-23 12:58:37.874652 +0000 GMT m=+1.437733201" name="hcs::Process::CloseStdin" parentSpanID=0000000000000000 pid=1804 spanID=5d9c463ad090dd1f startTime="2023-01-23 12:58:37.874652 +0000 GMT m=+1.437733201" traceID=15df3f854458dbfbfe341304130b6ebb time="2023-01-23T12:58:37.874652000Z" level=info msg=Span cid=TestRestartMonitor_Failure_Policy duration=0s endTime="2023-01-23 12:58:37.874652 +0000 GMT m=+1.437733201" name="hcs::Process::CloseStdout" parentSpanID=0000000000000000 pid=1804 spanID=68878dd2b[59](https://github.com/containerd/containerd/actions/runs/3986308559/jobs/6834893977#step:16:60)909f2 startTime="2023-01-23 12:58:37.874652 +0000 GMT m=+1.437733201" traceID=e883d7ebbda197fe2fe2f7ae75769b70 time="2023-01-23T12:58:37.874141700Z" level=info msg=Span duration="866.9µs" endTime="2023-01-23 12:58:37.8750086 +0000 GMT m=+1.438089801" event="&TaskStart{ContainerID:TestRestartMonitor_Failure_Policy,Pid:1804,XXX_unrecognized:[],}" name=publishEvent parentSpanID=05440f78a3497d8e spanID=3cdb71711f7659a9 startTime="2023-01-23 12:58:37.8741417 +0000 GMT m=+1.437222901" topic=/tasks/start traceID=46c581bdc00c11ec4cebfb8e5f6ef826 time="2023-01-23T12:58:36.675957000Z" level=info msg=Span duration=1.1996113s eid= endTime="2023-01-23 12:58:37.8755683 +0000 GMT m=+1.438669401" name=Start parentSpanID=fa58c8dfbd4051bc pid=1804 spanID=05440f78a3497d8e startTime="2023-01-23 12:58:36.675957 +0000 GMT m=+0.239058101" tid=TestRestartMonitor_Failure_Policy traceID=46c581bdc00c11ec4cebfb8e5f6ef826 time="2023-01-23T12:58:36.675957000Z" level=info msg=Span duration=1.1996113s endTime="2023-01-23 12:58:37.8755683 +0000 GMT m=+1.438669401" name=containerd.task.v2.Task.Start parentSpanID=0000000000000000 spanID=fa58c8dfbd4051bc startTime="2023-01-23 12:58:36.675957 +0000 GMT m=+0.239058101" traceID=46c581bdc00c11ec4cebfb8e5f6ef826 time="2023-01-23T12:58:37.875588200Z" level=info msg=Span duration=0s endTime="2023-01-23 12:58:37.8755882 +0000 GMT m=+1.438669401" name=HcsUnregisterProcessCallback parentSpanID=7e5d1b0381ab6196 spanID=8948629b66b48d68 startTime="2023-01-23 12:58:37.8755882 +0000 GMT m=+1.438669401" traceID=5cb4285aba472a72de0ef65bad321a10 time="2023-01-23T12:58:37.876203300Z" level=info msg=Span duration=0s endTime="2023-01-23 12:58:37.8762033 +0000 GMT m=+1.439284501" name=HcsCloseProcess parentSpanID=7e5d1b0381ab6196 spanID=9433a9334cbdb93a startTime="2023-01-23 12:58:37.8762033 +0000 GMT m=+1.439284501" traceID=5cb4285aba472a72de0ef65bad321a10 time="2023-01-23T12:58:37.875588200Z" level=info msg=Span cid=TestRestartMonitor_Failure_Policy duration="615.1µs" endTime="2023-01-23 12:58:37.8762033 +0000 GMT m=+1.439284501" name="hcs::Process::Close" parentSpanID=0000000000000000 pid=1804 spanID=7e5d1b0381ab6196 startTime="2023-01-23 12:58:37.8755882 +0000 GMT m=+1.438669401" traceID=5cb4285aba472a72de0ef65bad321a10 time="2023-01-23T12:58:37.875588200Z" level=info msg=Span duration="615.1µs" eid=TestRestartMonitor_Failure_Policy endTime="2023-01-23 12:58:37.8762033 +0000 GMT m=+1.439284501" name="hcsExec::waitForExit" parentSpanID=0000000000000000 spanID=7372d46a9ba235c4 startTime="2023-01-23 12:58:37.8755882 +0000 GMT m=+1.438669401" tid=TestRestartMonitor_Failure_Policy traceID=df6bdf6a1188abb994807906afbcd4ea time="2023-01-23T12:58:37.876203300Z" level=info msg=Span duration="508µs" endTime="2023-01-23 12:58:37.8767113 +0000 GMT m=+1.439792501" name=HcsShutdownComputeSystem options= parentSpanID=d997f31[60](https://github.com/containerd/containerd/actions/runs/3986308559/jobs/6834893977#step:16:61)d26cd45 spanID=b5f47dfcfcd73db1 startTime="2023-01-23 12:58:37.8762033 +0000 GMT m=+1.439284501" traceID=6efd355c108e3130e703091c18182e4c time="2023-01-23T12:58:37.876203300Z" level=info msg=Span duration=0s eid= endTime="2023-01-23 12:58:37.8762033 +0000 GMT m=+1.439284501" exitStatus=1 exitedAt="2023-01-23 12:58:37.8755882 +0000 GMT m=+1.438669401" name=State parentSpanID=9f1ef0cb31c6e50c spanID=aa09376417cf11df startTime="2023-01-23 12:58:37.8762033 +0000 GMT m=+1.439284501" status=STOPPED tid=TestRestartMonitor_Failure_Policy traceID=d3a5af567f4aec654f9bbd89853814e8 time="2023-01-23T12:58:37.876203300Z" level=info msg=Span duration=13.9423ms endTime="2023-01-23 12:58:37.8901456 +0000 GMT m=+1.453226801" name=containerd.task.v2.Task.State parentSpanID=0000000000000000 spanID=9f1ef0cb31c6e50c startTime="2023-01-23 12:58:37.8762033 +0000 GMT m=+1.439284501" traceID=d3a5af567f4aec654f9bbd89853814e8 time="2023-01-23T12:58:36.673846600Z" level=info msg=Span duration=1.2017216s eid=TestRestartMonitor_Failure_Policy endTime="2023-01-23 12:58:37.8755682 +0000 GMT m=+1.438669401" name="hcsExec::waitForContainerExit" parentSpanID=0000000000000000 spanID=ceacac7e271da173 startTime="2023-01-23 12:58:36.6738466 +0000 GMT m=+0.236947801" tid=TestRestartMonitor_Failure_Policy traceID=0038eb25ab459b92b4563d8d1becc29d time="2023-01-23T12:58:37.892368600Z" level=info msg=Span duration="507.6µs" endTime="2023-01-23 12:58:37.8928762 +0000 GMT m=+1.455957101" name=Connect parentSpanID=c0dfc494e2e06983 shimPid=2988 spanID=cbca0b2dc8e99555 startTime="2023-01-23 12:58:37.8923686 +0000 GMT m=+1.455449501" taskPid=2988 tid=TestRestartMonitor_Failure_Policy traceID=9ca0076f301b71f40fb167715f7db6ed version= time="2023-01-23T12:58:37.892368600Z" level=info msg=Span duration="507.6µs" endTime="2023-01-23 12:58:37.8928762 +0000 GMT m=+1.455957101" name=containerd.task.v2.Task.Connect parentSpanID=0000000000000000 spanID=c0dfc494e2e06983 startTime="2023-01-23 12:58:37.8923686 +0000 GMT m=+1.455449501" traceID=9ca0076f301b71f40fb167715f7db6ed time="2023-01-23T12:58:36.673846600Z" level=info msg=Span cid=TestRestartMonitor_Failure_Policy duration=1.3820758s endTime="2023-01-23 12:58:38.0559224 +0000 GMT m=+1.[61](https://github.com/containerd/containerd/actions/runs/3986308559/jobs/6834893977#step:16:62)9023601" name="hcs::System::waitBackground" parentSpanID=0000000000000000 spanID=c3c165e6411475a1 startTime="2023-01-23 12:58:36.6738466 +0000 GMT m=+0.236947801" traceID=84492429b0c2acabdef4f0aa78919c94 time="2023-01-23T12:58:38.055945400Z" level=info msg=Span duration=3.1561ms endTime="2023-01-23 12:58:38.0591015 +0000 GMT m=+1.[62](https://github.com/containerd/containerd/actions/runs/3986308559/jobs/6834893977#step:16:63)2179701" name="hcsshim::UnprepareLayer" parentSpanID=d997f3160d26cd45 path="C:\\Users\\RUNNER~1\\AppData\\Local\\Temp\\TestRestartMonitor708044512\\001\\root\\io.containerd.snapshotter.v1.windows\\snapshots\\3" spanID=ec8be0f578041acc startTime="2023-01-23 12:58:38.0559454 +0000 GMT m=+1.619023601" traceID=6efd355c108e3130e703091c18182e4c time="2023-01-23T12:58:38.059101500Z" level=info msg=Span duration=90.62[63](https://github.com/containerd/containerd/actions/runs/3986308559/jobs/6834893977#step:16:64)ms endTime="2023-01-23 12:58:38.1497278 +0000 GMT m=+1.712806001" name="hcsshim::DeactivateLayer" parentSpanID=d997f3160d26cd45 path="C:\\Users\\RUNNER~1\\AppData\\Local\\Temp\\TestRestartMonitor708044512\\001\\root\\io.containerd.snapshotter.v1.windows\\snapshots\\3" spanID=f776278e5e0d469e startTime="2023-01-23 12:58:38.0591015 +0000 GMT m=+1.622179701" traceID=6efd355c108e3130e703091c18182e4c time="2023-01-23T12:58:38.149729200Z" level=info msg=Span duration=0s endTime="2023-01-23 12:58:38.1497292 +0000 GMT m=+1.712806001" name=HcsUnregisterComputeSystemCallback parentSpanID=02626e2[64](https://github.com/containerd/containerd/actions/runs/3986308559/jobs/6834893977#step:16:65)4167270 spanID=0d4db5be291f9e42 startTime="2023-01-23 12:58:38.1497292 +0000 GMT m=+1.712806001" traceID=d3260a62b693d755ec25392f9834b403 time="2023-01-23T12:58:38.149729200Z" level=info msg=Span duration=0s endTime="2023-01-23 12:58:38.1497292 +0000 GMT m=+1.712806001" name=HcsCloseComputeSystem parentSpanID=02626e2644167270 spanID=1838fc560f28ca14 startTime="2023-01-23 12:58:38.1497292 +0000 GMT m=+1.712806001" traceID=d3260a62b693d755ec25392f9834b403 time="2023-01-23T12:58:38.149729200Z" level=info msg=Span cid=TestRestartMonitor_Failure_Policy duration=0s endTime="2023-01-23 12:58:38.1497292 +0000 GMT m=+1.712806001" name="hcs::System::Close" parentSpanID=0000000000000000 spanID=02626e2644167270 startTime="2023-01-23 12:58:38.1497292 +0000 GMT m=+1.712806001" traceID=d3260a62b693d755ec25392f9834b403 time="2023-01-23T12:58:38.149729200Z" level=info msg=Span duration="532.7µs" endTime="2023-01-23 12:58:38.1502619 +0000 GMT m=+1.713338701" event="&TaskExit{ContainerID:TestRestartMonitor_Failure_Policy,ID:TestRestartMonitor_Failure_Policy,Pid:1804,ExitStatus:1,ExitedAt:2023-01-23 12:58:37.8755882 +0000 GMT m=+1.438669401,XXX_unrecognized:[],}" name=publishEvent parentSpanID=d997f3160d26cd45 spanID=232343eff430f6e6 startTime="2023-01-23 12:58:38.1497292 +0000 GMT m=+1.712806001" topic=/tasks/exit traceID=6efd355c108e3130e703091c18182e4c .... ```

Steps to reproduce the issue

Unknown

Describe the results you received and expected

CI should be 🟢

What version of containerd are you using?

main branch

Any other relevant information

No response

Show configuration if it is related to CRI plugin.

No response

gabriel-samfira commented 1 year ago

Hmm. This is interesting:

time="2023-01-23T12:58:36.274097200Z" level=error msg=Span bundle="C:\\Users\\RUNNER~1\\AppData\\Local\\Temp\\TestRestartMonitor708044512\\001\\state\\io.containerd.runtime.v2.task\\testing\\TestRestartMonitor_Always" checkpoint= duration=173.2594ms endTime="2023-01-23 12:58:36.4473566 +0000 GMT m=+0.197510901" error="failed to mount container storage: hcsshim::PrepareLayer failed in Win32: Access is denied. (0x5)" name=Create parentSpanID=86a0e719d645c03e parentcheckpoint= spanID=dd4b54b1d415de6c startTime="2023-01-23 12:58:36.2740972 +0000 GMT m=+0.024251501" stderr= stdin= stdout= terminal=false tid=TestRestartMonitor_Always traceID=7cea767b0607fdbd30d0ed3eb2045b0a

Will investigate.