Better Logging for the Web Application

See… structured logging…

When I last left my sample web application, I was doing simple logging to the terminal which is not useful for very long. I want structured logging and I want the app and Rocket to write to (separate) files. So, let’s switch out the crates log and simple_log for slog and sloggers to get better logging for my web application.

Application Logging

Slog‘s “ambition is to be The Logging Library for Rust” and it sure seems adaptable. There are several “helper” crates to log to the terminal or syslog, log as json, etc. However, slog is complex! Which seems to be the main reason sloggers came about. Sloggers brings you the most useful features of slog without the complex setup. It happens to include an example of configuring via an inline TOML string. I’ve already got my CONFIG global pulling from a TOML file, so I add this to conf/development.toml:

<conf/development.toml>

...
[logconfig]
type = "file"
format = "compact"
source_location = "module_and_line"
timezone = "local"
level = "debug"
path = "log/error.log"
rotate_size = 1073741824
rotate_keep = 2

[webservice]
weblog_path = "log/access.log"
...

Plus, I add logging.rs to set up the global LOGGING instance so everyone can log; just like everyone can pull from the global CONFIG instance:

<logging.rs>

use crate::settings::CONFIG;
use crate::sloggers::{Build, Config};
use once_cell::sync::Lazy;

#[derive(Debug)]
pub struct Logging {
    pub logger: slog::Logger,
}

pub static LOGGING: Lazy<Logging> = Lazy::new(|| {
    let logconfig = &CONFIG.logconfig;
    let builder = logconfig.try_to_builder().unwrap();
    let logger = builder.build().unwrap();

    Logging { logger: logger }
});

Sloggers is really easy to use to set up a slog instance. Here, I simply pull the logconfig from my global CONFIG, build the logger, and store it in my new OnceCell Lazy LOGGING global.

And then, Web Access Logging

At this point, application logging is going to my new log/error.log file, but Rocket logging is still coming to the screen. This is actually good – as I mentioned, I want to have them going to separate files anyway. So now with some slogging experience, it’s a simple matter to set up a second file, specifically for Rocket. I do need to add yet another crate, this time rocket_slog – so that Rocket internals can glom on to the slog instance that I make. Here is the new start_webservice function:

<src/lib.src>

...
pub fn start_webservice() {
    let logger = &LOGGING.logger;
    let weblog_path = &CONFIG.webservice.weblog_path;
    let bind_address = &CONFIG.webservice.bind_address;
    let bind_port = &CONFIG.webservice.bind_port;

    // start rocket webservice
    let version = include_str!("version.txt");
    let mut builder = FileLoggerBuilder::new(weblog_path);

    builder.level(Severity::Debug);

    let weblogger = builder.build().unwrap();
    let fairing = SlogFairing::new(weblogger);
    warn!(logger, "Waiting for connections...";
        "address" => bind_address,
        "port" => bind_port,
        "version" => version);

    rocket::ignite()
        .attach(fairing)
        .attach(Template::fairing())
        .attach(SpaceHelmet::default())
        .mount("/", routes![routes::index, routes::favicon])
        .mount("/img", StaticFiles::from("src/view/static/img"))
        .mount("/css", StaticFiles::from("src/view/static/css"))
        .mount("/js", StaticFiles::from("src/view/static/js"))
        .launch();
}

Now I have log/error.log for application logging (I’ll rename that later to log/app.log) and log/access.log for Rocket logging. But I still don’t have structured logs!

Finally, Structured Logs

I try several ways (with my limited Rust knowledge and experience) but it appears that with sloggers ease of use, you trade away options if you want to get fancy. At least, I couldn’t figure out how to get slog_json or something called slog_bunyan to work with sloggers. It looks like I have to deal with slog directly.

Later, on another night, I tackle these changes. I dump sloggers and, though much searching around, I end up with a merge of two examples I find (from slog and slog-bunyan). Thankfully, I am getting a little better at understanding the API docs that are posted for crates! Anyway, here is how the app logging setup looks now:

<src/logging.rs>

...
pub static LOGGING: Lazy<Logging> = Lazy::new(|| {
    let logconfig = &CONFIG.logconfig;
    let logfile = &logconfig.applog_path;
    let file = OpenOptions::new()
        .create(true)
        .write(true)
        .truncate(true)
        .open(logfile)
        .unwrap();
    let applogger = slog::Logger::root(
        Mutex::new(slog_bunyan::default(file)).fuse(),
        o!("location" => FnValue(move |info| {
            format!("{}:{} {}", info.file(), info.line(), info.module(), )
          })
        ),
    );
    Logging { logger: applogger } });

Notice I still pull the applog_path from the CONFIG and then create that filehandle. Next, a single but complicated call into slog returns a Logger instance, which I store into my global. The o! macro, provided by the slog crate, lets me add a JSON field to every log record that gets written. I copy from an example and add the file, line number, and module name where the log was generated. I’ll probably come back to this later and add more data. Also, notice I am using slog_bunyan for the JSON formatting. slog-json actually recommends using slog_bunyan for a “more complete output format.” Bunyan logging seems to originate as a node.js module. Lastly, I also change the weblogger in the same way – now both are JSON logs and still log to separate files.

This actually wasn’t as complicated as I feared. I’ve lost some of the easily configurable sloggers features like auto file rotation, but I’ll figure that out as well – it’s probably actually just a slog feature that I need to enable.

Results, JSON Style

Here is how both look now – I think next post I’ll work on a JSON log viewer so we can watch these easier, as we develop.

<log/app.log>

{"msg":"Service starting","v":0,"name":"slog-rs","level":40,"time":"2019-07-20T03:40:13.781382592+00:00","hostname":"ip-169-254-169-254","pid":6368,"location":"src/lib.rs:48 ppslib","run_level":"development"}
{"msg":"Waiting for connections...","v":0,"name":"slog-rs","level":40,"time":"2019-07-20T03:40:13.784899718+00:00","hostname":"ip-169-254-169-254","pid":6368,"location":"src/lib.rs:76 ppslib","version":"0.1.0","port":3000,"address":"0.0.0.0"}

<log/access.log>

{"msg":"listening","v":0,"name":"slog-rs","level":30,"time":"2019-07-20T05:31:21.068959173+00:00","hostname":"ip-169-254-169-254","pid":7700,"address":"http://0.0.0.0:3000"}
{"msg":"request","v":0,"name":"slog-rs","level":30,"time":"2019-07-20T05:31:22.402815352+00:00","hostname":"ip-169-254-169-254","pid":7700,"uri":"\"/\"","method":"Get"}
{"msg":"response","v":0,"name":"slog-rs","level":30,"time":"2019-07-20T05:31:22.404425952+00:00","hostname":"ip-169-254-169-254","pid":7700,"status":"200 OK","route":"\u001b[32mGET\u001b[0m \u001b[34m/\u001b[0m \u001b[36m(\u001b[0m\u001b[35mindex\u001b[0m\u001b[36m)\u001b[0m"}

Again, if all that was complicated to follow and you prefer to look at the git commits as I went through this ordeal, check out the repository.

The post Better Logging for the Web Application appeared first on Learning Rust.