History and logbook failing. Where to start looking?

ashscott · October 2, 2022, 11:38am

I’m using MariaDB and my history and logbook data keep failing, as illustrated by the image of my processor usage history below.

It’s as if it’s being turned off. MariaDB is continually running.

An HA restart restores it but it fails again.

I’ve uninstalled MariaDB and reconfigured it, twice, to no avail.

This is the only error I see in the MariaDB log. Unsure what it’s trying to tell me though.

ERROR: Got unexpected response from the API: There is already a MySQL service in use from core_mariadb

Any ideas where to look next?

tom_l · October 2, 2022, 11:44am

Looks like it is failing at the same time early in the new day every day.

What time is it when that happens (zoom in).

ashscott · October 2, 2022, 11:49am

It’s around 01:30.

HA is still running and the error I posted above was around 08:30.

At 01:00 each morning the Google Backup addon runs which could possibly take 30 minutes though there’s nothing to indicate it’s end time.

tom_l · October 2, 2022, 11:51am

Look closer at the actual time, on a few different days. Is it always exactly the same?

ashscott · October 2, 2022, 11:52am

No. It varies by 7-10 minutes.

ashscott · October 2, 2022, 12:01pm

Well, this has just gotten a whole lot worse.

I’ve just tried a restart and HA is stuck on loading recorder.

ashscott · October 2, 2022, 12:04pm

It’s finally restarted and is showing the following error in the logs:

Logger: homeassistant.setup
Source: setup.py:184
First occurred: 1:01:13 PM (4 occurrences)
Last logged: 1:01:24 PM

Setup failed for logbook: (DependencyError(...), 'Could not setup dependencies: recorder')
Setup failed for history: (DependencyError(...), 'Could not setup dependencies: recorder')
Setup failed for energy: (DependencyError(...), 'Could not setup dependencies: history, recorder')
Setup failed for default_config: (DependencyError(...), 'Could not setup dependencies: energy, history, logbook')

Any idea why that would be?

tom_l · October 2, 2022, 12:05pm

Not without seeing the MariaDB logs.

ashscott · October 2, 2022, 12:17pm

I commented out:

recorder:
  db_url: mysql://homeassistant:password@core-mariadb/homeassistant?charset=utf8mb4

in configuration.yaml and HA restarted pretty rapidly.

With it back in it’s taking an age to restart again, getting stuck on starting Recorder.

Once HA restarted, MariaDB log shows:

s6-rc: info: service s6rc-oneshot-runner: starting
s6-rc: info: service s6rc-oneshot-runner successfully started
s6-rc: info: service fix-attrs: starting
s6-rc: info: service fix-attrs successfully started
s6-rc: info: service legacy-cont-init: starting
s6-rc: info: service legacy-cont-init successfully started
s6-rc: info: service legacy-services: starting
services-up: info: copying legacy longrun mariadb (no readiness notification)
services-up: info: copying legacy longrun mariadb-lock (no readiness notification)
[12:40:36] INFO: Using existing mariadb initial system
[12:40:36] INFO: Starting MariaDB
221002 12:40:36 mysqld_safe Logging to '/data/databases/mariadb.err'.
221002 12:40:36 mysqld_safe Starting mariadbd daemon with databases from /data/databases
221002 12:40:36 mysqld_safe Starting mariadbd daemon with databases from /data/databases
2022-10-02 12:40:36 0 [Note] /usr/bin/mariadbd (server 10.6.8-MariaDB) starting as process 241 ...
2022-10-02 12:40:36 0 [Note] InnoDB: Compressed tables use zlib 1.2.12
2022-10-02 12:40:36 0 [Note] InnoDB: Number of pools: 1
2022-10-02 12:40:36 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
2022-10-02 12:40:36 0 [Note] mariadbd: O_TMPFILE is not supported on /var/tmp (disabling future attempts)
2022-10-02 12:40:36 0 [Note] InnoDB: Using Linux native AIO
2022-10-02 12:40:36 0 [Note] InnoDB: Initializing buffer pool, total size = 134217728, chunk size = 134217728
2022-10-02 12:40:36 0 [Note] InnoDB: Completed initialization of buffer pool
2022-10-02 12:40:36 0 [Note] InnoDB: 128 rollback segments are active.
2022-10-02 12:40:36 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2022-10-02 12:40:36 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2022-10-02 12:40:36 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2022-10-02 12:40:36 0 [Note] InnoDB: 10.6.8 started; log sequence number 290481921229; transaction id 15230434
2022-10-02 12:40:36 0 [Note] Plugin 'FEEDBACK' is disabled.
2022-10-02 12:40:36 0 [Note] InnoDB: Loading buffer pool(s) from /data/databases/ib_buffer_pool
2022-10-02 12:40:36 0 [Note] Server socket created on IP: '0.0.0.0'.
2022-10-02 12:40:36 0 [Note] Server socket created on IP: '::'.
2022-10-02 12:40:36 0 [Note] InnoDB: Buffer pool(s) load completed at 221002 12:40:36
2022-10-02 12:40:36 0 [Note] /usr/bin/mariadbd: ready for connections.
Version: '10.6.8-MariaDB'  socket: '/run/mysqld/mysqld.sock'  port: 3306  MariaDB Server
[12:40:37] INFO: Check data integrity and fix corruptions
mysql.column_stats                                 OK
mysql.columns_priv                                 OK
mysql.db                                           OK
mysql.event                                        OK
mysql.func                                         OK
mysql.global_priv                                  OK
mysql.gtid_slave_pos                               OK
mysql.help_category                                OK
mysql.help_keyword                                 OK
mysql.help_relation                                OK
mysql.help_topic                                   OK
mysql.index_stats                                  OK
mysql.innodb_index_stats                           OK
mysql.innodb_table_stats                           OK
mysql.plugin                                       OK
mysql.proc                                         OK
mysql.procs_priv                                   OK
mysql.proxies_priv                                 OK
mysql.roles_mapping                                OK
mysql.servers                                      OK
mysql.table_stats                                  OK
mysql.tables_priv                                  OK
mysql.time_zone                                    OK
mysql.time_zone_leap_second                        OK
mysql.time_zone_name                               OK
mysql.time_zone_transition                         OK
mysql.time_zone_transition_type                    OK
mysql.transaction_registry                         OK
homeassistant.event_data                           OK
homeassistant.events                               OK
homeassistant.recorder_runs                        OK
homeassistant.schema_changes                       OK
homeassistant.state_attributes                     OK
homeassistant.states                               OK
homeassistant.statistics                           OK
homeassistant.statistics_meta                      OK
homeassistant.statistics_runs                      OK
homeassistant.statistics_short_term                OK
sys.sys_config                                     OK
[12:40:37] INFO: Ensuring internal database upgrades are performed
[12:40:37] INFO: Ensure databases exists
[12:40:37] INFO: Create database homeassistant
[12:40:37] INFO: Ensure users exists and are updated
[12:40:37] INFO: Update user homeassistant
[12:40:37] INFO: Init/Update rights
[12:40:38] INFO: Granting all privileges to homeassistant on homeassistant
[12:40:38] INFO: Successfully send service information to Home Assistant.
s6-rc: info: service legacy-services successfully started
[12:52:48] INFO: Lock tables using mariadb client...
[12:52:48] INFO: MariaDB tables locked.
2022-10-02 12:55:56 19 [Warning] Aborted connection 19 to db: 'homeassistant' user: 'homeassistant' host: '172.30.32.1' (Got an error reading communication packets)
2022-10-02 12:55:56 17 [Warning] Aborted connection 17 to db: 'homeassistant' user: 'homeassistant' host: '172.30.32.1' (Got an error reading communication packets)
2022-10-02 12:55:56 18 [Warning] Aborted connection 18 to db: 'homeassistant' user: 'homeassistant' host: '172.30.32.1' (Got an error reading communication packets)
2022-10-02 12:55:56 20 [Warning] Aborted connection 20 to db: 'homeassistant' user: 'homeassistant' host: '172.30.32.1' (Got timeout reading communication packets)
2022-10-02 13:06:21 22 [Warning] Aborted connection 22 to db: 'homeassistant' user: 'homeassistant' host: '172.30.32.1' (Got timeout reading communication packets)

ashscott · October 2, 2022, 1:00pm

I’ve uninstalled MariaDB and removed the recorder in config.

Restarted HA.

Reinstalled MariaDB, added db_url: mysql://homeassistant:password@core-mariadb/homeassistant?charset=utf8mb4 to config and restarted.

HA restarted rapidly and MariaDB log looks fine.

I’ve also changed the backup time to 04:00 to see if the problem re-occurs and time shifts.

tom_l · October 2, 2022, 9:37pm

Bad time to do that. Recorder purging happens at 4:12am.

ashscott · October 3, 2022, 6:01am

Thanks for the headsup. I changed it to 03:00.

ashscott · October 14, 2022, 11:44am

This has failed again.

Any idea what I can log (or where) to try and track down the reason for the failure?

I’m seeing this in the MariaDB log. Not sure if it’s either helpful or relevant.

ashscott · October 22, 2022, 7:05am

Further investigation shows that the ‘crash’ of history/logbook recording occurs when the CPU usage goes above 90%, and this occurs when nightly backups are scheduled.

My Frigate add-on consumes about 60% of CPU capacity but should recording history stop, requiring a restart?