The release's report times the first SSH login; QEMU's hardening asserted

boot/report.go

@@ -34,10 +34,17 @@ type Report struct {
 	Only string `json:"only,omitempty"`
 	// Login is how a login prompt was reached: "echo" when the getty was replaced by one, so
 	// agetty's unconditional second is not in the usable column; "agetty" when it was not.
-	Login    string    `json:"login"`
-	Specs    []Row     `json:"specs"`
-	Variants []Row     `json:"variants"`
-	Skipped  []Skipped `json:"skipped,omitempty"`
+	Login string `json:"login"`
+	// FirstLogin is the goal's number: the release as built, logged into over SSH through its
+	// vsock from the moment before QEMU is exec'd, in phases "accepts" (sshd takes a
+	// connection) and "login" (`true` has run as spin). The rows below time the serial
+	// console's prompt, which nothing a workspace does waits for: a change can move the two
+	// in opposite directions, as v20261113.03 did. Absent from a report made without sudo or
+	// /dev/vhost-vsock, and from releases before it was added.
+	FirstLogin *Boot     `json:"first_login,omitempty"`
+	Specs      []Row     `json:"specs"`
+	Variants   []Row     `json:"variants"`
+	Skipped    []Skipped `json:"skipped,omitempty"`
 }
 
 // Host is what the boot times were measured on.
@@ -101,16 +108,23 @@ func Summarise(runs []Run, failure string) Boot {
 				ds = append(ds, d)
 			}
 		}
-		p50, ok := Percentile(ds, 0.5)
-		if !ok {
-			continue
+		if s, ok := SummaryOf(ds); ok {
+			b.Phases[p.String()] = s
 		}
-		p95, _ := Percentile(ds, 0.95)
-		b.Phases[p.String()] = Summary{P50: ms(p50), P95: ms(p95), N: len(ds)}
 	}
 	return b
 }
 
+// SummaryOf is the p50 and p95 of ds, and false when ds is empty.
+func SummaryOf(ds []time.Duration) (Summary, bool) {
+	p50, ok := Percentile(ds, 0.5)
+	if !ok {
+		return Summary{}, false
+	}
+	p95, _ := Percentile(ds, 0.95)
+	return Summary{P50: ms(p50), P95: ms(p95), N: len(ds)}, true
+}
+
 func ms(d time.Duration) float64 { return math.Round(float64(d.Microseconds())/10) / 100 }
 
 // Diff writes, as Markdown, what changed from old to new: every row whose command line,
@@ -136,11 +150,51 @@ func Diff(w io.Writer, old, new Report, threshold float64) {
 			fmt.Fprintf(w, "- `%s` changed: `%s` → `%s`\n", k, short(a), short(b))
 		}
 	}
+	firstLogin(w, old.FirstLogin, new.FirstLogin)
 	partial := new.Only != ""
 	section(w, "Feature matrix", old.Specs, new.Specs, threshold, partial)
 	section(w, "Image variants", old.Variants, new.Variants, threshold, partial)
 }
 
+// firstLogin writes the goal's number first and always, moved or not: it is the one a change is
+// decided on, and the sections after it time the console's prompt.
+func firstLogin(w io.Writer, old, new *Boot) {
+	if old == nil && new == nil {
+		return
+	}
+	fmt.Fprintf(w, "\n### First SSH login\n\n")
+	fmt.Fprintln(w, "| phase | p50 / p95 (ms) | p50 |")
+	fmt.Fprintln(w, "|---|---|---|")
+	for _, p := range []string{"accepts", "login"} {
+		a, aok := phase(old, p)
+		b, bok := phase(new, p)
+		move := "-"
+		if aok && bok && a.P50 > 0 {
+			move = fmt.Sprintf("%+.1f%%", 100*(b.P50-a.P50)/a.P50)
+		}
+		fmt.Fprintf(w, "| %s | %s → %s | %s |\n", p, summary(a, aok), summary(b, bok), move)
+	}
+	if new != nil && new.Failed > 0 {
+		fmt.Fprintf(w, "\n%d of %d boots had no login: %s\n", new.Failed, new.Boots, new.Error)
+	}
+	fmt.Fprintln(w, "\nThe sections below time the serial console's prompt, which no workspace waits for.")
+}
+
+func phase(b *Boot, p string) (Summary, bool) {
+	if b == nil {
+		return Summary{}, false
+	}
+	s, ok := b.Phases[p]
+	return s, ok
+}
+
+func summary(s Summary, ok bool) string {
+	if !ok {
+		return "-"
+	}
+	return fmt.Sprintf("%.1f / %.1f", s.P50, s.P95)
+}
+
 func section(w io.Writer, title string, old, new []Row, threshold float64, partial bool) {
 	before := map[string]Row{}
 	for _, r := range old {
@@ -303,10 +357,7 @@ func outcome(r Row) string {
 
 func usable(r Row) string {
 	s, ok := r.Boot.Phases["usable"]
-	if !ok {
-		return "-"
-	}
-	return fmt.Sprintf("%.1f / %.1f", s.P50, s.P95)
+	return summary(s, ok)
 }
 
 func name(r Report) string {

boot/report_test.go

@@ -12,6 +12,7 @@ import (
 	"runtime"
 	"strings"
 	"testing"
+	"time"
 
 	"github.com/spin-stack/spin-machine/boot"
 )
@@ -75,7 +76,8 @@ func combinations() [][]choice {
 //
 // Needs /dev/kvm and a built release tree (SPIN_MACHINE_OUTPUT, or _output). The vsock rows
 // need /dev/vhost-vsock; without it those rows are listed as skipped rather than reported as
-// failing. With sudo and /dev/nbd0 the getty is
+// failing. With sudo, /dev/nbd0 and /dev/vhost-vsock the release as built is also logged into
+// over SSH, the goal's number (Report.FirstLogin). With sudo and /dev/nbd0 the getty is
 // replaced by an echo, and every variant of the image runs; without them
 // the usable column carries agetty's second and the variants that edit the image are skipped.
 func TestReport(t *testing.T) {
@@ -161,6 +163,16 @@ func TestReport(t *testing.T) {
 		r.Specs = append(r.Specs, row)
 	}
 
+	switch {
+	case !only.MatchString("first login"):
+	case !sudo:
+		r.Skipped = append(r.Skipped, boot.Skipped{ID: "first login", Why: "writes a key into the overlay, which needs sudo and /dev/nbd0"})
+	case missing["vsock=on"] != "":
+		r.Skipped = append(r.Skipped, boot.Skipped{ID: "first login", Why: missing["vsock=on"]})
+	default:
+		r.FirstLogin = measureFirstLogin(t, out, reps, flags)
+	}
+
 	vs := variants
 	if k := kernelB(t); k != "" {
 		vs = append(vs[:len(vs):len(vs)], variant{label: "kernel B", cpus: "2", memory: "2048",
@@ -205,6 +217,36 @@ func measure(t *testing.T, out string, v variant, reps int) boot.Boot {
 	return b
 }
 
+// measureFirstLogin boots the release as built reps times and logs into each over SSH through
+// its vsock, as boot:ssh-first does: the goal's number, in the report beside the console's.
+func measureFirstLogin(t *testing.T, out string, reps int, flags []string) *boot.Boot {
+	t.Helper()
+	row, signer := sshRow(t)
+	v := row("first login", "")
+	v.flags = flags
+	b := &boot.Boot{Boots: reps, Phases: map[string]boot.Summary{}}
+	var accepts, logins []time.Duration
+	for range reps {
+		r := firstSSH(t, out, v, signer)
+		if r.listen == 0 || r.login == 0 {
+			b.Failed++
+			if b.Error == "" {
+				b.Error = r.why
+			}
+			continue
+		}
+		accepts, logins = append(accepts, r.listen), append(logins, r.login)
+	}
+	if s, ok := boot.SummaryOf(accepts); ok {
+		b.Phases["accepts"] = s
+	}
+	if s, ok := boot.SummaryOf(logins); ok {
+		b.Phases["login"] = s
+	}
+	t.Logf("first login: %d/%d boots logged in", b.Boots-b.Failed, b.Boots)
+	return b
+}
+
 // static runs a spin-machine command that builds the machine without starting it, over the
 // fixed file names a report records, and returns its output lines with the release
 // directory written as $RELEASE.

boot/report_unit_test.go

@@ -150,3 +150,61 @@ func TestDiff(t *testing.T) {
 		t.Errorf("a row a partial run did not ask about is reported gone, or one under the threshold is listed:\n%s", got)
 	}
 }
+
+// The goal's number comes before the console's sections, moved or not, and reads "-" on the
+// side of a release from before it was measured.
+func TestDiffFirstLogin(t *testing.T) {
+	login := func(accepts, login float64) *Boot {
+		return &Boot{Boots: 20, Phases: map[string]Summary{
+			"accepts": {P50: accepts, P95: accepts + 10, N: 20}, "login": {P50: login, P95: login + 20, N: 20}}}
+	}
+	var b bytes.Buffer
+	Diff(&b, Report{Release: "v1", FirstLogin: login(300, 400)}, Report{Release: "v2", FirstLogin: login(300, 360)}, 0.05)
+	out := b.String()
+	for _, want := range []string{
+		"| accepts | 300.0 / 310.0 → 300.0 / 310.0 | +0.0% |",
+		"| login | 400.0 / 420.0 → 360.0 / 380.0 | -10.0% |",
+	} {
+		if !strings.Contains(out, want) {
+			t.Errorf("missing %q in:\n%s", want, out)
+		}
+	}
+	if strings.Index(out, "First SSH login") > strings.Index(out, "Feature matrix") {
+		t.Errorf("the first login is not before the console's sections:\n%s", out)
+	}
+
+	b.Reset()
+	nw := login(300, 360)
+	nw.Failed, nw.Error = 2, "sshd never accepted"
+	Diff(&b, Report{Release: "v1"}, Report{Release: "v2", FirstLogin: nw}, 0.05)
+	for _, want := range []string{"| login | - → 360.0 / 380.0 | - |", "2 of 20 boots had no login: sshd never accepted"} {
+		if !strings.Contains(b.String(), want) {
+			t.Errorf("missing %q in:\n%s", want, b.String())
+		}
+	}
+
+	// The other way round: a report made without sudo or vsock has no first login, and the
+	// release before it does. Nothing moved by -100%.
+	b.Reset()
+	Diff(&b, Report{Release: "v1", FirstLogin: login(300, 400)}, Report{Release: "v2"}, 0.05)
+	if want := "| login | 400.0 / 420.0 → - | - |"; !strings.Contains(b.String(), want) {
+		t.Errorf("missing %q in:\n%s", want, b.String())
+	}
+
+	// A p50 under a millisecond is still one to move from, and one failed boot is said.
+	b.Reset()
+	nw = login(1, 360)
+	nw.Failed, nw.Error = 1, "refused"
+	Diff(&b, Report{Release: "v1", FirstLogin: login(0.5, 360)}, Report{Release: "v2", FirstLogin: nw}, 0.05)
+	for _, want := range []string{"| accepts | 0.5 / 10.5 → 1.0 / 11.0 | +100.0% |", "1 of 20 boots had no login: refused"} {
+		if !strings.Contains(b.String(), want) {
+			t.Errorf("missing %q in:\n%s", want, b.String())
+		}
+	}
+
+	b.Reset()
+	Diff(&b, Report{Release: "v1"}, Report{Release: "v2"}, 0.05)
+	if strings.Contains(b.String(), "First SSH login") {
+		t.Errorf("two reports with no first login have a section for one:\n%s", b.String())
+	}
+}

boot/ssh_first_test.go

@@ -55,39 +55,7 @@ func TestFirstSSH(t *testing.T) {
 		t.Skip("no /dev/vhost-vsock: run task vsock")
 	}
 	reps := envInt(t, "REPS", 10)
-
-	pub, priv, err := ed25519.GenerateKey(nil)
-	if err != nil {
-		t.Fatal(err)
-	}
-	signer, err := xssh.NewSignerFromKey(priv)
-	if err != nil {
-		t.Fatal(err)
-	}
-	sshPub, err := xssh.NewPublicKey(pub)
-	if err != nil {
-		t.Fatal(err)
-	}
-	key := filepath.Join(t.TempDir(), "key")
-	if err := os.WriteFile(key+".pub", xssh.MarshalAuthorizedKey(sshPub), 0o644); err != nil {
-		t.Fatal(err)
-	}
-
-	// Every row has the key, the echo getty, and sshd@.service ordered after the image's host
-	// key generation. The image carries that drop-in itself since 2026-11-12; it is written
-	// here as well because the lab boots published releases, and one from before it cannot be
-	// logged into over vsock at all - the per-connection sshd finds no host keys.
-	keySetup := `ids=$(awk -F: '$1=="spin"{print $3":"$4}' "$MNT/etc/passwd"); test -n "$ids"
-install -d -m 700 -o "${ids%:*}" -g "${ids#*:}" "$MNT/home/spin/.ssh"
-install -m 600 -o "${ids%:*}" -g "${ids#*:}" ` + key + `.pub "$MNT/home/spin/.ssh/authorized_keys"
-`
-	row := func(label, setup string) variant {
-		files := gettyDropin(gettyEcho)
-		files["/etc/systemd/system/sshd@.service.d/keygen.conf"] = "[Unit]\nWants=spin-machine-sshd-keygen.service\nAfter=spin-machine-sshd-keygen.service\n"
-		// The key in spin's own directory, owned by spin: sshd's StrictModes refuses one it
-		// cannot trust, and a refused key reads as a login that never comes.
-		return variant{label: label, cpus: cmp.Or(os.Getenv("CPUS"), "2"), memory: "2048", files: files, setup: keySetup + setup}
-	}
+	row, signer := sshRow(t)
 	// Rows measured against "as built" and dropped once they had answered, on the bench fleet,
 	// 10 boots of each interleaved, lab run 43308825692 (2026-11-12), p50/p95 ms of the first
 	// login: as built then 570/626; pam_motd off 558/588; logind back in the boot 558/593;
@@ -202,6 +170,43 @@ grep -q 'pam_systemd.so.*class=user-early-light' "$MNT/etc/pam.d/common-session"
 	t.Log(b.String())
 }
 
+// sshRow makes a key to log in with and returns it with a function that makes a row of the
+// release logged into with it: the key in spin's authorized_keys, the echo getty, sshd@ ordered
+// after the image's host key generation, and setup run after those. The image carries that last
+// drop-in itself since 2026-11-12; it is written here as well because the lab boots published
+// releases, and one from before it cannot be logged into over vsock at all - the per-connection
+// sshd finds no host keys.
+func sshRow(t *testing.T) (func(label, setup string) variant, xssh.Signer) {
+	t.Helper()
+	pub, priv, err := ed25519.GenerateKey(nil)
+	if err != nil {
+		t.Fatal(err)
+	}
+	signer, err := xssh.NewSignerFromKey(priv)
+	if err != nil {
+		t.Fatal(err)
+	}
+	sshPub, err := xssh.NewPublicKey(pub)
+	if err != nil {
+		t.Fatal(err)
+	}
+	key := filepath.Join(t.TempDir(), "key")
+	if err := os.WriteFile(key+".pub", xssh.MarshalAuthorizedKey(sshPub), 0o644); err != nil {
+		t.Fatal(err)
+	}
+	// The key in spin's own directory, owned by spin: sshd's StrictModes refuses one it cannot
+	// trust, and a refused key reads as a login that never comes.
+	keySetup := `ids=$(awk -F: '$1=="spin"{print $3":"$4}' "$MNT/etc/passwd"); test -n "$ids"
+install -d -m 700 -o "${ids%:*}" -g "${ids#*:}" "$MNT/home/spin/.ssh"
+install -m 600 -o "${ids%:*}" -g "${ids#*:}" ` + key + `.pub "$MNT/home/spin/.ssh/authorized_keys"
+`
+	return func(label, setup string) variant {
+		files := gettyDropin(gettyEcho)
+		files["/etc/systemd/system/sshd@.service.d/keygen.conf"] = "[Unit]\nWants=spin-machine-sshd-keygen.service\nAfter=spin-machine-sshd-keygen.service\n"
+		return variant{label: label, cpus: cmp.Or(os.Getenv("CPUS"), "2"), memory: "2048", files: files, setup: keySetup + setup}
+	}, signer
+}
+
 type firstSSHRun struct {
 	listen, login, prompt time.Duration
 	again                 time.Duration // a second login, right after the first: what any login costs
@@ -219,10 +224,11 @@ func firstSSH(t *testing.T, out string, v variant, signer xssh.Signer) firstSSHR
 	// Context ids are the host's: two machines with one fail to start, so this one's is drawn
 	// from a range nothing else here uses.
 	cid := uint32(100000 + rand.IntN(1<<20))
-	cmd := exec.Command(filepath.Join(out, "bin", "spin-machine"), "boot", "--release", out,
+	args := append([]string{"boot", "--release", out,
 		"--disk", overlay, "--memory", v.memory, "--cpus", v.cpus,
 		"--vsock-cid", fmt.Sprint(cid),
-		"--console", "file:/dev/stdout", "--append", "init=/sbin/init")
+		"--console", "file:/dev/stdout", "--append", "init=/sbin/init"}, v.flags...)
+	cmd := exec.Command(filepath.Join(out, "bin", "spin-machine"), args...)
 	cmd.SysProcAttr = &syscall.SysProcAttr{Setpgid: true}
 	stdout, err := cmd.StdoutPipe()
 	if err != nil {

docs/log.md

@@ -339,6 +339,8 @@ Measured and not shipped:
 
 **11-13 · kernel/qemu · branches `kernel-snapshot`, `qemu-snapshot` (rejected).** QEMU publishes bus 0's configuration space over fw_cfg after the firmware (etc/spin/pci-config) and the kernel answers boot-time configuration reads from it until each dword is written. It works (`PCI: configuration space of 5 devices on bus 0`) and is worth -14 ms against the same kernel without it (lab 43514550646), but only 2-3 ms against 0005, which already removes most repeated reads: 209/217 against 211/222 (lab 43514884598). Not worth a QEMU patch and a 250-line kernel patch.
 
+**11-13 · boot/qemu · branch `first-login-report` (this change).** v20261113.03's report read +11-18% on every row: the report times the serial console's prompt, and the getty drop-in removed in #250 left it Type=idle, waiting for the lane's units. The first login it does not time went 478/500 (v20261113.02, lab 43524334205) -> 381/410 ms (v20261113.03, lab 43524721490), two runs and not interleaved. The report now logs into the release over SSH too (`first_login`), and compare writes it first. The QEMU build asserts static-pie, full RELRO, an NX stack and stack canaries, which come from QEMU's and Alpine's defaults and no flag here. Measured and left out: one sshd for every connection (the vsock socket with Accept=no, an `sshd -D` from the first dispatch), first login 382/393 against 381/410 and a second 40 against 48 ms (lab 43524721490).
+
 ---
 
 ## 3. Rework cycles
@@ -514,6 +516,7 @@ Also the reusable builder, added and reverted on 10-13.
 | sntrup761 (OpenSSH default) | 104 vs 40 ms per login | #245, lab 43479854381 | 11-13 |
 | Configuration-space snapshot over fw_cfg (QEMU + kernel) | 209 vs 211 with 0005 | lab 43514884598 | 11-13 |
 | CPUWeight/IOWeight/Nice on the first login's lane | −2 ms over coldplug filtered; second login 63 vs 45 | lab 43518915618 | 11-13 |
+| One sshd for every connection (vsock Accept=no, `sshd -D` early) | First login 382 vs 381; second 40 vs 48 ms | lab 43524721490 | 11-13 |
 | Login without pam_systemd (diagnostic bound) | 380 vs 436, but no session, no XDG_RUNTIME_DIR | lab 43518044150 | 11-13 |
 | Lower the vCPU ceiling, drop the balloon or ACPI for boot time | Not tried: hotplug and dynamic memory are an invariant | AGENTS.md | 11-13 |
 

qemu/Dockerfile

@@ -380,6 +380,28 @@ RUN for b in /opt/qemu/bin/qemu-system-x86_64 /opt/qemu/bin/qemu-img \
     done && \
     echo "OK: every binary is statically linked"
 
+# Hardened, asserted for the same reason. No flag above asks for any of this: static-pie, full
+# RELRO, a non-executable stack and stack canaries come from QEMU's meson defaults and Alpine's
+# gcc (15.2 on 2026-11-13), so a bump of either could drop one without a line here changing.
+# QEMU runs a guest's device emulation on the host, which is where these earn their place.
+#
+# PIE is the ELF type (DYN for a static-pie, EXEC without); RELRO is full only with BIND_NOW,
+# since a lazily bound GOT stays writable; the canaries are counted as reads of the TLS guard
+# (%fs:0x28) in the code, because the binaries are stripped and __stack_chk_fail is no longer
+# a symbol to look for. 7111 of them in qemu-system-x86_64 as built 2026-11-13.
+RUN for b in /opt/qemu/bin/qemu-system-x86_64 /opt/qemu/bin/qemu-img \
+             /opt/qemu-tcg/bin/qemu-system-x86_64; do \
+        readelf -hW "$b" | grep -q 'Type:.*DYN' || { echo "ERROR: $b is not position-independent"; exit 1; }; \
+        readelf -lW "$b" | grep -q GNU_RELRO || { echo "ERROR: $b has no RELRO segment"; exit 1; }; \
+        readelf -dW "$b" | grep -q 'FLAGS.*BIND_NOW' || { echo "ERROR: $b is lazily bound; its RELRO is partial"; exit 1; }; \
+        stack=$(readelf -lW "$b" | grep GNU_STACK) || { echo "ERROR: $b has no GNU_STACK segment, so its stack is executable"; exit 1; }; \
+        case "$stack" in *RWE*) echo "ERROR: $b has an executable stack"; exit 1 ;; esac; \
+        canaries=$(objdump -d --no-show-raw-insn "$b" | grep -c '%fs:0x28') || true; \
+        [ "${canaries:-0}" -gt 0 ] || { echo "ERROR: $b has no stack canaries"; exit 1; }; \
+        echo "$b: static-pie, full RELRO, NX stack, $canaries canary reads"; \
+    done && \
+    echo "OK: every binary is hardened"
+
 # qboot, the BIOS this machine boots with. QEMU's SeaBIOS is built for every guest a PC can run; this machine boots one Linux kernel
 # through PVH and nothing else, and qboot is a firmware for exactly that. Measured on the lab
 # runner, 20 boots interleaved (2026-09-29): 121.9 -> 114.8 ms p50 to a diagnostic init, and