util/log: improvements, simplifications and bug fixes #52200

... for clarity while reading the code. Release note: None

The functions that manage the status of file buffers are all in `sync_buffer.go` now. Release note: None

Prior to this patch, the file logging code would close the current log file before opening a new one. This was problematic, because if opening a new file would fail, there was nothing left over to work with. In particular, if the following conditions all held: - file logging was enabled - internal stderr writes (direct writes to stderr) were redirected to files - some error would occur asynchronously, or a panic initiated inside the Go runtime then the details of the error condition would be written to a now-closed file, and lost. This patch "does the right thing" by opening the new file before switching over whatever redirection may have been set up from the old file to the new one. This incidentally brings us one step closer to reducing the scope of the logger mutex, because with the newer logic it becomes safe(er) to let writes happen asynchronously with the file rotation logic. The commit also adds a few clarifying comments for the existing functions. Release note: None

Prior to this patch, TestLogScope attempted to be too clever for its own good: - it was trying to "do its work" by saving/restoring arbitrarily complex logging configurations. - it was also setting up redirection of stderr writes by the Go runtime (direct writes to fd 2 / os.Stderr, like what servers do). The first point above was complex because of the existence of secondary loggers. The code was also incorrect because it did not properly restore the state of secondary loggers, if they differed from the main logger. The code was also inadequate/surprising because it would take over file logging even if a surrounding test had logging redirected to files already. This is undesirable because, arguably, if testing code has set up file logging already (this is not the default) then the original files are the desired destination for log events. It's not clear that TestLogScope legitimately can take that over. This complexity was thus removed and the doc clarified that TestLogScope is only valid under the default configuration, when there was no file output configured yet and no secondary loggers active yet. The second point above (internal stderr redirect) was overly complex because the TestLogScope.Close() method was trying to "restore" whatever was there when the scope was open, using a stack-like state preservation structure. The problem here is that this code was invalid; the stderr redirection initialization in `SetupRedactionAndStderrRedirects()` really does not work well in recursive contexts. After removing the first point of complexity above (removing the stack-like behavior of TestLogScope), it could be theoretically possible to preserve the redirect of internal stderr writes; without the complexity of state preservation the implementation would likely be simpler. However we also have other reasons to dislike the stderr redirect in tests, so I decided to remove it here instead of conjuring new code. Finally, this patch removes the NoFileTestLogScope which was only good for the `demo` code. Instead of creating API complexity which many readers are bound to find and read about it, this patch transfers the complexity to the two unit tests that need it. Release note: None

Now that TestLogScope is not too clever any more, this test can work properly without error. Release note: None

Prior to this patch, `closeFileLocked()` would inconditionally reset the redirection of internal stderr writes back to the original stderr stream (`OrigStderr`). This was incorrect, because of the existence of secondary loggers. To understand why, consider a setup where client code wants internal stderr writes to be redirected to a logger B, while a non-stderr A logger is active. Then the following sequence can occur: - A creates a file. - B creates a file, and redirects internal stderr writes to it. At this point, the behavior is as expected: stderr writes are redirected. - now the code causes A.closeFileLocked() to be called. This causes the call on A to cancel the effects of the redirects on logger B - that is, unwanted "action at a distance". To correct this, this patch only restores the stderr redirect if the logger was also owning the redirection to start with. Furthermore, the entire idea of "redirecting stderr writes to a file" would be a little confusing if two or more loggers had the boolean set to do it. In that case, two loggers could non-deterministically compete to capture stderr when rotating their files alternatively. In order to clarify the API and prevent client code from accidentally relying on this poorly-defined behavior, the patch adds a new method `takeOverInternalStderr()` which enforces the invariant that at most one logger may take over stderr. Finally, for context, be it known that none of the irregularities fixed by this patch are currently impacting the remainder of the CockroachDB code base: `closeFileLocked()` is only called upon `TestLogScope.Close()`, and the previous patches in this sequence have ensured that no stderr is being redirected in the context of a TestLogScope. This patch thus only exists for the benefit of future uses of the API, or readers of the code. Release note: None

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

util/log: improvements, simplifications and bug fixes #52200

util/log: improvements, simplifications and bug fixes #52200

Commits on Aug 5, 2020