feat(appender): size-based rotation #2497
Conversation
CBenoit
force-pushed
the
master
branch
3 times, most recently
from
ca239d7 to
216ece8
Compare
|
CI is failing with: I believe this is unrelated to the changes in this PR. |
CBenoit
changed the title
|
This patch adds size-based rotation as an option. I think it is good enough to have a truncated log between files. The CI problems don't come for this patch. Thank you @CBenoit for this contribution, |
tracing-appender/src/rolling.rs
Outdated
| pub struct RollingWriter<'a>(RwLockReadGuard<'a, File>); | ||
| pub struct RollingWriter<'a> { | ||
| inner: RwLockReadGuard<'a, File>, | ||
| current_size: Arc<AtomicU64>, |
There was a problem hiding this comment.
@CBenoit, thank you very much for the feature. RollingWriter borrows RollingFileAppender, looks like there might be current_size: &'a AtomicU64 instead of Arc. It allows also us to avoid Arc in Inner.
There was a problem hiding this comment.
You’re probably right, I’ll try that!
tracing-appender/src/rolling.rs
Outdated
| } | ||
|
|
||
| /// Provides a daily and size-based rotation. | ||
| pub const fn daily_with_max_bytes(number_of_bytes: u64) -> Self { |
There was a problem hiding this comment.
Hi! I think <minutely|hourly>_with_max_bytes functions will be useful.
There was a problem hiding this comment.
Sure, I’ll add this.
|
I rebased on master and addressed the comments |
tracing-appender/src/rolling.rs
Outdated
| /// Provides a minutely and size-based rotation. | ||
| pub const fn minutely_with_max_bytes(number_of_bytes: u64) -> Self { | ||
| Self { | ||
| timed: Timed::Minutely, | ||
| max_bytes: Some(number_of_bytes), | ||
| } | ||
| } | ||
|
|
||
| /// Provides a hourly and size-based rotation. | ||
| pub const fn hourly_with_max_bytes(number_of_bytes: u64) -> Self { | ||
| Self { | ||
| timed: Timed::Hourly, | ||
| max_bytes: Some(number_of_bytes), | ||
| } | ||
| } | ||
|
|
||
| /// Provides a daily and size-based rotation. | ||
| pub const fn daily_with_max_bytes(number_of_bytes: u64) -> Self { | ||
| Self { | ||
| timed: Timed::Daily, | ||
| max_bytes: Some(number_of_bytes), | ||
| } |
There was a problem hiding this comment.
to reduce the total number of functions in the API, what do you think about just having a .with_max_bytes function taking an existing Rotation and adding a byte limit? so,
| /// Provides a minutely and size-based rotation. | |
| pub const fn minutely_with_max_bytes(number_of_bytes: u64) -> Self { | |
| Self { | |
| timed: Timed::Minutely, | |
| max_bytes: Some(number_of_bytes), | |
| } | |
| } | |
| /// Provides a hourly and size-based rotation. | |
| pub const fn hourly_with_max_bytes(number_of_bytes: u64) -> Self { | |
| Self { | |
| timed: Timed::Hourly, | |
| max_bytes: Some(number_of_bytes), | |
| } | |
| } | |
| /// Provides a daily and size-based rotation. | |
| pub const fn daily_with_max_bytes(number_of_bytes: u64) -> Self { | |
| Self { | |
| timed: Timed::Daily, | |
| max_bytes: Some(number_of_bytes), | |
| } | |
| /// Adds a maximum size limit to an existing `Rotation`. | |
| /// | |
| /// The new `Rotation` will rotate the log file when the log file reaches | |
| /// the specified size limit, or when the rotation period elapses, whichever | |
| /// occurs first. | |
| pub const fn with_max_bytes(self, number_of_bytes: u64) -> Self { | |
| Self { | |
| max_bytes: Some(number_of_bytes), | |
| ..self | |
| } | |
| } |
There was a problem hiding this comment.
This sounds good to me!
|
In my last commit, I addressed an issue I had with this patch: the overly specific date formatting was causing a new file to be created on start, always. So instead, I now insert an index into the file name allowing rotation when the max size is reached without conflicting with an already existing file whose name happened to be the same because of the formatting. Also, when the most recent file does not exceed the max size, we simply reuse it instead of creating yet another file. Here is how it looks like when I run my program repeatedly the same day: Note that even when the timed rotation is set to "never", the date is still inserted using the daily date format anyway. |
|
|
||
| #[derive(Debug)] | ||
| struct Inner { | ||
| log_directory: PathBuf, | ||
| log_filename_prefix: Option<String>, | ||
| log_filename_suffix: Option<String>, | ||
| log_filename_index: Option<AtomicU64>, |
There was a problem hiding this comment.
It's not entirely clear to me as to why log_filename_index and current_size are atomics nor am I entirely sure if they are correct. I would naively prefer to wrap these two fields in a single struct that is, in turn, wrapped in a RwLock, but I'll let Eliza comment on this.
In any case, an explanation as to why atomics are used for this would be really helpful.
There was a problem hiding this comment.
This is fair, wrapping these in a RwLock is definitely less error-prone.
Here I used atomics for the same reason next_date is atomic: RollingFileAppender is implementing MakeWriter, and we need to borrow fields using a shared reference to the RollingFileAppender. Ideally we don’t want to pay too high synchronization costs, and there is a RwLock<File> that is already relied upon when swapping the file.
current_size is used whenever data is written to the file in the Write implementation of either RollingFileAppender or RollingWriter<'a>, and fetch_add operations are performed, so it’s basically a counter.
fn write(&mut self, buf: &[u8]) -> io::Result<usize> {
let written = (&*self.inner).write(buf)?;
self.current_size.fetch_add(written, Ordering::SeqCst);
Ok(written)
}current_size is reset to 0 when refresh_writer is called:
fn refresh_writer(&self, now: OffsetDateTime, file: &mut File) {
let filename = self.join_date(&now);
if let Some(max_files) = self.max_files {
self.prune_old_logs(max_files);
}
match create_writer(&self.log_directory, &filename) {
Ok(new_file) => {
if let Err(err) = file.flush() {
eprintln!("Couldn't flush previous writer: {}", err);
}
*file = new_file;
self.current_size.store(0, Ordering::Release);
}
Err(err) => eprintln!("Couldn't create writer for logs: {}", err),
}
}This function requires an exclusive reference to the file, and we can either obtain this exclusive reference by calling write on &RwLock<File>, or get_mut or &mut RwLock<File>. We are guaranteed to not be writing in the file at the same time because of that.
log_filename_index is pretty similar to next_date, and is actually updated only when next_date was updated by the current thread, in advance_date_and_index (previously named advance_date):
fn advance_date_and_index(&self, now: OffsetDateTime, current: usize) -> bool {
let next_date = self
.rotation
.next_date(&now)
.map(|date| date.unix_timestamp() as usize)
.unwrap_or(0);
let next_date_updated = self
.next_date
.compare_exchange(current, next_date, Ordering::AcqRel, Ordering::Acquire)
.is_ok();
match &self.log_filename_index {
Some(index) if next_date_updated => {
if current == next_date {
index.fetch_add(1, Ordering::SeqCst);
} else {
index.store(0, Ordering::Release);
}
}
_ => {}
}
next_date_updated
}All of this is put together in the make_writer implementation:
fn make_writer(&'a self) -> Self::Writer {
let now = self.now();
// Should we try to roll over the log file?
if let Some(current_time) = self.state.should_rollover(now) {
// Did we get the right to lock the file? If not, another thread
// did it and we can just make a writer.
if self.state.advance_date_and_index(now, current_time) {
self.state.refresh_writer(now, &mut self.writer.write());
}
}
RollingWriter {
inner: self.writer.read(),
current_size: &self.state.current_size,
}
}advance_date_and_index will return true if this thread was able to swap next_date with the new date, and false if another thread did it faster. The thread which was able to swap the value will take the exclusive write access using RwLock::write, and the other threads will wait for the file to be actually swapped at the RwLock::read call. If a thread is able to call RwLock::read faster, then it’s okay, we’ll simply write a few more lines in the old file before the rotation can happen.
In the io::Write implementation for RollingFileAppender, things are even more straightforward because we have an exclusive reference, and it must be the case that no other thread is accessing the atomics or the RwLock:
fn write(&mut self, buf: &[u8]) -> io::Result<usize> {
let now = self.now();
let writer = self.writer.get_mut();
if let Some(current_time) = self.state.should_rollover(now) {
let did_cas = self.state.advance_date_and_index(now, current_time);
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);
}
let written = writer.write(buf)?;
self.state.current_size.fetch_add(
u64::try_from(written).expect("usize to u64 conversion"),
Ordering::SeqCst,
);
Ok(written)
}If it wasn’t for the MakeWriter, no atomic and no RwLock would be required at all.
I hope it clarifies things. Do you want me to document that in the code directly?
|
I cleaned a few last things. I want to add additional tests before merging, but otherwise I’m waiting for further reviews. |
|
This would be really nice to get merged, I was looking for this feature and was surprised I couldn't rotate logs based on size. |
|
Is there anything I can do to help get this pull request merged? |
To help me, you could add some additional tests (send a PR on my fork), but I don’t know if we can do much until one of the maintainers find enough time to review again. |
I can help with tests. Any particular test cases that are missing, or should I just be creative? |
Thank you! There are two functions that I would like covered more thoroughly because they are critical for this feature:
Here are three test cases I would like to have:
I already tested these properties in practice, and it appears to work as expected, but having a few automated tests would be much welcomed for future maintenance. If you can think of more, it’s welcomed too. |
This patch adds size-based rotation to tracing-appender. In a constraint environment, we should be able to contain the logging size and period. Related issues: - tokio-rs#1940 - tokio-rs#858
Follow the date format induced by the selected `Timed`. An index is inserted into the file name so we can rotate when the max size is reached. Also, when the most recent file does not exceed the max size, we simply reuse it instead of creating yet another file.
|
I rebased on top of master. |
+1, i'm looking forward for this feature as well. Thank you for this @CBenoit and everyone involved! |
|
Hi @CBenoit , I opened this PR #3026 trying to do a similar thing, then I realized your PR was doing a better job and I closed mine to concentrate the attention on this one. While I was reviewing your implementation I found an important difference about how we expect to rotate files by size. In your implementation, there is a certain degree of complexity around renaming files and keeping track of an index for same-frequency log files. As a user, what I would expect is to read the |
|
Hi @adrianbenavides!
Indeed, this sounds reasonable to me!
That sounds great! I’ll be glad to merge your work :) |
|
Hi all! Is there an estimation when this might be included in the library and supported? I see the PR has been open for quite some time but that it's also very active. If there is any way I can help, lmk. Would hope to use this asap Thanks |
As a simple contributor, I can’t really give you any ETA. However, I can tell you that I haven’t received any updates from the tokio/tracing maintainers since last year, so I don’t think it’s a priority for the project at the moment. Also, it is very likely that the maintainers already have their plates full with other projects, as I haven’t seen many PRs merged recently. As for the help, currently @adrianbenavides is simplifying the code and adding the remaining tests I wanted. That’s pretty much all I can see at the moment. |
This patch adds size-based rotation to tracing-appender.
Closes #1940
Closes #858
cc @hawkw @IniterWorker @CfirTsabari
Motivation
In a constrained environment, we should be able to contain the logging size and period.
Solution
Maximum bytes per log file may be specified in the
Rotationstruct.Written bytes are counted and when the specified maximum number of bytes is exceeded, log file is rolled over.