From b751b3379905ad22b7fd0d9134e1200453c2a9ad Mon Sep 17 00:00:00 2001 From: Elias Bakken Date: Fri, 18 Sep 2026 15:22:14 +0200 Subject: [PATCH] Retry a format that failed, instead of skipping it for ever (#168) A board sat unusable across five reboots and a fresh flash: storage FAILED, no images, mount refusing /dev/sda2 for a bad superblock, ssh-keygen-boot unable to restore host keys so sshd never started, and - with no readable options.cfg - the board on its own hotspot instead of the WiFi it was configured for. It read as a bad flash. It was a partition with no filesystem: correctly sized, and blank from its first byte. expand-usb asked whether the *partition* existed to decide whether there was anything to do, so the one thing that could fix the drive was the step being skipped. It now asks whether there is a filesystem - lsblk reports an empty FSTYPE, and lsblk is in the image - and formats a partition that has none without re-partitioning it. Why the format failed at all: on the first boot of a freshly written stick, ssh-keygen-boot started at 11:29:21 and failed at 11:29:22. mkfs on this stick takes ~31s by the measurement in the comment below, and that boot's log reached "Creating ext4 filesystem" - so mkfs was invoked and returned an error at once rather than being cut short. The device is fine: the same mkfs by hand afterwards succeeded in two seconds and brought the board straight back. That points at mke2fs opening the device O_EXCL while udev is still probing a partition that appeared a moment earlier - the same race as #145 and #147 - so there is a settle before the format now. It points, rather than proves, and that is the third fix here: mkfs wrote its reason to stderr, stderr went to the journal, and this rootfs is a ramdisk, so the explanation died with the reboot that followed. It goes to the reflash log now. set -e already stopped the script; nothing recorded why. The tests are static checks on the script text, like flash-cleanup.bats and for the same reason - this script hardcodes /dev/sda with no seams, and a real run needs root and losetup. All five defect tests fail against the old script. Co-Authored-By: Claude Opus 5 --- bin/prod/expand-usb | 42 ++++++++++++++++++-- test/bats/expand-usb.bats | 83 +++++++++++++++++++++++++++++++++++++++ 2 files changed, 122 insertions(+), 3 deletions(-) create mode 100644 test/bats/expand-usb.bats diff --git a/bin/prod/expand-usb b/bin/prod/expand-usb index a1b13f4..c60337a 100755 --- a/bin/prod/expand-usb +++ b/bin/prod/expand-usb @@ -9,11 +9,29 @@ info() { info "Running expand USB script" umount -q /mnt/usb/ || true -if [ -b /dev/sda2 ]; then - info "Partition 2 exists, exiting" +# "The partition exists" is not "the partition has a filesystem", and treating +# the two as the same is what made one bad boot permanent. A first boot that +# created sda2 and then failed to format it - the mkfs below can lose a race +# with udev, see the settle before it - left every later boot exiting here, so +# the drive stayed unformatted for good: the mount fails with a bad superblock, +# there is no options.cfg to read, ssh-keygen-boot cannot restore the host keys +# so sshd never starts, and the board comes up on its own hotspot with no +# storage. Seen on an A8 whose stick sat like that across five reboots. +# +# lsblk rather than blkid: both are in the image, and either would do, but lsblk +# is what the rest of this tree already reaches for. +if [ -b /dev/sda2 ] && [ -n "$(lsblk -no FSTYPE /dev/sda2 2>/dev/null)" ]; then + info "Partition 2 exists and holds a filesystem, exiting" exit 0 fi +if [ -b /dev/sda2 ]; then + # Nothing to create, everything still to format. Falling through rather + # than re-partitioning keeps this from throwing away a partition that is + # merely empty. + info "Partition 2 exists but has no filesystem - formatting it" +else + info "Creating partition on unused space" # fdisk's own in-place re-read of the table can fail with "Device or # resource busy" even though the write itself succeeded - a full @@ -41,6 +59,16 @@ if [ ! -b /dev/sda2 ]; then exit 1 fi +fi # end of "the partition had to be created" + +# mke2fs opens the device O_EXCL, and udev probes a partition the instant it +# appears - so the two race, and mke2fs loses by exiting immediately rather +# than waiting. That is how a stick ends up partitioned but unformatted, which +# used to be permanent (see the filesystem check at the top). Let udev finish +# with the new node before claiming it. +info "Waiting for udev to finish with the new partition" +udevadm settle --timeout=30 || true + info "Creating ext4 filesystem" # -J size=16 rather than the 128MB journal mke2fs picks by default for a # filesystem this size. That journal is the bulk of what mkfs writes here: @@ -63,7 +91,15 @@ info "Creating ext4 filesystem" # Note that lazy inode table init is already the default in mke2fs 1.47, so # the 1.9M inodes are not what costs time here - confirmed by the default and # lazy_itable_init=1 writing byte-for-byte the same 134MB. -mkfs.ext4 -F -E nodiscard -J size=16 /dev/sda2 +# Output into the log rather than onto stderr. set -e already stops the script +# when this fails, but the reason went to the journal - and this rootfs is a +# ramdisk, so the one explanation of why a board has no storage died with the +# reboot that followed. A whole investigation later, the answer was still +# unknown. Now it is in the same log as everything else. +if ! mkfs.ext4 -F -E nodiscard -J size=16 /dev/sda2 >> /var/log/reflash.log 2>&1; then + info "Could not create the filesystem on /dev/sda2 - see the mkfs output above" + exit 1 +fi # Via mount-unmount-usb, not a direct mount: that script holds the flock, and # this was the one caller bypassing it. Mounting here directly stacked a second diff --git a/test/bats/expand-usb.bats b/test/bats/expand-usb.bats new file mode 100644 index 0000000..3b13f3b --- /dev/null +++ b/test/bats/expand-usb.bats @@ -0,0 +1,83 @@ +#!/usr/bin/env bats + +load helper + +# expand-usb partitions and formats /dev/sda, hardcoded and with no env seams, +# so - as with flash-cleanup.bats - these are static checks on the script text +# rather than runs of it. Creating a real block device to run against needs +# root and losetup, which the suite does not have. This at least pins the +# defects that shipped. + +setup() { SCRIPT="$(cd "$(dirname "$BATS_TEST_FILENAME")/../../bin/prod" && pwd)/expand-usb"; } + +line_of() { grep -n "$1" "$SCRIPT" | head -1 | cut -d: -f1; } + +# The bug this suite exists for. A first boot created sda2, failed to format it, +# and every boot after that exited at the guard because the *partition* was +# there - so the drive stayed unformatted for good. The board then has no +# storage, no options.cfg, no ssh host keys, and sits on its own hotspot. +@test "expand-usb: the early exit requires a filesystem, not just a partition" { + local guard + guard=$(grep -n 'exists and holds a filesystem' "$SCRIPT" | head -1 | cut -d: -f1) + [ -n "$guard" ] + # The condition on that exit has to probe the filesystem, not only -b. + run sed -n "$((guard - 1))p" "$SCRIPT" + [[ "$output" == *"FSTYPE"* ]] +} + +# The other half: having found no filesystem, it has to go on and make one +# rather than falling out of the script. +@test "expand-usb: a partition with no filesystem is formatted, not skipped" { + local unformatted mkfs + unformatted=$(line_of 'has no filesystem') + mkfs=$(line_of 'mkfs.ext4 ') + [ -n "$unformatted" ] + [ -n "$mkfs" ] + [ "$unformatted" -lt "$mkfs" ] + # And partitioning has to be confined to the branch taken when the partition + # was absent, so the "exists but unformatted" path cannot re-create a + # partition that is already there. Checked by position rather than by reading + # the branch, because the else-branch text sits between the two markers above + # while never running on this path. + local else_line endif fdisk + else_line=$(grep -n '^else$' "$SCRIPT" | head -1 | cut -d: -f1) + endif=$(line_of 'end of "the partition had to be created"') + fdisk=$(line_of 'fdisk /dev/sda') + [ -n "$else_line" ] && [ -n "$endif" ] && [ -n "$fdisk" ] + [ "$else_line" -lt "$fdisk" ] + [ "$fdisk" -lt "$endif" ] + [ "$endif" -lt "$mkfs" ] +} + +# mke2fs opens the device O_EXCL and udev probes a partition the moment it +# appears; losing that race makes mkfs fail instantly, which is how the stick +# got into the state above. +@test "expand-usb: waits for udev to release the new partition before mkfs" { + local settle mkfs + settle=$(line_of 'udevadm settle') + mkfs=$(line_of 'mkfs.ext4 ') + [ -n "$settle" ] + [ -n "$mkfs" ] + [ "$settle" -lt "$mkfs" ] +} + +# The failure that started all this left no explanation anywhere: mkfs wrote to +# stderr, stderr went to the journal, and the journal is a ramdisk that the next +# reboot threw away. +@test "expand-usb: mkfs output is kept in the reflash log" { + run grep -c 'mkfs.ext4 .*>> */var/log/reflash.log' "$SCRIPT" + [ "$output" -ge 1 ] +} + +@test "expand-usb: a failed mkfs says so and stops" { + local fail + fail=$(line_of 'Could not create the filesystem') + [ -n "$fail" ] + run sed -n "$((fail + 1))p" "$SCRIPT" + [[ "$output" == *"exit 1"* ]] +} + +@test "expand-usb: is valid bash" { + run bash -n "$SCRIPT" + [ "$status" -eq 0 ] +}