Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Merged
merged 1 commit into from
Sep 23, 2019

Conversation

kolyshkin
Copy link
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
Copy link
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
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
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
Member

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

@thaJeztah
Copy link
Member

@cpuguy83 ptal

Copy link
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
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