Mariadb - Bad magic header in tc log.

[jpcastberg]

Installation Method

Docker Installation

AzuraCast Release Channel

Rolling Release Channel

Current AzuraCast Version

#2550ca4

What happened?

Issue started after upgrading azuracast to latest this morning - container would not become healthy, and it seemed that mariadb not starting up was the culprit (logs attached).

I wrassled with this one for a good bit, and stumbled on this fix. Didn't quite understand it, but it seemed safe enough to try. I replaced the mariadb version in the command to the one currently use, mariadb:11.2-jammy, which produced this log output (irrelevant lines excluded):

2024-05-20  4:10:12 0 [Note] Recovering after a crash using tc.log
2024-05-20  4:10:12 0 [ERROR] Bad magic header in tc log
2024-05-20  4:10:12 0 [ERROR] Crash recovery failed. Either correct the problem (if it's, for example, out of memory error) and restart, or delete tc log and start server with --tc-heuristic-recover={commit|rollback}

That error message led me to mariadb documentation which suggested deleting the file (in this case /var/lib/mysql/tc.log). After deleting that file and rebuilding/starting the azuracast container things began to work again!

I have no idea what went wrong here - hoping that you might, and that at least people facing the same problem can find this post. :)

Relevant log output

mariadb stdout | 2024-05-19 20:57:50 0 [Note] Starting MariaDB 11.2.3-MariaDB-1:11.2.3+maria~deb12 source revision 79580f4f96fc2547711f674eb8dd514abd312b4a as process 188
mariadb stdout | 
mariadb stdout | 2024-05-19 20:57:50 0 [Note] InnoDB: The first data file './ibdata1' did not exist. A new tablespace will be created!
mariadb stdout | 2024-05-19 20:57:50 0 [Note] InnoDB: Compressed tables use zlib 1.2.13
mariadb stdout | 
mariadb stdout | 2024-05-19 20:57:50 0 [Note] InnoDB: Number of transaction pools: 1
mariadb stdout | 2024-05-19 20:57:50 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
mariadb stdout | 
mariadb stdout | 2024-05-19 20:57:50 0 [Note] mariadbd: O_TMPFILE is not supported on /tmp (disabling future attempts)
mariadb stdout | 2024-05-19 20:57:50 0 [Warning] mariadbd: io_uring_queue_init() failed with errno 95
mariadb stdout | 2024-05-19 20:57:50 0 [Warning] InnoDB: liburing disabled: falling back to innodb_use_native_aio=OFF
mariadb stdout | 
mariadb stdout | 2024-05-19 20:57:50 0 [Note] InnoDB: Initializing buffer pool, total size = 128.000MiB, chunk size = 2.000MiB
mariadb stdout | 
mariadb stdout | 2024-05-19 20:57:50 0 [Note] InnoDB: Completed initialization of buffer pool
mariadb stdout | 
mariadb stdout | 2024-05-19 20:57:50 0 [Note] InnoDB: Setting file './ibdata1' size to 12.000MiB. Physically writing the file full; Please wait ...
mariadb stdout | 
mariadb stdout | 2024-05-19 20:57:50 0 [Note] InnoDB: File './ibdata1' size is now 12.000MiB.
mariadb stdout | 
mariadb stdout | 2024-05-19 20:57:50 0 [Note] InnoDB: File system buffers for log disabled (block size=512 bytes)
mariadb stdout | 
mariadb stdout | 2024-05-19 20:57:50 0 [Note] InnoDB: Data file .//undo001 did not exist: new to be created
mariadb stdout | 2024-05-19 20:57:50 0 [Note] InnoDB: Setting file .//undo001 size to 10.000MiB
mariadb stdout | 2024-05-19 20:57:50 0 [Note] InnoDB: Database physically writes the file full: wait...
mariadb stdout | 
mariadb stdout | 2024-05-19 20:57:50 0 [Note] InnoDB: Data file .//undo002 did not exist: new to be created
mariadb stdout | 2024-05-19 20:57:50 0 [Note] InnoDB: Setting file .//undo002 size to 10.000MiB
mariadb stdout | 2024-05-19 20:57:50 0 [Note] InnoDB: Database physically writes the file full: wait...
mariadb stdout | 
mariadb stdout | 2024-05-19 20:57:50 0 [Note] InnoDB: Data file .//undo003 did not exist: new to be created
mariadb stdout | 2024-05-19 20:57:50 0 [Note] InnoDB: Setting file .//undo003 size to 10.000MiB
mariadb stdout | 2024-05-19 20:57:50 0 [Note] InnoDB: Database physically writes the file full: wait...
mariadb stdout | 
mariadb stdout | 2024-05-19 20:57:50 0 [Note] InnoDB: Doublewrite buffer not found: creating new
mariadb stdout | 
mariadb stdout | 2024-05-19 20:57:50 0 [Note] InnoDB: Opened 3 undo tablespaces
mariadb stdout | 
mariadb stdout | 2024-05-19 20:57:50 0 [Note] InnoDB: 128 rollback segments in 3 undo tablespaces are active.
mariadb stdout | 
mariadb stdout | 2024-05-19 20:57:50 0 [Note] InnoDB: Setting file './ibtmp1' size to 12.000MiB. Physically writing the file full; Please wait ...
mariadb stdout | 
mariadb stdout | 2024-05-19 20:57:50 0 [Note] InnoDB: File './ibtmp1' size is now 12.000MiB.
mariadb stdout | 
mariadb stdout | 2024-05-19 20:57:50 0 [Note] InnoDB: log sequence number 0; transaction id 3
mariadb stdout | 2024-05-19 20:57:50 0 [Note] Plugin 'FEEDBACK' is disabled.
mariadb stdout | 2024-05-19 20:57:50 0 [Note] Plugin 'wsrep-provider' is disabled.
mariadb stdout | 
mariadb stdout | 2024-05-19 20:57:50 0 [ERROR] Could not open mysql.plugin table: "Table 'mysql.plugin' doesn't exist". Some plugins may be not loaded
mariadb stdout | 
mariadb stdout | 2024-05-19 20:57:50 0 [ERROR] Can't open and lock privilege tables: Table 'mysql.servers' doesn't exist
mariadb stdout | 
mariadb stdout | 2024-05-19 20:57:50 0 [Note] Server socket created on IP: '0.0.0.0'.
mariadb stdout | 
mariadb stdout | 2024-05-19 20:57:50 0 [Note] Server socket created on IP: '::'.
mariadb stdout | 
mariadb stdout | 2024-05-19 20:57:50 0 [ERROR] Fatal error: Can't open and lock privilege tables: Table 'mysql.db' doesn't exist
mariadb stdout | 2024-05-19 20:57:50 0 [ERROR] Aborting

-------------- separate part of logs --------------

[2024-05-20T03:57:52.364059+00:00] AzuraCast.ERROR: Doctrine\DBAL\Exception\ConnectionException: An exception occurred in the driver: SQLSTATE[HY000] [2002] Connection refused (uncaught exception) at /var/azuracast/www/vendor/doctrine/dbal/src/Driver/API/MySQL/ExceptionConverter.php line 80 while running console command `azuracast:sync:nowplaying` {"exception":"[object] (Doctrine\\DBAL\\Exception\\ConnectionException(code: 2002): An exception occurred in the driver: SQLSTATE[HY000] [2002] Connection refused at /var/azuracast/www/vendor/doctrine/dbal/src/Driver/API/MySQL/ExceptionConverter.php:80)\n[previous exception] [object] (Doctrine\\DBAL\\Driver\\PDO\\Exception(code: 2002): SQLSTATE[HY000] [2002] Connection refused at /var/azuracast/www/vendor/doctrine/dbal/src/Driver/PDO/Exception.php:28)\n[previous exception] [object] (PDOException(code: 2002): SQLSTATE[HY000] [2002] Connection refused at /var/azuracast/www/vendor/doctrine/dbal/src/Driver/PDO/MySQL/Driver.php:33)"} []
[2024-05-20T03:57:52.364634+00:00] AzuraCast.WARNING: Console command `azuracast:sync:nowplaying` exited with error code 2002. [] []

In ExceptionConverter.php line 80:
                                                                               
  An exception occurred in the driver: SQLSTATE[HY000] [2002] Connection refu  
  sed                                                                          
                                                                               

In Exception.php line 28:
                                             
  SQLSTATE[HY000] [2002] Connection refused  
                                             

In Driver.php line 33:
                                             
  SQLSTATE[HY000] [2002] Connection refused  
                                             

azuracast:sync:nowplaying [-t|--timeout [TIMEOUT]]