Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Bump hcsshim to b3f49c06ffaeef24d09c6c08ec8ec8425a0303e2 #40128

Open
wants to merge 1 commit into
base: master
from

Conversation

@vikramhh
Copy link

vikramhh commented Oct 24, 2019

rebased on top of #40154

  • depends on #40154 bump containerd/cgroups 5fbad35c2a7e855762d3c60f2e474ffcad0d470a

Among other things, this is required to pull in
microsoft/hcsshim#718 which should
take care of multiple issues reported to us.

full diff: microsoft/hcsshim@2226e08...6c7177e

includes:

Note that this is a temporary workaround for a bug in the platform, and will be reverted once that is addressed:

- What I did

- How I did it

- How to verify it

- Description for the changelog

- A picture of a cute animal (not mandatory but encouraged)

@thaJeztah

This comment has been minimized.

Copy link
Member

thaJeztah commented Oct 24, 2019


vendor/github.com/Microsoft/hcsshim/internal/schema2/properties.go:13:2: cannot find package "github.com/containerd/cgroups/stats/v1" in any of:
 	/go/src/github.com/docker/docker/vendor/github.com/containerd/cgroups/stats/v1 (vendor tree)
 	/usr/local/go/src/github.com/containerd/cgroups/stats/v1 (from $GOROOT)
 	/go/src/github.com/containerd/cgroups/stats/v1 (from $GOPATH)

Looks like this needs a more recent version of the containerd/cgroups package to get https://github.com/containerd/cgroups/blob/master/stats/v1/, which was added in containerd/cgroups#100

@thaJeztah

This comment was marked as resolved.

Copy link
Member

thaJeztah commented Oct 24, 2019

To other reviewers: please consider merging #39100 first; I've been rebasing that one for over 6 months now

@vikramhh

This comment has been minimized.

Copy link
Author

vikramhh commented Oct 29, 2019

@thaJeztah @tiborvass - #40128 is in now. How can I trigger all checks to run on this change so that we could see if there are any build breaks? I recall @andrewhsu telling me that I need a member of maintainers group to do that.

@thaJeztah

This comment has been minimized.

Copy link
Member

thaJeztah commented Oct 30, 2019

@vikramhh strange; CI should trigger as usual, because you didn't make changes to the Jenkinsfile. Could you try a rebase/force push to see if Jenkins starts?

Note that our current CI doesn't run tests with Hyper-V isolation, but I have a "WIP" test branch that adds Windows 1903 and hyper-v isolation to Jenkins; #39846

I'll rebase that PR on top of this one to see if we can confirm the issue is resolved

@thaJeztah

This comment has been minimized.

Copy link
Member

thaJeztah commented Oct 30, 2019

oh; your branch has a merge-conflict; you need to rebase and re-run vndr github.com/Microsoft/hcsshim

@thaJeztah thaJeztah force-pushed the vikramhh:bump_hcsshim branch from fe078eb to bbac75c Oct 30, 2019
@thaJeztah

This comment has been minimized.

Copy link
Member

thaJeztah commented Oct 30, 2019

@vikramhh I did a quick rebase and re-vendor

@thaJeztah

This comment has been minimized.

Copy link
Member

thaJeztah commented Oct 30, 2019

oh, I need to fix-up vendoring;

[2019-10-30T11:18:11.665Z]  D vendor/github.com/containerd/cgroups/stats/v1/doc.go
[2019-10-30T11:18:11.665Z]  D vendor/github.com/containerd/cgroups/stats/v1/metrics.pb.go
[2019-10-30T11:18:11.665Z]  D vendor/github.com/containerd/cgroups/stats/v1/metrics.proto
@thaJeztah thaJeztah force-pushed the vikramhh:bump_hcsshim branch 2 times, most recently from 92eca4c to c804ec6 Oct 30, 2019
@thaJeztah

This comment has been minimized.

Copy link
Member

thaJeztah commented Oct 30, 2019

opened #40154 to update containerd/cgroups, and based this on top of that one

@thaJeztah thaJeztah force-pushed the vikramhh:bump_hcsshim branch 3 times, most recently from 344d1a0 to ba2ff63 Oct 30, 2019
@thaJeztah

This comment has been minimized.

Copy link
Member

thaJeztah commented Oct 31, 2019

Seeing a lot of these failures on both RS1 and RS5;


[2019-10-30T14:22:37.513Z]     --- FAIL: TestDockerSuite/TestEventsContainerEventsAttrSort (3.17s)
[2019-10-30T14:22:37.513Z]         cli.go:29: assertion failed: 
[2019-10-30T14:22:37.513Z]             Command:  d:\CI\PR-39846\32\binary\docker.exe run --rm --name container-events-test busybox true
[2019-10-30T14:22:37.513Z]             ExitCode: 125
[2019-10-30T14:22:37.513Z]             Error:    exit status 125
[2019-10-30T14:22:37.513Z]             Stdout:   
[2019-10-30T14:22:37.513Z]             Stderr:   d:\CI\PR-39846\32\binary\docker.exe: Error response from daemon: process 1176 in container 01ef1c1ff2fddc4f76fdeb147bf724ce80a00bf46f90b4e3edf51531cf818426 encountered an error during hcsshim::Process::StdioLegacy: failure in a Windows system call: Element not found. (0x490).
[2019-10-30T14:22:37.513Z]             
[2019-10-30T14:22:37.513Z]             
[2019-10-30T14:22:37.513Z]             Failures:
[2019-10-30T14:22:37.513Z]             ExitCode was 125 expected 0
[2019-10-30T14:22:37.513Z]             Expected no error


[2019-10-30T13:57:29.000Z]     --- FAIL: TestDockerSuite/TestRunWorkingDirectory (4.12s)
[2019-10-30T13:57:29.000Z]         cli.go:29: assertion failed: 
[2019-10-30T13:57:29.000Z]             Command:  d:\CI\PR-40128\11\binary\docker.exe run --workdir C:/Windows busybox pwd
[2019-10-30T13:57:29.000Z]             ExitCode: 125
[2019-10-30T13:57:29.000Z]             Error:    exit status 125
[2019-10-30T13:57:29.000Z]             Stdout:   
[2019-10-30T13:57:29.000Z]             Stderr:   d:\CI\PR-40128\11\binary\docker.exe: Error response from daemon: process 4760 in container 0860bbbb4a73487c39416f46ecd6600b62e88d6627d89dd0fa6f19f1b0c261bb encountered an error during hcsshim::Process::StdioLegacy: failure in a Windows system call: Element not found. (0x490).
[2019-10-30T13:57:29.000Z]             
[2019-10-30T13:57:29.000Z]             
[2019-10-30T13:57:29.000Z]             Failures:
[2019-10-30T13:57:29.000Z]             ExitCode was 125 expected 0
[2019-10-30T13:57:29.000Z]             Expected no error
@vikramhh

This comment has been minimized.

Copy link
Author

vikramhh commented Oct 31, 2019

0x490 is ERROR_NOT_FOUND - this is very likely coming from makeOpenFiles in internal/hcs/utils.go

@kevpar - could you please take a look.

@thaJeztah

This comment has been minimized.

Copy link
Member

thaJeztah commented Oct 31, 2019

0x490 is ERROR_NOT_FOUND [https://golang.org/pkg/syscall/?GOOS=windows] - this is very likely coming from makeOpenFiles in internal/hcs/utils.go

Ok, so

func (s *DockerSuite) TestRunWorkingDirectory(c *testing.T) {
dir := "/root"
image := "busybox"
if testEnv.OSType == "windows" {
dir = `C:/Windows`
}
// First with -w
out, _ := dockerCmd(c, "run", "-w", dir, image, "pwd")
out = strings.TrimSpace(out)
if out != dir {
c.Errorf("-w failed to set working directory")
}
// Then with --workdir
out, _ = dockerCmd(c, "run", "--workdir", dir, image, "pwd")
out = strings.TrimSpace(out)
if out != dir {
c.Errorf("--workdir failed to set working directory")
}
}
starts a container with --workdir=C:\Windows. On Linux, specifying a non-existing directory as workdir, will create the working directory if it's not there. So it could be that something in the code is first trying to change to the directory, and then falling back to creating?

(I assume C:\Windows is in the image, but adding just in case)

@thaJeztah thaJeztah force-pushed the vikramhh:bump_hcsshim branch from ba2ff63 to b08093e Oct 31, 2019
@ebalders

This comment has been minimized.

Copy link

ebalders commented Nov 8, 2019

Any ETA on when this will be merged in?

@thaJeztah

This comment has been minimized.

Copy link
Member

thaJeztah commented Nov 8, 2019

@ebalders there's a regression in this hcsshim version, which is currently blocking this from being merged

@kevpar

This comment has been minimized.

Copy link
Contributor

kevpar commented Nov 8, 2019

I am taking a look at this.

@kevpar

This comment has been minimized.

Copy link
Contributor

kevpar commented Nov 8, 2019

@thaJeztah I'm not familiar with the moby Jenkins CI. Is there a command I can run to repro the CI tests locally?

@thaJeztah

This comment has been minimized.

Copy link
Member

thaJeztah commented Nov 8, 2019

@kevpar there probably is; you should be able to take the environment variables and commands that are in the Jenkinsfile (but admittedly, I'm not on Windows, and have never tried to do so.

Be aware that on Windows, the tests cannot run docker-in-docker, so may modify things on the host, so might be good to run them in a test-machine https://github.com/moby/moby/blob/master/Jenkinsfile#L949-L1006

@vikramhh may be able to help more with that

@thaJeztah

This comment has been minimized.

Copy link
Member

thaJeztah commented Nov 9, 2019

@kevpar are you on the community Slack (or on our internal Slack?) if not; perhaps you could inform if you could be added there; we do have a shared channel with Microsoft, which is sometimes handy for quick discussions

@vikramhh

This comment has been minimized.

Copy link
Author

vikramhh commented Nov 10, 2019

@kevpar - I tried to get a local repro but quickly ran into another issue, also in hcsshim. You may want to take a look at that first. With a docker daemon that has these hcsshim changes, I find the following:

C:\gopath\src\github.com\docker\docker>docker run --rm mcr.microsoft.com/windows/servercore:ltsc2019 true`
`docker: Error response from daemon: container 8cc37c049d7328d9fff3433632b6c86dc495bfb4d60856e59e90d227c451f26a encountered an error during hcsshim::System::CreateProcessNoStdio: failure in a Windows system call: The system cannot find the file specified. (0x2) extra info: {"CommandLine":"true","WorkingDirectory":"C:\\","CreateStdInPipe":true,"CreateStdOutPipe":true,"CreateStdErrPipe":true,"ConsoleSize":[0,0]}.

Here is the output from docker daemon when run with the --debug flag:

C:\gopath\bin\temp>dockerd.exe --debug
time="2019-11-10T14:26:36.709443200Z" level=info msg="Starting up"
time="2019-11-10T14:26:36.763447000Z" level=debug msg="Listener created for HTTP on npipe (//./pipe/docker_engine)"
time="2019-11-10T14:26:36.769450800Z" level=debug msg="Stackdump - waiting signal at Global\\stackdump-3152"
time="2019-11-10T14:26:36.769450800Z" level=info msg="Windows default isolation mode: process"
time="2019-11-10T14:26:36.770449000Z" level=debug msg="Using default logging driver json-file"
time="2019-11-10T14:26:36.770449000Z" level=debug msg="[graphdriver] trying provided driver: windowsfilter"
time="2019-11-10T14:26:36.770449000Z" level=debug msg="WindowsGraphDriver InitFilter at C:\\ProgramData\\docker\\windowsfilter"
time="2019-11-10T14:26:36.771445100Z" level=debug msg="Initialized graph driver windowsfilter"
time="2019-11-10T14:26:36.772446500Z" level=debug msg="Ignoring invalid digest sha256:0cb0663b573dc14c66c6b47467c561505d071367af6679f7d9f227fdf49d3296-f60566d6410fd8f33c0c2eba255f3b617a41313b717b8a952e3283d78471825e-removing"
time="2019-11-10T14:26:36.772446500Z" level=debug msg="Ignoring invalid digest sha256:0ef10fc62e511966e788c54679fd02b678111498d4ba6636c36fe22a26945c17-d79f3123c512dd497633cc535e23e348578667a2a89f2c93ee42a40751881bcf-removing"
time="2019-11-10T14:26:36.772446500Z" level=debug msg="Ignoring invalid digest sha256:1466f4ec2fa7179a675f5a2825120b84205a9ed9d4c42c4423968af446984f68-66249a70b7386d5f49bf89a60e3c6ce638cb4c64baf8026c4dcff814aff467e6-removing"
time="2019-11-10T14:26:36.773426800Z" level=debug msg="Ignoring invalid digest sha256:1b7551572c0ea8c98ce839d0b86abccc042557424d60b8f15e0e0df3220c66e7-83022ab77b3f29e5f7972246928c19cc2dc1b4bd32b60348a5a0bb8cdadd22f6-removing"
time="2019-11-10T14:26:36.773426800Z" level=debug msg="Ignoring invalid digest sha256:1ef81f9116b15701fea5e9b3015bd6faf2d2df1603b2e0f32663c951eb955e1e-cfe8a5f0d7d35bf6989d73edcc97fb11567a08224d8c3402f6f036a75ed9865d-removing"
time="2019-11-10T14:26:36.773426800Z" level=debug msg="Ignoring invalid digest sha256:20084a9e7acab64346da00da0818fea913d41dad33d5ab92ef277e3d0e5538b3-c99a2a86de0c37cecc5bec8ad95011701c001c3cc337ea5366bdc44d07323205-removing"
time="2019-11-10T14:26:36.773426800Z" level=debug msg="Ignoring invalid digest sha256:3028621079f8d318ca75325393150abb71e99cda6ec445b95698e5d266df79e7-f26a09b9679213138561f13ac314de7124d96827104886f68b1582fed00871d0-removing"
time="2019-11-10T14:26:36.773426800Z" level=debug msg="Ignoring invalid digest sha256:36ab587e4c9d5b92c8198a6d07d00a811e20f4b0601cd9f67e34e9e2316d1e94-a65d7cdc2e8c3f9881aafc1a947c46b709d3ad83108e27ea961413b063f5034d-removing"
time="2019-11-10T14:26:36.774446500Z" level=debug msg="Ignoring invalid digest sha256:385936468bb70caab17147fc7449c69fa580614d8016a6f48682bb272115987e-e5a5cdc560f7cda5743798c8f84539575d28bcc4eeb00c176375e2afe9870275-removing"
time="2019-11-10T14:26:36.774446500Z" level=debug msg="Ignoring invalid digest sha256:4ea904bbc0396d31e8fbf4fa2ce901a7fbc71567abff568e0153137cf2261f0a-8866bec9c70e892b5cfda518fdded0eb6fee4a16366df2fdbd5cdf0bc9dbfe66-removing"
time="2019-11-10T14:26:36.774446500Z" level=debug msg="Ignoring invalid digest sha256:4eba9880006fa41db021b2a1f16d3011c20382f77ac9e5ffd0fff5c78bdfad31-34cf421f842ddef128debdcb982a0f0af731065c73dde4c85bac25dcbef62dfa-removing"
time="2019-11-10T14:26:36.775438600Z" level=debug msg="Ignoring invalid digest sha256:51d8067a414204b03088d19f5b4f976623cea23fb5af9d3aba67d443a99d85e4-e1548021bd70941094614da3031756cbe602451328ff7f94e60581c3d2219bce-removing"
time="2019-11-10T14:26:36.775438600Z" level=debug msg="Ignoring invalid digest sha256:6f18435cf9dd3a896912fbaae501bb1d151e5c868d749ad4b132c11a02ef7bff-5f3e7de0c64619854d3e3c1b576dda42a5052c97ed62497c5998775aef43702a-removing"
time="2019-11-10T14:26:36.776412300Z" level=debug msg="Ignoring invalid digest sha256:77b6e71e4e50eaf1507de2054e9af5f63a73ee26b387be026ef8f5b199ef9a14-ffe56fad1011e2525979101e9cfe2badde6818bab2ef3ed519d6373088b8a11e-removing"
time="2019-11-10T14:26:36.776412300Z" level=debug msg="Ignoring invalid digest sha256:7975d87f65d733194993b8dbc57fec7138642074d2fef30946abaebc8359591b-ced3043d2bcd65cdb48aa0521731b11a249baddd106d6e09d18072fa795cfa9b-removing"
time="2019-11-10T14:26:36.776412300Z" level=debug msg="Ignoring invalid digest sha256:7e40b62e0f6d8d7d59ecf994e071f3198c7b06f1f8f9f76a6917d71f6f889bb2-c141ca36240e335af35250a807e37796d1b2f762ea9eef14990855a068f1a162-removing"
time="2019-11-10T14:26:36.777449200Z" level=debug msg="Ignoring invalid digest sha256:8451f5327c9dc993d37563a26a0ff3136ab6e221ff52b67573f221d1adfcd679-440dd214ed0f2d2cd823fa7348729c8af334b95b87dd6983d3706d8ca0911912-removing"
time="2019-11-10T14:26:36.777449200Z" level=debug msg="Ignoring invalid digest sha256:87d27531abafaf75e5c94e318af68044eb1f04210e336cded44b55129db678f5-a32c3642cac8c1bb5f558992f57db2853bf0f4a7e138e9cf17548a8e63966209-removing"
time="2019-11-10T14:26:36.778448600Z" level=debug msg="Ignoring invalid digest sha256:8cb4ac14ccdc0c431e8f982b863e98a691bd725265b9e540e80f768e1c84b9b0-f76d133c347f523767a620b630f2498fb90bce966b93c15365e73eb30bcdc13f-removing"
time="2019-11-10T14:26:36.779448600Z" level=debug msg="Ignoring invalid digest sha256:ab7432f3f9fb935efbbbb4777929f08f18c483e82ea187dd91a7458ec683dc85-2ab7fb0e0532736b972a17175ad32f706083d7718b5bd07980aa4bf63c84cced-removing"
time="2019-11-10T14:26:36.779448600Z" level=debug msg="Ignoring invalid digest sha256:b4b2843ac12109c6e5d084e589586433086883e7df86ce03d4430e27b1b8baba-9f047110cf7102d64f219cd5964035c15db3a8b9e2c92c16abe3a1d1e53849b9-removing"
time="2019-11-10T14:26:36.780448600Z" level=debug msg="Ignoring invalid digest sha256:ba420aeb30723506ef1aff5db6b81f12a65f05976b60e473a4fa65ae47eb8e17-4f3c276f42cd60e3279a0b2aade8d814e8c63f8be2f3f274795b74369aa8be23-removing"
time="2019-11-10T14:26:36.783448100Z" level=debug msg="Ignoring invalid digest sha256:c06439d0575849cee99502d14fc17564eeea1540319be44082f19f8b270cab57-1fb34f9591bd10f40d205dc8ccb85974f1ea258d47e8f3de33253ac0327e580c-removing"
time="2019-11-10T14:26:36.783448100Z" level=debug msg="Ignoring invalid digest sha256:cd004f09c238e8b02ef56a2d31e62b152620360628707ed24b2e007f26d1a240-9cbb6f1a5f9d646e1822ec4de2251a7ea2d612710bfa6991fe407a832935345f-removing"
time="2019-11-10T14:26:36.784396400Z" level=debug msg="Ignoring invalid digest sha256:cfa9069b7b0e6f373f23f2bb37b322be88341bda706b5d6f070f21369b6845ae-9bcad79d920ffe6d03c0e5dfdcedda6b1de2236f8f6f55bd8230ebb14435a7c6-removing"
time="2019-11-10T14:26:36.784396400Z" level=debug msg="Ignoring invalid digest sha256:d10492009737c4496b96afa569e9d5af52db2211ee46c5c65c03f03ae7dc4d1e-5904b94aff4c7a9d016c89f839c8b9e482bfc230eb87979747dca149c5f39365-removing"
time="2019-11-10T14:26:36.785401200Z" level=debug msg="Ignoring invalid digest sha256:dee9ca9bfcb1d2ab24a77801904011668972393240b2622a9249dbed0d8688bf-0a843d84759d083861e49a531db01965ea4a311ae7818efb52497cc64d170f34-removing"
time="2019-11-10T14:26:36.785401200Z" level=debug msg="Ignoring invalid digest sha256:e8ea8559c77de95338e4f81cb2d735220f35b137365ed130485844cd71c4e144-540a24eb7e069c5b6441b77c2fc6f1123aa52b72a2f414e59d8183fee230e4d4-removing"
time="2019-11-10T14:26:36.786448300Z" level=debug msg="Ignoring invalid digest sha256:efc0624bfe0aded8428f18148f62d2a29579593da3c0ee38db05dffeccfb49d1-7d70b18293adbdcec38c545fc70ad693ae8c638445a76790e27a4c98d670b322-removing"
time="2019-11-10T14:26:36.786448300Z" level=debug msg="Ignoring invalid digest sha256:f24378c93086ee7f081cc3e04dd779481e3768bb4f1071a456231cf08bd7b9e0-0a278f4c867dfd943cc8e8a368527c10c0da6788c110decaeff2b6275d8a44f2-removing"
time="2019-11-10T14:26:36.787447100Z" level=debug msg="Ignoring invalid digest sha256:f34c9e664e5e2be96cc69f277c185093995cf70234e8bc24ec5c15520e8b2915-e043e0cf46c5623976e958356513657633f80b964a87a08482405c582efc204a-removing"
time="2019-11-10T14:26:36.787447100Z" level=debug msg="Ignoring invalid digest sha256:f57c85117cb1304577b9c55546539b6c9b919eb0c9df6f9b9585f02fe1a04bbf-167d442dd3bc87476381d73eb01e719515a01f143639c47cd5aa58e75620b502-removing"
time="2019-11-10T14:26:36.788446600Z" level=debug msg="Ignoring invalid digest sha256:fd0927404d16171de999b5e2f2e5cca14159d7e11e0e2c723b34734ed416df0b-73fef3091bd9c76014054b3a7918d8f959669bfd58301532cdc5f5588e9197a5-removing"
time="2019-11-10T14:26:37.443622600Z" level=debug msg="Max Concurrent Downloads: 3"
time="2019-11-10T14:26:37.443622600Z" level=debug msg="Max Concurrent Uploads: 5"
time="2019-11-10T14:26:37.445640400Z" level=debug msg="Max Download Attempts: 5"
time="2019-11-10T14:26:37.445640400Z" level=info msg="Loading containers: start."
time="2019-11-10T14:26:37.446609300Z" level=debug msg="Option Experimental: false"
time="2019-11-10T14:26:37.446609300Z" level=debug msg="Option DefaultDriver: nat"
time="2019-11-10T14:26:37.446609300Z" level=debug msg="Option DefaultNetwork: nat"
time="2019-11-10T14:26:37.447623700Z" level=debug msg="Network Control Plane MTU: 1500"
time="2019-11-10T14:26:37.448637500Z" level=info msg="Restoring existing overlay networks from HNS into docker"
time="2019-11-10T14:26:37.448637500Z" level=debug msg="[GET]=>[/networks/] Request : "
time="2019-11-10T14:26:37.454640900Z" level=debug msg="Network Response : [{\"ActivityId\":\"1916DAC2-1ECB-4BAD-9866-F53855E60234\",\"AdditionalParams\":{},\"CurrentEndpointCount\":0,\"Extensions\":[{\"Id\":\"E7C3B2F0-F3C5-48DF-AF2B-10FED6D72E7A\",\"IsEnabled\":false,\"Name\":\"Microsoft Windows Filtering Platform\"},{\"Id\":\"E9B59CFA-2BE1-4B21-828F-B6FBDBDDC017\",\"IsEnabled\":false,\"Name\":\"Microsoft Azure VFP Switch Extension\"},{\"Id\":\"EA24CD6C-D17A-4348-9190-09F0D5BE83DD\",\"IsEnabled\":true,\"Name\":\"Microsoft NDIS Capture\"}],\"Flags\":0,\"Health\":{\"AddressNotificationMissedCount\":0,\"AddressNotificationSequenceNumber\":0,\"InterfaceNotificationMissedCount\":0,\"InterfaceNotificationSequenceNumber\":0,\"LastErrorCode\":0,\"LastUpdateTime\":132176233665191108,\"RouteNotificationMissedCount\":0,\"RouteNotificationSequenceNumber\":0},\"ID\":\"5C242C1E-8E0F-4F65-B9E0-A0B7A6EA41E2\",\"IPv6\":false,\"LayeredOn\":\"E9D3332F-9838-4597-B19A-1927B9030180\",\"MacPools\":[{\"EndMacAddress\":\"00-15-5D-AB-5F-FF\",\"StartMacAddress\":\"00-15-5D-AB-50-00\"}],\"MaxConcurrentEndpoints\":2,\"Name\":\"nat\",\"NatName\":\"ICS256EE402-8034-4D1D-9EB8-5D04222F1CB6\",\"Policies\":[],\"Resources\":{\"AdditionalParams\":{},\"AllocationOrder\":2,\"Allocators\":[{\"AdapterNetCfgInstanceId\":\"{256EE402-8034-4D1D-9EB8-5D04222F1CB6}\",\"AdditionalParams\":{},\"AllocationOrder\":0,\"CompartmendId\":0,\"Connected\":true,\"DevicelessNic\":false,\"EndpointNicGuid\":\"6D6970C9-4D8A-4953-A190-E3CBBC4B0720\",\"EndpointPortGuid\":\"6701A3DA-BAAA-495A-90DF-82C9311301D8\",\"Health\":{\"LastErrorCode\":0,\"LastUpdateTime\":132176233666301166},\"Hidden\":false,\"ID\":\"7F0E506A-8704-4195-B246-52D3DFBE3170\",\"InterfaceGuid\":\"256EE402-8034-4D1D-9EB8-5D04222F1CB6\",\"IsPolicy\":false,\"IsolationId\":0,\"MacAddress\":\"00-15-5D-AB-54-A5\",\"ManagementPort\":true,\"NicFriendlyName\":\"nat\",\"PreferredPortFriendlyName\":\"Container NIC 7f0e506a\",\"State\":3,\"SwitchId\":\"426440BA-BC18-4200-9A57-8F6BD241B407\",\"Tag\":\"Host Vnic\",\"WaitForIpv6Interface\":false,\"nonPersistentPort\":false},{\"AdditionalParams\":{},\"AllocationOrder\":1,\"Dhcp\":false,\"Dns\":false,\"ExternalInterfaceConstraint\":0,\"Health\":{\"DHCPState\":1,\"DNSState\":1,\"ICSState\":2,\"LastErrorCode\":0,\"LastUpdateTime\":132176233668019931},\"ICSFlags\":0,\"ID\":\"734E3064-B385-4518-AC3E-811E19711423\",\"IsPolicy\":false,\"Prefix\":20,\"PrivateInterfaceGUID\":\"256EE402-8034-4D1D-9EB8-5D04222F1CB6\",\"State\":3,\"SubnetIPAddress\":\"172.25.144.0\",\"Tag\":\"ICS\"}],\"Health\":{\"LastErrorCode\":0,\"LastUpdateTime\":132176233666144915},\"ID\":\"1916DAC2-1ECB-4BAD-9866-F53855E60234\",\"PortOperationTime\":0,\"State\":1,\"SwitchOperationTime\":0,\"VfpOperationTime\":0,\"parentId\":\"AE2B38A4-0E9E-4D9A-BD17-F91BAC6E86D4\"},\"State\":1,\"Subnets\":[{\"AdditionalParams\":{},\"AddressPrefix\":\"172.25.144.0/20\",\"GatewayAddress\":\"172.25.144.1\",\"Health\":{\"LastErrorCode\":0,\"LastUpdateTime\":132176233666301166},\"ID\":\"759C2C0C-D4DC-43D2-8354-135B63CCF4EA\",\"Policies\":[],\"State\":0}],\"TotalEndpoints\":9,\"Type\":\"nat\",\"Version\":38654705666}]"
time="2019-11-10T14:26:37.514574000Z" level=debug msg="Network  nat (b937364) restored"
time="2019-11-10T14:26:37.629081000Z" level=debug msg="[GET]=>[/networks/] Request : "
time="2019-11-10T14:26:37.633107400Z" level=debug msg="Network Response : [{\"ActivityId\":\"1916DAC2-1ECB-4BAD-9866-F53855E60234\",\"AdditionalParams\":{},\"CurrentEndpointCount\":0,\"Extensions\":[{\"Id\":\"E7C3B2F0-F3C5-48DF-AF2B-10FED6D72E7A\",\"IsEnabled\":false,\"Name\":\"Microsoft Windows Filtering Platform\"},{\"Id\":\"E9B59CFA-2BE1-4B21-828F-B6FBDBDDC017\",\"IsEnabled\":false,\"Name\":\"Microsoft Azure VFP Switch Extension\"},{\"Id\":\"EA24CD6C-D17A-4348-9190-09F0D5BE83DD\",\"IsEnabled\":true,\"Name\":\"Microsoft NDIS Capture\"}],\"Flags\":0,\"Health\":{\"AddressNotificationMissedCount\":0,\"AddressNotificationSequenceNumber\":0,\"InterfaceNotificationMissedCount\":0,\"InterfaceNotificationSequenceNumber\":0,\"LastErrorCode\":0,\"LastUpdateTime\":132176233665191108,\"RouteNotificationMissedCount\":0,\"RouteNotificationSequenceNumber\":0},\"ID\":\"5C242C1E-8E0F-4F65-B9E0-A0B7A6EA41E2\",\"IPv6\":false,\"LayeredOn\":\"E9D3332F-9838-4597-B19A-1927B9030180\",\"MacPools\":[{\"EndMacAddress\":\"00-15-5D-AB-5F-FF\",\"StartMacAddress\":\"00-15-5D-AB-50-00\"}],\"MaxConcurrentEndpoints\":2,\"Name\":\"nat\",\"NatName\":\"ICS256EE402-8034-4D1D-9EB8-5D04222F1CB6\",\"Policies\":[],\"Resources\":{\"AdditionalParams\":{},\"AllocationOrder\":2,\"Allocators\":[{\"AdapterNetCfgInstanceId\":\"{256EE402-8034-4D1D-9EB8-5D04222F1CB6}\",\"AdditionalParams\":{},\"AllocationOrder\":0,\"CompartmendId\":0,\"Connected\":true,\"DevicelessNic\":false,\"EndpointNicGuid\":\"6D6970C9-4D8A-4953-A190-E3CBBC4B0720\",\"EndpointPortGuid\":\"6701A3DA-BAAA-495A-90DF-82C9311301D8\",\"Health\":{\"LastErrorCode\":0,\"LastUpdateTime\":132176233666301166},\"Hidden\":false,\"ID\":\"7F0E506A-8704-4195-B246-52D3DFBE3170\",\"InterfaceGuid\":\"256EE402-8034-4D1D-9EB8-5D04222F1CB6\",\"IsPolicy\":false,\"IsolationId\":0,\"MacAddress\":\"00-15-5D-AB-54-A5\",\"ManagementPort\":true,\"NicFriendlyName\":\"nat\",\"PreferredPortFriendlyName\":\"Container NIC 7f0e506a\",\"State\":3,\"SwitchId\":\"426440BA-BC18-4200-9A57-8F6BD241B407\",\"Tag\":\"Host Vnic\",\"WaitForIpv6Interface\":false,\"nonPersistentPort\":false},{\"AdditionalParams\":{},\"AllocationOrder\":1,\"Dhcp\":false,\"Dns\":false,\"ExternalInterfaceConstraint\":0,\"Health\":{\"DHCPState\":1,\"DNSState\":1,\"ICSState\":2,\"LastErrorCode\":0,\"LastUpdateTime\":132176233668019931},\"ICSFlags\":0,\"ID\":\"734E3064-B385-4518-AC3E-811E19711423\",\"IsPolicy\":false,\"Prefix\":20,\"PrivateInterfaceGUID\":\"256EE402-8034-4D1D-9EB8-5D04222F1CB6\",\"State\":3,\"SubnetIPAddress\":\"172.25.144.0\",\"Tag\":\"ICS\"}],\"Health\":{\"LastErrorCode\":0,\"LastUpdateTime\":132176233666144915},\"ID\":\"1916DAC2-1ECB-4BAD-9866-F53855E60234\",\"PortOperationTime\":0,\"State\":1,\"SwitchOperationTime\":0,\"VfpOperationTime\":0,\"parentId\":\"AE2B38A4-0E9E-4D9A-BD17-F91BAC6E86D4\"},\"State\":1,\"Subnets\":[{\"AdditionalParams\":{},\"AddressPrefix\":\"172.25.144.0/20\",\"GatewayAddress\":\"172.25.144.1\",\"Health\":{\"LastErrorCode\":0,\"LastUpdateTime\":132176233666301166},\"ID\":\"759C2C0C-D4DC-43D2-8354-135B63CCF4EA\",\"Policies\":[],\"State\":0}],\"TotalEndpoints\":9,\"Type\":\"nat\",\"Version\":38654705666}]"
time="2019-11-10T14:26:37.650875200Z" level=debug msg="Launching DNS server for network \"none\""
time="2019-11-10T14:26:37.725304000Z" level=debug msg="releasing IPv4 pools from network nat (b9373645dc15c3ce44160106f301296cae7ffac4ebeef3c02b29b8fa8560419c)"
time="2019-11-10T14:26:37.725304000Z" level=debug msg="ReleaseAddress(172.25.144.0/20, 172.25.144.1)"
time="2019-11-10T14:26:37.727310800Z" level=debug msg="ReleasePool(172.25.144.0/20)"
time="2019-11-10T14:26:37.737303400Z" level=debug msg="cleanupServiceDiscovery for network:b9373645dc15c3ce44160106f301296cae7ffac4ebeef3c02b29b8fa8560419c"
time="2019-11-10T14:26:37.763972300Z" level=debug msg="Allocating IPv4 pools for network nat (b9373645dc15c3ce44160106f301296cae7ffac4ebeef3c02b29b8fa8560419c)"
time="2019-11-10T14:26:37.763972300Z" level=debug msg="RequestPool(LocalDefault, 172.25.144.0/20, , map[], false)"
time="2019-11-10T14:26:37.766034100Z" level=debug msg="RequestAddress(172.25.144.0/20, 172.25.144.1, map[RequestAddressType:com.docker.network.gateway])"
time="2019-11-10T14:26:37.766034100Z" level=debug msg="[GET]=>[/endpoints/] Request : "
time="2019-11-10T14:26:37.770035900Z" level=debug msg="Network Response : []"
time="2019-11-10T14:26:37.778032600Z" level=debug msg="Launching DNS server for network \"nat\""
time="2019-11-10T14:26:37.779032600Z" level=debug msg="[GET]=>[/networks/5C242C1E-8E0F-4F65-B9E0-A0B7A6EA41E2] Request : "
time="2019-11-10T14:26:37.783139000Z" level=debug msg="Network Response : {\"ActivityId\":\"1916DAC2-1ECB-4BAD-9866-F53855E60234\",\"AdditionalParams\":{},\"CurrentEndpointCount\":0,\"Extensions\":[{\"Id\":\"E7C3B2F0-F3C5-48DF-AF2B-10FED6D72E7A\",\"IsEnabled\":false,\"Name\":\"Microsoft Windows Filtering Platform\"},{\"Id\":\"E9B59CFA-2BE1-4B21-828F-B6FBDBDDC017\",\"IsEnabled\":false,\"Name\":\"Microsoft Azure VFP Switch Extension\"},{\"Id\":\"EA24CD6C-D17A-4348-9190-09F0D5BE83DD\",\"IsEnabled\":true,\"Name\":\"Microsoft NDIS Capture\"}],\"Flags\":0,\"Health\":{\"AddressNotificationMissedCount\":0,\"AddressNotificationSequenceNumber\":0,\"InterfaceNotificationMissedCount\":0,\"InterfaceNotificationSequenceNumber\":0,\"LastErrorCode\":0,\"LastUpdateTime\":132176233665191108,\"RouteNotificationMissedCount\":0,\"RouteNotificationSequenceNumber\":0},\"ID\":\"5C242C1E-8E0F-4F65-B9E0-A0B7A6EA41E2\",\"IPv6\":false,\"LayeredOn\":\"E9D3332F-9838-4597-B19A-1927B9030180\",\"MacPools\":[{\"EndMacAddress\":\"00-15-5D-AB-5F-FF\",\"StartMacAddress\":\"00-15-5D-AB-50-00\"}],\"MaxConcurrentEndpoints\":2,\"Name\":\"nat\",\"NatName\":\"ICS256EE402-8034-4D1D-9EB8-5D04222F1CB6\",\"Policies\":[],\"Resources\":{\"AdditionalParams\":{},\"AllocationOrder\":2,\"Allocators\":[{\"AdapterNetCfgInstanceId\":\"{256EE402-8034-4D1D-9EB8-5D04222F1CB6}\",\"AdditionalParams\":{},\"AllocationOrder\":0,\"CompartmendId\":0,\"Connected\":true,\"DevicelessNic\":false,\"EndpointNicGuid\":\"6D6970C9-4D8A-4953-A190-E3CBBC4B0720\",\"EndpointPortGuid\":\"6701A3DA-BAAA-495A-90DF-82C9311301D8\",\"Health\":{\"LastErrorCode\":0,\"LastUpdateTime\":132176233666301166},\"Hidden\":false,\"ID\":\"7F0E506A-8704-4195-B246-52D3DFBE3170\",\"InterfaceGuid\":\"256EE402-8034-4D1D-9EB8-5D04222F1CB6\",\"IsPolicy\":false,\"IsolationId\":0,\"MacAddress\":\"00-15-5D-AB-54-A5\",\"ManagementPort\":true,\"NicFriendlyName\":\"nat\",\"PreferredPortFriendlyName\":\"Container NIC 7f0e506a\",\"State\":3,\"SwitchId\":\"426440BA-BC18-4200-9A57-8F6BD241B407\",\"Tag\":\"Host Vnic\",\"WaitForIpv6Interface\":false,\"nonPersistentPort\":false},{\"AdditionalParams\":{},\"AllocationOrder\":1,\"Dhcp\":false,\"Dns\":false,\"ExternalInterfaceConstraint\":0,\"Health\":{\"DHCPState\":1,\"DNSState\":1,\"ICSState\":2,\"LastErrorCode\":0,\"LastUpdateTime\":132176233668019931},\"ICSFlags\":0,\"ID\":\"734E3064-B385-4518-AC3E-811E19711423\",\"IsPolicy\":false,\"Prefix\":20,\"PrivateInterfaceGUID\":\"256EE402-8034-4D1D-9EB8-5D04222F1CB6\",\"State\":3,\"SubnetIPAddress\":\"172.25.144.0\",\"Tag\":\"ICS\"}],\"Health\":{\"LastErrorCode\":0,\"LastUpdateTime\":132176233666144915},\"ID\":\"1916DAC2-1ECB-4BAD-9866-F53855E60234\",\"PortOperationTime\":0,\"State\":1,\"SwitchOperationTime\":0,\"VfpOperationTime\":0,\"parentId\":\"AE2B38A4-0E9E-4D9A-BD17-F91BAC6E86D4\"},\"State\":1,\"Subnets\":[{\"AdditionalParams\":{},\"AddressPrefix\":\"172.25.144.0/20\",\"GatewayAddress\":\"172.25.144.1\",\"Health\":{\"LastErrorCode\":0,\"LastUpdateTime\":132176233666301166},\"ID\":\"759C2C0C-D4DC-43D2-8354-135B63CCF4EA\",\"Policies\":[],\"State\":0}],\"TotalEndpoints\":9,\"Type\":\"nat\",\"Version\":38654705666}"
time="2019-11-10T14:26:37.785250000Z" level=debug msg="Binding a resolver on network nat gateway 172.25.144.1"
time="2019-11-10T14:26:37.786441800Z" level=debug msg="Resolver bound successfully for network nat"
time="2019-11-10T14:26:37.819352700Z" level=info msg="Loading containers: done."
time="2019-11-10T14:26:37.830248600Z" level=info msg="Docker daemon" commit=51d49a8ccb graphdriver(s)=windowsfilter version=0.0.0-dev
time="2019-11-10T14:26:37.831309200Z" level=info msg="Daemon has completed initialization"
time="2019-11-10T14:26:37.874052500Z" level=debug msg="Registering routers"
time="2019-11-10T14:26:37.874052500Z" level=debug msg="Registering GET, /containers/{name:.*}/checkpoints"
time="2019-11-10T14:26:37.875052900Z" level=debug msg="Registering POST, /containers/{name:.*}/checkpoints"
time="2019-11-10T14:26:37.876050400Z" level=debug msg="Registering DELETE, /containers/{name}/checkpoints/{checkpoint}"
time="2019-11-10T14:26:37.876050400Z" level=debug msg="Registering HEAD, /containers/{name:.*}/archive"
time="2019-11-10T14:26:37.877053600Z" level=debug msg="Registering GET, /containers/json"
time="2019-11-10T14:26:37.874052500Z" level=debug msg="Config reload - waiting signal at Global\\docker-daemon-config-3152"
time="2019-11-10T14:26:37.877053600Z" level=debug msg="Registering GET, /containers/{name:.*}/export"
time="2019-11-10T14:26:37.878039900Z" level=debug msg="Registering GET, /containers/{name:.*}/changes"
time="2019-11-10T14:26:37.878039900Z" level=debug msg="Registering GET, /containers/{name:.*}/json"
time="2019-11-10T14:26:37.879048500Z" level=debug msg="Registering GET, /containers/{name:.*}/top"
time="2019-11-10T14:26:37.879048500Z" level=debug msg="Registering GET, /containers/{name:.*}/logs"
time="2019-11-10T14:26:37.880051000Z" level=debug msg="Registering GET, /containers/{name:.*}/stats"
time="2019-11-10T14:26:37.880051000Z" level=debug msg="Registering GET, /containers/{name:.*}/attach/ws"
time="2019-11-10T14:26:37.881047900Z" level=debug msg="Registering GET, /exec/{id:.*}/json"
time="2019-11-10T14:26:37.881047900Z" level=debug msg="Registering GET, /containers/{name:.*}/archive"
time="2019-11-10T14:26:37.882051300Z" level=debug msg="Registering POST, /containers/create"
time="2019-11-10T14:26:37.882051300Z" level=debug msg="Registering POST, /containers/{name:.*}/kill"
time="2019-11-10T14:26:37.882051300Z" level=debug msg="Registering POST, /containers/{name:.*}/pause"
time="2019-11-10T14:26:37.883048900Z" level=debug msg="Registering POST, /containers/{name:.*}/unpause"
time="2019-11-10T14:26:37.883048900Z" level=debug msg="Registering POST, /containers/{name:.*}/restart"
time="2019-11-10T14:26:37.884051600Z" level=debug msg="Registering POST, /containers/{name:.*}/start"
time="2019-11-10T14:26:37.886045900Z" level=debug msg="Registering POST, /containers/{name:.*}/stop"
time="2019-11-10T14:26:37.887046300Z" level=debug msg="Registering POST, /containers/{name:.*}/wait"
time="2019-11-10T14:26:37.887046300Z" level=debug msg="Registering POST, /containers/{name:.*}/resize"
time="2019-11-10T14:26:37.888047800Z" level=debug msg="Registering POST, /containers/{name:.*}/attach"
time="2019-11-10T14:26:37.888047800Z" level=debug msg="Registering POST, /containers/{name:.*}/copy"
time="2019-11-10T14:26:37.888047800Z" level=debug msg="Registering POST, /containers/{name:.*}/exec"
time="2019-11-10T14:26:37.889048500Z" level=debug msg="Registering POST, /exec/{name:.*}/start"
time="2019-11-10T14:26:37.889048500Z" level=debug msg="Registering POST, /exec/{name:.*}/resize"
time="2019-11-10T14:26:37.890050600Z" level=debug msg="Registering POST, /containers/{name:.*}/rename"
time="2019-11-10T14:26:37.890050600Z" level=debug msg="Registering POST, /containers/{name:.*}/update"
time="2019-11-10T14:26:37.891052200Z" level=debug msg="Registering POST, /containers/prune"
time="2019-11-10T14:26:37.891052200Z" level=debug msg="Registering POST, /commit"
time="2019-11-10T14:26:37.891052200Z" level=debug msg="Registering PUT, /containers/{name:.*}/archive"
time="2019-11-10T14:26:37.892047700Z" level=debug msg="Registering DELETE, /containers/{name:.*}"
time="2019-11-10T14:26:37.892047700Z" level=debug msg="Registering GET, /images/json"
time="2019-11-10T14:26:37.893050000Z" level=debug msg="Registering GET, /images/search"
time="2019-11-10T14:26:37.893050000Z" level=debug msg="Registering GET, /images/get"
time="2019-11-10T14:26:37.894050600Z" level=debug msg="Registering GET, /images/{name:.*}/get"
time="2019-11-10T14:26:37.894050600Z" level=debug msg="Registering GET, /images/{name:.*}/history"
time="2019-11-10T14:26:37.895030700Z" level=debug msg="Registering GET, /images/{name:.*}/json"
time="2019-11-10T14:26:37.897533400Z" level=debug msg="Registering POST, /images/load"
time="2019-11-10T14:26:37.897533400Z" level=debug msg="Registering POST, /images/create"
time="2019-11-10T14:26:37.897533400Z" level=debug msg="Registering POST, /images/{name:.*}/push"
time="2019-11-10T14:26:37.898571600Z" level=debug msg="Registering POST, /images/{name:.*}/tag"
time="2019-11-10T14:26:37.898571600Z" level=debug msg="Registering POST, /images/prune"
time="2019-11-10T14:26:37.899591600Z" level=debug msg="Registering DELETE, /images/{name:.*}"
time="2019-11-10T14:26:37.899591600Z" level=debug msg="Registering OPTIONS, /{anyroute:.*}"
time="2019-11-10T14:26:37.899591600Z" level=debug msg="Registering GET, /_ping"
time="2019-11-10T14:26:37.900542000Z" level=debug msg="Registering HEAD, /_ping"
time="2019-11-10T14:26:37.901592500Z" level=debug msg="Registering GET, /events"
time="2019-11-10T14:26:37.901592500Z" level=debug msg="Registering GET, /info"
time="2019-11-10T14:26:37.903593000Z" level=debug msg="Registering GET, /version"
time="2019-11-10T14:26:37.903593000Z" level=debug msg="Registering GET, /system/df"
time="2019-11-10T14:26:37.904592400Z" level=debug msg="Registering POST, /auth"
time="2019-11-10T14:26:37.907561700Z" level=debug msg="Registering GET, /volumes"
time="2019-11-10T14:26:37.908592200Z" level=debug msg="Registering GET, /volumes/{name:.*}"
time="2019-11-10T14:26:37.908592200Z" level=debug msg="Registering POST, /volumes/create"
time="2019-11-10T14:26:37.909565000Z" level=debug msg="Registering POST, /volumes/prune"
time="2019-11-10T14:26:37.910594300Z" level=debug msg="Registering DELETE, /volumes/{name:.*}"
time="2019-11-10T14:26:37.910594300Z" level=debug msg="Registering POST, /build"
time="2019-11-10T14:26:37.911591900Z" level=debug msg="Registering POST, /build/prune"
time="2019-11-10T14:26:37.911591900Z" level=debug msg="Registering POST, /build/cancel"
time="2019-11-10T14:26:37.912591600Z" level=debug msg="Registering POST, /session"
time="2019-11-10T14:26:37.912591600Z" level=debug msg="Registering POST, /swarm/init"
time="2019-11-10T14:26:37.912591600Z" level=debug msg="Registering POST, /swarm/join"
time="2019-11-10T14:26:37.913590600Z" level=debug msg="Registering POST, /swarm/leave"
time="2019-11-10T14:26:37.913590600Z" level=debug msg="Registering GET, /swarm"
time="2019-11-10T14:26:37.914593100Z" level=debug msg="Registering GET, /swarm/unlockkey"
time="2019-11-10T14:26:37.914593100Z" level=debug msg="Registering POST, /swarm/update"
time="2019-11-10T14:26:37.915564900Z" level=debug msg="Registering POST, /swarm/unlock"
time="2019-11-10T14:26:37.917540800Z" level=debug msg="Registering GET, /services"
time="2019-11-10T14:26:37.917540800Z" level=debug msg="Registering GET, /services/{id}"
time="2019-11-10T14:26:37.918591500Z" level=debug msg="Registering POST, /services/create"
time="2019-11-10T14:26:37.918591500Z" level=debug msg="Registering POST, /services/{id}/update"
time="2019-11-10T14:26:37.918591500Z" level=debug msg="Registering DELETE, /services/{id}"
time="2019-11-10T14:26:37.919592300Z" level=debug msg="Registering GET, /services/{id}/logs"
time="2019-11-10T14:26:37.919592300Z" level=debug msg="Registering GET, /nodes"
time="2019-11-10T14:26:37.920590400Z" level=debug msg="Registering GET, /nodes/{id}"
time="2019-11-10T14:26:37.920590400Z" level=debug msg="Registering DELETE, /nodes/{id}"
time="2019-11-10T14:26:37.921541800Z" level=debug msg="Registering POST, /nodes/{id}/update"
time="2019-11-10T14:26:37.921541800Z" level=debug msg="Registering GET, /tasks"
time="2019-11-10T14:26:37.922592300Z" level=debug msg="Registering GET, /tasks/{id}"
time="2019-11-10T14:26:37.922592300Z" level=debug msg="Registering GET, /tasks/{id}/logs"
time="2019-11-10T14:26:37.922592300Z" level=debug msg="Registering GET, /secrets"
time="2019-11-10T14:26:37.923569500Z" level=debug msg="Registering POST, /secrets/create"
time="2019-11-10T14:26:37.923569500Z" level=debug msg="Registering DELETE, /secrets/{id}"
time="2019-11-10T14:26:37.924591900Z" level=debug msg="Registering GET, /secrets/{id}"
time="2019-11-10T14:26:37.924591900Z" level=debug msg="Registering POST, /secrets/{id}/update"
time="2019-11-10T14:26:37.925593800Z" level=debug msg="Registering GET, /configs"
time="2019-11-10T14:26:37.927588600Z" level=debug msg="Registering POST, /configs/create"
time="2019-11-10T14:26:37.927588600Z" level=debug msg="Registering DELETE, /configs/{id}"
time="2019-11-10T14:26:37.927588600Z" level=debug msg="Registering GET, /configs/{id}"
time="2019-11-10T14:26:37.928563100Z" level=debug msg="Registering POST, /configs/{id}/update"
time="2019-11-10T14:26:37.928563100Z" level=debug msg="Registering GET, /plugins"
time="2019-11-10T14:26:37.928563100Z" level=debug msg="Registering GET, /plugins/{name:.*}/json"
time="2019-11-10T14:26:37.929593300Z" level=debug msg="Registering GET, /plugins/privileges"
time="2019-11-10T14:26:37.930592400Z" level=debug msg="Registering DELETE, /plugins/{name:.*}"
time="2019-11-10T14:26:37.931592800Z" level=debug msg="Registering POST, /plugins/{name:.*}/enable"
time="2019-11-10T14:26:37.931592800Z" level=debug msg="Registering POST, /plugins/{name:.*}/disable"
time="2019-11-10T14:26:37.932551200Z" level=debug msg="Registering POST, /plugins/pull"
time="2019-11-10T14:26:37.933592200Z" level=debug msg="Registering POST, /plugins/{name:.*}/push"
time="2019-11-10T14:26:37.934590000Z" level=debug msg="Registering POST, /plugins/{name:.*}/upgrade"
time="2019-11-10T14:26:37.936589200Z" level=debug msg="Registering POST, /plugins/{name:.*}/set"
time="2019-11-10T14:26:37.937590900Z" level=debug msg="Registering POST, /plugins/create"
time="2019-11-10T14:26:37.937590900Z" level=debug msg="Registering GET, /distribution/{name:.*}/json"
time="2019-11-10T14:26:37.938593600Z" level=debug msg="Registering POST, /grpc"
time="2019-11-10T14:26:37.938593600Z" level=debug msg="Registering GET, /networks"
time="2019-11-10T14:26:37.939592200Z" level=debug msg="Registering GET, /networks/"
time="2019-11-10T14:26:37.939592200Z" level=debug msg="Registering GET, /networks/{id:.+}"
time="2019-11-10T14:26:37.940590800Z" level=debug msg="Registering POST, /networks/create"
time="2019-11-10T14:26:37.940590800Z" level=debug msg="Registering POST, /networks/{id:.*}/connect"
time="2019-11-10T14:26:37.940590800Z" level=debug msg="Registering POST, /networks/{id:.*}/disconnect"
time="2019-11-10T14:26:37.941586400Z" level=debug msg="Registering POST, /networks/prune"
time="2019-11-10T14:26:37.941586400Z" level=debug msg="Registering DELETE, /networks/{id:.*}"
time="2019-11-10T14:26:37.942594100Z" level=info msg="API listen on //./pipe/docker_engine"
time="2019-11-10T14:26:42.189865000Z" level=debug msg="Calling HEAD /_ping"
time="2019-11-10T14:26:42.196865600Z" level=debug msg="Calling POST /v1.40/containers/create"
time="2019-11-10T14:26:42.197866800Z" level=debug msg="form data: {\"AttachStderr\":true,\"AttachStdin\":false,\"AttachStdout\":true,\"Cmd\":[\"true\"],\"Domainname\":\"\",\"Entrypoint\":null,\"Env\":[],\"HostConfig\":{\"AutoRemove\":true,\"Binds\":null,\"BlkioDeviceReadBps\":null,\"BlkioDeviceReadIOps\":null,\"BlkioDeviceWriteBps\":null,\"BlkioDeviceWriteIOps\":null,\"BlkioWeight\":0,\"BlkioWeightDevice\":[],\"CapAdd\":null,\"CapDrop\":null,\"Capabilities\":null,\"Cgroup\":\"\",\"CgroupParent\":\"\",\"ConsoleSize\":[61,207],\"ContainerIDFile\":\"\",\"CpuCount\":0,\"CpuPercent\":0,\"CpuPeriod\":0,\"CpuQuota\":0,\"CpuRealtimePeriod\":0,\"CpuRealtimeRuntime\":0,\"CpuShares\":0,\"CpusetCpus\":\"\",\"CpusetMems\":\"\",\"DeviceCgroupRules\":null,\"DeviceRequests\":null,\"Devices\":[],\"Dns\":[],\"DnsOptions\":[],\"DnsSearch\":[],\"ExtraHosts\":null,\"GroupAdd\":null,\"IOMaximumBandwidth\":0,\"IOMaximumIOps\":0,\"IpcMode\":\"\",\"Isolation\":\"\",\"KernelMemory\":0,\"KernelMemoryTCP\":0,\"Links\":null,\"LogConfig\":{\"Config\":{},\"Type\":\"\"},\"MaskedPaths\":null,\"Memory\":0,\"MemoryReservation\":0,\"MemorySwap\":0,\"MemorySwappiness\":-1,\"NanoCpus\":0,\"NetworkMode\":\"default\",\"OomKillDisable\":false,\"OomScoreAdj\":0,\"PidMode\":\"\",\"PidsLimit\":0,\"PortBindings\":{},\"Privileged\":false,\"PublishAllPorts\":false,\"ReadonlyPaths\":null,\"ReadonlyRootfs\":false,\"RestartPolicy\":{\"MaximumRetryCount\":0,\"Name\":\"no\"},\"SecurityOpt\":null,\"ShmSize\":0,\"UTSMode\":\"\",\"Ulimits\":null,\"UsernsMode\":\"\",\"VolumeDriver\":\"\",\"VolumesFrom\":null},\"Hostname\":\"\",\"Image\":\"mcr.microsoft.com/windows/servercore:ltsc2019\",\"Labels\":{},\"NetworkingConfig\":{\"EndpointsConfig\":{}},\"OnBuild\":null,\"OpenStdin\":false,\"StdinOnce\":false,\"Tty\":false,\"User\":\"\",\"Volumes\":{},\"WorkingDir\":\"\"}"
time="2019-11-10T14:26:42.202868000Z" level=debug msg="hcsshim::GetLayerMountPath" path="C:\\ProgramData\\docker\\windowsfilter\\e280ae88fe4afde08717cb8a598cb480a554bfd79316047592f1a3899997e6f3"
time="2019-11-10T14:26:42.202868000Z" level=debug msg="Calling proc (1)" path="C:\\ProgramData\\docker\\windowsfilter\\e280ae88fe4afde08717cb8a598cb480a554bfd79316047592f1a3899997e6f3"
time="2019-11-10T14:26:42.203867400Z" level=debug msg="Calling proc (2)" path="C:\\ProgramData\\docker\\windowsfilter\\e280ae88fe4afde08717cb8a598cb480a554bfd79316047592f1a3899997e6f3"
time="2019-11-10T14:26:42.203867400Z" level=debug msg="hcsshim::GetLayerMountPath - succeeded" mountPath="C:\\ProgramData\\docker\\windowsfilter\\e280ae88fe4afde08717cb8a598cb480a554bfd79316047592f1a3899997e6f3" path="C:\\ProgramData\\docker\\windowsfilter\\e280ae88fe4afde08717cb8a598cb480a554bfd79316047592f1a3899997e6f3"
time="2019-11-10T14:26:42.204868100Z" level=debug msg="hcsshim::CreateScratchLayer" path="C:\\ProgramData\\docker\\windowsfilter\\f813b883dfd86c78e991ced012df6a96962059035cf6ebb1d18456f9caf97e56"
time="2019-11-10T14:26:42.204868100Z" level=debug msg="hcsshim::NameToGuid" name=e280ae88fe4afde08717cb8a598cb480a554bfd79316047592f1a3899997e6f3
time="2019-11-10T14:26:42.205865200Z" level=debug msg="hcsshim::NameToGuid - succeeded" guid=f3fa31ff-3646-5aa8-aae6-fd07fa98dc11 name=e280ae88fe4afde08717cb8a598cb480a554bfd79316047592f1a3899997e6f3
time="2019-11-10T14:26:42.205865200Z" level=debug msg="hcsshim::NameToGuid" name=e98a4f90ea0b0b172cbc2a6520403c18c5be676fc98d967d5112940318664d8e
time="2019-11-10T14:26:42.206863300Z" level=debug msg="hcsshim::NameToGuid - succeeded" guid=aee45bbb-f900-54e3-8b4a-667e447fdf14 name=e98a4f90ea0b0b172cbc2a6520403c18c5be676fc98d967d5112940318664d8e
time="2019-11-10T14:26:42.211848500Z" level=debug msg="hcsshim::CreateScratchLayer - succeeded" path="C:\\ProgramData\\docker\\windowsfilter\\f813b883dfd86c78e991ced012df6a96962059035cf6ebb1d18456f9caf97e56"
time="2019-11-10T14:26:42.229293500Z" level=debug msg="Calling POST /v1.40/containers/f813b883dfd86c78e991ced012df6a96962059035cf6ebb1d18456f9caf97e56/attach?stderr=1&stdout=1&stream=1"
time="2019-11-10T14:26:42.229293500Z" level=debug msg="attach: stdout: begin"
time="2019-11-10T14:26:42.231286200Z" level=debug msg="attach: stderr: begin"
time="2019-11-10T14:26:42.231286200Z" level=debug msg="Calling POST /v1.40/containers/f813b883dfd86c78e991ced012df6a96962059035cf6ebb1d18456f9caf97e56/wait?condition=removed"
time="2019-11-10T14:26:42.232292000Z" level=debug msg="Calling POST /v1.40/containers/f813b883dfd86c78e991ced012df6a96962059035cf6ebb1d18456f9caf97e56/start"
time="2019-11-10T14:26:42.233295000Z" level=debug msg="WindowsGraphDriver Get() id f813b883dfd86c78e991ced012df6a96962059035cf6ebb1d18456f9caf97e56 mountLabel "
time="2019-11-10T14:26:42.235290200Z" level=debug msg="hcsshim::ActivateLayer" path="C:\\ProgramData\\docker\\windowsfilter\\f813b883dfd86c78e991ced012df6a96962059035cf6ebb1d18456f9caf97e56"
time="2019-11-10T14:26:42.279684900Z" level=debug msg="hcsshim::ActivateLayer - succeeded" path="C:\\ProgramData\\docker\\windowsfilter\\f813b883dfd86c78e991ced012df6a96962059035cf6ebb1d18456f9caf97e56"
time="2019-11-10T14:26:42.300517700Z" level=debug msg="hcsshim::PrepareLayer" path="C:\\ProgramData\\docker\\windowsfilter\\f813b883dfd86c78e991ced012df6a96962059035cf6ebb1d18456f9caf97e56"
time="2019-11-10T14:26:42.306074900Z" level=debug msg="hcsshim::NameToGuid" name=e280ae88fe4afde08717cb8a598cb480a554bfd79316047592f1a3899997e6f3
time="2019-11-10T14:26:42.309458500Z" level=debug msg="hcsshim::NameToGuid - succeeded" guid=f3fa31ff-3646-5aa8-aae6-fd07fa98dc11 name=e280ae88fe4afde08717cb8a598cb480a554bfd79316047592f1a3899997e6f3
time="2019-11-10T14:26:42.310449900Z" level=debug msg="hcsshim::NameToGuid" name=e98a4f90ea0b0b172cbc2a6520403c18c5be676fc98d967d5112940318664d8e
time="2019-11-10T14:26:42.311458300Z" level=debug msg="hcsshim::NameToGuid - succeeded" guid=aee45bbb-f900-54e3-8b4a-667e447fdf14 name=e98a4f90ea0b0b172cbc2a6520403c18c5be676fc98d967d5112940318664d8e
time="2019-11-10T14:26:42.341719300Z" level=debug msg="hcsshim::PrepareLayer - succeeded" path="C:\\ProgramData\\docker\\windowsfilter\\f813b883dfd86c78e991ced012df6a96962059035cf6ebb1d18456f9caf97e56"
time="2019-11-10T14:26:42.342753600Z" level=debug msg="hcsshim::GetLayerMountPath" path="C:\\ProgramData\\docker\\windowsfilter\\f813b883dfd86c78e991ced012df6a96962059035cf6ebb1d18456f9caf97e56"
time="2019-11-10T14:26:42.343816500Z" level=debug msg="Calling proc (1)" path="C:\\ProgramData\\docker\\windowsfilter\\f813b883dfd86c78e991ced012df6a96962059035cf6ebb1d18456f9caf97e56"
time="2019-11-10T14:26:42.346857400Z" level=debug msg="Calling proc (2)" path="C:\\ProgramData\\docker\\windowsfilter\\f813b883dfd86c78e991ced012df6a96962059035cf6ebb1d18456f9caf97e56"
time="2019-11-10T14:26:42.355105400Z" level=debug msg="hcsshim::GetLayerMountPath - succeeded" mountPath="\\\\?\\Volume{c8d2d088-e33c-4b87-9a28-1aeb6c3ad286}" path="C:\\ProgramData\\docker\\windowsfilter\\f813b883dfd86c78e991ced012df6a96962059035cf6ebb1d18456f9caf97e56"
time="2019-11-10T14:26:42.355190500Z" level=debug msg="container mounted via layerStore: &{\\\\?\\Volume{c8d2d088-e33c-4b87-9a28-1aeb6c3ad286} 0x3554460 0x3554460}"
time="2019-11-10T14:26:42.376254500Z" level=debug msg="Assigning addresses for endpoint gifted_hugle's interface on network nat"
time="2019-11-10T14:26:42.377253200Z" level=debug msg="RequestAddress(172.25.144.0/20, <nil>, map[])"
time="2019-11-10T14:26:42.378248200Z" level=debug msg="endpointStruct.EnableInternalDNS =[false]"
time="2019-11-10T14:26:42.379254100Z" level=debug msg="[POST]=>[/endpoints/] Request : {\"VirtualNetwork\":\"5C242C1E-8E0F-4F65-B9E0-A0B7A6EA41E2\",\"EnableInternalDNS\":true}"
time="2019-11-10T14:26:42.388256000Z" level=debug msg="Network Response : {\"ActivityId\":\"9AC791A8-64D1-472F-8747-416171579605\",\"AdditionalParams\":{},\"CreateProcessingStartTime\":132178696023852504,\"DNSServerList\":\"172.25.144.1,172.31.0.2\",\"DNSSuffix\":\"us-east-2.compute.internal\",\"EnableInternalDNS\":true,\"EnableLowInterfaceMetric\":true,\"EncapOverhead\":0,\"GatewayAddress\":\"172.25.144.1\",\"Health\":{\"LastErrorCode\":0,\"LastUpdateTime\":132178696023822506},\"ID\":\"7EB7BC15-4510-4225-8535-9F121F8FC438\",\"IPAddress\":\"172.25.145.155\",\"MacAddress\":\"00-15-5D-AB-58-C6\",\"Name\":\"Ethernet\",\"Policies\":[],\"PrefixLength\":20,\"Resources\":{\"AdditionalParams\":{},\"AllocationOrder\":0,\"Health\":{\"LastErrorCode\":0,\"LastUpdateTime\":132178696023822506},\"ID\":\"9AC791A8-64D1-472F-8747-416171579605\",\"PortOperationTime\":0,\"State\":1,\"SwitchOperationTime\":0,\"VfpOperationTime\":0,\"parentId\":\"1916DAC2-1ECB-4BAD-9866-F53855E60234\"},\"SharedContainers\":[],\"State\":1,\"Type\":\"nat\",\"Version\":38654705666,\"VirtualNetwork\":\"5C242C1E-8E0F-4F65-B9E0-A0B7A6EA41E2\",\"VirtualNetworkName\":\"nat\"}"
time="2019-11-10T14:26:42.408028500Z" level=debug msg="Assigning addresses for endpoint gifted_hugle's interface on network nat"
time="2019-11-10T14:26:42.447700500Z" level=debug msg="[GET]=>[/endpoints/7EB7BC15-4510-4225-8535-9F121F8FC438] Request : "
time="2019-11-10T14:26:42.451696800Z" level=debug msg="Network Response : {\"ActivityId\":\"9AC791A8-64D1-472F-8747-416171579605\",\"AdditionalParams\":{},\"CreateProcessingStartTime\":132178696023852504,\"DNSServerList\":\"172.25.144.1,172.31.0.2\",\"DNSSuffix\":\"us-east-2.compute.internal\",\"EnableInternalDNS\":true,\"EnableLowInterfaceMetric\":true,\"EncapOverhead\":0,\"GatewayAddress\":\"172.25.144.1\",\"Health\":{\"LastErrorCode\":0,\"LastUpdateTime\":132178696023822506},\"ID\":\"7EB7BC15-4510-4225-8535-9F121F8FC438\",\"IPAddress\":\"172.25.145.155\",\"MacAddress\":\"00-15-5D-AB-58-C6\",\"Name\":\"Ethernet\",\"Policies\":[],\"PrefixLength\":20,\"Resources\":{\"AdditionalParams\":{},\"AllocationOrder\":0,\"Health\":{\"LastErrorCode\":0,\"LastUpdateTime\":132178696023822506},\"ID\":\"9AC791A8-64D1-472F-8747-416171579605\",\"PortOperationTime\":0,\"State\":1,\"SwitchOperationTime\":0,\"VfpOperationTime\":0,\"parentId\":\"1916DAC2-1ECB-4BAD-9866-F53855E60234\"},\"SharedContainers\":[],\"State\":1,\"Type\":\"nat\",\"Version\":38654705666,\"VirtualNetwork\":\"5C242C1E-8E0F-4F65-B9E0-A0B7A6EA41E2\",\"VirtualNetworkName\":\"nat\"}"
time="2019-11-10T14:26:42.452656000Z" level=debug msg="[GET]=>[/endpoints/7EB7BC15-4510-4225-8535-9F121F8FC438] Request : "
time="2019-11-10T14:26:42.456696800Z" level=debug msg="Network Response : {\"ActivityId\":\"9AC791A8-64D1-472F-8747-416171579605\",\"AdditionalParams\":{},\"CreateProcessingStartTime\":132178696023852504,\"DNSServerList\":\"172.25.144.1,172.31.0.2\",\"DNSSuffix\":\"us-east-2.compute.internal\",\"EnableInternalDNS\":true,\"EnableLowInterfaceMetric\":true,\"EncapOverhead\":0,\"GatewayAddress\":\"172.25.144.1\",\"Health\":{\"LastErrorCode\":0,\"LastUpdateTime\":132178696023822506},\"ID\":\"7EB7BC15-4510-4225-8535-9F121F8FC438\",\"IPAddress\":\"172.25.145.155\",\"MacAddress\":\"00-15-5D-AB-58-C6\",\"Name\":\"Ethernet\",\"Policies\":[],\"PrefixLength\":20,\"Resources\":{\"AdditionalParams\":{},\"AllocationOrder\":0,\"Health\":{\"LastErrorCode\":0,\"LastUpdateTime\":132178696023822506},\"ID\":\"9AC791A8-64D1-472F-8747-416171579605\",\"PortOperationTime\":0,\"State\":1,\"SwitchOperationTime\":0,\"VfpOperationTime\":0,\"parentId\":\"1916DAC2-1ECB-4BAD-9866-F53855E60234\"},\"SharedContainers\":[],\"State\":1,\"Type\":\"nat\",\"Version\":38654705666,\"VirtualNetwork\":\"5C242C1E-8E0F-4F65-B9E0-A0B7A6EA41E2\",\"VirtualNetworkName\":\"nat\"}"
time="2019-11-10T14:26:42.467693800Z" level=debug msg="Programming external connectivity on endpoint gifted_hugle (dd9ab8e3a09ae75da961c66251ed422c5b8de594407f68956a45de50007d5d63)"
time="2019-11-10T14:26:42.468696800Z" level=debug msg="EnableService f813b883dfd86c78e991ced012df6a96962059035cf6ebb1d18456f9caf97e56 START"
time="2019-11-10T14:26:42.469698900Z" level=debug msg="EnableService f813b883dfd86c78e991ced012df6a96962059035cf6ebb1d18456f9caf97e56 DONE"
time="2019-11-10T14:26:42.560066000Z" level=debug msg="Generated spec: {\"ociVersion\":\"1.0.1-dev\",\"process\":{\"user\":{\"uid\":0,\"gid\":0},\"args\":[\"true\"],\"cwd\":\"C:\\\\\"},\"root\":{\"path\":\"\\\\\\\\?\\\\Volume{c8d2d088-e33c-4b87-9a28-1aeb6c3ad286}\\\\\"},\"hostname\":\"f813b883dfd8\",\"windows\":{\"layerFolders\":[\"C:\\\\ProgramData\\\\docker\\\\windowsfilter\\\\e280ae88fe4afde08717cb8a598cb480a554bfd79316047592f1a3899997e6f3\",\"C:\\\\ProgramData\\\\docker\\\\windowsfilter\\\\e98a4f90ea0b0b172cbc2a6520403c18c5be676fc98d967d5112940318664d8e\",\"C:\\\\ProgramData\\\\docker\\\\windowsfilter\\\\f813b883dfd86c78e991ced012df6a96962059035cf6ebb1d18456f9caf97e56\"],\"ignoreFlushesDuringBoot\":true,\"network\":{\"endpointList\":[\"7EB7BC15-4510-4225-8535-9F121F8FC438\"],\"allowUnqualifiedDNSQuery\":true}}}"
time="2019-11-10T14:26:42.561063900Z" level=debug msg="hcsshim::NameToGuid" name=e280ae88fe4afde08717cb8a598cb480a554bfd79316047592f1a3899997e6f3
time="2019-11-10T14:26:42.563067300Z" level=debug msg="hcsshim::NameToGuid - succeeded" guid=f3fa31ff-3646-5aa8-aae6-fd07fa98dc11 name=e280ae88fe4afde08717cb8a598cb480a554bfd79316047592f1a3899997e6f3
time="2019-11-10T14:26:42.563067300Z" level=debug msg="hcsshim::NameToGuid" name=e98a4f90ea0b0b172cbc2a6520403c18c5be676fc98d967d5112940318664d8e
time="2019-11-10T14:26:42.564053800Z" level=debug msg="hcsshim::NameToGuid - succeeded" guid=aee45bbb-f900-54e3-8b4a-667e447fdf14 name=e98a4f90ea0b0b172cbc2a6520403c18c5be676fc98d967d5112940318664d8e
time="2019-11-10T14:26:43.002563800Z" level=debug msg="HCS notification" notification-type=SystemCreateCompleted system-id=f813b883dfd86c78e991ced012df6a96962059035cf6ebb1d18456f9caf97e56
time="2019-11-10T14:26:43.006618600Z" level=debug msg="starting container" container=f813b883dfd86c78e991ced012df6a96962059035cf6ebb1d18456f9caf97e56 module=libcontainerd namespace=moby
time="2019-11-10T14:26:43.544852900Z" level=debug msg="HCS notification" notification-type=SystemStartCompleted system-id=f813b883dfd86c78e991ced012df6a96962059035cf6ebb1d18456f9caf97e56
time="2019-11-10T14:26:43.557728000Z" level=debug msg="createWindows() completed successfully" container=f813b883dfd86c78e991ced012df6a96962059035cf6ebb1d18456f9caf97e56 module=libcontainerd namespace=moby
time="2019-11-10T14:26:43.558726700Z" level=debug msg="start commandLine: true" container=f813b883dfd86c78e991ced012df6a96962059035cf6ebb1d18456f9caf97e56 module=libcontainerd namespace=moby
time="2019-11-10T14:26:43.558726700Z" level=info msg="sending event" container=f813b883dfd86c78e991ced012df6a96962059035cf6ebb1d18456f9caf97e56 event=create module=libcontainerd namespace=moby
time="2019-11-10T14:26:43.675323400Z" level=debug msg="Error from computeSystem.createProcess" spanID=d07181d4cec8fa36 traceID=393c3291e40931fbdb081ae09a5faac8
time="2019-11-10T14:26:43.685617500Z" level=error msg="CreateProcess() failed" container=f813b883dfd86c78e991ced012df6a96962059035cf6ebb1d18456f9caf97e56 error="container f813b883dfd86c78e991ced012df6a96962059035cf6ebb1d18456f9caf97e56 encountered an error during hcsshim::System::CreateProcessNoStdio: failure in a Windows system call: The system cannot find the file specified. (0x2) extra info: {\"CommandLine\":\"true\",\"WorkingDirectory\":\"C:\\\\\",\"CreateStdInPipe\":true,\"CreateStdOutPipe\":true,\"CreateStdErrPipe\":true,\"ConsoleSize\":[0,0]}" module=libcontainerd namespace=moby
time="2019-11-10T14:26:44.199599900Z" level=debug msg="HCS notification" notification-type=SystemExited system-id=f813b883dfd86c78e991ced012df6a96962059035cf6ebb1d18456f9caf97e56
time="2019-11-10T14:26:44.213418400Z" level=debug msg="system exited" spanID=c9af411696af0bad traceID=0544eebd1705053ad568cd6c9524589d
time="2019-11-10T14:26:44.214414900Z" level=debug msg="completed container shutdown" container=f813b883dfd86c78e991ced012df6a96962059035cf6ebb1d18456f9caf97e56 module=libcontainerd namespace=moby
time="2019-11-10T14:26:44.220419400Z" level=debug msg="attach: stdout: end"
time="2019-11-10T14:26:44.221417000Z" level=debug msg="attach: stderr: end"
time="2019-11-10T14:26:44.223417100Z" level=debug msg="attach done"
time="2019-11-10T14:26:44.256649700Z" level=debug msg="Revoking external connectivity on endpoint gifted_hugle (dd9ab8e3a09ae75da961c66251ed422c5b8de594407f68956a45de50007d5d63)"
time="2019-11-10T14:26:44.259323700Z" level=debug msg="[GET]=>[/endpoints/7EB7BC15-4510-4225-8535-9F121F8FC438] Request : "
time="2019-11-10T14:26:44.272540200Z" level=debug msg="Network Response : {\"ActivityId\":\"9AC791A8-64D1-472F-8747-416171579605\",\"AdditionalParams\":{},\"CreateProcessingStartTime\":132178696023852504,\"DNSServerList\":\"172.25.144.1,172.31.0.2\",\"DNSSuffix\":\"us-east-2.compute.internal\",\"EnableInternalDNS\":true,\"EnableLowInterfaceMetric\":true,\"EncapOverhead\":0,\"GatewayAddress\":\"172.25.144.1\",\"Health\":{\"LastErrorCode\":0,\"LastUpdateTime\":132178696023822506},\"ID\":\"7EB7BC15-4510-4225-8535-9F121F8FC438\",\"IPAddress\":\"172.25.145.155\",\"MacAddress\":\"00-15-5D-AB-58-C6\",\"Name\":\"Ethernet\",\"Policies\":[],\"PrefixLength\":20,\"RemoveProcessingStartTime\":132178696040589953,\"Resources\":{\"AdditionalParams\":{},\"AllocationOrder\":2,\"Allocators\":[],\"Health\":{\"LastErrorCode\":0,\"LastUpdateTime\":132178696023822506},\"ID\":\"9AC791A8-64D1-472F-8747-416171579605\",\"PortOperationTime\":0,\"State\":1,\"SwitchOperationTime\":0,\"VfpOperationTime\":0,\"parentId\":\"1916DAC2-1ECB-4BAD-9866-F53855E60234\"},\"SharedContainers\":[],\"StartTime\":132178696029980910,\"State\":4,\"Type\":\"nat\",\"Version\":38654705666,\"VirtualNetwork\":\"5C242C1E-8E0F-4F65-B9E0-A0B7A6EA41E2\",\"VirtualNetworkName\":\"nat\"}"
time="2019-11-10T14:26:44.277533600Z" level=debug msg="[GET]=>[/endpoints/7EB7BC15-4510-4225-8535-9F121F8FC438] Request : "
time="2019-11-10T14:26:44.285496600Z" level=debug msg="Network Response : {\"ActivityId\":\"9AC791A8-64D1-472F-8747-416171579605\",\"AdditionalParams\":{},\"CreateProcessingStartTime\":132178696023852504,\"DNSServerList\":\"172.25.144.1,172.31.0.2\",\"DNSSuffix\":\"us-east-2.compute.internal\",\"EnableInternalDNS\":true,\"EnableLowInterfaceMetric\":true,\"EncapOverhead\":0,\"GatewayAddress\":\"172.25.144.1\",\"Health\":{\"LastErrorCode\":0,\"LastUpdateTime\":132178696023822506},\"ID\":\"7EB7BC15-4510-4225-8535-9F121F8FC438\",\"IPAddress\":\"172.25.145.155\",\"MacAddress\":\"00-15-5D-AB-58-C6\",\"Name\":\"Ethernet\",\"Policies\":[],\"PrefixLength\":20,\"RemoveProcessingStartTime\":132178696040589953,\"Resources\":{\"AdditionalParams\":{},\"AllocationOrder\":2,\"Allocators\":[],\"Health\":{\"LastErrorCode\":0,\"LastUpdateTime\":132178696023822506},\"ID\":\"9AC791A8-64D1-472F-8747-416171579605\",\"PortOperationTime\":0,\"State\":1,\"SwitchOperationTime\":0,\"VfpOperationTime\":0,\"parentId\":\"1916DAC2-1ECB-4BAD-9866-F53855E60234\"},\"SharedContainers\":[],\"StartTime\":132178696029980910,\"State\":4,\"Type\":\"nat\",\"Version\":38654705666,\"VirtualNetwork\":\"5C242C1E-8E0F-4F65-B9E0-A0B7A6EA41E2\",\"VirtualNetworkName\":\"nat\"}"
time="2019-11-10T14:26:44.317715500Z" level=debug msg="[DELETE]=>[/endpoints/7EB7BC15-4510-4225-8535-9F121F8FC438] Request : "
time="2019-11-10T14:26:44.336295400Z" level=debug msg="Releasing addresses for endpoint gifted_hugle's interface on network nat"
time="2019-11-10T14:26:44.336295400Z" level=debug msg="ReleaseAddress(172.25.144.0/20, 172.25.145.155)"
time="2019-11-10T14:26:44.356768600Z" level=debug msg="WindowsGraphDriver Put() id f813b883dfd86c78e991ced012df6a96962059035cf6ebb1d18456f9caf97e56"
time="2019-11-10T14:26:44.357737200Z" level=debug msg="hcsshim::UnprepareLayer" path="C:\\ProgramData\\docker\\windowsfilter\\f813b883dfd86c78e991ced012df6a96962059035cf6ebb1d18456f9caf97e56"
time="2019-11-10T14:26:44.364825500Z" level=debug msg="hcsshim::UnprepareLayer - succeeded" path="C:\\ProgramData\\docker\\windowsfilter\\f813b883dfd86c78e991ced012df6a96962059035cf6ebb1d18456f9caf97e56"
time="2019-11-10T14:26:44.368849500Z" level=debug msg="hcsshim::DeactivateLayer" path="C:\\ProgramData\\docker\\windowsfilter\\f813b883dfd86c78e991ced012df6a96962059035cf6ebb1d18456f9caf97e56"
time="2019-11-10T14:26:44.450396900Z" level=debug msg="hcsshim::DeactivateLayer - succeeded" path="C:\\ProgramData\\docker\\windowsfilter\\f813b883dfd86c78e991ced012df6a96962059035cf6ebb1d18456f9caf97e56"
time="2019-11-10T14:26:44.457642700Z" level=error msg="f813b883dfd86c78e991ced012df6a96962059035cf6ebb1d18456f9caf97e56 cleanup: failed to delete container from containerd: no such container"
time="2019-11-10T14:26:44.466643900Z" level=debug msg="hcsshim::DestroyLayer" path="C:\\ProgramData\\docker\\windowsfilter\\f813b883dfd86c78e991ced012df6a96962059035cf6ebb1d18456f9caf97e56-removing"
time="2019-11-10T14:26:44.469642800Z" level=debug msg="hcsshim::DestroyLayer - succeeded" path="C:\\ProgramData\\docker\\windowsfilter\\f813b883dfd86c78e991ced012df6a96962059035cf6ebb1d18456f9caf97e56-removing"

The failure seems to come from computeSystem.createProcess [https://github.com/microsoft/hcsshim/blob/32862ca3495e8a6925d167ec163b43563cb75971/internal/hcs/system.go#L461]

Also, is there a way for us to gather traces from vmcompute so they could be shared with you in the future as well.

@vikramhh

This comment has been minimized.

Copy link
Author

vikramhh commented Nov 12, 2019

The above issue was a false positive and we were able to move on and get a repro of the original issue [0x490]. Issue was reproed with tracing enabled - @kevpar is taking a look.

@kevpar

This comment has been minimized.

Copy link
Contributor

kevpar commented Nov 12, 2019

@thaJeztah I'm on the Docker Community Slack. Is there a specific channel I should make sure I'm on?

@vikramhh It looks like the "Element not found" error can occur when running a container that exits immediately. There is a race condition that can cause Docker to still try to query for things like the stdio handles after the container has already exited and been cleaned up. I need to investigate further to determine what has changed to cause this.

@thaJeztah

This comment has been minimized.

Copy link
Member

thaJeztah commented Nov 12, 2019

I can add you both to the maintainers channel, which would give a more "quiet" channel to discuss if needed

@vikramhh vikramhh force-pushed the vikramhh:bump_hcsshim branch from b08093e to 60c194d Nov 15, 2019
@vikramhh vikramhh changed the title Bump hcsshim to 6c7177eae8be632af2e15e44b62d69ab18389ddb Bump hcsshim to b3f49c06ffaeef24d09c6c08ec8ec8425a0303e2 Nov 15, 2019
@vikramhh

This comment has been minimized.

Copy link
Author

vikramhh commented Nov 15, 2019

Changed the title to reflect the fact that we had to bump hcsshim further to take in microsoft/hcsshim#737

@thaJeztah

This comment has been minimized.

Copy link
Member

thaJeztah commented Nov 15, 2019

Looks like you may have to run vndr again;

[2019-11-15T22:42:52.013Z] The result of vndr differs
[2019-11-15T22:42:52.013Z] 
[2019-11-15T22:42:52.013Z]  D vendor/github.com/containerd/cgroups/stats/v1/metrics.pb.txt
[2019-11-15T22:42:52.013Z]  M vendor/github.com/containerd/cgroups/stats/v1/metrics.proto
[2019-11-15T22:42:52.013Z] 
[2019-11-15T22:42:52.013Z] Please vendor your package with github.com/LK4D4/vndr.
[2019-11-15T22:42:52.013Z] 
[2019-11-15T22:42:52.013Z] diff --git a/vendor/github.com/containerd/cgroups/stats/v1/metrics.proto b/ve
[2019-11-15T22:42:52.013Z] ndor/github.com/containerd/cgroups/stats/v1/metrics.proto
[2019-11-15T22:42:52.013Z] index e821e8407..ba6be851d 100644
[2019-11-15T22:42:52.013Z] --- a/vendor/github.com/containerd/cgroups/stats/v1/metrics.proto
[2019-11-15T22:42:52.013Z] +++ b/vendor/github.com/containerd/cgroups/stats/v1/metrics.proto
[2019-11-15T22:42:52.013Z] @@ -135,6 +135,7 @@ message NetworkStat {
[2019-11-15T22:42:52.013Z]  	uint64 tx_errors = 8;
[2019-11-15T22:42:52.013Z]  	uint64 tx_dropped = 9;
[2019-11-15T22:42:52.013Z]  }
[2019-11-15T22:42:52.013Z] +
[2019-11-15T22:42:52.013Z]  // CgroupStats exports per-cgroup statistics.
[2019-11-15T22:42:52.013Z]  message CgroupStats {
[2019-11-15T22:42:52.013Z]  	// number of tasks sleeping
Among other things, this is required to pull in
microsoft/hcsshim#718 which should
take care of multiple issues reported to us.

Also fixes microsoft/hcsshim#737
which was caught by checks while attempting to bump
up hcsshim version.

Signed-off-by: Vikram bir Singh <vikrambir.singh@docker.com>
@vikramhh vikramhh force-pushed the vikramhh:bump_hcsshim branch from 60c194d to 6658957 Nov 16, 2019
@vikramhh

This comment has been minimized.

Copy link
Author

vikramhh commented Nov 16, 2019

@thaJeztah - would you recommend running RS1 tests as well for this?

@thaJeztah

This comment has been minimized.

Copy link
Member

thaJeztah commented Nov 16, 2019

restarted CI with RS1 enabled as well

@vikramhh

This comment has been minimized.

Copy link
Author

vikramhh commented Nov 18, 2019

@thaJeztah - the RS1 failures seem to be known flaky tests mentioned in #39885 - does this look good to go otherwise?

@thaJeztah

This comment has been minimized.

Copy link
Member

thaJeztah commented Nov 18, 2019

Yes, if it's ready for review, feel free to move it out of draft

@vikramhh vikramhh marked this pull request as ready for review Nov 18, 2019
Copy link
Member

thaJeztah left a comment

LGTM

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
4 participants
You can’t perform that action at this time.