NAS-144436 / 28.0.0-BETA.1 / truenas-appliance-runner: skip GRUB's menu, and show where a boot's time goes

.github/actions/truenas-appliance-runner/action.yml

@@ -110,6 +110,11 @@ runs:
         ln -sf "$lib/appliance.sh" "$RUNNER_TEMP/truenas-appliance-bin/truenas-appliance"
         echo "$RUNNER_TEMP/truenas-appliance-bin" >> "$GITHUB_PATH"
         out="$("$lib/appliance.sh" start)"
+        # Folded: the boot as the appliance's console saw it, on the same
+        # clock as the milestones logged above.
+        echo "::group::The appliance's console during its boot (seconds since qemu started)"
+        cat "$APPLIANCE_DIR/console.ts.log" 2>/dev/null || echo "(no console)"
+        echo "::endgroup::"
         get() { sed -n "s/^$1=//p" <<<"$out"; }
         {
           echo "host=$(get TN_HOST)"

.github/actions/truenas-appliance-runner/appliance.sh

@@ -14,6 +14,11 @@
 #                                 disks, as <name>
 #   appliance.sh revert <name>    back to <name>, in seconds, no boot
 #   appliance.sh probe [baseline] change it, revert, check the change went
+#   appliance.sh boot-report     where the boot's time went: systemd's
+#                                 critical chain and slowest units, and
+#                                 middleware's start, over ssh. Leaves ssh
+#                                 on, with a key and sudo for the admin:
+#                                 revert afterwards if that matters
 #   appliance.sh call <method> [params...]
 #                                 a middleware API call, as the admin, its
 #                                 result as JSON on stdout
@@ -131,8 +136,9 @@ start() {
                  -device "virtio-blk-pci,drive=data$i,serial=data$i")
     done
 
-    local booted
+    local booted t0
     say "booting $disk as $name: ${memory} MB, $vcpus vCPUs, $ndata data disks of ${datagb}G"
+    t0=$(date +%s.%N)
     qemu-system-x86_64 -name "$name" -machine "q35,accel=$accel" -cpu "$cpu" -smp "$vcpus" -m "$memory" \
         -smbios "type=1,serial=$name" \
         -drive "if=pflash,format=raw,readonly=on,file=$OVMF_CODE" \
@@ -145,11 +151,16 @@ start() {
         -qmp "unix:$QMP,server=on,wait=off" \
         -display none -serial "file:$DIR/console.log" \
         -daemonize -pidfile "$DIR/qemu.pid"
+    # The console, each line with the seconds since qemu started, for as
+    # long as qemu runs: the boot's milestones below are on the same clock.
+    nohup "${TNCTL[@]}" tail-ts "$DIR/console.log" "$DIR/console.ts.log" \
+        --since "$t0" --pid "$(cat "$DIR/qemu.pid")" >/dev/null 2>&1 &
+    skip_grub "$DIR/console.log" "$QMP"
 
     if ! booted=$("${TNCTL[@]}" wait "$(url)" "$APPLIANCE_USER" "$APPLIANCE_TEMPLATE_PASSWORD" \
-            --timeout "${APPLIANCE_BOOT_TIMEOUT:-900}"); then
+            --since "$t0" --timeout "${APPLIANCE_BOOT_TIMEOUT:-900}"); then
         say "--- its console, last 60 lines"
-        tail -n 60 "$DIR/console.log" >&2 || true
+        console 60 >&2 || true
         die "the appliance's API never came up"
     fi
     say "API up ${booted}s after qemu started"
@@ -161,6 +172,7 @@ start() {
     {
         echo "APPLIANCE_PASSWORD_NOW=$(printf %q "$password")"
         echo "APPLIANCE_HTTP_PORT=$http"
+        echo "APPLIANCE_SSH_PORT=$sshp"
     } > "$STATE"
 
     local snapped=""
@@ -217,6 +229,82 @@ revert() {
     awk -v a="$t0" -v b="$(date +%s.%N)" 'BEGIN {printf "%.1f\n", b - a}'
 }
 
+# console [lines]: the end of its serial console, timed when it can be.
+console() {
+    if [ -s "$DIR/console.ts.log" ]; then
+        tail -n "${1:-100}" "$DIR/console.ts.log"
+    else
+        tail -n "${1:-100}" "$DIR/console.log"
+    fi
+}
+
+# boot_report: where the boot's time went, from inside: systemd's own
+# account of it, the chain of units middleware waited on, the slowest
+# units, and middleware's log of its own start. Over ssh, as the admin with
+# a key made here and sudo; those, and ssh, stay on afterwards.
+boot_report() {
+    running || die "no appliance running"
+    state
+    needs ssh openssh-client ssh-keygen openssh-client
+    local key="$DIR/report_key"
+    [ -f "$key" ] || ssh-keygen -q -t ed25519 -N '' -C appliance-boot-report -f "$key"
+    "${TNCTL[@]}" enable-ssh "$(url)" "$APPLIANCE_USER" "$APPLIANCE_PASSWORD_NOW" --pubkey "$(cat "$key.pub")" >&2
+    local port="${APPLIANCE_SSH_PORT:-2222}"
+    local -a ssh_
+    ssh_=(ssh -i "$key" -p "$port" -o BatchMode=yes -o ConnectTimeout=5
+          -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o LogLevel=ERROR
+          "$APPLIANCE_USER@127.0.0.1")
+    local i
+    for i in $(seq 1 30); do
+        "${ssh_[@]}" true 2>/dev/null && break
+        [ "$i" = 30 ] && die "no ssh into the appliance on 127.0.0.1:$port"
+        sleep 2
+    done
+    "${ssh_[@]}" 'bash -s' <<'REPORT'
+section() { printf '\n=== %s\n' "$*"; }
+cpu_seconds() {
+    awk -v hz="$(getconf CLK_TCK)" '/^cpu / {printf "user %.0f  system %.0f  idle %.0f  iowait %.0f  steal %.0f\n", ($2 + $3) / hz, $4 / hz, $5 / hz, $6 / hz, $9 / hz}' /proc/stat
+}
+section "systemd-analyze"
+systemd-analyze || true
+section "the critical chain to middlewared"
+systemd-analyze critical-chain middlewared.service --no-pager || true
+section "the critical chain to the default target"
+systemd-analyze critical-chain --no-pager || true
+section "the 30 slowest units"
+systemd-analyze blame --no-pager | head -n 30 || true
+section "middlewared's unit, from the journal"
+sudo -n journalctl -b -o short-monotonic -u middlewared --no-pager | head -n 40 || true
+section "middlewared's log of this boot's start"
+sudo -n awk '/ - Starting TrueNAS/ {n = 0; delete buf} {buf[++n] = $0} END {for (i = 1; i <= n && i <= 120; i++) print buf[i]}' /var/log/middlewared.log || true
+section "the journal's pauses over a second (kernel, initrd, userspace)"
+sudo -n journalctl -b -o short-monotonic --no-pager |
+    awk -F'[][]' 'NF > 2 {t = $2 + 0; if (seen && t - p >= 1) printf "%6.1fs before [%8.3f] %s\n", t - p, t, substr($3, 1, 150); p = t; seen = 1}' || true
+section "the kernel's own pauses over half a second"
+sudo -n dmesg |
+    awk -F'[][]' 'NF > 2 {t = $2 + 0; if (seen && t - p >= 0.5) printf "%6.1fs before [%8.3f] %s\n", t - p, t, substr($3, 1, 150); p = t; seen = 1}' || true
+section "the kernel's command line"
+cat /proc/cmdline
+section "where the guest's CPU time went since boot, in seconds"
+cpu_seconds
+section "the guest's clocksource"
+cat /sys/devices/system/clocksource/clocksource0/current_clocksource
+REPORT
+    echo
+    echo "=== the runner the appliance runs on"
+    echo "$(nproc) vCPUs, load $(cut -d' ' -f1-3 /proc/loadavg), $(free -m | awk '/^Mem:/ {print $2 " MB, " $7 " MB available"}')"
+    echo "Its CPU time since it booted, in seconds (steal is time its own host held its vCPUs back):"
+    cpu_seconds
+}
+
+# cpu_seconds: /proc/stat's CPU line in seconds. Steal is time the
+# hypervisor kept this machine's vCPUs from running; iowait is time spent
+# waiting for disks. Defined here and in the report's script on the
+# appliance alike.
+cpu_seconds() {
+    awk -v hz="$(getconf CLK_TCK)" '/^cpu / {printf "user %.0f  system %.0f  idle %.0f  iowait %.0f  steal %.0f\n", ($2 + $3) / hz, $4 / hz, $5 / hz, $6 / hz, $9 / hz}' /proc/stat
+}
+
 # probe <baseline>: that revert works and what it costs. A group is made
 # over the API, the appliance reverted to <baseline>, and the group must
 # be gone; KEY=value on stdout.
@@ -242,7 +330,8 @@ probe)     shift; probe "$@" ;;
 snapshot)  shift; snapshot "$@" ;;
 revert)    shift; revert "$@" ;;
 snapshots) running || die "no appliance running"; hmp info snapshots ;;
-console)   tail -n "${2:-100}" "$DIR/console.log" ;;
+console)   console "${2:-100}" ;;
+boot-report) boot_report ;;
 stop)      if running; then "${TNCTL[@]}" qmp "$QMP" quit >/dev/null || true; fi ;;
-*)         die "usage: appliance.sh start | snapshot <name> | revert <name> | probe [baseline] | call <method> [params...] | snapshots | console [lines] | stop" ;;
+*)         die "usage: appliance.sh start | snapshot <name> | revert <name> | probe [baseline] | call <method> [params...] | boot-report | snapshots | console [lines] | stop" ;;
 esac

.github/actions/truenas-appliance-runner/lib.sh

@@ -56,6 +56,22 @@ vars_qcow2() {
     qemu-img convert -q -f raw -O qcow2 "$OVMF_VARS" "$1"
 }
 
+# skip_grub <console log> <qmp socket>: TrueNAS's GRUB menu waits ten
+# seconds for a key on every boot, a sixth of the whole boot. This is the
+# key: Enter, through qemu's monitor, once the menu is on the console. In
+# the background, for up to a minute; the boot goes on regardless.
+skip_grub() {
+    (
+        for _ in $(seq 1 300); do
+            if grep -aq "Press enter to boot" "$1" 2>/dev/null; then
+                "${TNCTL[@]}" qmp "$2" send-key '{"keys": [{"type": "qcode", "data": "ret"}]}' >/dev/null 2>&1
+                exit 0
+            fi
+            sleep 0.2
+        done
+    ) >/dev/null 2>&1 &
+}
+
 # binds: where the appliance's forwarded ports listen. This machine's
 # loopback, and Docker's bridge when there is one, so that a container
 # reaches it as host.docker.internal; never the runner's network.

.github/actions/truenas-appliance-runner/test_tnctl.py

@@ -2,6 +2,8 @@
 test_tnctl.py. Standard library only, like tnctl."""
 
 import base64
+import contextlib
+import io
 import hashlib
 import json
 import os
@@ -10,6 +12,7 @@
 import sys
 import tempfile
 import threading
+import time
 import unittest
 from types import SimpleNamespace
 
@@ -122,11 +125,19 @@ def test_wait_until_ready(self):
             "auth.login_ex": lambda creds, notify: {"response_type": "SUCCESS" if creds["password"] == "pw" else "AUTH_ERR"},
             "system.ready": lambda notify: next(ready),
             # Bigger than one short frame length can say, and than two.
-            "system.info": lambda notify: {"blob": "x" * 70000},
+            "system.info": lambda notify: {"blob": "x" * 70000, "uptime_seconds": 12.5},
         })
         self.addCleanup(srv.close)
-        tnctl.cmd_wait(args(url=srv.url, user="truenas_admin", password="pw"))
-        self.assertEqual([m for m, _ in srv.calls], ["auth.login_ex", "system.ready", "system.ready", "system.ready"])
+        err = io.StringIO()
+        with contextlib.redirect_stderr(err):
+            tnctl.cmd_wait(args(url=srv.url, user="truenas_admin", password="pw", since=time.time()))
+        self.assertEqual([m for m, _ in srv.calls],
+                         ["auth.login_ex", "system.ready", "system.ready", "system.ready", "system.info"])
+        # Each milestone once, in the order they happen.
+        milestones = [line.split(" ", 2)[2] for line in err.getvalue().splitlines() if line.startswith("tnctl: +")]
+        self.assertEqual(milestones[:4], [f"port {srv.url.rsplit(':', 1)[1]} accepts connections",
+                                          "the API's websocket answers", "login accepted", "system.ready"])
+        self.assertIn("the guest's kernel started (it has been up 12.5s)", milestones[4])
         self.assertEqual(srv.paths, ["/api/current"])
         c = tnctl.login(srv.url, "truenas_admin", "pw")
         self.assertEqual(len(c.call("system.info")["blob"]), 70000)
@@ -191,5 +202,23 @@ def serve():
         self.assertEqual(e.exception.code, 1)
 
 
+class TestTailTs(unittest.TestCase):
+    def test_lines_are_timed_and_cleaned(self):
+        d = tempfile.mkdtemp()
+        src, out = os.path.join(d, "console.log"), os.path.join(d, "console.ts.log")
+        with open(src, "wb") as f:
+            f.write(b"\x1b[1;32m[  OK  ]\x1b[0m Started middlewared\r\n\r\nhalf")
+        # A pid that has exited: copy what is there, then stop.
+        dead = os.fork()
+        if dead == 0:
+            os._exit(0)
+        os.waitpid(dead, 0)
+        tnctl.cmd_tail_ts(args(file=src, out=out, since=time.time() - 5, pid=dead))
+        with open(out) as f:
+            lines = f.read().splitlines()
+        self.assertEqual([line.split(None, 1)[1] for line in lines], ["[  OK  ] Started middlewared", "half"])
+        self.assertTrue(all(4.5 < float(line.split()[0]) < 30 for line in lines), lines)
+
+
 if __name__ == "__main__":
     unittest.main()

.github/actions/truenas-appliance-runner/tnctl.py

@@ -14,11 +14,20 @@
       Once the installed system is up: create its admin. Only a system
       with no admin yet allows this, unauthenticated.
 
-  tnctl.py wait URL USER PASSWORD [--timeout S]
+  tnctl.py wait URL USER PASSWORD [--timeout S] [--since EPOCH]
       Until USER can log in and system.ready is true; prints the seconds.
+      With --since, a boot's: logs each milestone on the way in seconds
+      since EPOCH (qemu's start): the port accepting connections, the API's
+      websocket answering, the login accepted, system.ready, and when the
+      guest's kernel started (from its uptime).
+
+  tnctl.py tail-ts FILE OUT [--since EPOCH] [--pid PID]
+      Copy the lines FILE grows by into OUT, each prefixed with the seconds
+      since EPOCH, until PID exits: the serial console, timed.
 
   tnctl.py rotate URL USER PASSWORD NEW
-  tnctl.py enable-ssh URL USER PASSWORD
+  tnctl.py enable-ssh URL USER PASSWORD [--pubkey KEY]
+      ssh for USER with its password, or with KEY and sudo without one.
   tnctl.py call URL USER PASSWORD METHOD [JSON-PARAMS...]
       One call as USER, its result as JSON on stdout.
   tnctl.py wait-verify URL USER PASSWORD [--timeout S]
@@ -39,6 +48,7 @@
 import hashlib
 import json
 import os
+import re
 import socket
 import struct
 import sys
@@ -266,18 +276,90 @@
 
 def cmd_wait(a):
     start = time.monotonic()
-    c = retry("a login", a.timeout, lambda: login(a.url, a.user, a.password), every=2)
+    t0 = a.since
+    host, port = urllib.parse.urlsplit(a.url).hostname, urllib.parse.urlsplit(a.url).port or 80
+    seen = set()
+
+    def mark(what):
+        if t0 is not None and what not in seen:
+            seen.add(what)
+            log(f"+{time.time() - t0:.1f}s {what}")
+
+    def attempt():
+        with socket.create_connection((host, port), timeout=2):
+            pass
+        mark(f"port {port} accepts connections")
+        c = RPC(api(a.url), 30)
+        try:
+            mark("the API's websocket answers")
+            r = c.call("auth.login_ex", {"mechanism": "PASSWORD_PLAIN", "username": a.user, "password": a.password})
+            if (r or {}).get("response_type") != "SUCCESS":
+                raise RPCError("auth.login_ex", r)
+        except BaseException:
+            c.close()
+            raise
+        mark("login accepted")
+        return c
+
+    c = retry("a login", a.timeout, attempt, every=1)
+
     def ready():
         if not c.call("system.ready"):
             raise ValueError("not ready yet")
 
     try:
-        retry("system.ready", max(10, a.timeout - (time.monotonic() - start)), ready, every=2)
+        retry("system.ready", max(10, a.timeout - (time.monotonic() - start)), ready, every=1)
+        mark("system.ready")
+        if t0 is not None:
+            try:
+                uptime = float(c.call("system.info")["uptime_seconds"])
+                log(f"+{time.time() - t0 - uptime:.1f}s the guest's kernel started (it has been up {uptime:.1f}s)")
+            except (RPCError, KeyError, TypeError, ValueError) as e:
+                log("no uptime from system.info:", e)
     finally:
         c.close()
     print(f"{time.monotonic() - start:.1f}")
 
 
+ANSI = re.compile(rb"\x1b\[[0-9;?]*[ -/]*[@-~]|\x1b[()][A-Za-z0-9]|\r")
+
+
+def alive(pid):
+    try:
+        os.kill(pid, 0)
+    except ProcessLookupError:
+        return False
+    except PermissionError:
+        pass
+    return True
+
+
+def cmd_tail_ts(a):
+    t0 = a.since if a.since is not None else time.time()
+    while not os.path.exists(a.file):
+        if a.pid and not alive(a.pid):
+            return
+        time.sleep(0.2)
+    buf = b""
+    with open(a.file, "rb") as f, open(a.out, "ab", buffering=0) as out:
+        while True:
+            data = f.read(65536)
+            if not data:
+                if a.pid and not alive(a.pid):
+                    break
+                time.sleep(0.2)
+                continue
+            buf += data
+            *lines, buf = buf.split(b"\n")
+            stamp = f"{time.time() - t0:7.1f} ".encode()
+            for line in lines:
+                line = ANSI.sub(b"", line).rstrip()
+                if line:
+                    out.write(stamp + line + b"\n")
+        if buf.strip():
+            out.write(f"{time.time() - t0:7.1f} ".encode() + ANSI.sub(b"", buf).rstrip() + b"\n")
+
+
 def cmd_wait_verify(a):
     c = login(a.url, a.user, a.password)
     try:
@@ -303,7 +385,12 @@
     c = login(a.url, a.user, a.password)
     try:
         uid = c.call("user.query", [["username", "=", a.user]], {"get": True})["id"]
-        c.call("user.update", uid, {"ssh_password_enabled": True})
+        if a.pubkey:
+            # A key, and sudo without a password, for a script to log in
+            # with and read what only root can.
+            c.call("user.update", uid, {"sshpubkey": a.pubkey, "sudo_commands_nopasswd": ["ALL"]})
+        else:
+            c.call("user.update", uid, {"ssh_password_enabled": True})
         c.call("service.update", "ssh", {"enable": True})
         c.job("service.control", "START", "ssh", {"silent": False})
     finally:
@@ -377,10 +464,13 @@
 
     p("install", cmd_install, "url", timeout=3600).add_argument("--disk", default="")
     p("setup-admin", cmd_setup_admin, "url", "user", "password")
-    p("wait", cmd_wait, "url", "user", "password")
+    p("wait", cmd_wait, "url", "user", "password").add_argument("--since", type=float)
+    tail = p("tail-ts", cmd_tail_ts, "file", "out")
+    tail.add_argument("--since", type=float)
+    tail.add_argument("--pid", type=int)
     p("wait-verify", cmd_wait_verify, "url", "user", "password", timeout=300)
     p("rotate", cmd_rotate, "url", "user", "password", "new")
-    p("enable-ssh", cmd_enable_ssh, "url", "user", "password")
+    p("enable-ssh", cmd_enable_ssh, "url", "user", "password").add_argument("--pubkey", default="")
     p("call", cmd_call, "url", "user", "password", "method", timeout=120).add_argument("params", nargs="*")
     p("qmp", cmd_qmp, "socket", "command").add_argument("args", nargs="?")
     p("hmp", cmd_hmp, "socket", "line")