Unable to load Supervisor or add-on logs

Installation Home Assistant OS
1

When I try to look at supervisor logs via the web interface (settings → Add-ons, Backups & Supervisor → System), it tries for a while, then times out with the error:

Failed to get supervisor logs, Unknown error, see supervisor logs.

The browser console has a few errors indicating that the websocket connection was interrupted.

If I try to view supervisor logs using the command line via ha supervisor logs, I get the error

Get "http://supervisor/supervisor/logs": context deadline exceeded (Client.timeout exceeded while awaiting headers)

The same happens with core and host logs as well.

I’m running version 2021.12.5 on HA OS 7.0 on a rpi4 (2GB) with an SSD. I’m not sure when this started, as it’s been a while since I tried to look at supervisor logs, and I’ve updated a couple of times since. If I had to guess, I’d say it started since I updated to 2021.12.x

Once I’ve attempted to get logs using either of the above methods, the supervisor seems to be stalled for a while. When I reload the page, I get Could not load the Supervisor panel! with some troubleshooting tips. The Observer shows Connected, Supported, and Healthy. If I wait a bit and reload the page again, the supervisor panel loads back up (but still can’t get logs). At that point, Can't read Supervisor data: shows up in the logs at Configuration → Settings → Logs, but no additional detail. Also in those logs, there are timeout errors for all of my installed add-ons, e.g. Timeout on /addons/core_samba/stats request

I’ve tried rebooting/power cycling the host, and disabling all add-ons, to no avail.

If I don’t try to get the supervisor/core/host logs, everything works as expected. So maybe this is just one of those “well then don’t do that” things… but I worry it could be a symptom of an underlying problem that will come back to bite me later.

Has anyone else seen something like this? Any suggestions on how to debug it? Is there another way to get at the logs to see if there are any clues there?

2

Yes, I have the same problem on the same hardware (RPi4 2GB with SSD), only I’m running Supervised install (everything updated to the latest version) on Bullseye and I didn’t dare to ask for help as my installation is not officially supported :slight_smile:
Additionally, when trying to see logs in HA or running

ha supervisor logs

CPU starts throttling and is heating up (by 10 degress roughly), but in 30ish seconds after timeout it starts running normally again.

3

That should be supported is if is just vanilla Debian. Your system seems to meet the requirements of ADR 14.

4

Good to know it’s not just me! Did you notice when the problem started for you? i.e. after a specific update or change?

I managed to get my supervisor logs to load… I don’t know why it worked this time; when I try to access them again it still fails. But I don’t see anything suspicious in them:

21-12-28 11:58:47 INFO (MainThread) [supervisor.store.git] Update add-on https://github.com/home-assistant/addons repository
21-12-28 11:58:55 INFO (MainThread) [supervisor.store] Loading add-ons from store: 75 all - 0 new - 0 remove
21-12-28 11:59:00 INFO (MainThread) [supervisor.api.middleware.security] /supervisor/info access from cebe7a76_hassio_google_drive_backup
21-12-28 11:59:00 INFO (MainThread) [supervisor.api.middleware.security] /backups access from cebe7a76_hassio_google_drive_backup
21-12-28 11:59:19 INFO (MainThread) [supervisor.homeassistant.api] Updated Home Assistant API token
21-12-28 12:23:58 INFO (MainThread) [supervisor.auth] Auth request from 'core_mosquitto' for 'mqtt-user'
21-12-28 12:24:08 INFO (MainThread) [supervisor.auth] Auth request from 'core_mosquitto' for 'mqtt-user'
21-12-28 12:24:18 INFO (MainThread) [supervisor.auth] Auth request from 'core_mosquitto' for 'mqtt-user'
21-12-28 12:24:28 INFO (MainThread) [supervisor.auth] Auth request from 'core_mosquitto' for 'mqtt-user'
21-12-28 12:24:38 INFO (MainThread) [supervisor.auth] Auth request from 'core_mosquitto' for 'mqtt-user'
21-12-28 12:24:48 INFO (MainThread) [supervisor.auth] Auth request from 'core_mosquitto' for 'mqtt-user'
21-12-28 12:24:58 INFO (MainThread) [supervisor.auth] Auth request from 'core_mosquitto' for 'mqtt-user'
21-12-28 12:25:08 INFO (MainThread) [supervisor.auth] Auth request from 'core_mosquitto' for 'mqtt-user'
21-12-28 12:25:18 INFO (MainThread) [supervisor.auth] Auth request from 'core_mosquitto' for 'mqtt-user'
21-12-28 12:25:28 INFO (MainThread) [supervisor.auth] Auth request from 'core_mosquitto' for 'mqtt-user'
21-12-28 12:25:38 INFO (MainThread) [supervisor.auth] Auth request from 'core_mosquitto' for 'mqtt-user'
21-12-28 12:25:48 INFO (MainThread) [supervisor.auth] Auth request from 'core_mosquitto' for 'mqtt-user'
21-12-28 12:25:58 INFO (MainThread) [supervisor.auth] Auth request from 'core_mosquitto' for 'mqtt-user'
21-12-28 12:26:08 INFO (MainThread) [supervisor.auth] Auth request from 'core_mosquitto' for 'mqtt-user'
21-12-28 12:26:18 INFO (MainThread) [supervisor.auth] Auth request from 'core_mosquitto' for 'mqtt-user'
21-12-28 12:26:28 INFO (MainThread) [supervisor.auth] Auth request from 'core_mosquitto' for 'mqtt-user'
21-12-28 12:26:38 INFO (MainThread) [supervisor.auth] Auth request from 'core_mosquitto' for 'mqtt-user'
21-12-28 12:26:48 INFO (MainThread) [supervisor.auth] Auth request from 'core_mosquitto' for 'mqtt-user'
21-12-28 12:26:58 INFO (MainThread) [supervisor.auth] Auth request from 'core_mosquitto' for 'mqtt-user'
21-12-28 12:27:08 INFO (MainThread) [supervisor.auth] Auth request from 'core_mosquitto' for 'mqtt-user'
21-12-28 12:27:18 INFO (MainThread) [supervisor.auth] Auth request from 'core_mosquitto' for 'mqtt-user'
21-12-28 12:27:28 INFO (MainThread) [supervisor.auth] Successful login for 'mqtt-user'
21-12-28 12:29:53 INFO (MainThread) [supervisor.auth] Auth request from 'core_mosquitto' for 'mqtt-user'
21-12-28 12:29:59 INFO (MainThread) [supervisor.homeassistant.api] Updated Home Assistant API token
21-12-28 12:30:03 INFO (MainThread) [supervisor.auth] Successful login for 'mqtt-user'
21-12-28 12:37:26 INFO (MainThread) [supervisor.auth] Auth request from 'core_mosquitto' for 'mqtt-user'
21-12-28 12:37:33 INFO (MainThread) [supervisor.auth] Successful login for 'mqtt-user'
21-12-28 12:44:50 INFO (MainThread) [supervisor.auth] Auth request from 'core_mosquitto' for 'mqtt-user'
21-12-28 12:44:57 INFO (MainThread) [supervisor.auth] Successful login for 'mqtt-user'
21-12-28 12:54:45 INFO (MainThread) [supervisor.resolution.check] Starting system checks with state CoreState.RUNNING
21-12-28 12:54:45 INFO (MainThread) [supervisor.resolution.checks.base] Run check for IssueType.SECURITY/ContextType.CORE
21-12-28 12:54:45 INFO (MainThread) [supervisor.resolution.checks.base] Run check for IssueType.FREE_SPACE/ContextType.SYSTEM
21-12-28 12:54:45 INFO (MainThread) [supervisor.resolution.checks.base] Run check for IssueType.TRUST/ContextType.PLUGIN
21-12-28 12:57:25 INFO (MainThread) [supervisor.auth] Auth request from 'core_mosquitto' for 'mqtt-user'
21-12-28 12:57:35 INFO (MainThread) [supervisor.auth] Auth request from 'core_mosquitto' for 'mqtt-user'
21-12-28 12:57:42 INFO (MainThread) [supervisor.auth] Successful login for 'mqtt-user'
21-12-28 12:58:26 INFO (MainThread) [supervisor.host.info] Updating local host information
21-12-28 12:58:42 INFO (MainThread) [supervisor.host.services] Updating service information
21-12-28 12:58:42 INFO (MainThread) [supervisor.host.network] Updating local network information
21-12-28 12:58:44 INFO (MainThread) [supervisor.host.sound] Updating PulseAudio information
21-12-28 12:59:07 INFO (MainThread) [supervisor.api.middleware.security] /supervisor/info access from cebe7a76_hassio_google_drive_backup
21-12-28 12:59:07 INFO (MainThread) [supervisor.api.middleware.security] /backups access from cebe7a76_hassio_google_drive_backup
21-12-28 13:00:15 INFO (MainThread) [supervisor.homeassistant.api] Updated Home Assistant API token
21-12-28 13:02:14 INFO (MainThread) [supervisor.host.manager] Host information reload completed
21-12-28 13:02:14 INFO (MainThread) [supervisor.resolution.checks.base] Run check for IssueType.PWNED/ContextType.ADDON
21-12-28 13:02:14 INFO (MainThread) [supervisor.resolution.checks.base] Run check for IssueType.TRUST/ContextType.CORE
21-12-28 13:02:14 INFO (MainThread) [supervisor.resolution.checks.base] Run check for IssueType.TRUST/ContextType.SUPERVISOR
21-12-28 13:02:14 INFO (MainThread) [supervisor.resolution.check] System checks complete
21-12-28 13:02:14 INFO (MainThread) [supervisor.resolution.evaluate] Starting system evaluation with state CoreState.RUNNING
21-12-28 13:02:14 INFO (MainThread) [supervisor.resolution.evaluate] System evaluation complete
21-12-28 13:02:14 INFO (MainThread) [supervisor.resolution.fixup] Starting system autofix at state CoreState.RUNNING
21-12-28 13:02:14 INFO (MainThread) [supervisor.resolution.fixup] System autofix complete
21-12-28 13:03:57 INFO (MainThread) [supervisor.auth] Auth request from 'core_mosquitto' for 'mqtt-user'
21-12-28 13:04:05 INFO (MainThread) [supervisor.auth] Successful login for 'mqtt-user'
21-12-28 13:05:59 INFO (MainThread) [supervisor.api.middleware.security] /network/info access from core_ssh
21-12-28 13:05:59 INFO (MainThread) [supervisor.api.middleware.security] /network/info access from core_ssh
21-12-28 13:05:59 INFO (MainThread) [supervisor.api.middleware.security] /host/info access from core_ssh
21-12-28 13:05:59 INFO (MainThread) [supervisor.api.middleware.security] /core/info access from core_ssh
21-12-28 13:06:02 INFO (MainThread) [supervisor.api.middleware.security] /core/logs access from core_ssh
21-12-28 13:10:33 INFO (MainThread) [supervisor.auth] Auth request from 'core_mosquitto' for 'mqtt-user'
21-12-28 13:10:34 INFO (MainThread) [supervisor.auth] Successful login for 'mqtt-user'
21-12-28 13:27:06 INFO (MainThread) [supervisor.auth] Auth request from 'core_mosquitto' for 'mqtt-user'
21-12-28 13:27:16 INFO (MainThread) [supervisor.auth] Auth request from 'core_mosquitto' for 'mqtt-user'
21-12-28 13:27:47 INFO (MainThread) [supervisor.auth] Successful login for 'mqtt-user'
21-12-28 13:30:19 INFO (MainThread) [supervisor.homeassistant.api] Updated Home Assistant API token
21-12-28 13:58:02 INFO (MainThread) [supervisor.backups.manager] Found 4 backup files
21-12-28 13:58:06 INFO (MainThread) [supervisor.updater] Fetching update data from https://version.home-assistant.io/stable.json
21-12-28 14:00:16 INFO (MainThread) [supervisor.api.middleware.security] /supervisor/info access from cebe7a76_hassio_google_drive_backup
21-12-28 14:00:23 INFO (MainThread) [supervisor.homeassistant.api] Updated Home Assistant API token
21-12-28 14:00:23 INFO (MainThread) [supervisor.api.middleware.security] /backups access from cebe7a76_hassio_google_drive_backup
21-12-28 14:00:47 INFO (MainThread) [supervisor.api.middleware.security] /supervisor/info access from cebe7a76_hassio_google_drive_backup
21-12-28 14:00:47 INFO (MainThread) [supervisor.api.middleware.security] /backups access from cebe7a76_hassio_google_drive_backup
21-12-28 14:01:18 INFO (MainThread) [supervisor.api.middleware.security] /supervisor/info access from cebe7a76_hassio_google_drive_backup
21-12-28 14:01:18 INFO (MainThread) [supervisor.api.middleware.security] /backups access from cebe7a76_hassio_google_drive_backup
21-12-28 14:01:58 INFO (MainThread) [supervisor.api.middleware.security] /supervisor/logs access from core_ssh
5

Can’t say for sure, but i guess it was about the same as you noticed, that is upgrading to 2021.12.X. At the same time I upgraded Raspbian Buster to Bullseye and I thought it might be connected to that - but obviously it’s not if you notice the same on HAOS.

6

Ah that is not supported then. There is a Debian version of the Pi.

8

I still haven’t figured out what’s going on, but I was able to ssh into the host, and from there I can watch system load while attempting to fetch the logs. The load average climbs to 30+ (it usually hovers around 2), but CPU usage stays relatively low (5 to 30%). So I guess that means things are being blocked by something else… network or disk i/o maybe?

While attempting to fetch logs, the supervisor docker instance becomes completely unresponsive over ssh, and even the physical keyboard/monitor console stops responding.

I can actually get to the logs with docker logs hassio_supervisor, since it doesn’t timeout. But it takes 2+ minutes to load them. I wondered if it was because they were too big, but they only go back 2 weeks, and the total size is ~1M.

I don’t know much about Docker, but it seems like it’s what handles the supervisor logs. Maybe there is something amiss with my docker setup? I guess I need to go read up.

9

I just updated to 2021.12.7 and the problem seems much improved. The supervisor logs still take a really long time to load, but they do eventually load… at least most of the time. When they fail, I now get a 502 Bad Gateway error. But the real improvement is that things don’t seem to slow down as much while it tries to load them. Load average climbs to about 12, and things get a bit sluggish, but they keep working.

Nothing in the release notes for .6 or .7 jumps out at me as the fix, so I’m not sure what did the trick. But I’ll take it!

10

Same here… still really slow, but loads eventually… seems to me you might be right that this has something to do with docker… which version of docker are you running (I’m on 20.10.12)?

11

Looks like I’m on 20.10.9

12

I was about to propose, that you open an issue on Github, but then I saw, that there are already two issues for this and also a topic on this forum - as far as i could understand, it’s not an issue with HA or Supervisor, but more likely with SSD/USB3.0 speed.

https://forums.raspberrypi.com/viewtopic.php?f=28&t=245931

I checked my speed and it really is kinda low - only 50MB/sec, although I’m using an SSD adapter, which was working very fast on buster (it’s also on the list of “approved” adapters, but most likely something changed here with bullseye).

I tried the quirks solution, but unfortunately it doesn’t work for me (when I add quirks to cmdline.txt, the system doesn’t boot anymore). If you have courage, you may try and see if it helps :slight_smile: .

13

Nice find on that other forum thread; not sure how I missed that one!

I think blaming it on the SSD is a good call. I’m actually only using USB 2.0 for my SSD, as 3.0 seems to interfere with my z-wave/zigbee radio, even with a USB extension cable. So I only get 5 to 10MB/s.

It’s still a little strange to me that it’s so slow to load the logs… Since the total log size is 1MB, even at 5MB/s, it should go pretty quick. But since it no longer seems to take the supervisor out of commission while reading the logs, I’m not too worried about it.

I keep thinking that I should move to something a bit beefier than an RPi. Maybe this will push me to actually get around to that.

14

I tinkered a little bit more and got it working on my system (had to add additional dwc_otg.lpm_enable=0 to cmdline).
The disk reading speed improved from 50MB/s to 255MB/s and the logs are now opened immediately in Supervisor :). Even if you are using USB2, disabling UAS might do the trick for you, as obvisously there is another logic in background (not direct calculation 1MB file - 10MB/s reading speed).

It also solved another issue (which I didn’t even know was related to that) - that is, the logoff/reboot menu in Raspbian took ages to open and now it opens immediately.

15

I finally got around to trying the quirks solution, and it did speed things up about 3x, which is nice! Thanks for that tip!

It was a little tricky to figure out how to get to cmdline.txt with HassOS, so I’ll write it up here in case it helps anyone else:

Follow https://developers.home-assistant.io/docs/operating-system/debugging/ to get ssh access to the host OS.

ssh in, and find the vendor and product ID for the SSD as instructed in https://forums.raspberrypi.com/viewtopic.php?f=28&t=245931: Look in the output of dmesg for a line like:

[ 4096.646369] usb 2-1: New USB device found, idVendor=2109, idProduct=0715, bcdDevice=a0.00

This is logged for each USB device, so find the one that goes with the SSD (surrounding lines in the log give details about the device).

Mount the boot partition and edit cmdline.txt:

mkdir /tmp/boot
mount /dev/sda1 /tmp/boot
vi /tmp/boot/cmdline.txt

At the beginning of the line, add usb-storage.quirks=aaaa:bbbb:u where aaaa is the idVendor for your SSD and bbbb is the idProduct. My cmdline.txt looks like:

usb-storage.quirks=2109:0715:u dwc_otg.lpm_enable=0 console=tty1

Then save, and reboot. SSH back in and test speed with hdparm -t /dev/sda

Thanks again for your help! Superviser logs load in < 2s now.

4 Likes
16

I also have this problem for a while but didn’t looked into it. But now I have an issues and want to see the logs for more info but it’s taking ages which isn’t very beneficial for troubleshooting.

When I add the line to the cmdline.txt my rpi doesn’t boot at all

usb-storage.quirks=174c:55aa:u dwc_otg.lpm_enable=0

According to my find the product and deviceid are 174c and 55aa

root@raspberrypi:/home/pi# lsusb
Bus 002 Device 002: ID 174c:55aa ASMedia Technology Inc. ASM1051E SATA 6Gb/s bridge, ASM1053E SATA 6Gb/s bridge, ASM1153 SATA 3Gb/s bridge, ASM1153E SATA 6Gb/s bridge

5.968132] usb 2-2: new SuperSpeed Gen 1 USB device number 2 using xhci_hcd
[ 5.993098] usb 2-2: New USB device found, idVendor=174c, idProduct=55aa, bcdDevice= 1.00
[ 6.001443] usb 2-2: New USB device strings: Mfr=2, Product=3, SerialNumber=1
[ 6.008720] usb 2-2: Product: ASM105x
[ 6.012456] usb 2-2: Manufacturer: ASMT
[ 6.016369] usb 2-2: SerialNumber: 12345679256E
[ 6.062603] SCSI subsystem initialized
[ 6.081544] usbcore: registered new interface driver usb-storage
[ 6.101961] scsi host0: uas
[ 6.105511] usbcore: registered new interface driver uas
[ 6.106306] scsi 0:0:0:0: Direct-Access ASMT ASM105x 0 PQ: 0 ANSI: 6
[ 6.148375] sd 0:0:0:0: [sda] 468862128 512-byte logical blocks: (240 GB/224 GiB)
[ 6.156180] sd 0:0:0:0: [sda] Write Protect is off
[ 6.161078] sd 0:0:0:0: [sda] Mode Sense: 43 00 00 00
[ 6.161355] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn’t support DPO or FUA
[ 6.171227] sd 0:0:0:0: [sda] Optimal transfer size 33553920 bytes
[ 6.177589] usb 1-1.3: new full-speed USB device number 3 using xhci_hcd
[ 6.198244] sda: sda1 sda2

But when I add this line my system doesn’t boot at all

I also noticed I already have command in the cmdline.txt file

console=tty0 console=ttyS1,115200 root=/dev/sda2 rw fsck.repair=yes net.ifnames=0 rootwait

Not sure what it does or means. But even If I remove this line my system won’t boot. Even if delete everything (both lines)

usb-storage.quirks=174c:55aa:u dwc_otg.lpm_enable=0
console=tty0 console=ttyS1,115200 root=/dev/sda2 rw fsck.repair=yes net.ifnames=0 rootwait

Any suggestions?
I’m using the certified P1 cable along with a Kingston A400 ssd

17

nvm I have it working now (was trying for a while)

I had another look at the screenshot and noticed it shouldn’t the same line which I had. I needed the add the new line before the 2nd line. So it is 1 line instead of 2 lines

usb-storage.quirks=174c:55aa:u dwc_otg.lpm_enable=0 console=tty0 console=ttyS1,115200 root=/dev/sda2 rw fsck.repair=yes net.ifnames=0 rootwait

Now I can continue to my original problem lol

18

Thanks for the solution. However I had trouble with the Quirks.

I identified my SSD drive on usb 1-1.4 with idVendor=14b0, idProduct=0207:

# dmesg | grep "usb "
[    1.446297] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 6.06
[    1.446328] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    1.446350] usb usb1: Product: xHCI Host Controller
[    1.446367] usb usb1: Manufacturer: Linux 6.6.31-haos-raspi xhci-hcd
[    1.446385] usb usb1: SerialNumber: 0000:01:00.0
[    1.447615] usb usb2: New USB device found, idVendor=1d6b, idProduct=0003, bcdDevice= 6.06
[    1.447646] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    1.447669] usb usb2: Product: xHCI Host Controller
[    1.447685] usb usb2: Manufacturer: Linux 6.6.31-haos-raspi xhci-hcd
[    1.447702] usb usb2: SerialNumber: 0000:01:00.0
[    1.706819] usb 1-1: new high-speed USB device number 2 using xhci_hcd
[    1.856912] usb 1-1: New USB device found, idVendor=2109, idProduct=3431, bcdDevice= 4.21
[    1.856948] usb 1-1: New USB device strings: Mfr=0, Product=1, SerialNumber=0
[    1.856973] usb 1-1: Product: USB2.0 Hub
[    2.342819] usb 1-1.4: new high-speed USB device number 4 using xhci_hcd
[    2.480809] usb 1-1.4: New USB device found, idVendor=14b0, idProduct=0207, bcdDevice= 1.00
[    2.480844] usb 1-1.4: New USB device strings: Mfr=2, Product=3, SerialNumber=1
[    2.480870] usb 1-1.4: Product:  SA400S37960G
[    2.480889] usb 1-1.4: Manufacturer: KINGSTON
[    2.480907] usb 1-1.4: SerialNumber: AAAABBBBCCCC060D
[    4.017523] usb 1-1.3: cp210x converter now attached to ttyUSB0

I modified the cmdline.txt file to:

# cat /tmp/boot/cmdline.txt
usb-storage.quirks=14b0:0207:u dwc_otg.lpm_enable=0 console=tty0 usb-storage.quirks=174c:55aa:u,2109:0715:u,152d:0578:u,152d:0579:u,152d:1561:u,174c:0829:u,14b0:0206:u,174c:225c:u,7825:a2a4:u,152d:0562:u,125f:a88a:u

After the speed did not get better I noticed that the file now contains two definitions of usb-storage.quirks.

So I added my Quirk definition to the existing one like so:

dwc_otg.lpm_enable=0 console=tty0 usb-storage.quirks=14b0:0207:u,174c:55aa:u,2109:0715:u,152d:0578:u,152d:0579:u,152d:1561:u,174c:0829:u,14b0:0206:u,174c:225c:u,7825:a2a4:u,152d:0562:u,125f:a88a:u

This seems to work (at least the Quirk was applied):

#dmesg | grep "Quirks match"
[    2.497576] usb-storage 1-1.4:1.0: Quirks match for vid 14b0 pid 0207: 800000

However, the SSD speed did not increase much:

# hdparm -t /dev/sda
/dev/sda:
Timing buffered disk reads:   90 MB in 3.00 seconds = 30684 kB/s

After plugging the SSD into the USB 3.0 port (yes should have been obvious :face_in_clouds:). I’m at an acceptable seed of:

# hdparm -t /dev/sda

/dev/sda:
Timing buffered disk reads:  616 MB in 3.00 seconds = 210086 kB/s

Greetings