Core: Recorder purge_days not working

[Phontana]

Home Assistant release:
0.39.1

Python release:
3.5.2

Component/platform:
recorder

Description of problem:
The purge_days config option of the recorder is not working. I set purge_days to '3' 8 days ago, but it does not work. I can still see 8 days in history and it hasn't deleted old data.

Expected:
The data older than 3 days should be deleted.

Problem-relevant configuration.yaml entries and steps to reproduce:
recorder: purge_days: 3

[bram2202]

Same here.
Deleted the existing database,
Set: recorder : purge_days: 2

After 2 weeks the database still grows and can view values from the beginning of the new database

[ViperRNMC]

Same issue here, DB still grows.

[arsaboo]

Same here....purge is not respected and the database keeps growing.

[covrig]

Same here. home-assistant_v2 is getting close to 2Gb. A restart on Pi takes close to 10 minutes.

[arsaboo]

May be @kellerza has some thoughts on what is going on.

[kellerza]

Any idea when this stopped working?

[kellerza]

Most likely the signature of the event is wrong here, but not sure. Do you see anything in the log?

This is the signature @balloob changed in dev (but this might only come in 0.40, since it is a big change that needs to be tested in dev a bit

[covrig]

Probably for more than a week.
Nothing in the log. I keep getting the error below for a few weeks now, but I think it is a result of the database being to large.

[homeassistant.components.recorder] Error during query: (sqlite3.OperationalError) database is locked

I don't think this is related to the present issue:

[homeassistant.core] Timer got out of sync. Resetting

[arsaboo]

I am on 0.38.3 and even there the purge is not working. I have it set for 3 days, but I can see logs for 24 Feb (I am thinking I deleted the db file that day after restarting HA)

[Phontana]

I don't know When this started happening, I added the option last week.

I don't see anything in the log.

[kipwittchen]

I've had my purge set to 5 days for awhile now and the last date I can pull history for is February 12th which implies feb. 17th was the last day it worked. So looks like 0.38.3 maybe introduced it? (I don't recall exactly when I updated but I'm pretty good about it)

FYI, I'm running mysql if it makes any difference.

[arsaboo]

Quite possible that 0.38.3 introduced the bug as I am seeing it on 0.38.3.

[covrig]

@balloob @kellerza Is there any workaround for this bug? My Pi's microSD card died last night.

[balloob]

All of Recorder init has been updated in 0.40. Please let us know if you can repro the issue with that version.

[covrig]

@balloob Thanks for answering. I was on 0.39.1. I need to restore my device before I can move to 0.40. I assume that is the latest dev version?

[balloob]

Yes, 0.40 is what is currently in dev. Should be released in a week + change.

[kipwittchen]

If I want to run the dev version, are there any breaking changes to fix in my config at the moment?

[kipwittchen]

Hi @balloob, I upgraded to the dev version and it appears my database is still not being purged (I have it set to 5 days). It's been about 3 hours. Is the purge scheduled to happen at midnight or should it have already?

[kellerza]

The purge is only scheduled every second day.

If you want to cheat it you can change to timedelta(minutes=5) on your machine for a short while - see here

[covrig]

I noticed that. Is there a reason behind this? Why can't we have a daily purge?
I have a lot of ZWave devices and the database is always huge.

[kellerza]

Purging is probably quite heavy on IO (especially the SD card in a lot of case), so did not want to run this every day for that reason

[erikmouw]

FWIW, my database has grown from 32MB to 126 MB in a single day.

Before, I noticed that the Sonos media player component logs a change every 10 seconds, and while you could argue that might be interesting information about Sonos players that actually play something, for idle players it's not particularly interesting that they've been idle for 10 seconds more. I have 4 Sonos players, so you can imagine 34560 log entries a day about them don't give that much information, but it eats lots of diskspace (I used to have 400MB database files with 7 days of history).

Starting from hass 0.37 I have excluded the Sonos players from the recorder and purge after three days and that appeared to keep the database size around 20 MB (which IMHO is reasonable), but in 0.39 the excessive growth has come back. I don't know if that's due to an alleged error in the recorder component, or because I have enabled the Apple TV media player component. I've tried out excluding the Apple TV media player from the recorder, but that doesn't seem to work because I a) see errors about login failure to the Apple TV, and b) the database has grown with 100MB in a day. On the console, hass updates the Apple TV status every 10 seconds, and while the Apple TV is mainly used as YouTube and Netflix client, 21 hours a day it's just idle and I'm not particularly interested in that being logged every 10 seconds.

I have removed all Apple TV entries using:

sqlite> delete from states where states.entity_id is 'media_player.apple_tv';
sqlite> delete from events where events.event_data glob '*media_player.apple_tv*';

And after a vacuum full; that has brought the size back down to 28 MB, but if you look at the contents, there's still way too much data in the database:

sqlite> select event_id,event_type,created from events order by event_id asc limit 5;
182561|state_changed|2017-02-23 23:35:30.661369
182568|state_changed|2017-02-23 23:36:31.409922
182573|state_changed|2017-02-23 23:37:20.526096
182575|state_changed|2017-02-23 23:37:30.654007
182579|state_changed|2017-02-23 23:37:59.873685
sqlite> select state_id,entity_id,created from states order by state_id asc limit 5;
176940|sun.sun|2017-02-23 23:35:30.935146
176947|sun.sun|2017-02-23 23:36:32.366450
176952|device_tracker.timecapsule|2017-02-23 23:37:21.502903
176954|sun.sun|2017-02-23 23:37:31.588251
176958|device_tracker.timecapsule|2017-02-23 23:38:00.785411

IOW: I can confirm this bug, purge_days is ignored, and that wouldn't be too bad as the amount of data is still quite low (with sun.sun the most chatty one). However, if at the same time you have the recorder ignoring exclude items for very chatty components like the Apple TV, this bug becomes very visible.

[erikmouw]

I just thought a bit longer about this: a non-working purge_day and a very chatty Apple TV component (that even doesn't get excluded) might also be the cause of the "database locked" errors other users have seen.

(just my [insert-local-currency-here] 0.02)

[kipwittchen]

I changed the recorder file to timedelta(minutes=5) and I'm still getting no purging (running latest dev). It's been running about an hour like that now.

[pvizeli]

@ericgingras the sonos update bug is fix. I think 0.39 have a zwave log bug and that fill you DB.

[erikmouw]

@pvizeli: good to know the Sonos bug is fixed, that means I can remove the exclude items from the recorder.

I don't have any zwave devices yet, only a very chatty Apple TV component. Excluding it from the recorder doesn't make a difference, it still fills the database. Not only doesn't the recorder listen to the purge_days parameter, it also doesn't appear to listen to exclude parameters. Maybe something wrong in the parameter parsing of the recorder component?

[arsaboo]

This is still not fixed in 0.40. I have purge_days: 3, but I can still the logs going back 5 days.

[kipwittchen]

@arsaboo it may be due to timedelta(days=2)), I can't pull my logs from before March 10th (I have purge days set to 5) so it appears to be working again for me. And could be as much as 2 days after you upgrade to 0.40.0 before the purge (although I don't know what resets that timedelta).

[kellerza]

@kipwittchen, any restart will restart the timer

[arsaboo]

@kellerza @kipwittchen Indeed that seems to be the case. I tested it out by changing to timedelta(days=2)) and it deleted the logs. I guess, I should stop restarting HA too often 😉

Looks like the issue is fixed in 0.40 and can be closed. Wondering if we should change timedelta(days=1))

[balloob]

To be honest, instead of 1 day we should even keep it to run on HOMEASSISTANT_START and then every day ?

[erikmouw]

@balloob: That would be a sensible default. Make sure that the every day cleanup runs at night to prevent slowing down the user interface.

[covrig]

@kellerza It seems the bug is back as of 0.41.0. My db is growing way too much again (2 Gb with a purge_days: 2). Is this the case? Do I need to do something?

[PatteWi]

I have the same Issue with 0.43.2. Purge is set to 5 days but nothing is purged yet (the DB runs since 10 days)

[arsaboo]

@PatteWi The clock is reset after every reset. If you let HA run continuously for over 48 hours, your history will be purged.

[PatteWi]

@arsaboo Okay, this could be the solution. Just 24h waiting isn't enough?

[arsaboo]

Nopes....it is set to timedelta(days=2) see here.

[covrig]

@arsaboo No the case. I have 6 days from the last restart, with a 2 day purge and it does not work.

[arsaboo]

I am assuming you are on the latest build. Change timedelta(days=2) to timedelta(minutes=5).