From c2ece450dca6fefe3593fffae62b166c74cc1bd9 Mon Sep 17 00:00:00 2001 From: Manuel de Brito Fontes Date: Sat, 12 Sep 2026 13:46:08 -0300 Subject: [PATCH] logind starts at the first login and not at the boot, and that is 24ms MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit pam_systemd decides whether to register a session by calling logind_running(), which is access("/run/systemd/seats/") — 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 XDG_RUNTIME_DIR, no XDG_SESSION_ID and no user manager, and nothing anywhere reports an error. logind creates that directory itself, so the guard is false exactly while logind has never run. Creating it on the Varlink socket, which carries Service=systemd-logind.service, makes the guard tell the truth before logind runs and turns pam_systemd's connection into what starts it. Every login path activates it, not only SSH: the console getty and su go through the same module. Worth 24ms: 249/287 against 273/297 with logind wanted by multi-user.target, p50/p95 over 25 boots each, reproduced in two runs. The fork gives 4ms of that back and buys the sessions; masking logind outright would be 7ms better again and would leave every login without one. The want is overridden with a /dev/null symlink and not removed, because it is not in /etc to begin with: the package ships it in /usr. The first version of this used `rm -f` on the /etc path, removed nothing at all, and produced an image that built green and still started logind at boot. build.sh now asserts the override is present rather than the /etc path absent, which is the check that would have caught it. Two dead ends, both of which measure well and leave a machine whose logins have no session, because a console marker needs none: ordering sshd after logind repairs SSH and only SSH, and ordering the getty too hands the saving straight back; and RuntimeDirectory= on the socket creates nothing, since a unit with no Exec* line never applies its execution context. task boot:logind is what holds the half of this that a boot time cannot show: the shipped image passes, and SPIN_LOGIND_NO_SEATS=1 removes the drop-in and fails at the console login before it ever reaches SSH. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01CaRJvsQ773TwLQaY6tLZ9c --- Taskfile.yml | 14 +- boot/bench_test.go | 50 ++++++ boot/logind_test.go | 159 ++++++++++++++++++ boot/testdata/logind-check.sh | 46 +++++ boot/testdata/logind-session.sh | 12 ++ image/build.sh | 26 +++ .../local/lib/spin-base/optimize-systemd.sh | 14 ++ .../10-seats.conf | 28 +++ 8 files changed, 347 insertions(+), 2 deletions(-) create mode 100644 boot/logind_test.go create mode 100644 boot/testdata/logind-check.sh create mode 100644 boot/testdata/logind-session.sh create mode 100644 image/mkosi.extra/usr/local/lib/spin-base/rootfs/etc/systemd/system/systemd-logind-varlink.socket.d/10-seats.conf 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