daemon.ContainerLogs(): fix resource leak on follow

[kolyshkin]

When daemon.ContainerLogs() is called with options.follow=true
(as in docker logs --follow), the loggerutils.followLogs()
function never returns (even then the logs consumer is gone).
As a result, all the resources associated with it (including
an opened file descriptor for the log file being read, two FDs
for a pipe, and two FDs for inotify watch) are never released.

If this is repeated (such as by running docker logs --follow
and pressing Ctrl-C a few times), this results in DoS caused by
either hitting the limit of inotify watches, or the limit of
opened files. The only cure is daemon restart.

Apparently, what happens is:

1. logs consumer is gone, properly calling (*LogWatcher).Close()

2. WatchClose() is properly handled by a dedicated goroutine in
   followLogs(), cancelling the context.

3. Upon receiving the ctx.Done(), the code tries to synchronously
   send the log message to the logWatcher.Msg channel. Since the
   channel reader is gone, this operation blocks forever, and
   resource cleanup set up in defer statements at the beginning
   of followLogs() never happens.

The fix is to remove the synchronous send.

This commit also removes the code after it, which tried to
read and send the rest of the log file. The code in question
first appeared in commit c0391bf ("Split reader interface from
logger interface"), but it is still unclear why it is/was
needed (it makes no sense to write logs once the consumer
signaled it is no longer interested in those).

There are a few alternative approaches to fix the issue,
such as:

a. amend the consumer to read all the data from the channel
until it is closed. This can be done in, say, (*LogWatcher) Close().
For one thing, this looks ugly (why read and write useless data?).
Also, this approach requires closing the channel from the sending
side, which, given the amount of exit paths, looks less elegant
than a solution in this commit.

b. always write to the channel asynchronously (i.e. in a non-blocking
fashion, i.e. inside a select). This is actually what happens
in the code after this commit.

Should fix #37391

image from https://dubikvit.livejournal.com/409094.html

[thaJeztah]

Looks like there's a failure; https://jenkins.dockerproject.org/job/Docker-PRs/50259/console

That test was marked as flaky a couple of times; https://github.com/moby/moby/search?q=TestLogsFollowSlowStdoutConsumer&type=Issues could that flakiness be related?

05:52:22 FAIL: docker_cli_logs_test.go:214: DockerSuite.TestLogsFollowSlowStdoutConsumer
05:52:22 
05:52:22 docker_cli_logs_test.go:246:
05:52:22     c.Assert(actual, checker.Equals, expected)
05:52:22 ... obtained int = 53412
05:52:22 ... expected int = 150000

[kolyshkin]

05:52:22 FAIL: docker_cli_logs_test.go:214: DockerSuite.TestLogsFollowSlowStdoutConsumer

Fortunately I know a bit about this test. OK, so now we know why this code was needed :) Need to think.

[kolyshkin]

Simplest reproducer:

ID=$(docker run -d busybox sh -c "seq 1 100000"); docker logs --follow $ID | tail

Should output something like

...
99998
99999
100000

Instead it outputs:

...
51643
51644
51645

[thaJeztah]

@kolyshkin but that's only with | tail, correct ? (is it because it starts reading while output is still being added, so at that moment 51645 is the last output?)

i.e., this works;

ID=$(docker run -d busybox sh -c "seq 1 100000"); sleep 3; docker logs --follow $ID | tail

And so does this (with a tty attached, so docker logs shows raw terminal output)

ID=$(docker run -dt busybox sh -c "seq 1 100000"); docker logs --follow $ID | tail

[kolyshkin]

Nah, tail is just there to not clutter the terminal; it does not affect test case outcome. What tail does is it reads all the input into a circular buffer (sized N lines, default N is 20) until EOF, then prints the buffer contents.

It seems the problem is logWatcher.Close() is called when a container is stopped, not when a reader is gone. I will sleep on it and hopefully come up with something tomorrow.

[cpuguy83]

logWatcher.Close() is called when the client is gone:

moby/daemon/logs.go

Lines 106 to 114 in e158451

	if cLogCreated {
	defer func() {
	if err = cLog.Close(); err != nil {
	logrus.Errorf("Error closing logger: %v", err)
	}
	}()
	}
	// set up some defers
	defer logs.Close()

Where cLog is the created log driver in cases where the container was already stopped and logs is the log watcher.

So we should not be trying to send logs when the log watcher is closed.
What may need to happen is to make sure to drain the message chan in daemon/logs.go after the log watcher is closed, otherwise we can end up in an easy to trigger race where a message send is happening while we are closing.
The buffer of this channel is also insanely high... a number which was just picked because someone asked for it.... I don't think we need a buffer, or if we do have a buffer it can be very small.

It would also be nice perhaps to change the log reader interface to take a context instead of closing the log watcher, may help simplify some of the logic.

Honestly, there are too many goroutines here (one layer added relatively recently to support swarm logs).

[kolyshkin]

The (*logWatcher).Close() is also called from here:

moby/daemon/logger/jsonfilelog/jsonfilelog.go

Lines 169 to 177 in 09f5e9d

	// Close closes underlying file and signals all readers to stop.
	func (l *JSONFileLogger) Close() error {
	l.mu.Lock()
	l.closed = true
	err := l.writer.Close()
	for r := range l.readers {
	r.Close()
	delete(l.readers, r)
	}

So, it is called twice, once upon container stop, once upon consumer is gone. Whoever calls it first depends on the situation. In this scenario the logger is fast and the consumer is slow(er), so the first call is from container stop, thus (with the commit in this PR) the log consumer does not receive the remainder of the log.

If we comment out this line:

moby/daemon/logger/jsonfilelog/jsonfilelog.go

Line 175 in 09f5e9d

r.Close()

docker logs --follow works fine (with the commit from this PR), but it never exits (which, to my mind, is the correct behavior as the container could be started again, but is different from the current behavior).

For now, it seems like the best behavior would be to distinguish between "container stopped logging" and "logs consumer is gone" events, and act accordingly, i.e:

1. when "logs consumer is gone" received, stop immediately. In order to not have a race, the receiver should be inside the same select as the message sender (I guess).
2. when "container stopped logging" is received, disable the log rotation handling, otherwise continue until EOF.

Unfortunately it further complicates the code, which I wanted to avoid :-\

[codecov]

Codecov Report

❗ No coverage uploaded for pull request base (master@7aa797f). Click here to learn what that means.
The diff coverage is 41.93%.

@@            Coverage Diff            @@
##             master   #37576   +/-   ##
=========================================
  Coverage          ?   36.13%           
=========================================
  Files             ?      609           
  Lines             ?    45056           
  Branches          ?        0           
=========================================
  Hits              ?    16283           
  Misses            ?    26532           
  Partials          ?     2241

[kolyshkin]

It would also be nice perhaps to change the log reader interface to take a context instead of closing the log watcher, may help simplify some of the logic.

We have to react to two distinct events here:

1. logs producer (a container) gone. In this case followLogs() should stop watching for and reacting to logrotate events, and treat EOF as being done, otherwise keep sucking and pushing logs.
2. logs consumer (daemon.ContainerLogs()) gone. In this case we should clean up and be done.

A single context won't be enough here. Sigh :(

[kolyshkin]

OK, a test case DockerSuite.TestLogsFollowGoroutinesNoOutput uncovered a problem that I have fixed (not returning from followLogs() when consumer is gone but log is empty).

TODO: write a test case for #37391

[kolyshkin]

ppc failure on DockerSwarmSuite.TearDownTest is #33041

[kolyshkin]

OK, I removed the fixing commit and added the test case, doing a CI cycle to see if the newly added test case is detecting the issue.

[cpuguy83]

Yeah, so basically it looks like we just need to split notifications up. Would be nice not to modify the log watcher for this.

[kolyshkin]

Yeah, so basically it looks like we just need to split notifications up.
Would be nice not to modify the log watcher for this.

Here's my current solution (will push here once test case is checked to work): kolyshkin@16bc8991a

It is somewhat ugly and big, so I am wide open to any ideas how to make it look better.

[kolyshkin]

OK, fixed the windows CI failure/issue by fixing bugs in pkg/filenotify/poller (see PR #37734). The commits from this PR is currently included in this one, for the sake of Windows CI. Once #37734 is merged I will rebase.

[kolyshkin]

Windows CI failure <...> is apparently fixed by commit b3992ad.

Nope, the real fix is apparently commit 8269ff0dc5c (and that's another issue #27782 masks/workarounds). Anyway, all three fixes to filenotify make some sense.

[kolyshkin]

@cpuguy83 are you aware of any (unit or integration) test cases to check log rotation? As this PR touches that precious code that deals with rotated log files, I want to assess whether it broke something in that area...

[kolyshkin]

ci failures

janky:

01:52:53.778 FAIL: docker_cli_swarm_test.go:1376: DockerSwarmSuite.TestSwarmClusterRotateUnlockKey

power:

01:48:13.817 FAIL: docker_api_swarm_test.go:296: DockerSwarmSuite.TestAPISwarmLeaderElection
02:05:53.173 FAIL: docker_cli_swarm_test.go:1376: DockerSwarmSuite.TestSwarmClusterRotateUnlockKey

z:

01:52:20.860 FAIL: docker_cli_swarm_test.go:1376: DockerSwarmSuite.TestSwarmClusterRotateUnlockKey

• TestSwarmClusterRotateUnlockKey is flaky test: DockerSwarmSuite.TearDownTest on PowerPC #33041
• TestAPISwarmLeaderElection is Flaky test: TestAPISwarmLeaderElection #32673

both are flaky and unrelated to this PR

[kolyshkin]

I think this PR is ready for review/merge

[kolyshkin]

Speaking of log rotation, I was not sure I hadn't broken anything in that area, so I wrote a small test:

ID=$(docker run -d --log-opt=max-size=50K --log-opt=max-file=20 busybox sh -c 'i=0; while test $i -lt 10000; do echo $i; let i++; sleep 0; done')
docker logs --follow $ID | tee $ID.logs | wc -l

If it works, it should print 10000 (number of logs lines received).

It works on current master as well as with the code from this PR. I am not sure if I should make an integration test case out of it, but in any case this can be addressed in a followup.

PS note if I remove sleep 0 the test fails on both branches -- the logs are rotated way to fast to follow. This also means that the above test case has some empirical values built into it, and might not work on a system different from my laptop.

[kolyshkin]

On my laptop, the success of following rotated logs depends on the output rate, not the log rotation rate. I guess it is because most time is spent decoding json :-\

[cpuguy83]

This looks good, minor comment on timeouts in the test.
LGTM

[kolyshkin]

Test timeouts increased; rebased.

[cpuguy83]

LGTM

[kolyshkin]

CI is green 👯‍♂️

[vdemeester]

LGTM 🐯

[thaJeztah]

SGTM, and all green; let's merge 👍