Purge causes recorder to stop writing to the DB until HA is restarted (Auto purge happens at 4:12am) #117263
Comments
|
Hey there @home-assistant/core, mind taking a look at this issue as it has been labeled with an integration ( Code owner commandsCode owners of
(message by CodeOwnersMention) recorder documentation |
|
It sounds like you have an integration that is filling the database with state changes so quickly that the system cannot keep up. Try enabling debug logging for |
|
Hi, I enabled debug logging for I did just now install Home Assistant Container on a separate machine using the same configuration and noticed I could not reproduce the issue by running a manual purge. This could mean the issue is somehow caused by the installation environment. After doing a manual purge on the Container version the database size has been reduced to 620 MB, nice. When doing a purge on my original system with debug logging enabled for |
|
That sounds like a corrupt index You might try running an integrity check https://www.sqlite.org/pragma.html#pragma_integrity_check on the database and reindex anything that comes up: https://www.sqlite.org/lang_reindex.html It could also indicate a problem with your storage medium |
bdraco
added
database: sqlite3
problem in database
|
It is pretty much certainly an issue with my installation of HA Core and not with the database or storage medium. I installed HA Container on the same machine and now the issue is gone. Any suggestions why the issue only occurs with HA Core? |
|
Do you have a different version of SQLite on the core install? |
|
No because SQLite (the CLI tool) is not part of the Core dependencies. The Recorder page mentions Home Assistant uses SQLAlchemy for database access, but that module is not installed manually when installing Core. I expect HA installs this itself and also keeps it up to date. I don't know how I would compare the version numbers for this module. |
|
You can find the version under setting, system, repairs, three dot menu, system information |
|
Thanks @bdraco. According to the system information my Core install does indeed use a newer SQLite version than the Container install (3.45.3 > 3.44.2). It also uses a slightly newer Python version (3.12.3 > 3.12.2) for a slightly lower HA Core version (core-2024.5.2 < core-2024.5.3). I can try and see what happens if I equalize the Core install to the Container install. Do you know how I would downgrade the SQLite version? If you're interested I attach the system information outputs for the Core and Container installs: |
|
This is also happening for me now, a Core install. I recently upgraded Ubuntu Server to 24.04. Also on Python 3.12.3. The SQLite3 library version installed is 3.45.1-1ubuntu2. It gets locked up every morning at the programmed time (4:12?) and if I manually call the I installed the command-line |
|
I'm assuming this line: is the one causing the hang, as we never see the following log entry at .I also got logs that look the same once debugging / logging level debug are enabled: |
|
Partial thread dump via Not sure what the two |
|
I stoped HA and opened the database with the commandline So, I think I had some entry in the I just deleted the relevant events: And verified that no unreferenced Calling |
|
Unfortunately my instance got back to getting stuck at purge the second day after that. At this point my next steps are probably going to add debug logging to the diverse points of the above stack trace the next time this reproduces (I cleaned the database manually again this time). |
|
We found the problem Some old databases have Unfortunately SQLite does not support dropping a foreign key constraint (see To fix this the whole states table needs to be recreated using the steps here: https://www.sqlite.org/lang_altertable.html
|
|
so we need write a rebuild_table function for sqlite to fix this.
Going to go with the 12 step rebuild process.. Its slower but less risky. |
|
Will be fixed in 2024.8.0 |
|
cool, |
|
I'm not sure this is the actual problem in my case. I can't see any foreign key there... Edit: removed spurious extra copied text. |
Please check again as I looks like that is not the right database file unless you are running a 2-3 year old version of HA |
|
This instance was installed originally more than two years ago and has been migrated to the latest version each time via
Isn't this the right database file? What other name should I look for? |
|
Sure looks like its been changed recently. That's very strange that is missing all the foreign keys. I'm not sure whats going on with your system. events should look like this |
24 GB is likely enough. It should not be a problem, but is always better to have 2x the database size in case a table rebuild fails. I don't see any table rebuilds in your logs so either the table rebuild already happened, or there is something wrong with your database that prevents it from getting to that point. You can check to see if the table rebuild already happened by manually running the following % sqlite3 home-assistant_v2.db
SQLite version 3.43.2 2023-10-10 13:08:14
Enter ".help" for usage hints.
sqlite> .schema states
CREATE TABLE IF NOT EXISTS "states" (
"state_id" INTEGER NOT NULL ,
"entity_id" CHARACTER(0) NULL ,
"state" VARCHAR(255) NULL ,
"attributes" CHARACTER(0) NULL ,
"event_id" SMALLINT NULL ,
"last_changed" CHARACTER(0) NULL ,
"last_changed_ts" DOUBLE NULL ,
"last_updated" CHARACTER(0) NULL ,
"last_updated_ts" DOUBLE NULL ,
"old_state_id" INTEGER NULL ,
"attributes_id" INTEGER NULL ,
"context_id" CHARACTER(0) NULL ,
"context_user_id" CHARACTER(0) NULL ,
"context_parent_id" CHARACTER(0) NULL ,
"origin_idx" SMALLINT NULL ,
"context_id_bin" BLOB NULL ,
"context_user_id_bin" BLOB NULL ,
"context_parent_id_bin" BLOB NULL ,
"metadata_id" INTEGER NULL , last_reported_ts FLOAT,
PRIMARY KEY ("state_id"),
FOREIGN KEY("old_state_id") REFERENCES "states" ("state_id") ON UPDATE RESTRICT ON DELETE RESTRICT,
FOREIGN KEY("attributes_id") REFERENCES "state_attributes" ("attributes_id") ON UPDATE RESTRICT ON DELETE RESTRICT,
FOREIGN KEY("metadata_id") REFERENCES "states_meta" ("metadata_id") ON UPDATE RESTRICT ON DELETE RESTRICT
);
CREATE INDEX "ix_states_attributes_id" ON "states" ("attributes_id");
CREATE INDEX "ix_states_context_id_bin" ON "states" ("context_id_bin");
CREATE INDEX "ix_states_last_updated_ts" ON "states" ("last_updated_ts");
CREATE INDEX "ix_states_metadata_id_last_updated_ts" ON "states" ("metadata_id", "last_updated_ts");
CREATE INDEX "ix_states_old_state_id" ON "states" ("old_state_id");
sqlite> If you only see the 3 FOREIGN KEYs, the problem one has been removed and the rebuild is complete. If its still there, something else is wrong, and you'll need to enable |
|
I only see 2 FOREIGN KEYs: |
It looks like you don't have this issue. There should be a FK on |
Then why does the recorder purge cause my graphs to flatline? |
While the symptoms are the same, since the problematic foreign key is not there, its a different problem which will require a different solution. Please start a fresh issue report with debug logs for # Example configuration.yaml entry
logger:
default: info
logs:
sqlalchemy: debug |
|
2024.7.2 has certainly solved the "recorder locking-up" problem, but something is still not right in my system. The home-assistant_v2.db file grew from 3.2GB to 3.8GB after the upgrade, but has been static in size over the last 5 days. I have the following in configuration.yaml: |
|
Hey, I don't really know what to do, I'm having the same problem as above. recorder stops every day at4:30 and i have to reboot. I updated to 2024.7.2 and its the same. When i look in SQLite the temp table for events existed so it seems the migration did not complete. When i save the DB and try to do the migration externally it fails copying the data from the old table to the new because of "unique constraints". I really do not want to lose all of my energy data. I'm super annoyed that it was all working fine until a recent update and now I'm spending hours trying to fix it. Any ideas of where i might go for help? I tied the custom component but it didn't do anything (i assume it thinks the migration was completed). |
|
I also have the problem, just like jasonwfrancis1 |
|
As an added datapoint, I have been having this issue on mariadb. Upgrading didn't fix it. |
|
i managed to fix it myself, i basically migrated to maria DB and used a good tutorial to migrate all of the data. a few gaps while i was doing the whole process but i think im back up and running properly. just kicked off a purge, and its running...fingers crossed. |
|
Hi @bdraco After some time, my database keeps increasing. Don't know how to reduce it? I don't know if your corrections work correctly.
|
Also having this problem, even with 2024.7.2: It happens some time after the purge of 4 AM. However, events are no longer recorded after 4 AM. Until 04:12:xx log messages like this: Then: And then nothing from the recorder anymore. |
|
I am also still having this issue with 2024.7.4, recorder hangs after 4 in the morning and a reboot gets it going again. It was still working fine until I updated to 2024.7 |
|
Same over here, I’m on 2024.7.4 but recorder reliably does at 4am every day until a restart. What debug info can I provide to the effort? |
|
Still having this issue here as well, running 2024.8. I do have the recorder set to keep for 1 year, since I wanted the history but as mentioned above (#117263 (comment)) this was working fine up until last month (07/19 for me but I can't recall when or what version I may have updated to at that time). My recorder settings in configuration.yaml |
|
I have the same configuration, with 365 days of retention, but after upgrading to 2024.8 yesterday it seems my recorder didn't die last night at 4am! |
|
Same issue with 2024.8 |
|
I have default configuration and still have the issue 2024.8 |
|
After upgrading to 2024.8 and re-enabling auto_purge, today I see my graphs have stopped updating at 4 am again. SDD is at 100% and crunching away. After restarting HA, graphs are back, but with no data from 4am till restart. My recorder settings: @bdraco tagged as you provided the fix and closed the issue. Could it be the issue was not fixed in certain cases and can it be reopened? EDIT: added some info |
Run a manual purge with your retention time (1 year) and wait for it to stop crunching before restarting. |
|
I wish there was a way to do a manual migration. That would be fine for me. |
I'm currently doing this (90 days retention). It has been running for 3 hours now, with 100% disk usage. I assume this is not any different than auto purge? (which had been running for 8 hours without ending before I restarted) |
Its been posted above. |
|
Please be sure your system meets the disk space requirements before updating to 2024.8.1 https://www.home-assistant.io/integrations/recorder/#disk-space-requirements As there are multiple issue threads going, and your comments will likely be missed otherwise, please continue at https://community.home-assistant.io/t/psa-2024-7-recorder-problems/746428 |
and others
This problem is solved in 2024.7.2. If the system ran out of disk space, and the table rebuild failed, it will try again in 2024.8.1+ see issue #123348 and solution #123388
Workaround: Disabling nightly auto purge will prevent the issue from occurring (this is not a long term solution)
Be sure to re-enable auto-purge after installing 2024.7.2 or your database will grow without bounds, and your system will eventually run out of disk space or become sluggish.
Cause: #117263 (comment)
Solution: #120779
The problem
Every night at around ~4:10 the histories for all entities stop. This has been happening since at least April 9th. I updated Home Assistant to 2024.4.1 on April 5th, but I can't say for sure if this issue started directly afterwards. A restart of Home Assistant allows recording again but does not restore the history missed since ~4:10. I suspect it has something to do with the Recorder auto purge at 4:12 because the same symptoms happen when the purge is run manually.
I don't think the manual or automatic purge is currently able to finish because the (SQLite) database seems way too large (>6GB) for my configured
purge_keep_daysof 7.If I run
recorder.purgefrom the web UI the same symptoms happen like during the night. By looking at the mtime it is clearhome-assistant_v2.dbdoes not get written to anymore.htopshows HA using 100% of one CPU core continously andiotopshow HA reading from disk at ~400MB/s continously. This went on for at least 25 minutes before I stopped the process.The logs show nothing unusual happening around 4:12. When I run
recorder.purgefrom the web UI with verbose logging enabled the logs just show:When HA is stopped using SIGTERM the shutdown takes a long time and it is clear from the logs it is waiting for a Recorder task:
See the rest of the relevant messages during shutdown below.
What version of Home Assistant Core has the issue?
core-2024.5.2
What was the last working version of Home Assistant Core?
No response
What type of installation are you running?
Home Assistant Core
Integration causing the issue
Recorder
Link to integration documentation on our website
https://www.home-assistant.io/integrations/recorder/#service-purge
Diagnostics information
No response
Example YAML snippet
Anything in the logs that might be useful for us?
2024-05-11 15:20:00.573 WARNING (MainThread) [homeassistant.core] Timed out waiting for final writes to complete, the shutdown will continue 2024-05-11 15:20:00.573 WARNING (MainThread) [homeassistant.core] Shutdown stage 'final write': still running: <Task pending name='Task-2684' coro=<Recorder._async_shutdown() running at /srv/homeassistant/lib/python3.12/site-packages/homeassistant/components/recorder/core.py:475> wait_for=<Future pending cb=[_chain_future.<locals>._call_check_cancel() at /usr/lib/python3.12/asyncio/futures.py:387, <1 more>, Task.task_wakeup()] created at /usr/lib/python3.12/asyncio/base_events.py:449> cb=[set.remove()] created at /srv/homeassistant/lib/python3.12/site-packages/homeassistant/util/async_.py:40> 2024-05-11 15:20:30.580 WARNING (MainThread) [homeassistant.core] Timed out waiting for close event to be processed, the shutdown will continue 2024-05-11 15:20:30.580 WARNING (MainThread) [homeassistant.core] Shutdown stage 'close': still running: <Task pending name='Task-2684' coro=<Recorder._async_shutdown() running at /srv/homeassistant/lib/python3.12/site-packages/homeassistant/components/recorder/core.py:475> wait_for=<Future pending cb=[_chain_future.<locals>._call_check_cancel() at /usr/lib/python3.12/asyncio/futures.py:387, <1 more>, Task.task_wakeup()] created at /usr/lib/python3.12/asyncio/base_events.py:449> cb=[set.remove()] created at /srv/homeassistant/lib/python3.12/site-packages/homeassistant/util/async_.py:40> 2024-05-11 15:20:30.580 WARNING (MainThread) [homeassistant.core] Shutdown stage 'close': still running: <Task pending name='Task-2714' coro=<Recorder._async_close() running at /srv/homeassistant/lib/python3.12/site-packages/homeassistant/components/recorder/core.py:467> wait_for=<Future pending cb=[_chain_future.<locals>._call_check_cancel() at /usr/lib/python3.12/asyncio/futures.py:387, <1 more>, Task.task_wakeup()] created at /usr/lib/python3.12/asyncio/base_events.py:449> cb=[set.remove()] created at /srv/homeassistant/lib/python3.12/site-packages/homeassistant/util/async_.py:40> 2024-05-11 15:20:30.752 WARNING (Thread-4 (_do_shutdown)) [homeassistant.util.executor] Thread[SyncWorker_2] is still running at shutdown: File "/usr/lib/python3.12/threading.py", line 1030, in _bootstrap self._bootstrap_inner() File "/usr/lib/python3.12/threading.py", line 1073, in _bootstrap_inner self.run() File "/usr/lib/python3.12/threading.py", line 1010, in run self._target(*self._args, **self._kwargs) File "/usr/lib/python3.12/concurrent/futures/thread.py", line 92, in _worker work_item.run() File "/usr/lib/python3.12/concurrent/futures/thread.py", line 58, in run result = self.fn(*self.args, **self.kwargs) File "/usr/lib/python3.12/threading.py", line 1147, in join self._wait_for_tstate_lock() File "/usr/lib/python3.12/threading.py", line 1167, in _wait_for_tstate_lock if lock.acquire(block, timeout): 2024-05-11 15:20:30.919 WARNING (Thread-4 (_do_shutdown)) [homeassistant.util.executor] Thread[SyncWorker_4] is still running at shutdown: File "/usr/lib/python3.12/threading.py", line 1030, in _bootstrap self._bootstrap_inner() File "/usr/lib/python3.12/threading.py", line 1073, in _bootstrap_inner self.run() File "/usr/lib/python3.12/threading.py", line 1010, in run self._target(*self._args, **self._kwargs) File "/usr/lib/python3.12/concurrent/futures/thread.py", line 92, in _worker work_item.run() File "/usr/lib/python3.12/concurrent/futures/thread.py", line 58, in run result = self.fn(*self.args, **self.kwargs) File "/usr/lib/python3.12/threading.py", line 1147, in join self._wait_for_tstate_lock() File "/usr/lib/python3.12/threading.py", line 1167, in _wait_for_tstate_lock if lock.acquire(block, timeout): 2024-05-11 15:20:31.403 WARNING (Thread-4 (_do_shutdown)) [homeassistant.util.executor] Thread[SyncWorker_2] is still running at shutdown: File "/usr/lib/python3.12/threading.py", line 1030, in _bootstrap self._bootstrap_inner() File "/usr/lib/python3.12/threading.py", line 1073, in _bootstrap_inner self.run() File "/usr/lib/python3.12/threading.py", line 1010, in run self._target(*self._args, **self._kwargs) File "/usr/lib/python3.12/concurrent/futures/thread.py", line 92, in _worker work_item.run() File "/usr/lib/python3.12/concurrent/futures/thread.py", line 58, in run result = self.fn(*self.args, **self.kwargs) File "/usr/lib/python3.12/threading.py", line 1147, in join self._wait_for_tstate_lock() File "/usr/lib/python3.12/threading.py", line 1167, in _wait_for_tstate_lock if lock.acquire(block, timeout): 2024-05-11 15:20:31.887 WARNING (Thread-4 (_do_shutdown)) [homeassistant.util.executor] Thread[SyncWorker_4] is still running at shutdown: File "/usr/lib/python3.12/threading.py", line 1030, in _bootstrap self._bootstrap_inner() File "/usr/lib/python3.12/threading.py", line 1073, in _bootstrap_inner self.run() File "/usr/lib/python3.12/threading.py", line 1010, in run self._target(*self._args, **self._kwargs) File "/usr/lib/python3.12/concurrent/futures/thread.py", line 92, in _worker work_item.run() File "/usr/lib/python3.12/concurrent/futures/thread.py", line 58, in run result = self.fn(*self.args, **self.kwargs) File "/usr/lib/python3.12/threading.py", line 1147, in join self._wait_for_tstate_lock() File "/usr/lib/python3.12/threading.py", line 1167, in _wait_for_tstate_lock if lock.acquire(block, timeout): 2024-05-11 15:20:40.751 WARNING (MainThread) [homeassistant.util.executor] Thread[SyncWorker_2] is still running at shutdown: File "/usr/lib/python3.12/threading.py", line 1030, in _bootstrap self._bootstrap_inner() File "/usr/lib/python3.12/threading.py", line 1073, in _bootstrap_inner self.run() File "/usr/lib/python3.12/threading.py", line 1010, in run self._target(*self._args, **self._kwargs) File "/usr/lib/python3.12/concurrent/futures/thread.py", line 92, in _worker work_item.run() File "/usr/lib/python3.12/concurrent/futures/thread.py", line 58, in run result = self.fn(*self.args, **self.kwargs) File "/usr/lib/python3.12/threading.py", line 1147, in join self._wait_for_tstate_lock() File "/usr/lib/python3.12/threading.py", line 1167, in _wait_for_tstate_lock if lock.acquire(block, timeout): 2024-05-11 15:20:40.918 WARNING (MainThread) [homeassistant.util.executor] Thread[SyncWorker_4] is still running at shutdown: File "/usr/lib/python3.12/threading.py", line 1030, in _bootstrap self._bootstrap_inner() File "/usr/lib/python3.12/threading.py", line 1073, in _bootstrap_inner self.run() File "/usr/lib/python3.12/threading.py", line 1010, in run self._target(*self._args, **self._kwargs) File "/usr/lib/python3.12/concurrent/futures/thread.py", line 92, in _worker work_item.run() File "/usr/lib/python3.12/concurrent/futures/thread.py", line 58, in run result = self.fn(*self.args, **self.kwargs) File "/usr/lib/python3.12/threading.py", line 1147, in join self._wait_for_tstate_lock() File "/usr/lib/python3.12/threading.py", line 1167, in _wait_for_tstate_lock if lock.acquire(block, timeout): 2024-05-11 15:20:41.402 WARNING (MainThread) [homeassistant.util.executor] Thread[SyncWorker_2] is still running at shutdown: File "/usr/lib/python3.12/threading.py", line 1030, in _bootstrap self._bootstrap_inner() File "/usr/lib/python3.12/threading.py", line 1073, in _bootstrap_inner self.run() File "/usr/lib/python3.12/threading.py", line 1010, in run self._target(*self._args, **self._kwargs) File "/usr/lib/python3.12/concurrent/futures/thread.py", line 92, in _worker work_item.run() File "/usr/lib/python3.12/concurrent/futures/thread.py", line 58, in run result = self.fn(*self.args, **self.kwargs) File "/usr/lib/python3.12/threading.py", line 1147, in join self._wait_for_tstate_lock() File "/usr/lib/python3.12/threading.py", line 1167, in _wait_for_tstate_lock if lock.acquire(block, timeout): 2024-05-11 15:20:41.886 WARNING (MainThread) [homeassistant.util.executor] Thread[SyncWorker_4] is still running at shutdown: File "/usr/lib/python3.12/threading.py", line 1030, in _bootstrap self._bootstrap_inner() File "/usr/lib/python3.12/threading.py", line 1073, in _bootstrap_inner self.run() File "/usr/lib/python3.12/threading.py", line 1010, in run self._target(*self._args, **self._kwargs) File "/usr/lib/python3.12/concurrent/futures/thread.py", line 92, in _worker work_item.run() File "/usr/lib/python3.12/concurrent/futures/thread.py", line 58, in run result = self.fn(*self.args, **self.kwargs) File "/usr/lib/python3.12/threading.py", line 1147, in join self._wait_for_tstate_lock() File "/usr/lib/python3.12/threading.py", line 1167, in _wait_for_tstate_lock if lock.acquire(block, timeout):Additional information
I thought maybe my database could be corrupted, so with HA shutdown I ran
mv home-assistant_v2.db home-assistant_v2_old.db; sqlite3 home-assistant_v2_old.db ".recover" | sqlite3 home-assistant_v2.dband then tried to run a purge again. Unfortunately the problem was not resolved. My database did shrink by about 1.5 GB.The text was updated successfully, but these errors were encountered: