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 ] +}