Bug 1806000 - CRI-O failing with: error reserving ctr name
Summary: CRI-O failing with: error reserving ctr name
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: OpenShift Container Platform
Classification: Red Hat
Component: Node
Version: 4.3.0
Hardware: Unspecified
OS: Unspecified
high
high
Target Milestone: ---
: 4.7.0
Assignee: Peter Hunt
QA Contact: Sunil Choudhary
URL:
Whiteboard:
: 1836060 (view as bug list)
Depends On: 1779421
Blocks: 1186913 1934656
TreeView+ depends on / blocked
 
Reported: 2020-02-21 19:57 UTC by Ryan Phillips
Modified: 2024-06-13 22:28 UTC (History)
34 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Cause: Deep directories in volumes cause long SELinux relabelling times. Consequence: Container creation requests timeout, and the Kubelet retries, causing an error "error reserving ctr name" or "Kubelet may be retrying requests that are timing out in CRI-O due to system load" Fix: Save the results of a timed out container creation request, so when it's re-requested, the request can be fulfilled in a timely manner. Result: Containers with deep volumes do eventually succeed to be created.
Clone Of: 1779421
: 1934656 (view as bug list)
Environment:
Last Closed: 2021-02-24 15:10:53 UTC
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)
crio log of one master (7.09 MB, application/gzip)
2020-10-28 11:41 UTC, MinLi
no flags Details


Links
System ID Private Priority Status Summary Last Updated
Github cri-o cri-o issues 4221 0 None closed CRI-O should be smarter about context timeouts 2021-02-21 14:29:44 UTC
Github cri-o cri-o pull 4430 0 None closed [1.20] improve timeout handling and fix flakes 2021-02-21 14:29:44 UTC
Github openshift installer pull 3158 0 None closed [release-4.4] Bug 1806000: Bump RHCOS to 44.81.202002211631-0 2021-02-21 14:29:44 UTC
Red Hat Knowledge Base (Solution) 5075881 0 None None None 2023-09-14 06:00:11 UTC
Red Hat Product Errata RHSA-2020:5633 0 None None None 2021-02-24 15:11:46 UTC

Internal Links: 2023694

Comment 7 Peter Hunt 2020-07-23 02:06:32 UTC
Caden,

from what I can tell in your logs, crio is acting as it's supposed to. All of the pods that are failing because the name is reserved, are failing because crio is already trying to create the pod, but failing to because the network creation is failing/taking too long.

you can parse the files by doing:
grep 'name is reserved' $@ | grep -o "reserving pod name .* " | awk '{ printf $4"\n" }'

which gets the pod name that failed

then doing:

for pod in $(../get-pod-reserved-names.sh $file ); do grep $pod $file | grep -v 'name is reserved' >> reserved-pods-$file; done


returns errors like:
netplugin failed with no error message
error checking loopback interface: loopback interface is down
neither IPv4 nor IPv6 found when retrieving network status: [Unexpected address output   Unexpected address output  ]"

all of these indicate (to me) the node is hosed, and the networking stack cannot keep up.

eventually, each container is cleaned up and the kubelet stops retrying

However, this error message has been a consistent pain point, as it is not being clear in the problem. I have opened: https://github.com/cri-o/cri-o/pull/4002 to address this communication problem

Comment 8 Seth Jennings 2020-08-10 16:06:01 UTC
Ryan is on leave

Comment 10 Nicolas Nosenzo 2020-08-18 13:03:30 UTC
We're being heavily impacted by this issue:

Aug 18 10:12:30.733896 app-node1.example.com hyperkube[1566]: E0818 10:12:30.733791    1566 kuberuntime_manager.go:801] container start failed: CreateContainerError: reserving container name: error reserving ctr name k8s_minio_minio04-0_shared-anb_608b7853-ad8c-42aa-9eea-75d66c4d61bf_0 for id 70aa54ea03b5bf2568015082ac3eef2c01d8e39c8376bb4966b3520badaf131e: name is reserved

oc adm node-logs app-node1.example.com --path=journal --since='-2d' | grep "name is reserved" -c
36644

Comment 11 Nicolas Nosenzo 2020-08-18 13:05:32 UTC
Btw, it's not a 4.4 but 4.5.4 cluster, should we open a new bug ?

Cheers.

Comment 12 Peter Hunt 2020-08-18 13:48:59 UTC
Can we gather the information in https://bugzilla.redhat.com/show_bug.cgi?id=1806000#c7

and attach it? If you'd rather, you can post the full cri-o logs and I can parse it

This error usually happens when either the networking stack is taking a long time to create a new network for the pod, or the node is experiencing IOPs throttling (from too many writes to disk).

Comment 14 Nicolas Nosenzo 2020-08-19 10:15:22 UTC
Hi Peter,

- We got the list of failing pods:

$ grep 'name is reserved' crio-app-node1.example.com.txt  | grep -o "reserving ctr name .* " | awk '{ printf $4"\n" }' | uniq >> list_of_failing_pods
$ cat list_of_failing_pods
k8s_minio_minio04-0_shared-anb_1f2018cb-b43f-49e5-9844-f2c86449dba2_0
k8s_minio_minio04-0_shared-anb_3f221f73-b5ff-45ee-83bf-985535e41b28_0
k8s_minio_minio04-0_shared-anb_a499eefb-c34a-4e28-9d16-da3e6d6412d1_0
k8s_minio_minio04-0_shared-anb_19dc53b9-fd25-4553-8dea-2d18187d86fb_0
k8s_minio_minio04-0_shared-anb_608b7853-ad8c-42aa-9eea-75d66c4d61bf_0

- Then, looking for error messages related to these pods and not containing 'name is reserved' within the log string:

$ for pod in $(cat list_of_failing_pods); do grep $pod 0050-qi03osw1.ocp1-eps.postcom.deutschepost.de.08192020.txt | grep -vi 'name is reserved' >> reserved-pods-failure ;done

I can only find below kind of messages:

level=info msg="CreateCtr: releasing container name k8s_minio_minio04-0_shared-anb_608b7853-ad8c-42aa-9eea-75d66c4d61bf_0" id=772a6769-0716-428c-8fec-4389c993094f name=/runtime.v1alpha2.RuntimeService/CreateContainer

I will also attach the entire crio log file.

Note: This is becoming a production upgrade blocker at the customer side, any effort to speed up the resolution will be greatly appreciated.

Comment 16 Peter Hunt 2020-08-20 13:47:05 UTC
*** Bug 1836060 has been marked as a duplicate of this bug. ***

Comment 17 Peter Hunt 2020-08-20 21:17:26 UTC
well, that log gives good news and bad news.

The good news is it doesn't seem we have a leak. CRI-O attempts to create the container, takes a long time (too long in the kubelet's eyes), and eventually realizes the kubelet gave up on that request, and removes the container.

The problem is, the request is taking a very long time, and it is impossible to tell where CRI-O is currently stalled.

I have discussed this a bit with other CRI-O maintainers, and we are looking into solutions that give us more insight on where the container creation is stalling, and allow us to stop earlier in the container creation process.

Unfortunately, that will not come by tomorrow, so I am marking this to be dealt with next sprint.

Comment 26 Kir Kolyshkin 2020-09-14 18:19:05 UTC
> CRI-O recursively relabels all mount points passed to it to match the selinux labels created for the container. I imagine this relabelling process is what is making the request time out.

We have recently made an improvement in this process -- now relabeling is parallelized, see https://github.com/opencontainers/selinux/pull/89 and https://github.com/containers/storage/pull/557.
Looks like this is brought to cri-o in https://github.com/cri-o/cri-o/pull/3747

Comment 32 Peter Hunt 2020-10-02 19:38:01 UTC
I am making some progress here. Currently, CRI-O undoes all of its progress when it detects a timeout. I am working on having it instead save the progress and return the newly provisioned resource (in this bug, container) and return it then. You can check the progress in the attached github issue

I hope to have this implemented and tested next sprint. It won't totally remove the underlying problems (nodes get overloaded) but it should allow cri-o and kubelet to reconcile faster

Comment 34 MinLi 2020-10-28 11:39:29 UTC
I hit this problem when install OCP 4.7 with matrix profile: Disconnected UPI on Baremetal with RHCOS & RHEL7.8 & OVN & RT Kernel

$ oc describe co kube-scheduler
Name:         kube-scheduler
Namespace:    
Labels:       <none>
...
Status:
  Conditions:
    Last Transition Time:  2020-10-28T07:26:39Z
    Message:               StaticPodsDegraded: pod/openshift-kube-scheduler-zzhao-10135-tpqjf-control-plane-2 container "kube-scheduler" is not ready: CreateContainerError: Kubelet may be retrying requests that are timing out in CRI-O due to system load: error reserving ctr name k8s_kube-scheduler_openshift-kube-scheduler-zzhao-10135-tpqjf-control-plane-2_openshift-kube-scheduler_656a8a8907125a32bf765cc82f53bbd9_1 for id 701649cc596ce5b1114a3797bb01c00e67c336b1cbf2c1bd5a703b9050008ff5: name is reserved
StaticPodsDegraded: pod/openshift-kube-scheduler-zzhao-10135-tpqjf-control-plane-2 container "kube-scheduler" is waiting: CreateContainerError: Kubelet may be retrying requests that are timing out in CRI-O due to system load: error reserving ctr name k8s_kube-scheduler_openshift-kube-scheduler-zzhao-10135-tpqjf-control-plane-2_openshift-kube-scheduler_656a8a8907125a32bf765cc82f53bbd9_1 for id 701649cc596ce5b1114a3797bb01c00e67c336b1cbf2c1bd5a703b9050008ff5: name is reserved
    Reason:                StaticPods_Error
    Status:                True
    Type:                  Degraded
    Last Transition Time:  2020-10-28T03:56:46Z

And I check the log as mentioned in https://bugzilla.redhat.com/show_bug.cgi?id=1806000#c7:
$ grep 'name is reserved' b.out  | grep -o "reserving ctr name .* " | awk '{ printf $4"\n" }' | uniq > list_of_failing_pods

$ cat list_of_failing_pods
k8s_console_console-6fccfc9b4f-9zg8k_openshift-console_4f919228-02b8-4aca-b6a1-a3caaffa7782_14
k8s_kube-scheduler_openshift-kube-scheduler-zzhao-10135-tpqjf-control-plane-2_openshift-kube-scheduler_656a8a8907125a32bf765cc82f53bbd9_1
k8s_console_console-6fccfc9b4f-9zg8k_openshift-console_4f919228-02b8-4aca-b6a1-a3caaffa7782_14
k8s_kube-scheduler_openshift-kube-scheduler-zzhao-10135-tpqjf-control-plane-2_openshift-kube-scheduler_656a8a8907125a32bf765cc82f53bbd9_1

$  for pod in $(cat list_of_failing_pods); do grep $pod b.out | grep -vi 'name is reserved' >> reserved-pods-failure ;done

I found nothing error message.

Comment 35 MinLi 2020-10-28 11:41:27 UTC
Created attachment 1724762 [details]
crio log of one master

I attached one master's crio-log

Comment 36 Peter Hunt 2020-11-13 21:09:58 UTC
I have some evidence that my change will help mitigate the issue. Now to get it into upstream!

Comment 38 Peter Hunt 2020-12-15 21:26:38 UTC
So the PR that will mitigate this issue has merged in to 4.7

Note, this will not fix the underlying issue. A long running relabel of a volume will still timeout. However, previously this would result in the container never successfully being created. Now, the container should successfully be created *eventually*.

Comment 39 Peter Hunt 2020-12-15 21:27:56 UTC
A note for QE: The best way to verify this is working is making a really really deep directory, mount it as a volume into a container, and find the number of times the container is attempted to be created. It should be created just once or twice, rather than hitting a loop where cri-o times out, cleans up, and retries forever.

Comment 45 Ezequiel Hector Brizuela 2021-02-23 15:14:28 UTC
Any news regarding this?

Comment 46 Peter Hunt 2021-02-23 16:20:35 UTC
I have no updates nor advice to give, unfortunately

Comment 48 errata-xmlrpc 2021-02-24 15:10:53 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (Moderate: OpenShift Container Platform 4.7.0 security, bug fix, and enhancement update), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHSA-2020:5633


Note You need to log in before you can comment on or make changes to this bug.