Introduce a non blocking file appender

[zekisherif]

Motivation

A service we manage at work is currently migrating from using log4rs to Tracing as it provides many features we feel will greatly help our ability to investigate and resolve issues that may arise. Our services generally log to a file stored on disk and are rotated hourly.

Tracing today doesn't provide us out of the box support for logging to a file and we've had to work around this by implementing it ourself.

Solution

Our solution was to create a FileWriter which holds a reference to a crossbeam channel (sender side) . This FileWriter is what we pass to .make_writer on a subscriber. Tracing events will be sent through this channel and on the receiving end a worker thread will be responsible for logging the event to disk.

Notes

No tests are being included in this PR as from my understanding after talking with @davidbarsky is that we will be looking primarily for an interface here and any tests that will be added here will be different than what we have written internally.

[hawkw]

This is a feature a number of people have been asking for, so I'm really happy to see this PR — thanks for open-sourcing your work @zekisherif! I'm excited to take a look at the code.

[hawkw]

Thanks again for open-sourcing this, it looks like a good start. There's some additional work we'll want to do to make the API general enough to be applicable to users with different use-cases, or want more control over behavior.

My biggest concern about the currently-proposed API is that it isn't very composable. It seems like right now, the "rolling file appender" component and the "non-blocking logging with a dedicated worker thread" component are tightly coupled. Ideally, I would like users to be able to use both components separately, as well as together --- for example, we should be able to use the non-blocking worker thread for writing to stdout, or the rolling file appender without spawning a worker thread.

We could make these APIs more composable by providing a public type for a rolling file appender. This would implement tracing-subscriber's MakeWriter trait, and would only implement rolling log files and writing to them in a blocking manner. This could then be used with tracing-subscriber::fmt directly, without using the dedicated logging worker. I imagine an API where users can write code like this:

let file = tracing_appender::rolling::hourly("/var/log", "my_great_program-");  // returns a `MakeWriter`
tracing_subscriber::fmt()
    .with_writer(file)
    .init();

This would create a rolling log file appender without spawning a dedicated worker thread.

Then, we would also provide a type that wraps a MakeWriter implementation and implements a dedicated worker thread for logging to that writer in a non-blocking manner. Users could then (for example) spawn a dedicated worker thread for writing to stdout, like this:

let writer = tracing_appender::non_blocking(std::io::stdout); // returns a `MakeWriter`
tracing_subscriber::fmt()
    .with_writer(writer)
    .init();

Users could also combine the two to get the behavior this crate currently implements, like this:

let file = tracing_appender::rolling::hourly("/var/log", "my_great_program-");  // returns a `MakeWriter`
let writer = tracing_appender::non_blocking(std::io::stdout); // returns a `MakeWriter`
tracing_subscriber::fmt()
    .with_writer(writer)
    .init();

We could also provide a convenience constructor for getting both out of the box.

As you can probably see from the examples I provided, I think we can also make the APIs a bit more ergonomic some of the same patterns as #660, but we can do that after splitting the two main components here. I'm happy to provide more advice on that once we separate the APIs.

Before we publish this crate, we'll also want to add API documentation, tests, and examples. I'm fine with adding that in a follow-up PR, though.

I also had some other advice in inline comments. Hopefully it's all helpful, and thanks again for working on this.

[Matthias247]

Allocating a vector for each line will create a lot of memory churn, and I expect it to noticeably show up in profiles if logging is enabled. An alternative solution could be to have a pool of logging buffers.

[hawkw]

@Matthias247 I've started working on a solution for that separately (a ring buffer of strings, basically), and I'm hoping we can swap that in as a replacement for crossbeam_channel in the future. For this PR, I want to focus on the API design.

[Matthias247]

That way, the user can spawn the worker thread manually, allowing them to control things like the thread's name and how panics are propagated.

You can do the same by e.g. passing or parameterizing over a ThreadFactory, which is the common thing that is done in Java.

I am not convinced users should by required to manage the lifetime of threads - that just leaks implementation details.

[zekisherif]

The latest commit still needs some work (I'll continue tomorrow), but it includes a completed seperation of the apis for nonblocking and file appenders.

I still have to find a way to avoid calling make_writer for the nonblocking implementation on every write/flush.

[hawkw]

I still have to find a way to avoid calling make_writer for the nonblocking implementation on every write/flush.

Hmm, this actually seems like it might be a bit of a hole in the MakeWriter abstraction. Depending on the writer being used, we may or may not want MakeWriter to be called every time we write to an IO.

When std::io::stdout or std::io::stderr is in use, I think we may want to see make_writer called every time, since it acquires a lock on stdout/stderr. If we call it once and hold onto the returned writer, we would hold the lock on stdout for as long as the worker thread exists. This would prevent anything else in the program from ever writing to stdout. In some cases, where the subscriber is the only thing the writes to stdout, this is fine (and might offer a slight performance benefit), but some programs may have the occasional println! etc, and holding the writer indefinitely would make a println! block forever. On the other hand, a file appender could hold onto the writer forever when it's used with the logging worker thread. When it's not used in non_blocking mode, it would be correct to call it every time we write to the file, though, because calls may come from multiple threads.

I think that what we want is to call make_writer only once with the non_blocking writer, and document that clearly. We could provide a separate MakeWriter implementation for stdout/stderr to be used by the non_blocking writer if holding the lock forever is a problem, where every write call re-acquires the lock. This is kind of a shame, since there are now two separate APIs...I'll give it some more thought.

[hawkw]

Before merging this, I would really like to see some verification that it basically works, either in the form of an integration test or an example that we can run and manually smoke check. I know you wanted to add tests in a follow-up, but it would be good to have some kind of demonstration that this works correctly.

[zekisherif]

Before merging this, I would really like to see some verification that it basically works, either in the form of an integration test or an example that we can run and manually smoke check. I know you wanted to add tests in a follow-up, but it would be good to have some kind of demonstration that this works correctly.

Sure, I'll add the tests here the and hold the documentation for a seperate PR

[hawkw]

If you want to do more testing in a follow-up, that would be fine! The issue is less that we need a complete set of tests now, and more that I am a little uncomfortable merging code if it hasn't ever been run. :)

[hawkw]

I left some comments on the RustDoc examples. In particular, we should make sure that they are actually able to compile :)

I can also review the docs you added now, if you like, or I'd be happy to save working on them for a follow-up?

[davidbarsky]

Some phrasing nits. I'll need to add links to the other types and methods referenced in this module.

[zekisherif]

I can also review the docs you added now, if you like, or I'd be happy to save working on them for a follow-up?

I haven't completed the rest of the docs yet, can I get that in a new PR for you later today?

[hawkw]

Everything looks pretty good to me! I had a few more notes on the docs added in this PR, but I'm fine with saving that for a follow-up.

[hawkw]

nit: it would be good to link to non_blocking eventually. We can do that later when we come back and finish the docs.

[hawkw]

Might also be good to add something explaining what the two file paths are for (the directory to put logs in, and the prefix for the logfile names). Should also note that if the parent directory doesn't exist, this will create it.

All of that can be added later though, this is good for now.

[hawkw]

we should probably also explain what WorkerGuard is , as well as noting that it shouldn't be dropped accidentally :)

and, it's fine for users to drop it if they don't care about ensuring that logs are flushed on panics (but they probably do care about this)

[zekisherif]

Going to fix the doc test causing the issue.

[hawkw]

Okay, this looks great. I'm happy to merge it now and finish adding documentation and examples in a follow-up! :)

[hawkw]

(@davidbarsky any last thoughts?)

[davidbarsky]

@hawkw Nope, this looks like its in a good place! Lets do documentation and examples in followups.

[hawkw]

And it's merged! Thanks again for your contribution @zekisherif! I know this took a while to get through, so thanks for sticking with it <3