Diagnosing unreliable reboots

pelwell commented 1 year ago

This is a continuation of https://github.com/raspberrypi/firmware/issues/1559, a thread which is so long that the important diagnostic questions have got lost in the middle.

https://github.com/raspberrypi/firmware/issues/1559 was specifically about Pi 4, but the methods for diagnosing the problem are common to all Pis.

I'll be using the word "reboot" throughout this list, but it should apply equally to powering off.

When rebooting hangs, wait several minutes to see if it unsticks eventually.
Does sync && sudo reboot -f hang or reboot?
If reboot is very slow but eventually completes,
1. Add systemd.log_level=debug systemd.log_target=kmsg log_buf_len=1M enforcing=0 to /boot/cmdline.txt
2. Put the following in /usr/lib/systemd/system-shutdown/debug.sh:
```
#!/bin/sh
mount -o remount,rw /
dmesg > /shutdown-log.txt
mount -o remount,ro /
reboot
```
3. Make it executable:
```
$ sudo chmod +x /usr/lib/systemd/system-shutdown/debug.sh
```
4. Reboot twice - once to activate the logging, and once to generate /shutdown-log.txt.
5. Upload /shutdown-log.txt.
6. Remove the additions to cmdline.txt and delete (or make non-executable) /usr/lib/systemd/system-shutdown/debug.sh
If reboot doesn't complete, and if you have a serial/UART cable you can connect to header pins 6, 8, and 10, and a host computer (or another Raspberry Pi) to run a terminal app such as PuTTY or minicom:
1. Add enable_uart=1 to /boot/config.txt.
2. Add systemd.log_level=debug systemd.log_target=kmsg log_buf_len=1M enforcing=0 ignore_loglevel to /boot/cmdline.txt, being careful to remove quiet if it is present.
3. Run sync to flush outstanding writes, then power cycle.
4. Log in as usual (it will take a long time to boot, with thousands of lines of output, and if you are logging in over the serial connection you may have to hit Return to get the prompt), then sudo reboot and capture the output in your terminal program.

beren12 commented 1 year ago

Just to clarify these appears to be a systemd-related bug as I have never had a failed reboot with sysvinit on any of my rpi models. Yes on current releases sysvinit still works unfailingly.

pelwell commented 1 year ago

You're in danger of confusing apples with oranges. Further sysvinit discussion will be deleted as off-topic.

tianfeng-yang commented 1 year ago

@pelwell My Raspberry Pi 4B has a reboot hang problem, the following is the log information output according to step 4

Linux rasp4yzm 6.1.21-v8+ #1642 SMP PREEMPT Mon Apr  3 17:24:16 BST 2023 aarch64

The programs included with the Debian GNU/Linux system are free software;
the exact[  129.491710] systemd[1]: n/a: New incoming connection.
 distribution terms for [  129.499016] systemd[1]: n/a: Connections of user 0: 0 (of 1024 max)
each program are describ[  129.507279] systemd[1]: varlink-12: varlink: setting state idle-server
ed in the
individual fi[  129.516289] systemd[1]: varlink-12: New incoming message: {"method":"io.systemd.UserDatabase.GetUserRecord","parameters":{"userName":"pi","service":"io.systemd.DynamicUser"}}
les in /usr/share/doc/*/[  129.533592] systemd[1]: varlink-12: varlink: changing state idle-server → processing-method
copyright.

Debian GNU[  129.544147] systemd[1]: varlink-12: Sending message: {"error":"io.systemd.UserDatabase.NoRecordFound","parameters":{}}
/Linux comes with ABSOLU[  129.556844] systemd[1]: varlink-12: varlink: changing state processing-method → processed-method
TELY NO WARRANTY, to the[  129.567870] systemd[1]: varlink-12: varlink: changing state processed-method → idle-server
 extent
permitted by ap[  129.578569] systemd[1]: varlink-12: Got POLLHUP from socket.
plicable law.
Last login: Wed J[  129.587294] systemd[1]: varlink-12: varlink: changing state idle-server → pending-disconnect
un 14 08:18:07 CST 2023 [  129.597825] systemd[1]: varlink-12: varlink: changing state pending-disconnect → processing-disconnect
on ttyAMA0
[  129.609048] systemd[1]: varlink-12: varlink: changing state processing-disconnect → disconnected
[  129.619120] systemd[1]: n/a: New incoming connection.
[  129.624252] systemd[1]: n/a: Connections of user 0: 0 (of 1024 max)
[  129.630546] systemd[1]: varlink-12: varlink: setting state idle-server
[  129.637168] systemd[1]: varlink-12: New incoming message: {"method":"io.systemd.UserDatabase.GetUserRecord","parameters":{"uid":1000,"service":"io.systemd.DynamicUser"}}
[  129.652367] systemd[1]: varlink-12: varlink: changing state idle-server → processing-method
[  129.660945] systemd[1]: varlink-12: Sending message: {"error":"io.systemd.UserDatabase.NoRecordFound","parameters":{}}
[  129.671660] systemd[1]: varlink-12: varlink: changing state processing-method → processed-method
[  129.680636] systemd[1]: varlink-12: varlink: changing state processed-method → idle-server
[  129.689288] systemd[1]: varlink-12: Got POLLHUP from socket.
[  129.695056] systemd[1]: varlink-12: varlink: changing state idle-server → pending-disconnect
[  129.703722] systemd[1]: varlink-12: varlink: changing state pending-disconnect → processing-disconnect
[  129.713226] systemd[1]: varlink-12: varlink: changing state processing-disconnect → disconnected
[  129.722331] systemd[1]: Got message type=method_call sender=:1.5 destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=StartUnit cookie=15 reply_cookie=0 signature=ss error-name=n/a error-message=n/a
[  129.751276] systemd[1]: Sent message type=method_call sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=GetConnectionUnixUser cookie=195 reply_cookie=0 signature=s error-name=n/a error-message=n/a
[  129.773959] systemd[1]: Got message type=method_return sender=org.freedesktop.DBus destination=:1.2 path=n/a interface=n/a member=n/a cookie=23 reply_cookie=195 signature=u error-name=n/a error-message=n/a
[  129.792322] systemd[1]: user@1000.service: Trying to enqueue job user@1000.service/start/replace
[  129.801180] systemd[1]: Added job user@1000.service/start to transaction.
[  129.808039] systemd[1]: Pulling in sysinit.target/start from user@1000.service/start
[  129.815813] systemd[1]: Added job sysinit.target/start to transaction.
[  129.822374] systemd[1]: Pulling in dev-hugepages.mount/start from sysinit.target/start
[  129.830319] systemd[1]: Added job dev-hugepages.mount/start to transaction.
[  129.837298] systemd[1]: Pulling in -.slice/start from dev-hugepages.mount/start
[  129.844626] systemd[1]: Added job -.slice/start to transaction.
[  129.850562] systemd[1]: Pulling in -.mount/start from dev-hugepages.mount/start
[  129.857890] systemd[1]: Added job -.mount/start to transaction.
[  129.863825] systemd[1]: Pulling in -.slice/start from -.mount/start
[  129.870110] systemd[1]: Pulling in proc-sys-fs-binfmt_misc.automount/start from sysinit.target/start
[  129.879261] systemd[1]: Added job proc-sys-fs-binfmt_misc.automount/start to transaction.
[  129.887456] systemd[1]: Pulling in -.mount/start from proc-sys-fs-binfmt_misc.automount/start
[  129.896000] systemd[1]: Pulling in systemd-ask-password-console.path/start from sysinit.target/start
[  129.905164] systemd[1]: Added job systemd-ask-password-console.path/start to transaction.
[  129.913359] systemd[1]: Pulling in -.mount/start from systemd-ask-password-console.path/start
[  129.921903] systemd[1]: Pulling in shutdown.target/stop from systemd-ask-password-console.path/start
[  129.931059] systemd[1]: Added job shutdown.target/stop to transaction.
[  129.937618] systemd[1]: Pulling in emergency.service/stop from systemd-ask-password-console.path/start
[  129.946946] systemd[1]: Added job emergency.service/stop to transaction.
[  129.953666] systemd[1]: Pulling in emergency.target/stop from emergency.service/stop
[  129.961427] systemd[1]: Added job emergency.target/stop to transaction.
[  129.968058] systemd[1]: Pulling in systemd-pstore.service/start from sysinit.target/start
[  129.976255] systemd[1]: Added job systemd-pstore.service/start to transaction.
[  129.983494] systemd[1]: Pulling in -.mount/start from systemd-pstore.service/start
[  129.991081] systemd[1]: Pulling in system.slice/start from systemd-pstore.service/start
[  129.999102] systemd[1]: Added job system.slice/start to transaction.
[  130.005473] systemd[1]: Pulling in -.slice/start from system.slice/start
[  130.012192] systemd[1]: Pulling in shutdown.target/stop from systemd-pstore.service/start
[  130.020389] systemd[1]: Pulling in systemd-update-utmp.service/start from sysinit.target/start
[  130.029031] systemd[1]: Added job systemd-update-utmp.service/start to transaction.
[  130.036706] systemd[1]: Pulling in -.mount/start from systemd-update-utmp.service/start
[  130.044728] systemd[1]: Pulling in system.slice/start from systemd-update-utmp.service/start
[  130.053187] systemd[1]: Pulling in shutdown.target/stop from systemd-update-utmp.service/start
[  130.061831] systemd[1]: Pulling in sys-kernel-config.mount/start from sysinit.target/start
[  130.070119] systemd[1]: Added job sys-kernel-config.mount/start to transaction.
[  130.077450] systemd[1]: Pulling in modprobe@configfs.service/start from sys-kernel-config.mount/start
[  130.086689] systemd[1]: Added job modprobe@configfs.service/start to transaction.
[  130.094188] systemd[1]: Pulling in system-modprobe.slice/start from modprobe@configfs.service/start
[  130.103253] systemd[1]: Added job system-modprobe.slice/start to transaction.
[  130.110406] systemd[1]: Pulling in system.slice/start from system-modprobe.slice/start
[  130.118342] systemd[1]: Pulling in shutdown.target/stop from system-modprobe.slice/start
[  130.126453] systemd[1]: Pulling in -.mount/start from sys-kernel-config.mount/start
[  130.134128] systemd[1]: Pulling in -.slice/start from sys-kernel-config.mount/start
[  130.141804] systemd[1]: Pulling in keyboard-setup.service/start from sysinit.target/start
[  130.150000] systemd[1]: Added job keyboard-setup.service/start to transaction.
[  130.157239] systemd[1]: Pulling in system.slice/start from keyboard-setup.service/start
[  130.165261] systemd[1]: Pulling in local-fs-pre.target/start from keyboard-setup.service/start
[  130.173893] systemd[1]: Added job local-fs-pre.target/start to transaction.
[  130.180879] systemd[1]: Pulling in shutdown.target/stop from local-fs-pre.target/start
[  130.188825] systemd[1]: Pulling in local-fs.target/start from sysinit.target/start
[  130.196414] systemd[1]: Added job local-fs.target/start to transaction.
[  130.203045] systemd[1]: Pulling in boot.mount/start from local-fs.target/start
[  130.210285] systemd[1]: Added job boot.mount/start to transaction.
[  130.216486] systemd[1]: Pulling in systemd-fsck@dev-disk-by\x2dpartuuid-b080c534\x2d01.service/start from boot.mount/start
[  130.227548] systemd[1]: Added job systemd-fsck@dev-disk-by\x2dpartuuid-b080c534\x2d01.service/start to transaction.
[  130.238003] systemd[1]: Pulling in system-systemd\x2dfsck.slice/start from systemd-fsck@dev-disk-by\x2dpartuuid-b080c534\x2d01.service/start
[  130.250628] systemd[1]: Added job system-systemd\x2dfsck.slice/start to transaction.
[  130.258391] systemd[1]: Pulling in system.slice/start from system-systemd\x2dfsck.slice/start
[  130.266934] systemd[1]: Pulling in shutdown.target/stop from system-systemd\x2dfsck.slice/start
[  130.275652] systemd[1]: Pulling in dev-disk-by\x2dpartuuid-b080c534\x2d01.device/start from systemd-fsck@dev-disk-by\x2dpartuuid-b080c534\x2d01.service/start
[  130.289755] systemd[1]: Added job dev-disk-by\x2dpartuuid-b080c534\x2d01.device/start to transaction.
[  130.299004] systemd[1]: Pulling in dev-disk-by\x2dlabel-bootfs.device/start from dev-disk-by\x2dpartuuid-b080c534\x2d01.device/start
[  130.310945] systemd[1]: Added job dev-disk-by\x2dlabel-bootfs.device/start to transaction.
[  130.319241] systemd[1]: Pulling in dev-disk-by\x2dpartuuid-b080c534\x2d01.device/start from dev-disk-by\x2dlabel-bootfs.device/start
[  130.331173] systemd[1]: Pulling in dev-disk-by\x2did-mmc\x2dSR64G_0x171a43be\x2dpart1.device/start from dev-disk-by\x2dlabel-bootfs.device/start
[  130.344163] systemd[1]: Added job dev-disk-by\x2did-mmc\x2dSR64G_0x171a43be\x2dpart1.device/start to transaction.
[  130.354456] systemd[1]: Pulling in dev-disk-by\x2dpath-platform\x2dfe340000.mmc\x2dpart1.device/start from dev-disk-by\x2did-mmc\x2dSR64G_0x171a43be\x2dpart1.device/start
[  130.369690] systemd[1]: Added job dev-disk-by\x2dpath-platform\x2dfe340000.mmc\x2dpart1.device/start to transaction.
[  130.380237] systemd[1]: Pulling in sys-devices-platform-emmc2bus-fe340000.mmc-mmc_host-mmc0-mmc0:aaaa-block-mmcblk0-mmcblk0p1.device/start from dev-disk-by\x2dpath-platform\x2dfe340000.mmc\x2dpart1.device/start
[  130.398943] systemd[1]: Added job sys-devices-platform-emmc2bus-fe340000.mmc-mmc_host-mmc0-mmc0:aaaa-block-mmcblk0-mmcblk0p1.device/start to transaction.
[  130.412815] systemd[1]: Pulling in dev-disk-by\x2dpath-platform\x2dfe340000.mmc\x2dpart1.device/start from sys-devices-platform-emmc2bus-fe340000.mmc-mmc_host-mmc0-mmc0:aaaa-block-mmcblk0-mmcblk0p1.device/start
[  130.431534] systemd[1]: Pulling in dev-disk-by\x2duuid-2EAB\x2d4294.device/start from sys-devices-platform-emmc2bus-fe340000.mmc-mmc_host-mmc0-mmc0:aaaa-block-mmcblk0-mmcblk0p1.device/start
[  130.448425] systemd[1]: Added job dev-disk-by\x2duuid-2EAB\x2d4294.device/start to transaction.
[  130.457149] systemd[1]: Pulling in sys-devices-platform-emmc2bus-fe340000.mmc-mmc_host-mmc0-mmc0:aaaa-block-mmcblk0-mmcblk0p1.device/start from dev-disk-by\x2duuid-2EAB\x2d4294.device/start
[  130.474032] systemd[1]: Pulling in dev-disk-by\x2dpath-platform\x2dfe340000.mmc\x2dpart1.device/start from dev-disk-by\x2duuid-2EAB\x2d4294.device/start
[  130.487700] systemd[1]: Pulling in dev-mmcblk0p1.device/start from dev-disk-by\x2duuid-2EAB\x2d4294.device/start
[  130.497894] systemd[1]: Added job dev-mmcblk0p1.device/start to transaction.
[  130.504966] systemd[1]: Pulling in sys-devices-platform-emmc2bus-fe340000.mmc-mmc_host-mmc0-mmc0:aaaa-block-mmcblk0-mmcblk0p1.device/start from dev-mmcblk0p1.device/start
[  130.520197] systemd[1]: Pulling in dev-disk-by\x2dpath-platform\x2dfe340000.mmc\x2dpart1.device/start from dev-mmcblk0p1.device/start
[  130.532229] systemd[1]: Pulling in dev-disk-by\x2duuid-2EAB\x2d4294.device/start from dev-mmcblk0p1.device/start
[  130.542422] systemd[1]: Pulling in dev-disk-by\x2dpartuuid-b080c534\x2d01.device/start from dev-mmcblk0p1.device/start
[  130.553137] systemd[1]: Pulling in dev-disk-by\x2dlabel-bootfs.device/start from dev-mmcblk0p1.device/start
[  130.562897] systemd[1]: Pulling in dev-disk-by\x2did-mmc\x2dSR64G_0x171a43be\x2dpart1.device/start from dev-mmcblk0p1.device/start
[  130.574660] systemd[1]: Pulling in dev-disk-by\x2dpartuuid-b080c534\x2d01.device/start from dev-disk-by\x2duuid-2EAB\x2d4294.device/start
[  130.587029] systemd[1]: Pulling in dev-disk-by\x2dlabel-bootfs.device/start from dev-disk-by\x2duuid-2EAB\x2d4294.device/start
[  130.598469] systemd[1]: Pulling in dev-disk-by\x2did-mmc\x2dSR64G_0x171a43be\x2dpart1.device/start from dev-disk-by\x2duuid-2EAB\x2d4294.device/start
[  130.611892] systemd[1]: Pulling in dev-mmcblk0p1.device/start from sys-devices-platform-emmc2bus-fe340000.mmc-mmc_host-mmc0-mmc0:aaaa-block-mmcblk0-mmcblk0p1.device/start
[  130.627131] systemd[1]: Pulling in dev-disk-by\x2dpartuuid-b080c534\x2d01.device/start from sys-devices-platform-emmc2bus-fe340000.mmc-mmc_host-mmc0-mmc0:aaaa-block-mmcblk0-mmcblk0p1.device/start
[  130.644556] systemd[1]: Pulling in dev-disk-by\x2dlabel-bootfs.device/start from sys-devices-platform-emmc2bus-fe340000.mmc-mmc_host-mmc0-mmc0:aaaa-block-mmcblk0-mmcblk0p1.device/start
[  130.661012] systemd[1]: Pulling in dev-disk-by\x2did-mmc\x2dSR64G_0x171a43be\x2dpart1.device/start from sys-devices-platform-emmc2bus-fe340000.mmc-mmc_host-mmc0-mmc0:aaaa-block-mmcblk0-mmcblk0p1.device/start
[  130.679463] systemd[1]: Pulling in dev-disk-by\x2duuid-2EAB\x2d4294.device/start from dev-disk-by\x2dpath-platform\x2dfe340000.mmc\x2dpart1.device/start
[  130.693131] systemd[1]: Pulling in dev-mmcblk0p1.device/start from dev-disk-by\x2dpath-platform\x2dfe340000.mmc\x2dpart1.device/start
[  130.705154] systemd[1]: Pulling in dev-disk-by\x2dpartuuid-b080c534\x2d01.device/start from dev-disk-by\x2dpath-platform\x2dfe340000.mmc\x2dpart1.device/start
[  130.719344] systemd[1]: Pulling in dev-disk-by\x2dlabel-bootfs.device/start from dev-disk-by\x2dpath-platform\x2dfe340000.mmc\x2dpart1.device/start
[  130.732577] systemd[1]: Pulling in dev-disk-by\x2did-mmc\x2dSR64G_0x171a43be\x2dpart1.device/start from dev-disk-by\x2dpath-platform\x2dfe340000.mmc\x2dpart1.device/start
[  130.747811] systemd[1]: Pulling in sys-devices-platform-emmc2bus-fe340000.mmc-mmc_host-mmc0-mmc0:aaaa-block-mmcblk0-mmcblk0p1.device/start from dev-disk-by\x2did-mmc\x2dSR64G_0x171a43be\x2dpart1.device/start
[  130.766258] systemd[1]: Pulling in dev-disk-by\x2duuid-2EAB\x2d4294.device/start from dev-disk-by\x2did-mmc\x2dSR64G_0x171a43be\x2dpart1.device/start
[  130.779667] systemd[1]: Pulling in dev-mmcblk0p1.device/start from dev-disk-by\x2did-mmc\x2dSR64G_0x171a43be\x2dpart1.device/start
[  130.791431] systemd[1]: Pulling in dev-disk-by\x2dpartuuid-b080c534\x2d01.device/start from dev-disk-by\x2did-mmc\x2dSR64G_0x171a43be\x2dpart1.device/start
[  130.805363] systemd[1]: Pulling in dev-disk-by\x2dlabel-bootfs.device/start from dev-disk-by\x2did-mmc\x2dSR64G_0x171a43be\x2dpart1.device/start
[  130.818338] systemd[1]: Pulling in dev-mmcblk0p1.device/start from dev-disk-by\x2dlabel-bootfs.device/start
[  130.828098] systemd[1]: Pulling in dev-disk-by\x2dpath-platform\x2dfe340000.mmc\x2dpart1.device/start from dev-disk-by\x2dlabel-bootfs.device/start
[  130.841336] systemd[1]: Pulling in sys-devices-platform-emmc2bus-fe340000.mmc-mmc_host-mmc0-mmc0:aaaa-block-mmcblk0-mmcblk0p1.device/start from dev-disk-by\x2dlabel-bootfs.device/start
[  130.857784] systemd[1]: Pulling in dev-disk-by\x2duuid-2EAB\x2d4294.device/start from dev-disk-by\x2dlabel-bootfs.device/start
[  130.869195] systemd[1]: Pulling in dev-disk-by\x2did-mmc\x2dSR64G_0x171a43be\x2dpart1.device/start from dev-disk-by\x2dpartuuid-b080c534\x2d01.device/start
[  130.883123] systemd[1]: Pulling in dev-mmcblk0p1.device/start from dev-disk-by\x2dpartuuid-b080c534\x2d01.device/start
[  130.893838] systemd[1]: Pulling in dev-disk-by\x2dpath-platform\x2dfe340000.mmc\x2dpart1.device/start from dev-disk-by\x2dpartuuid-b080c534\x2d01.device/start
[  130.908030] systemd[1]: Pulling in sys-devices-platform-emmc2bus-fe340000.mmc-mmc_host-mmc0-mmc0:aaaa-block-mmcblk0-mmcblk0p1.device/start from dev-disk-by\x2dpartuuid-b080c534\x2d01.device/start
[  130.925442] systemd[1]: Pulling in dev-disk-by\x2duuid-2EAB\x2d4294.device/start from dev-disk-by\x2dpartuuid-b080c534\x2d01.device/start
[  130.937813] systemd[1]: Pulling in systemd-fsckd.socket/start from systemd-fsck@dev-disk-by\x2dpartuuid-b080c534\x2d01.service/start
[  130.949748] systemd[1]: Added job systemd-fsckd.socket/start to transaction.
[  130.956814] systemd[1]: Pulling in -.mount/start from systemd-fsckd.socket/start
[  130.964236] systemd[1]: Pulling in system.slice/start from systemd-fsckd.socket/start
[  130.972084] systemd[1]: Pulling in shutdown.target/stop from systemd-fsck@dev-disk-by\x2dpartuuid-b080c534\x2d01.service/start
[  130.983498] systemd[1]: Pulling in system.slice/start from boot.mount/start
[  130.990477] systemd[1]: Pulling in -.mount/start from boot.mount/start
[  130.997022] systemd[1]: Pulling in dev-disk-by\x2dpartuuid-b080c534\x2d01.device/start from boot.mount/start
[  131.006868] systemd[1]: Pulling in dev-mmcblk0p1.device/start from boot.mount/start
[  131.014542] systemd[1]: Pulling in umount.target/stop from boot.mount/start
[  131.021523] systemd[1]: Added job umount.target/stop to transaction.
[  131.027894] systemd[1]: Pulling in -.mount/start from local-fs.target/start
[  131.034873] systemd[1]: Pulling in systemd-fsck-root.service/start from local-fs.target/start
[  131.043419] systemd[1]: Added job systemd-fsck-root.service/start to transaction.
[  131.050927] systemd[1]: Pulling in system.slice/start from systemd-fsck-root.service/start
[  131.059213] systemd[1]: Pulling in systemd-fsckd.socket/start from systemd-fsck-root.service/start
[  131.068191] systemd[1]: Pulling in shutdown.target/stop from systemd-fsck-root.service/start
[  131.076649] systemd[1]: Pulling in systemd-remount-fs.service/start from local-fs.target/start
[  131.085279] systemd[1]: Added job systemd-remount-fs.service/start to transaction.
[  131.092871] systemd[1]: Pulling in system.slice/start from systemd-remount-fs.service/start
[  131.101241] systemd[1]: Pulling in local-fs-pre.target/start from systemd-remount-fs.service/start
[  131.110219] systemd[1]: Pulling in shutdown.target/stop from systemd-remount-fs.service/start
[  131.118762] systemd[1]: Pulling in shutdown.target/stop from local-fs.target/start
[  131.126351] systemd[1]: Pulling in cryptsetup.target/start from sysinit.target/start
[  131.134114] systemd[1]: Added job cryptsetup.target/start to transaction.
[  131.140919] systemd[1]: Pulling in shutdown.target/stop from cryptsetup.target/start
[  131.148680] systemd[1]: Pulling in swap.target/start from sysinit.target/start
[  131.155920] systemd[1]: Added job swap.target/start to transaction.
[  131.162203] systemd[1]: Pulling in shutdown.target/stop from swap.target/start
[  131.169446] systemd[1]: Pulling in systemd-sysctl.service/start from sysinit.target/start
[  131.177651] systemd[1]: Added job systemd-sysctl.service/start to transaction.
[  131.184895] systemd[1]: Pulling in system.slice/start from systemd-sysctl.service/start
[  131.192917] systemd[1]: Pulling in shutdown.target/stop from systemd-sysctl.service/start
[  131.201112] systemd[1]: Pulling in fake-hwclock.service/start from sysinit.target/start
[  131.209134] systemd[1]: Added job fake-hwclock.service/start to transaction.
[  131.216198] systemd[1]: Pulling in system.slice/start from fake-hwclock.service/start
[  131.224051] systemd[1]: Pulling in shutdown.target/stop from fake-hwclock.service/start
[  131.232073] systemd[1]: Pulling in sys-kernel-tracing.mount/start from sysinit.target/start
[  131.240443] systemd[1]: Added job sys-kernel-tracing.mount/start to transaction.
[  131.247855] systemd[1]: Pulling in -.slice/start from sys-kernel-tracing.mount/start
[  131.255616] systemd[1]: Pulling in -.mount/start from sys-kernel-tracing.mount/start
[  131.263379] systemd[1]: Pulling in kmod-static-nodes.service/start from sysinit.target/start
[  131.271835] systemd[1]: Added job kmod-static-nodes.service/start to transaction.
[  131.279335] systemd[1]: Pulling in system.slice/start from kmod-static-nodes.service/start
[  131.287617] systemd[1]: Pulling in systemd-binfmt.service/start from sysinit.target/start
[  131.295815] systemd[1]: Added job systemd-binfmt.service/start to transaction.
[  131.303062] systemd[1]: Pulling in system.slice/start from systemd-binfmt.service/start
[  131.311087] systemd[1]: Pulling in shutdown.target/stop from systemd-binfmt.service/start
[  131.319283] systemd[1]: Pulling in systemd-udevd.service/start from sysinit.target/start
[  131.327392] systemd[1]: Added job systemd-udevd.service/start to transaction.
[  131.334544] systemd[1]: Pulling in system.slice/start from systemd-udevd.service/start
[  131.342479] systemd[1]: Pulling in systemd-udevd-control.socket/start from systemd-udevd.service/start
[  131.351810] systemd[1]: Added job systemd-udevd-control.socket/start to transaction.
[  131.359571] systemd[1]: Pulling in -.mount/start from systemd-udevd-control.socket/start
[  131.367680] systemd[1]: Pulling in system.slice/start from systemd-udevd-control.socket/start
[  131.376236] systemd[1]: Pulling in systemd-udevd-kernel.socket/start from systemd-udevd.service/start
[  131.385475] systemd[1]: Added job systemd-udevd-kernel.socket/start to transaction.
[  131.393149] systemd[1]: Pulling in system.slice/start from systemd-udevd-kernel.socket/start
[  131.401605] systemd[1]: Pulling in systemd-random-seed.service/start from sysinit.target/start
[  131.410236] systemd[1]: Added job systemd-random-seed.service/start to transaction.
[  131.417910] systemd[1]: Pulling in -.mount/start from systemd-random-seed.service/start
[  131.426040] systemd[1]: Pulling in system.slice/start from systemd-random-seed.service/start
[  131.472948] systemd-journald[145]: Successfully sent stream file descriptor to service manager.
[  131.488467] systemd-user-runtime-dir[832]: SELinux enabled state cached to: disabled
[  131.496927] systemd-user-runtime-dir[832]: Bus n/a: changing state UNSET → OPENING
[  131.504721] systemd-user-runtime-dir[832]: sd-bus: starting bus by connecting to /run/dbus/system_bus_socket...
[  131.514917] systemd-user-runtime-dir[832]: Bus n/a: changing state OPENING → AUTHENTICATING
[  131.523633] systemd-user-runtime-dir[832]: Bus n/a: changing state AUTHENTICATING → HELLO
[  131.532031] systemd-user-runtime-dir[832]: Sent message type=method_call sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=Hello cookie=1 reply_cookie=0 signature=n/a error-name=n/a error-message=n/a
[  131.554964] systemd-user-runtime-dir[832]: Got message type=method_return sender=org.freedesktop.DBus destination=:1.10 path=n/a interface=n/a member=n/a cookie=1 reply_cookie=1 signature=s error-name=n/a error-message=n/a
[  131.574745] systemd-user-runtime-dir[832]: Bus n/a: changing state HELLO → RUNNING
[  131.582537] systemd-user-runtime-dir[832]: Sent message type=method_call sender=n/a destination=org.freedesktop.login1 path=/org/freedesktop/login1 interface=org.freedesktop.DBus.Properties member=Get cookie=2 reply_cookie=0 signature=ss error-name=n/a error-message=n/a
[  131.606553] systemd-user-runtime-dir[832]: Got message type=method_return sender=:1.5 destination=:1.10 path=n/a interface=n/a member=n/a cookie=20 reply_cookie=2 signature=v error-name=n/a error-message=n/a
[  131.625069] systemd-user-runtime-dir[832]: Sent message type=method_call sender=n/a destination=org.freedesktop.login1 path=/org/freedesktop/login1 interface=org.freedesktop.DBus.Properties member=Get cookie=3 reply_cookie=0 signature=ss error-name=n/a error-message=n/a
[  131.649111] systemd-user-runtime-dir[832]: Got message type=method_return sender=:1.5 destination=:1.10 path=n/a interface=n/a member=n/a cookie=21 reply_cookie=3 signature=v error-name=n/a error-message=n/a
[  131.667584] systemd-user-runtime-dir[832]: Bus n/a: changing state RUNNING → CLOSED
[  131.675505] systemd-user-runtime-dir[832]: Will mount /run/user/1000 owned by 1000:1000
[  131.683731] systemd-user-runtime-dir[832]: Mounting tmpfs (tmpfs) on /run/user/1000 (MS_NOSUID|MS_NODEV "mode=0700,uid=1000,gid=1000,size=397389824,nr_inodes=97019")...
[  131.752918] systemd-journald[145]: Successfully sent stream file descriptor to service manager.
[  131.788460] systemd-journald[145]: Journal effective settings seal=yes keyed_hash=no compress=yes compress_threshold_bytes=512B
[  131.801211] systemd-journald[145]: Fixed min_use=152.0M max_use=4.0G max_size=128.0M min_size=512.0K keep_free=2.9G n_max_files=100
[  131.966157] systemd-journald[145]: Journal effective settings seal=no keyed_hash=no compress=yes compress_threshold_bytes=512B
[  132.151645] systemd-journald[145]: Successfully sent stream file descriptor to service manager.
pi@rasp4yzm:~$
pi@rasp4yzm:~$ clear
pi@rasp4yzm:~$ sudo reboot
[  151.349717] systemd[1]: Bus private-bus-connection: changing state UNSET → OPENING
[  151.357691] systemd[1]: sd-bus: starting bus private-bus-connection on fds 12/12 (socket:[14314], socket:[14314])...
[  151.368440] systemd[1]: Bus private-bus-connection: changing state OPENING → AUTHENTICATING
[  151.377245] systemd[1]: Registering bus object implementation for path=/org/freedesktop/systemd1 iface=org.freedesktop.systemd1.Manager
[  151.390439] systemd[1]: Registering bus object implementation for path=/org/freedesktop/systemd1/job iface=org.freedesktop.systemd1.Job
[  151.402734] systemd[1]: Registering bus object implementation for path=/org/freedesktop/systemd1/unit iface=org.freedesktop.systemd1.Unit
[  151.415748] systemd[1]: Registering bus object implementation for path=/org/freedesktop/systemd1/unit iface=org.freedesktop.systemd1.Automount
[  151.428598] systemd[1]: Registering bus object implementation for path=/org/freedesktop/systemd1/unit iface=org.freedesktop.systemd1.Device
[  151.441154] systemd[1]: Registering bus object implementation for path=/org/freedesktop/systemd1/unit iface=org.freedesktop.systemd1.Mount
[  151.454156] systemd[1]: Registering bus object implementation for path=/org/freedesktop/systemd1/unit iface=org.freedesktop.systemd1.Path
[  151.466535] systemd[1]: Registering bus object implementation for path=/org/freedesktop/systemd1/unit iface=org.freedesktop.systemd1.Scope
[  151.479101] systemd[1]: Registering bus object implementation for path=/org/freedesktop/systemd1/unit iface=org.freedesktop.systemd1.Service
[  151.492635] systemd[1]: Registering bus object implementation for path=/org/freedesktop/systemd1/unit iface=org.freedesktop.systemd1.Slice
[  151.505162] systemd[1]: Registering bus object implementation for path=/org/freedesktop/systemd1/unit iface=org.freedesktop.systemd1.Socket
[  151.518015] systemd[1]: Registering bus object implementation for path=/org/freedesktop/systemd1/unit iface=org.freedesktop.systemd1.Swap
[  151.530748] systemd[1]: Registering bus object implementation for path=/org/freedesktop/systemd1/unit iface=org.freedesktop.systemd1.Target
[  151.543292] systemd[1]: Registering bus object implementation for path=/org/freedesktop/systemd1/unit iface=org.freedesktop.systemd1.Timer
[  151.555772] systemd[1]: Registering bus object implementation for path=/org/freedesktop/LogControl1 iface=org.freedesktop.LogControl1
[  151.567822] systemd[1]: Accepted new private connection.
[  151.573321] systemd[1]: Bus private-bus-connection: changing state AUTHENTICATING → RUNNING
[  151.581949] systemd[1]: Got message type=method_call sender=n/a destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=StartUnit cookie=1 reply_cookie=0 signature=ss error-name=n/a error-message=n/a
[  151.605240] systemd[1]: unit_file_find_fragment: reboot.target has alias runlevel6.target
[  151.613441] systemd[1]: unit_file_find_fragment: reboot.target has alias ctrl-alt-del.target
[  151.626794] systemd[1]: reboot.target: Trying to enqueue job reboot.target/start/replace-irreversibly
[  151.636064] systemd[1]: Added job reboot.target/start to transaction.
[  151.642525] systemd[1]: Pulling in systemd-reboot.service/start from reboot.target/start
[  151.650636] systemd[1]: Added job systemd-reboot.service/start to transaction.
[  151.657876] systemd[1]: Pulling in system.slice/start from systemd-reboot.service/start
[  151.665900] systemd[1]: Added job system.slice/start to transaction.
[  151.672270] systemd[1]: Pulling in -.slice/start from system.slice/start
[  151.678986] systemd[1]: Added job -.slice/start to transaction.
[  151.684923] systemd[1]: Pulling in umount.target/start from systemd-reboot.service/start
[  151.693030] systemd[1]: Added job umount.target/start to transaction.
[  151.699486] systemd[1]: Pulling in boot.mount/stop from umount.target/start
[  151.706464] systemd[1]: Added job boot.mount/stop to transaction.
[  151.712573] systemd[1]: Pulling in local-fs.target/stop from boot.mount/stop
[  151.719650] systemd[1]: Added job local-fs.target/stop to transaction.
[  151.726195] systemd[1]: Pulling in rpc-gssd.service/stop from umount.target/start
[  151.733702] systemd[1]: Added job rpc-gssd.service/stop to transaction.
[  151.740336] systemd[1]: Pulling in run-rpc_pipefs.mount/stop from umount.target/start
[  151.748194] systemd[1]: Added job run-rpc_pipefs.mount/stop to transaction.
[  151.755189] systemd[1]: Pulling in rpc-svcgssd.service/stop from run-rpc_pipefs.mount/stop
[  151.763471] systemd[1]: Added job rpc-svcgssd.service/stop to transaction.
[  151.770361] systemd[1]: Pulling in rpc-gssd.service/stop from run-rpc_pipefs.mount/stop
[  151.778385] systemd[1]: Pulling in run-user-1000.mount/stop from umount.target/start
[  151.786145] systemd[1]: Added job run-user-1000.mount/stop to transaction.
[  151.793036] systemd[1]: Pulling in var-swap.swap/stop from umount.target/start
[  151.800274] systemd[1]: Added job var-swap.swap/stop to transaction.
[  151.806645] systemd[1]: Pulling in final.target/start from systemd-reboot.service/start
[  151.814678] systemd[1]: Added job final.target/start to transaction.
[  151.821049] systemd[1]: Pulling in shutdown.target/start from systemd-reboot.service/start
[  151.829329] systemd[1]: Added job shutdown.target/start to transaction.
[  151.835960] systemd[1]: Pulling in systemd-random-seed.service/stop from shutdown.target/start
[  151.844590] systemd[1]: Added job systemd-random-seed.service/stop to transaction.
[  151.852176] systemd[1]: Pulling in polkit.service/stop from shutdown.target/start
[  151.859684] systemd[1]: Added job polkit.service/stop to transaction.
[  151.866149] systemd[1]: Pulling in ModemManager.service/stop from polkit.service/stop
[  151.874005] systemd[1]: Added job ModemManager.service/stop to transaction.
[  151.880984] systemd[1]: Pulling in e2scrub_all.timer/stop from shutdown.target/start
[  151.888746] systemd[1]: Added job e2scrub_all.timer/stop to transaction.
[  151.895464] systemd[1]: Pulling in systemd-networkd.service/stop from shutdown.target/start
[  151.903832] systemd[1]: Added job systemd-networkd.service/stop to transaction.
[  151.911253] systemd[1]: Pulling in systemd-networkd-wait-online.service/stop from systemd-networkd.service/stop
[  151.921387] systemd[1]: Added job systemd-networkd-wait-online.service/stop to transaction.
[  151.929760] systemd[1]: Pulling in rng-tools-debian.service/stop from shutdown.target/start
[  151.938129] systemd[1]: Added job rng-tools-debian.service/stop to transaction.
[  151.945456] systemd[1]: Pulling in network-online.target/stop from shutdown.target/start
[  151.953563] systemd[1]: Added job network-online.target/stop to transaction.
[  151.960631] systemd[1]: Pulling in wpa_supplicant.service/stop from shutdown.target/start
[  151.968826] systemd[1]: Added job wpa_supplicant.service/stop to transaction.
[  151.975977] systemd[1]: Pulling in fstrim.timer/stop from shutdown.target/start
[  151.983309] systemd[1]: Added job fstrim.timer/stop to transaction.
[  151.989593] systemd[1]: Pulling in hciuart.service/stop from shutdown.target/start
[  151.997216] systemd[1]: Added job hciuart.service/stop to transaction.
[  152.003762] systemd[1]: Pulling in systemd-user-sessions.service/stop from shutdown.target/start
[  152.012565] systemd[1]: Added job systemd-user-sessions.service/stop to transaction.
[  152.020325] systemd[1]: Pulling in systemd-pstore.service/stop from shutdown.target/start
[  152.028521] systemd[1]: Added job systemd-pstore.service/stop to transaction.
[  152.035674] systemd[1]: Pulling in systemd-ask-password-wall.path/stop from shutdown.target/start
[  152.044572] systemd[1]: Added job systemd-ask-password-wall.path/stop to transaction.
[  152.052423] systemd[1]: Pulling in user@1000.service/stop from shutdown.target/start
[  152.060183] systemd[1]: Added job user@1000.service/stop to transaction.
[  152.066950] systemd[1]: Pulling in rpi-eeprom-update.service/stop from shutdown.target/start
[  152.075414] systemd[1]: Added job rpi-eeprom-update.service/stop to transaction.
[  152.082831] systemd[1]: Pulling in getty-pre.target/stop from shutdown.target/start
[  152.090505] systemd[1]: Added job getty-pre.target/stop to transaction.
[  152.097163] systemd[1]: Pulling in systemd-machine-id-commit.service/stop from shutdown.target/start
[  152.106326] systemd[1]: Added job systemd-machine-id-commit.service/stop to transaction.
[  152.114552] systemd[1]: Pulling in dphys-swapfile.service/stop from shutdown.target/start
[  152.122761] systemd[1]: Added job dphys-swapfile.service/stop to transaction.
[  152.129917] systemd[1]: Pulling in dbus.service/stop from shutdown.target/start
[  152.137243] systemd[1]: Added job dbus.service/stop to transaction.
[  152.143527] systemd[1]: Pulling in e2scrub_all.service/stop from shutdown.target/start
[  152.151461] systemd[1]: Added job e2scrub_all.service/stop to transaction.
[  152.158352] systemd[1]: Pulling in systemd-fsck@dev-disk-by\x2dpartuuid-b080c534\x2d01.service/stop from shutdown.target/start
[  152.169760] systemd[1]: Added job systemd-fsck@dev-disk-by\x2dpartuuid-b080c534\x2d01.service/stop to transaction.
[  152.180125] systemd[1]: Pulling in boot.mount/stop from systemd-fsck@dev-disk-by\x2dpartuuid-b080c534\x2d01.service/stop
[  152.191013] systemd[1]: Pulling in raspberrypi-net-mods.service/stop from shutdown.target/start
[  152.199730] systemd[1]: Added job raspberrypi-net-mods.service/stop to transaction.
[  152.207404] systemd[1]: Pulling in access_point.service/stop from shutdown.target/start
[  152.215425] systemd[1]: Added job access_point.service/stop to transaction.
[  152.222403] systemd[1]: Pulling in paths.target/stop from shutdown.target/start
[  152.229739] systemd[1]: Added job paths.target/stop to transaction.
[  152.236029] systemd[1]: Pulling in systemd-ask-password-console.service/stop from shutdown.target/start
[  152.245443] systemd[1]: Added job systemd-ask-password-console.service/stop to transaction.
[  152.253810] systemd[1]: Pulling in nfs-utils.service/stop from shutdown.target/start
[  152.261570] systemd[1]: Added job nfs-utils.service/stop to transaction.
[  152.268288] systemd[1]: Pulling in rpc-svcgssd.service/stop from nfs-utils.service/stop
[  152.276314] systemd[1]: Pulling in rpc-gssd.service/stop from nfs-utils.service/stop
[  152.284075] systemd[1]: Pulling in dbus.socket/stop from shutdown.target/start
[  152.291332] systemd[1]: Added job dbus.socket/stop to transaction.
[  152.297530] systemd[1]: Pulling in wpa_supplicant.service/stop from dbus.socket/stop
[  152.305290] systemd[1]: Pulling in udisks2.service/stop from dbus.socket/stop
[  152.312442] systemd[1]: Added job udisks2.service/stop to transaction.
[  152.318987] systemd[1]: Pulling in systemd-logind.service/stop from dbus.socket/stop
[  152.326746] systemd[1]: Added job systemd-logind.service/stop to transaction.
[  152.333898] systemd[1]: Pulling in dbus.service/stop from dbus.socket/stop
[  152.340790] systemd[1]: Pulling in polkit.service/stop from dbus.socket/stop
[  152.347857] systemd[1]: Pulling in avahi-daemon.service/stop from dbus.socket/stop
[  152.355456] systemd[1]: Added job avahi-daemon.service/stop to transaction.
[  152.362437] systemd[1]: Pulling in ModemManager.service/stop from dbus.socket/stop
[  152.370024] systemd[1]: Pulling in NetworkManager.service/stop from dbus.socket/stop
[  152.377785] systemd[1]: Added job NetworkManager.service/stop to transaction.
[  152.384939] systemd[1]: Pulling in ssh.service/stop from shutdown.target/start
[  152.392178] systemd[1]: Added job ssh.service/stop to transaction.
[  152.398396] systemd[1]: Pulling in systemd-networkd-wait-online.service/stop from shutdown.target/start
[  152.407814] systemd[1]: Pulling in fake-hwclock.service/stop from shutdown.target/start
[  152.415838] systemd[1]: Added job fake-hwclock.service/stop to transaction.
[  152.422816] systemd[1]: Pulling in raspi-config.service/stop from shutdown.target/start
[  152.430877] systemd[1]: Added job raspi-config.service/stop to transaction.
[  152.437857] systemd[1]: Pulling in apt-daily-upgrade.timer/stop from shutdown.target/start
[  152.446138] systemd[1]: Added job apt-daily-upgrade.timer/stop to transaction.
[  152.453378] systemd[1]: Pulling in remote-fs.target/stop from shutdown.target/start
[  152.461053] systemd[1]: Added job remote-fs.target/stop to transaction.
[  152.467685] systemd[1]: Pulling in blockdev@dev-mmcblk0p1.target/stop from shutdown.target/start
[  152.476496] systemd[1]: Added job blockdev@dev-mmcblk0p1.target/stop to transaction.
[  152.484257] systemd[1]: Pulling in system-modprobe.slice/stop from shutdown.target/start
[  152.492366] systemd[1]: Added job system-modprobe.slice/stop to transaction.
[  152.499452] systemd[1]: Pulling in modprobe@fuse.service/stop from system-modprobe.slice/stop
[  152.507997] systemd[1]: Added job modprobe@fuse.service/stop to transaction.
[  152.515061] systemd[1]: Pulling in sys-fs-fuse-connections.mount/stop from modprobe@fuse.service/stop
[  152.524318] systemd[1]: Added job sys-fs-fuse-connections.mount/stop to transaction.
[  152.532081] systemd[1]: Pulling in modprobe@drm.service/stop from system-modprobe.slice/stop
[  152.540539] systemd[1]: Added job modprobe@drm.service/stop to transaction.
[  152.547517] systemd[1]: Pulling in modprobe@configfs.service/stop from system-modprobe.slice/stop
[  152.556406] systemd[1]: Added job modprobe@configfs.service/stop to transaction.
[  152.563818] systemd[1]: Pulling in sys-kernel-config.mount/stop from modprobe@configfs.service/stop
[  152.572882] systemd[1]: Added job sys-kernel-config.mount/stop to transaction.
[  152.580121] systemd[1]: Pulling in emergency.target/stop from shutdown.target/start
[  152.587795] systemd[1]: Added job emergency.target/stop to transaction.
[  152.594424] systemd[1]: Pulling in nss-lookup.target/stop from shutdown.target/start
[  152.602191] systemd[1]: Added job nss-lookup.target/stop to transaction.
[  152.608913] systemd[1]: Pulling in getty.target/stop from shutdown.target/start
[  152.616241] systemd[1]: Added job getty.target/stop to transaction.
[  152.622524] systemd[1]: Pulling in graphical.target/stop from shutdown.target/start
[  152.630198] systemd[1]: Added job graphical.target/stop to transaction.
[  152.636830] systemd[1]: Pulling in time-set.target/stop from shutdown.target/start
[  152.644425] systemd[1]: Added job time-set.target/stop to transaction.
[  152.650972] systemd[1]: Pulling in udisks2.service/stop from shutdown.target/start
[  152.658561] systemd[1]: Pulling in avahi-daemon.service/stop from shutdown.target/start
[  152.666582] systemd[1]: Pulling in apt-daily.service/stop from shutdown.target/start
[  152.674343] systemd[1]: Added job apt-daily.service/stop to transaction.
[  152.681062] systemd[1]: Pulling in systemd-boot-system-token.service/stop from shutdown.target/start
[  152.690212] systemd[1]: Added job systemd-boot-system-token.service/stop to transaction.
[  152.698320] systemd[1]: Pulling in emergency.service/stop from shutdown.target/start
[  152.706080] systemd[1]: Added job emergency.service/stop to transaction.
[  152.712797] systemd[1]: Pulling in emergency.target/stop from emergency.service/stop
[  152.720559] systemd[1]: Pulling in systemd-update-utmp-runlevel.service/stop from shutdown.target/start
[  152.729976] systemd[1]: Added job systemd-update-utmp-runlevel.service/stop to transaction.
[  152.738344] systemd[1]: Pulling in first-boot-complete.target/stop from shutdown.target/start
[  152.746886] systemd[1]: Added job first-boot-complete.target/stop to transaction.
[  152.754389] systemd[1]: Pulling in apt-daily-upgrade.service/stop from shutdown.target/start
[  152.762853] systemd[1]: Added job apt-daily-upgrade.service/stop to transaction.
[  152.770284] systemd[1]: Pulling in sound.target/stop from shutdown.target/start
[  152.777613] systemd[1]: Added job sound.target/stop to transaction.
[  152.783896] systemd[1]: Pulling in containerd.service/stop from shutdown.target/start
[  152.791742] systemd[1]: Added job containerd.service/stop to transaction.
[  152.798546] systemd[1]: Pulling in local-fs.target/stop from shutdown.target/start
[  152.806133] systemd[1]: Pulling in systemd-remount-fs.service/stop from shutdown.target/start
[  152.814675] systemd[1]: Added job systemd-remount-fs.service/stop to transaction.
[  152.822175] systemd[1]: Pulling in hostapd.service/stop from shutdown.target/start
[  152.829761] systemd[1]: Added job hostapd.service/stop to transaction.
[  152.836320] systemd[1]: Pulling in triggerhappy.socket/stop from shutdown.target/start
[  152.844255] systemd[1]: Added job triggerhappy.socket/stop to transaction.
[  152.851146] systemd[1]: Pulling in rescue.service/stop from shutdown.target/start
[  152.858650] systemd[1]: Added job rescue.service/stop to transaction.
[  152.865108] systemd[1]: Pulling in rescue.target/stop from rescue.service/stop
[  152.872348] systemd[1]: Added job rescue.target/stop to transaction.
[  152.878717] systemd[1]: Pulling in logrotate.timer/stop from shutdown.target/start
[  152.886304] systemd[1]: Added job logrotate.timer/stop to transaction.
[  152.892848] systemd[1]: Pulling in network-pre.target/stop from shutdown.target/start
[  152.900697] systemd[1]: Added job network-pre.target/stop to transaction.
[  152.907500] systemd[1]: Pulling in logrotate.service/stop from shutdown.target/start
[  152.915263] systemd[1]: Added job logrotate.service/stop to transaction.
[  152.921979] systemd[1]: Pulling in slices.target/stop from shutdown.target/start
[  152.929502] systemd[1]: Added job slices.target/stop to transaction.
[  152.935880] systemd[1]: Pulling in systemd-hwdb-update.service/stop from shutdown.target/start
[  152.944516] systemd[1]: Added job systemd-hwdb-update.service/stop to transaction.
[  152.952103] systemd[1]: Pulling in sockets.target/stop from shutdown.target/start
[  152.959602] systemd[1]: Added job sockets.target/stop to transaction.
[  153.093245] systemd-journald[145]: Successfully sent stream file descriptor to service manager.
[  153.110006] systemd-journald[145]: Successfully sent stream file descriptor to service manager.
[  153.153159] device wlan0 left promiscuous mode
[  153.156447] systemd-journald[145]: Successfully sent stream file descriptor to service manager.
[  153.165584] br0: port 1(wlan0) entered disabled state
[  153.168268] systemd-journald[145]: Successfully sent stream file descriptor to service manager.
[  153.183418] systemd-journald[145]: Successfully sent stream file descriptor to service manager.
[  153.200634] systemd-journald[145]: Successfully sent stream file descriptor to service manager.
[  153.212282] systemd-journald[145]: Successfully sent stream file descriptor to service manager.
[  153.223800] systemd-journald[145]: Successfully sent stream file descriptor to service manager.
[  153.606530] systemd-journald[145]: Successfully sent stream file descriptor to service manager.
[  153.637870] systemd-user-runtime-dir[931]: SELinux enabled state cached to: disabled
[  153.645765] systemd-user-runtime-dir[931]: Will remove /run/user/1000
[  153.697735] systemd-journald[145]: Successfully sent stream file descriptor to service manager.
[  153.726059] systemd-user-sessions[950]: SELinux enabled state cached to: disabled
[  154.234314] systemd-journald[145]: Successfully sent stream file descriptor to service manager.
[  154.318135] systemd-journald[145]: Successfully sent stream file descriptor to service manager.
[  154.328105] systemd-journald[145]: Successfully sent stream file descriptor to service manager.
[  154.356719] systemd-update-utmp[976]: Bus n/a: changing state UNSET → OPENING
[  154.364249] systemd-update-utmp[976]: sd-bus: starting bus by connecting to /run/systemd/private...
[  154.373575] systemd-update-utmp[976]: Bus n/a: changing state OPENING → AUTHENTICATING
[  154.382927] systemd-update-utmp[976]: Not writing wtmp: No such file or directory
[  154.390586] systemd-update-utmp[976]: Bus n/a: changing state AUTHENTICATING → RUNNING
[  154.398914] systemd-update-utmp[976]: Bus n/a: changing state RUNNING → CLOSED
[  154.437928] systemd-journald[145]: Successfully sent stream file descriptor to service manager.
[  154.528496] hwmon hwmon1: Undervoltage detected!
[  154.599046] systemd-shutdown[1]: Found cgroup2 on /sys/fs/cgroup/, full unified hierarchy
[  154.607590] systemd-shutdown[1]: Setting 'kernel/printk' to '5'.
[  154.865133] systemd-shutdown[1]: Successfully forked off '(sd-sync)' as PID 985.
[  154.872706] systemd-shutdown[1]: Syncing filesystems and block devices.
[  154.919274] systemd-shutdown[1]: binfmt_misc is not mounted, not detaching entries.
[  154.927049] systemd-shutdown[1]: Sending SIGTERM to remaining processes...
[  154.955258] systemd-journald[145]: Received SIGTERM from PID 1 (systemd-shutdow).
[  154.962991] systemd-journald[145]: systemd-journald stopped as PID 145 for the system.
[  155.015376] systemd-shutdown[1]: Sending SIGKILL to remaining processes...
[  155.039801] systemd-shutdown[1]: Using hardware watchdog 'Broadcom BCM2835 Watchdog timer', version 0, device /dev/watchdog
[  155.056059] systemd-shutdown[1]: Unmounting file systems.
[  155.063779] systemd-shutdown[1]: Successfully forked off '(sd-remount)' as PID 986.
[  155.065181] [986]: Remounting '/' read-only in with options '(null)'.
[  155.099371] EXT4-fs (mmcblk0p2): re-mounted. Quota mode: none.
[  155.123222] systemd-shutdown[1]: All filesystems unmounted.
[  155.128913] systemd-shutdown[1]: Deactivating swaps.
[  155.134181] systemd-shutdown[1]: All swaps deactivated.
[  155.139460] systemd-shutdown[1]: Detaching loop devices.
[  155.144874] systemd-shutdown[1]: sd-device-enumerator: Scan all dirs
[  155.151377] systemd-shutdown[1]: sd-device-enumerator: Scanning /sys/bus
[  155.158268] systemd-shutdown[1]: sd-device-enumerator: Scanning /sys/class
[  155.171995] systemd-shutdown[1]: All loop devices detached.
[  155.178030] systemd-shutdown[1]: Stopping MD devices.
[  155.183232] systemd-shutdown[1]: sd-device-enumerator: Scan all dirs
[  155.189700] systemd-shutdown[1]: sd-device-enumerator: Scanning /sys/bus
[  155.196570] systemd-shutdown[1]: sd-device-enumerator: Scanning /sys/class
[  155.203763] systemd-shutdown[1]: All MD devices stopped.
[  155.209125] systemd-shutdown[1]: Detaching DM devices.
[  155.214322] systemd-shutdown[1]: sd-device-enumerator: Scan all dirs
[  155.220772] systemd-shutdown[1]: sd-device-enumerator: Scanning /sys/bus
[  155.227629] systemd-shutdown[1]: sd-device-enumerator: Scanning /sys/class
[  155.234795] systemd-shutdown[1]: All DM devices detached.
[  155.240248] systemd-shutdown[1]: All filesystems, swaps, loop devices, MD devices and DM devices detached.
[  155.251120] systemd-shutdown[1]: Successfully forked off '(sd-executor)' as PID 988.
[  155.266815] systemd-shutdown[1]: (sd-executor) succeeded.
[  155.273614] systemd-shutdown[1]: Successfully forked off '(sd-sync)' as PID 989.
[  155.281250] systemd-shutdown[1]: Syncing filesystems and block devices.
[  155.288131] systemd-shutdown[1]: Rebooting.
[  155.293791] kvm: exiting hardware virtualization
[  155.366983] reboot: Restarting system

After waiting for more than 10 minutes, there has been no response

ragazenta commented 11 months ago

Hi, after upgrading bootloader to this version and upgrading firmware via sudo SKIP_KERNEL=1 rpi-update seems to fix reboot hang problem. Does this version of bootloader really solve the problem? https://github.com/raspberrypi/rpi-eeprom/commit/abce28f9bc8a1f817ff57b709abc2b2d53b78ea4

If I only upgrade the bootloader and not the firmware, reboot still hang sometimes.

MESS:00:00:08.034750:0: Read command line from file 'cmdline.txt':
MESS:00:00:08.040611:0: 'console=serial0,115200 console=tty1 root=PARTUUID=11b31d2a-02 rootfstype=ext4 fsck.repair=yes rootwait loglevel=3 quiet logo.nologo'
MESS:00:00:08.372388:0: brfs: File read: 132 bytes
MESS:00:00:20.884023:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:00:20.889289:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:00:20.997229:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:00:21.048287:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_WRITE_PROTECTED not defined
MESS:00:00:21.067257:0: Loading 'kernel7l.img' to 0x8000 size 0x0
MESS:00:00:21.070300:0: Device tree loaded to 0x2eff3500 (size 0xcaa4)
MESS:00:00:21.079909:0: uart: Set PL011 baud rate to 103448.300000 Hz
MESS:00:00:21.086244:0: uart: Baud rate change done...
MESS:00:00:21.088309:0: uart: Baud rate change done...

<!-- hang -->

MESS:00:00:08.034018:0: Read command line from file 'cmdline.txt':
MESS:00:00:08.039879:0: 'console=serial0,115200 console=tty1 root=PARTUUID=11b31d2a-02 rootfstype=ext4 fsck.repair=yes rootwait loglevel=3 quiet logo.nologo'
MESS:00:00:08.371587:0: brfs: File read: 132 bytes
MESS:00:00:12.358314:0: brfs: File read: /mfs/sd/kernel7l.img
MESS:00:00:12.361005:0: Loading 'kernel7l.img' to 0x8000 size 0x677610
MESS:00:00:12.367269:0: Device tree loaded to 0x2eff3500 (size 0xcaa4)
MESS:00:00:12.376934:0: uart: Set PL011 baud rate to 103448.300000 Hz
MESS:00:00:12.383269:0: uart: Baud rate change done...
MESS:00:00:12.385330:0: uart: Baud rate change done...
MESS:00:00:12.393865:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined

<!-- hang -->

tianfeng-yang commented 10 months ago

Hi, after upgrading bootloader to this version and upgrading firmware via sudo SKIP_KERNEL=1 rpi-update seems to fix reboot hang problem.

In my case, this was not resolved

Tiiteo commented 9 months ago

Hi, I found a reliable solution enabling at boot time the hardware Watchdog of the Broadcom. Logging with a serial cable the reboot process of the Raspberry Pi OS (Buster), I saw it hangs after all services are normally stopped. Most of time, reboot is OK after this log, but, randomly (very few), the OS stops at this step just like after a halt command.

[ 291.338847] reboot: Restarting system

Enabling the hardware watchdog like described by the link below solves the problem: https://diode.io/blog/running-forever-with-the-raspberry-pi-hardware-watchdog I made hundreds of automatic reboots during multiple days (x288 / day) with and without watchdog enabled this way. I always used exactly the same hardware and software.

With the watchdog enabled, I never get any trouble: the raspberry always boots after reboot command.
Without watchdog (#dtparam=watchdog=on in /boot/config.txt ), the systems always hangs after a few (or a few tens) of reboot command.

VoidVolker commented 9 months ago

@TestODTestOD hi! Sounds great, thx! Will test your solution. Btw, you got a typo in url - it has a wrong target link.

epigramx commented 6 months ago

Enabling watchdog does not solve it here. Updating to latest raspi os with full-upgrade doesn't, and upgrading to latest rpi-update doesn't either. [PS I don't have this issue on another pi4; it's on ubuntu; this one is on raspi os "Debian GNU/Linux 12 (bookworm)" (full-upgraded)] [The only "reliable" way I have to reboot or shutdown is the -f (forcing) variations of the halt command(or similar forcing)]

epigramx commented 5 months ago

My issue is solved and it was unrelated to the kernel or the even the default installation of the OS entirely. I had a booting script hanging the networking shutdown. I encourage people to use systemd.log_level=debug at the command line at /boot/firmware/cmdline.txt and look for "stopping held back" messages.

raspberrypi / linux

Diagnosing unreliable reboots #5503