Using follow log output causes json-log file descriptors to leak

[stawii]

Description

Using docker logs --follow on heavy logging containers causes *-json.log files not close. This leads to file descriptors to leak, and free space not reclaimed (if logs rotates).
Files are not closed even if container is removed. Only restart of Docker helps.

Steps to reproduce the issue:

1. Clean CentOS instalation, docker installed from official docker-ce-18.03.1.ce-1.el7.centos.x86_64.rpm package, no extra configuration done.
2. Create any container which does a lot of logging.
3. Run docker logs --follow CONTAINER_ID few times: one by one, gracefully stopping with Ctrl+C
4. Check numer of times json.log file is still open by looking into /proc/$(cat /run/docker.pid)/fd

Describe the results you received:

[root@docker ~]# ls -al /proc/$(cat /run/docker.pid)/fd | wc -l
20

[root@docker ~]# docker run -d -p 8080:80 httpd
2f99317bdcc1e33cc681f813de157cf83c054cb800708c1f892d0e28d98f9435

[root@docker ~]# ls -al /proc/$(cat /run/docker.pid)/fd | wc -l
26

[root@docker ~]# ab -n1000000 -c100 http://localhost:8080/  # to generate lot of logs

now, on second console run and stop by pressing Ctrl+C few times:

docker logs -f 2f99317bdcc1e33cc681f813de157cf83c054cb800708c1f892d0e28d98f9435

and now:

[root@docker ~]# ls -al /proc/$(cat /run/docker.pid)/fd | wc -l
51    --->> this should be still 26!

[root@docker ~]# docker rm 2f99317bdcc1e33cc681f813de157cf83c054cb800708c1f892d0e28d98f9435 -f

[root@docker ~]# ls -al /proc/$(cat /run/docker.pid)/fd | wc -l
45   --->>> this should go back to 20

Describe the results you expected:

See above.

Additional information you deem important (e.g. issue happens only occasionally):

Make sure A LOT of logs are generated. Sometimes fd is closed. Run at least 10 times.
First seen on v17.12.1, still present on v18.03.1.

Output of docker version:

Client:
 Version:      18.03.1-ce
 API version:  1.37
 Go version:   go1.9.5
 Git commit:   9ee9f40
 Built:        Thu Apr 26 07:20:16 2018
 OS/Arch:      linux/amd64
 Experimental: false
 Orchestrator: swarm

Server:
 Engine:
  Version:      18.03.1-ce
  API version:  1.37 (minimum version 1.12)
  Go version:   go1.9.5
  Git commit:   9ee9f40
  Built:        Thu Apr 26 07:23:58 2018
  OS/Arch:      linux/amd64
  Experimental: false

Output of docker info:

Containers: 1
 Running: 1
 Paused: 0
 Stopped: 0
Images: 3
Server Version: 18.03.1-ce
Storage Driver: overlay2
 Backing Filesystem: xfs
 Supports d_type: true
 Native Overlay Diff: true
Logging Driver: json-file
Cgroup Driver: cgroupfs
Plugins:
 Volume: local
 Network: bridge host macvlan null overlay
 Log: awslogs fluentd gcplogs gelf journald json-file logentries splunk syslog
Swarm: inactive
Runtimes: runc
Default Runtime: runc
Init Binary: docker-init
containerd version: 773c489c9c1b21a6d78b5c538cd395416ec50f88
runc version: 4fc53a81fb7c994640722ac585fa9ca548971871
init version: 949e6fa
Security Options:
 seccomp
  Profile: default
Kernel Version: 3.10.0-693.5.2.el7.x86_64
Operating System: CentOS Linux 7 (Core)
OSType: linux
Architecture: x86_64
CPUs: 2
Total Memory: 1.796GiB
Name: spam2
ID: V3P4:63VK:T2DA:QQLR:URRJ:LSOY:YLTF:25CZ:6R72:WOH6:FQYB:OB5K
Docker Root Dir: /var/lib/docker
Debug Mode (client): false
Debug Mode (server): false
Registry: https://index.docker.io/v1/
Labels:
Experimental: false
Insecure Registries:
 127.0.0.0/8
Live Restore Enabled: false

Additional environment details (AWS, VirtualBox, physical, etc.):

Tested on CentOS both on AWS and on Vagrant/VirtualBox - same results.

[waddles]

I have been investigating a similar issue which I think has the same root cause.

We have a dotnet core application that registers an inotify watch on a config file at startup. It sometimes fails at startup with the message

The configured user limit (256) on the number of inotify instances has been reached.

This relates to the sysctl setting /proc/sys/fs/inotify/max_user_instances which has been increased from the OS default fo 128.

When I investigated what was using all the inotify instances, I found dockerd had the vast majority of inotify file handles, with a correspondingly high number of stale file handles to a container's *-json.log file which had since been deleted.

For example, with 5 containers running:

# lsof -p $(pidof dockerd) | grep -c inotify
477
# lsof -p $(pidof dockerd) | grep -c deleted
1411

and after restarting docker, the same 5 containers running:

# lsof -p $(pidof dockerd) | grep -c inotify
5
# lsof -p $(pidof dockerd) | grep -c deleted
0

[stawii]

No assignees, no labels? Is this issue ignored or something?

[kolyshkin]

Reproduced on latest moby (update: and latest docker/cli).

[kolyshkin]

Let me summarize the current findings; will continue looking at it tomorrow.

I have tracked the issue down to the following code:

moby/daemon/logger/loggerutils/logfile.go

Lines 622 to 639 in 562df8c

	select {
	case logWatcher.Msg <- msg:
	case <-ctx.Done():
	logWatcher.Msg <- msg
	for {
	msg, err := decodeLogLine()
	if err != nil {
	return
	}
	if !since.IsZero() && msg.Timestamp.Before(since) {
	continue
	}
	if !until.IsZero() && msg.Timestamp.After(until) {
	return
	}
	logWatcher.Msg <- msg
	}
	}

Goroutine is stuck at line 625:

moby/daemon/logger/loggerutils/logfile.go

Line 625 in 562df8c

logWatcher.Msg <- msg

The problem is I can't grok this code. The relevant change is commit a69a59f (PR #27782).

// cc @cpuguy83 @tombooth ^^^^

[kolyshkin]

OK, what happens is

1. logs consumer is gone (still, (*LogWatcher).Close() is properly called and WatchClose() is received)
2. logs producer still tries to push a message to the channel:
   

   moby/daemon/logger/loggerutils/logfile.go

   Line 625 in 562df8c

   logWatcher.Msg <- msg

3. No one is reading the channel, so logs producer is stuck, its goroutine never returns, its cleanup (defer statements at the beginning of followLogs()) are never executed.

Now, I see two ways to solve it.

1. Remove the code that tries to write message(s) after WatchClose() has happened:

@@ -622,20 +634,7 @@ func followLogs(f *os.File, logWatcher *logger.LogWatcher, notifyRotate chan int
                select {
                case logWatcher.Msg <- msg:
                case <-ctx.Done():
-                       logWatcher.Msg <- msg
-                       for {
-                               msg, err := decodeLogLine()
-                               if err != nil {
-                                       return
-                               }
-                               if !since.IsZero() && msg.Timestamp.Before(since) {
-                                       continue
-                               }
-                               if !until.IsZero() && msg.Timestamp.After(until) {
-                                       return
-                               }
-                               logWatcher.Msg <- msg
-                       }
+                       return
                }
        }
 }

2. Keep reading the logs till the channel closes in logs consumer:

diff --git a/daemon/logger/logger.go b/daemon/logger/logger.go
index 912e855c7..a5a20d33b 100644
--- a/daemon/logger/logger.go
+++ b/daemon/logger/logger.go
@@ -123,6 +123,13 @@ func (w *LogWatcher) Close() {
        // only close if not already closed
        w.closeOnce.Do(func() {
                close(w.closeNotifier)
+               // make sure to read tail from the channel until it's closed
+               // in order for the writer to not block
+               for {
+                       if _, ok := <-w.Msg; !ok {
+                               return
+                       }
+               }
        })
 }

3. Do both (1) and (2).

I did some limited testing -- both (1) and (2) fixes the issue. Now, here's my humble opinion about those options.

(1) looks scary, as it blatantly removes a chunk of code that presumably is/was useful. Still, I admit I fail to understand the meaning of it -- why is it trying to push some log messages to the consumer if consumer has already signaled it is no longer interested in this? I have traced this code back to commit c0391bf (it is 3 y.o. so I'm not sure anyone remembers), and still can't figure out why.

(2) looks ugly (why the hell do we write useless data in one place and read it in another?). It can only make sense in case of a blocking write (like in line 625 in the code above), but if all the writes are non-blocking and with a proper check for context cancellation, there is no need whatsoever to read junk.

(3) looks redundant; rationale is the same as for (2).

@cpuguy83 PTAL

[cpuguy83]

As I recall, at the time <-WatchClose() would be closed when the container is shutdown, but we still needed to finish up reading the logs and deliver them to the client.

So I think what's happened here is we've mixed up (or potentially merged?) client signaling "I'm done" and container stopping.

[kolyshkin]

Proposed fix: #37576

I am still not sure if it is totally correct and flawless, or whether it breaks anything, but at least it looks like a step in the right direction. Also, I have to admit I never knew logging can be that hard.

[kolyshkin]

Simple but complete test case (requires dockerd to be run with "--debug"):

#!/bin/bash

set -e
set -o pipefail
set -u

numgor() {
	docker info | awk '($1 == "Goroutines:") {print $2; exit}'
}

waitgor() {
	local expected=$1
	local retries=20
	local duration=0.5
	echo -n "Waiting for goroutines to finish "
	while [ $retries -gt 0 ] ; do
		local actual=$(numgor)
		test $actual -le $expected && echo " OK" && return 0
		let retries--
		sleep $duration
		echo -n .
	done
	echo " FAIL"
	echo "Goroutine leak! Expecting <= $expected, got $actual" 1>&2
	return 1
}

CTID=$(docker run -d --network=none busybox sh -c "yes somewhat long line should be here so here it goes")
sleep 1
GOR=$(numgor)

PIDS=
for i in $(seq 1 10); do
	docker logs -f $CTID > /dev/null &
	PIDS="$PIDS $!"
done
sleep 1
kill -9 $PIDS
sleep 1
if ! waitgor $GOR; then
	echo look for leaks with ID $CTID
else
	echo PASS
fi
docker rm -f $CTID >/dev/null

[kolyshkin]

Simple but complete test case (requires dockerd to be run with "--debug"):

Better test case is at aa3bc5a

[kolyshkin]

All version of docker-ce from 17.03 to 18.06 are affected.

[tianon]

FWIW, I think this is probably related to (and thus your PR would fix!) an issue I've seen on Windows where a container can't be deleted because the container logs were followed at some point (and are thus still open and the file cannot be deleted, even though the "consumer" of those followed logs is long gone). 🎉 ❤️

[deinspanjer]

Thank you very much for this fix. We just ran into the problem in production and I'm very glad to find the issue and the fix so well documented.