It looks like there is a container with name web_apps-abcd-6b6cb5876b-nn9md_default_3dc00fd6-0c5d-42be-bec8-e4f6cad616da_0 and id 8b21a9870e3ecc09bbb92da2036bd3c9b35f5829873d80cfbd14dc1e1827923f in containerd. While kubelet want to create to a new one with name web_apps-abcd-6b6cb5876b-nn9md_default_3dc00fd6-0c5d-42be-bec8-e4f6cad616da_0, cri plugin failed on it.

Could you show docker ps -a or ctr c list

Did you manage to resolve this issue @sadortun? We are experiencing the same. Also on GKE with containerd runtime.

  Normal   Scheduled  2m21s               default-scheduler  Successfully assigned ***-77c979f8bf-px4v9 to gke-***-389a7e33-t1hl
  Warning  Failed     20s                 kubelet            Error: context deadline exceeded
  Normal   Pulled     7s (x3 over 2m20s)  kubelet            Container image "***" already present on machine
  Warning  Failed     7s (x2 over 19s)    kubelet            Error: failed to reserve container name ***-77c979f8bf-px4v9_***": name "***-77c979f8bf-px4v9_***" is reserved for "818fcfef09165d91ac8c86ed88714bb159a8358c3eca473ec07611a51d72b140"

We are deploying the same image to multiple deployments (30 - 40 pods) at the same time. No such issues with docker runtime.

Eventually, kubelet is able to resolve this issue without manual intervention, however, it is significantly slowing the deployment of new images during the release (extra 2-3 minutes to resolve name conflicts).

Hi @pfuhrmann

We did investigate this quite deeply with GKE Dev team and we were not able to reproduce it.

That said, We are pretty convince the issue comes from one of the two following issue:

• Disk IO is to high and containerd timeout because of that
• Starting 10-20+ pods at the same time on a single node cause a memory usage spike and at some point containerd process get killed.

Unfortunately after a month of back and forth with GKE devs, we were not able to find the solution.

The good new is, for us, we refactored our application and were able to reduce the number of starting pods from about 20, down to 5. Since then, we had no issues.

You might also want to increase node boot drive size. It seems to help too.

any update on this? did anybody manage to solve this? we are facing the same issue

We are also seeing the same issue, GKE with containerd. It does seem to be correlated with starting many pods at once.

Switching from cos_containerd back to cos (docker based) seems to have resolved the situation, at least in the short term.

We are also seeing the same issue, GKE with containerd. It does seem to be correlated with starting many pods at once.

Switching from cos_containerd back to cos (docker based) seems to have resolved the situation, at least in the short term.

Same for us once we switched back to cos with docker everything worked

Same for us once we switched back to cos with docker everything worked.

At the end we still had occasional issues and We also had to switch back to cos

jotting down some notes here, apologies if it's lengthy:

Let me try to explain/figure out the reason you got "failed to reserve container name" ..

Kubelet tried to create a container that it had already asked containerd to create at least once.. when containerd tried the first time it received a variable in the container create meta data named attempt and that variable held the default value 0 .. then containerd reserved the unique name for attempt 0 that you see in your log (see _0 at end of name) "web_apps-abcd-6b6cb5876b-nn9md_default_3dc00fd6-0c5d-42be-bec8-e4f6cad616da_0"... something happened causing a context timeout between kubelet and containerd .. the kubelet context timeout value is configurable.. "--runtime-request-timeout duration Default: 2m0s" a 2min timeout could happen for any number of reasons.. an unusually long garbage collection a file system hiccup, locked files, deadlocks while waiting, some very expensive init operation occurring in the node for one of your other containers.. who knows? That's why we have/need recovery procedures.

What should have happened is kubelet should've incremented the attempt number (or at least that's how I see it from this side (the containerd side) of the CRI api, but kubelet did not increment the attempt number and further containerd was still trying to create the container from the first request.. or the create on the containerd side may even be finished at this point, it is possible the timeout only happened on the kubelet side and containerd continued finishing the create, possibly even attempting to return the success result. If containerd actually failed it would have deleted the reservation for that container id as the immediate thing after we reserve the id in containerd is to defer it's removal on any error in the create.. https://github.com/containerd/containerd/blob/master/pkg/cri/server/container_create.go#L65-L84

So ok.. skimming over the kubelet code.. I believe this is the code that decides what attempt number we are on? https://github.com/kubernetes/kubernetes/blame/master/pkg/kubelet/kuberuntime/kuberuntime_container.go#L173-L292

In my skim.. I think I see a window where kubelet will try attempt 0 a second time after the first create attempt fails with a context timeout. But I may be reading the code wrong? @dims @feiskyer @Random-Liu

Bumped into this issue as well. Switching back to cos with docker.

Fwiw, we're hitting this this week.

kubectl get nodes -o json | jq '.items[].status.nodeInfo.containerRuntimeVersion' |uniq
"containerd://1.4.3"

In my case, the pod is owned by a (batch/v1)job, and the job by a (batch/v1beta1)cronjob.

"backup-db_backup-test-db-1629612000-cz8ks_test_efe343a0-5641-427c-8a65-1b7dc939432d_0" OR "188e7647efe4e1243a4fb3529c69f95c83e3876d4989ba94a409c652f99a8f32"

("backup-db_backup-test-db-1629612000-cz8ks_test_efe343a0-5641-427c-8a65-1b7dc939432d_0" OR "188e7647efe4e1243a4fb3529c69f95c83e3876d4989ba94a409c652f99a8f32")
-"Attempt:0"
"Attempt"

("backup-db_backup-test-db-1629612000-cz8ks_test_efe343a0-5641-427c-8a65-1b7dc939432d_0" OR "188e7647efe4e1243a4fb3529c69f95c83e3876d4989ba94a409c652f99a8f32")
"Attempt:0"

Default
2021-08-22 02:02:45.219 EDT
gke-default-cluster-default-pool-c90133be-6xkd
time="2021-08-22T06:02:44.792102443Z" level=error msg="CreateContainer within sandbox \"c9f8cf0e4fc280b632bf8f4365dccf34f213c5aa4636a4424aab68940d579128\" for &ContainerMetadata{Name:backup-db,Attempt:0,} failed" error="failed to reserve container name \"backup-db_backup-test-db-1629612000-cz8ks_test_efe343a0-5641-427c-8a65-1b7dc939432d_0\": name \"backup-db_backup-test-db-1629612000-cz8ks_test_efe343a0-5641-427c-8a65-1b7dc939432d_0\" is reserved for \"188e7647efe4e1243a4fb3529c69f95c83e3876d4989ba94a409c652f99a8f32\""
Default
2021-08-22 02:02:56.899 EDT
gke-default-cluster-default-pool-c90133be-6xkd
time="2021-08-22T06:02:56.899853062Z" level=error msg="CreateContainer within sandbox \"c9f8cf0e4fc280b632bf8f4365dccf34f213c5aa4636a4424aab68940d579128\" for &ContainerMetadata{Name:backup-db,Attempt:0,} failed" error="failed to reserve container name \"backup-db_backup-test-db-1629612000-cz8ks_test_efe343a0-5641-427c-8a65-1b7dc939432d_0\": name \"backup-db_backup-test-db-1629612000-cz8ks_test_efe343a0-5641-427c-8a65-1b7dc939432d_0\" is reserved for \"188e7647efe4e1243a4fb3529c69f95c83e3876d4989ba94a409c652f99a8f32\""

resource.labels.cluster_name="default-cluster"
"backup-test-db-1629612000-cz8ks_test"

Default
2021-08-22 02:00:03.259 EDT
gke-default-cluster-default-pool-c90133be-6xkd
I0822 06:00:03.259074 1653 kubelet.go:1916] SyncLoop (ADD, "api"): "backup-test-db-1629612000-cz8ks_test(efe343a0-5641-427c-8a65-1b7dc939432d)"
Default
2021-08-22 02:00:03.569 EDT
gke-default-cluster-default-pool-c90133be-6xkd
I0822 06:00:03.569830 1653 kuberuntime_manager.go:445] No sandbox for pod "backup-test-db-1629612000-cz8ks_test(efe343a0-5641-427c-8a65-1b7dc939432d)" can be found. Need to start a new one
Default
2021-08-22 02:00:43.213 EDT
gke-default-cluster-default-pool-c90133be-6xkd
I0822 06:00:43.213133    1653 kubelet.go:1954] SyncLoop (PLEG): "backup-test-db-1629612000-cz8ks_test(efe343a0-5641-427c-8a65-1b7dc939432d)", event: &pleg.PodLifecycleEvent{ID:"efe343a0-5641-427c-8a65-1b7dc939432d", Type:"ContainerStarted", Data:"c9f8cf0e4fc280b632bf8f4365dccf34f213c5aa4636a4424aab68940d579128"}
2021-08-22 02:02:45.217 EDT
gke-default-cluster-default-pool-c90133be-6xkd
E0822 06:02:44.792364 1653 remote_runtime.go:227] CreateContainer in sandbox "c9f8cf0e4fc280b632bf8f4365dccf34f213c5aa4636a4424aab68940d579128" from runtime service failed: rpc error: code = Unknown desc = failed to reserve container name "backup-db_backup-test-db-1629612000-cz8ks_test_efe343a0-5641-427c-8a65-1b7dc939432d_0": name "backup-db_backup-test-db-1629612000-cz8ks_test_efe343a0-5641-427c-8a65-1b7dc939432d_0" is reserved for "188e7647efe4e1243a4fb3529c69f95c83e3876d4989ba94a409c652f99a8f32"
Default
2021-08-22 02:02:45.217 EDT
gke-default-cluster-default-pool-c90133be-6xkd
E0822 06:02:42.840645 1653 pod_workers.go:191] Error syncing pod efe343a0-5641-427c-8a65-1b7dc939432d ("backup-test-db-1629612000-cz8ks_test(efe343a0-5641-427c-8a65-1b7dc939432d)"), skipping: failed to "StartContainer" for "backup-db" with CreateContainerError: "context deadline exceeded"
Default
2021-08-22 02:02:45.217 EDT
gke-default-cluster-default-pool-c90133be-6xkd
E0822 06:02:44.792589 1653 pod_workers.go:191] Error syncing pod efe343a0-5641-427c-8a65-1b7dc939432d ("backup-test-db-1629612000-cz8ks_test(efe343a0-5641-427c-8a65-1b7dc939432d)"), skipping: failed to "StartContainer" for "backup-db" with CreateContainerError: "failed to reserve container name \"backup-db_backup-test-db-1629612000-cz8ks_test_efe343a0-5641-427c-8a65-1b7dc939432d_0\": name \"backup-db_backup-test-db-1629612000-cz8ks_test_efe343a0-5641-427c-8a65-1b7dc939432d_0\" is reserved for \"188e7647efe4e1243a4fb3529c69f95c83e3876d4989ba94a409c652f99a8f32\""
Default
2021-08-22 02:02:56.900 EDT
gke-default-cluster-default-pool-c90133be-6xkd
E0822 06:02:56.900057 1653 remote_runtime.go:227] CreateContainer in sandbox "c9f8cf0e4fc280b632bf8f4365dccf34f213c5aa4636a4424aab68940d579128" from runtime service failed: rpc error: code = Unknown desc = failed to reserve container name "backup-db_backup-test-db-1629612000-cz8ks_test_efe343a0-5641-427c-8a65-1b7dc939432d_0": name "backup-db_backup-test-db-1629612000-cz8ks_test_efe343a0-5641-427c-8a65-1b7dc939432d_0" is reserved for "188e7647efe4e1243a4fb3529c69f95c83e3876d4989ba94a409c652f99a8f32"
Default
2021-08-22 02:02:56.900 EDT
gke-default-cluster-default-pool-c90133be-6xkd
E0822 06:02:56.900309 1653 pod_workers.go:191] Error syncing pod efe343a0-5641-427c-8a65-1b7dc939432d ("backup-test-db-1629612000-cz8ks_test(efe343a0-5641-427c-8a65-1b7dc939432d)"), skipping: failed to "StartContainer" for "backup-db" with CreateContainerError: "failed to reserve container name \"backup-db_backup-test-db-1629612000-cz8ks_test_efe343a0-5641-427c-8a65-1b7dc939432d_0\": name \"backup-db_backup-test-db-1629612000-cz8ks_test_efe343a0-5641-427c-8a65-1b7dc939432d_0\" is reserved for \"188e7647efe4e1243a4fb3529c69f95c83e3876d4989ba94a409c652f99a8f32\""

same, switching back to docker

@fuweid

Thanks for your time on this issue.

Unfortunately, I did stop using COS back in 2020 after we could not find a solution.

I'm 97% sure we were using overlayfs and as for the rest I have no way to find this historical data.

Sorry about that.

@sadortun I file pr to enhance this. #6478 (comment)

No sure that what different between docker and containerd in GKE. sorry about that.

We're on GKE 1.21.6-gke1500 and we've been seeing this problem for the last 1-2 months

@sadortun I file pr to enhance this. #6478 (comment)

I got some good results showing this patch improves the latency of "CreateContainer".

• Setup: GKE 1.20 ubuntu_containerd node with 10 GB boot disk
• Execution A
  • Add some disk IO stress-ng --io 1 -d 1 --timeout 7200 --hdd-bytes 8M
  • Create a deployment of nginx with 25 replicas
  • Check containerd log
• Execution B: repeat above steps with a newly built containerd with this patch
• Result A
  • Seen "failed to reserve container name"
  • The last pod is ready after 15min
• Result B
  • Not seen "failed to reserve container name"
  • All CreateContainer complete within 2 mins
  • The last pod is ready after 10min

Please note this is based on a couple of experiments, not ample data set. stress-ng doesn't produce stable IOPS so the disk state cannot be the exact same in two cases.

Summary (2022/02)

"failed to reserve container name" error is returned by containerd CRI if there is an in-flight CreateContainer request reserving the same container name (like below).
T1: 1st CreateContainer(XYZ) request is sent. (Timeout on Kubelet side)
T2: 2nd CreateContainer(XYZ) request is sent (Kubelet retry)
T3: 2nd CreateContainer request returns "failed to reserve container name XYZ" error
T4: 1st CreateContainer request is still in-flight…

Don't panic. Given sufficient time, the container and pod will be created successfully, as long as you are using restartPolicy:Always or restartPolicy:OnFailure in PodSpec.

Root Cause and Fix

Slow disk operations((e.g. disk throttle on GKE) are the culprit. What generates lots of disk IO can come from a number of factors: user's disk-heavy workload, big images pulling and containerd CRI implementation.

An unnecessary sync-fs operation was found as part of CreateContainer stack. It is the where CreateContainer gets stuck. The sync-fs is got rid of in #6478. Not only it makes CreateContainer return faster, but it reduces disk IO generated by containerd.

Please note there are perhaps other undiscovered reason contributing to this problem.

Mitigation

1. If pods are failed, consider to use restartPolicy:Always or restartPolicy:OnFailure in PodSpec
2. Increase the boot disk IOPS (e.g. upgrade disk type or increase disk size)
3. Upgrade containerd with this patch oci: use readonly mount to read user/group info #6478 which will be available in 1.6+ and 1.5.X(backport working in progress)