TEST-56-EXIT-TYPE is flaky

[mrc0mmand]

systemd version the issue has been seen with

latest main

Used distribution

Arch Linux

After re-introducing TEST-56 (and the respective functionality) in #20813 I've noticed a couple of random fails in various PRs, which make the test a bit unstable:

[    9.646864] testsuite-56.sh[226]: + systemd-analyze log-level debug
[    9.656400] systemd[1]: Reached target Login Prompts.
[    9.727537] systemd-logind[224]: Watching system buttons on /dev/input/event0 (Power Button)
[    9.728113] systemd-logind[224]: Watching system buttons on /dev/input/event1 (AT Translated Set 2 keyboard)
[    9.728633] systemd-logind[224]: New seat seat0.
[    9.745663] systemd[1]: Started D-Bus System Message Bus.
[    9.769374] systemd[1]: Setting log level to debug.
[    9.771228] testsuite-56.sh[226]: + cat
[    9.787120] testsuite-56.sh[226]: + chmod +x /tmp/test56-exit-cgroup.sh
[    9.799320] testsuite-56.sh[226]: + systemd-run --wait --unit=one -p Type=notify -p ExitType=cgroup -p 'ExecStartPost=bash -c "systemctl stop one &"' /tmp/test56-exit-cgroup.sh
[    9.917018] systemd[1]: Started User Login Management.
[    9.924796] systemd[1]: Reached target Multi-User System.
[    9.933681] dbus-daemon[229]: [system] Successfully activated service 'org.freedesktop.systemd1'
[    9.942264] systemd[1]: Starting Record Runlevel Change in UTMP...
[    9.984707] test56-exit-cgroup.sh[234]: + disown
[    9.985737] test56-exit-cgroup.sh[235]: + sleep infinity
[    9.988313] test56-exit-cgroup.sh[234]: + systemd-notify --ready
[    9.996744] test56-exit-cgroup.sh[238]: + sleep infinity
[   10.013322] systemd[1]: Starting /tmp/test56-exit-cgroup.sh...
[   10.019846] systemd[1]: systemd-update-utmp-runlevel.service: Deactivated successfully.
[   10.036639] systemd[1]: Finished Record Runlevel Change in UTMP.
[   10.056952] test56-exit-cgroup.sh[234]: + sleep infinity
[   10.132911] testsuite-56.sh[232]: Job for one.service canceled.
[   10.138704] systemd[1]: testsuite-56.service: Main process exited, code=exited, status=1/FAILURE
[   10.138845] systemd[1]: testsuite-56.service: Failed with result 'exit-code'.
[   10.170346] systemd[1]: Failed to start TEST-56-EXIT-TYPE.
[   10.182877] systemd[1]: one.service: Control process exited, code=killed, status=15/TERM
[   10.183105] systemd[1]: one.service: Failed with result 'signal'.

Full journal: system.journal.tar.gz

/cc @unusual-thoughts

[unusual-thoughts]

The one.service logs look like:

systemd[1]: one.service: Failed to load configuration: No such file or directory
systemd[1]: one.service: Trying to enqueue job one.service/start/fail
test56-exit-cgroup.sh[234]: + disown
test56-exit-cgroup.sh[235]: + sleep infinity
test56-exit-cgroup.sh[234]: + systemd-notify --ready
test56-exit-cgroup.sh[238]: + sleep infinity
systemd[1]: one.service: Installed new job one.service/start as 243
systemd[1]: one.service: Enqueued job one.service/start as 243
systemd[1]: one.service: Passing 0 fds to service
systemd[1]: one.service: About to execute /tmp/test56-exit-cgroup.sh
systemd[1]: one.service: Forked /tmp/test56-exit-cgroup.sh as 234
systemd[234]: one.service: Executing: /tmp/test56-exit-cgroup.sh
systemd[1]: one.service: Changed dead -> start
systemd[1]: Starting /tmp/test56-exit-cgroup.sh...
systemd[1]: one.service: Got notification message from PID 234 (READY=1)
systemd[1]: one.service: About to execute bash -c "systemctl stop one &"
systemd[1]: one.service: Forked bash as 239
systemd[1]: one.service: Changed start -> start-post
systemd[239]: one.service: Executing: bash -c "systemctl stop one &"
test56-exit-cgroup.sh[234]: + sleep infinity
systemd[1]: one.service: Trying to enqueue job one.service/stop/replace
systemd[1]: one.service: Job 243 one.service/start finished, result=canceled
systemd[1]: one.service: Installed new job one.service/stop as 299
systemd[1]: one.service: Enqueued job one.service/stop as 299
systemd[1]: one.service: Failed to send unit change signal for one.service: Connection reset by peer
systemd[1]: one.service: Changed start-post -> stop-sigterm
systemd[1]: one.service: Child 234 belongs to one.service.
systemd[1]: one.service: Main process exited, code=killed, status=15/TERM (success)
systemd[1]: one.service: Child 238 belongs to one.service.
systemd[1]: one.service: Child 239 belongs to one.service.
systemd[1]: one.service: Control process exited, code=killed, status=15/TERM
systemd[1]: one.service: Got final SIGCHLD for state stop-sigterm.
systemd[1]: one.service: Failed with result 'signal'.
systemd[1]: one.service: Service restart not allowed.
systemd[1]: one.service: Changed stop-sigterm -> failed
systemd[1]: one.service: Failed to delete cgroup entry from LSM BPF map: No such file or directory
systemd[1]: one.service: Job 299 one.service/stop finished, result=done
systemd[1]: Stopped /tmp/test56-exit-cgroup.sh.
systemd[1]: one.service: Unit entered failed state.
systemd[1]: one.service: Consumed 121ms CPU time.
systemd[1]: one.service: Control group is empty.

A normal execution looks like:

systemd[1]: one.service: Failed to load configuration: No such file or directory
systemd[1]: one.service: Trying to enqueue job one.service/start/fail
test56-exit-cgroup.sh[234]: + disown
test56-exit-cgroup.sh[235]: + sleep infinity
test56-exit-cgroup.sh[234]: + systemd-notify --ready
test56-exit-cgroup.sh[238]: + sleep infinity
systemd[1]: one.service: Installed new job one.service/start as 243
systemd[1]: one.service: Enqueued job one.service/start as 243
systemd[1]: one.service: Passing 0 fds to service
systemd[1]: one.service: About to execute /tmp/test56-exit-cgroup.sh
systemd[1]: one.service: Forked /tmp/test56-exit-cgroup.sh as 234
systemd[1]: one.service: Changed dead -> start
systemd[1]: Starting /tmp/test56-exit-cgroup.sh...
systemd[234]: one.service: Executing: /tmp/test56-exit-cgroup.sh
systemd[1]: one.service: Got notification message from PID 234 (READY=1)
systemd[1]: one.service: About to execute bash -c "systemctl stop one &"
systemd[1]: one.service: Forked bash as 239
systemd[1]: one.service: Changed start -> start-post
systemd[239]: one.service: Executing: bash -c "systemctl stop one &"
test56-exit-cgroup.sh[234]: + sleep infinity
systemd[1]: one.service: Child 239 belongs to one.service.
systemd[1]: one.service: Control process exited, code=exited, status=0/SUCCESS (success)
systemd[1]: one.service: Got final SIGCHLD for state start-post.
systemd[1]: one.service: Changed start-post -> running
systemd[1]: one.service: Job 243 one.service/start finished, result=done
systemd[1]: Started /tmp/test56-exit-cgroup.sh.
systemd[1]: one.service: Trying to enqueue job one.service/stop/replace
systemd[1]: one.service: Installed new job one.service/stop as 299
systemd[1]: one.service: Enqueued job one.service/stop as 299
systemd[1]: one.service: Changed running -> stop-sigterm
systemd[1]: Stopping /tmp/test56-exit-cgroup.sh...
systemd[1]: one.service: Child 284 belongs to one.service.
systemd[1]: one.service: Child 234 belongs to one.service.
systemd[1]: one.service: Main process exited, code=killed, status=15/TERM (success)
systemd[1]: one.service: Failed to send unit change signal for one.service: Connection reset by peer
systemd[1]: one.service: Child 238 belongs to one.service.
systemd[1]: one.service: Child 243 belongs to one.service.
systemd[1]: one.service: Child 235 belongs to one.service.
systemd[1]: one.service: Child 236 belongs to one.service.
systemd[1]: one.service: Child 283 belongs to one.service.
systemd[1]: one.service: Control group is empty.
systemd[1]: one.service: Deactivated successfully.
systemd[1]: one.service: Service restart not allowed.
systemd[1]: one.service: Changed stop-sigterm -> dead
systemd[1]: one.service: Job 299 one.service/stop finished, result=done
systemd[1]: Stopped /tmp/test56-exit-cgroup.sh.
systemd[1]: one.service: Consumed 29ms CPU time.
systemd[1]: one.service: Collecting.

There is a race between the kill command in the ExecStartPost='bash -c "systemctl stop one &"' subprocess and the parent ExecStartPost bash process exiting, such that .
It can be reproduced reliably by dropping the ampersand to ExecStartPost='bash -c "systemctl stop one "'. It should be solved by adding an extra delay to eg ExecStartPost='bash -c "(sleep 1; systemctl stop one)&"'