Better Logging for the Web Application

I replace log and simple_logger with slog and sloggers, and then change again

Part of a Series: Designing a Full-Featured WebApp with Rust
Part 1: Piecing Together a Rust Web Application
Part 2: My Next Step in Rust Web Application Dev
Part 3: It’s Not a Web Application Without a Database
Part 4: Better Logging for the Web Application
Part 5: Rust Web App Session Management with AWS
Part 6: OAuth Requests, APIs, Diesel, and Sessions
Part 7: Scraping off the Dust: Redeploy of my Rust web app
Part 8: Giving My App Secrets to the AWS SecretManager

A journal ledger of accounts... like logging but only uses numbers
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

A spider web, wet from rain...

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.

Piecing Together a Rust Web Application

Part I: I work on a global static Config and on logging

Part of a Series: Designing a Full-Featured WebApp with Rust
Part 1: Piecing Together a Rust Web Application
Part 2: My Next Step in Rust Web Application Dev
Part 3: It’s Not a Web Application Without a Database
Part 4: Better Logging for the Web Application
Part 5: Rust Web App Session Management with AWS
Part 6: OAuth Requests, APIs, Diesel, and Sessions
Part 7: Scraping off the Dust: Redeploy of my Rust web app
Part 8: Giving My App Secrets to the AWS SecretManager

Hrm… how to find the right piece on Crates.io ???

For over a decade, I’ve worked on web apps with Perl, the last several years with Catalyst/Moose/DBIC and a slew of internal abstractions. There are a bunch of features I expect to need in any web app: config files (at different platform levels); structured logging; database ORM; templating; cookie, authentication, and session controls; en/decryption for access secrets; etc. I spent most of the overnight hours playing with piecing together a Rust web application, though I still have much more to do. After struggling for hours for what amounts to 279 lines of Rust code, I decided it was well worth it. I’ll try to explore some of my problems and what I worked out. This might take more than one post, so I don’t put you to sleep.

Global (Static) Application Config

This probably isn’t idiomatic Rust and frowned upon for even more reasons. I’m sure I’ll adapt to Rustic thinking as I learn, but for now, I’m liking this. I like to have a Config struct that is setup at init time and is immutable (music to the Rust compiler’s ears, I’m sure). I battled this with const and lazy_static and numerous other things. Eventually, I settled on a Crate that the author seems to have stumbled into writing/publishing (unless I’m missing some context): OnceCell. Where I was having trouble getting lazy_static to work, once_cell::sync::OnceCell seemed to work for me rather quickly.

Coupled with that, I like the notion of having Config settings initialized by YAML or JSON or TOML files and also able to be overridden in some way – usually environment variables. This path (and an earlier post) took me to the aptly named Config Crate. It does just what I need for pulling settings into a config from various places. I ended up adding the dotenv Crate as well, because something else used it in an example. I’m not sure I’ll keep ALL of these options forever, but it’s in the mix for now. There are, obviously, many ways to allow overrides vs protect the settings on disk, and many ways to decide which platform you are running on besides an ENV variable – and I’m flexible.

EDIT: I just realized that putting <Mutex> on my type means I have to lock() it to read it – and that prevents other functions (and other threads) from reading it. Since I’m ok with CONFIG being immutable, I really don’t need the Mutex, so I dropped it.

My settings.rs module looks like this for now:

use config::{Config, Environment, File};
use dotenv::dotenv;
use once_cell::sync::Lazy;
use serde_derive::Deserialize;
use std::env;

#[derive(Debug, Deserialize)]
pub struct Server {
    pub run_level: String,
}

#[derive(Debug, Deserialize)]
pub struct WebService {
    pub bind_address: String,
    pub bind_port: u16,
}

#[derive(Debug, Deserialize)]
pub struct Settings {
    pub server: Server,
    pub webservice: WebService,
    pub database_url: String,
}

pub static CONFIG: Lazy<Settings> = Lazy::new(|| {
    dotenv().ok();
    let mut config = Config::default();
    let env = env::var("PPS_RUN_MODE").unwrap_or("development".into());

    config
        .merge(File::with_name("conf/default"))
        .unwrap()
        .merge(File::with_name(&format!("conf/{}", env)).required(false))
        .unwrap()
        .merge(File::with_name("conf/local").required(false))
        .unwrap()
        .merge(Environment::with_prefix("PPS"))
        .unwrap();
    match config.try_into() {
        Ok(c) => c,
        Err(e) => panic!("error parsing config files: {}", e),
    }
});

And config files like these examples:

conf/default.toml:

[server]
run_level = "default"

conf/development.toml:

[server]
run_level = "development"

[webservice]
bind_address = "0.0.0.0"
bind_port = 3000

conf/staging.toml:

[server]
run_level = "staging"

[webservice]
bind_address = "0.0.0.0"
bind_port = 3000

and, conf/production.toml:

[server]
run_level = "production"

[webservice]
bind_address = "0.0.0.0"
bind_port = 80



Application Logging

Piecing together a Rust web application includes another area of big concern – logging! Logging can easily become a tremendous burden of bandwidth and storage space, but a single log record might explain a production incident and lead you to a quick fix! Structured logging is great for logging platforms because storing and especially searching can be greatly improved when the message is static and data fields attached to the log record fill in the variable gaps.

To get things going, I started with the Crates log and simple_logger, but I probably will move to slog for the structured logging. The very first line in my main() is to call setup_logging() so if anything breaks on app initialization, we should get a log for it. With CONFIG a global static, this simple function looks like this for now, but soon I will work out specifying the logging level in the settings so it can be verbose for devs, but tamer on production:

pub fn setup_logging() {
    simple_logger::init_with_level(log::Level::Info)
        .expect("Trouble starting simple_logger");
    let run_level = &CONFIG.server.run_level;
    warn!("Running as run_level {}", run_level);
}

We still have the web framework, the database, encryption and more to come. Next up, more single-word Crates: Iron, Rocket and Diesel. I’d love to hear what Rust developers think of this so far – suggestions are welcome. Here’s the repository on Github – you can skip ahead and see what other messes I’ve made.