After working on the Sōzu HTTP reverse proxy for a while, I came up with an interesting approach to logging. Now why would I come up with my own logger, when there are existing solutions in Rust? Mainly, log and slog. That logging library grew up from testing things out with log, and changing requirements along the way.
Beginning with log and env_logger
Like a lot of other Rust developers, I started out with log and env_logger:
#[macro_use]
extern crate log;
extern crate env_logger;
fn main() {
env_logger::init().unwrap();
info!("starting up");
}
It's nice and easy: every library that depends on log will use that same set of logging macros (error, info, warn, debug, trace) that will use whatever global logger was defined. Here we use env_logger to define one.
env_logger is useful because it can apply a filter to the log, from an
environment variable:
[code lang=text]
# will show the logs above info level
RUST_LOG=info ./main
# will show the logs above info level, but also logs above debug level
# for the dependency 'dep1'
RUST_LOG=info,dep1=debug ./main
[/code]
You can also define the filter by module or apply a regular expression.
Custom formatter
env_logger allows you to build your own log formatter. This feature is especially important for me, as I like to add metadata to my logs.
Defining a custom formatter with env_logger is quite straightforward:
[code lang=text]
let format = |record: &LogRecord| {
format!("{} - {}", record.level(), record.args())
};
let mut builder = LogBuilder::new();
builder.format(format).filter(None, LogLevelFilter::Info);
if env::var("RUST_LOG").is_ok() {
builder.parse(&env::var("RUST_LOG").unwrap());
}
builder.init().unwrap();
[/code]
It is easily combined with the filtering and usage of the RUST_LOG environment variable.
Where things get annoying: reducing allocations
If you take a look at env_logger, you'll realize that it will allocate a String for every log line that will be written, using a formatting closure.
Let's get one thing out of the way first: I completely agree with the idea you should not try to optimize stuff too much. But I'm in the case of a networking component that will handle a lot of traffic. I had debugging sessions where I generated tens of gigabytes of logs in a few seconds, and needed almost all of them, to debug async IO issues. In those cases, the time spent allocating and deallocating log lines becomes relevant.
So, how would I get a custom log formatter that does not allocate much? As it turns out, when you tell log to use your logger with log::set_logger, it requires something that implements Log. The logger's log method receives a LogRecord, a structure that's created on the fly from LogLocation, LogMetadata and Arguments.
The first two are internal to log, I can't create them myself. The last one is interesting.
Arguments can be created from the format_args macro. That structure will roughly contain the format string split in the various substrings that appear between arguments. if you do println!("hello {}!", name), you would get a structure that contains "hello ", the content of name and "!". println! and other macros use this.
You can then use that Arguments with io::Write::write_fmt to write it directly to, say, a file or a socket. And it is implemented so that the individual parts are written one after another instead of allocating one big string.
So, how do I use that?
Well, it turns out that, basically, I can't. If I implement Log, I can get a Logrecord which gives me a &Arguments, while write requires a Arguments. So now I have to clone it, which defeats a bit the purpose.
So let's write our own then
There was another reason for the custom logging library: using a custom logging backend. Having the option between stdout and stderr is fine, but I might want to send them to a file or a socket.
So I started writing a specific logging library for sozu. First, copying the log filtering from env_logger. That part is mostly straightforward, but that's still a lot of code to copy around.
The logging macros specify a logging level then they all call the same common macro.
[code lang=text]
#[macro_export]
macro_rules! error {
($format:expr, $($arg:tt)*) => {
log!($crate::logging::LogLevel::Error, $format, "ERROR", $($arg)*);
};
($format:expr) => {
log!($crate::logging::LogLevel::Error, $format, "ERROR");
};
}
[/code]
The main logging macro has two interesting parts. First, we define some static metadata (that's coming from the log crate):
[code lang=text]
static _META: $crate::logging::LogMetadata = $crate::logging::LogMetadata {
level: $lvl,
target: module_path!(),
};
[/code]
That object will not be allocated over and over, all the data in there will be defined at compile time.
Then we call the logger itself (ignore the line with try_lock for now):
[code lang=text]
if let Ok(mut logger) = LOGGER.try_lock() {
logger.log(
&_META,
format_args!(
concat!("{}\t{}\t{}\t{}\t{}\t", $format, '\n'),
::time::now_utc().rfc3339(), ::time::precise_time_ns(), *$crate::logging::PID,
$level_tag, *$crate::logging::TAG));
}
[/code]
So we give this metadata structure to our logger, then we make an Arguments structure with format_args!. The concat! macro is there to concatenate the formatting string with the custom prefix. That way, I could write debug!("hello {}", name) and have the resulting format string be "{}\t{}\t{}\t{}\t{}\thello {}\n", generated at compile time and transformed through the format_args call.
I added the date in ISO format, along with a monotonic timestamp (that becomes handy when multiple workers might write logs concurrently), the process identifier, the log level and a process wide logging tag (to better identify workers).
So this starts looking good, right? Now how do we write this to configurable backends? Some backends already implement io::Write, others will need an intermediary buffer:
[code lang=text]
pub fn log<'a>(&mut self, meta: &LogMetadata, args: Arguments) {
if self.enabled(meta) {
match self.backend {
LoggerBackend::Stdout(ref mut stdout) => {
stdout.write_fmt(args);
},
LoggerBackend::Unix(ref mut socket) => {
socket.send(format(args).as_bytes());
},
LoggerBackend::Udp(ref mut socket, ref address) => {
socket.send_to(format(args).as_bytes(), address);
}
LoggerBackend::Tcp(ref mut socket) => {
socket.write_fmt(args);
},
}
}
}
[/code]
For Unix sockets and UDP, instead of allocating on the fly, it should probably use a buffer (hey, anyone wants to implement that?). Stdout and a TcpStream can be written to directly. Adding buffers might still be a good idea here, depending on what you want, because that write could fail. Would you like a logger that will send a partial log if it can't write on the socket, or one using a buffer that can be filled up?
So, now, what's next? Originally, sozu worked as one process with multiple threads, but evolved as a bunch of single threaded processes. But that raises an interesting question. How do you write logs concurrently?
Highly concurrent logs
It turns out that problem is not really easy. Most solutions end up in this list:
- every thread or process writes to stdout or a file at the same time
- synchronized access to the logging output
- one common logger everybody sends to
- every thread or process has its own connection to syslog (or even its own file to write to)
The first solution is easy, but has a few issues. First, writing to stdout is slow, and it can quickly overwhelm your terminal (yes, I know you can redirect to a file). Second, it's not really synchronized, so you might end up with incoherently interleaved log lines.
So we often move to the second solution, where access to the logging stream is protected by a mutex. Now you get multiple threads or processes that might spend their time waiting on each other for serializing and writing logs. Having all threads sharing one lock can quickly affect your performance. It's generally a better idea to have every thread or process running independently from the others (it's one of the principles in sozu's architecture, you can learn more about it in this french talk).
Alright then, moving on to the third solution: let's have one of the threads or processes handle the logging, and send the logs to it via cross thread channels or IPC. That will surely be easier than having everybody share a lock, right? This is also intersting because you can offload serialization and filtering to the logging thread. Unfortunately, that means one thread will handle all the logs, and it can be overwhelming. That also means a lot of data moving between workers (if using processes).
The last solution relies on external services: use the syslog daemon on your system, or a log aggregator somewhere on another machine, that every worker will send the logs to. Let that service interleave logs, and maybe scale up if necessary. Since in a large architecture, you might have such an aggregator, talking to it directly might be a good idea (oh hey BTW I wrote a syslog crate if you need).
With sozu, I ended up with a mixed solution. You can send the logs to various backends. If you choose stdout, then all workers will write to it directly without synchronization which will be mostly fine if you don't have a large traffic. But if you want, each worker can open its own connection to the logging service.
Now that concurrency is taken care of, there's a last issue that has annoyed me for months: how to use the logger from everywhere in the code, when it's obviously one big global mutable object?
the dreaded logging singleton
One thing I like about the macros from the log crate: you can use them anywhere in your code, and it will work. The other approach, used in languages like Haskell, or proposed by slog, is to carry your logger around, in function arguments or structure members. I can understand the idea, but I don't like it much, because I'll often need to add a debug call anywhere in the code, and when it's deep in a serie of five method calls, with those methods coming from traits implemented here and there, updating the types quickly gets annoying.
So, even if the idea of that global mutable logger singleton usually looks like a bad pattern, it can still be useful. In log, the log macro calls the log::Log::log method, getting the logger instance from the logger method. That method gets the logger instance from a global pointer to the logger, with an atomic integer used to indicate if the logger was initialized:
[code lang=text]
static mut LOGGER: *const Log = &NopLogger;
static STATE: AtomicUsize = ATOMIC_USIZE_INIT;
const UNINITIALIZED: usize = 0;
const INITIALIZING: usize = 1;
const INITIALIZED: usize = 2;
[...]
pub fn logger() -> &'static Log {
unsafe {
if STATE.load(Ordering::SeqCst) != INITIALIZED {
static NOP: NopLogger = NopLogger;
&NOP
} else {
&*LOGGER
}
}
}
[/code]
So how can that global mutable pointer be used from any thread? That's because the Log trait requires Send and Sync. As a reminder, Send means it can be sent to another thread, Sync means it can be shared between threads.
That's a cool trick, but usually we employ another pattern:
[code lang=text]
lazy_static! {
pub static ref LOGGER: Mutex<Logger> = Mutex::new(Logger::new());
pub static ref PID: i32 = unsafe { libc::getpid() };
pub static ref TAG: String = LOGGER.lock().unwrap().tag.clone();
}
[/code]
lazy_static allows you to define static variables that will be initialized at runtime, at first access (using the same pattern as log with std::sync::Once. Since our logger's log method needs an &mut, it's wrapped in a Mutex. That's where the call to try_lock comes from.
We might think the mutex is costly compared to log's solution, but remember that the logger instance has to be Sync, so depending on your implementation, there might be some synchronization somewhere. Except that for sozu, it's not the case! Each worker is single threaded, and has its own instance of the logger (possibly with each of them a connection to the logging service). Can't we have a logging system that does not require that mutex used everywhere?
Removing the last Mutex
This is a problem that annoyed me for months. It's not that I really mind the cost of that mutex (since no other thread ever touches it). It's just that I'd feel better not using one when I don't need it :)
And the solution to that problem got quite interesting. To mess around a bit, here's a playground of the logging solution based on lazy_static. You'll see why the code in Foo::modify is important.
There's a feature you can use to have a global variable available anywhere in a thread: thread_local. It uses thread local storage with an UnsafeCell to initialize and provide a variable specific to each thread:
[code lang=text]
thread_local!(static FOO: RefCell<u32> = RefCell::new(1));
FOO.with(|f| {
assert_eq!(*f.borrow(), 1);
*f.borrow_mut() = 2;
});
[/code]
So I tried to use this with my logger, but encountered an interesting bug, as you can see in another playground. I replaced my logging macro with this:
[code lang=text]
#[macro_export]
macro_rules! log {
($format:expr, $($arg:tt)+) => ({
{
LOGGER.with(|l| {
l.borrow_mut().log(
format_args!(
concat!("\t{}\t", $format, '\n'),
"a", $($arg)+));
});
}
});
}
[/code]
And got this error:
[code lang=text]
error[E0502]: cannot borrow `self` as immutable because `self.opt.0` is also borrowed as mutable
--> src/main.rs:36:21
|
36 | LOGGER.with(|l| {
| ^^^ immutable borrow occurs here
...
54 | if let Some(ref mut s) = self.opt {
| --------- mutable borrow occurs here
55 | log!("changing {} to {}", self.bar, new);
| -----------------------------------------
| | |
| | borrow occurs due to use of `self` in closure
| in this macro invocation
56 | }
| - mutable borrow ends here
[/code]
When implementing this inside sozu's source, I got about 330 errors like this one... So what happened? That with method requires a closure. Since we use a macro, if we use self.bar as argument, it will appear inside the closure. That becomes an issue with anything that has been already mutably borrowed somewhere.
I tried a few things, like calling format_args outside the closure, but I get the error error[E0597]: borrowed value does not live long enough. This is apparently a common problem with format_args.
But the real solution came from tomaka, with some macro trickery, as seen in one last playground:
[code lang=text]
#[macro_export]
macro_rules! log {
($format:expr $(, $args:expr)*) => ({
log!(__inner__ $format, [], [a,b,c,d,e,f,g,h,i,j,k,l,m,n,o,p,q,r,s,t,u,v]
$(, $args)*)
});
(__inner__ $format:expr, [$($transformed_args:ident),*], [$first_ident:ident $(, $other_idents:ident)*], $first_arg:expr $(, $other_args:expr)*) => ({
let $first_ident = &$first_arg;
log!(__inner__ $format, [$($transformed_args,)* $first_ident], [$($other_idents),*] $(, $other_args)*);
});
(__inner__ $format:expr, [$($final_args:ident),*], [$($idents:ident),*]) => ({
LOGGER.with(move |l| {
//let mut logger = *l.borrow_mut();
l.borrow_mut().log(
format_args!(
concat!("\t{}\t", $format, '\n'),
"a" $(, $final_args)*));
});
});
}
[/code]
The basic idea is that we could avoid the borrowing issue by doing an additional borrow. But since some of the arguments might by expressions (like 1+1 or self.size), we will store the reference to it in a local variable, with let $first_ident = &$first_arg;.
We cannot create variable or function names in macros out of thin air (sadly, because that would be extremely useful), so we instead do recursive macros calls, consuming arguments one after another.
In [$($transformed_args:ident),*], [$first_ident:ident $(, $other_idents:ident)*], $first_arg:expr $(, $other_args:expr)*,
transformed_args accumulates the idents (variable names) in which we stored the data.
[$first_ident:ident $(, $other_idents:ident)*] is matching on the list that started as [a,b,c,d,e,f,g,h,i,j,k,l,m,n,o,p,q,r,s,t,u,v], to get the first one in that list (storing it in $first_ident), and using it as variable names. As you might have guessed, that means I won't be able to use a log line with more than 21 arguments. That's a limitation I can live with.
The $first_arg:expr $(, $other_args:expr)* part matches on the log call's arguments, and gets the first in the list as $first_arg. We then use those in the line let $first_ident = &$first_arg; and recursively call log!, adding the variable name $first_ident to the list of transformed arguments, and the rest of the variable names list and the log call's arguments:
[code lang=text]
log!(__inner__ $format, [$($transformed_args,)* $first_ident], [$($other_idents),*] $(, $other_args)*);
[/code]
Once all of the logger's arguments are consumed, we can call format_args on the list of $transformed_args:
[code lang=text]
(__inner__ $format:expr, [$($transformed_args:ident),*], [$($idents:ident),*]) => ({
LOGGER.with(move |l| {
//let mut logger = *l.borrow_mut();
l.borrow_mut().log(
format_args!(
concat!("\t{}\t", $format, '\n'),
"a" $(, $transformed_args)*));
});
});
});
[/code]
and it works!
So, that last part may not be completely relevant to your logger implementation, but I thought
it was quite cool :)
Despite my issues with the log crate, it's quite useful and supported by a lot of libraries. It is currently getting a lot better as part of the libz blitz. I'd also encourage you to check out slog. I haven't felt the need to integrate it in sozu yet, but it can be interesting for new projects, as it comes with an ecosystem of composable libraries to extend it.