core: say why a container stopped by itself during its setup

.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
 

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

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_</var/lib/lxc>" name="/run/"' \
+  'audit: type=1400 apparmor="DENIED" operation="mount" profile="lxc-1010_</var/lib/lxc>" 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))