Open file handle to the log file makes all container operations to hang

[whites11]

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.

[thaJeztah]

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 (moby/moby#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).

[whites11]

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.

[thaJeztah]

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 opencontainers/runc#3017 was opened to at least give a bit more context (following kubernetes/kubernetes#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!)

[whites11]

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

[whites11]

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.