docker logs <container_w_no_logs> --tail <N> hangs in Docker 23.0.0

[dzdrav]

Description

Prior to Docker engine 23.0.0 release, docker logs <container> --tail <N> would output up to N container logs. If there were none, it would output zero lines and exit.

Since docker 23.0.0, this command hangs (instead of terminating).

Since there is no mention of this "feature" in the release notes, I took the libery of assuming it's a bug. Please correct me if I'm wrong and this is intended behaviour

Reproduce

You need a container that has at least one log

# verify `docker logs` won't hang on non-empty logfile
docker logs <container> --tail 5

# find out log path
docker inspect --format='{{.LogPath}}' <container> | xclip

# create an empty file
: > empty

# truncate the logfile
sudo cp empty <log path>

# docker will hang now
docker logs <container> --tail 5

Expected behavior

docker logs <container> --tail 5

should not hang, but return immediately on containers with no logs

docker version

Client: Docker Engine - Community
 Version:           23.0.0
 API version:       1.42
 Go version:        go1.19.5
 Git commit:        e92dd87
 Built:             Wed Feb  1 17:49:08 2023
 OS/Arch:           linux/amd64
 Context:           default

Server: Docker Engine - Community
 Engine:
  Version:          23.0.0
  API version:      1.42 (minimum version 1.12)
  Go version:       go1.19.5
  Git commit:       d7573ab
  Built:            Wed Feb  1 17:49:08 2023
  OS/Arch:          linux/amd64
  Experimental:     false
 containerd:
  Version:          1.6.16
  GitCommit:        31aa4358a36870b21a992d3ad2bef29e1d693bec
 runc:
  Version:          1.1.4
  GitCommit:        v1.1.4-0-g5fd4c4d
 docker-init:
  Version:          0.19.0
  GitCommit:        de40ad0

docker info

Client:
 Context:    default
 Debug Mode: false
 Plugins:
  buildx: Docker Buildx (Docker Inc.)
    Version:  v0.10.2
    Path:     /usr/libexec/docker/cli-plugins/docker-buildx
  compose: Docker Compose (Docker Inc.)
    Version:  v2.15.1
    Path:     /usr/lib/docker/cli-plugins/docker-compose
  scan: Docker Scan (Docker Inc.)
    Version:  v0.23.0
    Path:     /usr/libexec/docker/cli-plugins/docker-scan

Server:
 Containers: 31
  Running: 13
  Paused: 0
  Stopped: 18
 Images: 219
 Server Version: 23.0.0
 Storage Driver: overlay2
  Backing Filesystem: extfs
  Supports d_type: true
  Using metacopy: false
  Native Overlay Diff: true
  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.runc.v2 runc
 Default Runtime: runc
 Init Binary: docker-init
 containerd version: 31aa4358a36870b21a992d3ad2bef29e1d693bec
 runc version: v1.1.4-0-g5fd4c4d
 init version: de40ad0
 Security Options:
  apparmor
  seccomp
   Profile: builtin
 Kernel Version: 5.15.0-58-generic
 Operating System: Ubuntu 20.04.5 LTS
 OSType: linux
 Architecture: x86_64
 CPUs: 32
 Total Memory: 31.25GiB
 Name: <redacted>
 ID: <redacted>
 Docker Root Dir: /var/lib/docker
 Debug Mode: false
 Registry: https://index.docker.io/v1/
 Experimental: false
 Insecure Registries:
  127.0.0.0/8
 Live Restore Enabled: false

Additional Info

No response

[sam-thibault]

/cc @corhere

[sam-thibault]

Please note the warning here https://docs.docker.com/config/containers/logging/json-file/

Warning

The json-file logging driver uses file-based storage. These files are designed to be exclusively accessed by the Docker daemon. Interacting with these files with external tools may interfere with Docker’s logging system and result in unexpected behavior, and should be avoided.

[corhere]

The log following code was modified for v23.0.0 to fix several bugs. (moby/moby#43294 was missed when writing the v23.0.0 release notes. Whoops!)

$ docker run --rm -d --name pause1 alpine sleep 300
bea890b3f2601a5af4fe5216053a3b47c8bffcebdd6ba13303e7902482b58759
$ time docker logs pause1 --tail 5
real	0m 0.08s
user	0m 0.06s
sys	0m 0.07s
$ docker run --rm -d --name pause2 alpine sh -c 'printf "1\n2\n3\n4\n"; sleep 300'
ecf78f1b18f39bb7edc5d3fdcdd6062d069e6069bb93881e1e8c7ba469525129
$ time docker logs pause2 --tail 5
1
2
3
4
real	0m 0.08s
user	0m 0.06s
sys	0m 0.07s
$ docker version
Client:
 Version:           23.0.0
 API version:       1.42
 Go version:        go1.19.5
 Git commit:        e92dd87
 Built:             Wed Feb  1 17:43:29 2023
 OS/Arch:           linux/amd64
 Context:           default

Server: Docker Engine - Community
 Engine:
  Version:          23.0.0
  API version:      1.42 (minimum version 1.12)
  Go version:       go1.19.5
  Git commit:       d7573ab
  Built:            Wed Feb  1 17:46:24 2023
  OS/Arch:          linux/amd64
  Experimental:     false
 containerd:
  Version:          v1.6.16
  GitCommit:        31aa4358a36870b21a992d3ad2bef29e1d693bec
 runc:
  Version:          1.1.4
  GitCommit:        v1.1.4-0-g5fd4c4d
 docker-init:
  Version:          0.19.0
  GitCommit:        de40ad0

docker logs --tail terminates promptly when you leave alone files which the Docker daemon is designed to have exclusive access to. It is not a bug that the daemon behaves unexpectedly when you truncate those files, even if earlier versions of the daemon were more forgiving.

I'd be very interested to know what problem you're trying to solve by truncating container log files manually. The json-file log driver has options to configure logfile rotation. Feel free to open a feature request issue on github.com/moby/moby if those options are insufficient for your use case and none of the other log drivers are a good fit.

[dzdrav]

Please note the warning here https://docs.docker.com/config/containers/logging/json-file/

docker logs --tail terminates promptly when you leave alone files which the Docker daemon is designed to have exclusive access to. It

Truncating the file in-place seems to be the culprit. Just --tailing a container with no logs terminates immediately. Thank you both for the help.

I'd be very interested to know what problem you're trying to solve by truncating container log files manually. The json-file log driver has options to configure logfile rotation.

Log rotation indeed. In my case, time-based one which Docker doesn't support itself.

(Un)fortunately, the feature request already exists, almost 5 years in the making, with no real progress.

There was also a suggestion to allow a signal like SIGHUP that would instruct Docker daemon to reopen its log files (it could be used in conjunction with logrotate's create option). Since that was scrapped as well, the only solution (for this logging driver) is copytruncate which truncates the file in place.

Thank you for helping diagnose the problem. I acknowledge that this is expected (undefined) behaviour so I'm fine with closing this issue, but I'd like to use this opportunity to plug above issues as still relevant (time based log rotation).