Systems · Lesson 26.4

Log

Source
Write structured log records with a Logger: a level, a message and typed Fields, as text or as JSON lines, with levels that filter, context fields on every record, and the process-wide log on standard error.
You'll need: Interface value, Slice, Enum, JSON

A program that runs for a long time — a server, a background job, a build — needs a diary: a line for each thing worth knowing later, read when something has gone wrong and nobody was watching. PrintLine can write such lines, but a log wants two things more. Each record has a level, so the routine ones can be switched off without touching the code. And its details are fields with names and types — port=8080, not "listening on port 8080" — so a tool can search, filter and count them.

The Log package builds those records:

import Log::{
    Enabled, Field, Info, Level, LogFormat, Logger, SetFormat, SetLevel, SetTimestamps, Warn
};

A logger

A Logger writes records to any Io::Writer: a file, a socket, a pipe — or, here, standard output, so you can see them:

var log = Logger::New(allocator, StandardOut::Acquire(), LogFormat::Text);
log.SetTimestamps(false);

Every record normally starts with the time, in RFC 3339 and UTC to the millisecond, such as 2026-10-15T09:41:07.312Z. The lesson turns times off so that its output is the same on every run; a real program leaves them on, unless something downstream adds its own, as a service manager's journal does.

Logging never fails. A record that cannot be written is dropped, and the logger keeps the first failure for Failure() to report — a log that stops the program when the disk fills up would be worse than no log.

Records and fields

A record is a level, a message and a slice of fields. Field has one constructor for each type a value can have:

ConstructorValue typeWritten as
Field::Text("path", "/a b")textpath="/a b"
Field::Integer("status", -1)int64status=-1
Field::Unsigned("port", 80)uint64port=80
Field::Float("ratio", 0.5)float64ratio=0.5
Field::Boolean("tls", true)booltls=true
log.Info("server started", [Field::Unsigned("port", 8080), Field::Boolean("tls", false)]);
log.Warn("slow request", [Field::Text("path", "/search"), Field::Float("seconds", 2.5)]);
log.Error("cannot open file", [Field::Text("name", "my notes.txt")]);

In text, a value with a space, a quote or = in it is quoted, and a line break is written as \n, so a record is always exactly one line — even when a message comes from somewhere you do not control.

Levels

The levels run from the finest detail to the most serious:

LevelFor
Tracefollowing a program step by step
Debugdiagnosing a problem
Infothe ordinary progress of a program — the default
Warnsomething unexpected that the program survived
Errorsomething that failed

A logger writes records at its level and above. A record below it is dropped before any of it is built, and Enabled asks the question first — worth it when a field is costly to work out:

log.Debug("cache lookup", [Field::Text("key", "user:7")]);
PrintLine("debug enabled? {}", log.Enabled(Level::Debug));
log.SetLevel(Level::Debug);
log.Debug("cache lookup", [Field::Text("key", "user:7")]);

The first Debug writes nothing; the second, after SetLevel, does. A build can go further. The LogLevel define — rux run --define LogLevel=info, or LogLevel = "info" under [Build.Defines] in Rux.toml — drops everything below that level whatever a logger is set to, so the second Debug disappears too.

Context

SetContext gives a logger fields that start every record from then on. A server handling a request sets the request's identifier once, and every line it logs while handling it can be found by that one value:

let context = [Field::Text("request", "r-42")];
log.SetContext(context[..]);
log.Info("handled", [Field::Integer("status", 200)]);

The logger borrows the slice, so context must outlive the records that use it.

Text or JSON lines

LogFormat::Text is for people. LogFormat::JsonLines is for programs: one JSON object per line, with level and message members followed by the fields, their types intact — a log collector reads it without guessing where a value ends:

INFO  server started port=8080 tls=false
{"level":"info","message":"server started","port":8080,"tls":false}

The process-wide log

A program does not need a Logger to log. The free functions Info, Warn and the rest write to standard error, with settings of their own — SetLevel, SetFormat, SetTimestamps — that every thread shares. A lock is held only while a finished record is written, so records from different threads never mix within a line:

SetTimestamps(false);
SetLevel(Level::Warn);
SetFormat(LogFormat::Text);
PrintLine("global info enabled? {}", Enabled(Level::Info));
Info("not written: below the level");
Warn("disk almost full", [Field::Unsigned("free-mb", 120)]);

Standard error is the right place for a log: it reaches the screen, but stays out of the program's real output, so rux run > out.txt captures only what the program printed.

Logs that do not fill the disk

A log file that is only ever appended to grows until the disk is full. RotatingFile is a Writer that starts a fresh file before a write would take the current one past a size, keeping a few of the older ones as app.log.1, app.log.2 and so on. A record is never split between two files:

var holder = OsString::FromText(allocator, "Bin/app.log")?;
var file = RotatingFile::Open(allocator, Path::FromView(holder.View()), 1048576, 3)?;
var log = Logger::New(allocator, (@file).Stream(), LogFormat::JsonLines);
log.Info("started");

Here the file starts afresh at 1 MiB and three older files are kept. Stream lends the logger the file through a pointer, so file must stay in place while the logger uses it.

The program

The whole lesson is one package in the Examples repository. Its comments explain every step.

Src/Main.rux
// A log is a program's diary: one line for each thing worth knowing later, such as a request
// served, a file skipped or a retry. `PrintLine` can write such lines, but a log wants more. Each
// record has a level, so the noisy ones can be switched off; and its details are fields with
// names and types, `port=8080` rather than prose, so a tool can search and count them.
//
// The `Log` package builds those records. A `Logger` writes them to any `Io::Writer` — a file, a
// socket, or here standard output — as one line of text or one JSON object per line. Logging
// never fails: a record that cannot be written is dropped, and the logger remembers the first
// failure for `Failure` to report.
//
// Every record normally starts with the time. This program turns times off so that its output is
// the same on every run.
import Allocator::{ Allocator, SystemAllocator };
import Io::{ PrintLine, StandardOut };
import Log::{
    Enabled, Field, Info, Level, LogFormat, Logger, SetFormat, SetLevel, SetTimestamps, Warn
};

func Main() -> int {
    var system = SystemAllocator();
    let allocator: Allocator = system;

    // A logger over standard output, writing text. Its level starts at `Info`.
    var log = Logger::New(allocator, StandardOut::Acquire(), LogFormat::Text);
    log.SetTimestamps(false);

    // A message, then typed fields. Text with a space or a quote in it is quoted.
    log.Info("server started", [Field::Unsigned("port", 8080), Field::Boolean("tls", false)]);
    log.Warn("slow request", [Field::Text("path", "/search"), Field::Float("seconds", 2.5)]);
    log.Error("cannot open file", [Field::Text("name", "my notes.txt")]);

    // Levels run Trace, Debug, Info, Warn, Error. Records below the logger's level are dropped
    // before any of them is built; `Enabled` asks first, for a field that is costly to compute.
    log.Debug("cache lookup", [Field::Text("key", "user:7")]);
    PrintLine("debug enabled? {}", log.Enabled(Level::Debug));
    log.SetLevel(Level::Debug);
    log.Debug("cache lookup", [Field::Text("key", "user:7")]);

    // Context fields start every record from now on — handy for the request being handled.
    let context = [Field::Text("request", "r-42")];
    log.SetContext(context[..]);
    log.Info("handled", [Field::Integer("status", 200)]);

    // The same records as JSON lines: one object per line, ready for a log collector.
    var json = Logger::New(allocator, StandardOut::Acquire(), LogFormat::JsonLines);
    json.SetTimestamps(false);
    json.Info("server started", [Field::Unsigned("port", 8080), Field::Boolean("tls", false)]);
    json.Warn("slow request", [Field::Text("path", "/search"), Field::Float("seconds", 2.5)]);
    let failed = log.Failure() != none || json.Failure() != none;
    PrintLine("write failures: {}", failed ? "some" : "none");

    // The process-wide log needs no logger: `Info`, `Warn` and the rest write to standard error,
    // from any thread, with settings of their own.
    SetTimestamps(false);
    SetLevel(Level::Warn);
    SetFormat(LogFormat::Text);
    PrintLine("global info enabled? {}", Enabled(Level::Info));
    Info("not written: below the level");
    Warn("disk almost full", [Field::Unsigned("free-mb", 120)]);

    // A field is built from a key and a value of one type. The value's type picks the function:
    //
    //     Field::Integer("port", 8080u64)
    //         error: argument 2 to 'Field::Integer' has type 'uint64', but parameter 'value' requires 'int64'
    return 0;
}

Besides Io, its Rux.toml lists Allocator and Log under [Dependencies].

Run it

cd Examples/Systems/Log
rux run
INFO  server started port=8080 tls=false
WARN  slow request path=/search seconds=2.5
ERROR cannot open file name="my notes.txt"
debug enabled? false
DEBUG cache lookup key=user:7
INFO  handled request=r-42 status=200
{"level":"info","message":"server started","port":8080,"tls":false}
{"level":"warn","message":"slow request","path":"/search","seconds":2.5}
write failures: none
global info enabled? false

The program also writes one record to standard error, through the process-wide log, which the block above leaves out:

WARN  disk almost full free-mb=120

Common mistakes

Try it yourself

  1. Turn timestamps back on for log and run the program twice. Which part of each line changes?
  2. Make a Logger over StandardError::Acquire() in JSON lines, and run the program with rux run 2> log.txt. What ends up in the file?
  3. Log a message with a line break in it, such as "first\nsecond", in both formats. How is it kept on one line?
  4. Write a log to Bin/app.log through a RotatingFile with a limit of 200 bytes and one older file, log twenty records, and look at both files.

Learn more