diff --git a/Taskfile.yml b/Taskfile.yml index 660e23f..cf0afe7 100644 --- a/Taskfile.yml +++ b/Taskfile.yml @@ -150,6 +150,16 @@ tasks: cmds: - SPIN_BOOT_BENCH=1 go test ./boot/ -run TestBootCost -v -timeout 60m + boot:logind: + desc: >- + Check first SSH login, reconnect, user services and logout in a disposable guest. + Needs a built release and debugfs; uses KVM when available, otherwise TCG. + The image does not start logind at boot, so this checks the thing that makes that + safe: that the first login activates it and gets a real session. SPIN_LOGIND_NO_SEATS=1 + removes the drop-in that allows it and is expected to fail, not to measure anything. + cmds: + - SPIN_LOGIND_TEST=1 go test ./boot/ -run '^TestLogindSessions$' -count=1 -v -timeout 5m + boot:trace: desc: >- One boot's console printed against the host's clock, for finding a gap that belongs to @@ -170,7 +180,7 @@ tasks: cmds: - | set -euo pipefail - unformatted=$(gofmt -l machine cmd) + unformatted=$(gofmt -l machine cmd boot) if [ -n "$unformatted" ]; then echo "not gofmt'd:"; echo "$unformatted"; exit 1 fi @@ -184,7 +194,7 @@ tasks: - | set -euo pipefail for f in hack/release image/build.sh image/mkosi.postinst.chroot \ - image/mkosi.extra/usr/local/lib/spin-base/*.sh; do + image/mkosi.extra/usr/local/lib/spin-base/*.sh boot/testdata/*.sh; do bash -n "$f" || { echo "$f does not parse" >&2; exit 1; } done echo "OK: the shell scripts parse" diff --git a/boot/bench_test.go b/boot/bench_test.go index 14aafdd..1cdb271 100644 --- a/boot/bench_test.go +++ b/boot/bench_test.go @@ -84,6 +84,11 @@ func without(units ...string) variant { func labelled(l string, v variant) variant { v.label = l; return v } +func withFile(m map[string]string, path, content string) map[string]string { + m[path] = content + return m +} + var variants = []variant{ {label: "as shipped", cpus: "2", memory: "2048"}, {label: "baseline", cpus: "2", memory: "2048", files: gettyDropin(gettyEcho)}, @@ -112,6 +117,51 @@ var variants = []variant{ // The chrony rows are kept as the record of what removing it bought, and cannot be run // again: there is no time daemon in the image since 2026-09-10 (see image/mkosi.conf). labelled("sin logind", without("systemd-logind.service")), + // The inverse of what the image ships: logind put back into the boot transaction, which + // is the configuration this replaced. Since 2026-09-12 the want is overridden with a + // /dev/null symlink and the first login starts logind over its Varlink socket instead. + // 25 boots of each, same run, measured that day: + // + // as shipped, deferred 248/275 logind at boot (this row) 272/294 + // deferred, no drop-in 244/264 at boot, with the drop-in 282/322 + // masked outright 241/265 + // + // So deferring it is worth 24 ms, of which the drop-in gives 4 back for its fork, and + // masking it outright — which breaks every login — would be worth 7 more. + // + // This row neutralises the drop-in as well, and that is the whole reason it is written + // the long way instead of just restoring the want. With the drop-in left in place the + // same comparison reads 43 ms, because a service is implicitly ordered after the socket + // that triggers it: logind starting at boot then waits for an ExecStartPre fork that the + // shipped machine never puts on any path, and the row flatters the change by 19 ms. + // + // What makes the deferral possible is that drop-in rather than anything here: + // pam_systemd decides whether to register a session by calling logind_running(), which + // is access("/run/systemd/seats/") — a test for "is this a logind system", not "is + // logind up" — and on a false answer it logs "Skipping logind registration as logind is + // not running" and returns PAM_SUCCESS. Creating that directory on the Varlink socket, + // which carries Service=systemd-logind.service, is what gets pam_systemd as far as the + // connection that starts logind. + // + // Two dead ends on the way, both of which measure well *here* and leave a machine whose + // logins have no session, because the echo marker this row watches needs none: + // + // - Ordering sshd after logind instead repairs SSH and only SSH, with `su -l` and the + // console getty still landing with XDG_RUNTIME_DIR unset. Ordering the getty after + // logind too repairs those and hands the saving straight back. + // - RuntimeDirectory=systemd/seats on the socket, to make the directory without a + // fork, creates nothing: a unit with no Exec* line never applies its execution + // context. It benchmarked as the fastest row here because it *was* the masked + // machine. ExecStartPre=/bin/true makes the directory appear, which is both the + // proof and the reason the drop-in does not bother avoiding the fork. + // + // `task boot:logind` is what holds the half of this that a boot time cannot show. + {label: "logind at boot", cpus: "2", memory: "2048", + files: withFile(gettyDropin(gettyEcho), + "/etc/systemd/system/systemd-logind-varlink.socket.d/10-seats.conf", "[Socket]\n"), + links: map[string]string{ + "/etc/systemd/system/multi-user.target.wants/systemd-logind.service": "/lib/systemd/system/systemd-logind.service", + }}, // serial-getty is Type=idle, which holds the service until systemd's job queue is quiet. // If that dominates, `usable` has been measuring the queue draining rather than the // machine being ready — and it would have been invisible earlier, because the first test diff --git a/boot/logind_test.go b/boot/logind_test.go new file mode 100644 index 0000000..d33bb98 --- /dev/null +++ b/boot/logind_test.go @@ -0,0 +1,159 @@ +// SPDX-License-Identifier: Apache-2.0 + +package boot_test + +import ( + "bytes" + "context" + "os" + "os/exec" + "path/filepath" + "strings" + "testing" + "time" + + "github.com/spin-stack/spin-machine/machine" +) + +// A correctness test, including under TCG: none of its durations are boot +// performance measurements. It edits a private raw copy, without mounts or NBD. +func TestLogindSessions(t *testing.T) { + if os.Getenv("SPIN_LOGIND_TEST") != "1" { + t.Skip("set SPIN_LOGIND_TEST=1 to check first SSH login in a built image") + } + out, err := filepath.Abs("../_output") + if err != nil { + t.Fatal(err) + } + rel, err := machine.Open(out) + if err != nil { + t.Fatal(err) + } + base, err := rel.Rootfs() + if err != nil { + t.Fatal(err) + } + dir := t.TempDir() + raw := filepath.Join(dir, "rootfs.raw") + mustRun(t, filepath.Join(out, "bin/qemu-img"), "convert", "-f", "qcow2", "-O", "raw", base, raw) + debugfs := func(command string) string { + t.Helper() + output, err := exec.Command("debugfs", "-w", "-R", command, raw).CombinedOutput() + if err != nil { + t.Fatalf("debugfs %s: %v\n%s", command, err, output) + } + return string(output) + } + write := func(path, content string) { + t.Helper() + src := filepath.Join(dir, "input") + if err := os.WriteFile(src, []byte(content), 0644); err != nil { + t.Fatal(err) + } + // debugfs returns success even if the write failed. Read the guest file + // back to ensure the experiment actually installed its input. + debugfs("write " + src + " " + path) + got, err := exec.Command("debugfs", "-R", "cat "+path, raw).Output() + if err != nil || string(got) != content { + t.Fatalf("guest file %s differs from its input: %v", path, err) + } + } + // The shipped image does not start logind at boot: the first login activates it over + // the Varlink socket, which is worth 18 ms (see the 10-seats.conf drop-in). So the + // state this asserts before any login is `inactive`, and a machine that answers + // `active` has put logind back into the boot transaction. + // + // SPIN_LOGIND_NO_SEATS=1 removes the drop-in and nothing else. It is the experiment + // that says what the drop-in does, and it is expected to fail: without + // /run/systemd/seats, pam_systemd never asks logind for a session and never activates + // it, so every login — SSH and console alike — comes up with XDG_RUNTIME_DIR unset and + // no error anywhere (2026-09-12). + expectedState := "inactive" + if os.Getenv("SPIN_LOGIND_NO_SEATS") == "1" { + path := "/etc/systemd/system/systemd-logind-varlink.socket.d/10-seats.conf" + debugfs("rm " + path) + if strings.Contains(debugfs("stat "+path), "Inode:") { + t.Fatal("the drop-in is still in the image; the experiment would prove nothing") + } + } + for _, name := range []string{"logind-check.sh", "logind-session.sh"} { + content, err := os.ReadFile(filepath.Join("testdata", name)) + if err != nil { + t.Fatal(err) + } + write("/"+name, string(content)) + } + write("/etc/systemd/system/logind-check.service", `[Unit] +Description=Check on-demand sessions in a disposable guest +After=multi-user.target +[Service] +Type=oneshot +Environment=LOGIND_EXPECT=`+expectedState+` +ExecStart=/bin/sh /logind-check.sh +StandardOutput=journal+console +StandardError=journal+console +`) + write("/etc/systemd/system/logind-check.timer", `[Timer] +OnBootSec=3s +AccuracySec=100ms +`) + debugfs("symlink /etc/systemd/system/timers.target.wants/logind-check.timer /etc/systemd/system/logind-check.timer") + spec := rel.Spec() + spec.BootCPUs = 2 + spec.Memory.SizeMB = 1024 + spec.Disks = []machine.Disk{{Path: raw, Format: "raw"}} + spec.Serial = "stdio" + c := machine.DefaultCmdline() + c.Root = "/dev/vda" + c.Init = "/sbin/init" + spec.Cmdline = c.String() + args, err := spec.Args() + if err != nil { + t.Fatal(err) + } + if _, err := os.Stat("/dev/kvm"); err != nil { + spec.QEMU = filepath.Join(out, "bin/qemu-system-x86_64-tcg") + for i := range args { + args[i] = strings.ReplaceAll(args[i], "accel=kvm", "accel=tcg") + if args[i] == "host,migratable=on" { + args[i] = "max,migratable=on" + } + } + t.Log("TCG: checking functionality only") + } + ctx, cancel := context.WithTimeout(context.Background(), 2*time.Minute) + defer cancel() + cmd := exec.CommandContext(ctx, spec.QEMU, args...) + var stderr bytes.Buffer + cmd.Stderr = &stderr + stdout, err := cmd.StdoutPipe() + if err != nil { + t.Fatal(err) + } + if err := cmd.Start(); err != nil { + t.Fatal(err) + } + waited := false + stop := func() { + cancel() + if !waited { + _ = cmd.Wait() + waited = true + } + } + defer stop() + var console bytes.Buffer + buf := make([]byte, 4096) + for { + n, err := stdout.Read(buf) + console.Write(buf[:n]) + if strings.Contains(console.String(), "LOGIND_CHECK_OK") { + t.Log(console.String()) + return + } + if err != nil || strings.Contains(console.String(), "LOGIND_CHECK_FAILED") { + stop() + t.Fatalf("guest session check failed: %v\n%s\n%s", err, &console, &stderr) + } + } +} diff --git a/boot/testdata/logind-check.sh b/boot/testdata/logind-check.sh new file mode 100644 index 0000000..979b73c --- /dev/null +++ b/boot/testdata/logind-check.sh @@ -0,0 +1,46 @@ +#!/bin/sh +# SPDX-License-Identifier: Apache-2.0 +set -eu +trap 'cat /run/logind-session-result 2>/dev/null || true; journalctl -b -u ssh.service -u systemd-logind.service --no-pager; echo LOGIND_CHECK_FAILED' EXIT + +# Query PID1, not loginctl: asking login1 would itself activate logind. +test "$(systemctl show systemd-logind.service -p ActiveState --value)" = "$LOGIND_EXPECT" +systemctl is-active --quiet systemd-logind-varlink.socket +echo "LOGIND_INITIAL_STATE_OK $LOGIND_EXPECT" + +# Every login is PAM, not only sshd's: the console getty and su go through the same stack. +# Asserted separately from the SSH logins below because a configuration that starts logind +# on sshd's behalf passes those and fails this one (2026-09-12). +test "$(su -l spin -c 'echo ${XDG_RUNTIME_DIR:-unset}' /run/logind-session-result + cat /run/logind-session-result + grep -q '^SESSION_OK ' /run/logind-session-result + systemctl is-active --quiet systemd-logind.service + session=$(sed -n 's/^SESSION_OK //p' /run/logind-session-result | tr -d '\r') + test "$session" != "$previous_session" + previous_session=$session + # The session scope must finish after logout, even if the user's service + # manager stays alive for its configured stop delay. + for attempt in $(seq 50); do + state=$(systemctl show "session-$session.scope" -p ActiveState --value) + test "$state" != active && break + sleep 0.1 + done + test "$state" != active +done +trap - EXIT +echo LOGIND_CHECK_OK diff --git a/boot/testdata/logind-session.sh b/boot/testdata/logind-session.sh new file mode 100644 index 0000000..e04b3b9 --- /dev/null +++ b/boot/testdata/logind-session.sh @@ -0,0 +1,12 @@ +#!/bin/sh +# SPDX-License-Identifier: Apache-2.0 +# Runs as spin, through sshd's real PAM stack, in a disposable test guest. +set -eux +test "$(id -u)" = 1000 +test "${XDG_RUNTIME_DIR:-}" = /run/user/1000 +test "$(stat -c '%u:%a' "$XDG_RUNTIME_DIR")" = 1000:700 +test -n "${XDG_SESSION_ID:-}" +test "$(loginctl show-session "$XDG_SESSION_ID" -p Name --value)" = spin +systemctl --user list-units --no-pager >/dev/null +sudo -n true +printf 'SESSION_OK %s\n' "$XDG_SESSION_ID" diff --git a/image/build.sh b/image/build.sh index f646836..5f25794 100755 --- a/image/build.sh +++ b/image/build.sh @@ -216,6 +216,32 @@ for u in systemd-random-seed.service tmp.mount; do exit 1; } done +# logind is deferred rather than masked, and the two halves of that only work together. +# The drop-in makes pam_systemd's guard — access("/run/systemd/seats/") — true before +# logind has run, so the first login activates it over Varlink instead of being handed a +# session with no XDG_RUNTIME_DIR and no user manager. The overridden want is what keeps +# the 24 ms. Either half alone is a silent failure: without the drop-in every login comes +# up session-less and nothing logs an error, and a re-enabled want costs the boot time back +# while everything still works, so neither shows up anywhere but here. +in_image /etc/systemd/system/systemd-logind-varlink.socket.d/10-seats.conf || { + echo "ERROR: the image has no logind seats drop-in; every login would lose its session" >&2 + exit 1; } +# The want is overridden, not deleted: the package ships it in /usr, so the /etc path must +# hold a symlink to /dev/null. Asserting its *absence* is the version of this check that +# passed while the image still started logind at boot, because the /etc path was never +# there to remove (2026-09-12). +if ! stat_in_image /etc/systemd/system/multi-user.target.wants/systemd-logind.service | + grep -q '/dev/null'; then + echo "ERROR: the want for systemd-logind is not overridden; the package ships one in" \ + "/usr and logind is back in the boot transaction" >&2 + exit 1 +fi +if stat_in_image /etc/systemd/system/systemd-logind.service | grep -q '/dev/null'; then + echo "ERROR: systemd-logind.service is masked - deferring it means it still starts" \ + "on demand, and masked means it never starts at all" >&2 + exit 1 +fi + # The distribution's background maintenance, masked by configure-system.sh for reasons # that are written there. Asserted separately from the three above because the cause is a # different script: these come back if a package upgrade re-runs a unit's [Install], and diff --git a/image/mkosi.extra/usr/local/lib/spin-base/optimize-systemd.sh b/image/mkosi.extra/usr/local/lib/spin-base/optimize-systemd.sh index e6efb4a..a2c3c0c 100755 --- a/image/mkosi.extra/usr/local/lib/spin-base/optimize-systemd.sh +++ b/image/mkosi.extra/usr/local/lib/spin-base/optimize-systemd.sh @@ -281,6 +281,20 @@ rm -f /etc/systemd/system/multi-user.target.wants/ssh.service 2>/dev/null || tru mkdir -p /etc/systemd/system/sockets.target.wants ln -sf /lib/systemd/system/ssh.socket /etc/systemd/system/sockets.target.wants/ssh.socket +# logind out of the boot transaction, worth 24 ms. Not masked: masked means never started, +# and a login needs it. It stays enabled in every other sense and is started by the first +# thing that asks for a session over its Varlink socket — see the 10-seats.conf drop-in +# shipped beside it, which is what makes pam_systemd get as far as asking. +# +# A symlink to /dev/null and not `rm`, because the want is not in /etc to begin with: the +# package ships it at /usr/lib/systemd/system/multi-user.target.wants/systemd-logind.service. +# An `rm` of the /etc path is what this said first, and it removed nothing at all — the +# build passed, the image shipped, and logind started at boot exactly as before (2026-09-12). +# The /dev/null symlink in /etc overrides the want in /usr and nothing else: the unit itself +# is untouched, which is why it can still be activated on demand. +mkdir -p /etc/systemd/system/multi-user.target.wants +ln -sf /dev/null /etc/systemd/system/multi-user.target.wants/systemd-logind.service + log "Setting default target to multi-user..." ln -sf /lib/systemd/system/multi-user.target /etc/systemd/system/default.target diff --git a/image/mkosi.extra/usr/local/lib/spin-base/rootfs/etc/systemd/system/systemd-logind-varlink.socket.d/10-seats.conf b/image/mkosi.extra/usr/local/lib/spin-base/rootfs/etc/systemd/system/systemd-logind-varlink.socket.d/10-seats.conf new file mode 100644 index 0000000..550546d --- /dev/null +++ b/image/mkosi.extra/usr/local/lib/spin-base/rootfs/etc/systemd/system/systemd-logind-varlink.socket.d/10-seats.conf @@ -0,0 +1,28 @@ +# Why logind is not started at boot, and why this file is what allows that. +# +# pam_systemd decides whether to register a session by calling logind_running(), which is +# access("/run/systemd/seats/"). That is a test for "is this a system with logind", not for +# "is logind up". On a false answer it logs "Skipping logind registration as logind is not +# running" and returns PAM_SUCCESS: the login authenticates and lands with no session at +# all — no XDG_RUNTIME_DIR, no XDG_SESSION_ID, no user manager — and nothing reports an +# error. logind creates that directory itself, so the guard reads false exactly while +# logind has never run, and it never asks logind anything before answering. +# +# Creating the directory here makes the guard tell the truth before logind runs. The rest +# is already in place: this socket carries Service=systemd-logind.service, so the Varlink +# connection pam_systemd then makes is what starts logind. Every login path activates it, +# not only SSH — the console getty and su go through the same module. +# +# Worth 24 ms of boot: 248/275 against 272/294 with logind wanted by multi-user.target, +# p50/p95 over 25 boots each, measured 2026-09-12 with `task boot:bench`. The fork below +# is 4 ms of that (244/264 without it) and buys the sessions; masking logind outright +# would be 7 ms better again and would leave every login without one. `task boot:logind` +# is the test that holds that second half. +# +# ExecStartPre and not RuntimeDirectory=systemd/seats: a unit with no Exec* line never +# applies its execution context, so RuntimeDirectory alone creates nothing at all — and it +# then benchmarks *better*, because what it measures is a machine whose logins have no +# session. Adding ExecStartPre=/bin/true makes the directory appear, which is the proof, +# and also why there is no point avoiding the fork. +[Socket] +ExecStartPre=/bin/mkdir -p /run/systemd/seats