-
Story
-
Resolution: Done
-
Major
-
None
-
None
-
None
-
-
- What happened?
-
We've noticed that with version 1.29.1 we no longer can issue multiple `crictl stop` commands for the same container. If there is a `StopContainer` operation active, any other `StopContainer` operation will timeout at the client side waiting for the server to take a lock that is hold by the initial stop container operation.
-
- Context
In a scenario where you have one container that is unwilling to die gracefully over a long period of time (e.g. a big database that ignores SIGTERM for a long period of time while closing connections), the following regression happens:
- Sending a `crictl stop -t 300 <container>`, will send a SIGTERM and after 300s send a SIGKILL. This command hangs as it should while we wait for the container to die gracefully or get forcefully terminated after 300s.
- The container ignores SIGTERM, and won't die on its own. So we need to wait for the full timeout.
- We decided that we don't want to wait for 300s, and we now want to issue `crictl stop -t 0 <container>` to immediately kill it.
Currently, the second command will not take effect, and `crictl` will get a context timeout from `crio` server.
The following logs show the symptoms :
```
$ crictl stop dd5d5449948de
E0417 09:57:18.003776 750032 remote_runtime.go:366] "StopContainer from runtime service failed" err="rpc error: code = DeadlineExceeded desc = context deadline exceeded" containerID="dd5d5449948de"
FATA[0002] stopping the container "dd5d5449948de": rpc error: code = DeadlineExceeded desc = context deadline exceeded
```
This behavior was not present on version 1.27.1 and multiple stop container operations can be issued.
-
-
- What did you expect to happen?
-
I'd expect to have the same behavior we did in 1.27; where the second `crictl stop` command goes through and manages to kill the container. The container runtime should honor all stopping requests, even if there is one currently waiting in a longer timeout, we should be able to stop a container forcefully even if we mistakenly or purposely tried with a longer timeout before.
I think this might be a regression introduced around the time of [this refactor](https://github.com/cri-o/cri-o/commit/be5bac87bb56bbc1b01807668006dd246cab173c).
-
-
- How can we reproduce it (as minimally and precisely as possible)?
-
To reproduce the issue, in a host running k8s with cri-o as container runtime:
1) Create the following pod:
```
apiVersion: v1
kind: Pod
metadata:
name: sleepy-dummy
spec:
terminationGracePeriodSeconds: 3600
containers:
- name: sleepy-dummy
image: docker.io/library/busybox
command: ["sleep", "600"]
imagePullPolicy: IfNotPresent
```
This uses a `busibox` image to run a `sleep` command for 600 seconds. And has a terminationGracePeriodSeconds of 3600.
2) Check that the pod is running
```
$ kubectl get pods -n default sleepy-dummy
NAME READY STATUS RESTARTS AGE
sleepy-dummy 1/1 Running 0 14s
```
3) Attempt to delete the pod using `kubectl`. This will triger a `StopContiainer` call with a timeout o 3600; which will held the stop lock on crio server preventing any future stops to work.
```
$ kubectl delete pod -n infra-test sleepy-dummy
pod "sleepy-dummy" deleted
<hangs>
```
4) Attempt to stop the container using `crictl` stop.
```
$ crictl ps | grep sleepy
8c528df1cddbe ba5dc23f65d4cc4a4535bce55cf9e63b068eb02946e3422d3587e8ce803b6aab About a minute ago Running sleepy-dummy 0 05cfc9fc3bfed sleepy-dummy
$ sudo -i crictl stop 8c528df1cddbe
E0417 10:14:59.915882 798939 remote_runtime.go:366] "StopContainer from runtime service failed" err="rpc error: code = DeadlineExceeded desc = context deadline exceeded" containerID="8c528df1cddbe"
FATA[0002] stopping the container "8c528df1cddbe": rpc error: code = DeadlineExceeded desc = context deadline exceeded
```
Attempting to stop with explicit timeouts:
```
$ time sudo -i crictl -t 5s stop -t 0 8c528df1cddbe
E0417 10:15:20.765337 800099 remote_runtime.go:366] "StopContainer from runtime service failed" err="rpc error: code = DeadlineExceeded desc = context deadline exceeded" containerID="8c528df1cddbe"
FATA[0005] stopping the container "8c528df1cddbe": rpc error: code = DeadlineExceeded desc = context deadline exceeded
real 0m5.071s
user 0m0.049s
sys 0m0.031s
```
Note: the same can be achieved using `crictl stop -t 3600 <container>` on step 3.
-
-
- Anything else we need to know?
-
I've run a goroutine dump of the state of my cri-o server during step 4 of the reproduction steps and confirmed that there is at least one goroutine in the method `WaitOnStopTimeout` while all the others cannot enter the stop main method.
This is the first `crictl stop` issued, with the high timeout, waiting in [this timout channel](https://github.com/cri-o/cri-o/blob/main/internal/oci/container.go#L620) if I'm not mistaken. It is holding the `stopLock`.
```
goroutine 61352 [select, 1 minutes]:
github.com/cri-o/cri-o/internal/oci.(*Container).WaitOnStopTimeout(0xc00201ec00, {0x2455340, 0xc000ed9e90}, 0xe10)
github.com/cri-o/cri-o/internal/oci/container.go:591 +0x1ec
github.com/cri-o/cri-o/internal/oci.(*runtimeOCI).StopContainer(0xc001de5520, {0x2455340?, 0xc000ed9e30?}, 0xc00201ec00, 0xc000ed9e00?)
github.com/cri-o/cri-o/internal/oci/runtime_oci.go:815 +0x2e5
github.com/cri-o/cri-o/internal/oci.(*Runtime).StopContainer(0x2455340?, {0x2455340?, 0xc000ed9da0?}, 0x0?, 0x0?)
github.com/cri-o/cri-o/internal/oci/oci.go:308 +0xff
github.com/cri-o/cri-o/server.(*Server).stopContainer(0xc000280800, {0x2455340?, 0xc000ed9b30?}, 0xc00201ec00, 0x40?)
github.com/cri-o/cri-o/server/container_stop.go:60 +0x40b
github.com/cri-o/cri-o/server.(*Server).StopContainer(0xc000280800, {0x2455340?, 0xc000ed9950?}, 0xc000790e00)
github.com/cri-o/cri-o/server/container_stop.go:25 +0x2aa
k8s.io/cri-api/pkg/apis/runtime/v1._RuntimeService_StopContainer_Handler.func1({0x2455340, 0xc000ed9950}, {0x20224a0?, 0xc000790e00})
k8s.io/cri-api@v0.29.0/pkg/apis/runtime/v1/api.pb.go:11205 +0x75
main.main.func2.UnaryInterceptor.func6({0x2455340, 0xc000ed98c0}, {0x20224a0, 0xc000790e00}, 0xc000790e20, 0xc002a68c78)
github.com/cri-o/cri-o/server/otel-collector/interceptors.go:64 +0x198
k8s.io/cri-api/pkg/apis/runtime/v1._RuntimeService_StopContainer_Handler({0x20dbf20?, 0xc000280800}, {0x2455340, 0xc000ed98c0}, 0xc001b19380, 0x21fece8)
k8s.io/cri-api@v0.29.0/pkg/apis/runtime/v1/api.pb.go:11207 +0x135
google.golang.org/grpc.(*Server).processUnaryRPC(0xc000240000, {0x2455340, 0xc000ed9710}, {0x245ef00, 0xc000c604e0}, 0xc0017027e0, 0xc0001fb3b0, 0x33ffae0, 0x0)
google.golang.org/grpc@v1.60.1/server.go:1372 +0xe03
google.golang.org/grpc.(*Server).handleStream(0xc000240000, {0x245ef00, 0xc000c604e0}, 0xc0017027e0)
google.golang.org/grpc@v1.60.1/server.go:1783 +0xfec
google.golang.org/grpc.(*Server).serveStreams.func2.1()
google.golang.org/grpc@v1.60.1/server.go:1016 +0x59
created by google.golang.org/grpc.(*Server).serveStreams.func2 in goroutine 30695
google.golang.org/grpc@v1.60.1/server.go:1027 +0x115
```
Here is one of the following `crictl stops` calls, attempting to get the same lock for `ShouldBeStopped` function.
```
goroutine 61810 [sync.RWMutex.RLock]:
sync.runtime_SemacquireRWMutexR(0xc003389ce0?, 0xae?, 0x0?)
runtime/sema.go:82 +0x25
sync.(*RWMutex).RLock(...)
sync/rwmutex.go:71
github.com/cri-o/cri-o/internal/oci.(*Container).State(0xc00201ec00)
github.com/cri-o/cri-o/internal/oci/container.go:408 +0x52
github.com/cri-o/cri-o/internal/oci.(*Container).ShouldBeStopped(...)
github.com/cri-o/cri-o/internal/oci/container.go:549
github.com/cri-o/cri-o/internal/oci.(*runtimeOCI).StopContainer(0xc001de5520, {0x2455340?, 0xc003389ce0?}, 0xc00201ec00, 0xc003389cb0?)
github.com/cri-o/cri-o/internal/oci/runtime_oci.go:798 +0x153
github.com/cri-o/cri-o/internal/oci.(*Runtime).StopContainer(0x2455340?, {0x2455340?, 0xc003389bc0?}, 0x0?, 0x0?)
github.com/cri-o/cri-o/internal/oci/oci.go:308 +0xff
github.com/cri-o/cri-o/server.(*Server).stopContainer(0xc000280800, {0x2455340?, 0xc0033899b0?}, 0xc00201ec00, 0xd?)
github.com/cri-o/cri-o/server/container_stop.go:60 +0x40b
github.com/cri-o/cri-o/server.(*Server).StopContainer(0xc000280800, {0x2455340?, 0xc003389740?}, 0xc001f380a0)
github.com/cri-o/cri-o/server/container_stop.go:25 +0x2aa
k8s.io/cri-api/pkg/apis/runtime/v1._RuntimeService_StopContainer_Handler.func1({0x2455340, 0xc003389740}, {0x20224a0?, 0xc001f380a0})
k8s.io/cri-api@v0.29.0/pkg/apis/runtime/v1/api.pb.go:11205 +0x75
main.main.func2.UnaryInterceptor.func6({0x2455340, 0xc003389680}, {0x20224a0, 0xc001f380a0}, 0xc001f380c0, 0xc001ac43c0)
github.com/cri-o/cri-o/server/otel-collector/interceptors.go:64 +0x198
k8s.io/cri-api/pkg/apis/runtime/v1._RuntimeService_StopContainer_Handler({0x20dbf20?, 0xc000280800}, {0x2455340, 0xc003389680}, 0xc001c10600, 0x21fece8)
k8s.io/cri-api@v0.29.0/pkg/apis/runtime/v1/api.pb.go:11207 +0x135
google.golang.org/grpc.(*Server).processUnaryRPC(0xc000240000, {0x2455340, 0xc00114c6c0}, {0x245ef00, 0xc00117ba00}, 0xc00149de60, 0xc0001fb3b0, 0x33ffae0, 0x0)
google.golang.org/grpc@v1.60.1/server.go:1372 +0xe03
google.golang.org/grpc.(*Server).handleStream(0xc000240000, {0x245ef00, 0xc00117ba00}, 0xc00149de60)
google.golang.org/grpc@v1.60.1/server.go:1783 +0xfec
google.golang.org/grpc.(*Server).serveStreams.func2.1()
google.golang.org/grpc@v1.60.1/server.go:1016 +0x59
created by google.golang.org/grpc.(*Server).serveStreams.func2 in goroutine 61795
google.golang.org/grpc@v1.60.1/server.go:1027 +0x115
```
-
-
- CRI-O and Kubernetes version
-
<details>
```console
$ crio --version
crio version 1.29.1
Version: 1.29.1
GitCommit: 78e179ba8dd3ce462382a17049e8d1f770246af1
GitCommitDate: 2024-01-11T21:36:06Z
GitTreeState: clean
BuildDate: 1970-01-01T00:00:00Z
GoVersion: go1.21.1
Compiler: gc
Platform: linux/amd64
Linkmode: static
BuildTags:
static
netgo
osusergo
exclude_graphdriver_btrfs
exclude_graphdriver_devicemapper
seccomp
apparmor
selinux
LDFlags: unknown
SeccompEnabled: true
AppArmorEnabled: false
```
```console
$ kubectl version --output=json
{
"clientVersion":
,
"kustomizeVersion": "v5.0.4-0.20230601165947-6ce0bf390ce3",
"serverVersion":
}
```
</details>
-
-
- OS version
-
<details>
```console
- On Linux:
$ cat /etc/os-release
NAME="Oracle Linux Server"
VERSION="8.9"
ID="ol"
ID_LIKE="fedora"
VARIANT="Server"
VARIANT_ID="server"
VERSION_ID="8.9"
PLATFORM_ID="platform:el8"
PRETTY_NAME="Oracle Linux Server 8.9"
ANSI_COLOR="0;31"
CPE_NAME="cpe:/o:oracle:linux:8:9:server"
HOME_URL="https://linux.oracle.com/"
BUG_REPORT_URL="https://github.com/oracle/oracle-linux"
ORACLE_BUGZILLA_PRODUCT="Oracle Linux 8"
ORACLE_BUGZILLA_PRODUCT_VERSION=8.9
ORACLE_SUPPORT_PRODUCT="Oracle Linux"
ORACLE_SUPPORT_PRODUCT_VERSION=8.9
$ uname -a
Linux <redacted> 4.18.0-513.24.1.el8_9.x86_64 #1 SMP Wed Apr 10 08:10:12 PDT 2024 x86_64 x86_64 x86_64 GNU/Linux
```
</details>
-
-
- Additional environment details (AWS, VirtualBox, physical, etc.)
-
<details>
</details>