HAOS 14: Stuck on boot after rebooting on RPI 5 #3740
Comments
crug80
changed the title
crug80
changed the title
|
If you can reproduce it on every reboot, can you attach a HDMI display and check the output? What is the blinking pattern of the on-board LED what that happens? |
|
Not quickly. I need a micro hdmi cable to attach the monitor.. I'll try in the next days |
|
Although the original topic is slightly unrelated, see here: #3720 (comment) On the troublesome Pi with the old firmware I saw the same behavior, where it got stuck after a reboot and had to be power-cycled manually. |
I installed the nvme 2 months ago and I've updated to the latest firmware before to do it... So it should already update with a recent firmware. On monday I should receive the cable, so as first thing I will attach a monitor to see what happens |
|
Finally I got the cable... The leds remain fixed and this is the video log. As you can see the problem is on NVME. Do you think that is it an HAOS matter? |
|
The boot gets stuck early in the bootloader, which points to some hardware/incompatibility issue. It's either the NVMe HAT, the SSD, or the combination of both. What drive and HAT are you using? I'm afraid it's not fixable on our side though. |
|
The strange thing is that it appeared only after the OS upgrade, I tested reboot several times before going to production. |
|
While I can't get any logs until I get to the residence housing it, I'm having a similar issue with a Raspberry Pi 4 with a USB SSD. Update was clunky to 14.0 and required a reboot but then seemed to work and 14.1 seemed to do the same but now it's not coming back up after another reboot recently during a scheduled restart and restarting again didn't seem to fix it. I'll get logs if I can when I get there and also check the boot sequence on a screen, but seems to be the same issue so far. Was a driver module removed or changed with the kernel update? |
|
This issue has been occurring reliably since ~Nov 2024. It may not help much, but there has been a lot of conversation about this issue in the home-assistant/core issue tracker home-assistant/core#129714. From my experience, it appears that the Pi gets stuck in the bootloader, upon reboot (full system/host reboot). The Pi bootloader keeps attempting to boot different media and partitions, but fails to identify anything bootable.
|
|
Worth noting this issue appears to be related, as the symptoms are identical. I am able to reliably get logs, if that would be useful. In my case I'm attempting to update from 13.8 -> 14.2. Unsure if the issue is identical as the linked issue is on a Proxmark, but I'm on a pi5 getting the exact issue in the link. |
Bingo, I finally managed to reproduce it after several retries. The Pi, running from an SD card, became stuck in the bootloader, but the logs there were not particularly helpful (I could only see it was trying different boot modes as you correctly stated). Thankfully, the serial console was more chatty: For some reason, the bootloader attempts to load the tryboot config instead of the default one, although that should only be attempted after an upgrade. Seems there is something wrong with setting the reboot parameter for it, this shouldn't happen. It explains why RPi OS and cold boot are working correctly, this is probably some userspace bug. It doesn't explain all the issues that were reported but it's a serious lead, maybe the wrong behavior could manifest differently in other cases (i.e. after the upgrade instead of host reboot). |
Probably since home-assistant/supervisor#5276 introduced in Supervisor 2024.9.0, RAUC bootloader handler for tryboot can set the tryboot flag also when the tryboot file is not present, causing the Pi to become stuck in bootloader, trying to load the tryboot file. This happens when the device is already in the tryboot state, in that case the tryboot files and flag are created by set-primary and in turn the files are removed in set-state, while the flag is persisted, causing the bootloader to attempt loading non-existing file. To avoid unnecessary juggling with tryboot/config files, only create them and set the flag if the boot slot is different than the current one. Also, make sure that the flag is reboot parameter is cleared when the tryboot files are removed by the handler. Fixes #3740
Probably since home-assistant/supervisor#5276 introduced in Supervisor 2024.9.0, RAUC bootloader handler for tryboot can set the tryboot flag also when the tryboot file is not present, causing the Pi to become stuck in bootloader, trying to load the tryboot file. This happens when the device is already in the tryboot state, in that case the tryboot files and flag are created by set-primary and in turn the files are removed in set-state, while the flag is persisted, causing the bootloader to attempt loading non-existing file. To avoid unnecessary juggling with tryboot/config files, only create them and set the flag if the boot slot is different than the current one. Also, make sure that the flag is reboot parameter is cleared when the tryboot files are removed by the handler. Fixes #3740
Describe the issue you are experiencing
Tested the scenario 2 times in different days:
Ask for a system reboot from "developer tools" -> reboot the system
The system shutdown, but it remains off with the fan on..
I have to poweroff completely by removing the power, then it boots again.
What operating system image do you use?
rpi5-64 (Raspberry Pi 5 64-bit OS)
What version of Home Assistant Operating System is installed?
14
Did the problem occur after upgrading the Operating System?
Yes
Hardware details
System Information
Home Assistant Community Store
Home Assistant Cloud
Home Assistant Supervisor
Dashboards
Recorder
Steps to reproduce the issue
...
Anything in the Supervisor logs that might be useful for us?
�[32m2024-12-12 19:21:42.410 INFO (MainThread) [supervisor.addons.manager] Phase 'services' stopping 4 add-ons�[0m �[32m2024-12-12 19:21:42.415 INFO (SyncWorker_1) [supervisor.docker.manager] Stopping addon_a0d7b954_vscode application�[0m �[32m2024-12-12 19:21:46.750 INFO (SyncWorker_1) [supervisor.docker.manager] Cleaning addon_a0d7b954_vscode application�[0m �[32m2024-12-12 19:21:46.769 INFO (SyncWorker_3) [supervisor.docker.manager] Stopping addon_a0d7b954_influxdb application�[0m �[32m2024-12-12 19:21:50.166 INFO (SyncWorker_3) [supervisor.docker.manager] Cleaning addon_a0d7b954_influxdb application�[0m �[32m2024-12-12 19:21:50.182 INFO (SyncWorker_0) [supervisor.docker.manager] Stopping addon_a0d7b954_ssh application�[0m �[32m2024-12-12 19:21:53.313 INFO (SyncWorker_0) [supervisor.docker.manager] Cleaning addon_a0d7b954_ssh application�[0m �[32m2024-12-12 19:21:53.336 INFO (SyncWorker_5) [supervisor.docker.manager] Stopping addon_a0d7b954_grafana application�[0m �[32m2024-12-12 19:21:56.636 INFO (SyncWorker_5) [supervisor.docker.manager] Cleaning addon_a0d7b954_grafana application�[0m �[32m2024-12-12 19:21:56.655 INFO (MainThread) [supervisor.addons.manager] Phase 'system' stopping 1 add-ons�[0m �[32m2024-12-12 19:21:56.659 INFO (SyncWorker_1) [supervisor.docker.manager] Stopping addon_core_mosquitto application�[0m �[32m2024-12-12 19:22:00.215 INFO (SyncWorker_1) [supervisor.docker.manager] Cleaning addon_core_mosquitto application�[0m �[32m2024-12-12 19:22:00.226 INFO (MainThread) [supervisor.addons.manager] Phase 'initialize' stopping 0 add-ons�[0m �[32m2024-12-12 19:22:00.226 INFO (MainThread) [supervisor.plugins.cli] Stopping cli plugin�[0m �[32m2024-12-12 19:22:00.229 INFO (SyncWorker_4) [supervisor.docker.manager] Stopping hassio_cli application�[0m �[32m2024-12-12 19:22:03.400 INFO (SyncWorker_4) [supervisor.docker.manager] Cleaning hassio_cli application�[0m �[32m2024-12-12 19:22:03.411 INFO (MainThread) [supervisor.plugins.dns] Stopping CoreDNS plugin�[0m �[32m2024-12-12 19:22:03.414 INFO (SyncWorker_3) [supervisor.docker.manager] Stopping hassio_dns application�[0m �[32m2024-12-12 19:22:06.603 INFO (SyncWorker_3) [supervisor.docker.manager] Cleaning hassio_dns application�[0m �[32m2024-12-12 19:22:06.614 INFO (MainThread) [supervisor.plugins.audio] Stopping Audio plugin�[0m �[32m2024-12-12 19:22:06.616 INFO (SyncWorker_2) [supervisor.docker.manager] Stopping hassio_audio application�[0m �[32m2024-12-12 19:22:09.872 INFO (SyncWorker_2) [supervisor.docker.manager] Cleaning hassio_audio application�[0m �[32m2024-12-12 19:22:09.883 INFO (MainThread) [supervisor.plugins.multicast] Stopping Multicast plugin�[0m �[32m2024-12-12 19:22:09.886 INFO (SyncWorker_0) [supervisor.docker.manager] Stopping hassio_multicast application�[0m �[32m2024-12-12 19:22:13.005 INFO (SyncWorker_0) [supervisor.docker.manager] Cleaning hassio_multicast application�[0m �[31m2024-12-12 19:22:13.038 ERROR (MainThread) [aiohttp.server] Error handling request Traceback (most recent call last): File "/usr/local/lib/python3.12/site-packages/aiohttp/client_proto.py", line 92, in connection_lost uncompleted = self._parser.feed_eof() ^^^^^^^^^^^^^^^^^^^^^^^ File "aiohttp/_http_parser.pyx", line 513, in aiohttp._http_parser.HttpParser.feed_eof aiohttp.http_exceptions.TransferEncodingError: 400, message: Not enough data for satisfy transfer length header. The above exception was the direct cause of the following exception: Traceback (most recent call last): File "/usr/local/lib/python3.12/site-packages/aiohttp/web_protocol.py", line 477, in _handle_request resp = await request_handler(request) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/aiohttp/web_app.py", line 567, in _handle return await handler(request) ^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/aiohttp/web_middlewares.py", line 117, in impl return await handler(request) ^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/supervisor/supervisor/api/middleware/security.py", line 199, in block_bad_requests return await handler(request) ^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/supervisor/supervisor/api/middleware/security.py", line 215, in system_validation return await handler(request) ^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/supervisor/supervisor/api/middleware/security.py", line 285, in token_validation return await handler(request) ^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/supervisor/supervisor/api/middleware/security.py", line 298, in core_proxy return await handler(request) ^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/supervisor/supervisor/api/utils.py", line 104, in wrap_api msg_data = await method(api, *args, **kwargs) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/supervisor/supervisor/api/__init__.py", line 529, in get_addon_logs return await self._api_host.advanced_logs(request, *args, **kwargs) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/supervisor/supervisor/api/utils.py", line 104, in wrap_api msg_data = await method(api, *args, **kwargs) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/supervisor/supervisor/api/host.py", line 278, in advanced_logs return await self.advanced_logs_handler(request, identifier, follow) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/supervisor/supervisor/api/host.py", line 257, in advanced_logs_handler async for cursor, line in journal_logs_reader(resp, log_formatter): File "/usr/src/supervisor/supervisor/utils/systemd_journal.py", line 80, in journal_logs_reader line = await resp.content.readuntil(b"\n") ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/aiohttp/streams.py", line 355, in readuntil await self._wait("readuntil") File "/usr/local/lib/python3.12/site-packages/aiohttp/streams.py", line 316, in _wait await waiter aiohttp.client_exceptions.ClientPayloadError: Response payload is not completed: <TransferEncodingError: 400, message='Not enough data for satisfy transfer length header.'>�[0m s6-rc: info: service legacy-services: stopping �[32m2024-12-12 19:22:13.109 INFO (MainThread) [supervisor.misc.scheduler] Shutting down scheduled tasks�[0m �[32m2024-12-12 19:22:13.110 INFO (MainThread) [supervisor.docker.monitor] Stopped docker events monitor�[0m �[32m2024-12-12 19:22:13.110 INFO (MainThread) [supervisor.api] Stopping API on 172.30.32.2�[0m �[32m2024-12-12 19:22:13.115 INFO (MainThread) [supervisor.hardware.monitor] Stopped Supervisor hardware monitor�[0m �[32m2024-12-12 19:22:13.122 INFO (MainThread) [supervisor.dbus.manager] Closed conection to system D-Bus.�[0m �[32m2024-12-12 19:22:13.128 INFO (MainThread) [supervisor.core] Supervisor is down - 0�[0m �[32m2024-12-12 19:22:13.130 INFO (MainThread) [__main__] Closing Supervisor�[0m [18:22:13] INFO: �[32mWatchdog restart after closing�[0m [18:22:13] WARNING: �[33mHalt Supervisor�[0m [18:22:13] INFO: �[32mSupervisor restart after closing�[0m s6-rc: info: service legacy-services successfully stopped s6-rc: info: service legacy-cont-init: stopping s6-rc: info: service legacy-cont-init successfully stopped s6-rc: info: service fix-attrs: stopping s6-rc: info: service fix-attrs successfully stopped s6-rc: info: service s6rc-oneshot-runner: stopping s6-rc: info: service s6rc-oneshot-runner successfully stopped s6-rc: info: service s6rc-oneshot-runner: starting s6-rc: info: service s6rc-oneshot-runner successfully started s6-rc: info: service fix-attrs: starting s6-rc: info: service fix-attrs successfully started s6-rc: info: service legacy-cont-init: starting cont-init: info: running /etc/cont-init.d/udev.sh [18:32:09] INFO: �[32mUsing udev information from host�[0m cont-init: info: /etc/cont-init.d/udev.sh exited 0 s6-rc: info: service legacy-cont-init successfully started s6-rc: info: service legacy-services: starting services-up: info: copying legacy longrun supervisor (no readiness notification) services-up: info: copying legacy longrun watchdog (no readiness notification) [18:32:09] INFO: �[32mStarting local supervisor watchdog...�[0m s6-rc: info: service legacy-services successfully startedAnything in the Host logs that might be useful for us?
System information
No response
Additional information
After the reboot, recorder logs: The system could not validate that the sqlite3 database at //config/home-assistant_v2.db was shutdown cleanly
The text was updated successfully, but these errors were encountered: