Fix bug in log framer only affecting Windows #3608

schmichael · 2017-12-01T05:45:44Z

Manually tested on Windows and Linux using the reproducer attached to #3342 on Windows. Although there's nothing special about the job: streaming logs from any job on Windows would cause the issue.

The root cause is that a super subtle misused variable bug in parseFramerError would cause a nil error to be returned to after the framer had exited. HTTPServer.logs would see the nil error and think it should continue, but since the framer had exited it would immediately return an error which parseFramerError would again discard and the loop would repeat.

Normally this sort of tight loop would merely consume a single cpu core and be a nuisance. However this loop spawned a goroutine which would very quickly consume all memory until Nomad itself would OOM.

The 4 commits actually contain distinct fixes:

88cb8bb updates some very old dependencies. I was hoping that would fix it, but it did not. Therefore I'm happy to remove this commit, but I think keeping these deps up to date is ideal.
ac3fffc fixes at least 2 races in StreamFramer, however, I did not see any evidence either was hit.
ac3fffc also fixes the error handling bug in parseFramerError 👈
13a69bd is purely defensive code that should not be hit. I hate adding code like that and will remove if asked. I added it in this case because the surrounding code is extremely brittle and it would be extremely easy to cause The nomad logs -f command can make windows clients unresponsive/crash. #3342 another way without this safety check.
b4bacd6 adds a check for Windows special flavor of "connection closed" error. I looked and looked and found no other way to detect it other than that string comparison. It merely squelches an error from being logged, so the worst case scenario isn't so bad if the string is sometimes wrong (it worked in my testing).

Fixes #3342 Two bugs were fixed: * Closing the StreamFramer's exitCh before setting the error means other goroutines blocked on exitCh closing could see the error as nil. This was *not* observered. * parseFramerError on Windows would fall through and return an improperly captured nil err variable. There's no need for parseFramerError to be a closure which fixes the confusion.

I hate adding "this should never happen" checks, but causing a tight loop that OOMs Nomad is just too easy in this code otherwise.

chelseakomlo

Looks good! A couple questions about concurrency and where logic should be for translating the error type.

chelseakomlo · 2017-12-01T17:27:40Z

command/agent/fs_endpoint.go

@@ -466,8 +473,8 @@ func (s *StreamFramer) Send(file, fileEvent string, data []byte, offset int64) e
 	// If we are not running, return the error that caused us to not run or
 	// indicated that it was never started.
 	if !s.running {
-		if s.Err != nil {
-			return s.Err
+		if s.err != nil {


Should this be s.Err()? Otherwise add a comment about why this can be accessed directly.

Same for line 477

This method holds the appropriate lock (L470)

chelseakomlo · 2017-12-01T17:31:41Z

command/agent/fs_endpoint.go

+		select {
+		case <-framer.ExitCh():
+			err := parseFramerErr(framer.Err())
+			if err == syscall.EPIPE {


Can this logic be in parseFramerErr instead, since it already has logic related to translating errors? I.e, does the caller need to do the translation of syscall.EPIPE -> nil error directly?

it returns the error from parseFramerErr in line 740, but has this extra logic here where it turns that to nil. Good question though - why do we treat the error two different ways?

Reading this again, I am not convinced this block is necessary (saw your comment about defensive code). But if its here, I would make it return the value of parseFramerErr rather than nil to make handling exit channel events identical in both cases.

This change makes more sense in the actual code and not in the code review I promise. :) The code review cuts out the code 10 lines up that follow similar return behavior when handling the error from s.stream()

The error returned from s.stream() is already passed through parseFramerErr(), then line 924 converts EPIPE to nil in this func.

So this defensive code converts the framer error with the helper func and then follows the same if err == EPIPE { return nil } behavior as above.

Sorry the code is obtuse but the good news is that it only determines whether or not an error is logged when a client disconnects (EPIPE errors are not logged as they're expected).

The important thing in this defensive code is that we return from this infinite for{} loop if the framer has exited. The error code only matters for logging.

chelseakomlo · 2017-12-01T17:35:43Z

command/agent/fs_endpoint.go

 		s.l.Lock()
 		s.running = false
-		s.Err = err
+		s.err = err


Should this be set using a SetErr() method that has guards against concurrent access?

The appropriate lock is acquired on L394 and this should be the only place that sets s.err so I don't want to add a helper to encourage other uses.

dadgar · 2017-12-05T00:21:29Z

Does this fix: #2840?

schmichael · 2017-12-08T01:22:55Z

Does this fix: #2840?
@dadgar

I'm unsure. It sounds the same, but I could only reproduce this bug on Windows. Only 16 of the 120 goroutines listed in the snippet of output include the telltale blockUntilNextLog function that dominated the vast majority of the goroutines in this case.

github-actions · 2023-03-16T02:15:34Z

I'm going to lock this pull request because it has been closed for 120 days ⏳. This helps our maintainers find and focus on the active contributions.
If you have found a problem that seems related to this change, please open a new issue and complete the issue template so we can capture all the details necessary to investigate further.

schmichael added 4 commits November 30, 2017 15:52

Update tail, x/sys, and fsnotify deps

88cb8bb

Add defensive check to safeguard from future #3342s

13a69bd

I hate adding "this should never happen" checks, but causing a tight loop that OOMs Nomad is just too easy in this code otherwise.

Add check for Windows ECONNRESET

b4bacd6

chelseakomlo suggested changes Dec 1, 2017

View reviewed changes

Add changelog entry for #3608

e99a5f3

dadgar approved these changes Dec 5, 2017

View reviewed changes

schmichael merged commit 0921368 into master Dec 8, 2017

schmichael deleted the b-3342-windows-log-leak branch December 8, 2017 18:59

github-actions bot locked as resolved and limited conversation to collaborators Mar 16, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix bug in log framer only affecting Windows #3608

Fix bug in log framer only affecting Windows #3608

schmichael commented Dec 1, 2017

chelseakomlo left a comment

chelseakomlo Dec 1, 2017

chelseakomlo Dec 1, 2017

schmichael Dec 1, 2017

chelseakomlo Dec 1, 2017

preetapan Dec 4, 2017

preetapan Dec 4, 2017 •

edited

Loading

schmichael Dec 8, 2017

chelseakomlo Dec 1, 2017

schmichael Dec 1, 2017

dadgar commented Dec 5, 2017

schmichael commented Dec 8, 2017

github-actions bot commented Mar 16, 2023

Fix bug in log framer only affecting Windows #3608

Fix bug in log framer only affecting Windows #3608

Conversation

schmichael commented Dec 1, 2017

chelseakomlo left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

preetapan Dec 4, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dadgar commented Dec 5, 2017

schmichael commented Dec 8, 2017

github-actions bot commented Mar 16, 2023

preetapan Dec 4, 2017 •

edited

Loading