Docker Community Forums

Share and learn in the Docker community.

Docker source code walk through

Hi All

I have used Docker with K8s to deploy my workloads on small scale cluster. What I have noticed is when K8s deploys a new pod; it firsts creates sandbox container as part of a pod. Once Sandbox container is ready than it asks Docker to pull container image user has specified. When docker first get message to pull container it prints message 1 in logs snippet below; before it starts pulling image it does bunch of HTTP calls and almost 3 seconds later actually starts pulling the docker image as seen in log message 14. Since 3 seconds is huge compare to 10`s of microsecond typical go function spent executing. I want to figure out what is happening in these 3 seconds.

 1) May 07 13:23:13T HOST215 dockerd[236863]: time="2019-05-07T13:23:13.470382988-07:00" level=debug msg="Trying to pull centos from https://registry-1.docker.io v2"
 2) May 07 13:23:13T HOST215 dockerd[236863]: time="2019-05-07T13:23:13.533394060-07:00" level=debug msg="Calling GET /v1.38/containers/json?all=1&filters=%7B%22label%22%3A%7B%22io.kubernetes.docker.type%3Dpodsandbox%22%3Atrue%7D%7D&limit=0"
 3) May 07 13:23:13T HOST215 dockerd[236863]: time="2019-05-07T13:23:13.539019135-07:00" level=debug msg="Calling GET /v1.38/containers/json?all=1&filters=%7B%22label%22%3A%7B%22io.kubernetes.docker.type%3Dcontainer%22%3Atrue%7D%7D&limit=0"
 4) May 07 13:23:13T HOST215 dockerd[236863]: time="2019-05-07T13:23:13.542900893-07:00" level=debug msg="Calling GET /v1.38/containers/json?all=1&filters=%7B%22label%22%3A%7B%22io.kubernetes.docker.type%3Dpodsandbox%22%3Atrue%2C%22io.kubernetes.pod.uid%3Deff90de1-7105-11e9-b320-a4bf014bcf99%22%3Atrue%7D%7D&limit=0"
 5) May 07 13:23:13T HOST215 dockerd[236863]: time="2019-05-07T13:23:13.544960424-07:00" level=debug msg="Calling GET /v1.38/containers/05e7cb3d1efdb6105e030712f18d358a96062a72ec241c26a91b03c2d5a38154/json"
 6) May 07 13:23:13T HOST215 dockerd[236863]: time="2019-05-07T13:23:13.546231371-07:00" level=debug msg="Calling GET /v1.38/containers/05e7cb3d1efdb6105e030712f18d358a96062a72ec241c26a91b03c2d5a38154/json"
 7) May 07 13:23:13T HOST215 dockerd[236863]: time="2019-05-07T13:23:13.553221377-07:00" level=debug msg="Calling GET /v1.38/containers/json?all=1&filters=%7B%22label%22%3A%7B%22io.kubernetes.docker.type%3Dcontainer%22%3Atrue%2C%22io.kubernetes.pod.uid%3Deff90de1-7105-11e9-b320-a4bf014bcf99%22%3Atrue%7D%7D&limit=0"
 8) May 07 13:23:14T HOST215 dockerd[236863]: time="2019-05-07T13:23:14.300443613-07:00" level=debug msg="Calling GET /v1.38/containers/json?filters=%7B%22label%22%3A%7B%22io.kubernetes.docker.type%3Dpodsandbox%22%3Atrue%7D%7D&limit=0"
 9) May 07 13:23:14T HOST215 dockerd[236863]: time="2019-05-07T13:23:14.306325116-07:00" level=debug msg="Calling GET /v1.38/containers/json?all=1&filters=%7B%22label%22%3A%7B%22io.kubernetes.docker.type%3Dcontainer%22%3Atrue%7D%2C%22status%22%3A%7B%22running%22%3Atrue%7D%7D&limit=0"
10) May 07 13:23:14T HOST215 dockerd[236863]: time="2019-05-07T13:23:14.555374722-07:00" level=debug msg="Calling GET /v1.38/containers/json?all=1&filters=%7B%22label%22%3A%7B%22io.kubernetes.docker.type%3Dpodsandbox%22%3Atrue%7D%7D&limit=0"
11) May 07 13:23:14T HOST215 dockerd[236863]: time="2019-05-07T13:23:14.561243955-07:00" level=debug msg="Calling GET /v1.38/containers/json?all=1&filters=%7B%22label%22%3A%7B%22io.kubernetes.docker.type%3Dcontainer%22%3Atrue%7D%7D&limit=0"
12) May 07 13:23:15T HOST215 dockerd[236863]: time="2019-05-07T13:23:15.566067938-07:00" level=debug msg="Calling GET /v1.38/containers/json?all=1&filters=%7B%22label%22%3A%7B%22io.kubernetes.docker.type%3Dpodsandbox%22%3Atrue%7D%7D&limit=0"
13) May 07 13:23:15T HOST215 dockerd[236863]: time="2019-05-07T13:23:15.572037981-07:00" level=debug msg="Calling GET /v1.38/containers/json?all=1&filters=%7B%22label%22%3A%7B%22io.kubernetes.docker.type%3Dcontainer%22%3Atrue%7D%7D&limit=0"
14) May 07 13:23:16T HOST215 dockerd[236863]: time="2019-05-07T13:23:16.275032672-07:00" level=debug msg="Pulling ref from V2 registry: centos:latest"
15) May 07 13:23:16T HOST215 dockerd[236863]: time="2019-05-07T13:23:16.275113897-07:00" level=debug msg="docker.io/library/centos:latest resolved to a manifestList object with 5 entries; looking for a unknown/amd64 match"
16) May 07 13:23:16T HOST215 dockerd[236863]: time="2019-05-07T13:23:16.275158124-07:00" level=debug msg="found match for linux/amd64 with media type application/vnd.docker.distribution.manifest.v2+json, digest sha256:ca58fe458b8d94bc6e3072f1cfbd334855858e05e1fd633aa07cf7f82b048e66"
17) May 07 13:23:16T HOST215 dockerd[236863]: time="2019-05-07T13:23:16.299948758-07:00" level=debug msg="Calling GET /v1.38/containers/json?filters=%7B%22label%22%3A%7B%22io.kubernetes.docker.type%3Dpodsandbox%22%3Atrue%7D%7D&limit=0"
18) May 07 13:23:16T HOST215 dockerd[236863]: time="2019-05-07T13:23:16.305673333-07:00" level=debug msg="Calling GET /v1.38/containers/json?all=1&filters=%7B%22label%22%3A%7B%22io.kubernetes.docker.type%3Dcontainer%22%3Atrue%7D%2C%22status%22%3A%7B%22running%22%3Atrue%7D%7D&limit=0"
19) May 07 13:23:16T HOST215 dockerd[236863]: time="2019-05-07T13:23:16.309405996-07:00" level=debug msg="Calling GET /v1.38/containers/json?filters=%7B%22label%22%3A%7B%22io.kubernetes.docker.type%3Dpodsandbox%22%3Atrue%7D%7D&limit=0"
20) May 07 13:23:16T HOST215 dockerd[236863]: time="2019-05-07T13:23:16.315129131-07:00" level=debug msg="Calling GET /v1.38/containers/json?all=1&filters=%7B%22label%22%3A%7B%22io.kubernetes.docker.type%3Dcontainer%22%3Atrue%7D%2C%22status%22%3A%7B%22running%22%3Atrue%7D%7D&limit=0"
21) May 07 13:23:16T HOST215 dockerd[236863]: time="2019-05-07T13:23:16.576681711-07:00" level=debug msg="Calling GET /v1.38/containers/json?all=1&filters=%7B%22label%22%3A%7B%22io.kubernetes.docker.type%3Dpodsandbox%22%3Atrue%7D%7D&limit=0"
22) May 07 13:23:16T HOST215 dockerd[236863]: time="2019-05-07T13:23:16.582512131-07:00" level=debug msg="Calling GET /v1.38/containers/json?all=1&filters=%7B%22label%22%3A%7B%22io.kubernetes.docker.type%3Dcontainer%22%3Atrue%7D%7D&limit=0"

I followed docker source code between log message1 and 14; and found that Docker first tries to ping registry and pull tags during these 3 seconds but surprisingly all of http GET requests are made to sandbox container launched as part of pod initialization. (all requests are going to /v1.38/containers/*)

Why docker is pinging and pulling tags from sandbox containers? it is not pinging docker registry where centos image is located; can you help me understand so what tasks are being performed here?

beyond source code printing message 14; it tries to find centos image and eventually finds it within local storage.