Deadlock stackdump and log

[lowenna]

@jterry75 Hit this debugging removing the old shim code from containerd. If you get into a situation where the resources haven't been released from a previous attempt to run an Argon, and a scratch is mounted, running the test a second time ends up deadlocking until the go test timeout is reached. Haven't debugged - but stack trace and log below.

goroutine 26 [running]:
github.com/containerd/containerd/cmd/containerd/command.dumpStacks()
	e:/go/src/github.com/containerd/containerd/cmd/containerd/command/main.go:272 +0x8f
github.com/containerd/containerd/cmd/containerd/command.setupDumpStacks.func1(0xc00029f0a0, 0x15, 0x18c)
	e:/go/src/github.com/containerd/containerd/cmd/containerd/command/main_windows.go:89 +0xc2
created by github.com/containerd/containerd/cmd/containerd/command.setupDumpStacks
	e:/go/src/github.com/containerd/containerd/cmd/containerd/command/main_windows.go:85 +0x2c4

goroutine 1 [chan receive]:
github.com/containerd/containerd/cmd/containerd/command.App.func1(0xc0000f3760, 0xc0000f3760, 0xc00020bd17)
	e:/go/src/github.com/containerd/containerd/cmd/containerd/command/main.go:199 +0x8c6
github.com/containerd/containerd/vendor/github.com/urfave/cli.HandleAction(0xc4e7c0, 0xdb9d68, 0xc0000f3760, 0xc00024efc0, 0x0)
	e:/go/src/github.com/containerd/containerd/vendor/github.com/urfave/cli/app.go:502 +0xcf
github.com/containerd/containerd/vendor/github.com/urfave/cli.(*App).Run(0xc000362380, 0xc0000ae000, 0xb, 0x10, 0x0, 0x0)
	e:/go/src/github.com/containerd/containerd/vendor/github.com/urfave/cli/app.go:268 +0x5be
main.main()
	e:/go/src/github.com/containerd/containerd/cmd/containerd/main.go:33 +0x56

goroutine 24 [syscall]:
os/signal.signal_recv(0xdbbd20)
	C:/Go/src/runtime/sigqueue.go:139 +0xa3
os/signal.loop()
	C:/Go/src/os/signal/signal_unix.go:23 +0x29
created by os/signal.init.0
	C:/Go/src/os/signal/signal_unix.go:29 +0x48

goroutine 25 [select]:
github.com/containerd/containerd/cmd/containerd/command.handleSignals.func1(0xc00024f080, 0xc00024f020, 0xe5ece0, 0xc000078180, 0xc00006a300)
	e:/go/src/github.com/containerd/containerd/cmd/containerd/command/main_windows.go:47 +0xdf
created by github.com/containerd/containerd/cmd/containerd/command.handleSignals
	e:/go/src/github.com/containerd/containerd/cmd/containerd/command/main_windows.go:44 +0x90

goroutine 27 [select]:
github.com/containerd/containerd/vendor/github.com/docker/go-events.(*Broadcaster).run(0xc0002af720)
	e:/go/src/github.com/containerd/containerd/vendor/github.com/docker/go-events/broadcast.go:117 +0x1a2
created by github.com/containerd/containerd/vendor/github.com/docker/go-events.NewBroadcaster
	e:/go/src/github.com/containerd/containerd/vendor/github.com/docker/go-events/broadcast.go:39 +0x1b5

goroutine 28 [select]:
github.com/containerd/containerd/gc/scheduler.(*gcScheduler).run(0xc00024f980, 0xe5ece0, 0xc000078180)
	e:/go/src/github.com/containerd/containerd/gc/scheduler/scheduler.go:268 +0x1c7
created by github.com/containerd/containerd/gc/scheduler.init.0.func1
	e:/go/src/github.com/containerd/containerd/gc/scheduler/scheduler.go:132 +0x48d

goroutine 38 [sleep]:
time.Sleep(0x2540be400)
	C:/Go/src/runtime/time.go:105 +0x164
github.com/containerd/containerd/runtime/restart/monitor.(*monitor).run(0xc00035e050, 0x2540be400)
	e:/go/src/github.com/containerd/containerd/runtime/restart/monitor/monitor.go:155 +0x53
created by github.com/containerd/containerd/runtime/restart/monitor.init.0.func1
	e:/go/src/github.com/containerd/containerd/runtime/restart/monitor/monitor.go:85 +0x130

goroutine 39 [select]:
github.com/containerd/containerd/vendor/github.com/Microsoft/go-winio.(*win32PipeListener).makeConnectedServerPipe(0xc0003f7500, 0xc000335f40, 0x2, 0x1)
	e:/go/src/github.com/containerd/containerd/vendor/github.com/Microsoft/go-winio/pipe.go:257 +0x133
github.com/containerd/containerd/vendor/github.com/Microsoft/go-winio.(*win32PipeListener).listenerRoutine(0xc0003f7500)
	e:/go/src/github.com/containerd/containerd/vendor/github.com/Microsoft/go-winio/pipe.go:287 +0x106
created by github.com/containerd/containerd/vendor/github.com/Microsoft/go-winio.ListenPipe
	e:/go/src/github.com/containerd/containerd/vendor/github.com/Microsoft/go-winio/pipe.go:371 +0x293

goroutine 40 [chan receive]:
github.com/containerd/containerd/vendor/github.com/Microsoft/go-winio.(*win32PipeListener).Accept(0xc0003f7500, 0xdbb2e0, 0xc0003628c0, 0xe658a0, 0xc000402000)
	e:/go/src/github.com/containerd/containerd/vendor/github.com/Microsoft/go-winio/pipe.go:394 +0x155
github.com/containerd/containerd/vendor/google.golang.org/grpc.(*Server).Serve(0xc0003628c0, 0xe5c9e0, 0xc0003f7500, 0x0, 0x0)
	e:/go/src/github.com/containerd/containerd/vendor/google.golang.org/grpc/server.go:544 +0x217
github.com/containerd/containerd/services/server.(*Server).ServeGRPC(0xc0003bc060, 0xe5c9e0, 0xc0003f7500, 0x18, 0xc0003cbf38)
	e:/go/src/github.com/containerd/containerd/services/server/server.go:173 +0x70
github.com/containerd/containerd/services/server.(*Server).ServeGRPC-fm(0xe5c9e0, 0xc0003f7500, 0xc0003f7500, 0x0)
	e:/go/src/github.com/containerd/containerd/cmd/containerd/command/main.go:196 +0x45
github.com/containerd/containerd/cmd/containerd/command.serve.func1(0xe5c9e0, 0xc0003f7500, 0xc000406550, 0xe5ece0, 0xc000078180, 0xc00009e090, 0x23)
	e:/go/src/github.com/containerd/containerd/cmd/containerd/command/main.go:210 +0x7c
created by github.com/containerd/containerd/cmd/containerd/command.serve
	e:/go/src/github.com/containerd/containerd/cmd/containerd/command/main.go:208 +0x1c3

goroutine 33 [syscall, locked to thread]:
syscall.Syscall6(0x7ff890a470b0, 0x5, 0x1f8, 0xc000475f9c, 0xc000475fa0, 0xc000475fa8, 0xffffffff, 0x0, 0x0, 0x0, ...)
	C:/Go/src/runtime/syscall_windows.go:185 +0xfc
github.com/containerd/containerd/vendor/github.com/Microsoft/go-winio.getQueuedCompletionStatus(0x1f8, 0xc000475f9c, 0xc000475fa0, 0xc000475fa8, 0xffffffff, 0x0, 0x0)
	e:/go/src/github.com/containerd/containerd/vendor/github.com/Microsoft/go-winio/zsyscall_windows.go:100 +0xb6
github.com/containerd/containerd/vendor/github.com/Microsoft/go-winio.ioCompletionProcessor(0x1f8)
	e:/go/src/github.com/containerd/containerd/vendor/github.com/Microsoft/go-winio/file.go:159 +0xc2
created by github.com/containerd/containerd/vendor/github.com/Microsoft/go-winio.initIo
	e:/go/src/github.com/containerd/containerd/vendor/github.com/Microsoft/go-winio/file.go:72 +0x7d

goroutine 6 [select]:
github.com/containerd/containerd/vendor/github.com/Microsoft/go-winio.(*win32File).asyncIo(0xc00017e1e0, 0xc00041c030, 0x0, 0x0, 0xe53540, 0xb6b3c8, 0xc00006fe00, 0xc00006fd10, 0xc00006fd40)
	e:/go/src/github.com/containerd/containerd/vendor/github.com/Microsoft/go-winio/file.go:186 +0x14e
github.com/containerd/containerd/vendor/github.com/Microsoft/go-winio.connectPipe(0xc00017e1e0, 0x0, 0x0)
	e:/go/src/github.com/containerd/containerd/vendor/github.com/Microsoft/go-winio/pipe.go:383 +0xe5
github.com/containerd/containerd/vendor/github.com/Microsoft/go-winio.(*win32PipeListener).makeConnectedServerPipe.func1(0xc00006a360, 0xc00017e1e0)
	e:/go/src/github.com/containerd/containerd/vendor/github.com/Microsoft/go-winio/pipe.go:254 +0x32
created by github.com/containerd/containerd/vendor/github.com/Microsoft/go-winio.(*win32PipeListener).makeConnectedServerPipe
	e:/go/src/github.com/containerd/containerd/vendor/github.com/Microsoft/go-winio/pipe.go:253 +0xa9

goroutine 44 [select]:
github.com/containerd/containerd/vendor/google.golang.org/grpc/transport.(*controlBuffer).get(0xc0002b4040, 0x1, 0x0, 0x0, 0x0, 0x0)
	e:/go/src/github.com/containerd/containerd/vendor/google.golang.org/grpc/transport/controlbuf.go:289 +0x10a
github.com/containerd/containerd/vendor/google.golang.org/grpc/transport.(*loopyWriter).run(0xc00033e180)
	e:/go/src/github.com/containerd/containerd/vendor/google.golang.org/grpc/transport/controlbuf.go:374 +0x1c7
github.com/containerd/containerd/vendor/google.golang.org/grpc/transport.newHTTP2Server.func2(0xc0003ee400)
	e:/go/src/github.com/containerd/containerd/vendor/google.golang.org/grpc/transport/http2_server.go:276 +0xca
created by github.com/containerd/containerd/vendor/google.golang.org/grpc/transport.newHTTP2Server
	e:/go/src/github.com/containerd/containerd/vendor/google.golang.org/grpc/transport/http2_server.go:273 +0xd42

goroutine 45 [select]:
github.com/containerd/containerd/vendor/google.golang.org/grpc/transport.(*http2Server).keepalive(0xc0003ee400)
	e:/go/src/github.com/containerd/containerd/vendor/google.golang.org/grpc/transport/http2_server.go:867 +0x1f1
created by github.com/containerd/containerd/vendor/google.golang.org/grpc/transport.newHTTP2Server
	e:/go/src/github.com/containerd/containerd/vendor/google.golang.org/grpc/transport/http2_server.go:280 +0xd67

goroutine 46 [select]:
github.com/containerd/containerd/vendor/github.com/Microsoft/go-winio.(*win32File).asyncIo(0xc000070280, 0xc00045aea0, 0xc0000702b0, 0x0, 0xe53540, 0xb6b5a8, 0xe53540, 0xb6b5a8, 0x0)
	e:/go/src/github.com/containerd/containerd/vendor/github.com/Microsoft/go-winio/file.go:186 +0x14e
github.com/containerd/containerd/vendor/github.com/Microsoft/go-winio.(*win32File).Read(0xc000070280, 0xc000194000, 0x8000, 0x8000, 0x0, 0x0, 0x0)
	e:/go/src/github.com/containerd/containerd/vendor/github.com/Microsoft/go-winio/file.go:224 +0x144
bufio.(*Reader).Read(0xc00037c000, 0xc0004121f8, 0x9, 0x9, 0x18, 0xcca0c0, 0x0)
	C:/Go/src/bufio/bufio.go:216 +0x236
io.ReadAtLeast(0xe51480, 0xc00037c000, 0xc0004121f8, 0x9, 0x9, 0x9, 0x40ced9, 0x403135, 0xc00047bd80)
	C:/Go/src/io/io.go:310 +0x8f
io.ReadFull(0xe51480, 0xc00037c000, 0xc0004121f8, 0x9, 0x9, 0x6, 0xc000043488, 0xc000043400)
	C:/Go/src/io/io.go:329 +0x5f
github.com/containerd/containerd/vendor/golang.org/x/net/http2.readFrameHeader(0xc0004121f8, 0x9, 0x9, 0xe51480, 0xc00037c000, 0x0, 0xc000000000, 0xc00047be18, 0xc00047be90)
	e:/go/src/github.com/containerd/containerd/vendor/golang.org/x/net/http2/frame.go:237 +0x82
github.com/containerd/containerd/vendor/golang.org/x/net/http2.(*Framer).ReadFrame(0xc0004121c0, 0xc0000763c0, 0xc0000763c0, 0x0, 0x0)
	e:/go/src/github.com/containerd/containerd/vendor/golang.org/x/net/http2/frame.go:492 +0xaa
github.com/containerd/containerd/vendor/google.golang.org/grpc/transport.(*http2Server).HandleStreams(0xc0003ee400, 0xc0002b2180, 0xdbb338)
	e:/go/src/github.com/containerd/containerd/vendor/google.golang.org/grpc/transport/http2_server.go:426 +0x83
github.com/containerd/containerd/vendor/google.golang.org/grpc.(*Server).serveStreams(0xc0003628c0, 0xe680c0, 0xc0003ee400)
	e:/go/src/github.com/containerd/containerd/vendor/google.golang.org/grpc/server.go:676 +0xe4
github.com/containerd/containerd/vendor/google.golang.org/grpc.(*Server).handleRawConn.func2()
	e:/go/src/github.com/containerd/containerd/vendor/google.golang.org/grpc/server.go:631 +0x43
github.com/containerd/containerd/vendor/google.golang.org/grpc.(*Server).handleRawConn.func3(0xc0002ee040, 0xc0003628c0, 0x45d4790, 0xc0003ee400)
	e:/go/src/github.com/containerd/containerd/vendor/google.golang.org/grpc/server.go:639 +0x2e
created by github.com/containerd/containerd/vendor/google.golang.org/grpc.(*Server).handleRawConn
	e:/go/src/github.com/containerd/containerd/vendor/google.golang.org/grpc/server.go:638 +0x5ff


	PS E:\go\src\github.com\containerd\containerd> go test -v -run TestContainerStart
time="2019-03-26T18:51:34-07:00" level=error msg="hcsshim::DestroyLayer - failed failed in Win32: The process cannot access the file because it is being used by another process. (0x20)" error="hcsshim::DestroyLayer - failed failed in Win32: The process cannot access the file because it is being used by another process. (0x20)" path="C:\\Program Files\\containerd\\root-test"
time="2019-03-26T18:51:34-07:00" level=info msg="running tests against containerd" revision= runtime= version=1.2.0+unknown
time="2019-03-26T18:51:37-07:00" level=info msg="apply failure, attempting cleanup" error="failed to extract layer sha256:37c182b7517237c898714b9cc4688cf3699e1b5a352b247cfc187260cbd13ba9: Failed to safefile.OpenRelative failed in Win32: open \\\\?\\C:\\Program Files\\containerd\\root-test\\io.containerd.snapshotter.v1.windows\\snapshots\\1\\Files: Cannot create a file when that file already exists. (0x1f) Files: unknown" key="extract-234599400-ByGC sha256:37c182b7517237c898714b9cc4688cf3699e1b5a352b247cfc187260cbd13ba9"
failed to unpack image on snapshotter windows: failed to extract layer sha256:37c182b7517237c898714b9cc4688cf3699e1b5a352b247cfc187260cbd13ba9: Failed to safefile.OpenRelative failed in Win32: open \\?\C:\Program Files\containerd\root-test\io.containerd.snapshotter.v1.windows\snapshots\1\Files: Cannot create a file when that file already exists. (0x1f) Files: unknown: time="2019-03-26T18:51:34.383826400-07:00" level=info msg="starting containerd" revision= version=1.2.0+unknown
time="2019-03-26T18:51:34.383826400-07:00" level=debug msg="Stackdump - waiting signal at Global\\stackdump-2848"
time="2019-03-26T18:51:34.385863100-07:00" level=info msg="loading plugin \"io.containerd.content.v1.content\"..." type=io.containerd.content.v1
time="2019-03-26T18:51:34.385863100-07:00" level=info msg="loading plugin \"io.containerd.snapshotter.v1.windows-lcow\"..." type=io.containerd.snapshotter.v1
time="2019-03-26T18:51:34.386806600-07:00" level=info msg="loading plugin \"io.containerd.snapshotter.v1.windows\"..." type=io.containerd.snapshotter.v1
time="2019-03-26T18:51:34.386806600-07:00" level=info msg="loading plugin \"io.containerd.metadata.v1.bolt\"..." type=io.containerd.metadata.v1
time="2019-03-26T18:51:34.386806600-07:00" level=info msg="metadata content store policy set" policy=shared
time="2019-03-26T18:51:34.400804900-07:00" level=info msg="loading plugin \"io.containerd.differ.v1.walking\"..." type=io.containerd.differ.v1
time="2019-03-26T18:51:34.400804900-07:00" level=info msg="loading plugin \"io.containerd.gc.v1.scheduler\"..." type=io.containerd.gc.v1
time="2019-03-26T18:51:34.400804900-07:00" level=info msg="loading plugin \"io.containerd.service.v1.containers-service\"..." type=io.containerd.service.v1
time="2019-03-26T18:51:34.400804900-07:00" level=info msg="loading plugin \"io.containerd.service.v1.content-service\"..." type=io.containerd.service.v1
time="2019-03-26T18:51:34.400804900-07:00" level=info msg="loading plugin \"io.containerd.differ.v1.windows-lcow\"..." type=io.containerd.differ.v1
time="2019-03-26T18:51:34.400804900-07:00" level=info msg="loading plugin \"io.containerd.differ.v1.windows\"..." type=io.containerd.differ.v1
time="2019-03-26T18:51:34.400804900-07:00" level=info msg="loading plugin \"io.containerd.service.v1.diff-service\"..." type=io.containerd.service.v1
time="2019-03-26T18:51:34.400804900-07:00" level=info msg="loading plugin \"io.containerd.service.v1.images-service\"..." type=io.containerd.service.v1
time="2019-03-26T18:51:34.400804900-07:00" level=info msg="loading plugin \"io.containerd.service.v1.leases-service\"..." type=io.containerd.service.v1
time="2019-03-26T18:51:34.400804900-07:00" level=info msg="loading plugin \"io.containerd.service.v1.namespaces-service\"..." type=io.containerd.service.v1
time="2019-03-26T18:51:34.400804900-07:00" level=info msg="loading plugin \"io.containerd.service.v1.snapshots-service\"..." type=io.containerd.service.v1
time="2019-03-26T18:51:34.400804900-07:00" level=info msg="loading plugin \"io.containerd.runtime.v2.task\"..." type=io.containerd.runtime.v2
time="2019-03-26T18:51:34.401816200-07:00" level=debug msg="loading tasks in namespace" namespace=nnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnn
time="2019-03-26T18:51:34.402827500-07:00" level=error msg="cleanup working directory in namespace" error="open C:\\Program Files\\containerd\\root-test\\io.containerd.runtime.v2.task\\nnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnn: The system cannot find the file specified." namespace=nnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnn
time="2019-03-26T18:51:34.402827500-07:00" level=debug msg="loading tasks in namespace" namespace=testing
time="2019-03-26T18:51:34.402827500-07:00" level=error msg="cleanup working directory in namespace" error="open C:\\Program Files\\containerd\\root-test\\io.containerd.runtime.v2.task\\testing: The system cannot find the file specified." namespace=testing
time="2019-03-26T18:51:34.402827500-07:00" level=info msg="loading plugin \"io.containerd.service.v1.tasks-service\"..." type=io.containerd.service.v1
time="2019-03-26T18:51:34.402827500-07:00" level=info msg="loading plugin \"io.containerd.internal.v1.restart\"..." type=io.containerd.internal.v1
time="2019-03-26T18:51:34.402827500-07:00" level=info msg="loading plugin \"io.containerd.grpc.v1.containers\"..." type=io.containerd.grpc.v1
time="2019-03-26T18:51:34.402827500-07:00" level=info msg="loading plugin \"io.containerd.grpc.v1.content\"..." type=io.containerd.grpc.v1
time="2019-03-26T18:51:34.402827500-07:00" level=info msg="loading plugin \"io.containerd.grpc.v1.diff\"..." type=io.containerd.grpc.v1
time="2019-03-26T18:51:34.402827500-07:00" level=info msg="loading plugin \"io.containerd.grpc.v1.events\"..." type=io.containerd.grpc.v1
time="2019-03-26T18:51:34.402827500-07:00" level=info msg="loading plugin \"io.containerd.grpc.v1.healthcheck\"..." type=io.containerd.grpc.v1
time="2019-03-26T18:51:34.402827500-07:00" level=info msg="loading plugin \"io.containerd.grpc.v1.images\"..." type=io.containerd.grpc.v1
time="2019-03-26T18:51:34.402827500-07:00" level=info msg="loading plugin \"io.containerd.grpc.v1.leases\"..." type=io.containerd.grpc.v1
time="2019-03-26T18:51:34.402827500-07:00" level=info msg="loading plugin \"io.containerd.grpc.v1.namespaces\"..." type=io.containerd.grpc.v1
time="2019-03-26T18:51:34.402827500-07:00" level=info msg="loading plugin \"io.containerd.internal.v1.opt\"..." type=io.containerd.internal.v1
time="2019-03-26T18:51:34.402827500-07:00" level=info msg="loading plugin \"io.containerd.grpc.v1.snapshots\"..." type=io.containerd.grpc.v1
time="2019-03-26T18:51:34.402827500-07:00" level=info msg="loading plugin \"io.containerd.grpc.v1.tasks\"..." type=io.containerd.grpc.v1
time="2019-03-26T18:51:34.402827500-07:00" level=info msg="loading plugin \"io.containerd.grpc.v1.version\"..." type=io.containerd.grpc.v1
time="2019-03-26T18:51:34.402827500-07:00" level=info msg="loading plugin \"io.containerd.grpc.v1.introspection\"..." type=io.containerd.grpc.v1
time="2019-03-26T18:51:34.403823800-07:00" level=info msg=serving... address="\\\\.\\pipe\\containerd-containerd-test"
time="2019-03-26T18:51:34.403823800-07:00" level=info msg="containerd successfully booted in 0.021978s"
time="2019-03-26T18:51:34.507995300-07:00" level=debug msg="garbage collected" d=7.0615ms
time="2019-03-26T18:51:34.546914700-07:00" level=debug msg="(*service).Write started" expected="sha256:e35677b8b30134aef2d42d4fb760ed95810b7f41349171b1a714f18137346a0d" ref="index-sha256:e35677b8b30134aef2d42d4fb760ed95810b7f41349171b1a714f18137346a0d" total=829
time="2019-03-26T18:51:34.665008900-07:00" level=debug msg="(*service).Write started" expected="sha256:d9af90cc3dc435b8beb398d3257a3bf95f9d7fb39de09a9c10e0240623160632" ref="manifest-sha256:d9af90cc3dc435b8beb398d3257a3bf95f9d7fb39de09a9c10e0240623160632" total=942
time="2019-03-26T18:51:34.767615200-07:00" level=debug msg="(*service).Write started" expected="sha256:91fbd4baf11f5cecd2a550c9a64fb6b067203ade0acef88d88c9ab61f3112b1c" ref="layer-sha256:91fbd4baf11f5cecd2a550c9a64fb6b067203ade0acef88d88c9ab61f3112b1c" total=15322378
time="2019-03-26T18:51:34.767615200-07:00" level=debug msg="(*service).Write started" expected="sha256:6a5e981230da7b34a25588f20c8b6b5366256ab1e0aadc0b7ecb566855bf4679" ref="layer-sha256:6a5e981230da7b34a25588f20c8b6b5366256ab1e0aadc0b7ecb566855bf4679" total=98266490
time="2019-03-26T18:51:34.767615200-07:00" level=debug msg="(*service).Write started" expected="sha256:91da8a971b53abbd8ab184966e5854c8f4a084ed7f294b0ae1ce8a20bccb4e4e" ref="config-sha256:91da8a971b53abbd8ab184966e5854c8f4a084ed7f294b0ae1ce8a20bccb4e4e" total=807
time="2019-03-26T18:51:37.214719500-07:00" level=debug msg="create image" name="mcr.microsoft.com/windows/nanoserver/insider:10.0.17763.55" target="sha256:e35677b8b30134aef2d42d4fb760ed95810b7f41349171b1a714f18137346a0d"
time="2019-03-26T18:51:37.222668200-07:00" level=debug msg="event published" ns=testing topic=/images/create type=containerd.services.images.v1.ImageCreate
time="2019-03-26T18:51:37.233578800-07:00" level=debug msg="stat snapshot" key="sha256:37c182b7517237c898714b9cc4688cf3699e1b5a352b247cfc187260cbd13ba9"
time="2019-03-26T18:51:37.234599400-07:00" level=debug msg="prepare snapshot" key="extract-234599400-ByGC sha256:37c182b7517237c898714b9cc4688cf3699e1b5a352b247cfc187260cbd13ba9" parent=
time="2019-03-26T18:51:37.238609300-07:00" level=debug msg="hcsshim::CreateScratchLayer" path="C:\\Program Files\\containerd\\root-test\\io.containerd.snapshotter.v1.windows\\snapshots\\1"
time="2019-03-26T18:51:37.241599900-07:00" level=debug msg="hcsshim::CreateScratchLayer - succeeded" path="C:\\Program Files\\containerd\\root-test\\io.containerd.snapshotter.v1.windows\\snapshots\\1"
time="2019-03-26T18:51:37.257648500-07:00" level=debug msg="event published" ns=testing topic=/snapshot/prepare type=containerd.events.SnapshotPrepare
time="2019-03-26T18:51:37.300627900-07:00" level=debug msg="unpigz not found, falling back to go gzip" error="exec: \"unpigz\": executable file not found in %PATH%"
time="2019-03-26T18:51:37.303585800-07:00" level=debug msg="remove snapshot" key="extract-234599400-ByGC sha256:37c182b7517237c898714b9cc4688cf3699e1b5a352b247cfc187260cbd13ba9"
time="2019-03-26T18:51:37.311655600-07:00" level=debug msg="event published" ns=testing topic=/snapshot/remove type=containerd.events.SnapshotRemove
time="2019-03-26T18:51:37.638921500-07:00" level=debug msg="schedule snapshotter cleanup" snapshotter=windows
time="2019-03-26T18:51:37.641899000-07:00" level=warning msg="snapshot garbage collection failed" error="failed to detach VHD: invalid argument: rename C:\\Program Files\\containerd\\root-test\\io.containerd.snapshotter.v1.windows\\snapshots\\1 C:\\Program Files\\containerd\\root-test\\io.containerd.snapshotter.v1.windows\\snapshots\\rm-1: Access is denied." snapshotter=windows
time="2019-03-26T18:51:37.641899000-07:00" level=debug msg="garbage collected" d=8.812ms