The Importance of Logging
Intro programming classes will nag you to do all sorts of programming chores: make sure your code actually compiles, write unit tests, write comments, split the code into functions (though sometimes the commenting and factoring advice is bad). Today, however, I want to talk about one little chore, one particular little habit, that is just as essential as all of those things, but rarely covered in the CS100 lectures or grading rubrics: logging.
And why am I choosing this particular topic for a blog post today? Simple: It’s to punish an earlier version of myself for not logging enough, for not caring about logging enough. It turns out it’s important. But I’ll get back to the OOP blog series soon enough, don’t worry!
Logging – writing text describing what’s been happening in your program
to a file or other storage system – is essential for any software
system. Luckily, Rust has a (nearly) standard logging framework,
technically outside the standard library but maintained by many of
the same people and solidly endorsed by the community: the log
crate. But note: Even though this post
is written specifically for Rustaceans, much of the advice and commentary
in here will apply to logging systems in all programming languages.
Logging is essential for debugging and troubleshooting. When you find a bug, you need to find out which specific part of the program is actually broken out of the many parts, because it’s often not the part that’s visbly acting weird. This is often the first step in addressing a new bug after reproducing it, or even part of figuring out how to reproduce it – or the step before that, so obvious it goes without saying, of noticing that a bug exists.
In fact, logs can be helpful at every stage of the debugging process. You have to confirm your assumptions on what parts are known to work. After all, the whole program is supposed to work, and often times, the thing that’s broken is something that you would’ve assumed definitely worked, until absolutely everything else was ruled out.
Every programmer understands this intuitively, even as a student or a beginning self-taught programmer: When you are developing a project, and it’s not working, the easiest ad hoc debugging technique is “debug print statements,” a go-to technique of CS100 students worldwide. Ironically, CS100 professors often advocate against this in favor of debuggers, in spite of the fact that logging, the grown-up version of debug prints, is more generally useful, as code often exhibits bugs in environments where it didn’t happen to be running in a debugger, like production.
Debug prints work, by accomplishing two goals:
- Verifying that the program got to the point of that debug print line.
- Verifying that the data it has at that point is correct.
Logging is fundamentally debug print statements, but phrased and annotated correctly, so that it looks professional both in the code and in the log, and uses actual logging mechanisms with timestamps and log levels and stuff.
So instead of:
initialize_rainbows();
println!("Got here 2");
initialize_sunshine();
println("Got here!!!!");
You write the much nicer-looking:
initialize_rainbows();
info!("Rainbows fully initialized");
initialize_sunshine();
info!("Sunshine fully initialized");
When To Log#
You should log as much as possible.
Every time you make a decision, you should log it. Every time you query a URL or build a string of some kind, you should log it. Every time you load a config parameter, you should definitely log it. This might seem silly, because you’re duplicating the configuration file, but a bug processing configuration (or prioritizing different sources of configuration) can be especially hard to find.
Logging can be used instead of comments to organize functions into parts. If you feel the need to tell the reader of your code what each part of a function does, perhaps you should tell your poor ops person which parts you’ve reached in the same breath. So instead of:
fn close_out_section(self) -> Result<()> {
// Flush dirty data
for datum in &mut self.data {
if datum.is_dirty() {
datum.flush()?;
}
}
// Close files
for file in &mut self.files {
file.flush()?;
file.close();
}
decrease_global_section_count()?;
Ok(())
}
You could write:
fn close_out_section(self) -> Result<()> {
info!("Closing out section: {}", self.name);
debug!("Flushing dirty data");
for datum in &mut self.data {
if datum.is_dirty() {
trace!("{} is dirty, flushing...", datum.name);
datum.flush()?;
}
}
debug!("Closing files");
for file in &mut self.files {
trace!("Closing {}", file.name);
file.flush()?;
file.close();
}
debug!("Decreasing global section count");
decrease_global_section_count()?;
debug!("Section successfully closed!");
Ok(())
}
These log statements serve both as comments to your reader and information to your administrator at the same time! And, since you are writing to someone who is perhaps not looking at the source code, you don’t feel silly adding even more information that’d be obvious to a reader – which is useful also to readers of the source code, who might not share your definition of what is obvious. In spite of what you may have heard, it’s still a good idea to err on the side of explaining things more in comments. (Yes, I linked that post twice. It’s that good.)
You may object that all this logging might slow down your process a little, and I can see wanting to avoid it in the middle of a computational loop. But oftentimes, people avoid logging when there is no possible performance excuse, when much slower I/O is happening all around it, in comparison to which the logging would be a rounding error. Remember that famous Donald Knuth quote: “[P]remature optimization is the root of all evil….”
Log Levels#
In addition to performance, you might claim that the amount of logging that I show above is spammy, and that the resulting log files would cause an information overload. But our programming foreparents were wise, and created an additional tool to address both this, and the potential performance problems: log levels.
An error message is different from a warning is different from information
is different from debug printing. We want to distinguish these, so we can
avoid seeing insufficiently important logs. There are many systems of log
levels, and Rust’s log
crate endorses a pretty typical list, enumerated
in its Level
enum:
pub enum Level {
Error,
Warn,
Info,
Debug,
Trace,
}
They form an ordered, descending scale of severity, so that Trace
is
the least severe. You probably always want to enable Error
-level logs
(though even they can be turned off) but you probably only want to enable
Trace
-level logs if you’re doing some serious debugging.
In recognition of how the levels are ordered, log filtering is typically
done by setting a level, and then logs of that level or more severe
are let through. So if the level is Debug
, Warn
logs are also outputted,
but if it is Error
, Warn
logs are suppressed. See the LevelFilter
enum.
Errors are for problems that stop the process, or at least the specific thing the process was doing (e.g. API or RPC request being serviced). Warnings are for where something seems wrong but we’re going to do it anyway.
Info, debug, and trace are honestly kind of just labels with decreasingly
urgent-sounding names, levels for the sake of levels. You should
use them according to importance, so that most of the absolute nonsense
can get filtered out as mere trace
, like implementation details
or extra information. You also want the occasional interesting
high-level stuff to be captured with info
, like what high-level task
is the process currently working on. Medium-level tasks can get debug
.
In general, the more performance-critical the code, the lower the log level you want to use, to increase the likelihood that you’ll just have a (very predictable) branch to indicate that you don’t need to print that line. Then, if there’s an actual problem, an operator can raise the log level (which they can sometimes do on a per-module basis) when those lines are worth seeing.
As a corrollary, configuration should use info
and warn
heavily, and
generally log at higher log levels. Configuration only happens once,
and in one section, so it’s allowed to be spammy. Furthermore, raising
the log level at run-time won’t help reveal more configuration logs:
unless the configuration is re-processed, you’ve just already missed
those messages. Finally, configuration is never too latency sensitive
for logging – configuration is the least performance sensitive part
of your program.
So there is no excuse. Loading different configuration than you thought you had is a shockingly common cause of bugs and confusing system behavior. Log obsessively in your configuration code, at high log levels.
Using the Log Crate in Your Rust Projects#
So how do we log in Rust?
log
is a framework – in the words of its well-written
documentation, it is a “lightweight
logging facade.” The front-end is shared: You output logs through the
log
crate itself. The backend is pluggable, meaning that different
backends exist with different features.
As a result, as the documentation says, libraries should
just use the log
crate, so that when they output logs,
it will work with any backend. Applications choose the
backends, and import an appropriate crate, like for example
env_logger
.
The log
documentation has a list of available backend
crates.
This split between what crates should be used by libraries as opposed
to application is not uncommon in Rust. For example, it also comes up
with error handling, where libraries should generally use thiserror
to
preserve error information in a way that applications can programmatically
investigate, but applications generally want to use anyhow
and eyre
to ergonomically convey any errors they cannot handle to the user.
Newsletter
Find out via e-mail when I make new posts!