progress.Log writes the events of a Bus as JSON, one object per line: an
event log, for a bug report, a CI job’s artifacts, a test, or a converter to
another tracing system. The displays are for people and may change their text
from one release to the next; the log is for programs, and its format is an
interface of the kit, versioned apart from the module. This document is its
reference. progress/testdata/log-v1.jsonl is version 1, line for line, and
the tests fail when the log writes anything else.
How a program lets its users ask for a log, by a flag or a variable, and
where it writes it, is the program’s to say in its manual.
progress/cliprogress opens it for a program that names its flag and its
variable.
Lines#
The first line of a run says what the run is; every line after it is one event:
{"v":1,"type":"trace","run":"0123456789abcdef","trace":"4bf92f3577b34da6a3ce929d0e0e4736","parent":"00f067aa0ba902b7","traceFlags":"01","traceState":"rojo=00f067aa0ba902b7","program":"prog","version":"v1.2.3"}
{"v":1,"run":"0123456789abcdef","trace":"4bf92f3577b34da6a3ce929d0e0e4736","seq":5,"time":"2026-09-25T12:00:00.000000000Z","type":"start","span":"b7e3a1c09d2f4e10","parent":"b7e3a1c09d2f4e0f","kind":"target","name":"exe0001","state":"queued","node":"exe0001","host":"exe0001.hpc.example.org","role":"compute"}
Several runs may append to one file, the commands of one CI job for
instance, and may share one trace; run tells their lines apart. Each run
writes whole lines, in pieces of at most 64 KiB, a longer line on its own,
so the lines of runs appending to one local file at once, each opening it
for appending, do not cut into each other. That holds only where a write is
taken whole: a pipe takes one whole only up to PIPE_BUF bytes, 4 KiB on
Linux, and a file on NFS not at all when several machines append to it, so
runs that write to a pipe or to NFS at once each need a file of their own.
The first line#
| Key | Holds |
|---|---|
v | The version of the format, 1 |
type | trace |
run | The run, 16 hexadecimal digits drawn for each Log unless LogOptions.RunID names it, the same on every line of the run |
trace | The trace the run’s spans belong to, 32 hexadecimal digits |
parent, traceFlags, traceState | When the run continues a trace another program began, as ParseTraceContext reads it from a W3C traceparent and tracestate: the span of that program’s the run works under, 16 hexadecimal digits; the trace flags, two; and the tracestate as it was given |
program, version | The program that wrote the log and its version, as LogOptions name them; the program is the Bus’s, BusOptions.Program, when LogOptions names none |
An event#
| Key | Holds |
|---|---|
v | The version of the format, 1 |
run, trace | As on the first line |
seq | The event’s number, from 1, as the Bus numbered it: the one order every sink saw. It has no gaps but those of the advances the log left out, which leftOut on the span’s end counts. Lines are in that order but for an advance the log held: it follows the lines of other spans written while it waited |
time | When the event happened, in UTC, as RFC 3339 with nine digits after the second, so that the times of one run sort as they happened |
type | start; run, a queued span that starts to run; update, a span whose total, message, or unit and size of work changed; line, a line of output; end; suspend and resume, the displays taken off the terminal for a question and put back; advance, a span whose amount changed, which the Bus sends at most once each 100 ms a span, by its clock |
span, parent | The span the event is about and the one it was started under, 16 hexadecimal digits each; the root has no parent. A suspend or resume has only a span, the one it was asked for under, if any |
kind | command, step, batch, target, call or wait |
name | What the span is, in few words |
flags | A list of hidden, fold, show-lines and dry-run |
state | queued, running or ended, once the event has happened |
node, host, role | What a target or a call is for, a node or whatever else the program’s targets are, and the address and role the work goes to |
total, limit, batch | How many targets a step or a batch expects, how many it works on at once, and a batch’s place among its step’s, 2/5 |
message | One short line for a display, such as the question a confirmation asks |
method, path, httpStatus | The request of an HTTP call, and the status of its answer |
cache, source | Where a lookup was answered from, such as hit, miss, memory or disk; and the kind of source a secret or a credential was read from, never the value |
timeout | The bound of a call, or the length of a wait, in seconds |
exit | The exit code of a command; 0 is written, and a command that gave none has no exit |
amount, size | How much of the span’s own work is done, and how much there is, in its unit; never what is below it. A span has them on every event from the first that sets them, the amount the Bus last sent in an advance or an update, which takes the newest, and its end the final one; a size left out is one not known |
unit | What the span’s work is counted in: items, bytes or percent, whose size is always 100 |
status | How the span ended: ok, failed, canceled or skipped |
class | Why a span that failed did: target, transport, timeout, auth, pin, usage or canceled |
err | The error the span ended with, on one line |
stream | The stream a line of output came from, stdout or stderr |
dropped | The lines of output the sinks were not sent: on a line, those left out since the span’s previous line, and on an end, all of the span’s |
leftOut | The advances of the span the log did not write: on an advance, those since the span’s previous advance that it wrote, and on an end, all of the span’s. LogOptions.AdvanceEvery sets how often the log writes an advance of a span, a second by default, by the events’ times, and the first of a span is always written; the newest advance it would leave out it holds instead, and writes once its place comes, unless another event of the span comes first, so that the amount a span stopped at is in the log while its work pauses; a negative value writes every one the Bus sends, and then there is no leftOut. Unlike dropped, which lines the sinks were never sent, the Bus sent these to every sink, and only the log leaves them out |
A key whose value is zero or empty is left out, but for exit. name,
message and err are text for people, not names to match: a program may
change them in any release. Every other value is one this document lists.
Versions#
v is progress.LogVersion. It changes only when what a key or a value
means changes, and such a change is a breaking change of the kit, named in
its release notes. Under version 1:
- a key or a value may be added, in a minor release, and a reader leaves out the keys and the values it does not know rather than failing on them;
- a key is never renamed or removed, and a value never changes its meaning;
- the golden log is changed only by adding to it.
The version of the log is not the version of the module: a release of the
kit that adds nothing to the log writes the same version, and a program that
reads logs written by several releases reads each line by its v.
What never goes in#
A span can say only what progress.Fields holds, so the log has no place for
an argument vector, a script, standard input, the environment, a header or
the value of a secret or a credential. A line event says which stream the
line came from, and nothing of what it said: the text of a line never leaves
the process. The log asks for no lines of output itself, so there are line
events only while a display asks for them.
The text that does go in, a name, a message or an error, has been through
progress.Sanitize, as every text in an event has: nothing in it acts on a
terminal, and it keeps to its bound. An error may still name a host and say
why it failed, so a program that writes the log to a file creates it
readable by its owner alone.
Writing#
The log writes from a goroutine of its own, never under the Bus’s lock, in
whole lines: once 64 KiB wait, as the command, a step or a batch ends, and
LogOptions.FlushEvery after a line came at the latest, a second by default,
so that a log followed as it grows, or that of a run killed, falls little
behind. A program whose log a live view of the run follows sets it shorter;
a negative value writes each line as it comes. An idle log waits for nothing. A write that fails stops the
log, and so does a writer that falls 8 MiB behind, a pipe whose reader has
stopped: the log never holds the work up. A log that falls behind still
writes the lines it had taken, should its writer take them after all, and
leaves out those that come after, so that what is written is the start of
the run without a gap. Close writes what is left, waiting five seconds at
most, and returns the error that stopped the log short, if one did. Once
it has given up waiting, the log starts no write; one already under way
cannot be stopped, so Close says so, and Done is closed once that write
has returned, after which the writer may be closed.
Reading#
progress/eventlog reads the log back, as the rules above ask of a
reader. Decode turns a line into the first line of a run, or into one
of its events as a progress.Event, the one the Bus sent the log but for
the text of a line of output, which the log never held. It leaves out a
key it does not know, a value it does not know of a key whose values are
the kit’s, and a key whose value is of the wrong type; it refuses a line
of another version, with an error that matches ErrVersion, so that a
program can tell its user that the log is newer than the reader, a line
of a type it does not know, and an event without a time or, but for a
suspend or resume, without its span. A Reducer counts the lines it
refused in Skipped. It sanitises
every text as a Bus does, cut to the same bounds, so that a log another
program wrote, or one changed by hand, reaches a terminal or a page no
less safe than one the kit wrote. A test reads the golden log, writes it
again with progress.Log and compares the two, line for line, so the
reader and the writer cannot drift apart; a fuzz target holds the same
for any line the reader takes.
Tail reads a log as it grows, a poll at a time, whole lines only, and
leaves out a line longer than MaxLine, 1 MiB. It follows the rotation
of progress/cliprogress: the copy with “.1” after the log’s name is
read first, and read on while a command that had the log open when it
was moved still writes there. A log cut short, or made again, is read
again from its start, and the reader it feeds is told to forget what it
had. The Forwarder of NewForwarder gives the events of one run, the
run of the trace the server handed the child, to a progress.Sink, each
once, by the seq of the run, so that a log read again gives no event
twice, and drops the lines of every other run: what a server that runs a
command as a child, with the child’s log in a file of its own, sends on
as the child’s progress. Reducer folds the lines into runs, each the tree of
the spans of its command, the first span of the kind command, as a
view of what a program did draws them; a span whose parent the log does
not hold is the command’s. It keeps ReducerOptions.KeepRuns runs,
DefaultKeepRuns, 100, by default, dropping the oldest that has ended first,
else the oldest, and ReducerOptions.MaxSpans spans of a run,
DefaultMaxSpans, 131072, by default, tells which runs changed since it
was last asked, and returns one run by its ID.
The golden log#
progress/testdata/log-v1.jsonl is a run that has every key this document
lists, but program, which came after it and which a test of its own checks
on the first line, and every value this document lists for a key: each
type, kind, flags, state, status, class, stream and unit. Of the
keys whose values are the program’s to choose, text such as name and
err, where a lookup was answered from, cache, and the kind of source a
source names, it has an example each, and each of the examples this
document gives for cache.
The span ids, which each Bus draws at random, are written as #1, #2 and
so on in the order they first appear. The test that writes it compares what
the log writes with it, line for line, and fails on any difference; another
test sets every part of an Event and fails when one is neither logged nor
left out on purpose, and a third fails when a value has no name in the log,
or when a key or a listed value is on no line of the file.
go test ./progress -run TestTheEventLog -update rewrites the file, and the
difference is then a change to the format, reviewed as one: it keeps
version 1 only when it adds.
The file is changed only by adding to it. Its first 48 lines, the trace and
47 events of a command exec, are those version 1 was first released with,
and a test fails when they are not, byte for byte. What the file has said
since, a value of cache and a dropped count among them, comes after
them, from a second command, status, run on the same Bus once exec has
ended, so its events go on from seq 48 and its spans from #18. A third
command, fetch, run once status has ended, reports work in each unit,
with its advance events, one of them with a leftOut and its end with another, and its amount, size and unit.