From 004db23cca709aee390fa30e98f1ac0fd3689f31 Mon Sep 17 00:00:00 2001 From: EJ Campbell Date: Wed, 19 Aug 2026 08:20:22 -0700 Subject: [PATCH] test: run TEST-03-JOBS cycle starts at log level info 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. --- test/units/TEST-03-JOBS.sh | 51 +++++++++++++++++++++++++++++--------- 1 file changed, 39 insertions(+), 12 deletions(-) diff --git a/test/units/TEST-03-JOBS.sh b/test/units/TEST-03-JOBS.sh index 50089c1965..539c2b132d 100755 --- a/test/units/TEST-03-JOBS.sh +++ b/test/units/TEST-03-JOBS.sh @@ -8,6 +8,26 @@ set -o pipefail # shellcheck source=test/units/util.sh . "$(dirname "$0")"/util.sh +# Two subtests below change the log level (the transactions-with-cycles one to info, the +# RestartRandomizedDelaySec= one to debug) and restore it inline when they pass. On abort, +# the EXIT handler restores the boot-time level and cleans up the transient unit the +# aborting subtest had in flight, as in TEST-26-SYSTEMCTL.sh. +ORIG_LOG_LEVEL="$(systemctl log-level)" + +at_exit() { + set +e + + systemctl log-level "$ORIG_LOG_LEVEL" + + if [[ -v UNIT_NAME && -e /run/systemd/system/"$UNIT_NAME" ]]; then + systemctl stop "$UNIT_NAME" + rm -f /run/systemd/system/"$UNIT_NAME" + systemctl daemon-reload + fi +} + +trap at_exit EXIT + # Simple test for that daemon-reexec works in container. # See: https://github.com/systemd/systemd/pull/23883 systemctl daemon-reexec @@ -116,7 +136,22 @@ Requires=transaction-cycle$(((i + 1) % 20)).service ExecStart=true EOF done + +# The image boots with systemd.log_level=debug, so the daemon-reload and the 20 cyclic starts +# below make PID1 emit thousands of debug messages per second. Under that burst journald falls +# behind and PID1's journal socket sends time out after 10ms (src/basic/log.c). A timed-out +# message is either dropped outright, since log_struct() ignores the send result, or falls back +# to kmsg, where the structured TRANSACTION_ID= field is lost, so the TRANSACTION_ID= matches +# below cannot find it. Run this section at log level info instead: the asserted messages are +# emitted at err and warning (src/core/transaction.c) and are unaffected. +systemctl log-level info + systemctl daemon-reload + +# Let journald drain anything the preceding subtests already queued at debug level, so no +# earlier backlog is still competing with the messages asserted on below. +journalctl --sync + for i in {0..19}; do # This intentionally fails with: # Failed to start transaction-cycle0.service: Transaction order is cyclic. See system logs for details. @@ -125,6 +160,9 @@ done IDS_FILE="/tmp/TEST-03-JOBS-CYCLE-IDS-$RANDOM" varlinkctl call /run/systemd/io.systemd.Manager io.systemd.Manager.Describe '{}' | jq '.runtime.TransactionsWithOrderingCycle' >"$IDS_FILE" + +systemctl log-level "$ORIG_LOG_LEVEL" + [[ "$(jq length "$IDS_FILE")" -ge 20 ]] journalctl --sync for i in {0..19}; do @@ -259,17 +297,6 @@ assert_eq "$(systemctl show "$UNIT_NAME" -P RestartRandomizedDelayUSec)" "1s" # The chosen delay is logged at debug level when the unit enters auto-restart, so we can read it without # waiting for the delay to elapse. -PREV_LOG_LEVEL="$(systemctl log-level)" - -restart_randomized_delay_cleanup() { - set +e - systemctl log-level "$PREV_LOG_LEVEL" - systemctl stop "$UNIT_NAME" - rm -f /run/systemd/system/"$UNIT_NAME" - systemctl daemon-reload -} -trap restart_randomized_delay_cleanup EXIT - systemctl log-level debug get_restart_interval() { @@ -292,7 +319,7 @@ for _ in {1..4}; do DELAYS+=("$delay") done -systemctl log-level "$PREV_LOG_LEVEL" +systemctl log-level "$ORIG_LOG_LEVEL" : "Chosen randomized restart delays: ${DELAYS[*]} (totals: ${TOTALS[*]})" for delay in "${DELAYS[@]}"; do