Skip to main content
Everything so far has asked Bazel questions. This section runs it, and reads what it emits while it works. Bazel will write both of these to a file — --build_event_json_file for the Build Event Protocol, --execution_log_compact_file for the execution log. Neither needs a service. What they need is something to read them, and that friction is why the work usually happens elsewhere: a BES endpoint on CI, a dashboard after the fact. .aspect/observe.axl does it here instead, on the machine that produced them, while the build is still running.

​
Five passes

The file arrived whole, but it was built in five steps and .course/observe-passes/ has each one. Read them in order, and read them as diffs — that is where the shape of the thing is, and even the largest diff is smaller than the finished file:
Each pass also carries its own module docstring explaining what it added and why, so the diffs read as prose as much as code. pass5.axl is byte-identical to the .aspect/observe.axl you already have — the fifth pass is the finished file, not a step before it. The directory holds one more thing, _fmt_block.txt: a standalone copy of the _ljust / _rjust / _seconds helpers. The passes still define them inline — the copy is there so you can read the column arithmetic once, up front, and then skim past it everywhere it reappears in the diffs. To run a pass, copy it over .aspect/observe.axl:
git checkout -- .aspect/observe.axl puts the finished file back.
Copy it onto observe.axl, not alongside it. cp .course/observe-passes/pass1.axl .aspect/ leaves two files declaring a task named observe, and then every aspect command in this repository fails — aspect describe included:
Delete the stray file and it all comes back.
Pass 1 — spawn and wait.
test() doesn’t block; wait() does. Run it — Bazel’s progress streams to your terminal exactly as a bare bazel test would, because an unset stdout inherits. Pass 2 — read the events live. Three lines carry the whole lesson:
Note bazel.build_events is a bare global. ctx.bazel is only for spawning. The ordering is the point, and it is easy to get wrong in a way that silently still works. Create the iterator after the spawn and you miss the early burst. Call wait() before the loop and there is nothing left to watch — wait() returns when Bazel has exited. Pass 3 — aggregate. Status counts, cached results, flaky list, slowest N. Pass 4 — the execution log. The second stream, covered below. Pass 5 — --format=json.

​
Proof that it is live

The execution log only records actions Bazel actually ran, so there has to be something to run. Start by emptying the local action cache:
The bazel clean is not optional. Step 1 had you run bazel test //..., so arriving here your action cache is warm, and a warm aspect observe //... prints spawns 0 and then stops — no runners, no cache hits by mnemonic, no largest action. There is no execution log to read. The clean is cheap, because .bazelrc keeps the disk cache in ~/.cache/bazel/course-disk: it throws away the local action cache and the rebuild replays from disk in about a second.
The task stamps each result with milliseconds since the spawn, so you can interleave them with Bazel’s own action counter:
Two results printed while Bazel was between its 356th and 373rd action, with 2 of 55 tests finished. That is a live read, not a replay. The denominator climbs as Bazel discovers work, which is why it is 676 on one line and 677 on the next.
The interleave is a terminal effect. Bazel redraws that counter in place on a tty and emits almost none of it when its output is a pipe or a file, so aspect observe //... > log keeps every [+ ...ms] line and loses nearly all the [n / m] ones. Watch this one on screen.

​
The execution log, live too

The second stream comes off the same invocation, and it is live as well. Its spelling is the shorter of the two:
Ask for the log, iterate it. There is no handle to create before the spawn as there is for the BEP half, and no ordering to get wrong. The task drains it in its own loop, after the BEP loop and before wait() — the same side of wait() as everything else live, which leaves wait() doing nothing but handing back the exit code. It is also complete, and that is measured rather than promised. Eighteen counted invocations of a clean //... — six with nothing but a counter in the loop, six with _read_execution_log’s real input-set reconstruction in it, six read from a file on disk instead — returned 8929 entries, 458 spawns and 6864 file records every single time, with no variation in any of the three, and all eighteen named the same largest action: GoLink of @@gazelle+//cmd/gazelle:gazelle, at 13817 inputs. //lib/queue:queue_test on its own — one test, 20 spawns — is 5676 entries, every run, every spelling. The reason it holds is that the reader’s sends block: an expensive loop holds the producer up instead of losing entries to it, which is why the middle six read the same as the other twelve. None of those counts are on your screen. observe.axl prints spawns, runners, cache hits by mnemonic and largest action, and never an entry count, so every entry figure above came from a throwaway task written to do nothing but count them — which is also the only way you would ever check a claim like this one. A file sink — bazel.execution_log.file(path = ...) in execution_log = [...] — is the other shape, and all it changes is when. Bazel writes the entries to a path you name, and you read them back off disk after wait() with bazel.build.execution_log.ExecLogEntry().parse_from_delimited(ctx.std.fs.open(path)): all 8929 of them, decoded in 16 ms. That is the right shape when what you want is a finished build’s worth of actions rather than a running build’s — it is how aspect run --watch decides what to restart. For a report you print at the end either way, it buys nothing the live read doesn’t already have.
Do not ask for both at once. build.execution_logs() has to be the stream’s only reader, and a sink is already a reader. The call is refused, cleanly, and the refusal names what to do instead: “this build’s execution log already has a consumer: either execution_logs() was called twice, or the build was configured with a decoded execution_log.file(...) sink or an execution_log.iterator() handle, each of which clones a subscriber of its own, after which the stream’s own is dropped. Either way there is nothing left to hand out. Pass an execution_log.iterator() handle in execution_log=[...] and iterate that instead: a handle clones too, so it can be combined with sinks, and its kinds= filter runs in Rust before an entry becomes a Starlark value.”That refusal is the single-subscriber rule showing through. build.execution_logs() takes the stream’s own subscriber rather than cloning one, and a sink or handle has already cloned and left none behind — so there is nothing to hand out. The handle is the shape that composes, which is why the message points at it.
execution_log = True is not the only live form. You can also pass a handle — bazel.execution_log.iterator(), in execution_log = [...] and drained before wait(). It reads the same complete stream: 8929 entries here, and 8929 to both consumers when passed alongside a file() sink in one invocation.The reason to reach for it is cost. A handle takes kinds, and kinds is applied in Rust before an entry ever becomes a Starlark value, where a type(entry.type) == "spawn" test in your own loop pays for the conversion first and then throws the entry away. On this build spawns were 458 of 8929 entries — 5.1% of the stream, so nineteen entries in twenty converted for nothing. observe.axl passes True because its input-set reconstruction genuinely reads almost every kind; a spawn-shaped report is the case where kinds pays, and you will write one in the next section.

​
Cold against warm

The execution log is the only place the difference shows up. What decides the answer is whether Bazel’s local action cache still holds the actions, and what it falls back to when it doesn’t: The same 458 actions in the first two rows — only who ran them differs — and the third row runs nothing at all. The test verdicts are no help in telling these apart; only the action log distinguishes them. With one exception worth noting: the cold row is the only one that actually executes all 55 tests, so it is the only one where the flaky test in internal/domain/forecast can fire. You will meet that test again in the next section. If it does fire, the warm row below it reports spawns 1 rather than 0, and the one spawn is that test. A flaky verdict is not a cacheable one, so the next run has exactly one action left to settle. Nothing is wrong — rerun the warm row once more and you get the 0.
It is bazel clean that empties the local action cache — not a change to the command line. Add --define=x=1 to a warm run and you still get spawns 0; the action cache keys on the actions, not on your argv.And the cold row genuinely needs a scratch --disk_cache, fresh each time you want that row. .bazelrc points the disk cache at ~/.cache/bazel/course-disk for the whole machine, so once anything on this laptop has built this repository there is no cold left to find without one. If the last two rows are all you ever see, that is why.

​
Your turn

Bazel flags go straight after the target pattern:
-- is not the separator here. aspect observe //lib/queue:queue_test -- --nocache_test_results loses one dash and Bazel reads what is left as a target pattern:
observe.axl declares args.passthrough(position = "post_command"), which already means “everything after the targets”. Just type the flag.
Now widen the filter: change kinds = ["test_summary"] in _impl to kinds = ["test_summary", "action_completed"] and run it again. Nothing happens — not one extra event. Bazel does not publish an ActionExecuted event for an action that succeeded unless you ask it to:
Now it crashes:
Which is the lesson. _test_record() reads payload.overall_status off whatever the drain loop pops, so kinds is not a convenience — it is the only thing guaranteeing the loop ever sees a test_summary. (And note the two names for one thing: you filtered on action_completed, and the payload that arrives calls itself action_executed.) To see the volume, make the loop say what it got instead of assuming. One stanza, immediately above record = _test_record(event):
725 action_completed events against 55 test_summary ones — and 725 is exactly the number in Bazel’s own 725 processes: line. That filter is doing real work. Then put the file back:
Next: you won’t ship this.