Skip to content

os/v3/puppy: the boot's log capture waits for /data instead of testing it once - #1001

Merged
bong-water-water-bong merged 7 commits into
mainfrom
os/v3-c22-logs
Nov 4, 2026
Merged

bong-water-water-bong merged 7 commits into
mainfrom
os/v3-c22-logs

Conversation

@bong-water-water-bong

@bong-water-water-bong bong-water-water-bong commented Nov 4, 2026 •

Copy link
Copy Markdown
Collaborator

closes #1000

4 Nov, desktopgate on the frozen c20 image (e066f9eaaf0a…): of five boots that reached userspace, one kept a log
and four kept none
— /data/logs/<boot-id>/ absent, and nothing written to 1BIT-DATA at all (dumpe2fs: Mount count: 1, last mount ~3.7 min into the boot). Two one-shot tests are why, and each fails silently.

Root cause

  1. /etc/init.d/06onboard-logs ran ~7 s into the boot and return 0ed unless " /data " was already in
    /proc/mounts at that instant. Nothing re-ran it, so a boot whose partition mounts later logs nowhere for the
    rest of its life — and the only trace was a line on tty1 that nobody is looking at.
  2. 1bit-logs' dir() only asked "can I mkdir", and $DATA is a directory even when nothing is mounted on it
    (05onboard-data mkdir -ps it before mounting). So a boot with no mount wrote the "persisted" log onto the
    RAM-backed root and returned 0 — the same class, one layer down. That is also why the missing logs left no error
    anywhere.

A third defect fell out of gating it (below): the mount-point test compared $DATA literally, and /tmp is a
symlink to /initrd/mnt/tmpfs/tmp in this image
, so a mount reached through it was invisible to the test.

The change (5 files, +79/−13)

  • 1bit-logs: mounted() requires $DATA to be a mount point — resolved with readlink -f — and dir() refuses
    without it; daemon() waits for the mount (5 s poll, one line per state change) instead of exiting; snap on an
    unmounted $DATA is rc=1 and creates nothing (it used to return 0 after writing to the root fs).
  • 06onboard-logs: no one-shot test — the daemon is started unconditionally and the service says which state it
    started in (writing /data/logs/… vs /data is not mounted yet, 1bit-logs waits for it).
  • 1bit-desktop: logdir() falls back to /var/log/1bit-logs instead of returning an empty word (dir can now
    refuse), which would otherwise have turned "$d/xwin-console.log" into /xwin-console.log on the root.
  • container-build.sh: refuses a packed image carrying either old spelling (this boot's logs stay in RAM, or a
    1bit-logs with no mounted() line).
  • vm-check.sh: U3 boot logs now requires the mount point AND a live daemon AND BOOT with the cmdline; a new
    U3 logs wait row mounts a tmpfs over the daemon's target inside the guest — the same ordering as /data arriving
    late — and requires the log to appear without anything restarting the daemon. It prints mount-rc, mount-lines,
    daemon liveness and the daemon's own two lines, so this class is never diagnosed by guesswork again.

Reproducer, before and after, same command

~/wt/os3i/c22-logs-repro.sh <repo> <before|after> runs the real two files in an unprivileged mount namespace
(only the service's LOGS/PIDFILE/log-sink paths are substituted), reproducing one boot's ordering: the service
starts with nothing mounted, then the partition arrives.

BEFORE (origin/main)
  service: 06onboard-logs: no /data partition: this boot's logs stay in RAM
  A service-started=no before-mount-BOOT=0 after-mount-BOOT=0     <- the boot's log is lost even after the mount
  B snap-rc=0 files-created=4                                     <- "persisted" log written to the root fs, rc 0
  RESULT: FAIL

AFTER (this branch)
  service: 06onboard-logs: /data is not mounted yet, 1bit-logs waits for it (pid …)
  A service-started=yes before-mount-BOOT=0 after-mount-BOOT=1     <- BOOT appears after the late mount
  B snap-rc=1 files-created=1                                      <- refuses, creates nothing
  RESULT: PASS

Run twice per arm; same verdict both times.

Gates

  • sh -n / bash -n clean on every touched script; tools/copyright.py --check rc=0; no shellcheck warning on any
    of them (0 before, 0 after); the row table's embedded python compile()s.
  • vm-check.sh on an artifact carrying the fix — 51 PASS / 0 FAIL / 3 SKIP (/tmp/c22-vm3.log; the SKIPs are the
    two board rows and U7 ssh, which needs a private key). The artifact is the c21 image with only these three files
    re-packed into its puppy SFS (mksquashfs → mkimage.sh, sha256 91a4024919379d76b91790bffcd8946109152bd2c7d9251f74c5f7d82417530a) —
    a patched test image, not a cycle artifact; the next image from main carries it.
PASS U3 boot logs  data-is-mount | logs-daemon-running | /data/logs/20261104T130743-dd31d144/ | boot-logs-on-data
PASS U3 logs wait  logs-wait pre=0 post=1 mount-rc=0 mount-lines=1 daemon-alive=yes
                   | 1bit-logs: /tmp/logs-late is not mounted yet - waiting for it (nothing is persisted until then)
                   | 1bit-logs: /tmp/logs-late is mounted after waiting, this boot's logs go to … | logs-wait-for-data
  • The symlink finding, measured in the guest with a new diagnostic (~/wt/os3i/c22-guest-probe.sh: boots the
    shipped image under OVMF + Secure Boot, selects the serial-shell entry, drives commands): ls -ld /tmp →
    /tmp -> /initrd/mnt/tmpfs/tmp; after mount -t tmpfs none /tmp/logs-late, findmnt prints
    /initrd/mnt/tmpfs/tmp/logs-late none tmpfs rw,relatime,inode64 while a literal " /tmp/logs-late " match in
    /proc/mounts finds nothing. With the canonical-path fix the same boot logs
    … is mounted after waiting, this boot's logs go to /tmp/logs-late2/logs/<boot-id> and the BOOT file is there.
  • Shutdown ordering checked, not assumed: rc.shutdown stops /etc/init.d/* in reverse order
    (sort -r, rc.shutdown:80), so 06onboard-logs stop's final snap runs before 05onboard-data stop unmounts
    /data — the last 15 s are still captured.

Not in this PR / not claimed

  • No cycle-22 image (the artifact above is a test image). This is the fix and its gate; the next image carries it from
    main.
  • The u2-desktop-session / u5-modprobe rows that need a boot log are pi-release's files; this PR makes their input
    exist on every boot that mounts /data at all.
  • Nothing merged, no tag, no device ticket, no stick write, :18097 untouched.

bong-water-water-bong added 3 commits November 4, 2026 08:50
…g it once

4 Nov (TOS3-NOTE-c21-logs): of five boots that reached userspace, one kept a log and four kept none - on
the 1BIT-DATA partition and anywhere else. Two one-shot tests are why, and each fails silently:

- /etc/init.d/06onboard-logs ran 7 s into the boot and returned 0 unless " /data " was already in
  /proc/mounts at that instant. Nothing re-ran it (measured: /data mounted 3.7 min into a boot), so the
  rest of that boot logged nowhere.
- 1bit-logs' dir() only asked "can I mkdir", and $DATA is a directory even when the partition never
  mounted (05onboard-data mkdirs it first). So a boot with no mount wrote its "persisted" log to the
  RAM-backed root and reported success - the same class, one layer down.

Now: dir() requires $DATA to be a mount point (/proc/mounts), and the daemon waits for it (5 s poll, one
line per state change) instead of exiting, so a boot where /data ever mounts has its evidence. The
service starts the daemon unconditionally and says which state it started in.

`1bit-logs snap` on an unmounted $DATA is now rc=1 and creates nothing, where it used to return 0 after
writing to the root filesystem.

Gates: c22-logs-repro.sh reproduces the boot ordering from the two real files (before = origin/main,
after = this tree) in an unprivileged mount namespace: before = service gives up, no log after the late
mount, snap rc=0 with 4 files created on the root fs; after = daemon waits, BOOT appears after the mount,
snap rc=1 and nothing created. vm-check: `U3 boot logs` now requires the mount point AND a live daemon,
and a new `U3 logs wait` row mounts a tmpfs over the daemon's target inside the guest and requires the log
to appear. container-build.sh refuses a packed image carrying either old spelling.
… empty word

1bit-logs dir now refuses on an unmounted $DATA (the fix in the previous commit), and 1bit-desktop used
its output directly as a path: an empty word turns "$d/xwin-console.log" into "/xwin-console.log" on
the root filesystem. It falls back to /var/log/1bit-logs, which is what the function already did when the
tool was missing. Three arms measured with a stub: prints a dir -> that dir; exits 1 -> the fallback;
missing tool -> the fallback.
@github-actions

github-actions Bot commented Nov 4, 2026 •

Copy link
Copy Markdown

PR Reviewer Guide 🔍

(Review updated until commit d5360a9)

Here are some key observations to aid the review process:

🎫 Ticket compliance analysis 🔶

1000 - Partially compliant

Compliant requirements:

  • The boot's log capture waits for /data instead of testing it once
  • The 1bit-logs dir() function requires $DATA to be a mount point
  • The daemon waits for the mount instead of exiting
  • The service starts the daemon unconditionally
  • The snap command refuses to run on an unmounted $DATA
  • The build process refuses images carrying the old spelling

Non-compliant requirements:

  • None

Requires further human verification:

  • None
⏱️ Estimated effort to review: 3 🔵🔵🔵⚪⚪
🧪 PR contains tests
🔒 No security concerns identified
⚡ Recommended focus areas for review

Mount Point Check

The mounted() function uses readlink -f to canonicalize the path, which is good for handling symlinks like /tmp. However, if readlink -f fails or returns an empty string, the function will return 1, which could cause unexpected behavior. The function should handle potential errors from readlink -f more robustly to avoid false negatives in mount detection.

mounted() {
    real=$(readlink -f "$DATA" 2> /dev/null) || return 1
    [ -n "$real" ] || return 1
    grep -q " $real " /proc/mounts 2> /dev/null
}
Daemon Loop

The daemon loop in daemon() function uses a while loop with a sleep 5 to wait for the mount. While this approach works, it introduces a delay of up to 5 seconds before the logs start being written. If the mount happens very quickly, this could be inefficient. Consider using a more responsive mechanism if possible, such as monitoring for mount events.

daemon() {
    # rc.services runs this with `start` at boot, and the partition can mount AFTER that point (measured 4 Nov: /data
    # mounted 3.7 min into a boot, and a one-shot test is what lost that boot's log). So wait for it instead of
    # giving up: a boot where /data ever mounts has its evidence, and one where it never does is said once.
    waited=
    while ! d=$(dir); do
        [ -n "$waited" ] || { say "1bit-logs: $DATA is not mounted yet - waiting for it (nothing is persisted until then)"; waited=1; }
        sleep 5
    done
    [ -n "$waited" ] && say "1bit-logs: $DATA is mounted after waiting, this boot's logs go to $d"

@bong-water-water-bong bong-water-water-bong left a comment

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

VERDICT: READY — I reproduced both silent failures and the fix on this box, without a VM and without a mount.

Reviewed at 7fc902e84 (5 files, +69/-10).

The A/B, on this host. 1bit-logs takes ONEBIT_LOG_DATA, so the whole mechanism runs here. Same directory that
is not a mount point, main vs this head:

$ ONEBIT_LOG_DATA=/tmp/tprs-logs-X 1bit-logs dir          # at main:
/tmp/tprs-logs-X/logs/20261104T130323-4c8f0841            # rc 0, and 3 files created in the RAM directory
                                                          # -> the "persisted" log written to RAM, reported OK

$ ONEBIT_LOG_DATA=/tmp/tprs-logs-Y 1bit-logs dir          # at this head:
                                                          # rc 1, no output, 0 files created
$ ONEBIT_LOG_DATA=/tmp/tprs-logs-Y 1bit-logs snap
1bit-logs: nothing persists (/tmp/tprs-logs-Y is not a mounted partition)   # rc 1, 0 files
$ timeout 6 ONEBIT_LOG_DATA=/tmp/tprs-logs-Y 1bit-logs daemon
1bit-logs: /tmp/tprs-logs-Y is not mounted yet - waiting for it (nothing is persisted until then)
          # rc 124 = still waiting when I killed it, and 0 files written

So both halves are real: dir() no longer treats "can I mkdir" as "is it mounted", and daemon() waits instead of
exiting (and says the waiting line exactly once). The message also names the directory, which is what the c21 note had
to reconstruct from dumpe2fs mount counts.

The rest of the checks. bash -n clean on all five changed files; shellcheck -S warning silent on the three
runtime scripts (1bit-logs, 06onboard-logs, 1bit-desktop). No boot-hang risk from the new loop: 06onboard-logs
starts the daemon with &, so the wait never blocks rc.services. And I looked for the third caller of 1bit-logs dir
rather than trusting the two the PR fixes: 1bit-console-menu:572 already guards with
[ -n "$bootlogs" ] && [ -d "$bootlogs" ], so the empty-output class of bug that 1bit-desktop's logdir() had (/xwin-console.log)
does not exist anywhere else.

Two build/VM checks I could not run and am relying on the PR for: the container-build.sh refusals (they need an
unsquashfs of the packed SFS) and the new U3 logs wait vm-check row (it mounts a tmpfs in the guest — I did not mount
anything on this box, per the lane rules). The guest row is the right instrument for the "mount arrives late" half, and
the shape of it matches what I reproduced here: pre=0, then a mount, then a BOOT file appearing with the daemon still
alive.

One note, not a gate: the wait has no bound. A box that never mounts /data (the desktop image without a data
partition) now keeps a sleeper forever instead of exiting, which is a deliberate reading of "a boot where it never does
is said once" — but it does change the process's lifetime, and stop() is now the only thing that ends it. If that
matters, a cap (say 30 min, then the old one-line exit) keeps the diagnostic and the old semantics.

… symlink in this image

Measured in the guest (c22-guest-probe.sh): /tmp -> /initrd/mnt/tmpfs/tmp, so a tmpfs mounted at
/tmp/logs-late appears in /proc/mounts as /initrd/mnt/tmpfs/tmp/logs-late; findmnt showed the mount and
the literal " $DATA " compare found nothing, so the daemon waited with the partition mounted. The path
is resolved with readlink -f first now; the U3 logs wait row resolves it too when it reports mount-lines.
Guest proof on the rebuilt test image: the daemon says it waits, then writes
/tmp/logs-late2/logs/<bootid>/BOOT after the tmpfs lands.
@github-actions

github-actions Bot commented Nov 4, 2026

Copy link
Copy Markdown

Persistent review updated to latest commit 0718669

@bong-water-water-bong

Copy link
Copy Markdown
Collaborator Author

#1001 ready for review at 0718669 — the boot's log capture waits for /data instead of testing it once (closes #1000). Reproducer before/after in the body, and vm-check 51 PASS / 0 FAIL / 3 SKIP on an image carrying the fix. One finding worth the reviewer's attention: /tmp is a symlink to /initrd/mnt/tmpfs/tmp in this image, so the mount-point test resolves the path (readlink -f) — a literal compare called a mounted directory unmounted, measured in the guest.

@bong-water-water-bong bong-water-water-bong left a comment

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

VERDICT: READY

Re-verdicted at 0718669d5 (one new commit after the 13:03 verdict at 7fc902e84): mounted() now canonicalises the
data path, and the U3 logs wait guest row does the same for its $d.

The new commit fixes a real defect in the previous one. 1bit-logs compared $DATA literally against
/proc/mounts, but /proc/mounts records the mount point the kernel was given, so a tmpfs mounted at a path that
reaches through the /tmp symlink is recorded under the resolved path — the daemon would wait for ever on a directory
that is mounted. I reproduced both halves of that with a symlinked directory and a mount fixture (the same strings,
without touching /proc):

old mounted(): says NOT mounted   <- the defect, on a mounted directory
new mounted(): says mounted       <- the fix
/…/targetdir (no symlink):  old mounted, new mounted    (no regression)
/…/absent     (not mounted): old not mounted, new not mounted

So it is not just a fix for the case in the comment: it is the difference between "unmounted" and "mounted through a
symlink", and the fail-closed direction is preserved (readlink -f failing or empty -> return 1 -> still not
mounted). readlink -f already runs inside this image in vm-check.sh rows 542/629/632, so the tool is present in
the guest.

bash -n clean on both changed files, shellcheck silent on 1bit-logs (0 findings).

Not re-run by me: the two guest-only rows still need the VM (the U3 logs wait row mounts a tmpfs, and I mount
nothing on this box), and container-build.sh's refusal arms need the packed SFS. Everything from the 13:03 review
stands unchanged: at f17cc61 1bit-logs dir wrote 3 files into a non-mount and reported OK, and this head exits 1
with no output and no files; snap exits 1 naming the reason; daemon waits and writes nothing.

The unbounded-wait note still stands as a design question, not a gate: a box that never mounts /data keeps a
sleeper forever instead of exiting.

@bong-water-water-bong bong-water-water-bong added the tprs-ready TPRS: review verdict READY posted by the standing reviewer; merge gate satisfied label Nov 4, 2026
@github-actions

github-actions Bot commented Nov 4, 2026

Copy link
Copy Markdown

Persistent review updated to latest commit 7ca1776

@bong-water-water-bong bong-water-water-bong left a comment

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

VERDICT: READY at 9eef254a2 — merge-only update, own content byte-identical.

Checked with a hash of the PR's own diff at both heads rather than by eyeballing the file list: git diff <merge-base> <head> | sha256sum is the same at 0718669d5 and at 9eef254a2, so nothing of this PR's moved. The branch is MERGEABLE/BLOCKED; the whole delta is main advancing (#1007, #1002, and the console-TUI/prefix-cache work that landed with them).

Evidence from the review at 0718669d5 stands: mounted() canonicalises the data path — tested against a symlinked directory and a mount fixture (old: NOT mounted on a mounted dir; new: mounted), fail-closed on both.

CI at this head: red/pending: build, pr_agent, Analyze (rust) — pr_agent failures on engine PRs are superseded-run cancellations ("Canceling since a higher priority waiting request exists"), not findings.

@bong-water-water-bong
bong-water-water-bong merged commit 5eb2200 into main Nov 4, 2026
9 checks passed
@bong-water-water-bong
bong-water-water-bong deleted the os/v3-c22-logs branch November 4, 2026 18:12
bong-water-water-bong pushed a commit that referenced this pull request Nov 4, 2026
@github-actions

github-actions Bot commented Nov 4, 2026

Copy link
Copy Markdown

Persistent review updated to latest commit d5360a9

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

Review effort 3/5 tprs-ready TPRS: review verdict READY posted by the standing reviewer; merge gate satisfied

Projects

None yet

Development

Successfully merging this pull request may close these issues.

os/v3/puppy: the appliance keeps no boot log on most boots (/data mounts after 06onboard-logs' one-shot test)

1 participant