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:

1. Verifying that the program got to the point of that debug print line.
2. 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.