search

microsoft / hcsshim

Windows - Host Compute Service Shim
MIT License
568 stars 256 forks source link

hcsshim::ComputeSystem::CreateProcess - Begin Operation: Error 80070002 ("The system cannot find the file specified") with Windows: Experimental: ContainerD runtime #674

Closed vikramhh closed 5 years ago

vikramhh commented 5 years ago

Setup:

  1. containerd [https://github.com/containerd/containerd/blob/master/.appveyor.yml]
  2. dockerd built building using windows.ps1 from the repo docker\ee-engine
  3. ContainerD Runtime enabled https://github.com/moby/moby/pull/38541
  4. Build container with build -t busybox . using the following Dockerfile:
FROM mcr.microsoft.com/windows/servercore:ltsc2019
RUN mkdir C:\tmp && mkdir C:\bin
ADD http://frippery.org/files/busybox/busybox.exe /bin/
RUN setx /M PATH "C:\bin;%PATH%"
RUN powershell busybox.exe --list ^|%{$nul = {cmd /c mklink C:\bin\$_.exe busybox.exe}}
CMD ["sh"]
  1. Run container using run -i -a stdin busybox echo foo

Expected: Success

Observed: 

Error response from daemon: CreateProcess bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965: The system cannot find the file specified.
(extra info: {"CommandLine":"echo foo","WorkingDirectory":"C:\\","CreateStdInPipe":true,"CreateStdOutPipe":true,"CreateStdErrPipe":true}): unknown.

Output of docker info: 

Containers: 1
 Running: 0
 Paused: 0
 Stopped: 1
Images: 8
Server Version: 0.0.0-dev
Storage Driver: windowsfilter (windows) lcow (linux)
 Windows:
 LCOW:
Logging Driver: json-file
Plugins:
 Volume: local
 Network: ics l2bridge l2tunnel nat null overlay transparent
 Log: awslogs etwlogs fluentd gcplogs gelf json-file local logentries splunk syslog
Swarm: inactive
Default Isolation: process
Kernel Version: 10.0 17763 (17763.1.amd64fre.rs5_release.180914-1434)
Operating System: Windows Server 2019 Datacenter Version 1809 (OS Build 17763.615)
OSType: windows
Architecture: x86_64
CPUs: 2
Total Memory: 4GiB
Name: EC2AMAZ-0ISL8J2
ID: 72842f94-704b-4984-b2a6-cf5383cea91c
Docker Root Dir: C:\CI\CI-402db4829e\daemon
Debug Mode (client): false
Debug Mode (server): true
 File Descriptors: -1
 Goroutines: 33
 System Time: 2019-08-21T22:25:01.8420273Z
 EventsListeners: 0
Registry: https://index.docker.io/v1/
Labels:
Experimental: true
Insecure Registries:
 127.0.0.0/8
Live Restore Enabled: false

containerd traces[see around line 171 of the traces]:

C:\gopath\src\github.com\containerd\containerd\bin>containerd.exe
time="2019-08-21T22:05:08.211600800Z" level=info msg="starting containerd" revision=fc9335d75c4bf77185f75914e1d8e89786222f43 version=v1.3.0-beta.1-35-gfc9335d7
time="2019-08-21T22:05:08.291594000Z" level=info msg="loading plugin \"io.containerd.content.v1.content\"..." type=io.containerd.content.v1
time="2019-08-21T22:05:08.296592600Z" level=info msg="loading plugin \"io.containerd.snapshotter.v1.windows-lcow\"..." type=io.containerd.snapshotter.v1
time="2019-08-21T22:05:08.302600600Z" level=info msg="loading plugin \"io.containerd.snapshotter.v1.windows\"..." type=io.containerd.snapshotter.v1
time="2019-08-21T22:05:08.305594000Z" level=info msg="loading plugin \"io.containerd.metadata.v1.bolt\"..." type=io.containerd.metadata.v1
time="2019-08-21T22:05:08.305594000Z" level=info msg="metadata content store policy set" policy=shared
time="2019-08-21T22:05:08.306598300Z" level=info msg="loading plugin \"io.containerd.differ.v1.walking\"..." type=io.containerd.differ.v1
time="2019-08-21T22:05:08.306598300Z" level=info msg="loading plugin \"io.containerd.gc.v1.scheduler\"..." type=io.containerd.gc.v1
time="2019-08-21T22:05:08.307603900Z" level=info msg="loading plugin \"io.containerd.service.v1.containers-service\"..." type=io.containerd.service.v1
time="2019-08-21T22:05:08.307603900Z" level=info msg="loading plugin \"io.containerd.service.v1.content-service\"..." type=io.containerd.service.v1
time="2019-08-21T22:05:08.307603900Z" level=info msg="loading plugin \"io.containerd.differ.v1.windows-lcow\"..." type=io.containerd.differ.v1
time="2019-08-21T22:05:08.307603900Z" level=info msg="loading plugin \"io.containerd.differ.v1.windows\"..." type=io.containerd.differ.v1
time="2019-08-21T22:05:08.307603900Z" level=info msg="loading plugin \"io.containerd.service.v1.diff-service\"..." type=io.containerd.service.v1
time="2019-08-21T22:05:08.307603900Z" level=info msg="loading plugin \"io.containerd.service.v1.images-service\"..." type=io.containerd.service.v1
time="2019-08-21T22:05:08.308590900Z" level=info msg="loading plugin \"io.containerd.service.v1.leases-service\"..." type=io.containerd.service.v1
time="2019-08-21T22:05:08.308590900Z" level=info msg="loading plugin \"io.containerd.service.v1.namespaces-service\"..." type=io.containerd.service.v1
time="2019-08-21T22:05:08.308590900Z" level=info msg="loading plugin \"io.containerd.service.v1.snapshots-service\"..." type=io.containerd.service.v1
time="2019-08-21T22:05:08.308590900Z" level=info msg="loading plugin \"io.containerd.runtime.v2.task\"..." type=io.containerd.runtime.v2
time="2019-08-21T22:05:08.311598300Z" level=error msg="loading container 36b4c180ffc0bbb95b314ffe657af4d699644e0e58a6be5a5031ac8126500399" error="container \"36b4c180ffc0bbb95b314ffe657af4d699644e0e58a6be5a5031ac8126500399\" in namespace \"moby\": not found"
time="2019-08-21T22:05:08.317602600Z" level=error msg="loading container 755878c3c98d14e0b56f99907e5b88c121166ef95187a2aa3d1ccbc50f1a0b56" error="container \"755878c3c98d14e0b56f99907e5b88c121166ef95187a2aa3d1ccbc50f1a0b56\" in namespace \"moby\": not found"
time="2019-08-21T22:05:08.319602400Z" level=error msg="loading container 8dbccfa2316cf44b5ac7e9a1c57293f29f13d7130c2487b561a3f1b46b5bc53c" error="container \"8dbccfa2316cf44b5ac7e9a1c57293f29f13d7130c2487b561a3f1b46b5bc53c\" in namespace \"moby\": not found"
time="2019-08-21T22:05:08.322601900Z" level=error msg="loading container 8fccb87df7ca24ac349e6dfd3ca5252ce52d2fc3d37f366876168d8709e77b51" error="container \"8fccb87df7ca24ac349e6dfd3ca5252ce52d2fc3d37f366876168d8709e77b51\" in namespace \"moby\": not found"
time="2019-08-21T22:05:08.324556400Z" level=error msg="loading container b1000d1997a9c286a506f2fed38c108a1949b94b3e760748a073843e24a29af5" error="container \"b1000d1997a9c286a506f2fed38c108a1949b94b3e760748a073843e24a29af5\" in namespace \"moby\": not found"
time="2019-08-21T22:05:08.326602400Z" level=error msg="loading container b8a5a402b31fce54cd567cb5493acc6f96425a850e1f00bd61565b17f14337cb" error="container \"b8a5a402b31fce54cd567cb5493acc6f96425a850e1f00bd61565b17f14337cb\" in namespace \"moby\": not found"
time="2019-08-21T22:05:08.328605500Z" level=error msg="loading container c26deb03d4b78cc0450dcd5bfcc6c6bd1d9f3126b3d6d0c61a0dc64ce637b35f" error="container \"c26deb03d4b78cc0450dcd5bfcc6c6bd1d9f3126b3d6d0c61a0dc64ce637b35f\" in namespace \"moby\": not found"
time="2019-08-21T22:05:08.330601400Z" level=error msg="loading container c403ed117121545f1a8b166d647d8eee1224e5b8fb192ba6c6afd827763c6130" error="container \"c403ed117121545f1a8b166d647d8eee1224e5b8fb192ba6c6afd827763c6130\" in namespace \"moby\": not found"
time="2019-08-21T22:05:08.332602500Z" level=info msg="loading plugin \"io.containerd.service.v1.tasks-service\"..." type=io.containerd.service.v1
time="2019-08-21T22:05:08.332602500Z" level=info msg="loading plugin \"io.containerd.internal.v1.restart\"..." type=io.containerd.internal.v1
time="2019-08-21T22:05:08.332602500Z" level=info msg="loading plugin \"io.containerd.grpc.v1.containers\"..." type=io.containerd.grpc.v1
time="2019-08-21T22:05:08.332602500Z" level=info msg="loading plugin \"io.containerd.grpc.v1.content\"..." type=io.containerd.grpc.v1
time="2019-08-21T22:05:08.332602500Z" level=info msg="loading plugin \"io.containerd.grpc.v1.diff\"..." type=io.containerd.grpc.v1
time="2019-08-21T22:05:08.333599200Z" level=info msg="loading plugin \"io.containerd.grpc.v1.events\"..." type=io.containerd.grpc.v1
time="2019-08-21T22:05:08.333599200Z" level=info msg="loading plugin \"io.containerd.grpc.v1.healthcheck\"..." type=io.containerd.grpc.v1
time="2019-08-21T22:05:08.333599200Z" level=info msg="loading plugin \"io.containerd.grpc.v1.images\"..." type=io.containerd.grpc.v1
time="2019-08-21T22:05:08.333599200Z" level=info msg="loading plugin \"io.containerd.grpc.v1.leases\"..." type=io.containerd.grpc.v1
time="2019-08-21T22:05:08.333599200Z" level=info msg="loading plugin \"io.containerd.grpc.v1.namespaces\"..." type=io.containerd.grpc.v1
time="2019-08-21T22:05:08.333599200Z" level=info msg="loading plugin \"io.containerd.internal.v1.opt\"..." type=io.containerd.internal.v1
time="2019-08-21T22:05:08.335562600Z" level=info msg="loading plugin \"io.containerd.grpc.v1.snapshots\"..." type=io.containerd.grpc.v1
time="2019-08-21T22:05:08.335562600Z" level=info msg="loading plugin \"io.containerd.grpc.v1.tasks\"..." type=io.containerd.grpc.v1
time="2019-08-21T22:05:08.335562600Z" level=info msg="loading plugin \"io.containerd.grpc.v1.version\"..." type=io.containerd.grpc.v1
time="2019-08-21T22:05:08.335562600Z" level=info msg="loading plugin \"io.containerd.grpc.v1.introspection\"..." type=io.containerd.grpc.v1
time="2019-08-21T22:05:08.335562600Z" level=info msg=serving... address="\\\\.\\pipe\\containerd-containerd.ttrpc"
time="2019-08-21T22:05:08.336604500Z" level=info msg=serving... address="\\\\.\\pipe\\containerd-containerd"
time="2019-08-21T22:05:08.337611500Z" level=info msg="containerd successfully booted in 0.127009s"
time="2019-08-21T22:05:22.410914500Z" level=info msg=Create bundle="C:\\ProgramData\\containerd\\state\\io.containerd.runtime.v2.task\\moby\\ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839" checkpoint= parentcheckpoint= rootfs="[]" stderr="\\\\.\\pipe\\containerd-ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839-init-stderr" stdin= stdout="\\\\.\\pipe\\containerd-ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839-init-stdout" terminal=false tid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839
time="2019-08-21T22:05:22.460916900Z" level=debug msg=newHcsStandloneTask tid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839
time="2019-08-21T22:05:22.461919600Z" level=debug msg=newHcsTask ownsParent=true tid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839
time="2019-08-21T22:05:22.461919600Z" level=debug msg="npipeio::New" eid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839 stderr="\\\\.\\pipe\\containerd-ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839-init-stderr" stdin= stdout="\\\\.\\pipe\\containerd-ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839-init-stdout" terminal=false tid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839
time="2019-08-21T22:05:22.461919600Z" level=debug msg="hcsshim::CreateContainer options: &{ID:ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839 Owner:containerd-shim-runhcs-v1.exe Spec:0xc000176080 SchemaVersion:<nil> HostingSystem:<nil> NetworkNamespace: DoNotReleaseResourcesOnFailure:false}"
time="2019-08-21T22:05:22.462922000Z" level=debug msg="hcsshim::CreateContainer using schema {\"Major\":2,\"Minor\":1}"
time="2019-08-21T22:05:22.463922600Z" level=debug msg="hcsoci::createNetworkNamespace - Begin" cid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839
time="2019-08-21T22:05:22.463922600Z" level=debug msg="[POST]=>[/namespaces/] Request : {}"
time="2019-08-21T22:05:22.480922500Z" level=debug msg="Network Response : {\"ActivityId\":\"97FBA58F-ECC2-42D8-A8AB-52766F41144D\",\"AdditionalParams\":{},\"Containers\":[],\"Health\":{\"LastErrorCode\":0,\"LastUpdateTime\":132108987224769239},\"ID\":\"59B1057A-E526-415A-B840-B61662558067\",\"IsDefault\":false,\"Policies\":[],\"Resources\":{\"AdditionalParams\":{},\"AllocationOrder\":0,\"Health\":{\"LastErrorCode\":0,\"LastUpdateTime\":132108987224769239},\"ID\":\"97FBA58F-ECC2-42D8-A8AB-52766F41144D\",\"PortOperationTime\":0,\"State\":1,\"SwitchOperationTime\":0,\"VfpOperationTime\":0},\"State\":1,\"Version\":38654705666}"
time="2019-08-21T22:05:22.480922500Z" level=info msg="created network namespace 59B1057A-E526-415A-B840-B61662558067 for ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839"
time="2019-08-21T22:05:22.481891900Z" level=debug msg="[POST]=>[/namespaces/59B1057A-E526-415A-B840-B61662558067/addresource] Request : {\"Type\":\"Endpoint\",\"Data\":{\"Id\":\"596A5308-C906-456F-B714-28EBEB04442A\"}}"
time="2019-08-21T22:05:22.484924500Z" level=info msg="added network endpoint 596A5308-C906-456F-B714-28EBEB04442A to namespace 59B1057A-E526-415A-B840-B61662558067"
time="2019-08-21T22:05:22.484924500Z" level=debug msg="hcsoci::createNetworkNamespace - End" cid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839
time="2019-08-21T22:05:22.485924700Z" level=debug msg="hcsshim::CreateContainer allocating resources"
time="2019-08-21T22:05:22.486923200Z" level=debug msg="hcsshim::allocateWindowsResources scratch folder: C:\\CI\\CI-402db4829e\\daemon\\windowsfilter\\ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839"
time="2019-08-21T22:05:22.488925200Z" level=debug msg="hcsshim::CreateContainer creating container document"
time="2019-08-21T22:05:22.489924100Z" level=debug msg="hcsshim: CreateHCSContainerDocument"
time="2019-08-21T22:05:22.489924100Z" level=debug msg="hcsshim::NameToGuid" name=3f61527dce9118f2843a35b7496773bdf389256f36dad2d44cce3b9dac42a007
time="2019-08-21T22:05:22.491917900Z" level=debug msg="hcsshim::NameToGuid - succeeded" guid=99c26bda-5b00-5e36-b346-1f8464d8a411 name=3f61527dce9118f2843a35b7496773bdf389256f36dad2d44cce3b9dac42a007
time="2019-08-21T22:05:22.491917900Z" level=debug msg="hcsshim::NameToGuid" name=ea56bf4293cffe1aca4c13c33d8edaa5a44cefe738f88a0dfdd2aa349e8aa55e
time="2019-08-21T22:05:22.496918300Z" level=debug msg="hcsshim::NameToGuid - succeeded" guid=90c8a5ca-8b78-5f79-80c2-50e2353a96e3 name=ea56bf4293cffe1aca4c13c33d8edaa5a44cefe738f88a0dfdd2aa349e8aa55e
time="2019-08-21T22:05:22.496918300Z" level=debug msg="hcsshim::NameToGuid" name=1e0c1ae396c5961b787282e3fed93018633f66c0bd9175fac337b044d34dc94e
time="2019-08-21T22:05:22.497922200Z" level=debug msg="hcsshim::NameToGuid - succeeded" guid=3b8a85e6-0901-5097-b9db-e5c9652c0aa0 name=1e0c1ae396c5961b787282e3fed93018633f66c0bd9175fac337b044d34dc94e
time="2019-08-21T22:05:22.497922200Z" level=debug msg="hcsshim::NameToGuid" name=0378ac8e7b742c01d9f0488dc120fb45f5a5d576807767598689f40b480bfecc
time="2019-08-21T22:05:22.498926900Z" level=debug msg="hcsshim::NameToGuid - succeeded" guid=d1ec8c49-b3df-5f05-8ca1-a2c790da8e28 name=0378ac8e7b742c01d9f0488dc120fb45f5a5d576807767598689f40b480bfecc
time="2019-08-21T22:05:22.499922100Z" level=debug msg="hcsshim::NameToGuid" name=7196f0a48b987516b111a3551e0dc28505faf8570500921916f69185e8cb170f
time="2019-08-21T22:05:22.499922100Z" level=debug msg="hcsshim::NameToGuid - succeeded" guid=fdc8e540-e6ad-5a37-9cd1-eba8a97618a8 name=7196f0a48b987516b111a3551e0dc28505faf8570500921916f69185e8cb170f
time="2019-08-21T22:05:22.500921800Z" level=debug msg="hcsshim::CreateContainer creating compute system"
time="2019-08-21T22:05:22.500921800Z" level=debug msg="hcsshim::CreateComputeSystem - Begin Operation" cid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839
time="2019-08-21T22:05:22.502921400Z" level=debug msg="HCS ComputeSystem Document" cid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839 json="{\"Owner\":\"containerd-shim-runhcs-v1.exe\",\"SchemaVersion\":{\"Major\":2,\"Minor\":1},\"Container\":{\"GuestOs\":{\"HostName\":\"ac3bb94184f2\"},\"Storage\":{\"Layers\":[{\"Id\":\"99c26bda-5b00-5e36-b346-1f8464d8a411\",\"Path\":\"C:\\\\CI\\\\CI-402db4829e\\\\daemon\\\\windowsfilter\\\\3f61527dce9118f2843a35b7496773bdf389256f36dad2d44cce3b9dac42a007\"},{\"Id\":\"90c8a5ca-8b78-5f79-80c2-50e2353a96e3\",\"Path\":\"C:\\\\CI\\\\CI-402db4829e\\\\daemon\\\\windowsfilter\\\\ea56bf4293cffe1aca4c13c33d8edaa5a44cefe738f88a0dfdd2aa349e8aa55e\"},{\"Id\":\"3b8a85e6-0901-5097-b9db-e5c9652c0aa0\",\"Path\":\"C:\\\\CI\\\\CI-402db4829e\\\\daemon\\\\windowsfilter\\\\1e0c1ae396c5961b787282e3fed93018633f66c0bd9175fac337b044d34dc94e\"},{\"Id\":\"d1ec8c49-b3df-5f05-8ca1-a2c790da8e28\",\"Path\":\"C:\\\\CI\\\\CI-402db4829e\\\\daemon\\\\windowsfilter\\\\0378ac8e7b742c01d9f0488dc120fb45f5a5d576807767598689f40b480bfecc\"},{\"Id\":\"fdc8e540-e6ad-5a37-9cd1-eba8a97618a8\",\"Path\":\"C:\\\\CI\\\\CI-402db4829e\\\\daemon\\\\windowsfilter\\\\7196f0a48b987516b111a3551e0dc28505faf8570500921916f69185e8cb170f\"}],\"Path\":\"\\\\\\\\?\\\\Volume{72ec7446-cd0e-4a36-a81b-6cde1f516d6d}\\\\\"},\"Networking\":{\"AllowUnqualifiedDnsQuery\":true,\"Namespace\":\"59B1057A-E526-415A-B840-B61662558067\"}},\"ShouldTerminateOnLastHandleClosed\":true}"
time="2019-08-21T22:05:22.863935900Z" level=debug msg="hcsshim::CreateComputeSystem - End Operation - Success" cid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839
time="2019-08-21T22:05:22.863935900Z" level=debug msg=newHcsExec eid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839 tid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839
time="2019-08-21T22:05:22.877932300Z" level=debug msg="hcsshim::ComputeSystem::Wait - Begin Operation" cid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839
time="2019-08-21T22:05:22.877932300Z" level=debug msg="hcsExec::Wait" eid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839 tid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839
time="2019-08-21T22:05:23.005931100Z" level=info msg=Create result=Success tid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839
time="2019-08-21T22:05:23.005931100Z" level=info msg=Start eid= tid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839
time="2019-08-21T22:05:23.005931100Z" level=debug msg="hcsExec::Start" eid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839 tid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839
time="2019-08-21T22:05:23.008934800Z" level=debug msg="hcsshim::ComputeSystem::Start - Begin Operation" cid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839
time="2019-08-21T22:05:23.516948400Z" level=debug msg="hcsshim::ComputeSystem::Start - End Operation - Success" cid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839
time="2019-08-21T22:05:23.516948400Z" level=debug msg="hcsshim::ComputeSystem::CreateProcess - Begin Operation" cid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839
time="2019-08-21T22:05:23.520947200Z" level=debug msg="HCS ComputeSystem Process Document" cid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839 json="{\"CommandLine\":\"cmd /S /C powershell busybox.exe --list ^|%{$nul = {cmd /c mklink C:\\\\bin\\\\$_.exe busybox.exe}}\",\"WorkingDirectory\":\"C:\\\\\",\"CreateStdOutPipe\":true,\"CreateStdErrPipe\":true}"
time="2019-08-21T22:05:23.608949800Z" level=debug msg="HCS ComputeSystem CreateProcess PID" cid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839 pid=3152
time="2019-08-21T22:05:23.608949800Z" level=debug msg="hcsshim::ComputeSystem::CreateProcess - End Operation - Success" cid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839
time="2019-08-21T22:05:23.620944400Z" level=debug msg="hcsshim::Process::Stdio - Begin Operation" cid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839 pid=3152
time="2019-08-21T22:05:23.644950500Z" level=debug msg="hcsshim::Process::Stdio - End Operation - Success" cid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839 pid=3152
time="2019-08-21T22:05:23.848956400Z" level=info msg=Start eid= result=Success tid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839
time="2019-08-21T22:05:23.848956400Z" level=debug msg="hcsshim::Process::Wait - Begin Operation" cid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839 pid=3152
time="2019-08-21T22:05:23.926958500Z" level=info msg=State eid= tid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839
time="2019-08-21T22:05:23.995962400Z" level=info msg=State eid= result=Success tid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839
time="2019-08-21T22:05:26.008999300Z" level=debug msg="hcsExec::Start::Stdout - Copy completed" eid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839 tid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839
time="2019-08-21T22:05:26.008999300Z" level=debug msg="hcsExec::Start::Stderr - Copy completed" eid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839 tid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839
time="2019-08-21T22:05:26.013000200Z" level=debug msg="hcsshim::Process::Wait - End Operation - Success" cid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839 pid=3152
time="2019-08-21T22:05:26.014008500Z" level=debug msg="hcsshim::Process::ExitCode - Begin Operation" cid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839 pid=3152
time="2019-08-21T22:05:26.014008500Z" level=debug msg="hcsshim::Process::Properties - Begin Operation" cid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839 pid=3152
time="2019-08-21T22:05:26.016004100Z" level=debug msg="hcsshim::Process::Properties - End Operation - Success" cid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839 pid=3152
time="2019-08-21T22:05:26.016004100Z" level=debug msg="hcsshim::Process::ExitCode - End Operation - Success" cid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839 pid=3152
time="2019-08-21T22:05:26.017006000Z" level=debug msg="hcsExec::waitForExit - Exited" eid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839 exitCode=0 tid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839
time="2019-08-21T22:05:26.017006000Z" level=debug msg="hcsshim::Process::Close - Begin Operation" cid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839 pid=3152
time="2019-08-21T22:05:26.018007100Z" level=debug msg="hcsshim::Process::Close - End Operation - Success" cid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839 pid=3152
time="2019-08-21T22:05:26.019008200Z" level=debug msg="npipeio::Close" eid= tid=
time="2019-08-21T22:05:26.019983600Z" level=debug msg="hcsTask::close" tid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839
time="2019-08-21T22:05:26.019983600Z" level=debug msg="hcsshim::ComputeSystem::Shutdown - Begin Operation" cid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839
time="2019-08-21T22:05:26.046008600Z" level=debug msg="hcsshim::ComputeSystem::Shutdown - End Operation - Success" cid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839
time="2019-08-21T22:05:26.046008600Z" level=debug msg="hcsshim::ComputeSystem::WaitTimeout - Begin Operation" cid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839
time="2019-08-21T22:05:26.587017700Z" level=debug msg="hcsshim::ComputeSystem::Wait - End Operation - Success" cid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839
time="2019-08-21T22:05:26.587017700Z" level=debug msg="hcsshim::ComputeSystem::WaitTimeout - End Operation - Success" cid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839
time="2019-08-21T22:05:26.587981000Z" level=debug msg="hcsshim::ComputeSystem::Terminate - Begin Operation" cid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839
time="2019-08-21T22:05:26.591018800Z" level=debug msg="hcsshim::ComputeSystem::Terminate - End Operation - Success" cid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839
time="2019-08-21T22:05:26.592018500Z" level=debug msg="[POST]=>[/namespaces/59B1057A-E526-415A-B840-B61662558067/removeresource] Request : {\"Type\":\"Endpoint\",\"Data\":{\"Id\":\"596A5308-C906-456F-B714-28EBEB04442A\"}}"
time="2019-08-21T22:05:26.596020400Z" level=debug msg="[DELETE]=>[/namespaces/59B1057A-E526-415A-B840-B61662558067] Request : "
time="2019-08-21T22:05:26.601016400Z" level=debug msg="hcsshim::ComputeSystem::Close - Begin Operation" cid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839
time="2019-08-21T22:05:26.602016600Z" level=debug msg="hcsshim::ComputeSystem::Close - End Operation - Success" cid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839
time="2019-08-21T22:05:26.685975700Z" level=info msg=State eid= tid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839
time="2019-08-21T22:05:26.685975700Z" level=info msg=State eid= result=Success tid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839
time="2019-08-21T22:05:26.688019600Z" level=info msg=State eid= tid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839
time="2019-08-21T22:05:26.689972600Z" level=info msg=State eid= result=Success tid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839
time="2019-08-21T22:05:26.691026400Z" level=info msg=Delete eid= tid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839
time="2019-08-21T22:05:26.691026400Z" level=debug msg="hcsTask::DeleteExec" eid= tid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839
time="2019-08-21T22:05:26.775014100Z" level=info msg=Delete eid= result=Success tid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839
time="2019-08-21T22:05:26.775014100Z" level=info msg=Shutdown now=false tid=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839
time="2019-08-21T22:05:26.779023200Z" level=info msg="shim disconnected" id=ac3bb94184f274421b203d409a5dcef7e7df828878bd8898db4c8600319a5839
time="2019-08-21T22:05:29.569338000Z" level=info msg=Create bundle="C:\\ProgramData\\containerd\\state\\io.containerd.runtime.v2.task\\moby\\bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965" checkpoint= parentcheckpoint= rootfs="[]" stderr="\\\\.\\pipe\\containerd-bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965-init-stderr" stdin="\\\\.\\pipe\\containerd-bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965-init-stdin" stdout="\\\\.\\pipe\\containerd-bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965-init-stdout" terminal=false tid=bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965
time="2019-08-21T22:05:29.620340400Z" level=debug msg=newHcsStandloneTask tid=bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965
time="2019-08-21T22:05:29.620340400Z" level=debug msg=newHcsTask ownsParent=true tid=bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965
time="2019-08-21T22:05:29.624325300Z" level=debug msg="npipeio::New" eid=bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965 stderr="\\\\.\\pipe\\containerd-bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965-init-stderr" stdin="\\\\.\\pipe\\containerd-bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965-init-stdin" stdout="\\\\.\\pipe\\containerd-bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965-init-stdout" terminal=false tid=bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965
time="2019-08-21T22:05:29.625345600Z" level=debug msg="hcsshim::CreateContainer options: &{ID:bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965 Owner:containerd-shim-runhcs-v1.exe Spec:0xc000172080 SchemaVersion:<nil> HostingSystem:<nil> NetworkNamespace: DoNotReleaseResourcesOnFailure:false}"
time="2019-08-21T22:05:29.625345600Z" level=debug msg="hcsshim::CreateContainer using schema {\"Major\":2,\"Minor\":1}"
time="2019-08-21T22:05:29.626348500Z" level=debug msg="hcsoci::createNetworkNamespace - Begin" cid=bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965
time="2019-08-21T22:05:29.627344500Z" level=debug msg="[POST]=>[/namespaces/] Request : {}"
time="2019-08-21T22:05:29.640343700Z" level=debug msg="Network Response : {\"ActivityId\":\"D9991EBD-B122-435B-8E59-747D3F2EFA05\",\"AdditionalParams\":{},\"Containers\":[],\"Health\":{\"LastErrorCode\":0,\"LastUpdateTime\":132108987296363452},\"ID\":\"1BF44CCA-E9CF-47D7-851D-BE8569D9BB2F\",\"IsDefault\":false,\"Policies\":[],\"Resources\":{\"AdditionalParams\":{},\"AllocationOrder\":0,\"Health\":{\"LastErrorCode\":0,\"LastUpdateTime\":132108987296363452},\"ID\":\"D9991EBD-B122-435B-8E59-747D3F2EFA05\",\"PortOperationTime\":0,\"State\":1,\"SwitchOperationTime\":0,\"VfpOperationTime\":0},\"State\":1,\"Version\":38654705666}"
time="2019-08-21T22:05:29.640343700Z" level=info msg="created network namespace 1BF44CCA-E9CF-47D7-851D-BE8569D9BB2F for bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965"
time="2019-08-21T22:05:29.641345500Z" level=debug msg="[POST]=>[/namespaces/1BF44CCA-E9CF-47D7-851D-BE8569D9BB2F/addresource] Request : {\"Type\":\"Endpoint\",\"Data\":{\"Id\":\"A0F2B584-19AC-4D26-9A68-3788888D61A7\"}}"
time="2019-08-21T22:05:29.645350300Z" level=info msg="added network endpoint A0F2B584-19AC-4D26-9A68-3788888D61A7 to namespace 1BF44CCA-E9CF-47D7-851D-BE8569D9BB2F"
time="2019-08-21T22:05:29.645350300Z" level=debug msg="hcsoci::createNetworkNamespace - End" cid=bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965
time="2019-08-21T22:05:29.646331100Z" level=debug msg="hcsshim::CreateContainer allocating resources"
time="2019-08-21T22:05:29.646331100Z" level=debug msg="hcsshim::allocateWindowsResources scratch folder: C:\\CI\\CI-402db4829e\\daemon\\windowsfilter\\bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965"
time="2019-08-21T22:05:29.647346100Z" level=debug msg="hcsshim::CreateContainer creating container document"
time="2019-08-21T22:05:29.648343000Z" level=debug msg="hcsshim: CreateHCSContainerDocument"
time="2019-08-21T22:05:29.648343000Z" level=debug msg="hcsshim::NameToGuid" name=c38bca1daa0fba1b66d68c6bde756611caa18f0189eb1fe9f001522c1450195b
time="2019-08-21T22:05:29.649347900Z" level=debug msg="hcsshim::NameToGuid - succeeded" guid=12e26474-2a46-589b-89a0-0af9a4ad2425 name=c38bca1daa0fba1b66d68c6bde756611caa18f0189eb1fe9f001522c1450195b
time="2019-08-21T22:05:29.649347900Z" level=debug msg="hcsshim::NameToGuid" name=93e9fc986d2a15e93a928c9f9ce31858dea6e80367d936575c66c050b1d84c0a
time="2019-08-21T22:05:29.650345000Z" level=debug msg="hcsshim::NameToGuid - succeeded" guid=63d7e051-4263-532d-8d5d-a7534fef1bd4 name=93e9fc986d2a15e93a928c9f9ce31858dea6e80367d936575c66c050b1d84c0a
time="2019-08-21T22:05:29.651346000Z" level=debug msg="hcsshim::NameToGuid" name=3f61527dce9118f2843a35b7496773bdf389256f36dad2d44cce3b9dac42a007
time="2019-08-21T22:05:29.651346000Z" level=debug msg="hcsshim::NameToGuid - succeeded" guid=99c26bda-5b00-5e36-b346-1f8464d8a411 name=3f61527dce9118f2843a35b7496773bdf389256f36dad2d44cce3b9dac42a007
time="2019-08-21T22:05:29.652347800Z" level=debug msg="hcsshim::NameToGuid" name=ea56bf4293cffe1aca4c13c33d8edaa5a44cefe738f88a0dfdd2aa349e8aa55e
time="2019-08-21T22:05:29.656338500Z" level=debug msg="hcsshim::NameToGuid - succeeded" guid=90c8a5ca-8b78-5f79-80c2-50e2353a96e3 name=ea56bf4293cffe1aca4c13c33d8edaa5a44cefe738f88a0dfdd2aa349e8aa55e
time="2019-08-21T22:05:29.656338500Z" level=debug msg="hcsshim::NameToGuid" name=1e0c1ae396c5961b787282e3fed93018633f66c0bd9175fac337b044d34dc94e
time="2019-08-21T22:05:29.660346300Z" level=debug msg="hcsshim::NameToGuid - succeeded" guid=3b8a85e6-0901-5097-b9db-e5c9652c0aa0 name=1e0c1ae396c5961b787282e3fed93018633f66c0bd9175fac337b044d34dc94e
time="2019-08-21T22:05:29.660346300Z" level=debug msg="hcsshim::NameToGuid" name=0378ac8e7b742c01d9f0488dc120fb45f5a5d576807767598689f40b480bfecc
time="2019-08-21T22:05:29.662346100Z" level=debug msg="hcsshim::NameToGuid - succeeded" guid=d1ec8c49-b3df-5f05-8ca1-a2c790da8e28 name=0378ac8e7b742c01d9f0488dc120fb45f5a5d576807767598689f40b480bfecc
time="2019-08-21T22:05:29.662346100Z" level=debug msg="hcsshim::NameToGuid" name=7196f0a48b987516b111a3551e0dc28505faf8570500921916f69185e8cb170f
time="2019-08-21T22:05:29.664345900Z" level=debug msg="hcsshim::NameToGuid - succeeded" guid=fdc8e540-e6ad-5a37-9cd1-eba8a97618a8 name=7196f0a48b987516b111a3551e0dc28505faf8570500921916f69185e8cb170f
time="2019-08-21T22:05:29.664345900Z" level=debug msg="hcsshim::CreateContainer creating compute system"
time="2019-08-21T22:05:29.671341900Z" level=debug msg="hcsshim::CreateComputeSystem - Begin Operation" cid=bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965
time="2019-08-21T22:05:29.672309800Z" level=debug msg="HCS ComputeSystem Document" cid=bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965 json="{\"Owner\":\"containerd-shim-runhcs-v1.exe\",\"SchemaVersion\":{\"Major\":2,\"Minor\":1},\"Container\":{\"GuestOs\":{\"HostName\":\"bf7f42b8b104\"},\"Storage\":{\"Layers\":[{\"Id\":\"12e26474-2a46-589b-89a0-0af9a4ad2425\",\"Path\":\"C:\\\\CI\\\\CI-402db4829e\\\\daemon\\\\windowsfilter\\\\c38bca1daa0fba1b66d68c6bde756611caa18f0189eb1fe9f001522c1450195b\"},{\"Id\":\"63d7e051-4263-532d-8d5d-a7534fef1bd4\",\"Path\":\"C:\\\\CI\\\\CI-402db4829e\\\\daemon\\\\windowsfilter\\\\93e9fc986d2a15e93a928c9f9ce31858dea6e80367d936575c66c050b1d84c0a\"},{\"Id\":\"99c26bda-5b00-5e36-b346-1f8464d8a411\",\"Path\":\"C:\\\\CI\\\\CI-402db4829e\\\\daemon\\\\windowsfilter\\\\3f61527dce9118f2843a35b7496773bdf389256f36dad2d44cce3b9dac42a007\"},{\"Id\":\"90c8a5ca-8b78-5f79-80c2-50e2353a96e3\",\"Path\":\"C:\\\\CI\\\\CI-402db4829e\\\\daemon\\\\windowsfilter\\\\ea56bf4293cffe1aca4c13c33d8edaa5a44cefe738f88a0dfdd2aa349e8aa55e\"},{\"Id\":\"3b8a85e6-0901-5097-b9db-e5c9652c0aa0\",\"Path\":\"C:\\\\CI\\\\CI-402db4829e\\\\daemon\\\\windowsfilter\\\\1e0c1ae396c5961b787282e3fed93018633f66c0bd9175fac337b044d34dc94e\"},{\"Id\":\"d1ec8c49-b3df-5f05-8ca1-a2c790da8e28\",\"Path\":\"C:\\\\CI\\\\CI-402db4829e\\\\daemon\\\\windowsfilter\\\\0378ac8e7b742c01d9f0488dc120fb45f5a5d576807767598689f40b480bfecc\"},{\"Id\":\"fdc8e540-e6ad-5a37-9cd1-eba8a97618a8\",\"Path\":\"C:\\\\CI\\\\CI-402db4829e\\\\daemon\\\\windowsfilter\\\\7196f0a48b987516b111a3551e0dc28505faf8570500921916f69185e8cb170f\"}],\"Path\":\"\\\\\\\\?\\\\Volume{72ec7446-cd0e-4a36-a81b-6cde1f516d6d}\\\\\"},\"Networking\":{\"AllowUnqualifiedDnsQuery\":true,\"Namespace\":\"1BF44CCA-E9CF-47D7-851D-BE8569D9BB2F\"}},\"ShouldTerminateOnLastHandleClosed\":true}"
time="2019-08-21T22:05:30.021353300Z" level=debug msg="hcsshim::CreateComputeSystem - End Operation - Success" cid=bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965
time="2019-08-21T22:05:30.021353300Z" level=debug msg=newHcsExec eid=bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965 tid=bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965
time="2019-08-21T22:05:30.032355200Z" level=debug msg="hcsshim::ComputeSystem::Wait - Begin Operation" cid=bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965
time="2019-08-21T22:05:30.032355200Z" level=debug msg="hcsExec::Wait" eid=bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965 tid=bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965
time="2019-08-21T22:05:30.138350400Z" level=info msg=Create result=Success tid=bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965
time="2019-08-21T22:05:30.141358800Z" level=info msg=Start eid= tid=bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965
time="2019-08-21T22:05:30.141358800Z" level=debug msg="hcsExec::Start" eid=bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965 tid=bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965
time="2019-08-21T22:05:30.142357300Z" level=debug msg="hcsshim::ComputeSystem::Start - Begin Operation" cid=bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965
time="2019-08-21T22:05:30.644365300Z" level=debug msg="hcsshim::ComputeSystem::Start - End Operation - Success" cid=bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965
time="2019-08-21T22:05:30.644365300Z" level=debug msg="hcsshim::ComputeSystem::CreateProcess - Begin Operation" cid=bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965
time="2019-08-21T22:05:30.646341200Z" level=debug msg="HCS ComputeSystem Process Document" cid=bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965 json="{\"CommandLine\":\"echo foo\",\"WorkingDirectory\":\"C:\\\\\",\"CreateStdInPipe\":true,\"CreateStdOutPipe\":true,\"CreateStdErrPipe\":true}"
time="2019-08-21T22:05:30.812372700Z" level=debug msg="HCS Result" json="{\"Error\":-2147024894,\"ErrorMessage\":\"The system cannot find the file specified.\"}"
time="2019-08-21T22:05:30.812372700Z" level=error msg="hcsshim::ComputeSystem::CreateProcess - End Operation - Error" cid=bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965 error="CreateProcess bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965: The system cannot find the file specified.\n(extra info: {\"CommandLine\":\"echo foo\",\"WorkingDirectory\":\"C:\\\\\",\"CreateStdInPipe\":true,\"CreateStdOutPipe\":true,\"CreateStdErrPipe\":true})"
time="2019-08-21T22:05:30.813374900Z" level=debug msg="hcsshim::ComputeSystem::Terminate - Begin Operation" cid=bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965
time="2019-08-21T22:05:30.860366700Z" level=debug msg="hcsshim::ComputeSystem::Terminate - End Operation - Success" cid=bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965
time="2019-08-21T22:05:30.860366700Z" level=debug msg="npipeio::Close" eid= tid=
time="2019-08-21T22:05:30.884370900Z" level=error msg=Start eid= error="CreateProcess bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965: The system cannot find the file specified.\n(extra info: {\"CommandLine\":\"echo foo\",\"WorkingDirectory\":\"C:\\\\\",\"CreateStdInPipe\":true,\"CreateStdOutPipe\":true,\"CreateStdErrPipe\":true})" result=Error tid=bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965
time="2019-08-21T22:05:30.884370900Z" level=debug msg="hcsTask::close" tid=bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965
time="2019-08-21T22:05:30.884370900Z" level=debug msg="hcsshim::ComputeSystem::Shutdown - Begin Operation" cid=bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965
time="2019-08-21T22:05:30.886325200Z" level=debug msg="hcsshim::ComputeSystem::Shutdown - End Operation - Success" cid=bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965
time="2019-08-21T22:05:30.887371400Z" level=debug msg="hcsshim::ComputeSystem::WaitTimeout - Begin Operation" cid=bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965
time="2019-08-21T22:05:30.888371900Z" level=info msg=State eid= tid=bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965
time="2019-08-21T22:05:30.888371900Z" level=info msg=State eid= result=Success tid=bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965
time="2019-08-21T22:05:30.888371900Z" level=info msg=State eid= tid=bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965
time="2019-08-21T22:05:30.890375300Z" level=info msg=State eid= result=Success tid=bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965
time="2019-08-21T22:05:30.892375100Z" level=info msg=CloseIO eid= stdin=true tid=bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965
time="2019-08-21T22:05:30.892375100Z" level=debug msg="hcsExec::CloseIO" eid=bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965 stdin=true tid=bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965
time="2019-08-21T22:05:30.896370700Z" level=debug msg="npipeio::CloseStdin" eid= tid=
time="2019-08-21T22:05:30.898372800Z" level=info msg=CloseIO eid= result=Success stdin=true tid=bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965
time="2019-08-21T22:05:30.892375100Z" level=info msg=Delete eid= tid=bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965
time="2019-08-21T22:05:30.899374100Z" level=debug msg="hcsTask::DeleteExec" eid= tid=bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965
time="2019-08-21T22:05:31.051403300Z" level=info msg=Delete eid= result=Success tid=bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965
time="2019-08-21T22:05:31.051403300Z" level=info msg=Shutdown now=false tid=bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965
time="2019-08-21T22:05:31.056376300Z" level=info msg="shim disconnected" id=bf7f42b8b104d9a0915360fd693d7b595236bd80c419ad51f97171a57a463965
vikramhh commented 5 years ago

Subtle changes to the Dockerfile [such as adding a Write-Host to the loop] cause the issue to "go away". So this could be a timing/race issue.

vikramhh commented 5 years ago

Tracked the issue to change in the Dockerfile. Closing.