Recorder warns sqlite3 was not shutdown cleanly, despite controlled shutdown

[adamfeldman]

The problem

Recently, I often but not always get a warning that the Recorder's default sqlite3 DB was not shutdown cleanly. This is despite performing a controlled shutdown via the UI on the Hardware settings page.

Currently running 2022.6.x and HAOS 8.1. This issue started within the past month or so. Hard for me to pinpoint if it's correlated with HAOS 8.x or the Core version.

I have a feeling this issue will need to be moved to the HAOS repo, but the direct problem that is logged is from Recorder.

I have run HAOS in a VM for a few years (OVA image running within KVM on Proxmox). I always shut it down from within the HAOS guest via the UI.

I am sure there are more diagnostics I can help pull, I am not sure where to start.

Thank you teams!

2022-06-18 09:21:03 WARNING (Recorder) [homeassistant.components.recorder.util] The system could not validate that the sqlite3 database at //config/home-assistant_v2.db was shutdown cleanly

What version of Home Assistant Core has the issue?

core-2022.6.6

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant OS

Integration causing the issue

Recorder

Link to integration documentation on our website

https://www.home-assistant.io/integrations/recorder/

Diagnostics information

No response

Example YAML snippet

No response

Anything in the logs that might be useful for us?

No response

Additional information

No response

[probot-home-assistant[bot]]

recorder documentation recorder source _{^{(message by IssueLinks)}}

[probot-home-assistant[bot]]

Hey there @home-assistant/core, mind taking a look at this issue as it has been labeled with an integration (recorder) you are listed as a code owner for? Thanks! _{^{(message by CodeOwnersMention)}}

[mrcfelici]

I have the same problem, is there any news about it? Many thanks

[pvizeli]

I guess the issue is, that core now doing online database migration. We need a way to get the information on the supervisor to prevent shutdown/reboots while core migrates live the database. Maybe it's also an issue with sqlite. Coult be that the python 3.10 upgrade solve that in 2022.7

[adamfeldman]

Thanks for the info @pvizeli! The issue remains in the 2022.7.x series and on HAOS 8.2.

In my experience it's very consistent – IIRC anytime I've done a controlled shutdown via the UI, the sqlite warning shows up in the logs.

[nvOC-Stubo]

Same issue here with Supervisor 2022.07.0 and HA 2022.8.3.

[snowmangh]

I also have this error but usually after shutting down/restarting my Synology NAS. HA 2022.7.6 running inside Docker.

[jimmyl88]

I have the same problem after restarting HA from GUI, have to reboot the VM.

Have recently moved my VM to a new host and get a corrupt db-file. Then i restored to a 5 days old backup and then it all worked for 2 weeks.

Home Assistant 2022.10.5 Supervisor 2022.10.0 Operating System 9.3

[Commifreak]

Same here (docker) 2023-01-02 10:40:07.272 WARNING (Recorder) [homeassistant.components.recorder.util] The system could not validate that the sqlite3 database at //config/home-assistant_v2.db was shutdown cleanly but it always was a clean shutdown. Maybe sometimes the shutdown does not finish ongoing events? During my test I had this:

2023-01-02 10:45:31.925 WARNING (Recorder) [homeassistant.components.recorder.util] The system could not validate that the sqlite3 database at //config/home-assistant_v2.db was shutdown cleanly
2023-01-02 10:45:31.984 WARNING (Recorder) [homeassistant.components.recorder.util] Ended unfinished session (id=13 from 2023-01-02 09:44:37.593355)

[bdraco]

If you shutdown via docker you can hit the container shutdown timeout (I think its 10 seconds) which causes an abrupt shutdown as it does not give Home Assistant enough time to properly shutdown

[TTLucian]

I use VMWare Workstation and I get this error every time I restart the VM. HASOS is shutting down cleanly.

The system could not validate that the sqlite3 database at //config/home-assistant_v2.db was shutdown cleanly

Ended unfinished session (id=462 from 2023-02-15 21:45:30.649049)

[Commifreak]

I also checked my docker env: shutdown timeout: 120sec. HA is done earlier but the message keeps popping up (sometimes, not always).

[LucaOlovrap]

Same issue here. Does anyone has a workaround with the exception of removing that database and let it regenerate it (it keeps reboot and appear after some days)?

[bdraco]

We need a full log from the run before the issue appears with debug logging turned on for homeassistant.components.recorder

I also opened https://github.com/home-assistant/core/pull/91261 which will cause the recorder to try to shutdown cleanly if something really goes wrong.

[issue-triage-workflows[bot]]

There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates. Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 👍 This issue has now been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.

[Commifreak]

Let us know if that works for you by adding a comment 👍

Issue still there.

[ELind77]

I am experiencing the same issue running HA on Docker.

I run HAnon unRAID and I take nightly backups of all of the Docker volumes (there is an unRAID plugin that makes common practice). The backup process logs show the HA container was stopped in 10 seconds while I have the timeout set at 120 seconds. Not really sure what's going on here.

I can check the logs from the HA container this weekend. Any advice on what to look for?

I can also try moving to MariaDB but it would be nice to get some insight into this issue.

[gcarneiro]

I was having this problem, new installations or restored, after reboot HA did not start. I changed my sd card and problem stop.

[masi]

I'm using Home Assistant OS on a Home Assistant Yellow and get this error every time I power on HA. I'm always use the UI to do a clean shut down.

I do this quite often as I'm still playing around.

[ginjo]

Also experiencing this issue using docker image homeassistant/home-assistant:2024.1

[Deimos761]

Same problem for me I noted this issue since core 2024.1.1 and now it goes on 2024.1.6. Never shuttted down abruptly; daily clean host.shutdown. Before restarting, daily clean database (1 hour before) I tried to erase the db and starting a new one but the issue is still there.

I use HAOS in a VMware environment

Logger: homeassistant.components.recorder.util
Source: components/recorder/util.py:332
Integration: Recorder (documentation, issues)
First occurred: 00:59:07 (1 occurrences)
Last logged: 00:59:07

The system could not validate that the sqlite3 database at //config/home-assistant_v2.db was shutdown cleanly

[RhavoX]

In HA 2024.2 when node-red issues the host_shutdown service I also get this log.

[amarofarinha]

Hi all. i have the same here. I migrated from homeassistant blue to a proxmox cluster and now i allways have this log entry when reestart. Everything seems to be working fine but allways 2 messages related.

Proxmox 8.1.4

Core 2024.2.5 Supervisor 2024.02.1 Operating System 12.0 Frontend 20240207.1

i have these 2 entries in log:

Logger: homeassistant.components.recorder.util Source: components/recorder/util.py:611 Integration: Recorder (documentation, issues) First occurred: 3:51:35 PM (1 occurrences) Last logged: 3:51:35 PM

Ended unfinished session (id=312 from 2024-03-01 15:47:50.708938)

Logger: homeassistant.components.recorder.util Source: components/recorder/util.py:332 Integration: Recorder (documentation, issues) First occurred: 3:51:35 PM (1 occurrences) Last logged: 3:51:35 PM

The system could not validate that the sqlite3 database at //config/home-assistant_v2.db was shutdown cleanly

[litinoveweedle]

I have the issue on the 2024.04.03 on my supervised installation as well. I realized it during the development of the custom integration. If I restart HA (from the web menu) after it was running from the previous day (means more than ~ ten hours) I will get same error after HA restart:

2024-04-20 16:02:02.369 WARNING (Recorder) [homeassistant.components.recorder.util] The system could not validate that the sqlite3 database at //config/home-assistant_v2.db was shutdown cleanly
2024-04-20 16:02:02.384 WARNING (Recorder) [homeassistant.components.recorder.util] Ended unfinished session (id=565 from 2024-04-19 23:51:45.488175)

The HA shutdown phase seems to be very long (very close to 300s / 5min) and there is nothing in the logs after HA restart is triggered (with normal warning log level). Is there any 5min shutdown timeout? Can it be extended?

But if I restart HA after it was running only for few tens of minutes (up to hour or two), the restart is almost immediate.

I use HA on supervised installation on server hardware, with SQLite being placed on NVMe disk, so bare HW performance shall not be an issue, even with my DB size around 1GB.

@bdraco: I just started HA recorder with debug set, but due to said above to reproduce error I will need to keep it running for some time and therefore the produced log would be huge. I am also not completely comfortable to share all the data publicly. Is there anything we can do about it? Thank you.

[bdraco]

It seems like you have something blocking shutdown which is why it gives up and shuts down uncleanly. You might be able enable debug logs for homeassistant.core, and than down a shutdown to reveal what it is waiting for

[litinoveweedle]

Hello @bdraco, thank you for reply. I will first finish my test with recorder debug (sometime tomorrow) and then I will try the one with the suggested homeassistant.core debug.

But anyway, to have something blocking HA shutdown could (and probably would occasionally happen) in the complex and open HA architecture. The point is it doesn't seem to be handled by the homeassistant.core correctly. If I have open SQLite connection and shutdown call shall is scheduled, close call has to be scheduled and executed even if there would be something (custom integration) hanging. I would expect any integration to be terminated after shutdown timeout expiration and then SQLite connection to be properly closed.

[bdraco]

If a custom integration is blocking the event loop it can prevent the shutdown code from running. Since custom integrations execute at the same privilege level as Home Assistant itself they can disrupt normal operation. If it is a case is the event loop being blocked you may be able to find it by turning on asyncio debug with the profiler integration

[litinoveweedle]

Thank you, that explanation makes sense. The only issue is, that it appear only after some runtime, therefore being harder to reproduce. I will try to provide debug.

[litinoveweedle]

@bdraco So with recorder debug, this is how the HA restart looks like:

2024-04-21 17:20:12.112 DEBUG (Recorder) [homeassistant.components.recorder.core] Processing task: <Event call_service[L]: domain=homeassistant, service=restart, service_data=>
2024-04-21 17:20:12.112 DEBUG (Recorder) [homeassistant.components.recorder.pool.RecorderPool] Connection <sqlite3.Connection object at 0x7f155495eb60> checked out from pool
2024-04-21 17:20:16.554 DEBUG (Recorder) [homeassistant.components.recorder.core] Processing task: <Event homeassistant_stop[L]>

thats all, past that stop message nothing was logged. As you can see from log after the restart, it took exactly 4 minutes for HA restart and database was not correctly closed.

2024-04-21 17:24:16.762 WARNING (Recorder) [homeassistant.components.recorder.util] The system could not validate that the sqlite3 database at //config/home-assistant_v2.db was shutdown cleanly
2024-04-21 17:24:16.787 WARNING (Recorder) [homeassistant.components.recorder.util] Ended unfinished session (id=566 from 2024-04-20 14:02:02.367693)

[bdraco]

If definitely shouldn't take 4 minutes to get there.

You could try turning on full debug logs and see if anything comes up during the restart, if not you'll probably have to instrument the code to find the source of shutdown being blocked. Alternatively, if the UI is still responsive for the 4 minute after shutdown is requested, we could add a service to the profiler to dump all the current running tasks