[BUG] normal docker-compose down results in mariadb innodb crash recovery

[fleischsalatinspace]

I need do investigate this further, but it looks if using docker-compose down mariadb container does not get shutdown successfully and crashes instead. This results in a innodb crash recovery on every db start. Mariadb container logs look like this:

cat /var/lib/mysql/9b552028c3fb.err
2022-01-10 11:06:22 0 [Note] InnoDB: Using Linux native AIO
2022-01-10 11:06:22 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2022-01-10 11:06:22 0 [Note] InnoDB: Uses event mutexes
2022-01-10 11:06:22 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2022-01-10 11:06:22 0 [Note] InnoDB: Number of pools: 1
2022-01-10 11:06:22 0 [Note] InnoDB: Using SSE2 crc32 instructions
2022-01-10 11:06:22 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2022-01-10 11:06:22 0 [Note] InnoDB: Completed initialization of buffer pool
2022-01-10 11:06:22 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2022-01-10 11:06:22 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=58323719930
2022-01-10 11:06:23 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2022-01-10 11:06:23 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2022-01-10 11:06:23 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2022-01-10 11:06:23 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2022-01-10 11:06:23 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2022-01-10 11:06:23 0 [Note] InnoDB: Waiting for purge to start
2022-01-10 11:06:23 0 [Note] InnoDB: 10.3.17 started; log sequence number 58323719939; transaction id 82286801
2022-01-10 11:06:23 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2022-01-10 11:06:23 0 [Note] InnoDB: Buffer pool(s) load completed at 220110 11:06:23
2022-01-10 11:06:23 0 [Note] Plugin 'FEEDBACK' is disabled.
2022-01-10 11:06:23 0 [Note] Recovering after a crash using tc.log
2022-01-10 11:06:23 0 [Note] Starting crash recovery...
2022-01-10 11:06:23 0 [Note] Crash recovery finished.

I haven't noticed any impact on data integrity. If we add correct depends_on in the service declarations and maybe a healthcheck for every service, this issue can be solved.

[fleischsalatinspace]

Well there is already depends_on in pf service declaration:

   depends_on:
      - pfdb
      - pf-redis
      - pf-socket

[samoneilll]

@fleischsalatinspace maybe we could use stop_grace_period for this?

I personally have never had any issues with it probably due to very low database usage from maria, but maybe if you have heavier db utilization it might take longer than the default 10s to flush writes, and then docker-compose sends a SIGKILL.

Adding the stop_grace_period to the compose file might be a good place to start to see if mariadb just needs more time to respond to the SIGTERM

[samoneilll]

@fleischsalatinspace still having issues with this or can we close?

[fleischsalatinspace]

Just checked in the logs this still happens an all instances with a broad range of instance sizes. I have not tried stop_grace_period . Consulting the internet i am not sure what severity this error message actually is : https://mariadb.com/kb/en/heuristic-recovery-with-the-transaction-coordinator-log/#automatic-crash-recovery-with-the-memory-mapped-file-based-transaction-coordinator-log As mentioned above I have not noticed any impact on data integrity :shrug:

[samoneilll]

It seems like it's normal unless you have binary logging enabled? Or am I not understanding the docs correctly.