MariaDB replication failure: Fatal error 1236 - binlog shows 'Event truncated'

Question

Disclaimer: I am not a certified DBA

I have configured MariaDB Master - Slave replication and everything was working but now have an error that I cannot get past.

I have run the following on the slave server

> show slave status\G

This is the output

    Slave_IO_State: 
                  Master_Host: 192.168.193.116
                  Master_User: replication
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: violet-1.005377
          Read_Master_Log_Pos: 812448796
               Relay_Log_File: mariadb-relay-bin.000002
                Relay_Log_Pos: 536
        Relay_Master_Log_File: violet-1.005377
             Slave_IO_Running: No
            Slave_SQL_Running: Yes
              Replicate_Do_DB: violet
          Replicate_Ignore_DB: 
           Replicate_Do_Table: 
       Replicate_Ignore_Table: 
      Replicate_Wild_Do_Table: 
  Replicate_Wild_Ignore_Table: 
                   Last_Errno: 0
                   Last_Error: 
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 812448796
              Relay_Log_Space: 836
              Until_Condition: None
               Until_Log_File: 
                Until_Log_Pos: 0
           Master_SSL_Allowed: No
           Master_SSL_CA_File: 
           Master_SSL_CA_Path: 
              Master_SSL_Cert: 
            Master_SSL_Cipher: 
               Master_SSL_Key: 
        Seconds_Behind_Master: NULL
Master_SSL_Verify_Server_Cert: No
                Last_IO_Errno: 1236
                Last_IO_Error: Got fatal error 1236 from master when reading data from binary log: 'log event entry exceeded max_allowed_packet; Increase max_allowed_packet on master; the first event 'violet-1.005377' at 812448796, the last event read from 'violet-1.005377' at 812448796, the last byte read from 'violet-1.005377' at 812448815.'
               Last_SQL_Errno: 0
               Last_SQL_Error: 
  Replicate_Ignore_Server_Ids: 
             Master_Server_Id: 1
               Master_SSL_Crl: 
           Master_SSL_Crlpath: 
                   Using_Gtid: No
                  Gtid_IO_Pos: 
      Replicate_Do_Domain_Ids: 
  Replicate_Ignore_Domain_Ids: 
                Parallel_Mode: conservative

The max_allowed_packet on master and slave are both set to 1G

The master status is currently as below

show master status

+-----------------+-----------+--------------+------------------+
| File            | Position  | Binlog_Do_DB | Binlog_Ignore_DB |
+-----------------+-----------+--------------+------------------+
| violet-1.005380 | 338731974 | violet       |                  |
+-----------------+-----------+--------------+------------------+

Checking the binlog with the following command

> mysqlbinlog --start-position=812448815 /var/lib/mysql/violet-1.005377 --hexdump

produces the output below

/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#190611 23:26:18 server id 1  end_log_pos 249 
# Position
#           |Timestamp   |Type |Master ID   |Size        |Master Pos  |Flags
#        4  |8a 2a 00 5d |0f   |01 00 00 00 |f5 00 00 00 |f9 00 00 00 |00 00
#
#       17  04 00 31 30 2e 31 2e 33  35 2d 4d 61 72 69 61 44  |..10.1.35-MariaD|
#       27  42 00 6c 6f 67 00 00 00  00 00 00 00 00 00 00 00  |B.log...........|
#       37  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
#       47  00 00 00 00 00 00 00 00  13 38 0d 00 08 00 12 00  |.........8......|
#       57  04 04 04 04 12 00 00 dd  00 04 1a 08 00 00 00 08  |................|
#       67  08 08 02 00 00 00 0a 0a  0a 00 00 00 00 00 00 00  |................|
#       77  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
#       87  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
#       97  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
#       a7  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
#       b7  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
#       c7  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
#       d7  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
#       e7  00 00 00 00 00 00 00 00  00 04 13 04 00 00 6c ea  |..............l.|
#       f7  fc 09                                             |..|
#
# Event:    Start: binlog v 4, server v 10.1.35-MariaDB created 190611 23:26:18
BINLOG '
iioAXQ8BAAAA9QAAAPkAAAAAAAQAMTAuMS4zNS1NYXJpYURCAGxvZwAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAA3QAEGggAAAAICAgCAAAACgoKAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAEEwQAAGzq/Ak=
'/*!*/;
ERROR: Error in Log_event::read_log_event(): 'Event truncated', data_len: 1701407845, event_type: 32
ERROR: Could not read entry at offset 812448815: Error in log format or read error.
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

If I run CHANGE MASTER TO .... MASTER_LOG_POSITION=812448815 then I get an identical error but the position will be something like 812448834 (based on the fact that I have done this 4 times from the initial error and it just keeps failing, the last log position was reported as 812448796)

How can I prevent this error from occurring and get my replication working again without having to do a full backup / restore and reset of the replication process?

Answer 1

This error is usually caused by a hardware glitch or a bug so vague that it hasn't been found in over a decade. The optimal solution that will definitely fix it without any risk of anomalies is to fully re-initialize the replication. You can do this without downtime or locking by using either xtrabackup or mysqldump --single-transaction.

Replication can be expensive if you have terabytes of data, so there may be a way you can restore replication without rebuilding the slave completely. You can use mysqlbinlog on the master to identify where the transaction is begin and look for near position 812448796 (your Exec_Master_Log_Pos). There is a very good chance that the position listed is actually has error and no transaction in the binlog starts at that position. You are also very likely to find that the coordinate distances between these transactions are nowhere near your max_allowed_packet value.

If that is the case, you can reset your replication coordinates on the slave to the last transaction mysqlbinlog lists that is before the position the slave thinks it is at. You can find more details on exactly what to do in this MariaDB and MySQL troubleshooting article.

Answer 2

I purged the logs, took a fresh dump of the DB, restored to the slave and started the replication service again and replication was working smoothly.

For a while.

I then ended up with the same issue after a few hours so have decided to forget about replication and just use regular backups of the relevant data tables. Not ideal but it works.