VhdToTar: copyWithTimeout on the stdout pipe

[rn]

Environment:

• Windows Build: Windows 10 Pro Insider Build 16296
• LinuxKit kernel 4.12.14
• Docker master build: daemon c982ee8 client a41caad

While running some tests in a loop, I occasionally get a hang with the following error message:

DEBU[2017-09-26T16:18:34.617012400+01:00] lcowdriver: applydiff: id 6a1cda21328e8afbcfd33f97a38f4524cff2de90d305dfbc92ba2e38f74a7493
DEBU[2017-09-26T16:18:34.618012300+01:00] lcowdriver: startservicevmifnotrunning 6a1cda21328e8afbcfd33f97a38f4524cff2de90d305dfbc92ba2e38f74a7493:: Adding entry to service vm map
DEBU[2017-09-26T16:18:34.618012300+01:00] lcowdriver: startservicevmifnotrunning 6a1cda21328e8afbcfd33f97a38f4524cff2de90d305dfbc92ba2e38f74a7493:: service vm doesn't exist. Now starting it up: 6a1cda21328e8afbcfd33f97a38f4524cff2de90d305dfbc92ba2e38f74a7493
DEBU[2017-09-26T16:18:34.618012300+01:00] lcowdriver: startservicevmifnotrunning 6a1cda21328e8afbcfd33f97a38f4524cff2de90d305dfbc92ba2e38f74a7493: locking cachedScratchMutex
DEBU[2017-09-26T16:18:34.618012300+01:00] lcowdriver: startServiceVmIfNotRunning: (applydiff 6a1cda21328e8afbcfd33f97a38f4524cff2de90d305dfbc92ba2e38f74a7493) cloning cached scratch for mvd
DEBU[2017-09-26T16:18:34.635010700+01:00] lcowdriver: startServiceVmIfNotRunning: (applydiff 6a1cda21328e8afbcfd33f97a38f4524cff2de90d305dfbc92ba2e38f74a7493) adding cloned scratch as mvd
DEBU[2017-09-26T16:18:34.635010700+01:00] lcowdriver: startservicevmifnotrunning 6a1cda21328e8afbcfd33f97a38f4524cff2de90d305dfbc92ba2e38f74a7493: releasing cachedScratchMutex
DEBU[2017-09-26T16:18:34.635010700+01:00] lcowdriver: startServiceVmIfNotRunning: (applydiff 6a1cda21328e8afbcfd33f97a38f4524cff2de90d305dfbc92ba2e38f74a7493) starting 6a1cda21328e8afbcfd33f97a38f4524cff2de90d305dfbc92ba2e38f74a7493_svm
DEBU[2017-09-26T16:18:34.636012000+01:00] opengcs: StartUtilityVM: &{Options:{KirdPath:C:\Program Files\Linux Containers KernelFile:bootx64.efi InitrdFile:initrd.img Vhdx:C:\Program Files\Linux Containers\uvm.vhdx TimeoutSeconds:0 BootParameters:console=ttyS0} Name:6a1cda21328e8afbcfd33f97a38f4524cff2de90d305dfbc92ba2e38f74a7493_svm RequestedMode:3 ActualMode:0 UvmTimeoutSeconds:300 Uvm:<nil> MappedVirtualDisks:[{HostPath:C:\lcow\lcow\scratch\6a1cda21328e8afbcfd33f97a38f4524cff2de90d305dfbc92ba2e38f74a7493.vhdx ContainerPath:/tmp/scratch CreateInUtilityVM:true ReadOnly:false Cache: AttachOnly:false}]}
DEBU[2017-09-26T16:18:34.636012000+01:00] opengcs: StartUtilityVM: calling HCS with '{"SystemType":"container","Name":"6a1cda21328e8afbcfd33f97a38f4524cff2de90d305dfbc92ba2e38f74a7493_svm","Layers":null,"HvPartition":true,"HvRuntime":{"ImagePath":"C:\\Program Files\\Linux Containers","LinuxInitrdFile":"initrd.img","LinuxKernelFile":"bootx64.efi","LinuxBootParameters":"console=ttyS0"},"ContainerType":"linux","TerminateOnLastHandleClosed":true,"MappedVirtualDisks":[{"HostPath":"C:\\lcow\\lcow\\scratch\\6a1cda21328e8afbcfd33f97a38f4524cff2de90d305dfbc92ba2e38f74a7493.vhdx","ContainerPath":"/tmp/scratch","CreateInUtilityVM":true,"AttachOnly":false}]}'
DEBU[2017-09-26T16:18:34.636012000+01:00] HCSShim::CreateContainer id=6a1cda21328e8afbcfd33f97a38f4524cff2de90d305dfbc92ba2e38f74a7493_svm config={"SystemType":"container","Name":"6a1cda21328e8afbcfd33f97a38f4524cff2de90d305dfbc92ba2e38f74a7493_svm","Layers":null,"HvPartition":true,"HvRuntime":{"ImagePath":"C:\\Program Files\\Linux Containers","LinuxInitrdFile":"initrd.img","LinuxKernelFile":"bootx64.efi","LinuxBootParameters":"console=ttyS0"},"ContainerType":"linux","TerminateOnLastHandleClosed":true,"MappedVirtualDisks":[{"HostPath":"C:\\lcow\\lcow\\scratch\\6a1cda21328e8afbcfd33f97a38f4524cff2de90d305dfbc92ba2e38f74a7493.vhdx","ContainerPath":"/tmp/scratch","CreateInUtilityVM":true,"AttachOnly":false}]}
DEBU[2017-09-26T16:18:34.637010100+01:00] HCSShim::CreateContainer id=6a1cda21328e8afbcfd33f97a38f4524cff2de90d305dfbc92ba2e38f74a7493_svm merged config={"ContainerType":"linux","HvPartition":true,"HvRuntime":{"Com1PipeName":"\\\\localhost\\pipe\\vmpipe","ImagePath":"C:\\Program Files\\Linux Containers","LinuxBootParameters":"console=ttyS0","LinuxInitrdFile":"initrd.img","LinuxKernelFile":"bootx64.efi"},"Layers":null,"MappedVirtualDisks":[{"AttachOnly":false,"ContainerPath":"/tmp/scratch","CreateInUtilityVM":true,"HostPath":"C:\\lcow\\lcow\\scratch\\6a1cda21328e8afbcfd33f97a38f4524cff2de90d305dfbc92ba2e38f74a7493.vhdx"}],"Name":"6a1cda21328e8afbcfd33f97a38f4524cff2de90d305dfbc92ba2e38f74a7493_svm","SystemType":"container","TerminateOnLastHandleClosed":true}
ERRO[2017-09-26T16:23:34.609311500+01:00] opengcs: VhdToTar: C:\lcow\lcow\ee614ea0c685cb5613f8919adf7dd82cb7a894407926b24bb4d7cc409e406306\sandbox.vhdx:  copyWithTimeout on the stdout pipe (from utility VM) failed: opengcs: copyWithTimeout: timed out (vhdtotarstream: copy tarstream from exportSandbox -path /tmp/ee614ea0c685cb5613f8919adf7dd82cb7a894407926b24bb4d7cc409e406306)
DEBU[2017-09-26T16:23:34.609311500+01:00] opengcs: VhdToTar: copied 0 bytes of the tarstream of C:\lcow\lcow\ee614ea0c685cb5613f8919adf7dd82cb7a894407926b24bb4d7cc409e406306\sandbox.vhdx from the utility VM
DEBU[2017-09-26T16:23:34.610280300+01:00] HCSShim::Process::Close processid=463
DEBU[2017-09-26T16:23:34.610280300+01:00] HCSShim::Process::Close succeeded processid=463

and then nothing happens.

PS C:\WINDOWS\system32> hcsdiag list
6a1cda21328e8afbcfd33f97a38f4524cff2de90d305dfbc92ba2e38f74a7493_svm
    Hyper-V Linux Container,    Created

ee614ea0c685cb5613f8919adf7dd82cb7a894407926b24bb4d7cc409e406306_svm
    Hyper-V Linux Container,    Running

The test uses two files:
.\fakenpm\Dockerfile

FROM node:6-onbuild

.\fakenpm\packages.json:

{
  "name": "fakenpm",
  "version": "1.0.0",
  "description": "",
  "main": "index.js",
  "scripts": {
    "test": "echo \"Error: no test specified\" && exit 1"
  },
  "author": "",
  "license": "ISC"
}

and then runs:

for ($i=1; $i -le 50; $i++) { docker build -t foo fakenpm; docker system prune -a -f }

[rn]

actually, the error message may be a red herring as I've just seen it fly past without lockup