[MDEV-18437] Binlog logging Statement AND Row at the same time Created: 2019-01-31  Updated: 2019-05-20  Resolved: 2019-05-20

Status: Closed
Project: MariaDB Server
Component/s: Configuration, Replication, Storage Engine - InnoDB
Affects Version/s: 10.2.21
Fix Version/s: 10.2.25, 10.3.16, 10.4.5

Type: Bug Priority: Major
Reporter: Pablo Guzmán Assignee: Andrei Elkin
Resolution: Duplicate Votes: 1
Labels: log_bin, statement
Environment:

Docker mariadb:10.2 running under Ubuntu 16.04

Attachments: Text File global_variables.txt     Text File master_binary.txt     Text File slave_rely_binary.txt    

 Description   

We recently upgraded from MariaDB 10.1 to MariaDB 10.2.21 and we are facing a critical error in our replication schema.

From our diagnosis, one transaction, when writing to binlog, is inserting one event in both formats, Mixed AND Statement. When the slave tries to duplicate the binary log it gets a "DUPLICATE PRIMARY KEY" in that transaction.

               Last_SQL_Error: Error 'Duplicate entry '5277245' for key 'PRIMARY'' on query. Default database: 'SVC'. Query: 'INSERT INTO `FileTaskDateLog` (`idFileTaskDate`, `fecha`, `action`, `message`) VALUES ('660794', '2019-01-30 18:01:02', 'SAVED FILE', 'Guardado archivo {DbAPI_SVC_Objects_InputFile:671150} in the file system')'

This error can be seen in this extract from the master's binary log (using mysqlbinlog -v option)

384057858-# at 217275360
 
384057873-#190130 18:01:02 server id 2  end_log_pos 217275402 CRC32 0x2539902c 	GTID 2-2-381134617 trans
 
384057968-/*!100001 SET @@session.gtid_seq_no=381134617*//*!*/;
 
384058022-BEGIN
 
....
 
384065477-### INSERT INTO `SVC`.`FileTaskDateLog`
 
384065517-### SET
 
384065525:###   @1=5277245
 
384065542-###   @2=660794
 
384065558-###   @3='2019-01-30 18:01:02'
 
384065589-###   @4='SAVED FILE'
 
384065611-###   @5='Guardado archivo {DbAPI_SVC_Objects_InputFile:671150} in the file system'
 
384065695-# at 217277527
 
384065710-#190130 18:01:02 server id 2  end_log_pos 217277559 CRC32 0x1d92ecbd 	Intvar
 
384065787:SET INSERT_ID=5277245/*!*/;
 
384065815-# at 217277559
 
384065830-#190130 18:01:02 server id 2  end_log_pos 217277839 CRC32 0xa5e57101 	Query	thread_id=693090	exec_time=0	error_code=0
 
384065948-SET TIMESTAMP=1548882062/*!*/;
 
384065979-INSERT INTO `FileTaskDateLog` (`idFileTaskDate`, `fecha`, `action`, `message`) VALUES ('660794', '2019-01-30 18:01:02', 'SAVED FILE', 'Guardado archivo {DbAPI_SVC_Objects_InputFile:671150} in the file system')
 
384066189-/*!*/;
 
384066196-# at 217277839
 
384066211-#190130 18:01:02 server id 2  end_log_pos 217277870 CRC32 0x0fafcd18 	Xid = 58771609
 
384066296-COMMIT/*!*/;

Update:
We found the cause that caused this error:
One process we had did a weird behavior;
START TRANSACTION, then LOCKS TABLES, <does stuff where the error happens>, then UNLOCK TABLES and finally COMMIT.

Removing this behavior (Removing the Lock Tables and leaving it with just transactions) solved the issue. (Reading the documentation it seems when you issue LOCK TABLES the active transaction should be closed, it seems that behavior it's acting oddly)

 Comments   
Comment by Daniel Ragle [ 2019-04-24 ]

I added a test case reduction over on:

https://jira.mariadb.org/browse/MDEV-19158

but now think my report may be better suited here, as the duplicate RBR and Statement in the binary log is exactly what I am seeing as well. I'm seeing this behavior in 10.3.14.

In my case, the following all appear to be required:

  • A table (say t1) with a trigger that modifies a second table (say t2)
  • LOCK TABLES t1 WRITE, t3 WRITE
  • modify t1 such that the trigger actually executes (I.E., if it's an UPDATE trigger then perform an actual UPDATE on t1). Doesn't seem to matter if the trigger actually makes any changes, it just needs to execute
  • INSERT t3

The final INSERT of T3 is where the error in the binary log occurs for me. In my case all the tables are MyISAM, so no TRANSACTION statements are in play. t2 is locked implicitly; but even if you add it directly to the LOCK statement you still get the errant behavior.

Comment by Sujatha Sivakumar (Inactive) [ 2019-05-20 ]

This issue is a duplicate of MDEV-19158.

Generated at Thu Feb 08 08:44:05 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.