docker / for-win

Bug reports for Docker Desktop for Windows
https://www.docker.com/products/docker#/windows
1.86k stars 289 forks source link

Building images with many files takes up to 7x longer for Windows images compared to Linux images #3229

Open filipesilva opened 5 years ago

filipesilva commented 5 years ago

Expected behavior

Creating files in a Windows docker container build is roughly on part with creating them on Linux.

Actual behavior

Creating files in a Windows docker container build takes up to 7 times longer than on Linux.

Information

In https://github.com/filipesilva/windows-docker-many-files there is a reproduction of how Windows Docker containers is slow to build images with many small files when compared to Linux containers. The cost of creating a file on Windows seems to be up to 7x than on Linux. This time is not spend in the build step proper, but rather after the build step, in Docker operations.

As mentioned in this github comment about slow builds and the official docker page about antivirus, disabling Windows Defender for docker folders helps cut this cost by about half, but it's still slow.

You can see see docker file access and Windows defender scanning those files with https://docs.microsoft.com/en-us/sysinternals/downloads/procmon. To exclude the docker folder in a admin Powershell run Set-MpPreference -ExclusionPath $Env:ProgramData'\Docker', '\Device\'.

This slowness can be seen mainly in between the build steps, I assume due to adding the files to the new layer. At this point docker ps -a reports no container is actually up.

To show this I used Node dependencies, because they are what I work with everyday and known for having lots of small files.

For a small dependency set the time is already 3 to 7 times longer in Windows than in Linux containers:

Linux:

Windows:

The relative time difference seems to be maintained for larger dependency sets too:

Linux:

Windows:

Relevant system information:

Steps to reproduce the behavior

  1. git clone https://github.com/filipesilva/windows-docker-many-files && cd windows-docker-many-files
  2. switch Docker to using Linux containers
  3. time docker build --no-cache --build-arg FROM="node:10.11" .
  4. switch Docker to using windows containers
  5. time docker build --no-cache --build-arg FROM="stefanscherer/node-windows:10.11" .
  6. repeat steps with --build-arg PACKAGE_JSON="large-package.json" for an example with more files
docker-robott commented 5 years ago

Issues go stale after 90d of inactivity. Mark the issue as fresh with /remove-lifecycle stale comment. Stale issues will be closed after an additional 30d of inactivity.

Prevent issues from auto-closing with an /lifecycle frozen comment.

If this issue is safe to close now please do so.

Send feedback to Docker Community Slack channels #docker-for-mac or #docker-for-windows. /lifecycle stale

filipesilva commented 5 years ago

/lifecycle frozen

sparky005 commented 5 years ago

Any movement on this issue? I am having the same problem on a variety of Windows machines.

tardyp commented 5 years ago

Trying to build a msys2 container for CI purposes, I got this issue as well. The build process is stuck for hours. with dockerd using 30% of cpu on my 8 core machine.

As per https://docs.docker.com/config/daemon/

I tried to dump a stack trace (docker 19-03-1):

goroutine 58 [running]:
github.com/docker/docker/pkg/signal.DumpStacks(0xc000816360, 0x15, 0x0, 0x0, 0x0, 0x0)
        C:/go/src/github.com/docker/docker/pkg/signal/trap.go:83 +0x9c
github.com/docker/docker/daemon.(*Daemon).setupDumpStackTrap.func1(0xc0008169a0, 0x15, 0x20c, 0xc000816360, 0x15)
        C:/go/src/github.com/docker/docker/daemon/debugtrap_windows.go:38 +0xe3
created by github.com/docker/docker/daemon.(*Daemon).setupDumpStackTrap
        C:/go/src/github.com/docker/docker/daemon/debugtrap_windows.go:34 +0x2f2

goroutine 1 [chan receive, 300 minutes]:
main.(*DaemonCli).start(0xc0006793b0, 0xc0001347e0, 0x0, 0x0)
        C:/go/src/github.com/docker/docker/cmd/dockerd/daemon.go:259 +0xb95
main.runDaemon(0xc0001347e0, 0xc0001c6100, 0x0)
        C:/go/src/github.com/docker/docker/cmd/dockerd/docker_windows.go:37 +0x131
main.newDaemonCommand.func1(0xc0001c4000, 0xc0001b8720, 0x0, 0x1, 0x0, 0x0)
        C:/go/src/github.com/docker/docker/cmd/dockerd/docker.go:34 +0x5d
github.com/docker/docker/vendor/github.com/spf13/cobra.(*Command).execute(0xc0001c4000, 0xc000082430, 0x1, 0x1, 0xc0001c4000, 0xc000082430)
        C:/go/src/github.com/docker/docker/vendor/github.com/spf13/cobra/command.go:762 +0x46c
github.com/docker/docker/vendor/github.com/spf13/cobra.(*Command).ExecuteC(0xc0001c4000, 0x0, 0x0, 0xc0000ba010)
        C:/go/src/github.com/docker/docker/vendor/github.com/spf13/cobra/command.go:852 +0x2f3
github.com/docker/docker/vendor/github.com/spf13/cobra.(*Command).Execute(...)
        C:/go/src/github.com/docker/docker/vendor/github.com/spf13/cobra/command.go:800
main.main()
        C:/go/src/github.com/docker/docker/cmd/dockerd/docker.go:97 +0x19e

goroutine 39 [syscall, 300 minutes]:
os/signal.signal_recv(0x4656d6)
        C:/.GOROOT/src/runtime/sigqueue.go:139 +0xa3
os/signal.loop()
        C:/.GOROOT/src/os/signal/signal_unix.go:23 +0x29
created by os/signal.init.0
        C:/.GOROOT/src/os/signal/signal_unix.go:29 +0x48

goroutine 56 [chan receive, 300 minutes]:
github.com/docker/docker/pkg/signal.Trap.func1(0xc000728a20, 0x25464a0, 0xc0000cc000, 0xc000830100)
        C:/go/src/github.com/docker/docker/pkg/signal/trap.go:38 +0x62
created by github.com/docker/docker/pkg/signal.Trap
        C:/go/src/github.com/docker/docker/pkg/signal/trap.go:36 +0x125

goroutine 45 [select]:
github.com/docker/docker/vendor/go.opencensus.io/stats/view.(*worker).start(0xc00060eec0)
        C:/go/src/github.com/docker/docker/vendor/go.opencensus.io/stats/view/worker.go:144 +0xe4
created by github.com/docker/docker/vendor/go.opencensus.io/stats/view.init.0
        C:/go/src/github.com/docker/docker/vendor/go.opencensus.io/stats/view/worker.go:29 +0x5e

goroutine 55 [select, 300 minutes]:
main.(*handler).Execute(0xc0001394e0, 0xc00006d170, 0x1, 0x1, 0xc0005d82a0, 0xc0005d8300, 0x43f3bd)
        C:/go/src/github.com/docker/docker/cmd/dockerd/service_windows.go:350 +0x1e8
github.com/docker/docker/vendor/golang.org/x/sys/windows/svc.(*service).run.func1(0xc000132a40, 0xc00006d170, 0x1, 0x1, 0xc0005d82a0, 0xc0005d8300, 0xc0005d8360)
        C:/go/src/github.com/docker/docker/vendor/golang.org/x/sys/windows/svc/service.go:237 +0x71
created by github.com/docker/docker/vendor/golang.org/x/sys/windows/svc.(*service).run
        C:/go/src/github.com/docker/docker/vendor/golang.org/x/sys/windows/svc/service.go:236 +0x20c

goroutine 29 [syscall, 300 minutes, locked to thread]:
syscall.Syscall(0x7ff836a76580, 0x1, 0xc00018ff48, 0x0, 0x0, 0x0, 0x0, 0x0)
        C:/.GOROOT/src/runtime/syscall_windows.go:184 +0xea
github.com/docker/docker/vendor/golang.org/x/sys/windows.StartServiceCtrlDispatcher(0xc00018ff48, 0x222d048, 0xc000132a40)
        C:/go/src/github.com/docker/docker/vendor/golang.org/x/sys/windows/zsyscall_windows.go:397 +0x6b
github.com/docker/docker/vendor/golang.org/x/sys/windows/svc.Run(0x2180474, 0x6, 0x2547080, 0xc0001394e0, 0xc00018ffb8, 0xb34b30)
        C:/go/src/github.com/docker/docker/vendor/golang.org/x/sys/windows/svc/service.go:351 +0x1ce
main.initService.func1(0x3915400, 0xc0001394e0, 0xc0001b8740)
        C:/go/src/github.com/docker/docker/cmd/dockerd/service_windows.go:303 +0xfd
created by main.initService
        C:/go/src/github.com/docker/docker/cmd/dockerd/service_windows.go:299 +0x301

goroutine 30 [select, 300 minutes]:
github.com/docker/docker/vendor/golang.org/x/sys/windows/svc.(*service).run(0xc000132a40)
        C:/go/src/github.com/docker/docker/vendor/golang.org/x/sys/windows/svc/service.go:249 +0x38c
created by github.com/docker/docker/vendor/golang.org/x/sys/windows/svc.Run
        C:/go/src/github.com/docker/docker/vendor/golang.org/x/sys/windows/svc/service.go:349 +0x1c0

goroutine 68 [IO wait]:
internal/poll.runtime_pollWait(0x8121098, 0x72, 0x254b340)
        C:/.GOROOT/src/runtime/netpoll.go:182 +0x5d
internal/poll.(*pollDesc).wait(0xc000154748, 0x72, 0x386be00, 0x0, 0x0)
        C:/.GOROOT/src/internal/poll/fd_poll_runtime.go:87 +0xa2
internal/poll.(*ioSrv).ExecIO(0x38e6c00, 0xc000154598, 0x222d538, 0x572ddc0, 0xc0008cc000, 0xc0001cfbc8)
        C:/.GOROOT/src/internal/poll/fd_windows.go:228 +0x124
internal/poll.(*FD).ReadFrom(0xc000154580, 0xc0007ba000, 0x200, 0x200, 0x0, 0x0, 0x0, 0x0, 0x0)
        C:/.GOROOT/src/internal/poll/fd_windows.go:642 +0x120
net.(*netFD).readFrom(0xc000154580, 0xc0007ba000, 0x200, 0x200, 0x24c96038f5ba0, 0x2000, 0x1, 0x7b10488, 0x38f5ba0)
        C:/.GOROOT/src/net/fd_windows.go:158 +0x62
net.(*UDPConn).readFrom(0xc000006350, 0xc0007ba000, 0x200, 0x200, 0xc0007ba000, 0x200, 0xc0007ba000, 0x7b10488)
        C:/.GOROOT/src/net/udpsock_posix.go:47 +0x71
net.(*UDPConn).ReadFrom(0xc000006350, 0xc0007ba000, 0x200, 0x200, 0x5857ed, 0xc000154580, 0xbf581cb9ef04c548, 0x106619fdf479, 0xc0001cfdc0)
        C:/.GOROOT/src/net/udpsock.go:121 +0x65
github.com/docker/docker/vendor/github.com/miekg/dns.ReadFromSessionUDP(0xc000006350, 0xc0007ba000, 0x200, 0x200, 0x0, 0x0, 0x38f14e0, 0xc0001cfe38)
        C:/go/src/github.com/docker/docker/vendor/github.com/miekg/dns/udp_windows.go:19 +0x60
github.com/docker/docker/vendor/github.com/miekg/dns.(*Server).readUDP(0xc0001411e0, 0xc000006350, 0x77359400, 0x3914b00, 0x2546f01, 0x3914b00, 0x81216f8, 0x3914b00, 0x8121601)
        C:/go/src/github.com/docker/docker/vendor/github.com/miekg/dns/server.go:695 +0xc2
github.com/docker/docker/vendor/github.com/miekg/dns.(*defaultReader).ReadUDP(0xc00072a010, 0xc000006350, 0x77359400, 0x81216c8, 0xc0006631d0, 0x1, 0x0, 0x2547180, 0xc0006631d0)
        C:/go/src/github.com/docker/docker/vendor/github.com/miekg/dns/server.go:261 +0x4d
github.com/docker/docker/vendor/github.com/miekg/dns.(*Server).serveUDP(0xc0001411e0, 0xc000006350, 0x0, 0x0)
        C:/go/src/github.com/docker/docker/vendor/github.com/miekg/dns/server.go:547 +0x119
github.com/docker/docker/vendor/github.com/miekg/dns.(*Server).ActivateAndServe(0xc0001411e0, 0x0, 0x0)
        C:/go/src/github.com/docker/docker/vendor/github.com/miekg/dns/server.go:461 +0x2ec
github.com/docker/docker/vendor/github.com/docker/libnetwork.(*resolver).Start.func2(0xc0001411e0)
        C:/go/src/github.com/docker/docker/vendor/github.com/docker/libnetwork/resolver.go:160 +0x32
created by github.com/docker/docker/vendor/github.com/docker/libnetwork.(*resolver).Start
        C:/go/src/github.com/docker/docker/vendor/github.com/docker/libnetwork/resolver.go:159 +0x10a

goroutine 59 [sleep]:
runtime.goparkunlock(...)
        C:/.GOROOT/src/runtime/proc.go:307
time.Sleep(0x3b9aca00)
        C:/.GOROOT/src/runtime/time.go:105 +0x16e
github.com/docker/docker/daemon/stats.(*Collector).Run(0xc000727540)
        C:/go/src/github.com/docker/docker/daemon/stats/collector.go:96 +0x193
created by github.com/docker/docker/daemon.(*Daemon).newStatsCollector
        C:/go/src/github.com/docker/docker/daemon/stats_collector.go:24 +0x18b

goroutine 60 [chan receive]:
github.com/docker/docker/daemon.(*Daemon).execCommandGC(0xc000660200)
        C:/go/src/github.com/docker/docker/daemon/exec.go:305 +0x151
created by github.com/docker/docker/daemon.NewDaemon
        C:/go/src/github.com/docker/docker/daemon/daemon.go:1073 +0x29b9

goroutine 61 [select, 129 minutes]:
github.com/docker/docker/vendor/github.com/docker/libnetwork.(*controller).watchLoop(0xc00065e100)
        C:/go/src/github.com/docker/docker/vendor/github.com/docker/libnetwork/store.go:452 +0xcd
created by github.com/docker/docker/vendor/github.com/docker/libnetwork.(*controller).startWatch
        C:/go/src/github.com/docker/docker/vendor/github.com/docker/libnetwork/store.go:469 +0xd4

goroutine 69 [IO wait, 300 minutes]:
internal/poll.runtime_pollWait(0x8120fc8, 0x72, 0x254b340)
        C:/.GOROOT/src/runtime/netpoll.go:182 +0x5d
internal/poll.(*pollDesc).wait(0xc0001557c8, 0x72, 0x386be00, 0x0, 0x0)
        C:/.GOROOT/src/internal/poll/fd_poll_runtime.go:87 +0xa2
internal/poll.(*ioSrv).ExecIO(0x38e6c00, 0xc000155618, 0xc00061e000, 0x1, 0x0, 0x434)
        C:/.GOROOT/src/internal/poll/fd_windows.go:228 +0x124
internal/poll.(*FD).acceptOne(0xc000155600, 0x434, 0xc000614000, 0x2, 0x2, 0xc000155618, 0x0, 0xc0000afd10, 0x41304f, 0x10)
        C:/.GOROOT/src/internal/poll/fd_windows.go:864 +0xa9
internal/poll.(*FD).Accept(0xc000155600, 0xc0007c6000, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
        C:/.GOROOT/src/internal/poll/fd_windows.go:898 +0x148
net.(*netFD).accept(0xc000155600, 0xc00066a5a0, 0x5730f40, 0x1)
        C:/.GOROOT/src/net/fd_windows.go:193 +0x81
net.(*TCPListener).accept(0xc000006358, 0x435f46, 0xc0000ca1c0, 0xc0000afed8)
        C:/.GOROOT/src/net/tcpsock_posix.go:139 +0x39
net.(*TCPListener).Accept(0xc000006358, 0x258cb88, 0xc000006358, 0x60, 0xc0000aff18)
        C:/.GOROOT/src/net/tcpsock.go:260 +0x4f
github.com/docker/docker/vendor/github.com/miekg/dns.(*Server).serveTCP(0xc0001412b0, 0x258cb60, 0xc000006358, 0x0, 0x0)
        C:/go/src/github.com/docker/docker/vendor/github.com/miekg/dns/server.go:514 +0x87
github.com/docker/docker/vendor/github.com/miekg/dns.(*Server).ActivateAndServe(0xc0001412b0, 0x0, 0x0)
        C:/go/src/github.com/docker/docker/vendor/github.com/miekg/dns/server.go:469 +0x267
github.com/docker/docker/vendor/github.com/docker/libnetwork.(*resolver).Start.func3(0xc0001412b0)
        C:/go/src/github.com/docker/docker/vendor/github.com/docker/libnetwork/resolver.go:166 +0x32
created by github.com/docker/docker/vendor/github.com/docker/libnetwork.(*resolver).Start
        C:/go/src/github.com/docker/docker/vendor/github.com/docker/libnetwork/resolver.go:165 +0x179

goroutine 70 [select, 300 minutes]:
github.com/docker/docker/daemon/telemetry.(*Telemetry).start.func1(0xc000041ec0)
        C:/go/src/github.com/docker/docker/daemon/telemetry/telemetry.go:60 +0xd7
created by github.com/docker/docker/daemon/telemetry.(*Telemetry).start
        C:/go/src/github.com/docker/docker/daemon/telemetry/telemetry.go:58 +0xa0

goroutine 71 [chan receive]:
github.com/docker/docker/builder/builder-next/adapters/containerimage.newResolverCache.func1(0xc00006cfb0, 0xc000142640)
        C:/go/src/github.com/docker/docker/builder/builder-next/adapters/containerimage/pull.go:896 +0x50
created by github.com/docker/docker/builder/builder-next/adapters/containerimage.newResolverCache
        C:/go/src/github.com/docker/docker/builder/builder-next/adapters/containerimage/pull.go:894 +0x9c

goroutine 72 [sync.Cond.Wait, 300 minutes]:
runtime.goparkunlock(...)
        C:/.GOROOT/src/runtime/proc.go:307
sync.runtime_notifyListWait(0xc00060e450, 0x0)
        C:/.GOROOT/src/runtime/sema.go:510 +0x107
sync.(*Cond).Wait(0xc00060e440)
        C:/.GOROOT/src/sync/cond.go:56 +0xa5
github.com/docker/docker/vendor/github.com/moby/buildkit/util/cond.(*StatefulCond).Wait(0xc0007b54d0)
        C:/go/src/github.com/docker/docker/vendor/github.com/moby/buildkit/util/cond/cond.go:28 +0x9f
github.com/docker/docker/vendor/github.com/moby/buildkit/solver.(*scheduler).loop(0xc0007c50a0)
        C:/go/src/github.com/docker/docker/vendor/github.com/moby/buildkit/solver/scheduler.go:101 +0x16f
created by github.com/docker/docker/vendor/github.com/moby/buildkit/solver.newScheduler
        C:/go/src/github.com/docker/docker/vendor/github.com/moby/buildkit/solver/scheduler.go:35 +0x1b4

goroutine 32 [chan receive, 300 minutes]:
github.com/docker/docker/vendor/github.com/moby/buildkit/solver.(*scheduler).loop.func2(0xc0007c50a0)
        C:/go/src/github.com/docker/docker/vendor/github.com/moby/buildkit/solver/scheduler.go:76 +0x3f
created by github.com/docker/docker/vendor/github.com/moby/buildkit/solver.(*scheduler).loop
        C:/go/src/github.com/docker/docker/vendor/github.com/moby/buildkit/solver/scheduler.go:75 +0x74

goroutine 73 [select, 300 minutes]:
github.com/docker/docker/daemon.(*Daemon).ProcessClusterNotifications(0xc000660200, 0x259c7e0, 0xc000726a80, 0xc0000cd500)
        C:/go/src/github.com/docker/docker/daemon/events.go:126 +0xec
created by main.(*DaemonCli).start
        C:/go/src/github.com/docker/docker/cmd/dockerd/daemon.go:244 +0xb06

goroutine 74 [syscall, 300 minutes, locked to thread]:
syscall.Syscall(0x7ff836e32270, 0x2, 0x444, 0xffffffff, 0x0, 0x0, 0x0, 0x0)
        C:/.GOROOT/src/runtime/syscall_windows.go:184 +0xea
github.com/docker/docker/vendor/golang.org/x/sys/windows.WaitForSingleObject(0x444, 0xffffffff, 0x21c32ca, 0x24, 0xc00075ffa8)
        C:/go/src/github.com/docker/docker/vendor/golang.org/x/sys/windows/zsyscall_windows.go:1097 +0x6b
main.(*DaemonCli).setupConfigReloadTrap.func1(0xc0006793b0)
        C:/go/src/github.com/docker/docker/cmd/dockerd/daemon_windows.go:72 +0x1d2
created by main.(*DaemonCli).setupConfigReloadTrap
        C:/go/src/github.com/docker/docker/cmd/dockerd/daemon_windows.go:63 +0x46

goroutine 75 [chan receive, 300 minutes]:
github.com/docker/docker/api/server.(*Server).serveAPI(0xc0007289c0, 0x0, 0x0)
        C:/go/src/github.com/docker/docker/api/server/server.go:95 +0x135
github.com/docker/docker/api/server.(*Server).Wait(0xc0007289c0, 0xc00099df20)
        C:/go/src/github.com/docker/docker/api/server/server.go:205 +0x36
created by main.(*DaemonCli).start
        C:/go/src/github.com/docker/docker/cmd/dockerd/daemon.go:252 +0xb6b

goroutine 76 [IO wait, 131 minutes]:
internal/poll.runtime_pollWait(0x8121168, 0x72, 0x254b340)
        C:/.GOROOT/src/runtime/netpoll.go:182 +0x5d
internal/poll.(*pollDesc).wait(0xc0008321c8, 0x72, 0x386be00, 0x0, 0x0)
        C:/.GOROOT/src/internal/poll/fd_poll_runtime.go:87 +0xa2
internal/poll.(*ioSrv).ExecIO(0x38e6c00, 0xc000832018, 0xc00061e060, 0x1, 0x0, 0x728)
        C:/.GOROOT/src/internal/poll/fd_windows.go:228 +0x124
internal/poll.(*FD).acceptOne(0xc000832000, 0x728, 0xc00262c000, 0x2, 0x2, 0xc000832018, 0x466ed0, 0xc000a75ca0, 0x41304f, 0x10)
        C:/.GOROOT/src/internal/poll/fd_windows.go:864 +0xa9
internal/poll.(*FD).Accept(0xc000832000, 0xc0000781c0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
        C:/.GOROOT/src/internal/poll/fd_windows.go:898 +0x148
net.(*netFD).accept(0xc000832000, 0x222e0b8, 0xc000a75e28, 0x5e4024a7)
        C:/.GOROOT/src/net/fd_windows.go:193 +0x81
net.(*TCPListener).accept(0xc00072a240, 0x776149, 0xc000658f30, 0x4e4a9d)
        C:/.GOROOT/src/net/tcpsock_posix.go:139 +0x39
net.(*TCPListener).Accept(0xc00072a240, 0xc000a75ea0, 0x18, 0xc000a50600, 0x77577b)
        C:/.GOROOT/src/net/tcpsock.go:260 +0x4f
net/http.(*Server).Serve(0xc000658ea0, 0x258cb60, 0xc00072a240, 0x0, 0x0)
        C:/.GOROOT/src/net/http/server.go:2859 +0x234
github.com/docker/docker/api/server.(*HTTPServer).Serve(...)
        C:/go/src/github.com/docker/docker/api/server/server.go:113
github.com/docker/docker/api/server.(*Server).serveAPI.func1(0xc000a03860, 0xc0008300e0)
        C:/go/src/github.com/docker/docker/api/server/server.go:87 +0xd9
created by github.com/docker/docker/api/server.(*Server).serveAPI
        C:/go/src/github.com/docker/docker/api/server/server.go:84 +0x8d

goroutine 1035 [select, 127 minutes]:
io.(*pipe).Read(0xc000663040, 0xc0019c0000, 0x100000, 0x100000, 0x0, 0x0, 0x0)
        C:/.GOROOT/src/io/pipe.go:50 +0xee
io.(*PipeReader).Read(0xc000136158, 0xc0019c0000, 0x100000, 0x100000, 0x0, 0x0, 0x7b01520)
        C:/.GOROOT/src/io/pipe.go:127 +0x53
io.(*teeReader).Read(0xc0009a0cc0, 0xc0019c0000, 0x100000, 0x100000, 0xc0017d7cf8, 0x41304f, 0x100000)
        C:/.GOROOT/src/io/io.go:535 +0x5c
io.(*teeReader).Read(0xc0009a0d60, 0xc0019c0000, 0x100000, 0x100000, 0x0, 0x0, 0x0)
        C:/.GOROOT/src/io/io.go:535 +0x5c
github.com/docker/docker/vendor/github.com/vbatts/tar-split/tar/asm.NewInputTarStream.func1(0x2547060, 0xc0009a0d60, 0xc000136270, 0x25466a0, 0xc00226a690, 0x2546680, 0x3915578)
        C:/go/src/github.com/docker/docker/vendor/github.com/vbatts/tar-split/tar/asm/disassemble.go:130 +0x5d2
created by github.com/docker/docker/vendor/github.com/vbatts/tar-split/tar/asm.NewInputTarStream
        C:/go/src/github.com/docker/docker/vendor/github.com/vbatts/tar-split/tar/asm/disassemble.go:45 +0x206

goroutine 973 [select, 165 minutes]:
io.(*pipe).Read(0xc0000ca910, 0xc0005d0000, 0x8000, 0x8000, 0x200, 0x0, 0x0)
        C:/.GOROOT/src/io/pipe.go:50 +0xee
io.(*PipeReader).Read(0xc00072a458, 0xc0005d0000, 0x8000, 0x8000, 0x200, 0x0, 0x0)
        C:/.GOROOT/src/io/pipe.go:127 +0x53
io.copyBuffer(0x25475c0, 0xc00072a480, 0x2546fc0, 0xc00072a458, 0xc0005d0000, 0x8000, 0x8000, 0x0, 0xc000acdfaf, 0xc0007075c0)
        C:/.GOROOT/src/io/io.go:402 +0x129
io.Copy(...)
        C:/.GOROOT/src/io/io.go:364
os/exec.(*Cmd).stdin.func1(0xc00099d500, 0x100000000000000)
        C:/.GOROOT/src/os/exec/exec.go:243 +0x6e
os/exec.(*Cmd).Start.func1(0xc00114c9a0, 0xc000d60de0)
        C:/.GOROOT/src/os/exec/exec.go:409 +0x2e
created by os/exec.(*Cmd).Start
        C:/.GOROOT/src/os/exec/exec.go:408 +0x5ed

goroutine 1011 [IO wait, 131 minutes]:
internal/poll.runtime_pollWait(0x8120c88, 0x72, 0x254b340)
        C:/.GOROOT/src/runtime/netpoll.go:182 +0x5d
internal/poll.(*pollDesc).wait(0xc0000ffa88, 0x72, 0x386be00, 0x0, 0x0)
        C:/.GOROOT/src/internal/poll/fd_poll_runtime.go:87 +0xa2
internal/poll.(*ioSrv).ExecIO(0x38e6c00, 0xc0000ff8d8, 0x222d530, 0x2543f60, 0xc000078030, 0xc000b4deb8)
        C:/.GOROOT/src/internal/poll/fd_windows.go:228 +0x124
internal/poll.(*FD).Read(0xc0000ff8c0, 0xc0005adcc1, 0x1, 0x1, 0x0, 0x0, 0x0)
        C:/.GOROOT/src/internal/poll/fd_windows.go:502 +0x26b
net.(*netFD).Read(0xc0000ff8c0, 0xc0005adcc1, 0x1, 0x1, 0x0, 0xc000005620, 0xc00169a000)
        C:/.GOROOT/src/net/fd_windows.go:152 +0x56
net.(*conn).Read(0xc000136028, 0xc0005adcc1, 0x1, 0x1, 0x0, 0x0, 0x0)
        C:/.GOROOT/src/net/net.go:177 +0x70
net/http.(*connReader).backgroundRead(0xc0005adcb0)
        C:/.GOROOT/src/net/http/server.go:677 +0x5f
created by net/http.(*connReader).startBackgroundRead
        C:/.GOROOT/src/net/http/server.go:673 +0xd1

goroutine 976 [chan receive, 127 minutes]:
os/exec.(*Cmd).Wait(0xc00114c2c0, 0x0, 0x0)
        C:/.GOROOT/src/os/exec/exec.go:482 +0x12d
github.com/docker/docker/daemon/graphdriver/windows.(*Driver).importLayer(0xc00084e180, 0xc00257dd80, 0x40, 0x2546fc0, 0xc000136258, 0xc0007358c0, 0x9, 0x9, 0x0, 0x2547060, ...)
        C:/go/src/github.com/docker/docker/daemon/graphdriver/windows/windows.go:782 +0x277
github.com/docker/docker/daemon/graphdriver/windows.(*Driver).ApplyDiff(0xc00084e180, 0xc00257dd80, 0x40, 0xc000bf6100, 0x40, 0x2546fc0, 0xc000136258, 0xc000136258, 0x0, 0x0)
        C:/go/src/github.com/docker/docker/daemon/graphdriver/windows/windows.go:590 +0xb9
github.com/docker/docker/layer.(*layerStore).applyTar(0xc000728d20, 0xc0009b6ca0, 0x5731100, 0xc0009a0340, 0xc000bf6100, 0x40, 0xc000150840, 0x0, 0x0)
        C:/go/src/github.com/docker/docker/layer/layer_store.go:263 +0x1e4
github.com/docker/docker/layer.(*layerStore).registerWithDescriptor(0xc000728d20, 0x5731100, 0xc0009a0340, 0xc0027fd540, 0x47, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
        C:/go/src/github.com/docker/docker/layer/layer_store.go:343 +0x2a1
github.com/docker/docker/layer.(*layerStore).Register(0xc000728d20, 0x5731100, 0xc0009a0340, 0xc0027fd540, 0x47, 0x0, 0x2571360, 0xc0009a0340, 0x0)
        C:/go/src/github.com/docker/docker/layer/layer_store.go:281 +0x9a
github.com/docker/docker/daemon/images.(*ImageService).CommitImage(0xc0007d3180, 0x0, 0x0, 0x0, 0x0, 0xc0006a1cc0, 0xc0006a0140, 0xc000b9b940, 0x40, 0x0, ...)
        C:/go/src/github.com/docker/docker/daemon/images/image_commit.go:42 +0x271
github.com/docker/docker/daemon/images.(*ImageService).CommitBuildStep(0xc0007d3180, 0x0, 0x0, 0x0, 0x0, 0xc0006a1cc0, 0xc0006a0140, 0xc000b9b940, 0x40, 0x0, ...)
        C:/go/src/github.com/docker/docker/daemon/images/image_commit.go:126 +0x102
github.com/docker/docker/builder/dockerfile.(*Builder).commitContainer(0xc000150790, 0xc0009d6850, 0xc000b9b940, 0x40, 0xc0006a0140, 0x2544840, 0xc000a3a480)
        C:/go/src/github.com/docker/docker/builder/dockerfile/internals.go:109 +0x129
github.com/docker/docker/builder/dockerfile.dispatchRun(0xc0009d6850, 0xc0007c89c0, 0xc000150790, 0x257e960, 0xc0009dc870, 0xc00061e180, 0xc0006637c0, 0xc00061e180, 0xc002298ea8)
        C:/go/src/github.com/docker/docker/builder/dockerfile/dispatchers.go:400 +0xa17
github.com/docker/docker/builder/dockerfile.dispatch(0xc0009d6850, 0xc0007c89c0, 0xc000150790, 0x257e960, 0xc0009dc870, 0xc00061e180, 0x2545f20, 0xc0006637c0, 0x0, 0x0)
        C:/go/src/github.com/docker/docker/builder/dockerfile/evaluator.go:83 +0x3f2
github.com/docker/docker/builder/dockerfile.(*Builder).dispatchDockerfileWithCancellation(0xc000150790, 0xc000e0c240, 0x1, 0x1, 0x0, 0x0, 0x0, 0x5c, 0x257e960, 0xc0009dc870, ...)
        C:/go/src/github.com/docker/docker/builder/dockerfile/builder.go:347 +0x523
github.com/docker/docker/builder/dockerfile.(*Builder).build(0xc000150790, 0x257e960, 0xc0009dc870, 0xc000a5c9f0, 0x0, 0x0, 0x0)
        C:/go/src/github.com/docker/docker/builder/dockerfile/builder.go:265 +0x31c
github.com/docker/docker/builder/dockerfile.(*BuildManager).Build(0xc00060e000, 0x259c7e0, 0xc00008bd00, 0x2570d60, 0xc0009dc4e0, 0x2543fe0, 0xc000a3a460, 0x2544840, 0xc000a3a480, 0x2544840, ...)
        C:/go/src/github.com/docker/docker/builder/dockerfile/builder.go:120 +0x38d
github.com/docker/docker/api/server/backend/build.(*Backend).Build(0xc0007b5530, 0x259c8a0, 0xc0009dc3c0, 0x2570d60, 0xc0009dc4e0, 0x2543fe0, 0xc000a3a460, 0x2544840, 0xc000a3a480, 0x2544840, ...)
        C:/go/src/github.com/docker/docker/api/server/backend/build/backend.go:68 +0x524
github.com/docker/docker/api/server/router/build.(*buildRouter).postBuild(0xc00060e580, 0x259c8a0, 0xc0009dc3c0, 0x258cde0, 0xc0005b0000, 0xc002612400, 0xc0009dc120, 0x0, 0x0)
        C:/go/src/github.com/docker/docker/api/server/router/build/build_routes.go:281 +0x736
github.com/docker/docker/api/server/middleware.ExperimentalMiddleware.WrapHandler.func1(0x259c8a0, 0xc0009dc3c0, 0x258cde0, 0xc0005b0000, 0xc002612400, 0xc0009dc120, 0x259c8a0, 0xc0009dc3c0)
        C:/go/src/github.com/docker/docker/api/server/middleware/experimental.go:26 +0x180
github.com/docker/docker/api/server/middleware.VersionMiddleware.WrapHandler.func1(0x259c8a0, 0xc0009dc360, 0x258cde0, 0xc0005b0000, 0xc002612400, 0xc0009dc120, 0x20, 0x25051f7)
        C:/go/src/github.com/docker/docker/api/server/middleware/version.go:62 +0x612
github.com/docker/docker/pkg/authorization.(*Middleware).WrapHandler.func1(0x259c8a0, 0xc0009dc360, 0x258cde0, 0xc0005b0000, 0xc002612400, 0xc0009dc120, 0x259c8a0, 0xc0009dc360)
        C:/go/src/github.com/docker/docker/pkg/authorization/middleware.go:59 +0x834
github.com/docker/docker/api/server.(*Server).makeHTTPHandler.func1(0x258cde0, 0xc0005b0000, 0xc002612300)
        C:/go/src/github.com/docker/docker/api/server/server.go:142 +0x22a
net/http.HandlerFunc.ServeHTTP(0xc0009272a0, 0x258cde0, 0xc0005b0000, 0xc002612300)
        C:/.GOROOT/src/net/http/server.go:1995 +0x4b
github.com/docker/docker/vendor/github.com/gorilla/mux.(*Router).ServeHTTP(0xc0006d0480, 0x258cde0, 0xc0005b0000, 0xc002612600)
        C:/go/src/github.com/docker/docker/vendor/github.com/gorilla/mux/mux.go:212 +0xea
github.com/docker/docker/api/server.(*routerSwapper).ServeHTTP(0xc000a078a0, 0x258cde0, 0xc0005b0000, 0xc002612600)
        C:/go/src/github.com/docker/docker/api/server/router_swapper.go:29 +0x77
net/http.serverHandler.ServeHTTP(0xc000658ea0, 0x258cde0, 0xc0005b0000, 0xc002612600)
        C:/.GOROOT/src/net/http/server.go:2774 +0xaf
net/http.(*conn).serve(0xc00074c0a0, 0x259c7e0, 0xc00008a000)
        C:/.GOROOT/src/net/http/server.go:1878 +0x858
created by net/http.(*Server).Serve
        C:/.GOROOT/src/net/http/server.go:2884 +0x2fb

goroutine 972 [select, 165 minutes]:
io.(*pipe).Read(0xc0000ca730, 0xc002130000, 0x100000, 0x100000, 0x0, 0x0, 0x0)
        C:/.GOROOT/src/io/pipe.go:50 +0xee
io.(*PipeReader).Read(0xc00072a3d0, 0xc002130000, 0x100000, 0x100000, 0x0, 0x0, 0x7b01520)
        C:/.GOROOT/src/io/pipe.go:127 +0x53
io.(*teeReader).Read(0xc000d60be0, 0xc002130000, 0x100000, 0x100000, 0xc000b7dcf8, 0x41304f, 0x100000)
        C:/.GOROOT/src/io/io.go:535 +0x5c
io.(*teeReader).Read(0xc000d60c20, 0xc002130000, 0x100000, 0x100000, 0x0, 0x0, 0x0)
        C:/.GOROOT/src/io/io.go:535 +0x5c
github.com/docker/docker/vendor/github.com/vbatts/tar-split/tar/asm.NewInputTarStream.func1(0x2547060, 0xc000d60c20, 0xc00072a460, 0x25466a0, 0xc000dc7a10, 0x2546680, 0x3915578)
        C:/go/src/github.com/docker/docker/vendor/github.com/vbatts/tar-split/tar/asm/disassemble.go:130 +0x5d2
created by github.com/docker/docker/vendor/github.com/vbatts/tar-split/tar/asm.NewInputTarStream
        C:/go/src/github.com/docker/docker/vendor/github.com/vbatts/tar-split/tar/asm/disassemble.go:45 +0x206

goroutine 848 [IO wait, 171 minutes]:
internal/poll.runtime_pollWait(0x8120d58, 0x72, 0x254b340)
        C:/.GOROOT/src/runtime/netpoll.go:182 +0x5d
internal/poll.(*pollDesc).wait(0xc000155a88, 0x72, 0x386be00, 0x0, 0x0)
        C:/.GOROOT/src/internal/poll/fd_poll_runtime.go:87 +0xa2
internal/poll.(*ioSrv).ExecIO(0x38e6c00, 0xc0001558d8, 0x222d530, 0x50, 0x50, 0xc00078c820)
        C:/.GOROOT/src/internal/poll/fd_windows.go:228 +0x124
internal/poll.(*FD).Read(0xc0001558c0, 0xc00090c1c1, 0x1, 0x1, 0x0, 0x0, 0x0)
        C:/.GOROOT/src/internal/poll/fd_windows.go:502 +0x26b
net.(*netFD).Read(0xc0001558c0, 0xc00090c1c1, 0x1, 0x1, 0xc000726198, 0xc000a53f68, 0x46f424)
        C:/.GOROOT/src/net/fd_windows.go:152 +0x56
net.(*conn).Read(0xc000006008, 0xc00090c1c1, 0x1, 0x1, 0x0, 0x0, 0x0)
        C:/.GOROOT/src/net/net.go:177 +0x70
net/http.(*connReader).backgroundRead(0xc00090c1b0)
        C:/.GOROOT/src/net/http/server.go:677 +0x5f
created by net/http.(*connReader).startBackgroundRead
        C:/.GOROOT/src/net/http/server.go:673 +0xd1

goroutine 324 [syscall, 129 minutes, locked to thread]:
syscall.Syscall6(0x7ff836e26b90, 0x5, 0x500, 0xc000b45f9c, 0xc000b45fa0, 0xc000b45fa8, 0xffffffff, 0x0, 0x0, 0x0, ...)
        C:/.GOROOT/src/runtime/syscall_windows.go:197 +0xed
github.com/docker/docker/vendor/github.com/Microsoft/go-winio.getQueuedCompletionStatus(0x500, 0xc000b45f9c, 0xc000b45fa0, 0xc000b45fa8, 0xffffffff, 0x254b340, 0xc001150008)
        C:/go/src/github.com/docker/docker/vendor/github.com/Microsoft/go-winio/zsyscall_windows.go:100 +0xb6
github.com/docker/docker/vendor/github.com/Microsoft/go-winio.ioCompletionProcessor(0x500)
        C:/go/src/github.com/docker/docker/vendor/github.com/Microsoft/go-winio/file.go:159 +0xb6
created by github.com/docker/docker/vendor/github.com/Microsoft/go-winio.initIo
        C:/go/src/github.com/docker/docker/vendor/github.com/Microsoft/go-winio/file.go:72 +0x7d

goroutine 971 [runnable, locked to thread]:
syscall.Syscall(0x7ff836e326c0, 0x1, 0xc001c05a40, 0x0, 0x0, 0x0, 0x0, 0x0)
        C:/.GOROOT/src/runtime/syscall_windows.go:184 +0xea
syscall.RemoveDirectory(0xc001c05a40, 0x254b340, 0xc001150a50)
        C:/.GOROOT/src/syscall/zsyscall_windows.go:465 +0x6b
os.Remove(0xc000e24580, 0x78, 0x78, 0xc00150f9c8)
        C:/.GOROOT/src/os/file_windows.go:276 +0x19c
os.removeAll(0xc000e24580, 0x78, 0xc000e24580, 0x78)
        C:/.GOROOT/src/os/removeall_noat.go:29 +0x196
os.RemoveAll(0xc000e24580, 0x78, 0x4a, 0x217be32)
        C:/.GOROOT/src/os/path.go:67 +0x3c
os.removeAll(0xc000cea4b0, 0x4a, 0xc000cea4b0, 0x4a)
        C:/.GOROOT/src/os/removeall_noat.go:70 +0x5f3
os.RemoveAll(0xc000cea4b0, 0x4a, 0x3d, 0x217be32)
        C:/.GOROOT/src/os/path.go:67 +0x3c
os.removeAll(0xc0012f2940, 0x3d, 0xc0012f2940, 0x3d)
        C:/.GOROOT/src/os/removeall_noat.go:70 +0x5f3
os.RemoveAll(0xc0012f2940, 0x3d, 0x30, 0x217be32)
        C:/.GOROOT/src/os/path.go:67 +0x3c
os.removeAll(0xc00074b9b0, 0x30, 0xc00074b9b0, 0x30)
        C:/.GOROOT/src/os/removeall_noat.go:70 +0x5f3
os.RemoveAll(0xc00074b9b0, 0x30, 0x2a, 0x217be32)
        C:/.GOROOT/src/os/path.go:67 +0x3c
os.removeAll(0xc00012a4b0, 0x2a, 0x131d601, 0x1)
        C:/.GOROOT/src/os/removeall_noat.go:70 +0x5f3
os.RemoveAll(0xc00012a4b0, 0x2a, 0x0, 0x0)
        C:/.GOROOT/src/os/path.go:67 +0x3c
github.com/docker/docker/vendor/github.com/Microsoft/hcsshim/internal/wclayer.(*legacyLayerReaderWrapper).Close(0xc0000ba590, 0xc0000ba590, 0x2546fe0)
        C:/go/src/github.com/docker/docker/vendor/github.com/Microsoft/hcsshim/internal/wclayer/exportlayer.go:74 +0x95
github.com/docker/docker/daemon/graphdriver/windows.(*Driver).exportLayer.func1.1(0x7f4, 0xc00059b7e8)
        C:/go/src/github.com/docker/docker/daemon/graphdriver/windows/windows.go:672 +0x120
github.com/docker/docker/vendor/github.com/Microsoft/go-winio.RunWithPrivileges(0xc000ab5f88, 0x1, 0x1, 0xc00008a000, 0x0, 0x0)
        C:/go/src/github.com/docker/docker/vendor/github.com/Microsoft/go-winio/privilege.go:92 +0x164
github.com/docker/docker/vendor/github.com/Microsoft/go-winio.RunWithPrivilege(...)
        C:/go/src/github.com/docker/docker/vendor/github.com/Microsoft/go-winio/privilege.go:72
github.com/docker/docker/daemon/graphdriver/windows.(*Driver).exportLayer.func1(0xc00084e180, 0xc001414b80, 0x40, 0xc0009d0b40, 0x9, 0x9, 0xc00072a3e8)
        C:/go/src/github.com/docker/docker/daemon/graphdriver/windows/windows.go:665 +0xf3
created by github.com/docker/docker/daemon/graphdriver/windows.(*Driver).exportLayer
        C:/go/src/github.com/docker/docker/daemon/graphdriver/windows/windows.go:664 +0x198

goroutine 1036 [select, 127 minutes]:
io.(*pipe).Read(0xc000663180, 0xc000bee000, 0x8000, 0x8000, 0x200, 0x0, 0x0)
        C:/.GOROOT/src/io/pipe.go:50 +0xee
io.(*PipeReader).Read(0xc000136258, 0xc000bee000, 0x8000, 0x8000, 0x200, 0x0, 0x0)
        C:/.GOROOT/src/io/pipe.go:127 +0x53
io.copyBuffer(0x25475c0, 0xc0001362c8, 0x2546fc0, 0xc000136258, 0xc000bee000, 0x8000, 0x8000, 0x0, 0x0, 0x0)
        C:/.GOROOT/src/io/io.go:402 +0x129
io.Copy(...)
        C:/.GOROOT/src/io/io.go:364
os/exec.(*Cmd).stdin.func1(0x0, 0x0)
        C:/.GOROOT/src/os/exec/exec.go:243 +0x6e
os/exec.(*Cmd).Start.func1(0xc00114c2c0, 0xc0009a0f00)
        C:/.GOROOT/src/os/exec/exec.go:409 +0x2e
created by os/exec.(*Cmd).Start
        C:/.GOROOT/src/os/exec/exec.go:408 +0x5ed

goroutine 1034 [runnable, locked to thread]:
syscall.Syscall(0x7ff836e326c0, 0x1, 0xc000e13720, 0x0, 0x0, 0x0, 0x0, 0x0)
        C:/.GOROOT/src/runtime/syscall_windows.go:184 +0xea
syscall.RemoveDirectory(0xc000e13720, 0x254b340, 0xc00096dc00)
        C:/.GOROOT/src/syscall/zsyscall_windows.go:465 +0x6b
os.Remove(0xc0010eabe0, 0x4a, 0x0, 0x0)
        C:/.GOROOT/src/os/file_windows.go:276 +0x19c
os.removeAll(0xc0010eabe0, 0x4a, 0xc0010eabe0, 0x4a)
        C:/.GOROOT/src/os/removeall_noat.go:92 +0x3e7
os.RemoveAll(0xc0010eabe0, 0x4a, 0x3d, 0x217be32)
        C:/.GOROOT/src/os/path.go:67 +0x3c
os.removeAll(0xc002240c40, 0x3d, 0xc002240c40, 0x3d)
        C:/.GOROOT/src/os/removeall_noat.go:70 +0x5f3
os.RemoveAll(0xc002240c40, 0x3d, 0x30, 0x217be32)
        C:/.GOROOT/src/os/path.go:67 +0x3c
os.removeAll(0xc0017a6b70, 0x30, 0xc0017a6b70, 0x30)
        C:/.GOROOT/src/os/removeall_noat.go:70 +0x5f3
os.RemoveAll(0xc0017a6b70, 0x30, 0x2a, 0x217be32)
        C:/.GOROOT/src/os/path.go:67 +0x3c
os.removeAll(0xc00074a0f0, 0x2a, 0x131d601, 0x1)
        C:/.GOROOT/src/os/removeall_noat.go:70 +0x5f3
os.RemoveAll(0xc00074a0f0, 0x2a, 0x0, 0x0)
        C:/.GOROOT/src/os/path.go:67 +0x3c
github.com/docker/docker/vendor/github.com/Microsoft/hcsshim/internal/wclayer.(*legacyLayerReaderWrapper).Close(0xc00072a0a8, 0xc00072a0a8, 0x2546fe0)
        C:/go/src/github.com/docker/docker/vendor/github.com/Microsoft/hcsshim/internal/wclayer/exportlayer.go:74 +0x95
github.com/docker/docker/daemon/graphdriver/windows.(*Driver).exportLayer.func1.1(0x5dc, 0xc000950270)
        C:/go/src/github.com/docker/docker/daemon/graphdriver/windows/windows.go:672 +0x120
github.com/docker/docker/vendor/github.com/Microsoft/go-winio.RunWithPrivileges(0xc0027edf88, 0x1, 0x1, 0xc000727000, 0x0, 0x0)
        C:/go/src/github.com/docker/docker/vendor/github.com/Microsoft/go-winio/privilege.go:92 +0x164
github.com/docker/docker/vendor/github.com/Microsoft/go-winio.RunWithPrivilege(...)
        C:/go/src/github.com/docker/docker/vendor/github.com/Microsoft/go-winio/privilege.go:72
github.com/docker/docker/daemon/graphdriver/windows.(*Driver).exportLayer.func1(0xc00084e180, 0xc000b9b940, 0x40, 0xc0008e73b0, 0x9, 0x9, 0xc0001361a8)
        C:/go/src/github.com/docker/docker/daemon/graphdriver/windows/windows.go:665 +0xf3
created by github.com/docker/docker/daemon/graphdriver/windows.(*Driver).exportLayer
        C:/go/src/github.com/docker/docker/daemon/graphdriver/windows/windows.go:664 +0x198

goroutine 906 [chan receive, 165 minutes]:
os/exec.(*Cmd).Wait(0xc00114c9a0, 0x0, 0x0)
        C:/.GOROOT/src/os/exec/exec.go:482 +0x12d
github.com/docker/docker/daemon/graphdriver/windows.(*Driver).importLayer(0xc00084e180, 0xc0001b3640, 0x40, 0x2546fc0, 0xc00072a458, 0xc0009d14d0, 0x9, 0x9, 0x0, 0x2547060, ...)
        C:/go/src/github.com/docker/docker/daemon/graphdriver/windows/windows.go:782 +0x277
github.com/docker/docker/daemon/graphdriver/windows.(*Driver).ApplyDiff(0xc00084e180, 0xc0001b3640, 0x40, 0xc0008d0100, 0x40, 0x2546fc0, 0xc00072a458, 0xc00072a458, 0x0, 0x0)
        C:/go/src/github.com/docker/docker/daemon/graphdriver/windows/windows.go:590 +0xb9
github.com/docker/docker/layer.(*layerStore).applyTar(0xc000728d20, 0xc0009b7950, 0x5731100, 0xc000d60400, 0xc0008d0100, 0x40, 0xc0001504d0, 0x0, 0x0)
        C:/go/src/github.com/docker/docker/layer/layer_store.go:263 +0x1e4
github.com/docker/docker/layer.(*layerStore).registerWithDescriptor(0xc000728d20, 0x5731100, 0xc000d60400, 0xc000d2af00, 0x47, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
        C:/go/src/github.com/docker/docker/layer/layer_store.go:343 +0x2a1
github.com/docker/docker/layer.(*layerStore).Register(0xc000728d20, 0x5731100, 0xc000d60400, 0xc000d2af00, 0x47, 0x0, 0x2571360, 0xc000d60400, 0x0)
        C:/go/src/github.com/docker/docker/layer/layer_store.go:281 +0x9a
github.com/docker/docker/daemon/images.(*ImageService).CommitImage(0xc0007d3180, 0x0, 0x0, 0x0, 0x0, 0xc00078f400, 0xc00078e3c0, 0xc001414b80, 0x40, 0x0, ...)
        C:/go/src/github.com/docker/docker/daemon/images/image_commit.go:42 +0x271
github.com/docker/docker/daemon/images.(*ImageService).CommitBuildStep(0xc0007d3180, 0x0, 0x0, 0x0, 0x0, 0xc00078f400, 0xc00078e3c0, 0xc001414b80, 0x40, 0x0, ...)
        C:/go/src/github.com/docker/docker/daemon/images/image_commit.go:126 +0x102
github.com/docker/docker/builder/dockerfile.(*Builder).commitContainer(0xc000150580, 0xc0009ef8f0, 0xc001414b80, 0x40, 0xc00078e3c0, 0x2544840, 0xc000d62420)
        C:/go/src/github.com/docker/docker/builder/dockerfile/internals.go:109 +0x129
github.com/docker/docker/builder/dockerfile.dispatchRun(0xc0009ef8f0, 0xc0007336c0, 0xc000150580, 0x257e960, 0xc00090d1d0, 0xc000d34280, 0xc00078ce60, 0xc000d34280, 0xc000ef2ea8)
        C:/go/src/github.com/docker/docker/builder/dockerfile/dispatchers.go:400 +0xa17
github.com/docker/docker/builder/dockerfile.dispatch(0xc0009ef8f0, 0xc0007336c0, 0xc000150580, 0x257e960, 0xc00090d1d0, 0xc000d34280, 0x2545f20, 0xc00078ce60, 0x0, 0x0)
        C:/go/src/github.com/docker/docker/builder/dockerfile/evaluator.go:83 +0x3f2
github.com/docker/docker/builder/dockerfile.(*Builder).dispatchDockerfileWithCancellation(0xc000150580, 0xc000d028a0, 0x1, 0x1, 0x0, 0x0, 0x0, 0x5c, 0x257e960, 0xc00090d1d0, ...)
        C:/go/src/github.com/docker/docker/builder/dockerfile/builder.go:347 +0x523
github.com/docker/docker/builder/dockerfile.(*Builder).build(0xc000150580, 0x257e960, 0xc00090d1d0, 0xc000a48e40, 0x0, 0x0, 0x0)
        C:/go/src/github.com/docker/docker/builder/dockerfile/builder.go:265 +0x31c
github.com/docker/docker/builder/dockerfile.(*BuildManager).Build(0xc00060e000, 0x259c7e0, 0xc000726c00, 0x2570d60, 0xc00090cc90, 0x2543fe0, 0xc000d62400, 0x2544840, 0xc000d62420, 0x2544840, ...)
        C:/go/src/github.com/docker/docker/builder/dockerfile/builder.go:120 +0x38d
github.com/docker/docker/api/server/backend/build.(*Backend).Build(0xc0007b5530, 0x259c8a0, 0xc00090cba0, 0x2570d60, 0xc00090cc90, 0x2543fe0, 0xc000d62400, 0x2544840, 0xc000d62420, 0x2544840, ...)
        C:/go/src/github.com/docker/docker/api/server/backend/build/backend.go:68 +0x524
github.com/docker/docker/api/server/router/build.(*buildRouter).postBuild(0xc00060e580, 0x259c8a0, 0xc00090cba0, 0x258cde0, 0xc000c540e0, 0xc00011cb00, 0xc00090c8d0, 0x0, 0x0)
        C:/go/src/github.com/docker/docker/api/server/router/build/build_routes.go:281 +0x736
github.com/docker/docker/api/server/middleware.ExperimentalMiddleware.WrapHandler.func1(0x259c8a0, 0xc00090cba0, 0x258cde0, 0xc000c540e0, 0xc00011cb00, 0xc00090c8d0, 0x259c8a0, 0xc00090cba0)
        C:/go/src/github.com/docker/docker/api/server/middleware/experimental.go:26 +0x180
github.com/docker/docker/api/server/middleware.VersionMiddleware.WrapHandler.func1(0x259c8a0, 0xc00090c9c0, 0x258cde0, 0xc000c540e0, 0xc00011cb00, 0xc00090c8d0, 0x20, 0x25051f7)
        C:/go/src/github.com/docker/docker/api/server/middleware/version.go:62 +0x612
github.com/docker/docker/pkg/authorization.(*Middleware).WrapHandler.func1(0x259c8a0, 0xc00090c9c0, 0x258cde0, 0xc000c540e0, 0xc00011cb00, 0xc00090c8d0, 0x259c8a0, 0xc00090c9c0)
        C:/go/src/github.com/docker/docker/pkg/authorization/middleware.go:59 +0x834
github.com/docker/docker/api/server.(*Server).makeHTTPHandler.func1(0x258cde0, 0xc000c540e0, 0xc00011c900)
        C:/go/src/github.com/docker/docker/api/server/server.go:142 +0x22a
net/http.HandlerFunc.ServeHTTP(0xc0009272a0, 0x258cde0, 0xc000c540e0, 0xc00011c900)
        C:/.GOROOT/src/net/http/server.go:1995 +0x4b
github.com/docker/docker/vendor/github.com/gorilla/mux.(*Router).ServeHTTP(0xc0006d0480, 0x258cde0, 0xc000c540e0, 0xc002612000)
        C:/go/src/github.com/docker/docker/vendor/github.com/gorilla/mux/mux.go:212 +0xea
github.com/docker/docker/api/server.(*routerSwapper).ServeHTTP(0xc000a078a0, 0x258cde0, 0xc000c540e0, 0xc002612000)
        C:/go/src/github.com/docker/docker/api/server/router_swapper.go:29 +0x77
net/http.serverHandler.ServeHTTP(0xc000658ea0, 0x258cde0, 0xc000c540e0, 0xc002612000)
        C:/.GOROOT/src/net/http/server.go:2774 +0xaf
net/http.(*conn).serve(0xc00067a000, 0x259c7e0, 0xc000726080)
        C:/.GOROOT/src/net/http/server.go:1878 +0x858
created by net/http.(*Server).Serve
        C:/.GOROOT/src/net/http/server.go:2884 +0x2fb

We can see two running coroutines, which are deleting stuff. I did another trace a few minutes ago, and I can see the upper stack pointers changing, but not

We also have another coroutine, stuck in: https://github.com/moby/moby/blob/master/daemon/graphdriver/windows/windows.go#L782

Which is a reexec call to writeLayer. Looking at my list of process, I don't see another dockerd process. Not sure if this is a thing

@jhowardmsft sorry for pinging directly. Any idea?

I will try to restart by enabling debug, and disable reexec using DOCKER_WINDOWSFILTER_NOREEXEC environment variable, as code suggests.

tardyp commented 5 years ago

After a few restart of dockerd, I have problems starting it because of error

time="2019-09-16T15:16:57.691323600-07:00" level=warning msg="failed to rename C:\\ProgramData\\docker\\tmp for background deletion: rename C:\\ProgramData\\docker\\tmp C:\\ProgramData\\docker\\tmp-old: Access is denied.. Deleting synchronously"

So I did zap the tmp directories, and then the dockerd daemon start again

PS C:\Program Files\docker> C:\docker-ci-zap.exe -folder C:\ProgramData\docker\tmp\
INFO: Zapped successfully
PS C:\Program Files\docker> C:\docker-ci-zap.exe -folder C:\ProgramData\docker\tmp-old
INFO: Zapped successfully

After running with debug mode, I get this trace in stdout:

time="2019-09-16T15:24:42.736428100-07:00" level=debug msg="completed container shutdown" container=a82013c6bc13c66af5bb7cc949cac2b9f339a79f0ad0d003331308c804f25e3d module=libcontainerd namespace=moby process=init
time="2019-09-16T15:24:42.738447100-07:00" level=debug msg="hcsshim::ComputeSystem::Close - Begin Operation" cid=a82013c6bc13c66af5bb7cc949cac2b9f339a79f0ad0d003331308c804f25e3d
time="2019-09-16T15:24:42.739441600-07:00" level=debug msg="hcsshim::ComputeSystem::Close - End Operation - Success" cid=a82013c6bc13c66af5bb7cc949cac2b9f339a79f0ad0d003331308c804f25e3d
time="2019-09-16T15:24:42.739441600-07:00" level=info msg="sending event" container=a82013c6bc13c66af5bb7cc949cac2b9f339a79f0ad0d003331308c804f25e3d event=exit event-info="{a82013c6bc13c66af5bb7cc949cac2b9f339a79f0ad0d003331308c804f25e3d init 3664 0 2019-09-16 15:24:41.
337428 -0700 PDT m=+275.328253001 false <nil>}" module=libcontainerd namespace=moby
time="2019-09-16T15:24:42.740434500-07:00" level=debug msg="attach: stdout: end"
time="2019-09-16T15:24:42.740434500-07:00" level=debug msg="attach: stderr: end"
time="2019-09-16T15:24:42.741445700-07:00" level=debug msg="attach done"
time="2019-09-16T15:24:42.742443400-07:00" level=debug msg="Revoking external connectivity on endpoint charming_feistel (7c9f688e533631d0d9716bde140c921d28b1d8ec1e6e33df1629fef9a2217413)"
time="2019-09-16T15:24:42.742443400-07:00" level=debug msg="hcsshim::OpenComputeSystem - Begin Operation" cid=a82013c6bc13c66af5bb7cc949cac2b9f339a79f0ad0d003331308c804f25e3d
time="2019-09-16T15:24:42.743436000-07:00" level=debug msg="hcsshim::OpenComputeSystem - End Operation - Success" cid=a82013c6bc13c66af5bb7cc949cac2b9f339a79f0ad0d003331308c804f25e3d
time="2019-09-16T15:24:42.759433400-07:00" level=debug msg="[DELETE]=>[/endpoints/DBF67B10-B591-4C33-A169-CAEE26926A2A] Request : "
time="2019-09-16T15:24:42.776436900-07:00" level=debug msg="Releasing addresses for endpoint charming_feistel's interface on network nat"
time="2019-09-16T15:24:42.777434500-07:00" level=debug msg="ReleaseAddress(172.30.160.0/20, 172.30.172.172)"
time="2019-09-16T15:24:42.790433600-07:00" level=debug msg="WindowsGraphDriver Put() id a82013c6bc13c66af5bb7cc949cac2b9f339a79f0ad0d003331308c804f25e3d"
time="2019-09-16T15:24:42.791432700-07:00" level=debug msg="hcsshim::UnprepareLayer" path="C:\\ProgramData\\docker\\windowsfilter\\a82013c6bc13c66af5bb7cc949cac2b9f339a79f0ad0d003331308c804f25e3d"
time="2019-09-16T15:24:42.820432200-07:00" level=debug msg="hcsshim::UnprepareLayer - succeeded" path="C:\\ProgramData\\docker\\windowsfilter\\a82013c6bc13c66af5bb7cc949cac2b9f339a79f0ad0d003331308c804f25e3d"
time="2019-09-16T15:24:42.821432500-07:00" level=debug msg="hcsshim::DeactivateLayer" path="C:\\ProgramData\\docker\\windowsfilter\\a82013c6bc13c66af5bb7cc949cac2b9f339a79f0ad0d003331308c804f25e3d"
time="2019-09-16T15:24:44.372486300-07:00" level=debug msg="hcsshim::DeactivateLayer - succeeded" path="C:\\ProgramData\\docker\\windowsfilter\\a82013c6bc13c66af5bb7cc949cac2b9f339a79f0ad0d003331308c804f25e3d"
time="2019-09-16T15:24:44.381487100-07:00" level=debug msg="WindowsGraphDriver Get() id a82013c6bc13c66af5bb7cc949cac2b9f339a79f0ad0d003331308c804f25e3d mountLabel "
time="2019-09-16T15:24:44.383445100-07:00" level=debug msg="hcsshim::ActivateLayer" path="C:\\ProgramData\\docker\\windowsfilter\\a82013c6bc13c66af5bb7cc949cac2b9f339a79f0ad0d003331308c804f25e3d"
time="2019-09-16T15:24:44.452447300-07:00" level=debug msg="hcsshim::ActivateLayer - succeeded" path="C:\\ProgramData\\docker\\windowsfilter\\a82013c6bc13c66af5bb7cc949cac2b9f339a79f0ad0d003331308c804f25e3d"
time="2019-09-16T15:24:44.453449000-07:00" level=debug msg="hcsshim::PrepareLayer" path="C:\\ProgramData\\docker\\windowsfilter\\a82013c6bc13c66af5bb7cc949cac2b9f339a79f0ad0d003331308c804f25e3d"
time="2019-09-16T15:24:44.454435100-07:00" level=debug msg="hcsshim::NameToGuid" name=587d388ce20d5ddb80b8a7bb3fdee9884797737ce33b5b00db78ec2726270193
time="2019-09-16T15:24:44.455442600-07:00" level=debug msg="hcsshim::NameToGuid - succeeded" guid=d2bcf92e-e6f1-5afc-b50c-c3fbfcc9a367 name=587d388ce20d5ddb80b8a7bb3fdee9884797737ce33b5b00db78ec2726270193
time="2019-09-16T15:24:44.455442600-07:00" level=debug msg="hcsshim::NameToGuid" name=65f611a0bfa46f6fd8b4bbc023523ffec0ac9f1d0e4a4275308f3c2597f8fe94
time="2019-09-16T15:24:44.456434300-07:00" level=debug msg="hcsshim::NameToGuid - succeeded" guid=4d300955-edda-50d3-9fab-70b3607593fe name=65f611a0bfa46f6fd8b4bbc023523ffec0ac9f1d0e4a4275308f3c2597f8fe94
time="2019-09-16T15:24:44.457432900-07:00" level=debug msg="hcsshim::NameToGuid" name=6e06c85f7fd717a1b6a8c9664c1c422c03a65a079624b0136f77465c00325654
time="2019-09-16T15:24:44.457432900-07:00" level=debug msg="hcsshim::NameToGuid - succeeded" guid=1bb144a6-293b-5d89-a479-95d37976ecb9 name=6e06c85f7fd717a1b6a8c9664c1c422c03a65a079624b0136f77465c00325654
time="2019-09-16T15:24:44.458434400-07:00" level=debug msg="hcsshim::NameToGuid" name=a35c063592d63f30c6a7dc361d6b24991123e180c07c3d8f646809a2fae2ba05
time="2019-09-16T15:24:44.458434400-07:00" level=debug msg="hcsshim::NameToGuid - succeeded" guid=7c936f90-3131-5f18-ad64-69ffca88a11c name=a35c063592d63f30c6a7dc361d6b24991123e180c07c3d8f646809a2fae2ba05
time="2019-09-16T15:24:44.459441200-07:00" level=debug msg="hcsshim::NameToGuid" name=522119ca0c1d5ec876732c63b752ff7a5f3bf7f73f2ad859e2934d7c0ceccb76
time="2019-09-16T15:24:44.460433300-07:00" level=debug msg="hcsshim::NameToGuid - succeeded" guid=f0990ba7-98d1-58ac-9898-58ba8a8e228c name=522119ca0c1d5ec876732c63b752ff7a5f3bf7f73f2ad859e2934d7c0ceccb76
time="2019-09-16T15:24:44.461433500-07:00" level=debug msg="hcsshim::NameToGuid" name=f0141935f0501d855ac26c573a443b5c3f1247ab3b567d1aba955e2f693eb933
time="2019-09-16T15:24:44.461433500-07:00" level=debug msg="hcsshim::NameToGuid - succeeded" guid=e5e54c1a-e4b1-5e27-aaf3-0908e255e124 name=f0141935f0501d855ac26c573a443b5c3f1247ab3b567d1aba955e2f693eb933
time="2019-09-16T15:24:44.462436100-07:00" level=debug msg="hcsshim::NameToGuid" name=3ff0e976381974986917b24702945d256792418a306c75efc9676f520d2d4c1a
time="2019-09-16T15:24:44.463716900-07:00" level=debug msg="hcsshim::NameToGuid - succeeded" guid=e0716d0b-eac4-57de-b20a-577ab7950b9e name=3ff0e976381974986917b24702945d256792418a306c75efc9676f520d2d4c1a
time="2019-09-16T15:24:44.464432500-07:00" level=debug msg="hcsshim::NameToGuid" name=917c3115bec50e148192c381f45442cbf414b4f1c02abe34f176793a0f8e3293
time="2019-09-16T15:24:44.464432500-07:00" level=debug msg="hcsshim::NameToGuid - succeeded" guid=db22d86f-df3c-5a60-9616-c9a57c798281 name=917c3115bec50e148192c381f45442cbf414b4f1c02abe34f176793a0f8e3293
time="2019-09-16T15:24:44.465435100-07:00" level=debug msg="hcsshim::NameToGuid" name=e357ee86499cd2e21c6d39ba2c5bd599f0ddfee2fb3ac6a0e48835ff54679421
time="2019-09-16T15:24:44.466432300-07:00" level=debug msg="hcsshim::NameToGuid - succeeded" guid=87e54c4d-5fc7-5f08-b6fd-7ba18d88c689 name=e357ee86499cd2e21c6d39ba2c5bd599f0ddfee2fb3ac6a0e48835ff54679421
time="2019-09-16T15:24:44.570488400-07:00" level=debug msg="hcsshim::PrepareLayer - succeeded" path="C:\\ProgramData\\docker\\windowsfilter\\a82013c6bc13c66af5bb7cc949cac2b9f339a79f0ad0d003331308c804f25e3d"
time="2019-09-16T15:24:44.571451500-07:00" level=debug msg="hcsshim::GetLayerMountPath" path="C:\\ProgramData\\docker\\windowsfilter\\a82013c6bc13c66af5bb7cc949cac2b9f339a79f0ad0d003331308c804f25e3d"
time="2019-09-16T15:24:44.571451500-07:00" level=debug msg="Calling proc (1)" path="C:\\ProgramData\\docker\\windowsfilter\\a82013c6bc13c66af5bb7cc949cac2b9f339a79f0ad0d003331308c804f25e3d"
time="2019-09-16T15:24:44.574435200-07:00" level=debug msg="Calling proc (2)" path="C:\\ProgramData\\docker\\windowsfilter\\a82013c6bc13c66af5bb7cc949cac2b9f339a79f0ad0d003331308c804f25e3d"
time="2019-09-16T15:24:44.577428600-07:00" level=debug msg="hcsshim::GetLayerMountPath - succeeded" mountPath="\\\\?\\Volume{62dfba48-d8ce-11e9-bdd5-e30d2ae5e3f9}" path="C:\\ProgramData\\docker\\windowsfilter\\a82013c6bc13c66af5bb7cc949cac2b9f339a79f0ad0d003331308c804f2
5e3d"
time="2019-09-16T15:24:44.578433100-07:00" level=debug msg="hcsshim::UnprepareLayer" path="C:\\ProgramData\\docker\\windowsfilter\\a82013c6bc13c66af5bb7cc949cac2b9f339a79f0ad0d003331308c804f25e3d"
time="2019-09-16T15:24:44.581440800-07:00" level=debug msg="hcsshim::UnprepareLayer - succeeded" path="C:\\ProgramData\\docker\\windowsfilter\\a82013c6bc13c66af5bb7cc949cac2b9f339a79f0ad0d003331308c804f25e3d"
time="2019-09-16T15:24:44.582433300-07:00" level=debug msg="hcsshim::ExportLayer" exportFolderPath="C:\\ProgramData\\docker\\tmp\\hcs445978809" path="C:\\ProgramData\\docker\\windowsfilter\\a82013c6bc13c66af5bb7cc949cac2b9f339a79f0ad0d003331308c804f25e3d"
time="2019-09-16T15:24:44.583441600-07:00" level=debug msg="hcsshim::NameToGuid" name=587d388ce20d5ddb80b8a7bb3fdee9884797737ce33b5b00db78ec2726270193
time="2019-09-16T15:24:44.585433500-07:00" level=debug msg="hcsshim::NameToGuid - succeeded" guid=d2bcf92e-e6f1-5afc-b50c-c3fbfcc9a367 name=587d388ce20d5ddb80b8a7bb3fdee9884797737ce33b5b00db78ec2726270193
time="2019-09-16T15:24:44.586428400-07:00" level=debug msg="hcsshim::NameToGuid" name=65f611a0bfa46f6fd8b4bbc023523ffec0ac9f1d0e4a4275308f3c2597f8fe94
time="2019-09-16T15:24:44.587427000-07:00" level=debug msg="hcsshim::NameToGuid - succeeded" guid=4d300955-edda-50d3-9fab-70b3607593fe name=65f611a0bfa46f6fd8b4bbc023523ffec0ac9f1d0e4a4275308f3c2597f8fe94
time="2019-09-16T15:24:44.584433800-07:00" level=debug msg="hcsshim::GetLayerMountPath" path="C:\\ProgramData\\docker\\windowsfilter\\587d388ce20d5ddb80b8a7bb3fdee9884797737ce33b5b00db78ec2726270193"
time="2019-09-16T15:24:44.589435800-07:00" level=debug msg="Calling proc (1)" path="C:\\ProgramData\\docker\\windowsfilter\\587d388ce20d5ddb80b8a7bb3fdee9884797737ce33b5b00db78ec2726270193"
time="2019-09-16T15:24:44.588708600-07:00" level=debug msg="hcsshim::NameToGuid" name=6e06c85f7fd717a1b6a8c9664c1c422c03a65a079624b0136f77465c00325654
time="2019-09-16T15:24:44.590437200-07:00" level=debug msg="Calling proc (2)" path="C:\\ProgramData\\docker\\windowsfilter\\587d388ce20d5ddb80b8a7bb3fdee9884797737ce33b5b00db78ec2726270193"
time="2019-09-16T15:24:44.590437200-07:00" level=debug msg="hcsshim::NameToGuid - succeeded" guid=1bb144a6-293b-5d89-a479-95d37976ecb9 name=6e06c85f7fd717a1b6a8c9664c1c422c03a65a079624b0136f77465c00325654
time="2019-09-16T15:24:44.592450100-07:00" level=debug msg="hcsshim::NameToGuid" name=a35c063592d63f30c6a7dc361d6b24991123e180c07c3d8f646809a2fae2ba05
time="2019-09-16T15:24:44.591446200-07:00" level=debug msg="hcsshim::GetLayerMountPath - succeeded" mountPath="C:\\ProgramData\\docker\\windowsfilter\\587d388ce20d5ddb80b8a7bb3fdee9884797737ce33b5b00db78ec2726270193" path="C:\\ProgramData\\docker\\windowsfilter\\587d388
ce20d5ddb80b8a7bb3fdee9884797737ce33b5b00db78ec2726270193"
time="2019-09-16T15:24:44.592450100-07:00" level=debug msg="hcsshim::NameToGuid - succeeded" guid=7c936f90-3131-5f18-ad64-69ffca88a11c name=a35c063592d63f30c6a7dc361d6b24991123e180c07c3d8f646809a2fae2ba05
time="2019-09-16T15:24:44.594446000-07:00" level=debug msg="hcsshim::NameToGuid" name=522119ca0c1d5ec876732c63b752ff7a5f3bf7f73f2ad859e2934d7c0ceccb76
time="2019-09-16T15:24:44.593442800-07:00" level=debug msg="hcsshim::CreateLayer" parent=587d388ce20d5ddb80b8a7bb3fdee9884797737ce33b5b00db78ec2726270193 path="C:\\ProgramData\\docker\\windowsfilter\\3ea30338a6f25452c103ec983049f4e3abd64e219dfa5a85e91a92eb5f300583"
time="2019-09-16T15:24:44.594446000-07:00" level=debug msg="hcsshim::NameToGuid - succeeded" guid=f0990ba7-98d1-58ac-9898-58ba8a8e228c name=522119ca0c1d5ec876732c63b752ff7a5f3bf7f73f2ad859e2934d7c0ceccb76
time="2019-09-16T15:24:44.596435400-07:00" level=debug msg="hcsshim::NameToGuid" name=f0141935f0501d855ac26c573a443b5c3f1247ab3b567d1aba955e2f693eb933
time="2019-09-16T15:24:44.595435900-07:00" level=debug msg="hcsshim::CreateLayer - succeeded" parent=587d388ce20d5ddb80b8a7bb3fdee9884797737ce33b5b00db78ec2726270193 path="C:\\ProgramData\\docker\\windowsfilter\\3ea30338a6f25452c103ec983049f4e3abd64e219dfa5a85e91a92eb5f
300583"
time="2019-09-16T15:24:44.596435400-07:00" level=debug msg="hcsshim::NameToGuid - succeeded" guid=e5e54c1a-e4b1-5e27-aaf3-0908e255e124 name=f0141935f0501d855ac26c573a443b5c3f1247ab3b567d1aba955e2f693eb933
time="2019-09-16T15:24:44.598433500-07:00" level=debug msg="hcsshim::NameToGuid" name=3ff0e976381974986917b24702945d256792418a306c75efc9676f520d2d4c1a
time="2019-09-16T15:24:44.599433400-07:00" level=debug msg="hcsshim::NameToGuid - succeeded" guid=e0716d0b-eac4-57de-b20a-577ab7950b9e name=3ff0e976381974986917b24702945d256792418a306c75efc9676f520d2d4c1a
time="2019-09-16T15:24:44.599433400-07:00" level=debug msg="hcsshim::NameToGuid" name=917c3115bec50e148192c381f45442cbf414b4f1c02abe34f176793a0f8e3293
time="2019-09-16T15:24:44.599433400-07:00" level=debug msg="hcsshim::GetLayerMountPath" path="C:\\ProgramData\\docker\\windowsfilter\\587d388ce20d5ddb80b8a7bb3fdee9884797737ce33b5b00db78ec2726270193"
time="2019-09-16T15:24:44.601432200-07:00" level=debug msg="Calling proc (1)" path="C:\\ProgramData\\docker\\windowsfilter\\587d388ce20d5ddb80b8a7bb3fdee9884797737ce33b5b00db78ec2726270193"
time="2019-09-16T15:24:44.600434900-07:00" level=debug msg="hcsshim::NameToGuid - succeeded" guid=db22d86f-df3c-5a60-9616-c9a57c798281 name=917c3115bec50e148192c381f45442cbf414b4f1c02abe34f176793a0f8e3293
time="2019-09-16T15:24:44.602433400-07:00" level=debug msg="hcsshim::NameToGuid" name=e357ee86499cd2e21c6d39ba2c5bd599f0ddfee2fb3ac6a0e48835ff54679421
time="2019-09-16T15:24:44.601432200-07:00" level=debug msg="Calling proc (2)" path="C:\\ProgramData\\docker\\windowsfilter\\587d388ce20d5ddb80b8a7bb3fdee9884797737ce33b5b00db78ec2726270193"
time="2019-09-16T15:24:44.602433400-07:00" level=debug msg="hcsshim::NameToGuid - succeeded" guid=87e54c4d-5fc7-5f08-b6fd-7ba18d88c689 name=e357ee86499cd2e21c6d39ba2c5bd599f0ddfee2fb3ac6a0e48835ff54679421
time="2019-09-16T15:24:44.603434300-07:00" level=debug msg="hcsshim::GetLayerMountPath - succeeded" mountPath="C:\\ProgramData\\docker\\windowsfilter\\587d388ce20d5ddb80b8a7bb3fdee9884797737ce33b5b00db78ec2726270193" path="C:\\ProgramData\\docker\\windowsfilter\\587d388
ce20d5ddb80b8a7bb3fdee9884797737ce33b5b00db78ec2726270193"
time="2019-09-16T15:25:44.733683300-07:00" level=debug msg="hcsshim::ExportLayer - succeeded" exportFolderPath="C:\\ProgramData\\docker\\tmp\\hcs445978809" path="C:\\ProgramData\\docker\\windowsfilter\\a82013c6bc13c66af5bb7cc949cac2b9f339a79f0ad0d003331308c804f25e3d"

at this stage, the dockerd is still stuck at deleting stuff

goroutine 52 [running]:
github.com/docker/docker/pkg/signal.DumpStacks(0xc0001ba300, 0x15, 0x0, 0x0, 0x0, 0x0)
        C:/go/src/github.com/docker/docker/pkg/signal/trap.go:83 +0x9c
github.com/docker/docker/daemon.(*Daemon).setupDumpStackTrap.func1(0xc0001ba9c0, 0x14, 0x354, 0xc0001ba300, 0x15)
        C:/go/src/github.com/docker/docker/daemon/debugtrap_windows.go:38 +0xe3
created by github.com/docker/docker/daemon.(*Daemon).setupDumpStackTrap
        C:/go/src/github.com/docker/docker/daemon/debugtrap_windows.go:34 +0x2f2

goroutine 1 [chan receive, 7 minutes]:
main.(*DaemonCli).start(0xc0005e2ff0, 0xc0000cc660, 0x0, 0x0)
        C:/go/src/github.com/docker/docker/cmd/dockerd/daemon.go:259 +0xb95
main.runDaemon(0xc0000cc660, 0xc000192100, 0x0)
        C:/go/src/github.com/docker/docker/cmd/dockerd/docker_windows.go:37 +0x131
main.newDaemonCommand.func1(0xc000190000, 0x3915578, 0x0, 0x0, 0x0, 0x0)
        C:/go/src/github.com/docker/docker/cmd/dockerd/docker.go:34 +0x5d
github.com/docker/docker/vendor/github.com/spf13/cobra.(*Command).execute(0xc000190000, 0xc0000781c0, 0x0, 0x0, 0xc000190000, 0xc0000781c0)
        C:/go/src/github.com/docker/docker/vendor/github.com/spf13/cobra/command.go:762 +0x46c
github.com/docker/docker/vendor/github.com/spf13/cobra.(*Command).ExecuteC(0xc000190000, 0x0, 0x0, 0xc0000ba010)
        C:/go/src/github.com/docker/docker/vendor/github.com/spf13/cobra/command.go:852 +0x2f3
github.com/docker/docker/vendor/github.com/spf13/cobra.(*Command).Execute(...)
        C:/go/src/github.com/docker/docker/vendor/github.com/spf13/cobra/command.go:800
main.main()
        C:/go/src/github.com/docker/docker/cmd/dockerd/docker.go:97 +0x19e

goroutine 26 [syscall, 7 minutes]:
os/signal.signal_recv(0x4656d6)
        C:/.GOROOT/src/runtime/sigqueue.go:139 +0xa3
os/signal.loop()
        C:/.GOROOT/src/os/signal/signal_unix.go:23 +0x29
created by os/signal.init.0
        C:/.GOROOT/src/os/signal/signal_unix.go:29 +0x48

goroutine 51 [runnable, locked to thread]:
syscall.Syscall(0x7ffc38de26c0, 0x1, 0xc001ba6f00, 0x0, 0x0, 0x0, 0x0, 0x0)
        C:/.GOROOT/src/runtime/syscall_windows.go:184 +0xea
syscall.RemoveDirectory(0xc001ba6f00, 0x254b340, 0xc000d22540)
        C:/.GOROOT/src/syscall/zsyscall_windows.go:465 +0x6b
os.Remove(0xc001b15300, 0x78, 0x78, 0xc000ff5a28)
        C:/.GOROOT/src/os/file_windows.go:276 +0x19c
os.removeAll(0xc001b15300, 0x78, 0xc001b15300, 0x78)
        C:/.GOROOT/src/os/removeall_noat.go:29 +0x196
os.RemoveAll(0xc001b15300, 0x78, 0x4a, 0x217be32)
        C:/.GOROOT/src/os/path.go:67 +0x3c
os.removeAll(0xc00003fef0, 0x4a, 0xc00003fef0, 0x4a)
        C:/.GOROOT/src/os/removeall_noat.go:70 +0x5f3
os.RemoveAll(0xc00003fef0, 0x4a, 0x3d, 0x217be32)
        C:/.GOROOT/src/os/path.go:67 +0x3c
os.removeAll(0xc00078d680, 0x3d, 0xc00078d680, 0x3d)
        C:/.GOROOT/src/os/removeall_noat.go:70 +0x5f3
os.RemoveAll(0xc00078d680, 0x3d, 0x30, 0x217be32)
        C:/.GOROOT/src/os/path.go:67 +0x3c
os.removeAll(0xc0007150b0, 0x30, 0xc0007150b0, 0x30)
        C:/.GOROOT/src/os/removeall_noat.go:70 +0x5f3
os.RemoveAll(0xc0007150b0, 0x30, 0x2a, 0x217be32)
        C:/.GOROOT/src/os/path.go:67 +0x3c
os.removeAll(0xc000714f90, 0x2a, 0xc000714f90, 0x2a)
        C:/.GOROOT/src/os/removeall_noat.go:70 +0x5f3
os.RemoveAll(0xc000714f90, 0x2a, 0x1d, 0x217be32)
        C:/.GOROOT/src/os/path.go:67 +0x3c
os.removeAll(0xc0001ba680, 0x1d, 0x1, 0x5)
        C:/.GOROOT/src/os/removeall_noat.go:70 +0x5f3
os.RemoveAll(0xc0001ba680, 0x1d, 0x0, 0x221eb3f)
        C:/.GOROOT/src/os/path.go:67 +0x3c
github.com/docker/docker/daemon.prepareTempDir.func1(0xc0001ba680, 0x1d)
        C:/go/src/github.com/docker/docker/daemon/daemon.go:1324 +0x40
created by github.com/docker/docker/daemon.prepareTempDir
        C:/go/src/github.com/docker/docker/daemon/daemon.go:1323 +0x3c4

goroutine 44 [select]:
github.com/docker/docker/vendor/go.opencensus.io/stats/view.(*worker).start(0xc0007f0cc0)
        C:/go/src/github.com/docker/docker/vendor/go.opencensus.io/stats/view/worker.go:144 +0xe4
created by github.com/docker/docker/vendor/go.opencensus.io/stats/view.init.0
        C:/go/src/github.com/docker/docker/vendor/go.opencensus.io/stats/view/worker.go:29 +0x5e

goroutine 50 [chan receive, 7 minutes]:
github.com/docker/docker/pkg/signal.Trap.func1(0xc0000ccc00, 0x25464a0, 0xc0000cc000, 0xc000800640)
        C:/go/src/github.com/docker/docker/pkg/signal/trap.go:38 +0x62
created by github.com/docker/docker/pkg/signal.Trap
        C:/go/src/github.com/docker/docker/pkg/signal/trap.go:36 +0x125

goroutine 14 [sleep]:
runtime.goparkunlock(...)
        C:/.GOROOT/src/runtime/proc.go:307
time.Sleep(0x3b9aca00)
        C:/.GOROOT/src/runtime/time.go:105 +0x16e
github.com/docker/docker/daemon/stats.(*Collector).Run(0xc0000433c0)
        C:/go/src/github.com/docker/docker/daemon/stats/collector.go:96 +0x193
created by github.com/docker/docker/daemon.(*Daemon).newStatsCollector
        C:/go/src/github.com/docker/docker/daemon/stats_collector.go:24 +0x18b

goroutine 15 [chan receive, 2 minutes]:
github.com/docker/docker/daemon.(*Daemon).execCommandGC(0xc000194200)
        C:/go/src/github.com/docker/docker/daemon/exec.go:305 +0x151
created by github.com/docker/docker/daemon.NewDaemon
        C:/go/src/github.com/docker/docker/daemon/daemon.go:1073 +0x29b9

goroutine 198 [select, 1 minutes]:
io.(*pipe).Read(0xc00084ec80, 0xc001c0c000, 0x100000, 0x100000, 0x0, 0x0, 0x0)
        C:/.GOROOT/src/io/pipe.go:50 +0xee
io.(*PipeReader).Read(0xc000134108, 0xc001c0c000, 0x100000, 0x100000, 0x0, 0x0, 0x6ca82c0)
        C:/.GOROOT/src/io/pipe.go:127 +0x53
io.(*teeReader).Read(0xc000c9c440, 0xc001c0c000, 0x100000, 0x100000, 0xc000bcdcf8, 0x41304f, 0x100000)
        C:/.GOROOT/src/io/io.go:535 +0x5c
io.(*teeReader).Read(0xc000c9c540, 0xc001c0c000, 0x100000, 0x100000, 0x0, 0x0, 0x0)
        C:/.GOROOT/src/io/io.go:535 +0x5c
github.com/docker/docker/vendor/github.com/vbatts/tar-split/tar/asm.NewInputTarStream.func1(0x2547060, 0xc000c9c540, 0xc0001341c8, 0x25466a0, 0xc001226120, 0x2546680, 0x3915578)
        C:/go/src/github.com/docker/docker/vendor/github.com/vbatts/tar-split/tar/asm/disassemble.go:130 +0x5d2
created by github.com/docker/docker/vendor/github.com/vbatts/tar-split/tar/asm.NewInputTarStream
        C:/go/src/github.com/docker/docker/vendor/github.com/vbatts/tar-split/tar/asm/disassemble.go:45 +0x206

goroutine 76 [IO wait, 7 minutes]:
internal/poll.runtime_pollWait(0x6c9f220, 0x72, 0x254b340)
        C:/.GOROOT/src/runtime/netpoll.go:182 +0x5d
internal/poll.(*pollDesc).wait(0xc0005e81c8, 0x72, 0x386be00, 0x0, 0x0)
        C:/.GOROOT/src/internal/poll/fd_poll_runtime.go:87 +0xa2
internal/poll.(*ioSrv).ExecIO(0x38e6c00, 0xc0005e8018, 0xc0005f2100, 0x1, 0x0, 0x458)
        C:/.GOROOT/src/internal/poll/fd_windows.go:228 +0x124
internal/poll.(*FD).acceptOne(0xc0005e8000, 0x458, 0xc000a08000, 0x2, 0x2, 0xc0005e8018, 0xc000b72000, 0xc000b4dd10, 0x41304f, 0x10)
        C:/.GOROOT/src/internal/poll/fd_windows.go:864 +0xa9
internal/poll.(*FD).Accept(0xc0005e8000, 0xc000078750, 0x0, 0x0, 0x0, 0x0, 0xc000000000, 0x0, 0x0, 0x0, ...)
        C:/.GOROOT/src/internal/poll/fd_windows.go:898 +0x148
net.(*netFD).accept(0xc0005e8000, 0xc0007c6120, 0x79a4fc8, 0x1a52601)
        C:/.GOROOT/src/net/fd_windows.go:193 +0x81
net.(*TCPListener).accept(0xc000134180, 0x435f46, 0xc0000ca0d0, 0xc000b4ded8)
        C:/.GOROOT/src/net/tcpsock_posix.go:139 +0x39
net.(*TCPListener).Accept(0xc000134180, 0x258cb88, 0xc000134180, 0x60, 0xc000b4df18)
        C:/.GOROOT/src/net/tcpsock.go:260 +0x4f
github.com/docker/docker/vendor/github.com/miekg/dns.(*Server).serveTCP(0xc000dfa4e0, 0x258cb60, 0xc000134180, 0x0, 0x0)
        C:/go/src/github.com/docker/docker/vendor/github.com/miekg/dns/server.go:514 +0x87
github.com/docker/docker/vendor/github.com/miekg/dns.(*Server).ActivateAndServe(0xc000dfa4e0, 0x0, 0x0)
        C:/go/src/github.com/docker/docker/vendor/github.com/miekg/dns/server.go:469 +0x267
github.com/docker/docker/vendor/github.com/docker/libnetwork.(*resolver).Start.func3(0xc000dfa4e0)
        C:/go/src/github.com/docker/docker/vendor/github.com/docker/libnetwork/resolver.go:166 +0x32
created by github.com/docker/docker/vendor/github.com/docker/libnetwork.(*resolver).Start
        C:/go/src/github.com/docker/docker/vendor/github.com/docker/libnetwork/resolver.go:165 +0x179

goroutine 146 [chan receive, 7 minutes]:
github.com/docker/docker/vendor/github.com/moby/buildkit/solver.(*scheduler).loop.func2(0xc000f8e0e0)
        C:/go/src/github.com/docker/docker/vendor/github.com/moby/buildkit/solver/scheduler.go:76 +0x3f
created by github.com/docker/docker/vendor/github.com/moby/buildkit/solver.(*scheduler).loop
        C:/go/src/github.com/docker/docker/vendor/github.com/moby/buildkit/solver/scheduler.go:75 +0x74

goroutine 75 [IO wait]:
internal/poll.runtime_pollWait(0x6c9f2f0, 0x72, 0x254b340)
        C:/.GOROOT/src/runtime/netpoll.go:182 +0x5d
internal/poll.(*pollDesc).wait(0xc0001017c8, 0x72, 0x386be00, 0x0, 0x0)
        C:/.GOROOT/src/internal/poll/fd_poll_runtime.go:87 +0xa2
internal/poll.(*ioSrv).ExecIO(0x38e6c00, 0xc000101618, 0x222d538, 0x6c9b450, 0xc00044e000, 0xc000b49bc8)
        C:/.GOROOT/src/internal/poll/fd_windows.go:228 +0x124
internal/poll.(*FD).ReadFrom(0xc000101600, 0xc000644400, 0x200, 0x200, 0x0, 0x0, 0x0, 0x0, 0x0)
        C:/.GOROOT/src/internal/poll/fd_windows.go:642 +0x120
net.(*netFD).readFrom(0xc000101600, 0xc000644400, 0x200, 0x200, 0x1774038f5b20, 0x2000, 0x1, 0x79a3f08, 0x38f5b20)
        C:/.GOROOT/src/net/fd_windows.go:158 +0x62
net.(*UDPConn).readFrom(0xc000134170, 0xc000644400, 0x200, 0x200, 0xc000644400, 0x200, 0xc000644400, 0x79a3f08)
        C:/.GOROOT/src/net/udpsock_posix.go:47 +0x71
net.(*UDPConn).ReadFrom(0xc000134170, 0xc000644400, 0x200, 0x200, 0x5857ed, 0xc000101600, 0xbf5820f3a37b6c40, 0x6694fa9c69, 0xc000b49dc0)
        C:/.GOROOT/src/net/udpsock.go:121 +0x65
github.com/docker/docker/vendor/github.com/miekg/dns.ReadFromSessionUDP(0xc000134170, 0xc000644400, 0x200, 0x200, 0x0, 0x0, 0x38f14e0, 0xc000b49e38)
        C:/go/src/github.com/docker/docker/vendor/github.com/miekg/dns/udp_windows.go:19 +0x60
github.com/docker/docker/vendor/github.com/miekg/dns.(*Server).readUDP(0xc000dfa410, 0xc000134170, 0x77359400, 0x3914b00, 0x2546f01, 0x3914b00, 0x6ca7ad8, 0x3914b00, 0x6ca7a01)
        C:/go/src/github.com/docker/docker/vendor/github.com/miekg/dns/server.go:695 +0xc2
github.com/docker/docker/vendor/github.com/miekg/dns.(*defaultReader).ReadUDP(0xc000924000, 0xc000134170, 0x77359400, 0x6ca7aa8, 0xc00084e5a0, 0x1, 0x0, 0x2547180, 0xc00084e5a0)
        C:/go/src/github.com/docker/docker/vendor/github.com/miekg/dns/server.go:261 +0x4d
github.com/docker/docker/vendor/github.com/miekg/dns.(*Server).serveUDP(0xc000dfa410, 0xc000134170, 0x0, 0x0)
        C:/go/src/github.com/docker/docker/vendor/github.com/miekg/dns/server.go:547 +0x119
github.com/docker/docker/vendor/github.com/miekg/dns.(*Server).ActivateAndServe(0xc000dfa410, 0x0, 0x0)
        C:/go/src/github.com/docker/docker/vendor/github.com/miekg/dns/server.go:461 +0x2ec
github.com/docker/docker/vendor/github.com/docker/libnetwork.(*resolver).Start.func2(0xc000dfa410)
        C:/go/src/github.com/docker/docker/vendor/github.com/docker/libnetwork/resolver.go:160 +0x32
created by github.com/docker/docker/vendor/github.com/docker/libnetwork.(*resolver).Start
        C:/go/src/github.com/docker/docker/vendor/github.com/docker/libnetwork/resolver.go:159 +0x10a

goroutine 54 [select, 2 minutes]:
github.com/docker/docker/vendor/github.com/docker/libnetwork.(*controller).watchLoop(0xc00011e300)
        C:/go/src/github.com/docker/docker/vendor/github.com/docker/libnetwork/store.go:452 +0xcd
created by github.com/docker/docker/vendor/github.com/docker/libnetwork.(*controller).startWatch
        C:/go/src/github.com/docker/docker/vendor/github.com/docker/libnetwork/store.go:469 +0xd4

goroutine 121 [select, 7 minutes]:
github.com/docker/docker/daemon.(*Daemon).ProcessClusterNotifications(0xc000194200, 0x259c7e0, 0xc00012cbc0, 0xc0000ccae0)
        C:/go/src/github.com/docker/docker/daemon/events.go:126 +0xec
created by main.(*DaemonCli).start
        C:/go/src/github.com/docker/docker/cmd/dockerd/daemon.go:244 +0xb06

goroutine 119 [sync.Cond.Wait, 7 minutes]:
runtime.goparkunlock(...)
        C:/.GOROOT/src/runtime/proc.go:307
sync.runtime_notifyListWait(0xc000cc0290, 0x0)
        C:/.GOROOT/src/runtime/sema.go:510 +0x107
sync.(*Cond).Wait(0xc000cc0280)
        C:/.GOROOT/src/sync/cond.go:56 +0xa5
github.com/docker/docker/vendor/github.com/moby/buildkit/util/cond.(*StatefulCond).Wait(0xc000ace450)
        C:/go/src/github.com/docker/docker/vendor/github.com/moby/buildkit/util/cond/cond.go:28 +0x9f
github.com/docker/docker/vendor/github.com/moby/buildkit/solver.(*scheduler).loop(0xc000f8e0e0)
        C:/go/src/github.com/docker/docker/vendor/github.com/moby/buildkit/solver/scheduler.go:101 +0x16f
created by github.com/docker/docker/vendor/github.com/moby/buildkit/solver.newScheduler
        C:/go/src/github.com/docker/docker/vendor/github.com/moby/buildkit/solver/scheduler.go:35 +0x1b4

goroutine 125 [select]:
io.(*pipe).Read(0xc0000ca910, 0xc000a32000, 0x2000, 0x2000, 0x0, 0xc000646a80, 0xc000646aa8)
        C:/.GOROOT/src/io/pipe.go:50 +0xee
io.(*PipeReader).Read(0xc000134148, 0xc000a32000, 0x2000, 0x2000, 0x9, 0x40f403, 0xc000b28000)
        C:/.GOROOT/src/io/pipe.go:127 +0x53
io/ioutil.devNull.ReadFrom(0x0, 0x2546fc0, 0xc000134148, 0x1e9db80, 0x1, 0x79aada8)
        C:/.GOROOT/src/io/ioutil/ioutil.go:147 +0x99
io.copyBuffer(0x254ad00, 0x3915448, 0x2546fc0, 0xc000134148, 0x0, 0x0, 0x0, 0x16bfd381, 0x0, 0x0)
        C:/.GOROOT/src/io/io.go:388 +0x303
io.Copy(...)
        C:/.GOROOT/src/io/io.go:364
github.com/docker/docker/layer.(*layerStore).applyTar(0xc000868240, 0xc000cbf0c0, 0x79aad28, 0xc000b712c0, 0xc000c12400, 0x40, 0xc0006c6000, 0x0, 0x0)
        C:/go/src/github.com/docker/docker/layer/layer_store.go:267 +0x24a
github.com/docker/docker/layer.(*layerStore).registerWithDescriptor(0xc000868240, 0x79aad28, 0xc000b712c0, 0xc000cf6be0, 0x47, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
        C:/go/src/github.com/docker/docker/layer/layer_store.go:343 +0x2a1
github.com/docker/docker/layer.(*layerStore).Register(0xc000868240, 0x79aad28, 0xc000b712c0, 0xc000cf6be0, 0x47, 0x0, 0x2571360, 0xc000b712c0, 0x0)
        C:/go/src/github.com/docker/docker/layer/layer_store.go:281 +0x9a
github.com/docker/docker/daemon/images.(*ImageService).CommitImage(0xc000196dc0, 0x0, 0x0, 0x0, 0x0, 0xc000d53040, 0xc0000903c0, 0xc000c36c40, 0x40, 0x0, ...)
        C:/go/src/github.com/docker/docker/daemon/images/image_commit.go:42 +0x271
github.com/docker/docker/daemon/images.(*ImageService).CommitBuildStep(0xc000196dc0, 0x0, 0x0, 0x0, 0x0, 0xc000d53040, 0xc0000903c0, 0xc000c36c40, 0x40, 0x0, ...)
        C:/go/src/github.com/docker/docker/daemon/images/image_commit.go:126 +0x102
github.com/docker/docker/builder/dockerfile.(*Builder).commitContainer(0xc000159a20, 0xc000657f10, 0xc000c36c40, 0x40, 0xc0000903c0, 0x2544840, 0xc0000048c0)
        C:/go/src/github.com/docker/docker/builder/dockerfile/internals.go:109 +0x129
github.com/docker/docker/builder/dockerfile.dispatchRun(0xc000657f10, 0xc000c4dc70, 0xc000159a20, 0x257e960, 0xc000a1cc30, 0xc0005f2e80, 0xc000929310, 0xc0005f2e80, 0xc000c0cd58)
        C:/go/src/github.com/docker/docker/builder/dockerfile/dispatchers.go:400 +0xa17
github.com/docker/docker/builder/dockerfile.dispatch(0xc000657f10, 0xc000c4dc70, 0xc000159a20, 0x257e960, 0xc000a1cc30, 0xc0005f2e80, 0x2545f20, 0xc000929310, 0x0, 0x0)
        C:/go/src/github.com/docker/docker/builder/dockerfile/evaluator.go:83 +0x3f2
github.com/docker/docker/builder/dockerfile.(*Builder).dispatchDockerfileWithCancellation(0xc000159a20, 0xc000ddeba0, 0x1, 0x1, 0x0, 0x0, 0x0, 0x5c, 0x257e960, 0xc000a1cc30, ...)
        C:/go/src/github.com/docker/docker/builder/dockerfile/builder.go:347 +0x523
github.com/docker/docker/builder/dockerfile.(*Builder).build(0xc000159a20, 0x257e960, 0xc000a1cc30, 0xc000a1dfb0, 0x0, 0x0, 0x0)
        C:/go/src/github.com/docker/docker/builder/dockerfile/builder.go:265 +0x31c
github.com/docker/docker/builder/dockerfile.(*BuildManager).Build(0xc000043840, 0x259c7e0, 0xc0000439c0, 0x2570d60, 0xc000a1c900, 0x2543fe0, 0xc0000048a0, 0x2544840, 0xc0000048c0, 0x2544840, ...)
        C:/go/src/github.com/docker/docker/builder/dockerfile/builder.go:120 +0x38d
github.com/docker/docker/api/server/backend/build.(*Backend).Build(0xc000ace4b0, 0x259c8a0, 0xc000a1c870, 0x2570d60, 0xc000a1c900, 0x2543fe0, 0xc0000048a0, 0x2544840, 0xc0000048c0, 0x2544840, ...)
        C:/go/src/github.com/docker/docker/api/server/backend/build/backend.go:68 +0x524
github.com/docker/docker/api/server/router/build.(*buildRouter).postBuild(0xc000cc0400, 0x259c8a0, 0xc000a1c870, 0x258cde0, 0xc0007d4000, 0xc00079a600, 0xc000a1c4b0, 0x0, 0x0)
        C:/go/src/github.com/docker/docker/api/server/router/build/build_routes.go:281 +0x736
github.com/docker/docker/api/server/middleware.ExperimentalMiddleware.WrapHandler.func1(0x259c8a0, 0xc000a1c870, 0x258cde0, 0xc0007d4000, 0xc00079a600, 0xc000a1c4b0, 0x259c8a0, 0xc000a1c870)
        C:/go/src/github.com/docker/docker/api/server/middleware/experimental.go:26 +0x180
github.com/docker/docker/api/server/middleware.VersionMiddleware.WrapHandler.func1(0x259c8a0, 0xc000a1c660, 0x258cde0, 0xc0007d4000, 0xc00079a600, 0xc000a1c4b0, 0xc000b28000, 0x1e83e40)
        C:/go/src/github.com/docker/docker/api/server/middleware/version.go:62 +0x612
github.com/docker/docker/pkg/authorization.(*Middleware).WrapHandler.func1(0x259c8a0, 0xc000a1c660, 0x258cde0, 0xc0007d4000, 0xc00079a600, 0xc000a1c4b0, 0x2, 0x1ede201)
        C:/go/src/github.com/docker/docker/pkg/authorization/middleware.go:59 +0x834
github.com/docker/docker/api/server/middleware.DebugRequestMiddleware.func1(0x259c8a0, 0xc000a1c660, 0x258cde0, 0xc0007d4000, 0xc00079a600, 0xc000a1c4b0, 0x259c8a0, 0xc000a1c660)
        C:/go/src/github.com/docker/docker/api/server/middleware/debug.go:25 +0x8c0
github.com/docker/docker/api/server.(*Server).makeHTTPHandler.func1(0x258cde0, 0xc0007d4000, 0xc00079a500)
        C:/go/src/github.com/docker/docker/api/server/server.go:142 +0x22a
net/http.HandlerFunc.ServeHTTP(0xc000b999c0, 0x258cde0, 0xc0007d4000, 0xc00079a500)
        C:/.GOROOT/src/net/http/server.go:1995 +0x4b
github.com/docker/docker/vendor/github.com/gorilla/mux.(*Router).ServeHTTP(0xc0007d8180, 0x258cde0, 0xc0007d4000, 0xc00079a800)
        C:/go/src/github.com/docker/docker/vendor/github.com/gorilla/mux/mux.go:212 +0xea
github.com/docker/docker/api/server.(*routerSwapper).ServeHTTP(0xc000dbdb80, 0x258cde0, 0xc0007d4000, 0xc00079a800)
        C:/go/src/github.com/docker/docker/api/server/router_swapper.go:29 +0x77
net/http.serverHandler.ServeHTTP(0xc0000a9040, 0x258cde0, 0xc0007d4000, 0xc00079a800)
        C:/.GOROOT/src/net/http/server.go:2774 +0xaf
net/http.(*conn).serve(0xc0007a2000, 0x259c7e0, 0xc000042180)
        C:/.GOROOT/src/net/http/server.go:1878 +0x858
created by net/http.(*Server).Serve
        C:/.GOROOT/src/net/http/server.go:2884 +0x2fb

goroutine 124 [IO wait, 5 minutes]:
internal/poll.runtime_pollWait(0x6c9f3c0, 0x72, 0x254b340)
        C:/.GOROOT/src/runtime/netpoll.go:182 +0x5d
internal/poll.(*pollDesc).wait(0xc00080e1c8, 0x72, 0x386be00, 0x0, 0x0)
        C:/.GOROOT/src/internal/poll/fd_poll_runtime.go:87 +0xa2
internal/poll.(*ioSrv).ExecIO(0x38e6c00, 0xc00080e018, 0xc000004080, 0x1, 0x0, 0x570)
        C:/.GOROOT/src/internal/poll/fd_windows.go:228 +0x124
internal/poll.(*FD).acceptOne(0xc00080e000, 0x570, 0xc000e2e000, 0x2, 0x2, 0xc00080e018, 0x466ed0, 0xc000b63ca0, 0x41304f, 0x10)
        C:/.GOROOT/src/internal/poll/fd_windows.go:864 +0xa9
internal/poll.(*FD).Accept(0xc00080e000, 0xc000854040, 0x0, 0x0, 0x0, 0x0, 0xc000000000, 0x0, 0x0, 0x0, ...)
        C:/.GOROOT/src/internal/poll/fd_windows.go:898 +0x148
net.(*netFD).accept(0xc00080e000, 0x222e0b8, 0xc000b63e28, 0x1f8a7e0)
        C:/.GOROOT/src/net/fd_windows.go:193 +0x81
net.(*TCPListener).accept(0xc0000062d8, 0x776149, 0xc0000a90d0, 0x4e4a9d)
        C:/.GOROOT/src/net/tcpsock_posix.go:139 +0x39
net.(*TCPListener).Accept(0xc0000062d8, 0xc000b63ea0, 0x18, 0xc000453c80, 0x77577b)
        C:/.GOROOT/src/net/tcpsock.go:260 +0x4f
net/http.(*Server).Serve(0xc0000a9040, 0x258cb60, 0xc0000062d8, 0x0, 0x0)
        C:/.GOROOT/src/net/http/server.go:2859 +0x234
github.com/docker/docker/api/server.(*HTTPServer).Serve(...)
        C:/go/src/github.com/docker/docker/api/server/server.go:113
github.com/docker/docker/api/server.(*Server).serveAPI.func1(0xc000976360, 0xc000800620)
        C:/go/src/github.com/docker/docker/api/server/server.go:87 +0xd9
created by github.com/docker/docker/api/server.(*Server).serveAPI
        C:/go/src/github.com/docker/docker/api/server/server.go:84 +0x8d

goroutine 123 [chan receive, 7 minutes]:
github.com/docker/docker/api/server.(*Server).serveAPI(0xc0000ccba0, 0x610000004d, 0xc000928380)
        C:/go/src/github.com/docker/docker/api/server/server.go:95 +0x135
github.com/docker/docker/api/server.(*Server).Wait(0xc0000ccba0, 0xc0000ac8a0)
        C:/go/src/github.com/docker/docker/api/server/server.go:205 +0x36
created by main.(*DaemonCli).start
        C:/go/src/github.com/docker/docker/cmd/dockerd/daemon.go:252 +0xb6b

goroutine 122 [syscall, 7 minutes, locked to thread]:
syscall.Syscall(0x7ffc38de2270, 0x2, 0x474, 0xffffffff, 0x0, 0x0, 0x0, 0x0)
        C:/.GOROOT/src/runtime/syscall_windows.go:184 +0xea
github.com/docker/docker/vendor/golang.org/x/sys/windows.WaitForSingleObject(0x474, 0xffffffff, 0x21c32ca, 0x24, 0xc000bc5fa8)
        C:/go/src/github.com/docker/docker/vendor/golang.org/x/sys/windows/zsyscall_windows.go:1097 +0x6b
main.(*DaemonCli).setupConfigReloadTrap.func1(0xc0005e2ff0)
        C:/go/src/github.com/docker/docker/cmd/dockerd/daemon_windows.go:72 +0x1d2
created by main.(*DaemonCli).setupConfigReloadTrap
        C:/go/src/github.com/docker/docker/cmd/dockerd/daemon_windows.go:63 +0x46

goroutine 148 [IO wait, 5 minutes]:
internal/poll.runtime_pollWait(0x6c9f150, 0x72, 0x254b340)
        C:/.GOROOT/src/runtime/netpoll.go:182 +0x5d
internal/poll.(*pollDesc).wait(0xc0005e8cc8, 0x72, 0x386be00, 0x0, 0x0)
        C:/.GOROOT/src/internal/poll/fd_poll_runtime.go:87 +0xa2
internal/poll.(*ioSrv).ExecIO(0x38e6c00, 0xc0005e8b18, 0x222d530, 0x1e8dc40, 0x1bedb79, 0x1bedb76)
        C:/.GOROOT/src/internal/poll/fd_windows.go:228 +0x124
internal/poll.(*FD).Read(0xc0005e8b00, 0xc00100c0a1, 0x1, 0x1, 0x0, 0x0, 0x0)
        C:/.GOROOT/src/internal/poll/fd_windows.go:502 +0x26b
net.(*netFD).Read(0xc0005e8b00, 0xc00100c0a1, 0x1, 0x1, 0xc000042418, 0xc000bc9f68, 0x46f424)
        C:/.GOROOT/src/net/fd_windows.go:152 +0x56
net.(*conn).Read(0xc000924038, 0xc00100c0a1, 0x1, 0x1, 0x0, 0x0, 0x0)
        C:/.GOROOT/src/net/net.go:177 +0x70
net/http.(*connReader).backgroundRead(0xc00100c090)
        C:/.GOROOT/src/net/http/server.go:677 +0x5f
created by net/http.(*connReader).startBackgroundRead
        C:/.GOROOT/src/net/http/server.go:673 +0xd1

goroutine 142 [chan receive]:
github.com/docker/docker/builder/builder-next/adapters/containerimage.newResolverCache.func1(0xc0007047b0, 0xc0000caa00)
        C:/go/src/github.com/docker/docker/builder/builder-next/adapters/containerimage/pull.go:896 +0x50
created by github.com/docker/docker/builder/builder-next/adapters/containerimage.newResolverCache
        C:/go/src/github.com/docker/docker/builder/builder-next/adapters/containerimage/pull.go:894 +0x9c

goroutine 141 [select, 7 minutes]:
github.com/docker/docker/daemon/telemetry.(*Telemetry).start.func1(0xc000043400)
        C:/go/src/github.com/docker/docker/daemon/telemetry/telemetry.go:60 +0xd7
created by github.com/docker/docker/daemon/telemetry.(*Telemetry).start
        C:/go/src/github.com/docker/docker/daemon/telemetry/telemetry.go:58 +0xa0

goroutine 227 [runnable, locked to thread]:
syscall.Syscall(0x7ffc38de2330, 0x1, 0xc001452000, 0x0, 0x0, 0x0, 0x0, 0x0)
        C:/.GOROOT/src/runtime/syscall_windows.go:184 +0xea
syscall.DeleteFile(0xc001452000, 0x78, 0xc001452000)
        C:/.GOROOT/src/syscall/zsyscall_windows.go:477 +0x6b
os.Remove(0xc0013e6000, 0x78, 0x78, 0xc000bc19c8)
        C:/.GOROOT/src/os/file_windows.go:272 +0x171
os.removeAll(0xc0013e6000, 0x78, 0xc0013e6000, 0x78)
        C:/.GOROOT/src/os/removeall_noat.go:29 +0x196
os.RemoveAll(0xc0013e6000, 0x78, 0x4a, 0x217be32)
        C:/.GOROOT/src/os/path.go:67 +0x3c
os.removeAll(0xc001bfb270, 0x4a, 0xc001bfb270, 0x4a)
        C:/.GOROOT/src/os/removeall_noat.go:70 +0x5f3
os.RemoveAll(0xc001bfb270, 0x4a, 0x3d, 0x217be32)
        C:/.GOROOT/src/os/path.go:67 +0x3c
os.removeAll(0xc0016a5a80, 0x3d, 0xc0016a5a80, 0x3d)
        C:/.GOROOT/src/os/removeall_noat.go:70 +0x5f3
os.RemoveAll(0xc0016a5a80, 0x3d, 0x30, 0x217be32)
        C:/.GOROOT/src/os/path.go:67 +0x3c
os.removeAll(0xc001481290, 0x30, 0xc001481290, 0x30)
        C:/.GOROOT/src/os/removeall_noat.go:70 +0x5f3
os.RemoveAll(0xc001481290, 0x30, 0x2a, 0x217be32)
        C:/.GOROOT/src/os/path.go:67 +0x3c
os.removeAll(0xc000d1c000, 0x2a, 0x131d601, 0x1)
        C:/.GOROOT/src/os/removeall_noat.go:70 +0x5f3
os.RemoveAll(0xc000d1c000, 0x2a, 0x0, 0x0)
        C:/.GOROOT/src/os/path.go:67 +0x3c
github.com/docker/docker/vendor/github.com/Microsoft/hcsshim/internal/wclayer.(*legacyLayerReaderWrapper).Close(0xc0000ba980, 0xc0000ba980, 0x2546fe0)
        C:/go/src/github.com/docker/docker/vendor/github.com/Microsoft/hcsshim/internal/wclayer/exportlayer.go:74 +0x95
github.com/docker/docker/daemon/graphdriver/windows.(*Driver).exportLayer.func1.1(0x5f8, 0xc00078e000)
        C:/go/src/github.com/docker/docker/daemon/graphdriver/windows/windows.go:672 +0x120
github.com/docker/docker/vendor/github.com/Microsoft/go-winio.RunWithPrivileges(0xc000bc1f88, 0x1, 0x1, 0xc000bfe380, 0x0, 0x0)
        C:/go/src/github.com/docker/docker/vendor/github.com/Microsoft/go-winio/privilege.go:92 +0x164
github.com/docker/docker/vendor/github.com/Microsoft/go-winio.RunWithPrivilege(...)
        C:/go/src/github.com/docker/docker/vendor/github.com/Microsoft/go-winio/privilege.go:72
github.com/docker/docker/daemon/graphdriver/windows.(*Driver).exportLayer.func1(0xc00084c690, 0xc000c36c40, 0x40, 0xc000a8a5a0, 0x9, 0x9, 0xc000134128)
        C:/go/src/github.com/docker/docker/daemon/graphdriver/windows/windows.go:665 +0xf3
created by github.com/docker/docker/daemon/graphdriver/windows.(*Driver).exportLayer
        C:/go/src/github.com/docker/docker/daemon/graphdriver/windows/windows.go:664 +0x198

goroutine 159 [syscall, 2 minutes, locked to thread]:
syscall.Syscall6(0x7ffc38dd6b90, 0x5, 0x5dc, 0xc000ae9f9c, 0xc000ae9fa0, 0xc000ae9fa8, 0xffffffff, 0x0, 0x0, 0x0, ...)
        C:/.GOROOT/src/runtime/syscall_windows.go:197 +0xed
github.com/docker/docker/vendor/github.com/Microsoft/go-winio.getQueuedCompletionStatus(0x5dc, 0xc000ae9f9c, 0xc000ae9fa0, 0xc000ae9fa8, 0x31ffffffff, 0x254b340, 0xc00078e008)
        C:/go/src/github.com/docker/docker/vendor/github.com/Microsoft/go-winio/zsyscall_windows.go:100 +0xb6
github.com/docker/docker/vendor/github.com/Microsoft/go-winio.ioCompletionProcessor(0x5dc)
        C:/go/src/github.com/docker/docker/vendor/github.com/Microsoft/go-winio/file.go:159 +0xb6
created by github.com/docker/docker/vendor/github.com/Microsoft/go-winio.initIo
        C:/go/src/github.com/docker/docker/vendor/github.com/Microsoft/go-winio/file.go:72 +0x7d

Not sure exactly what should I do to enable more traces like find out which files hcsshim is trying to delete.

dvasdekis commented 3 years ago

Suffering from this personally when running apt-get install as a build step, both on Hyper-V and on WSL2. Takes around 10x as long relative to OSX, even with Antivirus off.