systemd
systemd copied to clipboard
Published
20 hours ago •
systemd
systemd
TEST-60-MOUNT-RATELIMIT occasionally fails during daemon-reexec in nspawn
systemd version the issue has been seen with
latest main
Used distribution
Arch Linux
Linux kernel version used
5.19.2-arch1-2
CPU architectures issue was seen on
No response
Component
No response
Expected behaviour you didn't see
No response
Unexpected behaviour you saw
In a couple of instances I noticed TEST-60 fail in a strange way when running in nspawn:
[ 1429.132180] H systemd[1]: Unmounting tmp-hoge.mount...
[ 1429.132894] H systemd[1]: tmp-hoge.mount: Deactivated successfully.
[ 1429.132995] H systemd[1]: Unmounted tmp-hoge.mount.
[ 1429.138308] H systemd[1]: Mounting tmp-hoge.mount...
[ 1429.211643] H systemd[1]: Mounted tmp-hoge.mount.
[ 1429.219430] H testsuite-60.sh[30]: + systemctl daemon-reexec
[ 1429.228060] H systemd[1]: Reexecuting.
[ 1429.345856] H testsuite-60.sh[30]: + sleep 1
[ 1430.348594] H testsuite-60.sh[344]: ++ systemctl is-failed tmp-hoge.mount
[ 1430.356990] H testsuite-60.sh[30]: + [[ active == \f\a\i\l\e\d ]]
[ 1430.357184] H testsuite-60.sh[30]: + journalctl -u tmp-hoge.mount -q --grep 'but there is no mount'
[ 1430.363253] H testsuite-60.sh[30]: + systemctl stop tmp-hoge.mount
[ 1430.372512] H systemd[1]: Unmounting tmp-hoge.mount...
[ 1430.374867] H systemd[1]: tmp-hoge.mount: Deactivated successfully.
[ 1430.375028] H systemd[1]: Unmounted tmp-hoge.mount.
[ 1430.378063] H testsuite-60.sh[30]: + (( i++ ))
[ 1430.378063] H testsuite-60.sh[30]: + (( i < 10 ))
[ 1430.378063] H testsuite-60.sh[30]: + systemctl --no-block start tmp-hoge.mount
[ 1430.388351] H systemd[1]: Mounting tmp-hoge.mount...
[ 1430.389520] H testsuite-60.sh[30]: + sleep .27798
[ 1430.669053] H testsuite-60.sh[30]: + systemctl daemon-reexec
[ 1430.677580] H systemd[1]: Mounted tmp-hoge.mount.
[ 1430.678540] H systemd[1]: Reexecuting.
[ 1430.782465] H testsuite-60.sh[30]: + sleep 1
[ 1430.788947] H systemd[1]: Reached target testsuite.target.
[ 1430.789334] H systemd[1]: Starting end.service...
[ 1430.790802] H sh[369]: + systemctl poweroff --no-block
[ 1430.795787] H systemd-logind[27]: The system will power off now!
[ 1430.796294] H systemd-logind[27]: System is powering down.
[ 1430.807180] H systemd[1]: multi-user.target: Found ordering cycle on testsuite.target/stop
[ 1430.807217] H systemd[1]: multi-user.target: Found dependency on end.service/stop
[ 1430.807251] H systemd[1]: multi-user.target: Found dependency on multi-user.target/stop
[ 1430.807289] H systemd[1]: multi-user.target: Job testsuite.target/stop deleted to break ordering cycle starting with multi-user.target/stop
[ 1430.814120] H systemd[1]: end.service: Deactivated successfully.
[ 1430.814260] H systemd[1]: Stopped end.service.
[ 1430.814756] H systemd[1]: Removed slice system-modprobe.slice.
[ 1430.815138] H systemd[1]: Stopped target cryptsetup.target.
[ 1430.815449] H systemd[1]: Stopped target getty.target.
[ 1430.815679] H systemd[1]: Stopped target integritysetup.target.
[ 1430.815981] H systemd[1]: Stopped target paths.target.
[ 1430.816085] H systemd[1]: systemd-ask-password-console.path: Deactivated successfully.
[ 1430.816266] H systemd[1]: Stopped systemd-ask-password-console.path.
[ 1430.816409] H systemd[1]: systemd-ask-password-wall.path: Deactivated successfully.
[ 1430.822846] H systemd[1]: Stopped systemd-ask-password-wall.path.
[ 1430.823195] H systemd[1]: Stopped target slices.target.
[ 1430.823506] H systemd[1]: Stopped target sockets.target.
[ 1430.823801] H systemd[1]: Stopped target timers.target.
[ 1430.823911] H systemd[1]: systemd-tmpfiles-clean.timer: Deactivated successfully.
[ 1430.824103] H systemd[1]: Stopped systemd-tmpfiles-clean.timer.
[ 1430.824420] H systemd[1]: Stopped target veritysetup.target.
[ 1430.824605] H systemd[1]: systemd-coredump.socket: Deactivated successfully.
[ 1430.824871] H systemd[1]: Closed systemd-coredump.socket.
[ 1430.825313] H systemd[1]: Stopping console-getty.service...
[ 1430.825611] H systemd[1]: Stopping dbus.service...
[ 1430.825685] H systemd[1]: Stopping systemd-logind.service...
[ 1430.826208] H systemd[1]: Stopping systemd-update-utmp.service...
[ 1430.827134] H systemd[1]: testsuite-60.service: Main process exited, code=killed, status=15/TERM
[ 1430.827179] H systemd[1]: testsuite-60.service: Failed with result 'signal'.
Journals:
Steps to reproduce the problem
No response
Additional program output to the terminal or log subsystem illustrating the issue
No response
Hmpf, this is strange, it looks like after daemon-reexec the testsuite.target is marked as reached, which then starts the end.service and shuts down the machine:
[ 2.712437] H systemd[322]: Successfully forked off '(direxec)' as PID 325.
...
[ 1552.717371] H testsuite-60.sh[30]: + (( i++ ))
[ 1552.717371] H testsuite-60.sh[30]: + (( i < 10 ))
[ 1552.717371] H testsuite-60.sh[30]: + systemctl --no-block start tmp-hoge.mount
...
[ 1552.767616] H testsuite-60.sh[30]: + sleep .13355
[ 1552.902819] H testsuite-60.sh[30]: + systemctl daemon-reexec
...
[ 1552.933601] H systemd[1]: Reexecuting.
[ 1552.950744] H systemd[1]: systemd-journald.service: Releasing resources.
[ 1552.950942] H systemd[1]: systemd-journald.service: Releasing all stored fds
[ 1553.006343] H systemd[1]: Bus bus-api-system: changing state RUNNING → CLOSED
[ 1553.006534] H systemd[1]: Bus private-bus-connection: changing state RUNNING → CLOSED
[ 1553.370118] H systemd[1]: Invoking unit catchup() handlers…
[ 1553.370583] H systemd[1]: Closing set fd 51
[ 1553.370786] H systemd[1]: Closing set fd 52
[ 1553.370989] H systemd[1]: Loaded units and determined initial transaction in 317ms.
[ 1553.371178] H systemd[1]: run-credentials.mount: Collecting.
[ 1553.371375] H systemd[1]: run-systemd-coredump.mount: Collecting.
[ 1553.371570] H systemd[1]: run-initctl.mount: Collecting.
[ 1553.371771] H systemd[1]: run-systemd-journal-dev\x2dlog.mount: Collecting.
[ 1553.371970] H systemd[1]: run-systemd-journal-syslog.mount: Collecting.
[ 1553.372169] H systemd[1]: dev.mount: Collecting.
[ 1553.372363] H systemd[1]: sys-fs.mount: Collecting.
[ 1553.372557] H systemd[1]: sys-fs-fuse.mount: Collecting.
[ 1553.372754] H systemd[1]: sys.mount: Collecting.
[ 1553.372948] H systemd[1]: sys-kernel.mount: Collecting.
[ 1553.373141] H systemd[1]: proc.mount: Collecting.
[ 1553.373337] H systemd[1]: proc-sys.mount: Collecting.
[ 1553.373532] H systemd[1]: proc-sys-fs.mount: Collecting.
[ 1553.373741] H systemd[1]: run-systemd-ask\x2dpassword.mount: Collecting.
[ 1553.373936] H systemd[1]: run-dbus.mount: Collecting.
[ 1553.374130] H systemd[1]: run-dbus-system_bus_socket.mount: Collecting.
[ 1553.374325] H systemd[1]: run-systemd-seats.mount: Collecting.
[ 1553.374525] H systemd[1]: run-systemd-users.mount: Collecting.
[ 1553.374725] H systemd[1]: var-lib-systemd-linger.mount: Collecting.
[ 1553.374923] H systemd[1]: var-tmp.mount: Collecting.
[ 1553.375117] H systemd[1]: run-systemd-sessions.mount: Collecting.
[ 1553.375310] H systemd[1]: run-systemd-shutdown.mount: Collecting.
[ 1553.375503] H systemd[1]: run-systemd-inhibit.mount: Collecting.
[ 1553.375708] H systemd[1]: var-lib-machines.raw.mount: Collecting.
[ 1553.375902] H systemd[1]: var-log-journal.mount: Collecting.
[ 1553.376095] H systemd[1]: var-lib.mount: Collecting.
[ 1553.376288] H systemd[1]: var-lib-systemd.mount: Collecting.
[ 1553.376483] H systemd[1]: var-lib-systemd-random\x2dseed.mount: Collecting.
[ 1553.376684] H systemd[1]: run-udev.mount: Collecting.
[ 1553.376881] H systemd[1]: run-udev-control.mount: Collecting.
[ 1553.377083] H systemd[1]: var.mount: Collecting.
[ 1553.377278] H systemd[1]: var-log.mount: Collecting.
[ 1553.377472] H systemd[1]: var-log-wtmp.mount: Collecting.
[ 1553.377670] H systemd[1]: run-systemd-journal-socket.mount: Collecting.
[ 1553.377865] H systemd[1]: run.mount: Collecting.
[ 1553.378063] H systemd[1]: run-systemd.mount: Collecting.
[ 1553.378263] H systemd[1]: run-systemd-journal.mount: Collecting.
[ 1553.378457] H systemd[1]: run-systemd-journal-stdout.mount: Collecting.
[ 1553.386384] H systemd[1]: systemd-logind.service: unit configures an IP firewall, but the local system does not support BPF/cgroup firewalling.
[ 1553.386584] H systemd[1]: (This warning is only shown for the first unit using IP firewalling.)
[ 1553.386785] H testsuite-60.sh[30]: + sleep 1
[ 1553.392914] H sh[340]: + systemctl poweroff --no-block
[ 1553.405008] H systemd[1]: Received SIGCHLD from PID 325 (n/a).
[ 1553.408169] H systemd[1]: testsuite.target changed dead -> active
[ 1553.408364] H systemd[1]: testsuite.target: Job 1 testsuite.target/start finished, result=done
[ 1553.408571] H systemd[1]: Reached target testsuite.target.
[ 1553.409219] H systemd[1]: end.service: Will spawn child (service_enter_start): /bin/sh
[ 1553.409429] H systemd[1]: end.service: Passing 0 fds to service
[ 1553.409629] H systemd[1]: end.service: About to execute /bin/sh -x -c "systemctl poweroff --no-block"
[ 1553.409852] H systemd[1]: end.service: Forked /bin/sh as 340
[ 1553.410476] H systemd[1]: end.service: Changed dead -> start
[ 1553.410687] H systemd[1]: Starting end.service...
[ 1553.411721] H systemd[340]: end.service: Kernel keyring access prohibited, ignoring.
[ 1553.411908] H systemd[340]: end.service: Executing: /bin/sh -x -c "systemctl poweroff --no-block"
[ 1553.412084] H systemd[1]: systemd-journald.service: Got notification message from PID 18 (FDSTORE=1)
[ 1553.412281] H systemd[1]: systemd-journald.service: Added fd 4 (n/a) to fd store.
[ 1553.412476] H systemd-logind[27]: The system will power off now!
[ 1553.413243] H systemd-logind[27]: System is powering down.
[ 1553.414127] H systemd[1]: poweroff.target: Trying to enqueue job poweroff.target/start/replace-irreversibly
[ 1553.414325] H systemd[1]: Added job poweroff.target/start to transaction.
[ 1553.414519] H systemd[1]: Pulling in systemd-poweroff.service/start from poweroff.target/start
[ 1553.414718] H systemd[1]: Added job systemd-poweroff.service/start to transaction.
[ 1553.414925] H systemd[1]: Pulling in system.slice/start from systemd-poweroff.service/start
[ 1553.415111] H systemd[1]: Added job system.slice/start to transaction.
[ 1553.415292] H systemd[1]: Pulling in -.slice/start from system.slice/start
[ 1553.415475] H systemd[1]: Added job -.slice/start to transaction.
[ 1553.415656] H systemd[1]: Pulling in final.target/start from systemd-poweroff.service/start
[ 1553.415869] H systemd[1]: Added job final.target/start to transaction.
[ 1553.416060] H systemd[1]: Pulling in shutdown.target/start from systemd-poweroff.service/start
[ 1553.416255] H systemd[1]: Added job shutdown.target/start to transaction.
[ 1553.416444] H systemd[1]: Pulling in systemd-sysusers.service/stop from shutdown.target/start
[ 1553.416635] H systemd[1]: Added job systemd-sysusers.service/stop to transaction.
[ 1553.416830] H systemd[1]: Pulling in initrd-usr-fs.target/stop from shutdown.target/start
[ 1553.417029] H systemd[1]: Added job initrd-usr-fs.target/stop to transaction.
[ 1553.417239] H systemd[1]: Pulling in multi-user.target/stop from shutdown.target/start
[ 1553.417436] H systemd[1]: Added job multi-user.target/stop to transaction.
[ 1553.417627] H systemd[1]: Pulling in graphical.target/stop from multi-user.target/stop
[ 1553.417826] H systemd[1]: Added job graphical.target/stop to transaction.
[ 1553.418041] H systemd[1]: Pulling in testsuite.target/stop from multi-user.target/stop
[ 1553.418235] H systemd[1]: Added job testsuite.target/stop to transaction.
[ 1553.418425] H systemd[1]: Pulling in systemd-tmpfiles-clean.service/stop from shutdown.target/start
[ 1553.418617] H systemd[1]: Added job systemd-tmpfiles-clean.service/stop to transaction.
[ 1553.418815] H systemd[1]: Pulling in timers.target/stop from shutdown.target/start
[ 1553.419010] H systemd[1]: Added job timers.target/stop to transaction.
[ 1553.419202] H systemd[1]: Pulling in systemd-repart.service/stop from shutdown.target/start
[ 1553.419394] H systemd[1]: Added job systemd-repart.service/stop to transaction.
[ 1553.419585] H systemd[1]: Pulling in initrd-fs.target/stop from shutdown.target/start
[ 1553.419783] H systemd[1]: Added job initrd-fs.target/stop to transaction.
[ 1553.419973] H systemd[1]: Pulling in systemd-update-utmp.service/stop from shutdown.target/start
[ 1553.420167] H systemd[1]: Added job systemd-update-utmp.service/stop to transaction.
[ 1553.420368] H systemd[1]: Pulling in systemd-update-utmp-runlevel.service/stop from systemd-update-utmp.service/stop
[ 1553.420563] H systemd[1]: Added job systemd-update-utmp-runlevel.service/stop to transaction.
[ 1553.420765] H systemd[1]: Pulling in systemd-tmpfiles-setup.service/stop from shutdown.target/start
[ 1553.420961] H systemd[1]: Added job systemd-tmpfiles-setup.service/stop to transaction.
[ 1553.421153] H systemd[1]: Pulling in systemd-ask-password-console.service/stop from shutdown.target/start
[ 1553.421346] H systemd[1]: Added job systemd-ask-password-console.service/stop to transaction.
[ 1553.421546] H systemd[1]: Pulling in sockets.target/stop from shutdown.target/start
[ 1553.421740] H systemd[1]: Added job sockets.target/stop to transaction.
[ 1553.421926] H systemd[1]: Pulling in end.service/stop from shutdown.target/start
[ 1553.422111] H systemd[1]: Added job end.service/stop to transaction.
[ 1553.422296] H systemd[1]: Pulling in basic.target/stop from shutdown.target/start
[ 1553.422482] H systemd[1]: Added job basic.target/stop to transaction.
[ 1553.422673] H systemd[1]: Pulling in initrd.target/stop from basic.target/stop
[ 1553.422863] H systemd[1]: Added job initrd.target/stop to transaction.
[ 1553.423050] H systemd[1]: Pulling in multi-user.target/stop from basic.target/stop
[ 1553.423236] H systemd[1]: Pulling in systemd-tmpfiles-clean.timer/stop from shutdown.target/start
[ 1553.423423] H systemd[1]: Added job systemd-tmpfiles-clean.timer/stop to transaction.
[ 1553.423609] H systemd[1]: Pulling in dbus.service/stop from shutdown.target/start
[ 1553.423827] H systemd[1]: Added job dbus.service/stop to transaction.
[ 1553.424023] H systemd[1]: Pulling in network.target/stop from shutdown.target/start
[ 1553.424214] H systemd[1]: Added job network.target/stop to transaction.
[ 1553.424407] H systemd[1]: Pulling in paths.target/stop from shutdown.target/start
[ 1553.424598] H systemd[1]: Added job paths.target/stop to transaction.
[ 1553.424806] H systemd[1]: Pulling in systemd-coredump.socket/stop from shutdown.target/start
[ 1553.424995] H systemd[1]: Added job systemd-coredump.socket/stop to transaction.
[ 1553.425184] H systemd[1]: Pulling in getty.target/stop from shutdown.target/start
[ 1553.425372] H systemd[1]: Added job getty.target/stop to transaction.
[ 1553.425556] H systemd[1]: Pulling in cryptsetup.target/stop from shutdown.target/start
[ 1553.425751] H systemd[1]: Added job cryptsetup.target/stop to transaction.
[ 1553.425937] H systemd[1]: Pulling in rescue.service/stop from shutdown.target/start
[ 1553.426124] H systemd[1]: Added job rescue.service/stop to transaction.
[ 1553.426312] H systemd[1]: Pulling in rescue.target/stop from rescue.service/stop
[ 1553.426500] H systemd[1]: Added job rescue.target/stop to transaction.
[ 1553.426694] H systemd[1]: Pulling in systemd-update-done.service/stop from shutdown.target/start
[ 1553.426901] H systemd[1]: Added job systemd-update-done.service/stop to transaction.
[ 1553.427099] H systemd[1]: Pulling in remote-fs-pre.target/stop from shutdown.target/start
[ 1553.427292] H systemd[1]: Added job remote-fs-pre.target/stop to transaction.
[ 1553.427487] H systemd[1]: Pulling in initrd-root-fs.target/stop from shutdown.target/start
[ 1553.427686] H systemd[1]: Added job initrd-root-fs.target/stop to transaction.
[ 1553.427877] H systemd[1]: Pulling in initrd-parse-etc.service/stop from initrd-root-fs.target/stop
[ 1553.428069] H systemd[1]: Added job initrd-parse-etc.service/stop to transaction.
[ 1553.428269] H systemd[1]: Pulling in network-pre.target/stop from shutdown.target/start
[ 1553.428456] H systemd[1]: Added job network-pre.target/stop to transaction.
[ 1553.428645] H systemd[1]: Pulling in veritysetup.target/stop from shutdown.target/start
[ 1553.428841] H systemd[1]: Added job veritysetup.target/stop to transaction.
[ 1553.429026] H systemd[1]: Pulling in veritysetup-pre.target/stop from shutdown.target/start
[ 1553.429212] H systemd[1]: Added job veritysetup-pre.target/stop to transaction.
[ 1553.429398] H systemd[1]: Pulling in local-fs.target/stop from shutdown.target/start
[ 1553.429584] H systemd[1]: Added job local-fs.target/stop to transaction.
[ 1553.429779] H systemd[1]: Pulling in remote-fs.target/stop from shutdown.target/start
[ 1553.429965] H systemd[1]: Added job remote-fs.target/stop to transaction.
[ 1553.430170] H systemd[1]: Pulling in systemd-ask-password-console.path/stop from shutdown.target/start
[ 1553.430455] H systemd[1]: Added job systemd-ask-password-console.path/stop to transaction.
[ 1553.430647] H systemd[1]: Pulling in systemd-ask-password-wall.service/stop from shutdown.target/start
[ 1553.430847] H systemd[1]: Added job systemd-ask-password-wall.service/stop to transaction.
[ 1553.431045] H systemd[1]: Pulling in ldconfig.service/stop from shutdown.target/start
[ 1553.431236] H systemd[1]: Added job ldconfig.service/stop to transaction.
[ 1553.431427] H systemd[1]: Pulling in proc-sys-fs-binfmt_misc.automount/stop from shutdown.target/start
[ 1553.431619] H systemd[1]: Added job proc-sys-fs-binfmt_misc.automount/stop to transaction.
[ 1553.431815] H systemd[1]: Pulling in integritysetup.target/stop from shutdown.target/start
[ 1553.432010] H systemd[1]: Added job integritysetup.target/stop to transaction.
[ 1553.432205] H systemd[1]: Pulling in systemd-fsck-root.service/stop from shutdown.target/start
[ 1553.432396] H systemd[1]: Added job systemd-fsck-root.service/stop to transaction.
[ 1553.432602] H systemd[1]: Pulling in testsuite.target/stop from shutdown.target/start
[ 1553.432793] H systemd[1]: Pulling in initrd.target/stop from shutdown.target/start
[ 1553.432979] H systemd[1]: Pulling in initrd-root-device.target/stop from shutdown.target/start
[ 1553.433166] H systemd[1]: Added job initrd-root-device.target/stop to transaction.
[ 1553.433357] H systemd[1]: Pulling in systemd-sysctl.service/stop from shutdown.target/start
[ 1553.433564] H systemd[1]: Added job systemd-sysctl.service/stop to transaction.
[ 1553.433791] H systemd[1]: Pulling in system-modprobe.slice/stop from shutdown.target/start
[ 1553.433985] H systemd[1]: Added job system-modprobe.slice/stop to transaction.
[ 1553.434176] H systemd[1]: Pulling in [email protected]/stop from system-modprobe.slice/stop
[ 1553.434368] H systemd[1]: Added job [email protected]/stop to transaction.
[ 1553.434564] H systemd[1]: Pulling in [email protected]/stop from system-modprobe.slice/stop
[ 1553.434762] H systemd[1]: Added job [email protected]/stop to transaction.
[ 1553.434965] H systemd[1]: Pulling in sys-kernel-config.mount/stop from [email protected]/stop
[ 1553.435152] H systemd[1]: Added job sys-kernel-config.mount/stop to transaction.
[ 1553.435338] H systemd[1]: Pulling in [email protected]/stop from system-modprobe.slice/stop
[ 1553.435530] H systemd[1]: Added job [email protected]/stop to transaction.
[ 1553.435723] H systemd[1]: Pulling in sys-fs-fuse-connections.mount/stop from [email protected]/stop
[ 1553.435910] H systemd[1]: Added job sys-fs-fuse-connections.mount/stop to transaction.
[ 1553.436097] H systemd[1]: Pulling in cryptsetup-pre.target/stop from shutdown.target/start
[ 1553.436284] H systemd[1]: Added job cryptsetup-pre.target/stop to transaction.
[ 1553.436470] H systemd[1]: Pulling in systemd-random-seed.service/stop from shutdown.target/start
[ 1553.436665] H systemd[1]: Added job systemd-random-seed.service/stop to transaction.
[ 1553.436851] H systemd[1]: Pulling in rc-local.service/stop from shutdown.target/start
[ 1553.437065] H systemd[1]: Added job rc-local.service/stop to transaction.
[ 1553.437258] H systemd[1]: Pulling in rescue.target/stop from shutdown.target/start
[ 1553.437450] H systemd[1]: Pulling in dbus.socket/stop from shutdown.target/start
[ 1553.437648] H systemd[1]: Added job dbus.socket/stop to transaction.
[ 1553.437848] H systemd[1]: Pulling in systemd-logind.service/stop from dbus.socket/stop
[ 1553.438041] H systemd[1]: Added job systemd-logind.service/stop to transaction.
[ 1553.438235] H systemd[1]: Pulling in dbus.service/stop from dbus.socket/stop
[ 1553.438428] H systemd[1]: Pulling in local-fs-pre.target/stop from shutdown.target/start
[ 1553.438619] H systemd[1]: Added job local-fs-pre.target/stop to transaction.
[ 1553.438816] H systemd[1]: Pulling in first-boot-complete.target/stop from shutdown.target/start
[ 1553.439025] H systemd[1]: Added job first-boot-complete.target/stop to transaction.
[ 1553.439217] H systemd[1]: Pulling in slices.target/stop from shutdown.target/start
[ 1553.439409] H systemd[1]: Added job slices.target/stop to transaction.
[ 1553.439600] H systemd[1]: Pulling in time-set.target/stop from shutdown.target/start
[ 1553.439797] H systemd[1]: Added job time-set.target/stop to transaction.
[ 1553.439991] H systemd[1]: Pulling in graphical.target/stop from shutdown.target/start
[ 1553.440188] H systemd[1]: Pulling in nss-user-lookup.target/stop from shutdown.target/start
[ 1553.440455] H systemd[1]: Added job nss-user-lookup.target/stop to transaction.
[ 1553.440649] H systemd[1]: Pulling in systemd-user-sessions.service/stop from shutdown.target/start
[ 1553.440848] H systemd[1]: Added job systemd-user-sessions.service/stop to transaction.
[ 1553.441041] H systemd[1]: Pulling in emergency.target/stop from shutdown.target/start
[ 1553.441232] H systemd[1]: Added job emergency.target/stop to transaction.
[ 1553.441429] H systemd[1]: Pulling in systemd-machine-id-commit.service/stop from shutdown.target/start
[ 1553.441624] H systemd[1]: Added job systemd-machine-id-commit.service/stop to transaction.
[ 1553.441819] H systemd[1]: Pulling in systemd-tmpfiles-setup-dev.service/stop from shutdown.target/start
[ 1553.442013] H systemd[1]: Added job systemd-tmpfiles-setup-dev.service/stop to transaction.
[ 1553.442207] H systemd[1]: Pulling in swap.target/stop from shutdown.target/start
[ 1553.442398] H systemd[1]: Added job swap.target/stop to transaction.
[ 1553.442596] H systemd[1]: Pulling in emergency.service/stop from shutdown.target/start
[ 1553.442793] H systemd[1]: Added job emergency.service/stop to transaction.
[ 1553.442986] H systemd[1]: Pulling in emergency.target/stop from emergency.service/stop
[ 1553.443177] H systemd[1]: Pulling in syslog.socket/stop from shutdown.target/start
[ 1553.443370] H systemd[1]: Added job syslog.socket/stop to transaction.
[ 1553.443561] H systemd[1]: Pulling in systemd-logind.service/stop from shutdown.target/start
[ 1553.443780] H systemd[1]: Pulling in systemd-boot-system-token.service/stop from shutdown.target/start
[ 1553.443973] H systemd[1]: Added job systemd-boot-system-token.service/stop to transaction.
[ 1553.444164] H systemd[1]: Pulling in sysinit.target/stop from shutdown.target/start
[ 1553.444355] H systemd[1]: Added job sysinit.target/stop to transaction.
[ 1553.444549] H systemd[1]: Pulling in basic.target/stop from sysinit.target/stop
[ 1553.444747] H systemd[1]: Pulling in console-getty.service/stop from sysinit.target/stop
[ 1553.444943] H systemd[1]: Added job console-getty.service/stop to transaction.
[ 1553.445134] H systemd[1]: Pulling in systemd-tmpfiles-clean.timer/stop from sysinit.target/stop
[ 1553.445373] H systemd[1]: Pulling in systemd-user-sessions.service/stop from sysinit.target/stop
[ 1553.445568] H systemd[1]: Pulling in rc-local.service/stop from sysinit.target/stop
[ 1553.445775] H systemd[1]: Pulling in dbus.socket/stop from sysinit.target/stop
[ 1553.445968] H systemd[1]: Pulling in dbus.service/stop from sysinit.target/stop
[ 1553.446164] H systemd[1]: Pulling in rescue.target/stop from sysinit.target/stop
[ 1553.446357] H systemd[1]: Pulling in testsuite-60.service/stop from sysinit.target/stop
[ 1553.446550] H systemd[1]: Added job testsuite-60.service/stop to transaction.
[ 1553.446747] H systemd[1]: Pulling in systemd-logind.service/stop from sysinit.target/stop
[ 1553.446942] H systemd[1]: Pulling in end.service/stop from sysinit.target/stop
[ 1553.447143] H systemd[1]: Pulling in systemd-ask-password-wall.service/stop from sysinit.target/stop
[ 1553.447344] H systemd[1]: Pulling in remote-cryptsetup.target/stop from shutdown.target/start
[ 1553.447538] H systemd[1]: Added job remote-cryptsetup.target/stop to transaction.
[ 1553.447735] H systemd[1]: Pulling in systemd-ask-password-wall.path/stop from shutdown.target/start
[ 1553.447928] H systemd[1]: Added job systemd-ask-password-wall.path/stop to transaction.
[ 1553.448121] H systemd[1]: Pulling in testsuite-60.service/stop from shutdown.target/start
[ 1553.448316] H systemd[1]: Pulling in systemd-binfmt.service/stop from shutdown.target/start
[ 1553.448567] H systemd[1]: Added job systemd-binfmt.service/stop to transaction.
[ 1553.448764] H systemd[1]: Pulling in systemd-update-utmp-runlevel.service/stop from shutdown.target/start
[ 1553.448959] H systemd[1]: Pulling in remote-veritysetup.target/stop from shutdown.target/start
[ 1553.449152] H systemd[1]: Added job remote-veritysetup.target/stop to transaction.
[ 1553.449343] H systemd[1]: Pulling in getty-pre.target/stop from shutdown.target/start
[ 1553.449537] H systemd[1]: Added job getty-pre.target/stop to transaction.
[ 1553.449737] H systemd[1]: Pulling in systemd-modules-load.service/stop from shutdown.target/start
[ 1553.449930] H systemd[1]: Added job systemd-modules-load.service/stop to transaction.
[ 1553.450121] H systemd[1]: Pulling in user.slice/stop from shutdown.target/start
[ 1553.450396] H systemd[1]: Added job user.slice/stop to transaction.
[ 1553.450589] H systemd[1]: Pulling in systemd-firstboot.service/stop from shutdown.target/start
[ 1553.450790] H systemd[1]: Added job systemd-firstboot.service/stop to transaction.
[ 1553.450991] H systemd[1]: Pulling in systemd-remount-fs.service/stop from shutdown.target/start
[ 1553.451186] H systemd[1]: Added job systemd-remount-fs.service/stop to transaction.
[ 1553.451379] H systemd[1]: Pulling in console-getty.service/stop from shutdown.target/start
[ 1553.451571] H systemd[1]: Pulling in umount.target/start from systemd-poweroff.service/start
[ 1553.451771] H systemd[1]: Added job umount.target/start to transaction.
[ 1553.451966] H systemd[1]: Pulling in tmp.mount/stop from umount.target/start
[ 1553.452158] H systemd[1]: Added job tmp.mount/stop to transaction.
[ 1553.452376] H systemd[1]: Pulling in tmp-hoge.mount/stop from tmp.mount/stop
[ 1553.452571] H systemd[1]: Added job tmp-hoge.mount/stop to transaction.
[ 1553.452772] H systemd[1]: Pulling in var-lib-machines.mount/stop from umount.target/start
[ 1553.452965] H systemd[1]: Added job var-lib-machines.mount/stop to transaction.
[ 1553.453156] H systemd[1]: Pulling in run-credentials-systemd\x2dtmpfiles\x2dsetup.service.mount/stop from umount.target/start
[ 1553.453360] H systemd[1]: Added job run-credentials-systemd\x2dtmpfiles\x2dsetup.service.mount/stop to transaction.
[ 1553.453568] H systemd[1]: Pulling in run-credentials-systemd\x2dtmpfiles\x2dsetup\x2ddev.service.mount/stop from umount.target/start
[ 1553.453785] H systemd[1]: Added job run-credentials-systemd\x2dtmpfiles\x2dsetup\x2ddev.service.mount/stop to transaction.
[ 1553.453979] H systemd[1]: Pulling in tmp-hoge.mount/stop from umount.target/start
[ 1553.454172] H systemd[1]: Found redundant job time-set.target/stop, dropping from transaction.
[ 1553.454362] H systemd[1]: Found redundant job cryptsetup-pre.target/stop, dropping from transaction.
[ 1553.454561] H systemd[1]: Found redundant job -.slice/start, dropping from transaction.
[ 1553.454756] H systemd[1]: Found redundant job proc-sys-fs-binfmt_misc.automount/stop, dropping from transaction.
[ 1553.454947] H systemd[1]: Found redundant job systemd-firstboot.service/stop, dropping from transaction.
[ 1553.455138] H systemd[1]: Found redundant job first-boot-complete.target/stop, dropping from transaction.
[ 1553.455332] H systemd[1]: Found redundant job sys-kernel-config.mount/stop, dropping from transaction.
[ 1553.455531] H systemd[1]: Found redundant job systemd-fsck-root.service/stop, dropping from transaction.
[ 1553.455727] H systemd[1]: Found redundant job [email protected]/stop, dropping from transaction.
[ 1553.455912] H systemd[1]: Found redundant job systemd-update-utmp-runlevel.service/stop, dropping from transaction.
[ 1553.456098] H systemd[1]: Found redundant job systemd-random-seed.service/stop, dropping from transaction.
[ 1553.456283] H systemd[1]: Found redundant job initrd-fs.target/stop, dropping from transaction.
[ 1553.456468] H systemd[1]: Found redundant job systemd-ask-password-console.service/stop, dropping from transaction.
[ 1553.456664] H systemd[1]: Found redundant job syslog.socket/stop, dropping from transaction.
[ 1553.456868] H systemd[1]: Found redundant job nss-user-lookup.target/stop, dropping from transaction.
[ 1553.457066] H systemd[1]: Found redundant job emergency.service/stop, dropping from transaction.
[ 1553.457262] H systemd[1]: Found redundant job system.slice/start, dropping from transaction.
[ 1553.457455] H systemd[1]: Found redundant job [email protected]/stop, dropping from transaction.
[ 1553.457649] H systemd[1]: Found redundant job remote-fs-pre.target/stop, dropping from transaction.
[ 1553.457846] H systemd[1]: Found redundant job initrd-usr-fs.target/stop, dropping from transaction.
[ 1553.458042] H systemd[1]: Found redundant job rescue.service/stop, dropping from transaction.
[ 1553.458244] H systemd[1]: Found redundant job systemd-machine-id-commit.service/stop, dropping from transaction.
[ 1553.458432] H systemd[1]: Found redundant job systemd-modules-load.service/stop, dropping from transaction.
[ 1553.458623] H systemd[1]: Found redundant job initrd-parse-etc.service/stop, dropping from transaction.
[ 1553.458815] H systemd[1]: Found redundant job initrd-root-fs.target/stop, dropping from transaction.
[ 1553.459002] H systemd[1]: Found redundant job systemd-sysctl.service/stop, dropping from transaction.
[ 1553.459189] H systemd[1]: Found redundant job graphical.target/stop, dropping from transaction.
[ 1553.459374] H systemd[1]: Found redundant job rescue.target/stop, dropping from transaction.
[ 1553.459561] H systemd[1]: Found redundant job systemd-boot-system-token.service/stop, dropping from transaction.
[ 1553.459757] H systemd[1]: Found redundant job systemd-update-done.service/stop, dropping from transaction.
[ 1553.459946] H systemd[1]: Found redundant job initrd.target/stop, dropping from transaction.
[ 1553.460148] H systemd[1]: Found redundant job var-lib-machines.mount/stop, dropping from transaction.
[ 1553.460346] H systemd[1]: Found redundant job systemd-repart.service/stop, dropping from transaction.
[ 1553.460540] H systemd[1]: Found redundant job systemd-ask-password-wall.service/stop, dropping from transaction.
[ 1553.460739] H systemd[1]: Found redundant job emergency.target/stop, dropping from transaction.
[ 1553.460953] H systemd[1]: Found redundant job initrd-root-device.target/stop, dropping from transaction.
[ 1553.461147] H systemd[1]: Found redundant job [email protected]/stop, dropping from transaction.
[ 1553.461350] H systemd[1]: Found redundant job ldconfig.service/stop, dropping from transaction.
[ 1553.461542] H systemd[1]: Found redundant job remote-cryptsetup.target/stop, dropping from transaction.
[ 1553.461751] H systemd[1]: Found redundant job rc-local.service/stop, dropping from transaction.
[ 1553.461944] H systemd[1]: Found redundant job systemd-tmpfiles-clean.service/stop, dropping from transaction.
[ 1553.462147] H systemd[1]: Found redundant job network-pre.target/stop, dropping from transaction.
[ 1553.462339] H systemd[1]: Found redundant job network.target/stop, dropping from transaction.
[ 1553.462532] H systemd[1]: Found redundant job remote-veritysetup.target/stop, dropping from transaction.
[ 1553.462731] H systemd[1]: Found redundant job systemd-binfmt.service/stop, dropping from transaction.
[ 1553.462924] H systemd[1]: Found redundant job systemd-sysusers.service/stop, dropping from transaction.
[ 1553.463121] H systemd[1]: Found redundant job remote-fs.target/stop, dropping from transaction.
[ 1553.463312] H systemd[1]: Found redundant job veritysetup-pre.target/stop, dropping from transaction.
[ 1553.463530] H systemd[1]: Found redundant job getty-pre.target/stop, dropping from transaction.
[ 1553.463769] H systemd[1]: Keeping job umount.target/start because of systemd-poweroff.service/start
[ 1553.463966] H systemd[1]: Keeping job integritysetup.target/stop because of shutdown.target/start
[ 1553.464159] H systemd[1]: Keeping job systemd-poweroff.service/start because of poweroff.target/start
[ 1553.464365] H systemd[1]: Keeping job getty.target/stop because of shutdown.target/start
[ 1553.464555] H systemd[1]: Garbage collecting job sys-fs-fuse-connections.mount/stop
[ 1553.464754] H systemd[1]: Keeping job umount.target/start because of systemd-poweroff.service/start
[ 1553.464943] H systemd[1]: Keeping job integritysetup.target/stop because of shutdown.target/start
[ 1553.465133] H systemd[1]: Keeping job systemd-poweroff.service/start because of poweroff.target/start
[ 1553.465323] H systemd[1]: Keeping job getty.target/stop because of shutdown.target/start
[ 1553.465514] H systemd[1]: Keeping job slices.target/stop because of shutdown.target/start
[ 1553.465710] H systemd[1]: Keeping job tmp-hoge.mount/stop because of umount.target/start
[ 1553.465900] H systemd[1]: Keeping job multi-user.target/stop because of basic.target/stop
[ 1553.466090] H systemd[1]: Keeping job end.service/stop because of sysinit.target/stop
[ 1553.466279] H systemd[1]: Keeping job dbus.socket/stop because of sysinit.target/stop
[ 1553.466483] H systemd[1]: Keeping job console-getty.service/stop because of shutdown.target/start
[ 1553.466685] H systemd[1]: Keeping job local-fs.target/stop because of shutdown.target/start
[ 1553.466876] H systemd[1]: Keeping job sysinit.target/stop because of shutdown.target/start
[ 1553.467105] H systemd[1]: Keeping job systemd-user-sessions.service/stop because of sysinit.target/stop
[ 1553.467298] H systemd[1]: Keeping job sockets.target/stop because of shutdown.target/start
[ 1553.467488] H systemd[1]: Keeping job cryptsetup.target/stop because of shutdown.target/start
[ 1553.467685] H systemd[1]: Keeping job systemd-tmpfiles-setup-dev.service/stop because of shutdown.target/start
[ 1553.467877] H systemd[1]: Keeping job systemd-tmpfiles-clean.timer/stop because of sysinit.target/stop
[ 1553.468071] H systemd[1]: Keeping job testsuite-60.service/stop because of shutdown.target/start
[ 1553.468275] H systemd[1]: Keeping job tmp.mount/stop because of umount.target/start
[ 1553.468462] H systemd[1]: Keeping job systemd-tmpfiles-setup.service/stop because of shutdown.target/start
[ 1553.468649] H systemd[1]: Keeping job run-credentials-systemd\x2dtmpfiles\x2dsetup.service.mount/stop because of umount.target/start
[ 1553.468851] H systemd[1]: Keeping job paths.target/stop because of shutdown.target/start
[ 1553.469038] H systemd[1]: Keeping job run-credentials-systemd\x2dtmpfiles\x2dsetup\x2ddev.service.mount/stop because of umount.target/start
[ 1553.469234] H systemd[1]: Keeping job final.target/start because of systemd-poweroff.service/start
[ 1553.469421] H systemd[1]: Keeping job systemd-update-utmp.service/stop because of shutdown.target/start
[ 1553.469608] H systemd[1]: Keeping job systemd-ask-password-wall.path/stop because of shutdown.target/start
[ 1553.469800] H systemd[1]: Keeping job system-modprobe.slice/stop because of shutdown.target/start
[ 1553.469987] H systemd[1]: Keeping job systemd-coredump.socket/stop because of shutdown.target/start
[ 1553.470173] H systemd[1]: Keeping job systemd-ask-password-console.path/stop because of shutdown.target/start
[ 1553.470387] H systemd[1]: Keeping job systemd-remount-fs.service/stop because of shutdown.target/start
[ 1553.470580] H systemd[1]: Keeping job local-fs-pre.target/stop because of shutdown.target/start
[ 1553.470780] H systemd[1]: Keeping job systemd-logind.service/stop because of sysinit.target/stop
[ 1553.470971] H systemd[1]: Keeping job user.slice/stop because of shutdown.target/start
[ 1553.471164] H systemd[1]: Keeping job dbus.service/stop because of sysinit.target/stop
[ 1553.471357] H systemd[1]: Keeping job basic.target/stop because of sysinit.target/stop
[ 1553.471565] H systemd[1]: Keeping job timers.target/stop because of shutdown.target/start
[ 1553.471760] H systemd[1]: Keeping job swap.target/stop because of shutdown.target/start
[ 1553.471947] H systemd[1]: Keeping job veritysetup.target/stop because of shutdown.target/start
[ 1553.472156] H systemd[1]: Keeping job shutdown.target/start because of systemd-poweroff.service/start
[ 1553.472353] H systemd[1]: Keeping job testsuite.target/stop because of shutdown.target/start
[ 1553.472546] H systemd[1]: multi-user.target: Found ordering cycle on testsuite.target/stop
[ 1553.472764] H systemd[1]: multi-user.target: Found dependency on end.service/stop
[ 1553.472971] H systemd[1]: multi-user.target: Found dependency on multi-user.target/stop
[ 1553.473183] H systemd[1]: multi-user.target: Job testsuite.target/stop deleted to break ordering cycle starting with multi-user.target/stop
[ 1553.473389] H systemd[1]: multi-user.target: Deleting job multi-user.target/stop as dependency of job testsuite.target/stop
[ 1553.473612] H systemd[1]: basic.target: Deleting job basic.target/stop as dependency of job multi-user.target/stop
[ 1553.473842] H systemd[1]: sysinit.target: Deleting job sysinit.target/stop as dependency of job basic.target/stop
[ 1553.474055] H systemd[1]: Keeping job umount.target/start because of systemd-poweroff.service/start
[ 1553.474246] H systemd[1]: Keeping job integritysetup.target/stop because of shutdown.target/start
[ 1553.474436] H systemd[1]: Keeping job systemd-poweroff.service/start because of poweroff.target/start
[ 1553.474627] H systemd[1]: Keeping job getty.target/stop because of shutdown.target/start
[ 1553.474824] H systemd[1]: Keeping job slices.target/stop because of shutdown.target/start
[ 1553.475026] H systemd[1]: Keeping job tmp-hoge.mount/stop because of umount.target/start
[ 1553.475212] H systemd[1]: Keeping job end.service/stop because of shutdown.target/start
[ 1553.475403] H systemd[1]: Keeping job dbus.socket/stop because of shutdown.target/start
[ 1553.475591] H systemd[1]: Keeping job console-getty.service/stop because of shutdown.target/start
[ 1553.475802] H systemd[1]: Keeping job local-fs.target/stop because of shutdown.target/start
[ 1553.475995] H systemd[1]: Keeping job systemd-user-sessions.service/stop because of shutdown.target/start
[ 1553.476188] H systemd[1]: Keeping job sockets.target/stop because of shutdown.target/start
[ 1553.476379] H systemd[1]: Keeping job cryptsetup.target/stop because of shutdown.target/start
[ 1553.476570] H systemd[1]: Keeping job systemd-tmpfiles-setup-dev.service/stop because of shutdown.target/start
[ 1553.476833] H systemd[1]: Keeping job systemd-tmpfiles-clean.timer/stop because of shutdown.target/start
[ 1553.477070] H systemd[1]: Keeping job testsuite-60.service/stop because of shutdown.target/start
[ 1553.477262] H systemd[1]: Keeping job tmp.mount/stop because of umount.target/start
[ 1553.477454] H systemd[1]: Keeping job systemd-tmpfiles-setup.service/stop because of shutdown.target/start
[ 1553.477647] H systemd[1]: Keeping job run-credentials-systemd\x2dtmpfiles\x2dsetup.service.mount/stop because of umount.target/start
[ 1553.477848] H systemd[1]: Keeping job paths.target/stop because of shutdown.target/start
[ 1553.478045] H systemd[1]: Keeping job run-credentials-systemd\x2dtmpfiles\x2dsetup\x2ddev.service.mount/stop because of umount.target/start
[ 1553.478248] H systemd[1]: Keeping job final.target/start because of systemd-poweroff.service/start
[ 1553.478435] H systemd[1]: Keeping job systemd-update-utmp.service/stop because of shutdown.target/start
[ 1553.478624] H systemd[1]: Keeping job systemd-ask-password-wall.path/stop because of shutdown.target/start
[ 1553.478817] H systemd[1]: Keeping job system-modprobe.slice/stop because of shutdown.target/start
[ 1553.479005] H systemd[1]: Keeping job systemd-coredump.socket/stop because of shutdown.target/start
[ 1553.479190] H systemd[1]: Keeping job systemd-ask-password-console.path/stop because of shutdown.target/start
[ 1553.479380] H systemd[1]: Keeping job systemd-remount-fs.service/stop because of shutdown.target/start
[ 1553.479566] H systemd[1]: Keeping job local-fs-pre.target/stop because of shutdown.target/start
[ 1553.479759] H systemd[1]: Keeping job systemd-logind.service/stop because of shutdown.target/start
[ 1553.479947] H systemd[1]: Keeping job user.slice/stop because of shutdown.target/start
[ 1553.480152] H systemd[1]: Keeping job dbus.service/stop because of dbus.socket/stop
[ 1553.480384] H systemd[1]: Keeping job timers.target/stop because of shutdown.target/start
[ 1553.480597] H systemd[1]: Keeping job swap.target/stop because of shutdown.target/start
[ 1553.480798] H systemd[1]: Keeping job veritysetup.target/stop because of shutdown.target/start
[ 1553.481002] H systemd[1]: Keeping job shutdown.target/start because of systemd-poweroff.service/start
I can seem to reproduce it with a "vanilla" meson build (meson build -Dinstall-tests=true) with:
diff --git a/test/units/testsuite-60.sh b/test/units/testsuite-60.sh
index a29364568d..ddbaff23bc 100755
--- a/test/units/testsuite-60.sh
+++ b/test/units/testsuite-60.sh
@@ -225,7 +225,7 @@ EOF
# shellcheck disable=SC2064
trap "rm -f /run/systemd/system/tmp-hoge.mount '$mount_mytmpfs'" RETURN
- for ((i = 0; i < 10; i++)); do
+ for ((i = 0; i < 100; i++)); do
systemctl --no-block start tmp-hoge.mount
sleep ".$RANDOM"
systemctl daemon-reexec
and
# BUILD_DIR=$PWD/build make -C test/TEST-60-MOUNT-RATELIMIT/ run TEST_NO_QEMU=yes NSPAWN_ARGUMENTS="--property AllowedCPUs=0"
but it still might take a couple of tries.
I get more consistent results with a coverge build (meson build-coverage -Db_coverage=true -Dinstall-tests=true) and:
# BUILD_DIR=$PWD/build-coverage make -C test/TEST-60-MOUNT-RATELIMIT/ run TEST_NO_QEMU=yes
...
system-modprobe.slice changed dead -> active
systemd-tmpfiles-clean.timer: Monotonic timer elapses in 13min 55.700788s.
systemd-tmpfiles-clean.timer: Changed dead -> waiting
[3663682.759379] testsuite-60.sh[33]: + sleep 1
[ OK ] Reached target testsuite.target.
Starting end.service...
[ SKIP ] Ordering cycle found, skipping end.service
In this case the test fails every time even without the iteration patch (at least on my F36 machine and in the daily coverage build on Arch Linux). Tested with a3e03a3f1874f31f7b6253a4a42482800e8fea59 ATTOW.
I'll pre-emptively add this to the v252 milestone, as it looks like a bug in the serialization/deserialization stuff. I'll try to bisect it in the meantime.
Ah, the bisect is going to be fun, as it's reproducible even with the commit that introduced the test (864d1a4f66).
Interesting, I used a trimmed-down version of TEST-60:
#!/usr/bin/env bash
# SPDX-License-Identifier: LGPL-2.1-or-later
set -eux
set -o pipefail
test_issue_23796() {
local mount_path mount_mytmpfs
mount_path="$(command -v mount 2>/dev/null)"
mount_mytmpfs="${mount_path/\/bin/\/sbin}.mytmpfs"
cat >"$mount_mytmpfs" <<EOF
#!/bin/bash
sleep ".\$RANDOM"
exec -- $mount_path -t tmpfs tmpfs "\$2"
EOF
chmod +x "$mount_mytmpfs"
mkdir -p /run/systemd/system
cat >/run/systemd/system/tmp-hoge.mount <<EOF
[Mount]
What=mytmpfs
Where=/tmp/hoge
Type=mytmpfs
EOF
# shellcheck disable=SC2064
trap "rm -f /run/systemd/system/tmp-hoge.mount '$mount_mytmpfs'" RETURN
for ((i = 0; i < 100; i++)); do
echo "Iteration $i/100"
systemctl --no-block start tmp-hoge.mount
sleep ".$RANDOM"
systemctl daemon-reexec
sleep 1
systemctl stop tmp-hoge.mount || :
done
}
: >/failed
systemd-analyze log-level debug
systemd-analyze log-target journal
systemctl daemon-reload
# test for reexecuting with background mount job
test_issue_23796
systemd-analyze log-level info
touch /testok
rm /failed
and with it I can reproduce it on v251 and v250*. On v249 it also fails after daemon-reexecute, but there's no "Ordering cycle found", so I'm not sure if it's the same issue:
[3671562.639293] H testsuite-60.sh[30]: Iteration 0/100
[3671562.639293] H testsuite-60.sh[30]: + systemctl --no-block start tmp-hoge.mount
[3671562.722799] H testsuite-60.sh[30]: + sleep .2171
[3671562.940709] H testsuite-60.sh[30]: + systemctl daemon-reexec
[3671563.272780] H testsuite-60.sh[30]: + sleep 1
[3671563.304120] H systemd[1]: testsuite-60.service: Job 77 testsuite-60.service/start finished, result=canceled
[3671563.304403] H systemd[1]: testsuite-60.service: Installed new job testsuite-60.service/stop as 196
[3671563.410744] H systemd[1]: testsuite-60.service: Changed start -> stop-sigterm
[3671563.412952] H systemd[1]: testsuite-60.service: Child 30 belongs to testsuite-60.service.
[3671563.413097] H systemd[1]: testsuite-60.service: Main process exited, code=killed, status=15/TERM
[3671563.413254] H systemd[1]: testsuite-60.service: Failed with result 'signal'.
[3671563.413402] H systemd[1]: testsuite-60.service: Service restart not allowed.
[3671563.413547] H systemd[1]: testsuite-60.service: Changed stop-sigterm -> failed
[3671563.413847] H systemd[1]: testsuite-60.service: Job 196 testsuite-60.service/stop finished, result=done
[3671563.413992] H systemd[1]: Stopped testsuite-60.service.
Anyway, I'm dropping the "regression" tag again, as the issue has been there for quite a while and I can't even find out if it worked at any point in time.
[*] Commits needed to successfully build given tag: v251 + bffde9b5869fffc09e7824d2ac0aeb82a31a134b v250 + bbe53713455be38c0a587626439fd171f28c77fc + bffde9b5869fffc09e7824d2ac0aeb82a31a134b v249 + c29537f39e4f413a6cbfe9669fa121bdd6d8b36f + 7c5b9952c4f6e2b72f90edbe439982528b7cf223 + e7f46ee3ae1cc66a94b293957721d68dc09d7449
I'm not really sure, since this seems to happen only in nspawn (but maybe I was lucky?). Let's see how #20330 pans out.
Unfortunately c39d0187746c0bfa3946ae10ce6c926c61d6e41f (#24919) does not help the issue.
The issue sounds scary for me, but only reported on a specific test environment. Hopefully it merely affects real system. Moved to v253 milestone.
The issue sounds scary for me, but only reported on a specific test environment. Hopefully it merely affects real system. Moved to v253 milestone.
It definitely sound scary, but since I can reproduce it even with systemd v249 I don't think it's something urgent, especially since no-one else reported it until now.
After many hours of digging around, I managed to isolate the issue to the systemd-debug-generator (or whereabouts), as I noticed that the testsuite.target sometimes loses its dependency on testsuite-60.service provided via systemd.wants=testsuite-60.service. Also, after replacing test/units/testsuite-60.sh with
#!/usr/bin/env bash
# SPDX-License-Identifier: LGPL-2.1-or-later
set -eux
systemctl log-level info
stat /run/systemd/generator.early/testsuite.target.wants/testsuite-60.service
for ((i = 0; i < 500; i++)); do
systemctl restart --no-block tmp.mount
systemctl daemon-reexec
stat /run/systemd/generator.early/testsuite.target.wants/testsuite-60.service
done
touch /testok
the test fails after a couple of tries with:
[2025808.003788] testsuite-60.sh[34]: + systemctl daemon-reexec
...
[2025808.163222] testsuite-60.sh[34]: + stat /run/systemd/generator.early/testsuite.target.wants/testsuite-60.service
[2025808.164252] testsuite-60.sh[192]: stat: cannot statx '/run/systemd/generator.early/testsuite.target.wants/testsuite-60.service': No such file or directory
even though the debug generator succeeded. Unfortunately, I can't seem to get any debug output from the generators when running with nspawn (as this happens only with nspawn, in QEMU everything works as expected).
Another interesting thing - with systemd.log_target=console or systemd.log_target=kmsg everything seems to work in nspawn as well.
Oh god, now I see it. Turns out I can reproduce it by calling the generator manually:
test/units/testsuite-60.sh
#!/usr/bin/env bash
# SPDX-License-Identifier: LGPL-2.1-or-later
set -eux
at_exit() {
set +e
ls -lR test/
}
trap at_exit EXIT
mkdir test
for ((i = 0; i < 500; i++)); do
rm -fr test/*
systemctl restart --no-block tmp.mount
systemctl daemon-reexec
/usr/lib/systemd/system-generators/systemd-debug-generator test/ test/ test/
ls -lR test/
stat test/testsuite.target.wants/testsuite-60.service
#stat /run/systemd/generator.early/testsuite.target.wants/testsuite-60.service
done
touch /testok
diff --git a/src/basic/proc-cmdline.c b/src/basic/proc-cmdline.c
index eea70d8606..ffae49732c 100644
--- a/src/basic/proc-cmdline.c
+++ b/src/basic/proc-cmdline.c
@@ -137,6 +137,8 @@ int proc_cmdline_parse(proc_cmdline_parse_t parse_item, void *data, ProcCmdlineF
if (r < 0)
return r;
+ log_warning("%s: line=%s", __func__, line);
+
return proc_cmdline_parse_given(line, parse_item, data, flags);
}
diff --git a/src/debug-generator/debug-generator.c b/src/debug-generator/debug-generator.c
index 1fe2b56810..d11f097581 100644
--- a/src/debug-generator/debug-generator.c
+++ b/src/debug-generator/debug-generator.c
@@ -60,6 +60,8 @@ static int parse_proc_cmdline_item(const char *key, const char *value, void *dat
if (r < 0)
return log_oom();
+ log_warning("%s: Got systemd.wants=%s", __func__, n);
+
} else if (proc_cmdline_key_streq(key, "systemd.debug_shell")) {
const char *t = NULL;
@@ -76,12 +78,15 @@ static int parse_proc_cmdline_item(const char *key, const char *value, void *dat
if (proc_cmdline_value_missing(key, value))
return 0;
+ log_warning("%s: Got systemd.unit=%s", __func__, value);
return free_and_strdup_warn(&arg_default_unit, value);
} else if (!value) {
const char *target;
target = runlevel_to_target(key);
+
+ log_warning("%s: !value, runlevel_to_target(%s) = %s", __func__, key, target);
if (target)
return free_and_strdup_warn(&arg_default_unit, target);
}
@@ -115,6 +120,8 @@ static int generate_wants_symlinks(void) {
_cleanup_free_ char *p = NULL, *f = NULL;
const char *target;
+ log_warning("%s: arg_default_unit=%s, in_initrd=%s", __func__, arg_default_unit, yes_no(in_initrd()));
+
/* This should match what do_queue_default_job() in core/main.c does. */
if (arg_default_unit)
target = arg_default_unit;
@@ -131,6 +138,8 @@ static int generate_wants_symlinks(void) {
if (!f)
return log_oom();
+ log_warning("%s: Creating symlink %s for unit %s with target %s", __func__, f, *u, target);
+
(void) mkdir_parents_label(p, 0755);
if (symlink(f, p) < 0)
...
[2032727.616652] systemd[1]: Reexecuting.
[2032727.992299] testsuite-60.sh[34]: + /usr/lib/systemd/system-generators/systemd-debug-generator test/ test/ test/
[2032727.995712] testsuite-60.sh[103]: proc_cmdline_parse: line=/usr/lib/systemd/systemd systemd.unit=testsuite.target systemd.wants=testsuite-60.service systemd.wants=end.service --system --deserialize 25
[2032727.995712] testsuite-60.sh[103]: parse_proc_cmdline_item: !value, runlevel_to_target(/usr/lib/systemd/systemd) = (null)
[2032727.995712] testsuite-60.sh[103]: parse_proc_cmdline_item: Got systemd.unit=testsuite.target
[2032727.995712] testsuite-60.sh[103]: parse_proc_cmdline_item: Got systemd.wants=testsuite-60.service
[2032727.995712] testsuite-60.sh[103]: parse_proc_cmdline_item: Got systemd.wants=end.service
[2032727.995712] testsuite-60.sh[103]: parse_proc_cmdline_item: !value, runlevel_to_target(--system) = (null)
[2032727.995712] testsuite-60.sh[103]: parse_proc_cmdline_item: !value, runlevel_to_target(--deserialize) = (null)
[2032727.995712] testsuite-60.sh[103]: parse_proc_cmdline_item: !value, runlevel_to_target(25) = (null)
[2032727.995712] testsuite-60.sh[103]: generate_wants_symlinks: arg_default_unit=testsuite.target, in_initrd=no
[2032727.995712] testsuite-60.sh[103]: generate_wants_symlinks: Creating symlink /usr/lib/systemd/system/testsuite-60.service for unit testsuite-60.service with target testsuite.target
[2032727.997069] testsuite-60.sh[103]: generate_wants_symlinks: arg_default_unit=testsuite.target, in_initrd=no
[2032727.997069] testsuite-60.sh[103]: generate_wants_symlinks: Creating symlink /usr/lib/systemd/system/end.service for unit end.service with target testsuite.target
[2032728.004835] testsuite-60.sh[34]: + ls -lR test/
[2032728.005905] testsuite-60.sh[104]: test/:
[2032728.005905] testsuite-60.sh[104]: total 4
[2032728.005905] testsuite-60.sh[104]: drwxr-xr-x. 2 root root 4096 Mar 18 22:49 testsuite.target.wants
[2032728.005905] testsuite-60.sh[104]: test/testsuite.target.wants:
[2032728.005905] testsuite-60.sh[104]: total 0
[2032728.005905] testsuite-60.sh[104]: lrwxrwxrwx. 1 root root 35 Mar 18 22:49 end.service -> /usr/lib/systemd/system/end.service
[2032728.005905] testsuite-60.sh[104]: lrwxrwxrwx. 1 root root 44 Mar 18 22:49 testsuite-60.service -> /usr/lib/systemd/system/testsuite-60.service
[2032728.006689] testsuite-60.sh[34]: + stat test/testsuite.target.wants/testsuite-60.service
[2032728.006925] testsuite-60.sh[105]: File: test/testsuite.target.wants/testsuite-60.service -> /usr/lib/systemd/system/testsuite-60.service
[2032728.006925] testsuite-60.sh[105]: Size: 44 Blocks: 0 IO Block: 4096 symbolic link
[2032728.006925] testsuite-60.sh[105]: Device: 259,10 Inode: 6473 Links: 1
[2032728.006925] testsuite-60.sh[105]: Access: (0777/lrwxrwxrwx) Uid: ( 0/ root) Gid: ( 0/ root)
[2032728.006925] testsuite-60.sh[105]: Access: 2023-03-18 22:49:51.098568296 +0100
[2032728.006925] testsuite-60.sh[105]: Modify: 2023-03-18 22:49:51.088568259 +0100
[2032728.006925] testsuite-60.sh[105]: Change: 2023-03-18 22:49:51.088568259 +0100
[2032728.006925] testsuite-60.sh[105]: Birth: 2023-03-18 22:49:51.088568259 +0100
[2032728.007878] testsuite-60.sh[34]: + (( i++ ))
[2032728.007878] testsuite-60.sh[34]: + (( i < 500 ))
[2032728.007878] testsuite-60.sh[34]: + rm -fr test/testsuite.target.wants
[2032728.007878] testsuite-60.sh[34]: + systemctl restart --no-block tmp.mount
[2032728.053238] systemd[1]: Unmounting tmp.mount...
[2032728.062140] testsuite-60.sh[34]: + systemctl daemon-reexec
[2032728.065688] systemd[1]: tmp.mount: Deactivated successfully.
[2032728.066450] systemd[1]: Unmounted tmp.mount.
[2032728.078425] systemd[1]: Mounting tmp.mount...
[2032728.101475] systemd[1]: Mounted tmp.mount.
[2032728.102049] systemd[1]: Reexecuting requested from client PID 109 (unit testsuite-60.service)...
[2032728.102466] systemd[1]: Reexecuting.
[2032728.491007] testsuite-60.sh[34]: + /usr/lib/systemd/system-generators/systemd-debug-generator test/ test/ test/
[2032728.491149] systemd[1]: Reached target testsuite.target.
[2032728.494392] testsuite-60.sh[126]: proc_cmdline_parse: line=/usr/lib/systemd/systemd systemd.unit=testsuite.target systemd.wants=testsuite-60.service systemd.wants=end.service --system --deserialize 3
[2032728.494392] testsuite-60.sh[126]: parse_proc_cmdline_item: !value, runlevel_to_target(/usr/lib/systemd/systemd) = (null)
[2032728.494392] testsuite-60.sh[126]: parse_proc_cmdline_item: Got systemd.unit=testsuite.target
[2032728.494392] testsuite-60.sh[126]: parse_proc_cmdline_item: Got systemd.wants=testsuite-60.service
[2032728.494392] testsuite-60.sh[126]: parse_proc_cmdline_item: Got systemd.wants=end.service
[2032728.494392] testsuite-60.sh[126]: parse_proc_cmdline_item: !value, runlevel_to_target(--system) = (null)
[2032728.494392] testsuite-60.sh[126]: parse_proc_cmdline_item: !value, runlevel_to_target(--deserialize) = (null)
[2032728.494392] testsuite-60.sh[126]: parse_proc_cmdline_item: !value, runlevel_to_target(3) = multi-user.target
[2032728.494392] testsuite-60.sh[126]: generate_wants_symlinks: arg_default_unit=multi-user.target, in_initrd=no
[2032728.494392] testsuite-60.sh[126]: generate_wants_symlinks: Creating symlink /usr/lib/systemd/system/testsuite-60.service for unit testsuite-60.service with target multi-user.target
[2032728.500703] testsuite-60.sh[126]: generate_wants_symlinks: arg_default_unit=multi-user.target, in_initrd=no
[2032728.500703] testsuite-60.sh[126]: generate_wants_symlinks: Creating symlink /usr/lib/systemd/system/end.service for unit end.service with target multi-user.target
[2032728.501502] systemd[1]: Starting end.service...
[2032728.502940] testsuite-60.sh[34]: + ls -lR test/
[2032728.504017] testsuite-60.sh[127]: test/:
[2032728.504017] testsuite-60.sh[127]: total 4
[2032728.504017] testsuite-60.sh[127]: drwxr-xr-x. 2 root root 4096 Mar 18 22:49 multi-user.target.wants
[2032728.504017] testsuite-60.sh[127]: test/multi-user.target.wants:
[2032728.504017] testsuite-60.sh[127]: total 0
[2032728.504017] testsuite-60.sh[127]: lrwxrwxrwx. 1 root root 35 Mar 18 22:49 end.service -> /usr/lib/systemd/system/end.service
[2032728.504017] testsuite-60.sh[127]: lrwxrwxrwx. 1 root root 44 Mar 18 22:49 testsuite-60.service -> /usr/lib/systemd/system/testsuite-60.service
[2032728.504907] testsuite-60.sh[34]: + stat test/testsuite.target.wants/testsuite-60.service
[2032728.505041] testsuite-60.sh[128]: stat: cannot statx 'test/testsuite.target.wants/testsuite-60.service': No such file or directory
[2032728.505195] testsuite-60.sh[34]: + at_exit
[2032728.505195] testsuite-60.sh[34]: + set +e
[2032728.505195] testsuite-60.sh[34]: + ls -lR test/
[2032728.505859] testsuite-60.sh[129]: test/:
[2032728.505859] testsuite-60.sh[129]: total 4
[2032728.505859] testsuite-60.sh[129]: drwxr-xr-x. 2 root root 4096 Mar 18 22:49 multi-user.target.wants
[2032728.505859] testsuite-60.sh[129]: test/multi-user.target.wants:
[2032728.505859] testsuite-60.sh[129]: total 0
[2032728.505859] testsuite-60.sh[129]: lrwxrwxrwx. 1 root root 35 Mar 18 22:49 end.service -> /usr/lib/systemd/system/end.service
[2032728.505859] testsuite-60.sh[129]: lrwxrwxrwx. 1 root root 44 Mar 18 22:49 testsuite-60.service -> /usr/lib/systemd/system/testsuite-60.service
...
As you can see from the output above, we always attempt to parse the FD number from --deserialize XX as a runlevel, and sometimes we hit a low-enough FD that it actually translates to a valid runlevel, overriding the target set by systemd.unit=.