> ## Documentation Index > Fetch the complete documentation index at: https://aspect.build/llms.txt > Use this file to discover all available pages before exploring further. # Watch Bazel work > Spawn Bazel from a task and read both of its structured output streams live, while it works — the Build Event Protocol and the execution log. ```shell theme={null} git checkout step-5 ``` 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: ```shell theme={null} diff .course/observe-passes/pass1.axl .course/observe-passes/pass2.axl diff .course/observe-passes/pass2.axl .course/observe-passes/pass3.axl diff .course/observe-passes/pass3.axl .course/observe-passes/pass4.axl diff .course/observe-passes/pass4.axl .course/observe-passes/pass5.axl ``` 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`: ```shell theme={null} cp .course/observe-passes/pass1.axl .aspect/observe.axl aspect observe //lib/queue:queue_test ``` `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: ```text theme={null} error: task "observe" in group [] (defined in ".aspect/observe.axl") conflicts with another task or group ``` Delete the stray file and it all comes back. **Pass 1 — spawn and wait.** ```python theme={null} build = ctx.bazel.test(flags = _bazel_flags(ctx), *ctx.args.targets) return build.wait().code ``` `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: ```python theme={null} events = bazel.build_events.iterator(kinds = ["test_summary"]) # BEFORE the spawn build = ctx.bazel.test(build_events = [events], ...) # handed to it for _tick in sleep_iter(_TICK_MS): # BEFORE wait() ... return build.wait().code ``` 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: ```shell theme={null} bazel clean aspect observe //... ``` 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: ```text theme={null} [356 / 676] 2 / 55 tests; 15 actions, 0 running; last test: ...lock:clock_test GoCompilePkg internal/domain/pricing/pricing.a; 0s disk-cache Testing //lib/schema:schema_test; 0s disk-cache [+ 1380ms] passed //lib/codec:codec_test [+ 1380ms] passed //lib/clock:clock_test [373 / 677] 3 / 55 tests; 16 actions, 0 running; last test: ...ema:schema_test ``` 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: ```python theme={null} build = ctx.bazel.test(execution_log = True, ...) for entry in build.execution_logs(): ... ``` 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: | | how to get there | spawns | runners | | - | - | - | - | | cold | `bazel clean`, plus a disk cache this build has never used: `aspect observe //... --disk_cache=$(mktemp -d)` | 458 | `darwin-sandbox 458` | | clean, disk cache intact | `bazel clean`, then `aspect observe //...` | 458 | `disk cache hit 458` | | warm | run it again, change nothing | **0** | — | 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: ```shell theme={null} aspect observe //lib/queue:queue_test --nocache_test_results --format=json 2>/dev/null | jq '.actions' ``` `--` 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: ```text theme={null} ERROR: no such target '//:-nocache_test_results' ``` `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: ```shell theme={null} aspect observe //lib/queue:queue_test --nocache_test_results --build_event_publish_all_actions ``` Now it crashes: ```text theme={null} error: Object of type `action_executed` has no attribute `overall_status` --> .aspect/observe.axl:101:18 ``` 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)`: ```python theme={null} if event.kind != "test_summary": print(" [+%sms] %s" % (_rjust(now_ms() - spawned_at, 6), event.kind)) continue ``` ```shell theme={null} bazel clean aspect observe //... --build_event_publish_all_actions 2>&1 | grep -c action_completed ``` ```text theme={null} 725 ``` 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: ```shell theme={null} git checkout -- .aspect/observe.axl ``` Next: you won't ship this. This documentation is built and hosted on [Mintlify](https://mintlify.com), a developer documentation platform.