Skip to content

logger: fix follow logs for max-file=1#39969

Merged
cpuguy83 merged 1 commit intomoby:masterfrom
kolyshkin:log-max-file-1-follow
Sep 23, 2019
Merged

logger: fix follow logs for max-file=1#39969
cpuguy83 merged 1 commit intomoby:masterfrom
kolyshkin:log-max-file-1-follow

Conversation

@kolyshkin
Copy link
Copy Markdown
Contributor

@kolyshkin kolyshkin commented Sep 20, 2019

In case jsonlogfile is used with max-file=1 and max-size set,
the log rotation is not performed; instead, the log file is closed
and re-opened with O_TRUNC.

This situation is not handled by the log reader in follow mode,
leading to an issue of log reader being stuck forever.

This situation (file close/reopen) could be handled in waitRead(),
but fsnotify library chose to not listen to or deliver this event
(IN_CLOSE_WRITE in inotify lingo) as it's not portable,
see fsnotify/fsnotify#252.

So, we have to handle this by checking the file size upon receiving
io.EOF from the log reader, and comparing the size with the one received
earlier. In case the new size is less than the old one, the file was
truncated and we need to seek to its beginning.

Fixes #39235. See the steps to verify in that issue.

Description for the changelog

jsonfile logger: Fix lollow logs stuck when max-size is set and max-file=1

In case jsonlogfile is used with max-file=1 and max-size set,
the log rotation is not perfomed; instead, the log file is closed
and re-open with O_TRUNC.

This situation is not handled by the log reader in follow mode,
leading to an issue of log reader being stuck forever.

This situation (file close/reopen) could be handled in waitRead(),
but fsnotify library chose to not listen to or deliver this event
(IN_CLOSE_WRITE in inotify lingo).

So, we have to handle this by checking the file size upon receiving
io.EOF from the log reader, and comparing the size with the one received
earlier. In case the new size is less than the old one, the file was
truncated and we need to seek to its beginning.

Fixes moby#39235.

Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>
@kolyshkin kolyshkin requested a review from cpuguy83 September 20, 2019 23:11
@kolyshkin
Copy link
Copy Markdown
Contributor Author

kolyshkin commented Sep 21, 2019

Did some manual checking using a locally compiled daemon and
cd integration-cli; go test -v -run TestDockerSuite/TestLogs .

Got the same failures before and after the commit, meaning this PR is not breaking anything (still looking at those failures...)

Update: the above was mistakenly done using journald log driver :) Using json-file reveals no failures with or without this PR

@kolyshkin
Copy link
Copy Markdown
Contributor Author

kir@kd:~/go/src/github.com/docker/docker/integration-cli$ go test -v -run TestDockerSuite/TestLogs .
INFO: Testing against a local daemon
=== RUN   TestDockerSuite
=== RUN   TestDockerSuite/TestLogsAPIContainerNotFound
=== RUN   TestDockerSuite/TestLogsAPIFollowEmptyOutput
=== RUN   TestDockerSuite/TestLogsAPINoStdoutNorStderr
=== RUN   TestDockerSuite/TestLogsAPIUntil
=== RUN   TestDockerSuite/TestLogsAPIUntilDefaultValue
=== RUN   TestDockerSuite/TestLogsAPIUntilFutureFollow
=== RUN   TestDockerSuite/TestLogsAPIWithStdout
=== RUN   TestDockerSuite/TestLogsCLIContainerNotFound
=== RUN   TestDockerSuite/TestLogsContainerBiggerThanPage
=== RUN   TestDockerSuite/TestLogsContainerMuchBiggerThanPage
=== RUN   TestDockerSuite/TestLogsContainerSmallerThanPage
=== RUN   TestDockerSuite/TestLogsFollowGoroutinesNoOutput
=== RUN   TestDockerSuite/TestLogsFollowGoroutinesWithStdout
=== RUN   TestDockerSuite/TestLogsFollowSlowStdoutConsumer
=== RUN   TestDockerSuite/TestLogsFollowStopped
=== RUN   TestDockerSuite/TestLogsSeparateStderr
=== RUN   TestDockerSuite/TestLogsSince
=== RUN   TestDockerSuite/TestLogsSinceFutureFollow
=== RUN   TestDockerSuite/TestLogsStderrInStdout
=== RUN   TestDockerSuite/TestLogsTail
=== RUN   TestDockerSuite/TestLogsTimestamps
=== RUN   TestDockerSuite/TestLogsWithDetails
--- PASS: TestDockerSuite (48.19s)
    --- PASS: TestDockerSuite/TestLogsAPIContainerNotFound (0.21s)
    --- PASS: TestDockerSuite/TestLogsAPIFollowEmptyOutput (1.17s)
    --- PASS: TestDockerSuite/TestLogsAPINoStdoutNorStderr (0.99s)
    --- PASS: TestDockerSuite/TestLogsAPIUntil (4.16s)
    --- PASS: TestDockerSuite/TestLogsAPIUntilDefaultValue (1.16s)
    --- PASS: TestDockerSuite/TestLogsAPIUntilFutureFollow (5.09s)
    --- PASS: TestDockerSuite/TestLogsAPIWithStdout (1.15s)
    --- PASS: TestDockerSuite/TestLogsCLIContainerNotFound (0.22s)
    --- PASS: TestDockerSuite/TestLogsContainerBiggerThanPage (1.14s)
    --- PASS: TestDockerSuite/TestLogsContainerMuchBiggerThanPage (1.33s)
    --- PASS: TestDockerSuite/TestLogsContainerSmallerThanPage (1.19s)
    --- PASS: TestDockerSuite/TestLogsFollowGoroutinesNoOutput (1.48s)
    --- PASS: TestDockerSuite/TestLogsFollowGoroutinesWithStdout (1.38s)
    --- PASS: TestDockerSuite/TestLogsFollowSlowStdoutConsumer (1.98s)
    --- PASS: TestDockerSuite/TestLogsFollowStopped (1.12s)
    --- PASS: TestDockerSuite/TestLogsSeparateStderr (1.10s)
    --- PASS: TestDockerSuite/TestLogsSince (7.13s)
    --- PASS: TestDockerSuite/TestLogsSinceFutureFollow (5.99s)
    --- PASS: TestDockerSuite/TestLogsStderrInStdout (1.13s)
    --- PASS: TestDockerSuite/TestLogsTail (1.36s)
    --- PASS: TestDockerSuite/TestLogsTimestamps (6.46s)
    --- PASS: TestDockerSuite/TestLogsWithDetails (1.03s)
PASS
ok  	github.com/docker/docker/integration-cli	48.238s

Copy link
Copy Markdown
Member

@thaJeztah thaJeztah left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

SGTM

should we have a test for this?

@thaJeztah
Copy link
Copy Markdown
Member

ah, I see your comment above; guess that means we can't add a test?

@thaJeztah
Copy link
Copy Markdown
Member

@cpuguy83 ptal

Copy link
Copy Markdown
Member

@cpuguy83 cpuguy83 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

@cpuguy83
Copy link
Copy Markdown
Member

I think a test that's actually testing the problem would be rather difficult.
Maybe if the logger code was instrumented for the test it could work but even then it still seems like it would be flaky.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

'docker logs -f' hangs on logfile rotation with --max-file=1

3 participants