62. A wait with no bound and no signal is how a working machine fails to boot

Status: accepted. Amends ADR-0002 on what systemd is being asked to guarantee for Tacid’s own units, and ADR-0013 on what the health gate is allowed to cost before the bootloader draws a conclusion from its silence.

Context

Two virtual machines timed out reaching multi-user.target after fifteen minutes. Nothing on either was broken. The desktop leg’s compositor was built, its session declared, its daemons installed; the update leg’s installer had a disk, a channel and a cache. Both were machines that worked, and neither finished starting.

The trail, on both, was the same:

• the console went quiet around 425 seconds in, with no error before or after it;
• tacid-first-boot.service — wantedBy = multi-user.target, so while it runs the boot is not finished — had started and never completed;
• it had printed not one word of the introduction, so it was not stuck writing to a console that was gone; it was stuck before its first sentence, in a call to the daemon;
• and on the desktop node the keeper that daemon reaches had printed nothing either — not even listening on /run/tacid/keeper.sock, which is the first thing it says.

The logs of the leg that hung and the leg that passed, read side by side, name the cause exactly. On both machines the keeper’s first act is to anchor its journal, which is a call to the stem; the stem is socket-activated, so that call is visible from outside as the stem’s own service starting. On the machine that passed, the stem said it was listening at 106.5 seconds and the keeper printed its first word at 106.9 — not sealed: this machine has no TPM counter. On the machine that hung, the stem said it was listening at 72.2 seconds and the keeper printed its first word never: the driver gave up 830 seconds later. Same code, same absent chip, and one of them answered in four hundred milliseconds.

So the difference is not in Tacid’s logic but in what the tpm2_* process the stem spawns did — on one machine it failed immediately, on the other it did not return.

The first guess about why was that the graphical closure carries tpm2-tools where the minimal one does not, so the small machine failed at execve. That guess was checkable and it is wrong: tpm2-tools is in environment.systemPackages, unconditionally, so it is on every Tacid machine that has ever booted. Both machines ran a real program. What is left to differ is the transport, because tpm2-tools resolves its own: device nodes first, then a simulator over a socket, then a resource manager over D-Bus. The machine that hung runs a D-Bus and the machine that answered does not, which is a hypothesis that fits and is still a hypothesis.

The finding does not depend on it. The stem waits for the process with wait_with_output, which has no timeout, so whatever the process was doing, the stem never answered, the keeper never got past its first call, the daemon was ordered after the keeper, the introduction was ordered after the daemon, and multi-user.target was ordered after the introduction. One subprocess that did not return, and a machine that would not finish booting.

It also does not depend on the machine being unusual. Every Tacid machine has those tools and most will never have a chip: the leg that tests updating installs its follower with --no-tpm, and a board or a virtual machine has nothing to seal to either. The graphical leg is where this was seen; it is not where it lives.

Two more details from the same minute are worth keeping, because both are the same mistake seen from another side. The health gate ran while the keeper was wedged, reported tacidd.service is running, and boot-complete.target was reached at 71.1 seconds — the boot was blessed on a machine whose keeper had not opened its socket and never would. And the introduction was Starting at 71.2 seconds, which is the last thing anybody said about it.

Underneath that were two defects. They look unrelated and they are the same mistake, which is why they are one record.

“Started” did not mean “can be reached.” Under Type=simple, systemd calls a unit started the moment the process is spawned. So After=tacid-keeper.service on the daemon, and After=tacidd.service on the introduction, ordered themselves against processes that existed rather than against doors that were open. On a machine where the keeper takes sixteen seconds to get from execve to bind — which is what software emulation does to a keeper that opens a journal, anchors it, reads its generations, seals to a chip and verifies a hash chain before it listens — everything ordered after it ran against a socket nobody was listening on. Sixteen seconds is not the interesting number; it is only larger than zero, and zero is what every After= in this system had been assuming.

The install test had already found the same defect from the other side and it had been read as a flake: wait_for_unit("tacid-keeper.service") returned, journalctl a second later held nothing, and the assertion was about a sentence the keeper had not reached yet.

A oneshot cannot fail by taking too long. systemd applies DefaultTimeoutStartSec to every unit except Type=oneshot, where the start timeout is disabled outright. This system has five oneshots and not one of them carried a bound, so not one of them could ever be killed for hanging — only for exiting non-zero, which a wedged process never does. The introduction was one. tacid-health is another, and it is requiredBy = boot-complete.target: a gate that hangs is a boot that is never blessed and, three boots later, a working generation abandoned with nothing anywhere saying why. tacid-update and tacid-collect are the other two, and a oneshot stuck in activating is a unit systemd will not start a second time — so the timer fires into a unit already running, does nothing, and the machine stops updating or stops collecting, silently, for as long as it is left alone.

The two are one mistake: every wait on the boot path was unbounded in both directions. Nothing said when a wait was satisfied, and nothing said when it had gone on too long. A machine in that state cannot report a fault, because from the inside there is no fault — there is a unit still trying, which is what a unit doing its job also looks like.

Decision

1. Every daemon on the boot path is Type=notify, and says READY=1 after it binds. Not before: the point of the signal is that anything ordered after this unit may now knock. sd_notify is written out rather than linked — it is one datagram to the socket named in NOTIFY_SOCKET, and a C library for fifteen lines of that would be a C library on the trust path of a system that forbids unsafe in its own crates.

2. Every Type=oneshot unit carries an explicit TimeoutStartSec. There is no unit in this system for which “may hang for ever” is the right default, and it is the default.

3. The bounds are generous, because slow is not broken. A unit killed for taking too long is a failed unit, a failed unit after an activation is a good generation rolled back, and a machine that rolls back working generations because it was emulated on a busy host is worse than one that starts slowly. 300 seconds for the daemons and the health gate, 600 for the update check, an hour for collection — the longest, because collecting a large store is genuinely slow and a collection killed halfway did nothing — and 120 for the introduction, which is the one unit here whose whole job is to say something nice.

4. Where a bound changes the outcome rather than only the diagnosis, it is paired with a refusal to continue. For four of the five oneshots the bound is free: a killed unit and a hung unit reach the same end state, and only the killed one leaves a line naming where it was. The two initrd units are not like that. before = sysroot.mount is ordering and not requirement, so a unit that fails lets the mount go ahead — and the machine boots, works, and is no longer ephemeral, with last boot’s writes in its root and nothing saying the property is gone. That is exactly the hidden state ADR-0036 exists to abolish, reached by the mechanism meant to make failures visible. A restore that did not happen (ADR-0054) is worse again, because somebody asked for their data back and is about to act on the data they asked to be rid of. Both are bounded and given OnFailure = emergency.target: the boot stops, somebody looks, and the bootloader still offers the generation before.

5. Subprocesses on the seal path are bounded where they are spawned, at ten seconds each. The seal was documented as best-effort and never fatal, and that was only ever true of a tpm2_* call that failed. wait_with_output waits for ever, and a chip that accepts a command and does not answer is a keeper that never starts.

6. A test asks whether the boot finished, not whether a target was reached. Reaching multi-user.target says nothing about what is still trying to reach it, which is how a fifteen-minute hang in one unit read as a machine that would not boot at all. The lifecycle test now asks is-system-running, that the job list is empty, and that no failed unit’s name contains tacid — so the next failure of this shape names the unit in seconds.

Consequences

• Ordering means what it says. After= on a Tacid daemon now waits for its socket, which is what every use of it in this system was written believing.
• A hang anywhere on the boot path becomes a failed unit with a name, inside a bounded time, instead of a machine that is still trying. That is the whole of what was bought: none of these changes make anything faster, and none of them fix a cause. They convert silence into a place to look.
• The health gate can no longer bless a boot whose keeper has not opened its socket. It is After= the three daemons, and that ordering now waits for sockets rather than for processes, so the case where it reported tacidd.service is running about a wedged machine cannot recur. It closed as a consequence of the ordering fix rather than by being addressed, which is worth saying: it was found by reading a log for something else.
• The health gate can now fail for being slow, and a failed health gate is a generation rolled back. This is accepted deliberately: the alternative is a gate that hangs, which reaches the same rollback by way of the boot counter and says nothing on the way.
• Two units can now stop a boot dead at an emergency prompt. That is a real cost, taken because the alternative for those two is a machine that boots and lies about what it is.
• A daemon that binds its socket, says READY=1, and then wedges is still invisible to the manager. Type=notify moves the boundary; it does not remove it. What would close it is a watchdog — WatchdogSec with the daemon pinging from its accept loop — and that is not built.
• Reading for that case found a path into it that needs nothing to go wrong at all. The keeper’s runtime is current_thread, its dispatch is synchronous, and its stem client blocks with no timeout — so Keeper::collect, which generations.collect reaches and the weekly timer asks for, holds both the keeper’s lock and its only thread for as long as a store collection takes. For that time the keeper accepts no connection and answers nobody: not the daemon, not tacid approve, not a person at a console. Nothing is broken on such a machine, and systemd is right that the unit is active. That is a real defect and it is not this record’s to fix; it is written down here because it is the same sentence as the one above, reached from the other end.

Alternatives rejected

Raise the test driver’s timeout. The machines were not slow; one unit was stopped. A larger number would have turned a fifteen-minute failure into a thirty-minute one with the same diagnosis, which is none.

TimeoutStartSec alone, everywhere, including the initrd. It is the cheap version of this record and it is wrong in exactly two places, where a failed unit boots the machine anyway without the property the unit exists to provide.

Requires= from sysroot.mount onto the initrd units instead of OnFailure. It reaches the same end for tacid-fresh-root and inverts the ownership: the mount would then be declaring what Tacid needs, in a unit NixOS generates. OnFailure keeps the statement in the unit making it.

Link libsystemd for sd_notify. Fifteen lines of protocol against a C library, its transitive closure, and its presence in the initrd, on the trust path of four daemons. The datagram is written out and tested against a real socket.