TestContainerd/GvisorRestart: [kubelet-check] timeout / failed to create containerd container: error unpacking image: content digest not found

[tstromberg]

Mentioned in #5133 - and seen at head.

[tstromberg]

Repeatable by:

kubelet is running, but apiserver isn't.

==> container status <==
CONTAINER           IMAGE               CREATED             STATE               NAME                 ATTEMPT             POD ID
ac3898ed13a60       119701e77cbc4       4 minutes ago       Running             kube-addon-manager   0                   4702533dea5fa
8d5df786c469b       2c4adeb21b4ff       4 minutes ago       Running             etcd                 0                   fb446bd05bffc

...
==> containerd <==
-- Logs begin at Sat 2019-08-24 20:53:10 UTC, end at Sat 2019-08-24 20:57:59 UTC. --
Aug 24 20:57:29 minikube containerd[1914]: time="2019-08-24T20:57:29.469131816Z" level=info msg="ExecSync for "8d5df786c469b6fb9ec64a1f7b013542de8e6ac96f6d9a477829bd8a47c41a20" with command [/bin/sh -ec ETCDCTL_API=3 etcdctl --endpoints=https://[127.0.0.1]:2379 --cacert=/var/lib/minikube/certs/etcd/ca.crt --cert=/var/lib/minikube/certs/etcd/healthcheck-client.crt --key=/var/lib/minikube/certs/etcd/healthcheck-client.key get foo] and timeout 15 (s)"
Aug 24 20:57:29 minikube containerd[1914]: time="2019-08-24T20:57:29.540479023Z" level=info msg="Exec process "dd015d4a249ee675eb3c71275cc682c0505d4c14b57227b6e17492b656df2926" exits with exit code 0 and error <nil>"
Aug 24 20:57:29 minikube containerd[1914]: time="2019-08-24T20:57:29.540484315Z" level=info msg="Finish piping "stderr" of container exec "dd015d4a249ee675eb3c71275cc682c0505d4c14b57227b6e17492b656df2926""
Aug 24 20:57:29 minikube containerd[1914]: time="2019-08-24T20:57:29.540497991Z" level=info msg="Finish piping "stdout" of container exec "dd015d4a249ee675eb3c71275cc682c0505d4c14b57227b6e17492b656df2926""
Aug 24 20:57:29 minikube containerd[1914]: time="2019-08-24T20:57:29.561358257Z" level=info msg="TaskExit event &TaskExit{ContainerID:8d5df786c469b6fb9ec64a1f7b013542de8e6ac96f6d9a477829bd8a47c41a20,ID:dd015d4a249ee675eb3c71275cc682c0505d4c14b57227b6e17492b656df2926,Pid:8239,ExitStatus:0,ExitedAt:2019-08-24 20:57:29.540281312 +0000 UTC,}"
Aug 24 20:57:29 minikube containerd[1914]: time="2019-08-24T20:57:29.571508963Z" level=info msg="ExecSync for "8d5df786c469b6fb9ec64a1f7b013542de8e6ac96f6d9a477829bd8a47c41a20" returns with exit code 0"
Aug 24 20:57:36 minikube containerd[1914]: time="2019-08-24T20:57:36.777914916Z" level=info msg="CreateContainer within sandbox "e4daf4bb9e8f888813ae9eb26b2172f29aa91f6d94f8cbb0c07e6584610fef04" for container &ContainerMetadata{Name:kube-scheduler,Attempt:0,}"
Aug 24 20:57:36 minikube containerd[1914]: time="2019-08-24T20:57:36.782034418Z" level=info msg="CreateContainer within sandbox "d2c12aa277bd2f69e3066aa51540d66f9b87b38d7669320a4f25fd6b690b6a52" for container &ContainerMetadata{Name:kube-controller-manager,Attempt:0,}"
Aug 24 20:57:36 minikube containerd[1914]: time="2019-08-24T20:57:36.807656578Z" level=error msg="CreateContainer within sandbox "d2c12aa277bd2f69e3066aa51540d66f9b87b38d7669320a4f25fd6b690b6a52" for &ContainerMetadata{Name:kube-controller-manager,Attempt:0,} failed" error="failed to create containerd container: error unpacking image: content digest sha256:3acd8d48d9dfa76e4c08c87a363ffbe9c29fa176ad73770bbb6e534f9d63c627: not found"
Aug 24 20:57:36 minikube containerd[1914]: time="2019-08-24T20:57:36.809887499Z" level=error msg="CreateContainer within sandbox "e4daf4bb9e8f888813ae9eb26b2172f29aa91f6d94f8cbb0c07e6584610fef04" for &ContainerMetadata{Name:kube-scheduler,Attempt:0,} failed" error="failed to create containerd container: error unpacking image: content digest sha256:0a3cb3151c7d08aaa907dd498609b37b7e1c64c91417989f5255a95769194b60: not found"
Aug 24 20:57:39 minikube containerd[1914]: time="2019-08-24T20:57:39.469005751Z" level=info msg="ExecSync for "8d5df786c469b6fb9ec64a1f7b013542de8e6ac96f6d9a477829bd8a47c41a20" with command [/bin/sh -ec ETCDCTL_API=3 etcdctl --endpoints=https://[127.0.0.1]:2379 --cacert=/var/lib/minikube/certs/etcd/ca.crt --cert=/var/lib/minikube/certs/etcd/healthcheck-client.crt --key=/var/lib/minikube/certs/etcd/healthcheck-client.key get foo] and timeout 15 (s)"
Aug 24 20:57:39 minikube containerd[1914]: time="2019-08-24T20:57:39.546468057Z" level=info msg="Finish piping "stderr" of container exec "6a81cc6ae77d4efaf55be1114d1ac451d3acba4fe900516723fd4f0224102e38""
Aug 24 20:57:39 minikube containerd[1914]: time="2019-08-24T20:57:39.546674104Z" level=info msg="Finish piping "stdout" of container exec "6a81cc6ae77d4efaf55be1114d1ac451d3acba4fe900516723fd4f0224102e38""
Aug 24 20:57:39 minikube containerd[1914]: time="2019-08-24T20:57:39.547248246Z" level=info msg="Exec process "6a81cc6ae77d4efaf55be1114d1ac451d3acba4fe900516723fd4f0224102e38" exits with exit code 0 and error <nil>"
Aug 24 20:57:39 minikube containerd[1914]: time="2019-08-24T20:57:39.572266548Z" level=info msg="TaskExit event &TaskExit{ContainerID:8d5df786c469b6fb9ec64a1f7b013542de8e6ac96f6d9a477829bd8a47c41a20,ID:6a81cc6ae77d4efaf55be1114d1ac451d3acba4fe900516723fd4f0224102e38,Pid:8480,ExitStatus:0,ExitedAt:2019-08-24 20:57:39.546984465 +0000 UTC,}"
Aug 24 20:57:39 minikube containerd[1914]: time="2019-08-24T20:57:39.584735305Z" level=info msg="ExecSync for "8d5df786c469b6fb9ec64a1f7b013542de8e6ac96f6d9a477829bd8a47c41a20" returns with exit code 0"
Aug 24 20:57:39 minikube containerd[1914]: time="2019-08-24T20:57:39.771236132Z" level=info msg="CreateContainer within sandbox "4ecd81da1da6ccf107aa39a1e2cfcac8eff6c5d0ca4239ebb877bec088f56570" for container &ContainerMetadata{Name:kube-apiserver,Attempt:0,}"
Aug 24 20:57:39 minikube containerd[1914]: time="2019-08-24T20:57:39.787350503Z" level=error msg="CreateContainer within sandbox "4ecd81da1da6ccf107aa39a1e2cfcac8eff6c5d0ca4239ebb877bec088f56570" for &ContainerMetadata{Name:kube-apiserver,Attempt:0,} failed" error="failed to create containerd container: error unpacking image: content digest sha256:3156e9a2eb83ed0b8a2a10323f2ce56abc37e7be95db4fb800f74c9237a9bee4: not found"
Aug 24 20:57:49 minikube containerd[1914]: time="2019-08-24T20:57:49.469197084Z" level=info msg="ExecSync for "8d5df786c469b6fb9ec64a1f7b013542de8e6ac96f6d9a477829bd8a47c41a20" with command [/bin/sh -ec ETCDCTL_API=3 etcdctl --endpoints=https://[127.0.0.1]:2379 --cacert=/var/lib/minikube/certs/etcd/ca.crt --cert=/var/lib/minikube/certs/etcd/healthcheck-client.crt --key=/var/lib/minikube/certs/etcd/healthcheck-client.key get foo] and timeout 15 (s)"
Aug 24 20:57:49 minikube containerd[1914]: time="2019-08-24T20:57:49.544967981Z" level=info msg="Finish piping "stdout" of container exec "a5005a584236f4560a055753e695d8418d85cbf7ffb4de010622e0c0801d6ed7""
Aug 24 20:57:49 minikube containerd[1914]: time="2019-08-24T20:57:49.545189327Z" level=info msg="Finish piping "stderr" of container exec "a5005a584236f4560a055753e695d8418d85cbf7ffb4de010622e0c0801d6ed7""
Aug 24 20:57:49 minikube containerd[1914]: time="2019-08-24T20:57:49.545636726Z" level=info msg="Exec process "a5005a584236f4560a055753e695d8418d85cbf7ffb4de010622e0c0801d6ed7" exits with exit code 0 and error <nil>"
Aug 24 20:57:49 minikube containerd[1914]: time="2019-08-24T20:57:49.574214067Z" level=info msg="TaskExit event &TaskExit{ContainerID:8d5df786c469b6fb9ec64a1f7b013542de8e6ac96f6d9a477829bd8a47c41a20,ID:a5005a584236f4560a055753e695d8418d85cbf7ffb4de010622e0c0801d6ed7,Pid:8786,ExitStatus:0,ExitedAt:2019-08-24 20:57:49.545485604 +0000 UTC,}"
Aug 24 20:57:49 minikube containerd[1914]: time="2019-08-24T20:57:49.581541964Z" level=info msg="ExecSync for "8d5df786c469b6fb9ec64a1f7b013542de8e6ac96f6d9a477829bd8a47c41a20" returns with exit code 0"
Aug 24 20:57:49 minikube containerd[1914]: time="2019-08-24T20:57:49.770409988Z" level=info msg="CreateContainer within sandbox "e4daf4bb9e8f888813ae9eb26b2172f29aa91f6d94f8cbb0c07e6584610fef04" for container &ContainerMetadata{Name:kube-scheduler,Attempt:0,}"
Aug 24 20:57:49 minikube containerd[1914]: time="2019-08-24T20:57:49.783508350Z" level=error msg="CreateContainer within sandbox "e4daf4bb9e8f888813ae9eb26b2172f29aa91f6d94f8cbb0c07e6584610fef04" for &ContainerMetadata{Name:kube-scheduler,Attempt:0,} failed" error="failed to create containerd container: error unpacking image: content digest sha256:0a3cb3151c7d08aaa907dd498609b37b7e1c64c91417989f5255a95769194b60: not found"
Aug 24 20:57:51 minikube containerd[1914]: time="2019-08-24T20:57:51.772253729Z" level=info msg="CreateContainer within sandbox "d2c12aa277bd2f69e3066aa51540d66f9b87b38d7669320a4f25fd6b690b6a52" for container &ContainerMetadata{Name:kube-controller-manager,Attempt:0,}"
Aug 24 20:57:51 minikube containerd[1914]: time="2019-08-24T20:57:51.791438149Z" level=error msg="CreateContainer within sandbox "d2c12aa277bd2f69e3066aa51540d66f9b87b38d7669320a4f25fd6b690b6a52" for &ContainerMetadata{Name:kube-controller-manager,Attempt:0,} failed" error="failed to create containerd container: error unpacking image: content digest sha256:3acd8d48d9dfa76e4c08c87a363ffbe9c29fa176ad73770bbb6e534f9d63c627: not found"
Aug 24 20:57:53 minikube containerd[1914]: time="2019-08-24T20:57:53.772367178Z" level=info msg="CreateContainer within sandbox "4ecd81da1da6ccf107aa39a1e2cfcac8eff6c5d0ca4239ebb877bec088f56570" for container &ContainerMetadata{Name:kube-apiserver,Attempt:0,}"
Aug 24 20:57:53 minikube containerd[1914]: time="2019-08-24T20:57:53.797518950Z" level=error msg="CreateContainer within sandbox "4ecd81da1da6ccf107aa39a1e2cfcac8eff6c5d0ca4239ebb877bec088f56570" for &ContainerMetadata{Name:kube-apiserver,Attempt:0,} failed" error="failed to create containerd container: error unpacking image: content digest sha256:3156e9a2eb83ed0b8a2a10323f2ce56abc37e7be95db4fb800f74c9237a9bee4: not found"
...
==> kubelet <==
-- Logs begin at Sat 2019-08-24 20:53:10 UTC, end at Sat 2019-08-24 20:57:59 UTC. --
Aug 24 20:57:57 minikube kubelet[2420]: E0824 20:57:57.045201    2420 kubelet.go:2248] node "minikube" not found
Aug 24 20:57:57 minikube kubelet[2420]: E0824 20:57:57.067937    2420 reflector.go:125] k8s.io/client-go/informers/factory.go:133: Failed to list *v1beta1.CSIDriver: Get https://localhost:8443/apis/storage.k8s.io/v1beta1/csidrivers?limit=500&resourceVersion=0: dial tcp 127.0.0.1:8443: connect: connection refused

[tstromberg]

This may be a red herring, but the interesting message to me is:

Aug 24 20:53:53 minikube containerd[1914]: time="2019-08-24T20:53:53.435458775Z" level=error msg="CreateContainer within sandbox "4ecd81da1da6ccf107aa39a1e2cfcac8eff6c5d0ca4239ebb877bec088f56570" for &ContainerMetadata{Name:kube-apiserver,Attempt:0,} failed" error="failed to create containerd container: error unpacking image: content digest sha256:3156e9a2eb83ed0b8a2a10323f2ce56abc37e7be95db4fb800f74c9237a9bee4: not found"

[tstromberg]

Apparently, the image appears with a different hash:

Aug 24 20:53:38 minikube containerd[1914]: time="2019-08-24T20:53:38.056556522Z" level=info msg="PullImage "k8s.gcr.io/kube-apiserver:v1.15.2" returns image reference "sha256:34a53be6c9a7e3ae37d8f26065157627edeee97e5d1bab880a78b9a9d8f0bcf1""

$ sudo crictl images | grep apiserver
k8s.gcr.io/kube-apiserver                 v1.15.2             34a53be6c9a7e       49.3MB

[afbjorklund]

I wonder if this bug is related: containerd/containerd#3401 ?

It is about containerd image cache keeping references to old garbage collected blobs...

[afbjorklund]

Not sure if we can update containerd, without docker being sad about it ?

containerd github.com/containerd/containerd v1.2.6 894b81a4b802e4eb2a91d1ce216b8817763c29fb

runc version 1.0.0-rc8
commit: 425e105d5a03fabd737a126ad93d62a9eeede87f

Anyway, if it is indeed the fix above then it is included in containerd v1.2.8

containerd/containerd@941dd9f

containerd/cri@fe0cb22

[ianlewis]

Upgrading to 1.2.8 seemed to fix the issue and seemed to work fine when using docker as a runtime when I tested locally. #5194