Preserve E2E run evidence

[chrisgleissner]

Summary

An E2E run currently leaves a console log and nothing else. When a suite fails
overnight, that log is all a reader has: no screen, no device log, no record of
what the device was doing at the time, and no way to re-run the single check
that failed without reading the suite's source.

This branch gives a run a directory and a reader.

• run-tests -o DIR keeps the whole run: every check, suite, health sweep and
  device request as JSONL, each suite's console log, the screens the suites
  read, and the state captured when a check failed.
• python3 tools/e2e_report.py DIR writes DIR/index.md
  with no device attached: a status line you can grep, then every failing check
  with its screen, its log tail, and the command that runs it again.
• --syslog adds the devices' own log to the same directory.
• --record adds a video of the harness's screen beside the device's, with the
  device's audio, subtitled with the check that was running.

The same branch makes the Ultimate II+L and the C64 Ultimate first-class runner
targets alongside the Ultimate 64, because a report is only worth having if the
gate covers more than one machine.

Five firmware files change. All five are in the device-log path, and the
section below explains each one and why the change has to be in the firmware
rather than in the harness.

This work and the machine-code monitor work were developed on one branch and
have now been separated. The monitor changes are in #785, which is based on
this branch and should be merged after it.

What a run keeps

-o DIR writes index.md at the top and one directory per target under it.
Inside a target's directory:

Artifact	What it is
run.jsonl	the plan, every health sweep, every suite verdict, and the run's own record
<label>-<suite>.jsonl	every check and device action of one suite, all attempts
<label>-<suite>.log	that suite's console output, all attempts appended in order
screens.jsonl	the screens the suites read, which they fetch anyway
capture/	the state captured when a check failed, and the recorder's stills as a .png and .txt pair
syslog.txt	the device's own log, with --syslog
video.mp4, video.srt	the recording, with --record

A suite run is identified as target/label/suite/attempt and a check is that
plus its index, and a suite run's file names are that key with the target
dropped and / written -. The record shapes are documented in
tests/lib/README.md. The full specification the implementation was written
against is tests/e2e/doc/observability-spec.md.

One rule runs through all of it: nothing the observability layer does may
change a verdict or an exit status. An output directory that cannot be created
is reported once and the run continues. A log file that cannot be written is
found when the collector starts rather than on the first datagram. An interval
that a component could not observe is recorded as a gap with a start and an
end, or with no end when it was still open, and shown on the timeline beside
the suite that was running at the time.

The report

index.md is Markdown and nothing else, so GitHub renders it, less
reads it and grep searches it. It opens with a fixed 15-line preamble and a
one-line verdict, then gives each failing check the screen it was looking at,
the tail of its log, the facts the run already knew about it, and the exact
command that reproduces it. A coverage section says what the run did not do:
what was planned but absent, and what skipped and why.

A killed run is rendered as a killed run rather than as a pass with missing
rows.

The device's own log

--syslog starts a collector on the host, points every target's log at it, and
checks at both ends of the run that each device is still configured to send it.
The device setting is boot-time state rather than run configuration, so the
runner reports a device that is not configured rather than reconfiguring it
mid-run.

The report shows the device log as a slice around each failure, which is where
it earns its place: a suite that fails because the firmware asserted has the
assertion text and the task list sitting next to the failing check.

Firmware changes, and why they belong in the firmware

Five files under software/ change, and they are all one piece of work: making
the device's log usable as evidence. The harness cannot recover a log the
device never sent, so each of these is a change only the firmware can make.

network/syslog.{cc,h}

The boot log had nowhere to go. custom_outbyte was pointed at the syslog
sink only after InitFunction::executeAll() returned. The product version
banner, the FPGA capabilities line and every init function's output therefore
reached the hardware UART and nothing else. A test runner has no UART. The
buffer is now opened before that output starts and the destination is decided
afterwards, so those lines are held and then forwarded.

A device with no syslog server configured now allocates the 16 KB buffer during
init and frees it again at the end of init, where before it never allocated it.
That transient is the cost of capturing the boot log, and close_buffer is
what keeps the steady state unchanged. This matters most on the U2, whose heap
is the tightest.

A caller that is about to halt could not get its message out. flush()
sends whatever the forwarding task has not sent yet, from the calling task. It
sends blocks rather than lines because there is no time left to throttle, and
the collector splits a block back into lines. It refuses to run on the lwIP
thread, where a socket call would wait on the thread it is running on.

The buffer is now touched by two tasks, so the locking had to follow.
charout's bounds check and its store moved inside the safe section together
with the cursor, because close_buffer can free the buffer from another task
and a check made outside the section would be made against a pointer that can
be freed before the store lands. linestartpos became a member so that a flush
and the forwarding task rewind the buffer and that cursor together. The
forwarding loop now computes its span and checks it before calling memchr,
because a negative count passed as a size_t would read four billion bytes.

Two counters were added, for datagrams the stack refused and for times the
buffer filled before it drained. Neither can be reported through the log itself
without risking a loop, so both are read over REST.

The destructor also changes from delete buf to delete[] buf. The buffer is
allocated with new char[], so the previous form was undefined behaviour.

system/assert.c

vAssertCalled entered the critical section, then printed the assertion and
the task list, then spun forever. Inside that critical section the syslog task
never runs again, so the one message worth having never left the machine. It
now prints, flushes, and then enters the critical section.

The cost is real and is stated in the code: printing outside the critical
section lets another task interleave characters into the same output, and the
task list is a snapshot taken with the scheduler still running. A message that
arrives interleaved is still worth more than one that never arrives.

syslog_flush is declared weak because assert.c is linked into applications
that have no syslog at all, and a null pointer is the correct answer there.

application/ultimate/ultimate.cc

Defines the syslog_flush that assert.c calls, opens the log buffer before
the boot output starts, and closes it again when no destination turns out to be
configured.

api/routes.cc

/v1/info reports syslog_failed_sends and syslog_overflows. A device
logging to an address where nothing is listening is harmless to a run and
completely silent, so without these two numbers a lossy link and a quiet device
look identical from the host. The health sweep reads them, and the report shows
them.

Recording

--record is off by default: it costs the device two streams and the LAN their
bandwidth for the length of the run. When it is on, the recorder writes the
harness's screen beside the device's video, with the device's audio, at 10
frames a second and lossless by default because the material is 40-column text
that a lossy encode blurs. Each frame carries a burned-in timecode, and the
report tells a reader the exact timecode to seek to for a given check. One
chapter per suite run, and an SRT track naming the check.

ffmpeg with libx264rgb is the only new external dependency, and only for
this flag.

Three machines, one gate

A target is a host, or cartridge@computer for a cartridge under test in the
computer that supplies its C64 keyboard and video. The Ultimate II+L in a C64
Ultimate is written u2@c64u.

tests/lib/targets.py answers where every surface of a device is: REST, FTP,
Telnet, keyboard injection, video, audio and logs. tests/lib/machine.py
identifies the machine once from /v1/info and answers what it is and which
firmware fixes its line does not have yet. A check that cannot run on a machine
therefore skips with the reason rather than failing, and --assume-fix=NAME
runs it anyway, which is how a backport is confirmed.

Targets that do not share a physical machine run at the same time, each in its
own child process, with every output line naming the target it came from.
Targets that do share one take turns.

The suites

Every suite now reports through tests/lib/report.py, so harness lines and
suite lines follow one set of rules and the JSONL records have one shape. The
suites were also adapted to the C64 Ultimate, whose menu differs from the
Ultimate 64's: a launcher in front of the file browser, a different task menu
key, and browser letters that mean navigation rather than search.

Concurrent targets no longer collide over FTP ports. cfg-partial-effectuate
is a new manual suite, split out of the CFG coverage because it needs an
operator decision.

Command line

-j/--jsonl-dir becomes -o/--output-dir, with no alias. The directory holds
every artifact a run keeps, not only JSONL, and keeping the old name would have
described a third of what it does.

./run-tests --help is regrouped by what a reader is looking for rather than
by the order the options were added, and gained an examples section and an exit
status table. --color auto|always|never is one implementation shared by every
program here; auto includes GitHub Actions, which renders the escapes without
being a terminal.

CI

.github/workflows/build.yml gains one step: make observability_test. It
needs no device and no network beyond loopback, it takes under 30 seconds, and
it runs before the firmware builds so that a broken report generator is
reported now rather than after an hour of building.

.github/workflows/e2e.yml is new and is the hardware gate. It is a separate
workflow rather than a job in build.yml because it runs on different
hardware, takes 15 to 30 minutes, must not run twice concurrently against one
set of devices, and should be distinguishable from a red build at a glance. It
runs on a schedule rather than per push, because the devices are physical and
shared.

It will not run at all until a self-hosted runner carries the e2e label on
the device LAN. That is an operator decision about a machine rather than a
repository change, and until somebody makes it the workflow is valid and never
triggers. tests/e2e/doc/self-hosted-runner.md is what that person needs: what
the machine has to provide, how firmware under test gets onto the devices by
JTAG or through the device's own updater, and what a run leaves behind.

Verification

Device-free, and run by CI on every push:

• make observability_test: 124 cases against a loopback device double, green
  in under 30 seconds. It covers the record shapes, the report's byte-for-byte
  output against a fixture, reproducibility, the gap and coverage rules, and
  the failure paths of every collector.
• tests/lib/runner_policy_test.py: 64 checks on the health, recovery and
  retry policy.
• tests/lib/check_transport_usage.py: 62 files checked for suites growing
  their own transport code.

On hardware, with firmware built from this branch and deployed to both devices
under test:

./run-tests c64u u64 u2@c64u -o runs/ --syslog --record

Target	Suite runs	Result	Duration	Recording
c64u	23	all passed, exit 0	599s	6947 frames, 0 shed
u64	23	all passed, exit 0	999s	10454 frames, 0 shed
u2@c64u	23	all passed, exit 0	1397s	14655 frames, 0 shed

RESULT: OK targets=3 suites=69 ok=69 fail=0 warn=0 skip=0 recoveries=0 exit=0,
with 1699 checks recorded. frames_padded, frames_shed, frames_reordered,
packets_malformed and menu_failed are 0 on all three, and the video timing
was detected rather than assumed: ntsc on the Ultimate 64, pal on the C64
Ultimate and on the U2+L inside it.

The artifacts of that run were then checked against the run's own records,
using the recorder's arithmetic and the firmware character set rather than a
description of either:

• Twelve frames spread across the three recordings had their burned-in
  timecode rendered from glyphs.Canvas and compared pixel by pixel. All
  twelve match, so a screenshot of any frame seeks back to itself.
• All 1690 subtitle cues were matched back to the kind=check record they
  name, and each cue start was recomputed from capture.started,
  capture.lead_in and the check's own interval. The worst disagreement is
  1 ms, which is the rounding to the .srt millisecond field.
• Eighteen stills, six per target, were located in the video at the position
  their suite record puts them at. In every case zero pixels differ across the
  201376-pixel picture area; the only differences are in the borders the
  stamp, the pane labels and the progress bar are drawn into, which a still
  deliberately omits.
• Each file's duration agrees with the frame count in its kind=capture
  record at 10 frames a second, and its geometry matches what that record
  claims.
• The report renders byte-identical twice, is Markdown only, and 1076 of the
  1078 file paths it names exist. The two that do not are naming examples in
  its own "How to read this" section.

The observability layer was also audited against earlier recorded runs rather
than only through its own tests. The output directory's records, console logs,
screens, captures and device log were cross-checked against each other and
against the console. The video's duration, frame count, chapters and subtitles
were cross-checked against the check records. The burned-in timecode was
compared pixel for pixel against what the report tells a reader to seek to, and
every still was reproduced pixel for pixel by the video frame at its moment.

That audit found seven defects. Each is fixed here with a test that fails
against the previous behaviour:

1. The timecode burned into every frame was late by the length of the title
   card, so a screenshot did not seek back to itself.
2. A check that reported its own verdict was recorded twice, with the second
   record contradicting the first. A suite of 39 checks reported 43.
3. Three suites left no verdict in their own records, which is what a killed
   suite looks like to the report.
4. A failing menu suite showed only the C64 screen behind it, while the window
   that caused the failure was in the screen spool and nowhere in the report.
5. A non-empty syslog-unmapped.txt was left unexplained.
6. Three record kinds were written and documented nowhere.
7. The observability suite failed inside the gate, because it inherited the
   gate's E2E_SYSLOG_OWNED and its own scripted runs then started no
   collector. This one appears only when several targets are driven at once,
   which is the case the concurrent run exists to cover.

Recording health on hardware: frames_shed 0, frames_padded 0,
packets_dropped 0, packets_malformed 0, frames_reordered 0, an audio
track carrying signal rather than silence, and the video timing detected rather
than assumed (ntsc on the Ultimate 64, pal on the U2+L in its C64
Ultimate).

Turning the observability features on does not change a verdict: the monitor
suite on u64 reaches the same result with and without --record and
--syslog.

Known limitations

The E2E workflow has never run. It needs a self-hosted runner carrying the
e2e label on the device LAN. Everything the workflow calls was run by hand
for this branch.

A full sweep loses recorder frames to the suites. frames_lost across a
23-suite sweep was 6 on c64u, 4927 on u2@c64u and 14187 on u64, against 34610,
64767 and 55409 frames completed. Several suites take the video stream for
their own captures, and the recorder receives nothing while they hold it. The
capture record carries this as a re-arm count, so a reader can see that the run
competed for the stream. The file itself stays complete: every recording's
duration equals its frame count at 10 frames a second, with one chapter per
suite run.

Three findings in the report and the sidecar are known and not addressed
here. The ## Screens section labels each still with its kind but not with
its mm:ss offset into the recording, which OBS-3.23 asks for. The
runner-policy suite drives its policy fixtures through the same reporting
module, so their synthetic suite records land in the run's JSONL and a fully
green run shows six incomplete rows in the verdict table and six entries
under ## Failing checks. And about a fifth of the subtitle cues have zero
duration, because the check they name measured under a millisecond; they are
greppable, which is what the sidecar is for, but a player shows nothing for
them.

The C64 Ultimate stops answering after sustained driving, and only mains
power brings it back. This happened twice during this gate: once its UI task
blocked in a modal that RUN/STOP would not release while every listener still
answered, and once it stopped answering REST altogether. Both followed hours of
continuous driving, and machine:reboot returns 200 and clears neither. The
runner handles it correctly, abandoning the run rather than failing every
remaining suite for the same reason.

That machine also answers about ten times slower than the Ultimate 64. The
health sweep's machine:readmem of $D012 takes a median of 271, 274 and
276ms across three complete u2@c64u sweeps, against 26ms on the Ultimate 64.