Handle potential timeouts when attempting to get the CNI lock

[lbernail]

With two different CNI plugins (and for two very different problems with them) we have seen situations where a CNI operation never returns and hangs, never releasing the the CNI lock. I think it would be helpful to add a timeout to the tentatives to get the lock and surface meaningful errors to the kubelet.

Today when this happens the CRI status call from the kubelet will time out with this log:

 Status from runtime service failed: rpc error: code = DeadlineExceeded desc = context deadline exceeded

The kubelet will then mark the node as NotReady with Reason container runtime is down which is misleading because crictl pods and crictl ps continues to work perfectly (but crictl info doesn't because it also calls the CRI status method).

The containerd call in the Status method is here: https://github.com/containerd/cri/blob/master/pkg/server/status.go#L44-L49
And the libcni.Status method is here: https://github.com/containerd/go-cni/blob/master/cni.go#L124-L132

I think adding a timeout to https://github.com/containerd/go-cni/blob/master/cni.go#L126 and returning a different meaningful error would be helpful and make debugging easier when this happens.

The default kubelet timeout for this call is 2mn: https://github.com/kubernetes/kubernetes/blob/master/staging/src/k8s.io/kubelet/config/v1beta1/types.go#L447-L453

So if we decide to this, we should probably use a shorter timeout (90s?).

I don't think sync/rwmutex supports timeouts so we'd need to use a different implementation. I'd be more than happy to help with a PR if you think it makes sense.

[AkihiroSuda]

Transferred the issue from the old CRI repo github.com/containerd/cri

[fuweid]

@lbernail which version of cri plugin are you using right now? I changed the logic that the CRI will not load the CNI plugin during Status call. containerd/cri#1405

[lbernail]

@fuweid I saw this on 1.2 but I'm pretty sure it also impacts master because we still have this call:

if err := c.netPlugin.Status(); err != nil {

which tries to acquire the CNI lock in the CRI status handler

I'll reproduce with 1.4 to be sure

[fuweid]

Any update? @lbernail

Both the c.netPlugin.Status() and c.netPlugin.Setup requires RLock. If there is no c.netPlugin.Load call, the RLock will not be impacted.

[lbernail]

@fuweid Sorry for the delay. I just test with 1.4.1 and it works a lot better!

So the only potential problem now is that we can't reload the configuration if a RunPodSandbox call is holding a Rlock which is not a big deal I think.

Is this only available since 1.4?

Many thanks and sorry for the issue, I had misunderstood the locking logic here

[fuweid]

@lbernail Yes. It is available since major release 1.4. :)

It is good to upgrade your containerd version ~

[lbernail]

We will soon!
Quick follow-up question: do you think we should add timeouts to Add/Del calls? It will avoid the situation where the kubelet CRI call times out with a misleading message.
We could surface a clearer error message from containerd such as "CNI invocation timed out")

[fuweid]

@lbernail the timeout can be propagated by kubelet RunPodSandbox context actually, like https://github.com/kubernetes/kubernetes/blob/v1.19.0/pkg/kubelet/cri/remote/remote_runtime.go#L98.

And containerd 1.4 release has added the context into https://github.com/containerd/cri/blob/release/1.4/pkg/server/sandbox_run.go#L147 (cni call uses that ctx https://github.com/containerd/go-cni/blob/8fbf3637eb5f67bb16eaacd4ec23a82e4d33b3ec/vendor/github.com/containernetworking/cni/pkg/invoke/raw_exec.go#L34)

[fuweid]

@lbernail I am going to close this issue. Please create new one if you have other questions. And thanks for reporting.