cli
cli copied to clipboard
Open file handle to the log file makes all container operations to hang
Description
Some containers make docker
commands to hang.
Example:
# docker ps -a | grep ce59
ce59e058f135 REDACTED "/bin/bash -c 'java …" 5 days ago Created k8s_basket-api_basket-api-bugfix-2991-correcting-taxrate-59f88d7ccf-4vfqv_com-next-dev_68bf8a2b-2830-4b9d-b4dc-fb7ccdc24457_0
This container is in Created
state so it never run AFAIK.
Any operation on it hangs:
# docker rm -f ce59e058f135
HANGS
# docker info ce59e058f135
HANGS
# docker stats ce59e058f135
HANGS
dockerd
holds a file handle on the log file for that container:
# lsof /var/lib/docker/containers/ce59e058f135016f401d400f41b356e4b631df8a3e81a1040c7b1f01a6169d06/ce59e058f135016f401d400f41b356e4b631df8a3e81a1040c7b1f01a6169d06-json.log
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
dockerd 2335 root 366w REG 259,10 0 220494219 /var/lib/docker/containers/ce59e058f135016f401d400f41b356e4b631df8a3e81a1040c7b1f01a6169d06/ce59e058f135016f401d400f41b356e4b631df8a3e81a1040c7b1f01a6169d06-json.log
and I suspect that is the reason why everything is stuck.
systemctl restart docker
makes the container and the FD disappear and the problem is solved.
Steps to reproduce the issue:
Unfortuately I don't know how I get into this situation. Container is created by kubernetes and that's all I know.
Output of docker version
:
Client:
Version: 20.10.12
API version: 1.41
Go version: go1.17.8
Git commit: 60293e390e
Built: Tue Apr 5 17:22:59 2022
OS/Arch: linux/amd64
Context: default
Experimental: true
Server:
Engine:
Version: 20.10.12
API version: 1.41 (minimum version 1.12)
Go version: go1.17.8
Git commit: bd6d47cb47
Built: Tue Apr 5 17:23:02 2022
OS/Arch: linux/amd64
Experimental: true
containerd:
Version: 1.5.11
GitCommit: 17624fd6043a8c74bb40105472f4ec9eff59bef1
runc:
Version: 1.1.0+dev.docker-20.10
GitCommit: b083ef4992ddc33fc7e699170c4abafa74d17818
docker-init:
Version: 0.19.0de40ad007797e0dcd8b7126f27bb87401d224240
GitCommit:
Output of docker info
:
Client:
Context: default
Debug Mode: false
Server:
Containers: 43
Running: 31
Paused: 0
Stopped: 12
Images: 150
Server Version: 20.10.12
Storage Driver: overlay2
Backing Filesystem: xfs
Supports d_type: true
Native Overlay Diff: false
userxattr: false
Logging Driver: json-file
Cgroup Driver: cgroupfs
Cgroup Version: 1
Plugins:
Volume: local
Network: bridge host ipvlan macvlan null overlay
Log: awslogs fluentd gcplogs gelf journald json-file local logentries splunk syslog
Swarm: inactive
Runtimes: io.containerd.runtime.v1.linux runc io.containerd.runc.v2
Default Runtime: runc
Init Binary: docker-init
containerd version: 17624fd6043a8c74bb40105472f4ec9eff59bef1
runc version: b083ef4992ddc33fc7e699170c4abafa74d17818
init version:
Security Options:
seccomp
Profile: default
selinux
Kernel Version: 5.15.32-flatcar
Operating System: Flatcar Container Linux by Kinvolk 3139.2.0 (Oklo)
OSType: linux
Architecture: x86_64
CPUs: 16
Total Memory: 62.03GiB
Name: REDACTED
ID: XPLD:ASQJ:MCMW:CMLZ:HNBY:YXLW:M362:HXLC:24L7:2MVD:TAGZ:VME7
Docker Root Dir: /var/lib/docker
Debug Mode: false
Username: giantswarmpull
Registry: https://index.docker.io/v1/
Labels:
Experimental: true
Insecure Registries:
127.0.0.0/8
Registry Mirrors:
https://giantswarm.azurecr.io/
Live Restore Enabled: true
Additional environment details (AWS, VirtualBox, physical, etc.):
This is an AWS EC2 instance.
Hmm.. hard to tell. I see you're not running the latest patch release of Docker 20.10, and there's been at least one fix related to logging in a later patch release (https://github.com/moby/moby/pull/43165),
One other aspect that could relate to this, is that the files used by the JSON-file logging driver were designed to be exclusively accessed by the docker daemon (they effectively are only an internal storage mechanism to facilitate the docker logs
function, which reads back the logs using the Docker API).
Unfortunately there's various tools (and I think kubernetes itself including) that access those files, which at times has resulted in either those files being locked, or ending up in multiple mount-namespaces (cAdvisor being a known actor in that), which can result in rather ugly situations (sometimes only resolvable by a reboot if mount namespaces get nested into other mount namespaces).
We found out what's causing the issue, if it might spark an idea on your end. There was an error in the Kubernetes Pod Spec, and the container failed creating with this error:
Error response from daemon: failed to create shim: OCI runtime create failed: runc create failed: unable to start container process: error during container init: environment variable value can't contain null(\x00): "ENV_NAME=REDACTED BINARY-LIKE STUFF"
That explains how the issue happens, not why.
So the error message comes from the OCI runtime (runc); https://github.com/opencontainers/runc/blob/main/libcontainer/init_linux.go#L113-L136
Environment variables are indeed not allowed to contain null
; Linux will reject them, but the error message is a bit cryptic ("invalid argument"), so https://github.com/opencontainers/runc/pull/3017 was opened to at least give a bit more context (following https://github.com/kubernetes/kubernetes/issues/102732).
I know at some point we added validation earlier in the stack to match what POSIX defines, but we had to revert that validation, because the specification about "what's allowed" is a bit of a grey area; and leaves a lot up to the implementation (so environment variables that should be invalid are actually accepted, and some frameworks depend on the invalid names, so we decided to leave it to Linux to decide what it accepts (without trying to match its validation).
Perhaps we could add back a check for this specific case though, as it's unlikely null
chars will be accepted by any implementation, and catching it early would be a slightly better experience.
As to the "why" for the log-file; that's a good question; it looks like the container state may be somewhere in between (container created, but the OCI runtime failing on it); usually that would mean it should catch that it failed, but perhaps there's some race condition here.
If you have a test environment to see if it still reproduces on the latest patch release, and the latest containerd/runc versions that may still be useful
I did a quick try with a plain docker run
, but I suspect the value is escaped there, so it didn't reproduce, but maybe there's some variation on how to pass it to get the null
character across the wire that I didn't try yet. (If you manage to find a way, please post!)
I also failed reproducing it with plain docker. Also not sure the lock on the log file is actually the real problem here. Will update if I have new info
I have been able to get the bull byte error using the docker client library:
package main
import (
"context"
"github.com/docker/docker/api/types/container"
"github.com/docker/docker/api/types/network"
"github.com/docker/docker/client"
v1 "github.com/opencontainers/image-spec/specs-go/v1"
)
func main() {
cli, err := client.NewClientWithOpts(client.FromEnv)
if err != nil {
panic(err)
}
_, err = cli.ContainerCreate(
context.Background(),
&container.Config{
Image: "alpine:latest",
Env: []string{
"TEST=prefix\x00suffix",
},
},
&container.HostConfig{},
&network.NetworkingConfig{},
&v1.Platform{},
"test-container",
)
if err != nil {
panic(err)
}
}
But, to my big surprise, this does not trigger the issue.
$ go run main.go
$ docker start test-container
Error response from daemon: failed to create shim task: OCI runtime create failed: runc create failed: unable to start container process: error during container init: environment variable value can't contain null(\x00): "TEST=prefix\x00suffix": unknown
Error: failed to start containers: test-container
$ docker rm test-container
test-container
So there must be something else as well.