Fix windows log file rotation with readers by cpuguy83 · Pull Request #41100 · moby/moby

cpuguy83 · 2020-06-12T23:04:40Z

This fixes the case where log rotation fails on Windows while there are
clients reading container logs.

thaJeztah · 2020-06-15T13:41:55Z

Seeing some failures on Windows RS5;

=== RUN   TestReadLog/tail_exact
    --- FAIL: TestReadLog/tail_exact (0.00s)
        local_test.go:146: assertion failed: error is not nil: error opening rotated log file: error opening file: The system cannot find the file specified.

=== RUN   TestReadLog/tail_less_than_available
    --- FAIL: TestReadLog/tail_less_than_available (0.00s)
        local_test.go:156: assertion failed: error is not nil: error opening rotated log file: error opening file: The system cannot find the file specified.

=== RUN   TestReadLog/tail_more_than_available
    --- FAIL: TestReadLog/tail_more_than_available (0.00s)
        local_test.go:164: assertion failed: error is not nil: error opening rotated log file: error opening file: The system cannot find the file specified.

cpuguy83 · 2020-06-15T23:29:20Z

I see the problem. It's an error handling issue with openFile

cpuguy83 · 2020-06-15T23:39:27Z

Should be fixed now.

thaJeztah · 2020-06-16T11:03:02Z

Hmm.. one failure remaining on RS5;

=== RUN   TestCheckCapacityAndRotate
--- FAIL: TestCheckCapacityAndRotate (0.01s)
    logfile_test.go:294: assertion failed: error is not nil: rename C:\Users\ContainerAdministrator\AppData\Local\Temp\TestCheckCapacityAndRotate612011099\log214931454 C:\Users\ContainerAdministrator\AppData\Local\Temp\TestCheckCapacityAndRotate612011099\log214931454.1: Access is denied.

cpuguy83 · 2020-06-17T17:21:37Z

I do not know why this is failing now... It didn't fail until I changed to not wrap the error from open...

cpuguy83 · 2020-07-14T19:24:16Z

Ok, so I had to change the this to evict log readers when there is an error rotating files.
I found that in this scenario:

Client opens log stream
Rotation occurs
Rotation occurs again

On step 3, the rotation will fail when it is trying to rename the current file.
It will either get an "Access is denied" error, or "file is being used by another process" error.

So on step 3, when an error occurs, it will evict readers and try again (a few times until successful || max retries).

The thinking here is allowing the container to make progress is more important than the log reader reading the logs.
We can't really seamlessly transfer the log reader without dropping logs anyway, so take the simpler route and have the client reconnect.
We pass the eviction error along to the client.

Without this change, log rotation is essentially broken on Windows if there are active log consumers.

cpuguy83 · 2020-07-15T00:18:24Z

Added a 2nd commit to fix some race conditions in the loggerutils tests.
Additionally, I think I fixed the flakey test. See commit for details.

thaJeztah · 2020-07-15T17:37:24Z

@kevpar @kolyshkin ptal

cpuguy83 · 2020-07-15T18:08:43Z

And split up commits for easier review.

cpuguy83 · 2020-07-17T23:09:03Z

All green.

thaJeztah · 2020-07-31T19:26:43Z

@kevpar @kolyshkin ptal

thaJeztah · 2020-08-24T09:26:15Z

@kolyshkin nits are addressed; PTAL

thaJeztah · 2020-08-31T08:53:22Z

@kevpar @kolyshkin @tonistiigi ptal

kevpar · 2020-08-31T18:44:16Z

I don't have much context on this code, but the issue I'm aware of should be fixed by switching to do file opens with FILE_SHARE_DELETE. It looks like this PR consistently uses the open/openFile wrappers which do so, so LGTM.

thaJeztah

overall seems good; left one comment/suggestion (as discussed)

Found by running with `go test -race` Signed-off-by: Brian Goff <[email protected]>

- Ignore some pointless errors (like not exist on remove) - Consolidate error handling/logging - Fix race condition reading last log timestamp in the compression goroutine. This needs to be done while holding the write lock, which is not (or may not be) locked while compressing a rotated log file. - Remove some indentation and consolidate mutex unlocking in `compressFile` Signed-off-by: Brian Goff <[email protected]>

This makes sure, on Windows, that all files are opened with FILE_SHARE_DELETE. On non-Windows this just calls the same `os.Open()`. Signed-off-by: Brian Goff <[email protected]>

This fixes the case where log rotation fails on Windows while there are clients reading container logs. Evicts readers if there is an error during rotation and try rotation again. This is needed for Windows with this scenario: 1. `docker logs -f` is called 2. Log rotation occurs (log.txt -> log.txt.1, truncate and re-open log.txt) 3. Log rotation occurs again (rm log.txt.1, log.txt -> log.txt.1) On step 3, before this change, the log rotation will fail with `Access is denied`. In this case, what we have is a reader holding a file handle to the primary log file. The log file is then rotated, but the reader still has a the handle open. `FILE_SHARE_DELETE` allows this to happen... but then we try to do it again for the next rotation and it blows up. So when it blows up we force all the readers to disconnect, close the log file, and try rotation again, which will succeed based on the added tests. Signed-off-by: Brian Goff <[email protected]>

thaJeztah

LGTM if green

cpuguy83 · 2020-10-30T00:31:57Z

All green!

StefanScherer

LGTM

tonistiigi

sgtm

tianon · 2020-11-05T19:54:58Z

+	} else {
+		var renameErr error
+		for i := 0; i < 10; i++ {
+			if renameErr = os.Rename(fname, fname+".1"); renameErr != nil && !os.IsNotExist(renameErr) {


~~If fname.1 already exists, this will potentially be the same issue, right? Should this use i or i+1 instead?~~
(Sorry I'm not more familiar with this code to know whether this even makes sense 🙈)

Discussed on maintainer call, this isn't relevant. 👍

cpuguy83 added area/logging platform/windows kind/bugfix PR's that fix bugs labels Jun 12, 2020

cpuguy83 mentioned this pull request Jun 12, 2020

Windows log rotation errors with active readers #40999

Closed

thaJeztah added the status/2-code-review label Jun 15, 2020

cpuguy83 force-pushed the windows_fix_rename_open_file branch from 5ae6d1c to aa8a4e8 Compare June 15, 2020 23:38

cpuguy83 force-pushed the windows_fix_rename_open_file branch from aa8a4e8 to fdeba53 Compare July 14, 2020 19:15

cpuguy83 force-pushed the windows_fix_rename_open_file branch 4 times, most recently from dedf05d to dd491c4 Compare July 15, 2020 00:16

cpuguy83 force-pushed the windows_fix_rename_open_file branch from dd491c4 to 0c548d7 Compare July 15, 2020 00:18

cpuguy83 requested a review from kolyshkin July 15, 2020 16:13

cpuguy83 force-pushed the windows_fix_rename_open_file branch from 0c548d7 to 0a1613c Compare July 15, 2020 18:08

cpuguy83 force-pushed the windows_fix_rename_open_file branch 2 times, most recently from edc0b7d to df66c91 Compare July 15, 2020 19:24

cpuguy83 mentioned this pull request Jul 20, 2020

Fix log file rotation test. #41239

Merged

kolyshkin reviewed Jul 31, 2020

View reviewed changes

Comment thread daemon/logger/loggerutils/logfile.go Outdated

kolyshkin reviewed Jul 31, 2020

View reviewed changes

Comment thread daemon/logger/loggerutils/logfile.go Outdated

cpuguy83 force-pushed the windows_fix_rename_open_file branch from df66c91 to 3366557 Compare August 20, 2020 19:14

thaJeztah added this to the 20.10.0 milestone Oct 20, 2020

thaJeztah reviewed Oct 22, 2020

View reviewed changes

Comment thread daemon/logger/loggerutils/logfile.go Outdated

thaJeztah reviewed Oct 22, 2020

View reviewed changes

cpuguy83 added 3 commits October 28, 2020 20:36

Fix various race conditions in loggerutils

3148a46

Found by running with `go test -race` Signed-off-by: Brian Goff <[email protected]>

Fix logfile to open all files with custom openFile

bcc993b

This makes sure, on Windows, that all files are opened with FILE_SHARE_DELETE. On non-Windows this just calls the same `os.Open()`. Signed-off-by: Brian Goff <[email protected]>

cpuguy83 force-pushed the windows_fix_rename_open_file branch from 3366557 to 6d65088 Compare October 28, 2020 20:43

cpuguy83 force-pushed the windows_fix_rename_open_file branch from 6d65088 to b102d46 Compare October 29, 2020 18:39

thaJeztah approved these changes Oct 29, 2020

View reviewed changes

StefanScherer approved these changes Nov 3, 2020

View reviewed changes

tonistiigi approved these changes Nov 5, 2020

View reviewed changes

tianon reviewed Nov 5, 2020

View reviewed changes

tianon merged commit 761066f into moby:master Nov 5, 2020

Conversation

cpuguy83 commented Jun 12, 2020 • edited by thaJeztah Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

thaJeztah commented Jun 15, 2020

Uh oh!

cpuguy83 commented Jun 15, 2020

Uh oh!

cpuguy83 commented Jun 15, 2020

Uh oh!

thaJeztah commented Jun 16, 2020

Uh oh!

cpuguy83 commented Jun 17, 2020

Uh oh!

cpuguy83 commented Jul 14, 2020

Uh oh!

cpuguy83 commented Jul 15, 2020

Uh oh!

thaJeztah commented Jul 15, 2020

Uh oh!

cpuguy83 commented Jul 15, 2020

Uh oh!

cpuguy83 commented Jul 17, 2020

Uh oh!

thaJeztah commented Jul 31, 2020

Uh oh!

Uh oh!

Uh oh!

thaJeztah commented Aug 24, 2020

Uh oh!

thaJeztah commented Aug 31, 2020

Uh oh!

kevpar commented Aug 31, 2020

Uh oh!

Uh oh!

thaJeztah left a comment

Choose a reason for hiding this comment

Uh oh!

thaJeztah left a comment

Choose a reason for hiding this comment

Uh oh!

cpuguy83 commented Oct 30, 2020

Uh oh!

StefanScherer left a comment

Choose a reason for hiding this comment

Uh oh!

tonistiigi left a comment

Choose a reason for hiding this comment

Uh oh!

tianon Nov 5, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

7 participants

cpuguy83 commented Jun 12, 2020 •

edited by thaJeztah

Loading

tianon Nov 5, 2020 •

edited

Loading