Repository navigation
Add size based log rotation to butil logging - #3687
Open
Sherlock0203 wants to merge 5 commits into
Open
Sherlock0203 wants to merge 5 commits into
Sherlock0203 wants to merge 5 commits into
Conversation
Add --log_rotate_size_mb (0, disabled by default) and --log_rotate_max_backups (10). When the current log file is about to grow beyond the limit it is renamed to "<log_file>.1", the older backups are shifted down and the ones beyond the limit are removed, so ".1" is always the most recent backup. The check lives in Log2File(), the single funnel of both DefaultLogSink and AsyncLogger::DoLog, so rotation covers synchronous and asynchronous logging alike and stays orthogonal to any later LogStream refactor. The file is opened in append mode, so its initial size is read with fstat()/GetFileSizeEx() instead of being counted from zero. A log larger than the limit is written as a whole rather than producing empty backups. The size that triggered a failed rotation does not change by itself, so retrying on the next log would close, reopen and rename the file for every single log. Instead the size at which rotation failed is remembered and rotation is retried once the file has grown by another --log_rotate_size_mb, with the error printed once rather than per log. A file smaller than it was at that point has been replaced from the outside, which lets rotation resume immediately. Sharing one log file between several processes is not supported together with rotation and is documented as such: on POSIX LoggingLock only serializes the threads of a single process, and after the rename the other processes would keep writing to the renamed inode. Running an external rotator such as logrotate on the same file is unsupported for the same reason.
Review fixes for the size based log rotation of apache#2696: The shift of the backups ignored the result of every rename, so when ".1" could not be moved to ".2" (a tail tool holding the backup open on Windows, a non-empty directory on the slot) the final rename went on anyway and silently replaced ".1" with the current file: every rotation dropped a generation while being accounted as a success. A shift that fails now aborts the rotation through the back off path and leaves every backup in place. The shift also renamed one index per --log_rotate_max_backups, which is only validated to be a positive int. A huge value turned every rotation into as many rename() calls under the logging lock, stalling both synchronous and asynchronous logging for minutes. Backups are numbered contiguously, so the highest existing one is probed and only the existing files are shifted. A rotation failure was never printed on Windows, and a log file that disappeared from under the process reset the back off: the ".\debug.log" that Windows falls back to when the requested name cannot be opened was then closed and reopened on every single log once over the limit. The error is now printed on every platform through SystemErrorCodeToString() and PathAsString(), and the disappeared file backs off too; the fresh file reopened under the original name is smaller, which lets rotation resume right away. LogRotationTest pointed the global logging destination at its temp file and never restored it: once CloseLogFile() had closed the handle, every later suite of test_butil appended to a file under that path and lost its stderr, leaving stray temp_file_XXXXXX files in the run directory. TearDown() now restores the default destination and also removes the obstacle directories that a failed test may leave behind. New tests: a failed shift keeps the newest backup (rotation resumes once the obstacle is gone); a huge --log_rotate_max_backups stays fast; threads logging synchronously through rotations lose and duplicate no log. docs/cn and docs/en now state that a backup which cannot be moved stops the rotation instead of being overwritten. StackTraceTest.find_symbol fails on the base commit of this branch (efef0e6) as well: pre-existing environment issue, unrelated.
Fix silent backup loss and test pollution in log rotation
InitializeLogFileHandle() also succeeds without opening anything when the destination no longer logs to a file, and Log2File() only looked at the return value: an async log that was still in the queue when a later InitLogging() moved the destination away from the file was written through a null FILE* and took the whole process down. The clang-unittest CI hit it through LogRotationTest::TearDown(), which restores the default destination: on builds with the cpu profiler enabled, LoggingTest.performance leaves millions of logs in the queue and the background thread keeps flushing them long after the test is over. The write is skipped when there is no handle to write through, the way MaybeRotateLogFileUnlocked() already checks. The queue draining behind the tests has a second effect: those logs go to whichever file is current, rotating it from under the assertions of the rotation tests that follow. LogRotationTest::SetUp() now drains the queue into the temp file first, with rotation on to bound the disk usage, and waits until the file stops growing, which costs a single stat() poll when the queue is already idle. A regression test reproduces the crash sequence (async backlog, CloseLogFile(), destination change) and the fixture now also saves and restores --async_log_in_background_always.
Fix crash on async logs flushed after the destination changed
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
What problem does this PR solve?
Issue Number: resolve #2696
Problem Summary:
butil ships a logging implementation that services can already run in
production, but it had no rotation: a long-running process kept appending
to a single file until the disk filled, so users had to move to glog or
run an external logrotate beside it. Issue #2696 asks whether butil
logging is meant to be production ready; this adds the missing rotation
so that it can be used standalone.
What is changed and the side effects?
Changed:
Two new gflags, both changeable at run time via
/flags:--log_rotate_size_mb(default 0, rotation off): rotate the log fileonce it is about to grow beyond this size in megabytes. Only takes
effect when logging to a file.
--log_rotate_max_backups(default 10): number of rotated files keptbesides the current one.
When the limit is reached, the current file is renamed to
<log_file>.1, the older backups shift down (.1->.2-> ...) andthe ones beyond the limit are removed, so
.1is always the most recentbackup. Lowering
--log_rotate_max_backupsat run time also removes thefiles left over from the previous, larger value.
Design notes:
Log2File(), the single funnel of bothDefaultLogSinkandAsyncLogger::DoLog, so rotation coverssynchronous and asynchronous logging alike.
starts from is read with
fstat()/GetFileSizeEx()instead of beingcounted from zero.
two files; an empty file is never rotated, so a log larger than the
limit is written as a whole instead of producing empty backups.
the size at which it failed is remembered and rotation is retried once
the file has grown by another
--log_rotate_size_mb, with the errorprinted once, naming the rename that failed and why. Logs keep being
appended to the current file in the meantime.
it open, a directory sits on the slot) stops the rotation instead of
being overwritten with the current file, so no generation is silently
dropped.
has been replaced or truncated from the outside, and rotation resumes
immediately.
the handle is closed so that the next write starts a fresh file, and
the backups are left untouched.
--log_rotate_max_backups(only validated to be a positive int) stillcosts a handful of rename() calls per rotation rather than one per
index, all under the logging lock.
Docs:
docs/en/streaming_log.mdanddocs/cn/streaming_log.mddescribethe two flags and the failure handling. Sharing one log file between
several processes, and running an external rotator such as logrotate on
the same file, are documented as unsupported together with rotation.
Side effects:
Performance effects: rotation is off by default; with
--log_rotate_size_mb=0the only addition on the write path is a flagcheck. When enabled, each log additionally updates a size counter, and
each rotation performs a bounded number of rename()/unlink() calls
(only the existing backups) while holding the logging lock.
Breaking backward compatibility: none. Rotation is disabled by
default, so existing deployments see no change in file names or file
contents. The two flags are new, all new code lives in the anonymous
namespace of
logging.cc, and there is no header or API change.Tests
13 new cases in
test/logging_unittest.cc(LogRotationTest):rotation and pruning, keeping one backup, a single log larger than the
limit, taking the size of an existing file into account after a restart,
async logging, lowering
--log_rotate_max_backupsat run time, externalrename of the current file, backing off while rotation keeps failing,
recovery after the file is replaced from the outside, a failed shift
keeping the newest backup, a huge
--log_rotate_max_backupsstaying fast(1e8, a handful of backups, ~11ms for several rotations), and 8 threads
logging synchronously through rotations without losing, duplicating or
tearing a single log.