[systemd-devel] Troubleshooting systemd shutdown problems - systemctl hangs in debug shell

Wed Jan 25 09:24:39 UTC 2023

Hi,

I am currently troubleshooting a problem where a raspberry pi zero w will
not reboot after running the `reboot` command (it does reboot with `reboot
-f` however) - it just "hangs". After enabling the serial console, my best
guess was that a job is stuck in systemd, so I tried enabling the early
boot shell. However, after I run `reboot` in a normal shell and change to
the early boot shell, running the command `systemctl` (for example,
`systemctl list-jobs`) just hangs forever. I can ctrl+c out of it and run
other commands (`ps`, `ls`, etc) but I can't seem to query systemd through
systemctl. Is there some way I can view the current state of systemd
without this command?

Some further details:
Linux kernel 5.15.89+ running on raspberry pi zero w (via Raspberry Pi OS)
systemd version: systemd 247 (247.3-7+rpi1+deb11u1)
+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP
+GCRYPT +GNUTLS +ACL +XZ +LZ4 +ZSTD +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2
-IDN +PCRE2 default-hierarchy=unified

systemd arguments on kernel commandline: systemd.log_level=debug
systemd.log_target=kmsg log_buf_len=1M enforcing=0 ignore_loglevel
systemd.debug-shell=1

Here is the tail end of the systemd log which is output to the serial
console after running `reboot`:

```
[  126.857450] systemd-journald[100]: Successfully sent stream file
descriptor to service manager.
[  126.942054] systemd-journald[100]: Successfully sent stream file
descriptor to service manager.
[  127.213116] systemd-journald[100]: Successfully sent stream file
descriptor to service manager.
[  127.272100] systemd-journald[100]: Successfully sent stream file
descriptor to service manager.
[  127.318344] systemd-journald[100]: Successfully sent stream file
descriptor to service manager.
[  127.522280] systemd-journald[100]: Successfully sent stream file
descriptor to service manager.
[  128.217070] systemd[1]: Sent message type=signal sender=n/a
destination=n/a path=/org/freedesktop/systemd1/unit/bluetooth_2eservice
interface=org.freedesktop.DBus.Properties member=PropertiesChanged
cookie=799 reply_cookie=0 signature=sa{sv}as error-name=n/a
error-message=n/a
[  128.274042] systemd[1]: Sent message type=signal sender=n/a
destination=n/a path=/org/freedesktop/systemd1/unit/bluetooth_2eservice
interface=org.freedesktop.DBus.Properties member=PropertiesChanged
cookie=800 reply_cookie=0 signature=sa{sv}as error-name=n/a
error-message=n/a
[  128.326185] systemd[1]: Child 522 (agetty) died (code=killed,
status=15/TERM)
[  128.347548] systemd[1]: getty at tty1.service: Failed to read oom_kill
field of memory.events cgroup attribute: No such file or directory
[  128.371639] systemd[1]: getty at tty1.service: Child 522 belongs to
getty at tty1.service.
[  128.390389] systemd[1]: getty at tty1.service: Main process exited,
code=killed, status=15/TERM
[  128.406372] systemd[1]: getty at tty1.service: Succeeded.
[  128.423193] systemd[1]: getty at tty1.service: Service restart not allowed.
[  128.438162] systemd[1]: getty at tty1.service: Changed stop-sigterm -> dead
[  128.457233] systemd[1]: getty at tty1.service: Job 662 getty at tty1.service/stop
finished, result=done
[  128.466383] systemd[1]: Stopped Getty on tty1.
[  128.499079] systemd[1]: Sent message type=signal sender=n/a
destination=n/a path=/org/freedesktop/systemd1/unit/getty_40tty1_2eservice
interface=org.freedesktop.DBus.Properties member=PropertiesChanged
cookie=801 reply_cookie=0 signature=sa{sv}as error-name=n/a
error-message=n/a
[  128.539439] systemd[1]: Sent message type=signal sender=n/a
destination=n/a path=/org/freedesktop/systemd1/unit/getty_40tty1_2eservice
interface=org.freedesktop.DBus.Properties member=PropertiesChanged
cookie=802 reply_cookie=0 signature=sa{sv}as error-name=n/a
error-message=n/a
[  128.575152] systemd[1]: Sent message type=signal sender=n/a
destination=n/a path=/org/freedesktop/systemd1
interface=org.freedesktop.systemd1.Manager member=JobRemoved cookie=803
reply_cookie=0 signature=uoss error-name=n/a error-message=n/a
[  128.610134] systemd[1]: getty at tty1.service: Consumed 40ms CPU time.
[  128.635696] systemd[1]: Sent message type=signal sender=n/a
destination=n/a path=/org/freedesktop/systemd1/unit/getty_40tty1_2eservice
interface=org.freedesktop.DBus.Properties member=PropertiesChanged
cookie=804 reply_cookie=0 signature=sa{sv}as error-name=n/a
error-message=n/a
[  128.672136] systemd[1]: Sent message type=signal sender=n/a
destination=n/a path=/org/freedesktop/systemd1/unit/getty_40tty1_2eservice
interface=org.freedesktop.DBus.Properties member=PropertiesChanged
cookie=805 reply_cookie=0 signature=sa{sv}as error-name=n/a
error-message=n/a
[  128.713716] systemd[1]: Child 525 ((agetty)) died (code=killed,
status=15/TERM)
[  128.737541] systemd[1]: getty at ttyGS0.service: Failed to read oom_kill
field of memory.events cgroup attribute: No such file or directory
[  128.758022] systemd[1]: getty at ttyGS0.service: Child 525 belongs to
getty at ttyGS0.service.
[  128.766575] systemd[1]: getty at ttyGS0.service: Main process exited,
code=killed, status=15/TERM
[  128.779496] systemd[1]: getty at ttyGS0.service: Succeeded.
[  128.785390] systemd[1]: getty at ttyGS0.service: Service restart not
allowed.
[  128.794270] systemd[1]: getty at ttyGS0.service: Changed stop-sigterm ->
dead
[  128.804306] systemd[1]: getty at ttyGS0.service: Job 700
getty at ttyGS0.service/stop finished, result=done
[  128.814886] systemd[1]: Stopped Getty on ttyGS0.
[  128.823697] systemd[1]: Sent message type=signal sender=n/a
destination=n/a
path=/org/freedesktop/systemd1/unit/getty_40ttyGS0_2eservice
interface=org.freedesktop.DBus.Properties member=PropertiesChanged
cookie=806 reply_cookie=0 signature=sa{sv}as error-name=n/a
error-message=n/a
[  128.853005] systemd[1]: Sent message type=signal sender=n/a
destination=n/a
path=/org/freedesktop/systemd1/unit/getty_40ttyGS0_2eservice
interface=org.freedesktop.DBus.Properties member=PropertiesChanged
cookie=807 reply_cookie=0 signature=sa{sv}as error-name=n/a
error-message=n/a
[  128.881151] systemd[1]: Sent message type=signal sender=n/a
destination=n/a path=/org/freedesktop/systemd1
interface=org.freedesktop.systemd1.Manager member=JobRemoved cookie=808
reply_cookie=0 signature=uoss error-name=n/a error-message=n/a
[  128.904528] systemd[1]: getty at ttyGS0.service: Consumed 7ms CPU time.
[  201.747274] systemd-journald[100]: Sent WATCHDOG=1 notification.
[  301.957264] systemd-journald[100]: Sent WATCHDOG=1 notification.
```

The "Sent WATCHDOG=1 notification." is just printed over and over as long
as I leave the system on (I left it running for 12hrs and it did not
reboot, it just printed this message). At this point in the shutdown, the
early shell is still accessible, but the `systemctl` command just hangs.

I have also posted the full log here as an attachment:
https://github.com/raspberrypi/firmware/issues/1559#issuecomment-1403052508

Any pointers you could provide me in further debugging this problem would
be greatly appreciated. I am not exactly sure where to go from here seeing
as the debug shell seems to be not working for me.

Thanks,
Jeremy
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.freedesktop.org/archives/systemd-devel/attachments/20230125/859c5806/attachment.htm>