tracing-appender 0.2.1 panics while rolling in debug mod #1987
Comments
|
And, this code: impl io::Write for RollingFileAppender {
fn write(&mut self, buf: &[u8]) -> io::Result<usize> {
let now = OffsetDateTime::now_utc().to_offset(self.offset);
let writer = self.writer.get_mut();
if self.state.should_rollover(now) {
let _did_cas = self.state.advance_date(now);
debug_assert!(_did_cas, "if we have &mut access to the appender, no other thread can have advanced the timestamp...");
self.state.refresh_writer(now, writer);
}
writer.write(buf)
}Should After advance_date, the debug_assert in refresh_writer may fail and cause a panic. |
|
Looking at this code, I believe the |
hawkw
added a commit
that referenced
this issue
Mar 12, 2022
This reproduces the bug described in #1987 Signed-off-by: Eliza Weisman <[email protected]>
hawkw
added a commit
that referenced
this issue
Mar 12, 2022
This branch fixes a bug in `RollingFileAppender` where `compare_exchange` is called with the _current timestamp_ as the "current value" of the next rollover timestamp, rather than the actual current value. This means that if the current time is *greater* than the rollover time, the CAS will fail and the appender will never roll over --- currently, rolling only functions correctly if we try to write to the file at *precisely* the rollover time. This means that, in practice, the appender almost never rolls over. I've fixed this by ensuring that the compare-and-swap is always performed with the current value of the atomic, rather than the current timestamp. `should_rollover` now returns an `Option` with the current value in it to indicate it's time to roll over, so that we perform the CAS with the value loaded in `should_rollover`. Fixes #1987
|
I think I encountered the same panic after leaving the server/app idle for like an hour (or few?), running on both x86_64 OSX and x86_64 CentOS 7: Here is my setup: #[tokio::main]
async fn main() {
// initialize tracing
let file_appender: RollingFileAppender =
tracing_appender::rolling::hourly("/path/to/logdir", "logfile");
let (non_blocking, _guard) = tracing_appender::non_blocking(file_appender);
let level: Level = Level::from_str("DEBUG").unwrap();
tracing_subscriber::fmt()
.with_writer(non_blocking)
.with_max_level(level)
.init();
// ...
} |
hansonchar
pushed a commit
to hansonchar/tracing
that referenced
this issue
Mar 12, 2022
This branch fixes a bug in `RollingFileAppender` where `compare_exchange` is called with the _current timestamp_ as the "current value" of the next rollover timestamp, rather than the actual current value. This means that if the current time is *greater* than the rollover time, the CAS will fail and the appender will never roll over --- currently, rolling only functions correctly if we try to write to the file at *precisely* the rollover time. This means that, in practice, the appender almost never rolls over. I've fixed this by ensuring that the compare-and-swap is always performed with the current value of the atomic, rather than the current timestamp. `should_rollover` now returns an `Option` with the current value in it to indicate it's time to roll over, so that we perform the CAS with the value loaded in `should_rollover`. Fixes tokio-rs#1987
|
#1989 will fix this! |
hawkw
added a commit
that referenced
this issue
Mar 13, 2022
This branch fixes a bug in `RollingFileAppender` where `compare_exchange` is called with the _current timestamp_ as the "current value" of the next rollover timestamp, rather than the actual current value. This means that if the current time is *greater* than the rollover time, the CAS will fail and the appender will never roll over --- currently, rolling only functions correctly if we try to write to the file at *precisely* the rollover time. This means that, in practice, the appender almost never rolls over. I've fixed this by ensuring that the compare-and-swap is always performed with the current value of the atomic, rather than the current timestamp. `should_rollover` now returns an `Option` with the current value in it to indicate it's time to roll over, so that we perform the CAS with the value loaded in `should_rollover`. I've also added a test that exercises a file rollover using a mock time. This would have caught the bug described in #1987. Fixes #1987 Signed-off-by: Eliza Weisman <[email protected]>
|
Testing so far is positive - the pull request seems to have fixed this issue. Thanks! |
davidbarsky
pushed a commit
that referenced
this issue
Mar 17, 2022
This branch fixes a bug in `RollingFileAppender` where `compare_exchange` is called with the _current timestamp_ as the "current value" of the next rollover timestamp, rather than the actual current value. This means that if the current time is *greater* than the rollover time, the CAS will fail and the appender will never roll over --- currently, rolling only functions correctly if we try to write to the file at *precisely* the rollover time. This means that, in practice, the appender almost never rolls over. I've fixed this by ensuring that the compare-and-swap is always performed with the current value of the atomic, rather than the current timestamp. `should_rollover` now returns an `Option` with the current value in it to indicate it's time to roll over, so that we perform the CAS with the value loaded in `should_rollover`. I've also added a test that exercises a file rollover using a mock time. This would have caught the bug described in #1987. Fixes #1987 Signed-off-by: Eliza Weisman <[email protected]>
hawkw
added a commit
that referenced
this issue
Mar 17, 2022
This branch fixes a bug in `RollingFileAppender` where `compare_exchange` is called with the _current timestamp_ as the "current value" of the next rollover timestamp, rather than the actual current value. This means that if the current time is *greater* than the rollover time, the CAS will fail and the appender will never roll over --- currently, rolling only functions correctly if we try to write to the file at *precisely* the rollover time. This means that, in practice, the appender almost never rolls over. I've fixed this by ensuring that the compare-and-swap is always performed with the current value of the atomic, rather than the current timestamp. `should_rollover` now returns an `Option` with the current value in it to indicate it's time to roll over, so that we perform the CAS with the value loaded in `should_rollover`. I've also added a test that exercises a file rollover using a mock time. This would have caught the bug described in #1987. Fixes #1987 Signed-off-by: Eliza Weisman <[email protected]>
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Bug Report
Version
├── tracing v0.1.31
│ ├── tracing-attributes v0.1.19 (proc-macro)
│ └── tracing-core v0.1.22
├── tracing-appender v0.2.1
│ └── tracing-subscriber v0.3.9
│ ├── tracing v0.1.31 ()
│ ├── tracing-core v0.1.22 ()
│ └── tracing-log v0.1.2
│ └── tracing-core v0.1.22 ()
├── tracing-log v0.1.2 ()
└── tracing-subscriber v0.3.9 (*)
Platform
Darwin clia-mbp-2.local 21.3.0 Darwin Kernel Version 21.3.0: Wed Jan 5 21:37:58 PST 2022; root:xnu-8019.80.24~20/RELEASE_X86_64 x86_64
Crates
tracing-appender
Description
I tried this code:
Then it panics while rolling file.
RUST_BACKTRACE=full
In advance_date fn I print some time info:
And it outputs:
nowis not equal toself.next_date.Wish this information is helpful!
The text was updated successfully, but these errors were encountered: