From ae89636f560caa42ec5ca5f9c168fc85903a5974 Mon Sep 17 00:00:00 2001 From: navigator Date: Sat, 3 Oct 2026 03:59:01 +0000 Subject: [PATCH] fix: a first boot finishes without a journal and without a watcher Two stalls of the published core 19.0-6 booted headless (BR2, 2026-10-03; CI's boot-published-layer fails on them). 15regen-sslcert exited 1 before doing anything: under bash -e its log() called logger, which fails with "socket /dev/log: Connection refused" when journald is down (status=243/CREDENTIALS in the CI container, the host's AppArmor profile denying the ramfs mount systemd 257 makes for credentials), and the first info line killed the hook. Its logger may not fail it now, nor may 95secupdates', the one other hook that logs under -e; the other hooks and libs do not call logger, and run's own log() was tolerant already. The first boot stalled after [30turnkey-init-fence] running when nobody was attached to the container console: run's notice() drew a dialog infobox on tty1 for every hook, tty1 in LXC is a pty whose master only an attached console reads, and after about 30 KB the write blocked in n_tty_write for good. A console with no size (stty answers 0 0 on an unattended LXC tty; a VT or an attached console answers its rows and columns) gets no notice, and a notice the console does not take within NOTICE_TIMEOUT (2 s, timeout --foreground) is given up with the ones after it, so no boot can wedge on its console. Each is said once in the inithooks log and the journal. --- COVERAGE.md | 20 ++++++ debian/changelog | 26 ++++++++ firstboot.d/15regen-sslcert | 15 +++-- firstboot.d/95secupdates | 25 +++++--- run | 43 ++++++++++++- tests/test-firstboot-pty.bats | 8 ++- tests/test-regen-sslcert.bats | 116 ++++++++++++++++++++++++++++++++++ tests/test-run.bats | 63 +++++++++++++++++- tests/test-secupdates.bats | 35 ++++++++++ 9 files changed, 331 insertions(+), 20 deletions(-) create mode 100644 tests/test-regen-sslcert.bats diff --git a/COVERAGE.md b/COVERAGE.md index 6b6f867..600605b 100644 --- a/COVERAGE.md +++ b/COVERAGE.md @@ -4,6 +4,26 @@ Measured on 2026-09-24 against upstream master (33c43b8), following the project decision 0003 (90 percent floor per repository, 95 percent for every file our changes touch). +## Branch fix/first-boot-without-journal-or-console: shell 99.64 (2026-10-03) + +Two first boot stalls of the published core booted headless. +`firstboot.d/15regen-sslcert` is measured for the first time, 27/27, from +`tests/test-regen-sslcert.bats` (8 tests): the certificate made and the +trust store updated, a logger that fails (journald down) not stopping the +hook, the services that run restarted, a key still being written waited +for, one that never matches, no turnkey-make-ssl-cert (fatal, said with +logger failing too), keel-init, the conf file. `tests/test-secupdates.bats` +gains three tests with logger failing (SKIP recorded, FORCE installed, the +record that cannot be written); `firstboot.d/95secupdates` 71/72 as +before. `tests/test-run.bats` gains three: the terminal tests run on a +sized pty (`stty rows 24 cols 80` under `script`, as a VT or an attached +console is), a pty nobody is attached to (no size) gets no notice and the +log says so once, and a sized pty nobody reads (python `pty.openpty`, the +master never read, dialog a stub writing more than the pty holds) does not +hold the boot: the notice is given up after NOTICE_TIMEOUT and the hooks +run on. `run` itself sits outside the directories kcov measures, as +before. 322 bats in all, total 99.64. + ## Branch feat/first-boot-fqdn: shell 99.62, Python 99 (2026-10-02) The first boot asks the fully qualified domain name (31fqdn). Shell: diff --git a/debian/changelog b/debian/changelog index df1590b..a13c40e 100644 --- a/debian/changelog +++ b/debian/changelog @@ -1,3 +1,29 @@ +inithooks (2.3.6+keel21) trixie; urgency=medium + + * A first boot without a journal finishes. 15regen-sslcert ran under + bash -e and its log() called logger, which fails with "socket + /dev/log: Connection refused" when journald is down (the published + core 19.0-6 booted headless on BR2, 2026-10-03: journald dies with + status=243/CREDENTIALS where the host's AppArmor profile denies the + ramfs mount systemd 257 makes for credentials); its first info line + killed the hook before it made the certificate. The hook's logger + may not fail it now, nor may 95secupdates', the one other hook that + logs under -e; the rest log through run, which was tolerant already. + * A first boot nobody is watching finishes. run drew a notice box on + tty1 for every hook since keel17; in an LXC container tty1 is a pty + whose master only an attached console reads (pct console, + lxc-console), so with nobody attached the boxes filled the pty's + buffer and the write after 30turnkey-init-fence blocked for good + (attaching the console drained 30 KB and the boot finished in 20 s). + A console with no size (stty answers 0 0, as an unattended LXC tty + does; a VT or an attached console answers its rows and columns) gets + no notice, and a notice the console does not take within 2 s + (NOTICE_TIMEOUT) is given up with the ones after it, so no boot can + wedge on its console. Each is said once in the inithooks log and the + journal, so an operator can tell why the screen stayed still. + + -- Marcos Mendez Sat, 03 Oct 2026 12:00:00 +0000 + inithooks (2.3.6+keel20) trixie; urgency=medium * postinst no longer restarts the console's getty on an upgrade. When diff --git a/firstboot.d/15regen-sslcert b/firstboot.d/15regen-sslcert index 4f5df49..25d3cd8 100755 --- a/firstboot.d/15regen-sslcert +++ b/firstboot.d/15regen-sslcert @@ -8,10 +8,14 @@ _hook=$(basename "$0") +# The journal is a side effect of a hook whose job is the certificate: +# under -e a logger that fails (journald down, "socket /dev/log: Connection +# refused", the published core 19.0-6 booted headless on 2026-10-03) killed +# the hook at its first line, so it may not fail the hook. log() { local level=$1 shift - logger -t inithooks -p "$level" "[$_hook] $*" + logger -t inithooks -p "$level" "[$_hook] $*" 2>/dev/null || true } fatal() { log 3 "$*"; echo "FATAL: [$_hook] $*" 1>&2 ; exit 1 ; } @@ -35,11 +39,12 @@ SERVICES=(nginx apache2 lighttpd tomcat10 tomcat11 webmin) # make sure that generated keys are ready to use - avoids occasional race # condition where cert & key don't (yet) match. a single sleep should be plenty # but let's be sure +# modulus_md5 KIND FILE: the md5 of the modulus of the x509 or rsa FILE +modulus_md5() { openssl "$1" -noout -modulus -in "$2" | openssl md5; } + for _wait in {1..5}; do - cert_md5=$(openssl x509 -noout -modulus -in /etc/ssl/private/cert.pem \ - | openssl md5) - key_md5=$(openssl rsa -noout -modulus -in /etc/ssl/private/cert.key \ - | openssl md5) + cert_md5=$(modulus_md5 x509 /etc/ssl/private/cert.pem) + key_md5=$(modulus_md5 rsa /etc/ssl/private/cert.key) if [[ "$cert_md5" == "$key_md5" ]]; then info "SSL cert and key have been written - ready to restart services" break diff --git a/firstboot.d/95secupdates b/firstboot.d/95secupdates index 037cb2f..69c8b6f 100755 --- a/firstboot.d/95secupdates +++ b/firstboot.d/95secupdates @@ -27,10 +27,17 @@ SEC_UPDATES_LOG="${SEC_UPDATES_LOG:-/var/log/inithooks/secupdates.log}" # so the first boot installs security fixes and nothing else. SEC_UPDATES_SOURCES="${SEC_UPDATES_SOURCES:-/etc/apt/sources.list.d/security.sources}" +# journal ARGS: logger, which may not fail the hook under -e: journald can +# be down (15regen-sslcert died of it on 2026-10-03), and the hook's own +# log file and the record are what matter. +journal() { + logger -t inithooks "$@" 2>/dev/null || true +} + record() { if ! { mkdir -p "$(dirname "$SEC_UPDATES_RECORD")" \ && echo "$1" > "$SEC_UPDATES_RECORD"; } 2>/dev/null; then - logger -t inithooks -p warn \ + journal -p warn \ "[95secupdates] could not record $1 in $SEC_UPDATES_RECORD" fi } @@ -50,7 +57,7 @@ modules_and_boot() { # yet is not a broken one. Nothing is recorded, since nothing was installed. offline() { local msg="[95secupdates] $1; security updates not installed, run turnkey-install-security-updates once the network is up" - logger -t inithooks -p warn "$msg" + journal -p warn "$msg" echo "WARNING: $msg" >> "$LOGFILE" exit 0 } @@ -75,7 +82,7 @@ install_updates() { # succeed, install nothing and the boot would go on as if it had if [[ ! -f "$SEC_UPDATES_SOURCES" ]]; then msg="[95secupdates] no security source at $SEC_UPDATES_SOURCES" - logger -t inithooks -p err "$msg" + journal -p err "$msg" echo "ERROR: $msg" >> "$LOGFILE" exit 1 fi @@ -87,7 +94,7 @@ install_updates() { OLDMD5=$(modules_and_boot | md5sum) if [[ -n "$(dpkg --audit 2>/dev/null)" ]]; then msg="[95secupdates] dpkg in an inconsistent state (see $LOGFILE)" - logger -t inithooks -p warn "$msg" + journal -p warn "$msg" echo "WARNING: $msg" >> "$LOGFILE" dpkg --audit 2>&1 | tee -a "$LOGFILE" fi @@ -113,17 +120,17 @@ install_updates() { # SEC_UPDATES preseeded - unset SEC_UPDATES will run interactive (below) if [[ "$SEC_UPDATES" == "skip" ]]; then record skip - logger -t inithooks -p warn "[95secupdates] security updates skipped" + journal -p warn "[95secupdates] security updates skipped" exit 0 elif [[ "$SEC_UPDATES" == "force" ]]; then - logger -t inithooks "[95secupdates] security updates being installed" + journal "[95secupdates] security updates being installed" install_updates # only an install that succeeded is recorded: install_updates exits # before this on failure, and offline record force exit 0 elif [[ -n "$SEC_UPDATES" ]]; then - logger -t inithooks -p err "[95secupdates] invalid preseed value: $SEC_UPDATES" + journal -p err "[95secupdates] invalid preseed value: $SEC_UPDATES" exit 1 fi @@ -133,7 +140,7 @@ $INITHOOKS_PATH/bin/secupdates-ask.py || exit_code=$? if [[ $exit_code -eq 99 ]]; then # secupdates-ask.py returns 99 if user selects 'skip' record skip - logger -t inithooks -p warn "[95secupdates] security updates skipped" + journal -p warn "[95secupdates] security updates skipped" exit 0 elif [[ $exit_code -ne 0 ]]; then # any other non-zero return code signals an unknown error; the run script @@ -141,7 +148,7 @@ elif [[ $exit_code -ne 0 ]]; then exit "$exit_code" else # exit_code == 0 - logger -t inithooks "[95secupdates] security updates being installed" + journal "[95secupdates] security updates being installed" install_updates record force fi diff --git a/run b/run index 075fa8e..e2b5131 100755 --- a/run +++ b/run @@ -49,6 +49,11 @@ chmod 640 "$INITHOOKS_LOGFILE" FIRSTBOOT_TITLE="Keel Linux - First boot configuration" BOOT_WAITED= +# How long a notice may take to reach the console before the notices are +# given up for this run. +NOTICE_TIMEOUT="${NOTICE_TIMEOUT:-2}" +NOTICES_OFF= + # notice TEXT # Shows TEXT in a box on the terminal the hooks draw on, and goes on: the # screen of the hook before stays up otherwise, and it looks frozen while a @@ -56,10 +61,42 @@ BOOT_WAITED= # on "Did you save the password?" after ). Nothing is drawn when the # output is not a terminal or goes to the log (REDIRECT_OUTPUT), and a # notice that cannot be drawn is not an error. +# +# A notice may never hold the boot. In an LXC container tty1 is a pty whose +# master only an attached console (pct console, lxc-console) reads: with +# nobody attached, the published core booted headless on 2026-10-03 wrote +# one box per hook until the pty's buffer was full and the next write +# blocked for good, after 30turnkey-init-fence. Such a console has no size +# (stty answers 0 0; a VT or an attached console answers its rows and +# columns), so no notice is drawn on it; and a notice that does not reach +# the console within NOTICE_TIMEOUT is given up, with the ones after it. +# Each case is said once, in the log, so an operator can tell. notice() { - [[ -t 1 ]] && [[ "$REDIRECT_OUTPUT" != "true" ]] || return 0 - dialog --backtitle "$FIRSTBOOT_TITLE" --infobox "$1" 5 60 2>/dev/null \ - || true + [[ -z "$NOTICES_OFF" ]] || return 0 + if [[ ! -t 1 ]] || [[ "$REDIRECT_OUTPUT" == "true" ]]; then + notices_off "the output is not a terminal" + return 0 + fi + # the console on fd 3 while the substitution runs: inside it fd 1 is + # the pipe that captures the answer, not the console + local size + { size=$(stty size <&3 2>/dev/null || true); } 3<&1 + if [[ -z "$size" ]] || [[ "$size" == "0 0" ]]; then + notices_off "the console has no size, nobody is attached to it" + return 0 + fi + timeout --foreground "$NOTICE_TIMEOUT" dialog --backtitle "$FIRSTBOOT_TITLE" \ + --infobox "$1" 5 60 2>/dev/null + if [[ $? -eq 124 ]]; then + notices_off "the console did not take a notice in ${NOTICE_TIMEOUT} s, nobody is reading it" + fi + return 0 +} + +# notices_off REASON: no more notices this run, said once +notices_off() { + NOTICES_OFF=true + log info "first boot notices not drawn: $1" } wait_for_boot() { diff --git a/tests/test-firstboot-pty.bats b/tests/test-firstboot-pty.bats index 4c82b8c..eba746b 100644 --- a/tests/test-firstboot-pty.bats +++ b/tests/test-firstboot-pty.bats @@ -130,10 +130,14 @@ operator() { # first_boot WORD KEYS... # The run on a pty under script, answered by operator, within TIMEOUT; it -# fails when a screen never came or the run did not end in time. +# fails when a screen never came or the run did not end in time. The pty +# gets the size of a console somebody is attached to: script gives it none +# when its own input is a pipe, and run draws no notice on a console with +# no size, since that is an LXC tty nobody is attached to. first_boot() { set -o pipefail - operator "$@" | timeout "$TIMEOUT" script -qfec "$REPO/run" "$SCREEN" \ + operator "$@" | timeout "$TIMEOUT" script -qfec \ + "stty rows $LINES cols $COLUMNS; $REPO/run" "$SCREEN" \ > /dev/null 2>&1 } diff --git a/tests/test-regen-sslcert.bats b/tests/test-regen-sslcert.bats new file mode 100644 index 0000000..c243995 --- /dev/null +++ b/tests/test-regen-sslcert.bats @@ -0,0 +1,116 @@ +#!/usr/bin/env bats +# Tests for firstboot.d/15regen-sslcert: the self-signed certificate made +# at first boot, and the services restarted for it. +# +# The published core 19.0-6 booted headless on BR2 (2026-10-03) left the +# hook at exit 1 before it did anything: under `bash -e` its log() called +# logger, which failed with "socket /dev/log: Connection refused" because +# journald was down, and the first info line killed the hook. The journal +# is a side effect of a hook whose job is the certificate, so a logger that +# fails may not stop it. +# +# turnkey-make-ssl-cert, openssl, systemctl, update-ca-certificates, sleep +# and logger are stubs; `which` is the real one, finding the stubs on PATH. + +bats_require_minimum_version 1.5.0 + +load helpers + +REPO=$BATS_TEST_DIRNAME/.. + +setup() { + setup_stubs + stub logger + stub turnkey-make-ssl-cert + # the certificate and the key agree from the first look, unless a test + # makes the first OPENSSL_DIFFER answers differ + stub openssl 'n=$(wc -l < "'"$STUBS"'/openssl.calls") +if (( n <= ${OPENSSL_DIFFER:-0} )); then echo "md5 $n"; else echo "md5 same"; fi' + stub systemctl 'if [[ "$1" == is-active ]]; then + [[ " ${RUNNING-} " == *" $3 "* ]] +fi' + stub update-ca-certificates + stub sleep + export INITHOOKS_CONF=$BATS_TEST_TMPDIR/inithooks.conf + unset _TURNKEY_INIT RUNNING OPENSSL_DIFFER +} + +@test "the certificate is made and the trust store updated" { + run "$REPO/firstboot.d/15regen-sslcert" + + [ "$status" -eq 0 ] + [ "$(calls turnkey-make-ssl-cert)" = "--default --force" ] + [ -e "$STUBS/update-ca-certificates.calls" ] + [[ "$output" == *"Generating SSL/TLS cert & key"* ]] +} + +@test "a logger that fails does not stop the hook" { + # journald down: logger exits 1 with "socket /dev/log: Connection + # refused", under bash -e + stub logger 'echo "logger: socket /dev/log: Connection refused" >&2; exit 1' + + run --separate-stderr "$REPO/firstboot.d/15regen-sslcert" + + [ "$status" -eq 0 ] + [ "$(calls turnkey-make-ssl-cert)" = "--default --force" ] + [ -e "$STUBS/update-ca-certificates.calls" ] + [[ "$output" == *"Restarting relevant services"* ]] + [[ "$stderr" != *"Connection refused"* ]] +} + +@test "the services that run are restarted, the others left alone" { + export RUNNING="apache2.service webmin.service" + + run "$REPO/firstboot.d/15regen-sslcert" + + [ "$status" -eq 0 ] + [ "$(grep '^restart' "$STUBS/systemctl.calls")" = "$(printf 'restart --quiet apache2\nrestart --quiet webmin')" ] +} + +@test "a key still being written is waited for" { + export OPENSSL_DIFFER=2 + + run "$REPO/firstboot.d/15regen-sslcert" + + [ "$status" -eq 0 ] + [[ "$output" == *"Waiting for updated ssl cert & key"* ]] + [[ "$output" == *"ready to restart services"* ]] + [ "$(calls sleep | wc -l)" -eq 1 ] +} + +@test "a key that never matches is reported after five looks" { + export OPENSSL_DIFFER=100 + + run "$REPO/firstboot.d/15regen-sslcert" + + [ "$status" -eq 0 ] + [ "$(calls sleep | wc -l)" -eq 5 ] + [[ "$output" == *"..."* ]] +} + +@test "without turnkey-make-ssl-cert the hook fails and says so, logger or not" { + rm "$STUBS/turnkey-make-ssl-cert" + stub logger 'exit 1' + + run --separate-stderr "$REPO/firstboot.d/15regen-sslcert" + + [ "$status" -eq 1 ] + [[ "$stderr" == *"FATAL"*"turnkey-make-ssl-cert executable not found"* ]] +} + +@test "keel-init does not make a new certificate" { + export _TURNKEY_INIT=1 + + run "$REPO/firstboot.d/15regen-sslcert" + + [ "$status" -eq 0 ] + [ -z "$(calls turnkey-make-ssl-cert)" ] +} + +@test "the conf file is read when it is there" { + echo "export SOMETHING=1" > "$INITHOOKS_CONF" + + run "$REPO/firstboot.d/15regen-sslcert" + + [ "$status" -eq 0 ] +} diff --git a/tests/test-run.bats b/tests/test-run.bats index 66e2aa9..02a261f 100644 --- a/tests/test-run.bats +++ b/tests/test-run.bats @@ -305,12 +305,38 @@ if (( n <= 2 )); then echo starting; else echo running; fi" # run_on_terminal # The runner with a terminal for its standard output, the way -# inithooks.service gives it tty1. +# inithooks.service gives it tty1: a sized one, as a VT or an attached +# console is. script gives the pty no size when its own input is none. run_on_terminal() { + INITHOOKS_DEFAULT=$DEFAULT run script -qec \ + "stty rows 24 cols 80; $BATS_TEST_DIRNAME/../run" /dev/null < /dev/null +} + +# run_on_unattended_terminal +# The runner on a terminal nobody is attached to: a pty with no size, as +# tty1 of an LXC container is until pct console or lxc-console attaches. +run_on_unattended_terminal() { INITHOOKS_DEFAULT=$DEFAULT run script -qec "$BATS_TEST_DIRNAME/../run" \ /dev/null < /dev/null } +# run_on_unread_terminal +# The runner on a sized terminal whose master nobody reads: what is written +# fills the pty's buffer and the next write blocks, which is what held the +# published core's first boot for good on 2026-10-03. The notices have one +# second to reach it. +run_on_unread_terminal() { + INITHOOKS_DEFAULT=$DEFAULT NOTICE_TIMEOUT=1 \ + run timeout 60 python3 - "$BATS_TEST_DIRNAME/../run" <<'PY' +import fcntl, os, pty, struct, subprocess, sys, termios +master, slave = pty.openpty() +fcntl.ioctl(slave, termios.TIOCSWINSZ, struct.pack("HHHH", 24, 80, 0, 0)) +proc = subprocess.run([sys.argv[1]], stdin=subprocess.DEVNULL, stdout=slave, + stderr=sys.stderr) +sys.exit(proc.returncode) +PY +} + @test "each first boot hook is named on the terminal while it runs" { stub dialog probe 15regen-sslcert @@ -348,6 +374,41 @@ run_on_terminal() { [ "$status" -eq 0 ] [ -z "$(calls dialog)" ] + grep -q "first boot notices not drawn: the output is not a terminal" \ + "$ROOT/inithooks.log" +} + +@test "nothing is drawn on a console nobody is attached to, and the log says so" { + stub dialog + probe 15first + probe 30second + + run_on_unattended_terminal + + [ "$status" -eq 0 ] + [ "$(wc -l < "$SEEN")" -eq 2 ] + [ -z "$(calls dialog)" ] + [ "$(grep -c "first boot notices not drawn" "$ROOT/inithooks.log")" -eq 1 ] + grep -q "notices not drawn: the console has no size" "$ROOT/inithooks.log" + grep -q "notices not drawn: the console has no size" "$STUBS/logger.calls" +} + +@test "a console that does not take a notice does not hold the boot" { + # dialog here writes more than the pty holds, so its write blocks the + # way the real one did; the runner gives it NOTICE_TIMEOUT and goes on + # without notices + stub dialog 'printf "%0131072d" 0' + probe 15first + probe 30second + probe 31third + + run_on_unread_terminal + + [ "$status" -eq 0 ] + [ "$(wc -l < "$SEEN")" -eq 3 ] + [ "$(calls dialog | wc -l)" -eq 1 ] + grep -q "notices not drawn: the console did not take a notice in 1 s" \ + "$ROOT/inithooks.log" } @test "a run whose output goes to the log draws nothing either" { diff --git a/tests/test-secupdates.bats b/tests/test-secupdates.bats index fd86318..d846a60 100644 --- a/tests/test-secupdates.bats +++ b/tests/test-secupdates.bats @@ -281,3 +281,38 @@ esac' [ "$(cat "$SEC_UPDATES_RECORD")" = "force" ] [[ "$(calls apt-get)" == *dist-upgrade* ]] } + +# journald down: logger exits 1 under bash -e (15regen-sslcert died of it +# on the published core booted headless, 2026-10-03) +@test "a preseeded SKIP is recorded when logger fails" { + stub logger 'echo "logger: socket /dev/log: Connection refused" >&2; exit 1' + echo "export SEC_UPDATES=SKIP" > "$INITHOOKS_CONF" + + run --separate-stderr "$REPO/firstboot.d/95secupdates" + + [ "$status" -eq 0 ] + [ "$(cat "$SEC_UPDATES_RECORD")" = "skip" ] + [[ "$stderr" != *"Connection refused"* ]] +} + +@test "a preseeded FORCE installs the updates when logger fails" { + stub logger 'exit 1' + echo "export SEC_UPDATES=FORCE" > "$INITHOOKS_CONF" + + run "$REPO/firstboot.d/95secupdates" + + [ "$status" -eq 0 ] + [ "$(cat "$SEC_UPDATES_RECORD")" = "force" ] + [[ "$(calls apt-get)" == *dist-upgrade* ]] +} + +@test "a record that cannot be written is still said when logger fails" { + stub logger 'exit 1' + export SEC_UPDATES_RECORD=$BATS_TEST_TMPDIR/file/sec-updates + touch "$BATS_TEST_TMPDIR/file" + echo "export SEC_UPDATES=SKIP" > "$INITHOOKS_CONF" + + run "$REPO/firstboot.d/95secupdates" + + [ "$status" -eq 0 ] +}