diff --git a/boot/report.go b/boot/report.go index 5903247..d477402 100644 --- a/boot/report.go +++ b/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 { diff --git a/boot/report_test.go b/boot/report_test.go index cd4963f..706bd0a 100644 --- a/boot/report_test.go +++ b/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. diff --git a/boot/report_unit_test.go b/boot/report_unit_test.go index 87e83c2..2217c1b 100644 --- a/boot/report_unit_test.go +++ b/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()) + } +} diff --git a/boot/ssh_first_test.go b/boot/ssh_first_test.go index 4929324..058b4c6 100644 --- a/boot/ssh_first_test.go +++ b/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 { diff --git a/docs/log.md b/docs/log.md index def577d..780a278 100644 --- a/docs/log.md +++ b/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 | diff --git a/qemu/Dockerfile b/qemu/Dockerfile index a506706..d913b68 100644 --- a/qemu/Dockerfile +++ b/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