Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-18437

Binlog logging Statement AND Row at the same time

    XMLWordPrintable

    Details

      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)

        Attachments

        1. global_variables.txt
          23 kB
          Pablo Guzmán
        2. master_binary.txt
          10 kB
          Pablo Guzmán
        3. slave_rely_binary.txt
          10 kB
          Pablo Guzmán

          Activity

            People

            Assignee:
            Elkin Andrei Elkin
            Reporter:
            pvguzman Pablo Guzmán
            Votes:
            1 Vote for this issue
            Watchers:
            4 Start watching this issue

              Dates

              Created:
              Updated:
              Resolved:

                Git Integration