Through some external monitoring I’ve started to notice that Home Assistant goes unresponsive for about 5 minutes every night at about 3am. When I look at the Home Assistant logs I see some of the usual messages that show up from a reboot (e.g. custom integrations present) so it seems that at the very least the core container or the app has restarted. By the time I get up in the morning there’s nothing present in the supervisor or host logs that indicate a problem, but I’m unclear on how far back they go.
My question: Since the HA logs get flushed on a reboot is there a way to make them persist, or is there an obvious background task that happens at 3am (I don’t have any automations that run then) that may be causing this?
Details on Setup:
Home Assistant OS 6.0
core-2021.6.6
supervisor-2021.06.6
Running on a Raspberry Pi 4 Model B Rev 1.2
Running on a brand new SD card
Other observations:
HA is the only thing that gets reported down so it doesn’t seem to be my home internet connection or the proxy that’s fronting HA
There are no logbook entries for the Raspberry Pi power supply voltage dropping
This is a bit rugged, and not thoroughly tested. However it might give you some ideas on how to keep HA log file history. I run HA in a docker container on a Ubuntu linux host, so it is not hard to run a script like this as a tmux session or other automatic startup method. I do not use the dedicated HA OS type installs, so I am not sure how to get this script to run there, hopefully there is a way.
You will need the linux utility ‘inotifywait’, it is part of ‘inotify-tools’ package, various install instructions are documented there:
Good hunting!
#!/usr/bin/env bash
#
# ha_log_rotate.sh
# 202106291016
#
# http://redsymbol.net/articles/unofficial-bash-strict-mode/
# Unofficial Bash Strict Mode (Unless You Looove Debugging)
set -euo pipefail
#
# try and keep a history of homeassistant log files
#
# path to ha log file
HA_PATH="/home/user/homeassistant/home-assistant.log"
# path to logrotate configuration file
ROT_CONFIG="/home/user/ha_log_rotate/ha.conf"
# the ha.conf file contains (note hard coded path to ha log file!!!):
#
#/home/user/homeassistant/home-assistant.log {
# rotate 9
#}
#
# path to logrotate state
ROT_STATE="/tmp/ha.state"
# loop forever
while [[ 1 == 1 ]]
do
# wait for ha log file to be created
while [[ ! -f $HA_PATH ]]
do
sleep 0.5
done
# watch for a close with a write on ha log file and do a log rotate when this occurs
while inotifywait $HA_PATH -e 'close_write';
do
logrotate -f -s $ROT_STATE $ROT_CONFIG
done
done
That’s the part I’m not so sure on. I know my way around Linux, but I’m not familiar enough with the Home Assistant OS architecture to be confident that I can do something like this as I don’t actually know how to get to a low enough level, even the way I know to SSH in is actually a container. I’ll do some digging though, I was thinking I’d have to go this route if I can’t find something else.
I was thinking about that too, didn’t notice the actual time was documented. For the sake of testing I just disabled auto_purge, I’ll see what happens tonight.
For what it’s worth manually purging with recorder.purge does not make the instance become unavailable.
alias: Backup Log on Shutdown
description: Backup Log on Shutdown
trigger:
- event: shutdown
platform: homeassistant
condition: []
action:
- data: {}
service: shell_command.backup_log
mode: single
This will work providing the restart causes the homeassistant stop event to fire. Restarting the Docker container causes it to fire for me, so I would think this would be the same in Home Assistant OS.
I’m not convinced I’m seeing a graceful shutdown where that event would fire, but having it won’t hurt so I’ve gone ahead and added it. We’ll see what happens tonight!
Overnight I still saw HA go down for ~5 minutes starting at 3am local time and unfortunately the automation that @Steven_Rollason had suggested didn’t fire which further confirms my theory that it’s not a graceful restart. For what it’s worth when I look in the log I also see the entry below which is what typically pops up when shutdown was less than graceful.
Since HA still went down this doesn’t seem to have changed anything, so I’ll re-enable auto_purge.
Next Steps
It seems that @CentralCommand is going to be my savior with log shipping here. I came across this thread in which they mentioned some addons they’d written to ship logs to Loki (which is viewable with Grafana). I have this stack up and running… now to wait till 3am.
Glad you found it It’s been really helpful for me too.
I have it on my list to write a community guide for “Persistent logging across restarts on HAOS” (or something along those lines) that basically goes through how to set up those addons and use it. There is already a Promtail+Loki community guide but its aimed at people with a container install as it describes doing things you can’t do in HAOS. I’ll get around to it at some point.
I now have a few days worth of logs that capture the restarts (thanks to @CentralCommand 's add ons) but I don’t see anything that indicates a problem. I see the services humming along, and then all of a sudden I start seeing log lines of supervisor rebooting.
which then starts to have a little more associated with it
2021-07-01 01:46:53
[system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' requested by ':1.7' (uid=0 pid=367 comm="/usr/sbin/NetworkManager --no-daemon ")
2021-07-01 01:46:53
Starting Network Manager Script Dispatcher Service...
2021-07-01 01:46:53
[system] Successfully activated service 'org.freedesktop.nm_dispatcher'
2021-07-01 01:46:53
Started Network Manager Script Dispatcher Service.
2021-07-01 01:47:03
NetworkManager-dispatcher.service: Succeeded.
That keeps up every few minutes until finally, all of a sudden HA reports that it’s rebooted.
2021-07-01 02:56:53
[system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' requested by ':1.7' (uid=0 pid=367 comm="/usr/sbin/NetworkManager --no-daemon ")
2021-07-01 02:56:53
Starting Network Manager Script Dispatcher Service...
2021-07-01 02:56:53
[system] Successfully activated service 'org.freedesktop.nm_dispatcher'
2021-07-01 02:56:53
Started Network Manager Script Dispatcher Service.
2021-07-01 02:57:03
NetworkManager-dispatcher.service: Succeeded.
2021-07-01 03:04:47
adjtime state 5 status 40 time Thu 2021-07-01 08:04:47.556094 UTC
2021-07-01 03:04:47
adjtime state 0 status 2000 time Thu 2021-07-01 08:04:47.556950 UTC
2021-07-01 03:04:47
Initial synchronization to time server 162.159.200.123:123 (time.cloudflare.com).
2021-07-01 03:04:47
Finished Wait Until Kernel Time Synchronized.
2021-07-01 03:04:47
Reached target System Time Synchronized.
2021-07-01 03:04:47
Started Periodic ext4 Online Metadata Check for All Filesystems.
2021-07-01 03:04:47
Started Discard unused blocks once a week.
2021-07-01 03:04:47
Reached target Timers.
2021-07-01 03:04:47
Starting HassOS supervisor...
2021-07-01 03:04:48
hassio_supervisor
2021-07-01 03:04:48
Started HassOS supervisor.
2021-07-01 03:04:48
Started Home Assistant CLI.
2021-07-01 03:04:48
Reached target Login Prompts.
2021-07-01 03:04:48
Reached target Multi-User System.
2021-07-01 03:04:48
Startup finished in 1.773s (kernel) + 35.138s (userspace) = 36.912s.
I’ve been staring at these logs for a couple of hours over the past few days now and I can’t find anything that stands out to me as abnormal. Not sure if anyone here may see something that sticks out?
Not that I can spot. Leading up to the reboot I see a lot of what seems to be DHCP negotiation (although it’s way faster than my DHCP lease is set to). For example there’s this snippet below where it’s repeating the same thing every 2 - 3 minutes, but that seems to be consistent even after the reboot.
It’s lower than I expected / recalled. It was set to five minutes, which I suppose if it’s renewing at half it’s lifetime that’s ~2.5 minutes which would explain the frequency. I did just push it out to an hour, I’ll see what happens tonight and share some logs in the morning.
Why so short? I doubt you are worried about running out of addresses to serve.
On the wireless network I manage where people move around a lot, the lease is 4 hours. I think our default lease time for our wired networks is 8 days.
At some point I was redoing DHCP reservations and didn’t want to have a crazy long TTL and didn’t want to run around rebooting everything as I did it. Afterwards I just forgot to up it again. It’s only 30 or so devices so it’s really not an issue for the router to be handing out the new addresses so fast.
It does make for a noisy network and, on the shared wireless airspace especially, add a lot of unnecessary overhead, reducing goodput (usable network bandwidth).
Thanks for the feedback on DHCP leases, I pushed it out to 24 hours since things are quite static. This did drastically reduce the log noise (see below) from NetworkManager, however I’m still seeing the instance become unavailable every day at the same time.
The only logs that show up around the restart are these:
2021-07-12 03:04:48
<info> [1626077088.0782] manager: (vethe31c7ac): new Veth device (/org/freedesktop/NetworkManager/Devices/9)
2021-07-12 03:04:48
<info> [1626077088.0836] manager: (vethbea90d5): new Veth device (/org/freedesktop/NetworkManager/Devices/10)
2021-07-12 03:04:48
<info> [1626077088.1443] manager: (veth8d69c4d): new Veth device (/org/freedesktop/NetworkManager/Devices/11)
2021-07-12 03:04:48
<info> [1626077088.1506] manager: (vethbbe54cb): new Veth device (/org/freedesktop/NetworkManager/Devices/12)
2021-07-12 03:04:48
<info> [1626077088.6795] device (vethbea90d5): carrier: link connected
2021-07-12 03:04:48
<info> [1626077088.6811] device (docker0): carrier: link connected
2021-07-12 03:04:49
<info> [1626077089.2117] device (vethbbe54cb): carrier: link connected
2021-07-12 03:04:58
<info> [1626077098.0334] manager: (veth1a6c8a8): new Veth device (/org/freedesktop/NetworkManager/Devices/13)
2021-07-12 03:04:58
<info> [1626077098.0399] manager: (vethe2994af): new Veth device (/org/freedesktop/NetworkManager/Devices/14)
2021-07-12 03:04:59
<info> [1626077099.0047] device (vethe2994af): carrier: link connected
2021-07-12 03:05:00
<info> [1626077100.0241] manager: (veth8e6df36): new Veth device (/org/freedesktop/NetworkManager/Devices/15)
2021-07-12 03:05:00
<info> [1626077100.0274] manager: (vethc060b3c): new Veth device (/org/freedesktop/NetworkManager/Devices/16)
2021-07-12 03:05:01
<info> [1626077101.0069] device (vethc060b3c): carrier: link connected
2021-07-12 03:05:01
<info> [1626077101.8750] manager: (veth8d5fbd7): new Veth device (/org/freedesktop/NetworkManager/Devices/17)
2021-07-12 03:05:01
<info> [1626077101.8786] manager: (veth00bfaa4): new Veth device (/org/freedesktop/NetworkManager/Devices/18)
2021-07-12 03:05:02
<info> [1626077102.8328] device (veth00bfaa4): carrier: link connected
2021-07-12 03:05:10
<info> [1626077110.7335] manager: (veth05a8284): new Veth device (/org/freedesktop/NetworkManager/Devices/19)
2021-07-12 03:05:10
<info> [1626077110.7400] manager: (veth4a00626): new Veth device (/org/freedesktop/NetworkManager/Devices/20)
2021-07-12 03:05:12
<info> [1626077112.1839] device (veth4a00626): carrier: link connected
2021-07-12 03:05:13
<info> [1626077113.1882] manager: (vethb9c2caa): new Veth device (/org/freedesktop/NetworkManager/Devices/21)
2021-07-12 03:05:13
<info> [1626077113.1943] manager: (veth3d14016): new Veth device (/org/freedesktop/NetworkManager/Devices/22)
2021-07-12 03:05:14
<info> [1626077114.1446] device (veth3d14016): carrier: link connected
2021-07-12 03:05:15
<info> [1626077115.2554] manager: (vethb317196): new Veth device (/org/freedesktop/NetworkManager/Devices/23)
2021-07-12 03:05:15
<info> [1626077115.2661] manager: (vetha472d3f): new Veth device (/org/freedesktop/NetworkManager/Devices/24)
2021-07-12 03:05:16
<info> [1626077116.3384] device (vetha472d3f): carrier: link connected
2021-07-12 03:05:24
<info> [1626077124.2465] manager: (vethf93e4a3): new Veth device (/org/freedesktop/NetworkManager/Devices/25)
2021-07-12 03:05:24
<info> [1626077124.2503] manager: (veth4280059): new Veth device (/org/freedesktop/NetworkManager/Devices/26)
2021-07-12 03:05:25
<info> [1626077125.2461] device (veth4280059): carrier: link connected
2021-07-12 03:05:26
<info> [1626077126.5668] manager: (veth2cd5c4f): new Veth device (/org/freedesktop/NetworkManager/Devices/27)
2021-07-12 03:05:26
<info> [1626077126.5720] manager: (veth907ebf0): new Veth device (/org/freedesktop/NetworkManager/Devices/28)
2021-07-12 03:05:27
<info> [1626077127.6969] device (veth907ebf0): carrier: link connected
2021-07-12 03:06:56
<info> [1626077216.0989] manager: (veth23a91df): new Veth device (/org/freedesktop/NetworkManager/Devices/29)
2021-07-12 03:06:56
<info> [1626077216.1022] manager: (veth0cb3e86): new Veth device (/org/freedesktop/NetworkManager/Devices/30)
2021-07-12 03:06:57
<info> [1626077217.1107] device (veth0cb3e86): carrier: link connected
2021-07-12 03:06:58
<info> [1626077218.2717] manager: (veth6acd5ff): new Veth device (/org/freedesktop/NetworkManager/Devices/31)
2021-07-12 03:06:58
<info> [1626077218.2822] manager: (veth96a2e48): new Veth device (/org/freedesktop/NetworkManager/Devices/32)
2021-07-12 03:06:59
<info> [1626077219.4592] device (veth96a2e48): carrier: link connected
2021-07-12 03:07:05
<info> [1626077225.7795] manager: (vethebbba1e): new Veth device (/org/freedesktop/NetworkManager/Devices/33)
2021-07-12 03:07:05
<info> [1626077225.7837] manager: (vethc68d416): new Veth device (/org/freedesktop/NetworkManager/Devices/34)
2021-07-12 03:07:07
<info> [1626077227.4228] device (vethc68d416): carrier: link connected
It’s been really helpful for me too.