Rotating log files in Rust, and reassembling them for inspection

Context

Open Analytics is working on a huge data processing pipeline in the context of high-content imaging. The latest work to this end is a new product that will work in conjunction with Phaedra as part of the pipeline which now covers much more ground than before. The entire backend of this new component is written in Rust and consists of several web servers.

Proper log rotation has been a focus as of late, since it is critical to be able to keep on top of things in this massive processing pipeline. In our Rust web servers, we use slog with slog-json for structured logging, writing log records to file as JSON objects. Log rotation is enabled through the file-rotate crate which plugs in as a middleware wrapping the File to which log records are written.

This crate is essentially like having logrotate embedded in each application binary. The benefit to this is that no infrastructure work is required in order to set up log rotation. Unlike logrotate, instead of a periodic task, the rotation logic is executed whenever log records are written to file.

file-rotate does not necessarily aim to be exactly like the classic logrotate, but provides some useful features, like:

• Content limit configuration: when to rotate
• Using count or timestamp as suffix
• Age-based deletion of log files, or a maximum number of files
• Optional compression
• Getting a list of log files

The benefit of the last point will become clear soon.

In our setup, we create files with log rotation as follows:

use file_rotate::{
compression::Compression,
suffix::{FileLimit, TimestampSuffixScheme},
ContentLimit, FileRotate,
};
pub fn file_rotate(path: PathBuf, lifetime: Duration) -> FileRotate<TimestampSuffixScheme> {
FileRotate::new(
path,
TimestampSuffixScheme::default(FileLimit::Age(lifetime)),
ContentLimit::BytesSurpassed(5_000_000),
Compression::OnRotate(2),
)
}

This creates a configuration of FileRotate which rotates files as they reach 5 MB, uses a timestamp as suffix, deletes files as their timestamp reach a certain age, and compresses all but the two most recent log files.

For example, these are some files found in production:

all.log
all.log.20220203T081449
all.log.20220203T071848
all.log.20220203T062250.gz
all.log.20220203T052652.gz

Read more about the library’s API in the file-rotate rustdocs.

Enter assemble-logs: Tool to assemble the contents of rotated log files, with filtering and pretty formatting

Now that our log history is scattered across multiple files, some of which are compressed, it can be impractically difficult to unravel the story of what happened in our application by looking back in the log history.

A first instinct could be to write a script to assemble these logs for inspection. For example to concatenate the aforemnetioned 5 log files, we can write

$ gunzip -c all.log.20220203T052652.gz ; gunzip -c all.log.20220203T062250.gz ; cat all.log.20220203T071848 all.log.20220203T081449 all.log | less

A script would make things a little easier, but maybe we can do better by utilizing the JSON format of log records to also do filtering and formatting. At Open Analytics, we created a Rust binary crate that uses the same file-rotate library to do all of this:

assemble-logs

It assumes that log records are written as JSON, and

• decompresses compressed log files
• assembles the contents of all log files in chronological order
• filters each record with an optional jq filter
• formats the log records prettily with colors
• writes the formatted log records to stdout, so piping it to less -r is a good idea

Usage is as follows:

$ assemble-logs assemble -h
assemble-logs-assemble
USAGE:
assemble-logs assemble [FLAGS] [OPTIONS] <LOG_PATH> [JQ]
ARGS:
<LOG_PATH> The path to the main log file
<JQ> JQ query; must return a bool; only used for filtering
FLAGS:
-c, --compact Compact - don't print newline on each key-value
-h, --help Print help information
-n, --no-format No formatting: just print json
-V, --version Print version information
OPTIONS:
--jq-transformation <JQ_TRANSFORMATION> Only effective with --no-format

Filtering with jq

The <JQ> arg is a jq query that acts as a log record filter and must return a boolean. Some examples:

Here is a full command line that would only show log records during a specific minute

assemble-logs assemble logs/all.log '.ts > "2021-09-02T22:30" and .ts < "2021-09-02T22:31"' | less -r

In the following we will only show the filter itself. Filter by (short) log level (CRIT, ERRO, WARN, INFO, DEBG, TRCE):

'.level == "WARN" or level == "ERRO"'

Tags can be very useful, especially if your application has several independent components, and perhaps even asynchronous periodic tasks – we have plenty, so we frequently want to follow a specific tag. To show only records with a specific tag:

'.tag == "phaedra-poller"'

Everything actix-related (e.g. all incoming requests):

'.tag | startswith("actix")'

Filtering makes use of the JSON fields that slog-json outputs. An example JSON log record:

{
"msg": "Start pollig worker",
"level": "DEBG",
"ts": "2022-01-31T15:20:20.637",
"tag": "poller",
"worker": "http://localhost:8002/",
"poller": 20166
}

The keys "msg", "level", "ts", "tag" are always present. The rest of the keys are key-value pairs set when logging with slog. These can all be used in the jq filter, so there are plenty of possibilities.

Future work

In assemble-logs, we plan to implement a follow subcommand that acts like tail -f. It will of course include formatting and filtering just like the assemble subcommand. Another current shortcoming is that the suffix scheme is hardcoded (AppendTimestamp) – it should be possible to configure this, perhaps on the command line.

Summary

In our Rust projects we have opted for application-internal log rotation rather than the conventional external log rotation using logrotate. Everything is inside the binary; log rotation is taken care of, even in your local dev setup.

Using a Rust library for log rotation has a further advantage: the library provides a function to get a list of all log files, chronologically ordered, with structured information about each suffix, which made the work on assemble-logs easier and less error prone (assuming that the library is correct). Should some behaviour change in file-rotate, we just have to update our dependencies.