diff --git a/.github/workflows/verify-split-files.yml b/.github/workflows/verify-split-files.yml index 85a3153..023e438 100644 --- a/.github/workflows/verify-split-files.yml +++ b/.github/workflows/verify-split-files.yml @@ -32,6 +32,7 @@ on: - "tests/java-memory.sh" - "tests/sudo-env.sh" - "tests/deb822-local-keyring.sh" + - "tests/ct-stop-facts.sh" - "tests/gpu-pci-class.sh" - "tests/nvidia-version-pin.sh" - "tests/external-installer.sh" @@ -93,6 +94,7 @@ on: - "tests/java-memory.sh" - "tests/sudo-env.sh" - "tests/deb822-local-keyring.sh" + - "tests/ct-stop-facts.sh" - "tests/gpu-pci-class.sh" - "tests/nvidia-version-pin.sh" - "tests/external-installer.sh" @@ -182,6 +184,9 @@ jobs: - name: deb822 local keyring tests run: bash tests/deb822-local-keyring.sh + - name: Container stop facts tests + run: bash tests/ct-stop-facts.sh + - name: GPU detection by PCI class tests run: bash tests/gpu-pci-class.sh diff --git a/pve/backend.func b/pve/backend.func index da4bd73..5e78caf 100644 --- a/pve/backend.func +++ b/pve/backend.func @@ -192,6 +192,27 @@ _pve_ct_stopped_by() { grep -oE 'UPID:[^"]+' | awk -F: '$6 ~ /^vz(stop|shutdown|reboot|destroy)$/ { print $6 " by " $8; exit }' } +# Why a container stopped by itself is in its own journal, which stops with it: +# what the host kernel logged about it, and where its shutdown began. +_pve_ct_stop_facts() { + local root="/var/lib/lxc/${CTID}/rootfs" log="" + journalctl -k --since "@${_CS_INSTALL_STARTED:-0}" -o cat --no-pager 2>/dev/null | + grep -E "lxc-${CTID}_<|/lxc/${CTID}/" | tail -n 5 | sed "s/^/${TAB}kernel: /" || true + pct mount "$CTID" >/dev/null 2>&1 || return 0 + if [[ -d "$root/var/log/journal" ]]; then + log="$(journalctl -D "$root/var/log/journal" -n 300 -o short-monotonic --no-hostname --no-pager -q 2>/dev/null)" || log="" + else + log="$(tail -n 300 "$root/var/log/syslog" 2>/dev/null || tail -n 300 "$root/var/log/messages" 2>/dev/null)" || log="" + fi + pct unmount "$CTID" >/dev/null 2>&1 || true + [[ -n "$log" ]] || return 0 + echo "${TAB}Container log where its shutdown began:" + awk '!s && /Received SIG|[Pp]owering (off|down)|Shutting down|Freezing|Caught <|emergency/ { s = NR } + { l[NR] = $0 } + END { f = s ? s - 3 : NR - 11; if (f < 1) f = 1; for (i = f; i <= NR && i < f + 12; i++) print l[i] }' <<<"$log" | + sed "s/^/${TAB} /" +} + # ------------------------------------------------------------------------------ # _pve_ct_gone_during_setup # @@ -214,6 +235,7 @@ _pve_ct_gone_during_setup() { fi msg_error "Container ${CTID} stopped by itself during its setup" journalctl -u "pve-container@${CTID}" -n 10 --no-pager -o cat 2>/dev/null | sed "s/^/${TAB}/" || true + _pve_ct_stop_facts export ERROR_CATEGORY_OVERRIDE="proxmox" _CS_SETUP_GONE_RC=199 } @@ -248,6 +270,7 @@ _pve_wait_for_detached_install() { echo "[INFO] The install did not fail: ${stopped_by} ended it" return 143 fi + _pve_ct_stop_facts return 199 fi pid="$(pct exec "$CTID" -- cat "${base}.pid" 2>/dev/null | tr -d '[:space:]')" @@ -1074,6 +1097,8 @@ EOF # ============================================================================ msg_info "Starting container" + # From here a stop counts as during the setup; unset, _pve_ct_stopped_by looked only from "now". + _CS_INSTALL_STARTED="$(date +%s)" # Checked, and with its own code. Unchecked, a failure here surfaced as pct's # generic 255 -- which the exit table reads as DPKG's fatal error, so 197 runs # across 70 apps in a fortnight were filed as a package manager problem when diff --git a/tests/ct-stop-facts.sh b/tests/ct-stop-facts.sh new file mode 100644 index 0000000..f5053fd --- /dev/null +++ b/tests/ct-stop-facts.sh @@ -0,0 +1,93 @@ +#!/usr/bin/env bash +# 55 runs in a week ended in "Container stopped by itself during its setup" +# with nothing but the host unit's start and stop in the log. +set -uo pipefail + +CORE_DIR="$(cd -- "$(dirname -- "${BASH_SOURCE[0]}")/.." && pwd)" +BACKEND="$CORE_DIR/pve/backend.func" +TEST_DIR="$(mktemp -d)" +trap 'rm -rf -- "$TEST_DIR"' EXIT +eval "$(awk '/^_pve_ct_stop_facts[(][)] [{]/,/^}/' "$BACKEND" | sed "s#/var/lib/lxc#$TEST_DIR/lxc#g")" +passed=0 failed=0 + +expect() { + if [[ "$2" == "$3" ]]; then + echo "PASS $1" + passed=$((passed + 1)) + else + echo "FAIL $1: expected <$2>, got <$3>" >&2 + failed=$((failed + 1)) + fi +} + +TAB=" " CTID=101 _CS_INSTALL_STARTED=1793658000 +ROOT="$TEST_DIR/lxc/101/rootfs" +MOUNT_OK=1 +pct() { + echo "$1" >>"$TEST_DIR/pct.calls" + [[ "$1" != mount ]] || ((MOUNT_OK)) +} +journalctl() { + case " $* " in + *" -k "*) cat "$TEST_DIR/kernel" ;; + *" -D $ROOT/var/log/journal "*) cat "$TEST_DIR/ctjournal" ;; + *) return 1 ;; + esac +} +reset() { + rm -rf "$TEST_DIR/lxc" "$TEST_DIR/pct.calls" + mkdir -p "$ROOT/var/log" + : >"$TEST_DIR/kernel" + : >"$TEST_DIR/ctjournal" +} + +reset +mkdir -p "$ROOT/var/log/journal" +for i in $(seq 1 20); do echo "[ 0.$i] systemd[1]: Started unit$i.service." >>"$TEST_DIR/ctjournal"; done +echo "[ 2.1] systemd[1]: Received SIGRTMIN+4 from PID 1 (systemd)." >>"$TEST_DIR/ctjournal" +for i in $(seq 1 20); do echo "[ 2.$((i + 1))] systemd[1]: Stopped unit$i.service." >>"$TEST_DIR/ctjournal"; done +printf '%s\n' \ + 'audit: type=1400 apparmor="DENIED" operation="mount" profile="lxc-101_" name="/run/"' \ + 'audit: type=1400 apparmor="DENIED" operation="mount" profile="lxc-1010_" name="/run/"' \ + 'oom-kill:constraint=CONSTRAINT_MEMCG,task_memcg=/lxc/101/ns/system.slice,task=node' \ + 'oom-kill:constraint=CONSTRAINT_MEMCG,task_memcg=/lxc/1010/ns/system.slice,task=java' >"$TEST_DIR/kernel" +out="$(_pve_ct_stop_facts)" +expect "kernel lines about this container only" 2 "$(grep -c '^ kernel: ' <<<"$out")" +expect "no kernel line about container 1010" 0 "$(grep -c '1010' <<<"$out" || true)" +expect "the log starts three entries before the shutdown signal" "Started unit18.service." \ + "$(grep -A1 'shutdown began' <<<"$out" | tail -n1 | awk '{print $(NF-1), $NF}')" +expect "the shutdown signal is shown" 1 "$(grep -c 'Received SIGRTMIN+4' <<<"$out")" +expect "twelve log lines at most" 12 "$(grep -c '^ \[' <<<"$out")" +expect "the rootfs is unmounted again" "mount unmount" "$(paste -sd' ' "$TEST_DIR/pct.calls")" + +reset +for i in $(seq 1 30); do echo "Nov 11 10:48:0$((i % 10)) ct kernel: line $i" >>"$ROOT/var/log/syslog"; done +out="$(_pve_ct_stop_facts)" +expect "without a journal, the tail of syslog" "line 30" "$(tail -n1 <<<"$out" | awk '{print $(NF-1), $NF}')" +expect "twelve syslog lines without a shutdown marker" 12 "$(grep -c 'kernel: line' <<<"$out")" + +reset +mkdir -p "$ROOT/var/log/journal" +echo "[ 0.1] systemd[1]: Started x.service." >"$TEST_DIR/ctjournal" +MOUNT_OK=0 +out="$(_pve_ct_stop_facts)" +expect "a rootfs that will not mount is left alone" "mount" "$(paste -sd' ' "$TEST_DIR/pct.calls")" +expect "and nothing is printed for it" "" "$out" +MOUNT_OK=1 + +reset +rc="$( + set -eEo pipefail + trap 'echo ERR' ERR + _pve_ct_stop_facts >/dev/null + echo "rc=$?" +)" +expect "an empty kernel log and no container log trip neither errexit nor the ERR trap" "rc=0" "$rc" + +expect "both stopped-by-itself paths collect the facts" 2 \ + "$(awk '/^(_pve_ct_gone_during_setup|_pve_wait_for_detached_install)[(][)] [{]/,/^}/' "$BACKEND" | grep -c '^ *_pve_ct_stop_facts$')" +expect "the setup clock starts with the container" 1 \ + "$(grep -A2 'msg_info "Starting container"' "$BACKEND" | grep -c '_CS_INSTALL_STARTED="$(date +%s)"')" + +printf '%s passed, %s failed\n' "$passed" "$failed" +((failed == 0))