The transactions-with-cycles subtest starts 20 mutually cyclic
services, reads the manager's TransactionsWithOrderingCycle ids over
varlink, and then requires a journal entry matching "cycle starting
with" for every id. On a fedora rawhide CI run the entry for
transaction id 42 was missing for the entire boot and journalctl
printed "-- No entries --", failing the unit, while the manager had
correctly recorded all 20 ids. In the exported journal of that boot,
transaction 42 kept only its debug-level enqueue line
transaction-cycle12.service: Trying to enqueue job
transaction-cycle12.service/start/replace
while the other 19 transactions each also kept the three messages
that follow it ("Found ordering cycle", "Unable to break cycle
starting with", "unfixable cyclic ordering dependency"), and PID1's
next message, accepted about 2 ms after the enqueue line, shows
journald itself kept ingesting.
The messages were lost, not late. The test VM boots with
systemd.log_level=debug, and the 20 cyclic starts made PID1 emit
about 12,400 debug messages within 30 seconds, 4,100 of them in the
final second, during which journald stalled for 94 ms between two
consecutive entries. PID1 gives its journal socket a 10 ms send
timeout (src/basic/log.c), and a message whose send times out is
either dropped outright, because log_struct() ignores the sendmsg
result and falls back only on formatting errors, or, for the plain
log calls that do fall back to kmsg, reappears as _TRANSPORT=kernel
text stripped of its structured fields, where a TRANSACTION_ID=
match cannot find it. The asserted messages are log_struct() calls,
so they are in the dropped class. Either way the journalctl
assertion comes up empty. This is also why the "journalctl --sync"
added in ed0727fecd does not help here: it only flushes what journald
already received.
Run the whole section, including the daemon-reload, at log level
info, and drain what the earlier subtests queued at debug level with
one "journalctl --sync" before the first start. The daemon-reload is
itself a heavy debug emitter that returns before journald has
drained its burst, so opening the quiet window after it would leave
that backlog competing with the first cycle messages. The two
messages the subtest greps for are emitted at LOG_ERR ("Unable to
break cycle starting with") and LOG_WARNING ("Job ... deleted to
break ordering cycle starting with") in src/core/transaction.c, and
the ids are recorded into transactions_with_cycle on the same code
path directly before them, so the assertion keeps its full strength
while the debug flood that displaced it is gone.
A single at_exit handler installed at the start of the test restores
the boot-time log level when any subtest aborts, and cleans up the
transient unit the aborting subtest had in flight, guarded on the
unit file existing as in TEST-26-SYSTEMCTL.sh. It replaces the
per-subtest restart_randomized_delay_cleanup() handler, so the two
subtests that change the log level share one restore path.
EJ Campbell
004db23cca