[#MDEV-17490] MariaDB 10.3 slave fails to replicate from a MariaDB 10.2 master

[MDEV-17490] MariaDB 10.3 slave fails to replicate from a MariaDB 10.2 master Created: 2018-10-18 Updated: 2023-05-02 Resolved: 2023-05-02
Status:	Closed
Project:	MariaDB Server
Component/s:	Replication, Server
Affects Version/s:	10.2.17, 10.2.18, 10.3.10, 10.8.5, 10.4.28
Fix Version/s:	N/A

Type:

Bug

Priority:

Critical

Reporter:

Gabriel Gomiz

Assignee:

suresh ramagiri

Resolution:

Incomplete

Votes:

Labels:

binlog, replication, slave

Environment:

CentOS 7.x

Issue Links:

Blocks
blocks	MDEV-17420	MariaDB slave 10.2 leaks temporary ta...	Open

Description

We have a 10.2.18 master and 4 slaves with 10.2.18. Because of this bug that I've reported last week (https://jira.mariadb.org/browse/MDEV-17420) we tried to upgrade one of the replicas to 10.3.10 to see if the bug was still there in that version.

After the upgrade, the slave began to sync binary log events from the master, but after a few seconds it stopped with the following errors:

mysqld[15138]: 2018-10-17  9:22:28 156 [ERROR] Slave IO thread did not receive an expected Rows-log end-of-statement for event starting at log 'main.010755' position 89390527 whose last block was seen at log 'main.010755' position 89390527. The end-of-statement should have been delivered before the current one at log 'main.010755' position 89390610

mysqld[15138]: 2018-10-17  9:22:28 156 [ERROR] Slave I/O: Relay log write failure: could not queue event from master, Internal MariaDB error code: 1595

We checked the binary log in the master and does not seem corrupted and the other 3 replicas are working ok (still with 10.2.18). Also the relay log on the slave seems ok.

The slave is stopped with the following status:

mainro [(none)]> show slave status\G

*************************** 1. row ***************************

           Master_Log_File: main.010755

       Read_Master_Log_Pos: 89411517

            Relay_Log_File: relay-bin.000002

             Relay_Log_Pos: 550

     Relay_Master_Log_File: main.010755

          Slave_IO_Running: No

         Slave_SQL_Running: Yes

       Exec_Master_Log_Pos: 89410432

           Relay_Log_Space: 1657

             Last_IO_Errno: 1595

             Last_IO_Error: Relay log write failure: could not queue event from master

            Last_SQL_Errno: 0

            Last_SQL_Error:

   Slave_SQL_Running_State: Slave has read all relay log; waiting for the slave I/O thread to update it

          Slave_DDL_Groups: 16763

Slave_Non_Transactional_Groups: 7974

    Slave_Transactional_Groups: 107415

We have already tried with RESET SLAVE, clearing relay logs and executing CHANGE MASTER TO again. But the result is the same.

I've dumped the master binary log at that position and, interestingly, slave IO thread stops in a binlog block (master binlog format is MIXED).

The master/slave set that is failing is the main database server for our organization. It has 1.2 TB of data with 38 databases, views, stored procedures, triggers and complex queries.

In the same servers, we have 3 other small sets of master/slaves with the same combination (10.2.18 master and 10.3.10 slaves) and are working perfectly. Of course, these sets are smaller and simpler than the instance that is failing.

Thanks

Comments

Comment by Daniel Black [ 2018-10-18 ]

Can you show the binary log around that position? If you don't want to make it public can you upload it to ftps://ftp.mariadb.com (doc: https://mariadb.com/kb/en/meta/mariadb-ftp-server/ ). You can make an extract binary log by taking the small header and appending it to extracted chunks (using dd) using the offset as a literal file offset. mysqlbinlog can show the required offsets to use and can test the resulting file.

Comment by Gabriel Gomiz [ 2018-10-18 ]

# mysqlbinlog -v main.010755 -j 89390527 | more

/*!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

#181017  7:23:26 server id 1  end_log_pos 256 CRC32 0x8114aae9 	Start: binlog v 4, server v 10.2.18-MariaDB-log created 181017  7:23:26 at startup

ROLLBACK/*!*/;

BINLOG '

ng3HWw8BAAAA/AAAAAABAAAAAAQAMTAuMi4xOC1NYXJpYURCLWxvZwAAAAAAAAAAAAAAAAAAAAAA

AAAAAAAAAAAAAAAAAACeDcdbEzgNAAgAEgAEBAQEEgAA5AAEGggAAAAICAgCAAAACgoKAAAAAAAA

AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA

AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA

AAAAAAAAAAAEEwQADQgICAoKCgHpqhSB

'/*!*/;

# at 89390527

# at 89390610

#181017  8:12:03 server id 1  end_log_pos 89390759 CRC32 0xc5f77b19 	Query	thread_id=67291	exec_time=0	error_code=0

SET TIMESTAMP=1539774723/*!*/;

SET @@session.pseudo_thread_id=67291/*!*/;

SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1, @@session.check_constraint_checks=1/*!*/;

SET @@session.sql_mode=1075838976/*!*/;

SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;

/*!\C utf8 *//*!*/;

SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=8/*!*/;

SET @@session.lc_time_names=0/*!*/;

SET @@session.collation_database=DEFAULT/*!*/;

DROP TEMPORARY TABLE IF EXISTS `compras`.`temp_trig1` /* generated by server */

/*!*/;

# at 89390759

#181017  8:12:03 server id 1  end_log_pos 89391072 CRC32 0xd7bc267b 	Query	thread_id=67291	exec_time=0	error_code=0

use `compras`/*!*/;

SET TIMESTAMP=1539774723/*!*/;

SET @@session.sql_mode=4194304/*!*/;

SET @@session.time_zone='SYSTEM'/*!*/;

INSERT INTO compra_artoc_locales     (id_art_oc, id_local, id_sector, cant_pedida, tipo_reserva, fecha_reserva, tipo_pedido, nro_pedido, update_st, update_ts)

  VALUES      ('26346652',79,90,1,1,'0000-00-00',0,0,0,'2018-10-17 08:12:03')

/*!*/;

# at 89391072

#181017  8:12:03 server id 1  end_log_pos 89391598 CRC32 0x5d3ac5ca 	Query	thread_id=67291	exec_time=0	error_code=0

SET TIMESTAMP=1539774723/*!*/;

I've tried forcing the sync with a START SLAVE IO_THREAD; in the slave, but always stops in a BINLOG block similar to that. Something weird is that mysqlbinlog is not decoding that block although I've executed it with "-v" flag. Please let me know if you need any more detail.

Comment by Gabriel Gomiz [ 2018-10-24 ]

I'm following these case with some more information. The block of the binlog where the slave stops is always similar:

Error:

Oct 24 11:10:37 san02.cooperativaobrera.coop mysqld[15138]: 2018-10-24 11:10:37 126581 [ERROR] Slave IO thread did not receive an expected Rows-log end-of-statement for event starting at log 'main.010757' position 7317767 whose last block was seen at log 'main.010757' position 7317767. The end-of-statement should have been delivered before the current one at log 'main.010757' position 7318907

Binlog extract (from position 7316759 to 7320051):

# mysqlbinlog --verbose --start-position 7316759 --stop-position 7320051 main.010757

/*!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

#181017  9:59:04 server id 1  end_log_pos 256 CRC32 0x17c91b2b 	Start: binlog v 4, server v 10.2.18-MariaDB-log created 181017  9:59:04

BINLOG '

GDLHWw8BAAAA/AAAAAABAAAAAAQAMTAuMi4xOC1NYXJpYURCLWxvZwAAAAAAAAAAAAAAAAAAAAAA

AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAA5AAEGggAAAAICAgCAAAACgoKAAAAAAAA

AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA

AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA

AAAAAAAAAAAEEwQADQgICAoKCgErG8kX

'/*!*/;

# at 7316759

#181017  9:59:48 server id 1  end_log_pos 7316884 CRC32 0x5d1c311c 	Table_map: `compras`.`compra_base_promo` mapped to number 79 (has triggers)

# at 7316884

#181017  9:59:48 server id 1  end_log_pos 7316996 CRC32 0x3110f6f2 	Table_map: `compras`.`compra_nego_promo_det` mapped to number 1150 (has triggers)

# at 7316996

#181017  9:59:48 server id 1  end_log_pos 7317069 CRC32 0x21d5fa17 	Table_map: `compras`.`compra_audit` mapped to number 80

# at 7317069

#181017  9:59:48 server id 1  end_log_pos 7317181 CRC32 0x4a53cd1f 	Table_map: `compras`.`compra_nego_promo_det` mapped to number 1150 (has triggers)

# at 7317181

#181017  9:59:48 server id 1  end_log_pos 7317254 CRC32 0xc1410f02 	Table_map: `compras`.`compra_audit` mapped to number 80

# at 7317254

#181017  9:59:48 server id 1  end_log_pos 7317366 CRC32 0xc7968128 	Table_map: `compras`.`compra_nego_promo_det` mapped to number 1150 (has triggers)

# at 7317366

#181017  9:59:48 server id 1  end_log_pos 7317478 CRC32 0x31c0d341 	Table_map: `faccargentina`.`articulos` mapped to number 2749

# at 7317478

#181017  9:59:48 server id 1  end_log_pos 7317590 CRC32 0xcd2a8076 	Table_map: `compras`.`compra_nego_promo_det` mapped to number 1150 (has triggers)

# at 7317590

#181017  9:59:48 server id 1  end_log_pos 7317663 CRC32 0x063be765 	Table_map: `compras`.`compra_audit` mapped to number 80

# at 7317663

#181017  9:59:48 server id 1  end_log_pos 7317767 CRC32 0x07cdd151 	Table_map: `faccargentina`.`cronograma_proveedor_articulo_coop_promo` mapped to number 2745

# at 7317767

# at 7318907

#181017  9:59:48 server id 1  end_log_pos 7319056 CRC32 0x19dbd9d6 	Query	thread_id=281516	exec_time=0	error_code=0

SET TIMESTAMP=1539781188/*!*/;

SET @@session.pseudo_thread_id=281516/*!*/;

SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1, @@session.check_constraint_checks=1/*!*/;

SET @@session.sql_mode=1075838976/*!*/;

SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;

/*!\C utf8 *//*!*/;

SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=8/*!*/;

SET @@session.lc_time_names=0/*!*/;

SET @@session.collation_database=DEFAULT/*!*/;

DROP TEMPORARY TABLE IF EXISTS `compras`.`temp_trig1` /* generated by server */

/*!*/;

# at 7319056

# at 7319332

#181017  9:59:48 server id 1  end_log_pos 7319332 CRC32 0xe5cd668a 	Annotate_rows:

#Q> INSERT INTO compras.compra_nego_promo_det

#Q> 		(id_cab_promo,id_articulo,id_proveedor,cant_vendida,cant_vendida_orig,costo_uni,impint,pvp)

#Q> 	select id_cab_promo,id_articulo,id_proveedor,cant_vendida,cant_vendida_orig,costo_uni,impint,pvp

#Q> 	from temp_tr

#181017  9:59:48 server id 1  end_log_pos 7319457 CRC32 0x495ee33d 	Table_map: `compras`.`compra_base_promo` mapped to number 79 (has triggers)

# at 7319457

#181017  9:59:48 server id 1  end_log_pos 7319569 CRC32 0xb3e1d052 	Table_map: `compras`.`compra_nego_promo_det` mapped to number 1150 (has triggers)

# at 7319569

#181017  9:59:48 server id 1  end_log_pos 7319642 CRC32 0xf2bf2ba0 	Table_map: `compras`.`compra_audit` mapped to number 80

# at 7319642

#181017  9:59:48 server id 1  end_log_pos 7319754 CRC32 0x8a8bff3a 	Table_map: `compras`.`compra_nego_promo_det` mapped to number 1150 (has triggers)

# at 7319754

#181017  9:59:48 server id 1  end_log_pos 7319827 CRC32 0x2901f91b 	Table_map: `compras`.`compra_audit` mapped to number 80

# at 7319827

#181017  9:59:48 server id 1  end_log_pos 7319939 CRC32 0xf9978338 	Table_map: `compras`.`compra_nego_promo_det` mapped to number 1150 (has triggers)

# at 7319939

#181017  9:59:48 server id 1  end_log_pos 7320051 CRC32 0xb331f5e1 	Table_map: `faccargentina`.`articulos` mapped to number 2749

DELIMITER ;

# End of log file

ROLLBACK /* added by mysqlbinlog */;

/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;

/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

Binlog extract (from position 7316759 to 7320051) with decode:

# mysqlbinlog --base64-output=decode-rows --verbose --start-position 7316759 --stop-position 7320051 main.010757

/*!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 7316759

#181017  9:59:48 server id 1  end_log_pos 7316884 CRC32 0x5d1c311c 	Table_map: `compras`.`compra_base_promo` mapped to number 79 (has triggers)

# at 7316884

#181017  9:59:48 server id 1  end_log_pos 7316996 CRC32 0x3110f6f2 	Table_map: `compras`.`compra_nego_promo_det` mapped to number 1150 (has triggers)

# at 7316996

#181017  9:59:48 server id 1  end_log_pos 7317069 CRC32 0x21d5fa17 	Table_map: `compras`.`compra_audit` mapped to number 80

# at 7317069

#181017  9:59:48 server id 1  end_log_pos 7317181 CRC32 0x4a53cd1f 	Table_map: `compras`.`compra_nego_promo_det` mapped to number 1150 (has triggers)

# at 7317181

#181017  9:59:48 server id 1  end_log_pos 7317254 CRC32 0xc1410f02 	Table_map: `compras`.`compra_audit` mapped to number 80

# at 7317254

#181017  9:59:48 server id 1  end_log_pos 7317366 CRC32 0xc7968128 	Table_map: `compras`.`compra_nego_promo_det` mapped to number 1150 (has triggers)

# at 7317366

#181017  9:59:48 server id 1  end_log_pos 7317478 CRC32 0x31c0d341 	Table_map: `faccargentina`.`articulos` mapped to number 2749

# at 7317478

#181017  9:59:48 server id 1  end_log_pos 7317590 CRC32 0xcd2a8076 	Table_map: `compras`.`compra_nego_promo_det` mapped to number 1150 (has triggers)

# at 7317590

#181017  9:59:48 server id 1  end_log_pos 7317663 CRC32 0x063be765 	Table_map: `compras`.`compra_audit` mapped to number 80

# at 7317663

#181017  9:59:48 server id 1  end_log_pos 7317767 CRC32 0x07cdd151 	Table_map: `faccargentina`.`cronograma_proveedor_articulo_coop_promo` mapped to number 2745

# at 7317767

# at 7318907

#181017  9:59:48 server id 1  end_log_pos 7319056 CRC32 0x19dbd9d6 	Query	thread_id=281516	exec_time=0	error_code=0

SET TIMESTAMP=1539781188/*!*/;

SET @@session.pseudo_thread_id=281516/*!*/;

SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1, @@session.check_constraint_checks=1/*!*/;

SET @@session.sql_mode=1075838976/*!*/;

SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;

/*!\C utf8 *//*!*/;

SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=8/*!*/;

SET @@session.lc_time_names=0/*!*/;

SET @@session.collation_database=DEFAULT/*!*/;

DROP TEMPORARY TABLE IF EXISTS `compras`.`temp_trig1` /* generated by server */

/*!*/;

# at 7319056

# at 7319332

#181017  9:59:48 server id 1  end_log_pos 7319332 CRC32 0xe5cd668a 	Annotate_rows:

#Q> INSERT INTO compras.compra_nego_promo_det

#Q> 		(id_cab_promo,id_articulo,id_proveedor,cant_vendida,cant_vendida_orig,costo_uni,impint,pvp)

#Q> 	select id_cab_promo,id_articulo,id_proveedor,cant_vendida,cant_vendida_orig,costo_uni,impint,pvp

#Q> 	from temp_tr

#181017  9:59:48 server id 1  end_log_pos 7319457 CRC32 0x495ee33d 	Table_map: `compras`.`compra_base_promo` mapped to number 79 (has triggers)

# at 7319457

#181017  9:59:48 server id 1  end_log_pos 7319569 CRC32 0xb3e1d052 	Table_map: `compras`.`compra_nego_promo_det` mapped to number 1150 (has triggers)

# at 7319569

#181017  9:59:48 server id 1  end_log_pos 7319642 CRC32 0xf2bf2ba0 	Table_map: `compras`.`compra_audit` mapped to number 80

# at 7319642

#181017  9:59:48 server id 1  end_log_pos 7319754 CRC32 0x8a8bff3a 	Table_map: `compras`.`compra_nego_promo_det` mapped to number 1150 (has triggers)

# at 7319754

#181017  9:59:48 server id 1  end_log_pos 7319827 CRC32 0x2901f91b 	Table_map: `compras`.`compra_audit` mapped to number 80

# at 7319827

#181017  9:59:48 server id 1  end_log_pos 7319939 CRC32 0xf9978338 	Table_map: `compras`.`compra_nego_promo_det` mapped to number 1150 (has triggers)

# at 7319939

#181017  9:59:48 server id 1  end_log_pos 7320051 CRC32 0xb331f5e1 	Table_map: `faccargentina`.`articulos` mapped to number 2749

DELIMITER ;

# End of log file

ROLLBACK /* added by mysqlbinlog */;

/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;

/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

In both dumps, position 7317767 is empty. Is that ok?

Comment by Gabriel Gomiz [ 2018-10-24 ]

I've extracted the binlog again with more previous events to the error position, and found a REPLACE to a table thas has triggers:

# at 7316759

#181017  9:59:48 server id 1  end_log_pos 7316759 CRC32 0x288f6779 	Annotate_rows:

#Q> REPLACE INTO compras.compra_base_promo (id_base_promo,id_cab_promo,id_promo,ind_tipo_base,id_cod_base_desde,id_cod_base_hasta,cantidad,importe,costo_real,costo_de_promocion,fec_ent_nvo_costo,fec_sal_nvo_costo,prec_vta_sal_prom,id_codigo_pedido,costo_salida_prom,precio_vta_antes,imp_int_real,imp_int_promocion,imp_int_salida_prom,ind_publicado,cantidad_beneficio,importe_beneficio,importe_asoc,porc_pron_venta,login,id_origen,hoja_publicacion,cuotas_sinteres,max_disponible, ind_volante,ind_afiche,extra_base) VALUES (0,14663,1,1,253732,253732,1,18.9,12.62,12.62,'0000-00-00','0000-00-00',19.67,69,12.62,19.67,0,0,0,1,0,0,18.9,0,'dzalcman',0,2,0,0,0,0,'{"costo_actual":{"costo_bruto":12.62,"impint":0.0,"costo_neto":12.62,"vigencia":"0000-00-00","bonificaciones":[{"porcentaje":0.0,"orden":1},{"porcentaje":0.0,"orden":2},{"porcentaje":0.0,"orden":3},{"porcentaje":0.0,"orden":4},{"porcentaje":0.0,"orden":5}]},"costo_promo":{"costo_bruto":12.62,"impint":0.0,"costo_neto":12.62,"vigencia":"2018-10-25","bonificaciones":[{"porcentaje":0.0,"orden":1},{"porcentaje":0.0,"orden":2},{"porcentaje":0.0,"orden":3},{"porcentaje":0.0,"orden":4},{"porcentaje":0.0,"orden":5}]},"costo_despues":{"costo_bruto":12.62,"impint":0.0,"costo_neto":12.62,"vigencia":"2018-12-01","bonificaciones":[{"porcentaje":0.0,"orden":1},{"porcentaje":0.0,"orden":2},{"porcentaje":0.0,"orden":3},{"porcentaje":0.0,"orden":4},{"porcentaje":0.0,"orden":5}]},"precio_venta_asoc_actual":19.67,"precio_venta_asoc_promo":18.9,"precio_venta_asoc_despues":19.67,"respeta_costos":true,"orden_compra_abierta":0,"tipo_oc":0,"cant_ord_abierta":0,"por_grupo":false,"tipo_negoc":0}')

All that follows seems to be the queries generated by the trigger:

#181017  9:59:48 server id 1  end_log_pos 7316884 CRC32 0x5d1c311c 	Table_map: `compras`.`compra_base_promo` mapped to number 79 (has triggers)

# at 7316884

#181017  9:59:48 server id 1  end_log_pos 7316996 CRC32 0x3110f6f2 	Table_map: `compras`.`compra_nego_promo_det` mapped to number 1150 (has triggers)

# at 7316996

#181017  9:59:48 server id 1  end_log_pos 7317069 CRC32 0x21d5fa17 	Table_map: `compras`.`compra_audit` mapped to number 80

# at 7317069

#181017  9:59:48 server id 1  end_log_pos 7317181 CRC32 0x4a53cd1f 	Table_map: `compras`.`compra_nego_promo_det` mapped to number 1150 (has triggers)

# at 7317181

#181017  9:59:48 server id 1  end_log_pos 7317254 CRC32 0xc1410f02 	Table_map: `compras`.`compra_audit` mapped to number 80

# at 7317254

#181017  9:59:48 server id 1  end_log_pos 7317366 CRC32 0xc7968128 	Table_map: `compras`.`compra_nego_promo_det` mapped to number 1150 (has triggers)

# at 7317366

#181017  9:59:48 server id 1  end_log_pos 7317478 CRC32 0x31c0d341 	Table_map: `faccargentina`.`articulos` mapped to number 2749

# at 7317478

#181017  9:59:48 server id 1  end_log_pos 7317590 CRC32 0xcd2a8076 	Table_map: `compras`.`compra_nego_promo_det` mapped to number 1150 (has triggers)

# at 7317590

#181017  9:59:48 server id 1  end_log_pos 7317663 CRC32 0x063be765 	Table_map: `compras`.`compra_audit` mapped to number 80

# at 7317663

#181017  9:59:48 server id 1  end_log_pos 7317767 CRC32 0x07cdd151 	Table_map: `faccargentina`.`cronograma_proveedor_articulo_coop_promo` mapped to number 2745

# at 7317767

# at 7318907

#181017  9:59:48 server id 1  end_log_pos 7319056 CRC32 0x19dbd9d6 	Query	thread_id=281516	exec_time=0	error_code=0

SET TIMESTAMP=1539781188/*!*/;

SET @@session.pseudo_thread_id=281516/*!*/;

SET @@session.sql_mode=1075838976/*!*/;

/*!\C utf8 *//*!*/;

SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=8/*!*/;

DROP TEMPORARY TABLE IF EXISTS `compras`.`temp_trig1` /* generated by server */

/*!*/;

# at 7319056

# at 7319332

#181017  9:59:48 server id 1  end_log_pos 7319332 CRC32 0xe5cd668a 	Annotate_rows:

#Q> INSERT INTO compras.compra_nego_promo_det

#Q> 		(id_cab_promo,id_articulo,id_proveedor,cant_vendida,cant_vendida_orig,costo_uni,impint,pvp)

#Q> 	select id_cab_promo,id_articulo,id_proveedor,cant_vendida,cant_vendida_orig,costo_uni,impint,pvp

#Q> 	from temp_tr

The trigger is somewhat complex and uses temporary tables. Excerpt of the trigger:

....

	drop temporary table if exists temp_trig1;

	create temporary table temp_trig1

	select b.id_cab_promo,

        b.id_cod_base_desde id_articulo,

        _getproveedorarticulo(b.id_cod_base_desde,@id_local) id_proveedor,

        0 cant_vendida,

        0 cant_vendida_orig,

        _getcostoproveedor(b.id_cod_base_desde,_getproveedorarticulo(id_cod_base_desde,@id_local),@fecha_fin) costo_uni,

        ifnull((select ar.impint from compras.compra_articulos ar where ar.id_articulo = b.id_cod_base_desde ),0) impint,

        if( b.cantidad > 0 and p.monto_descuento > 0 and b.id_cod_base_hasta < 100000, round(p.monto_descuento /  b.cantidad,2), b.importe_asoc )  pvp,

	ifnull(dd.id_promo_det,0) id_promo_det,

	ifnull(dd.tipo_negoc,0) tipo_negoc,

	ifnull(dd.porc_negoc,0) porc_negoc,

	ifnull(dd.bonif,0) bonif,

	ifnull(tiv.porcentaje,0) porc_iva

	FROM compras.compra_base_promo b

		JOIN compras.compra_promo p using ( id_cab_promo, id_promo )

		JOIN compras.compra_articulos ar on ( ar.id_articulo = b.id_cod_base_desde )

		JOIN comun.tipo_iva tiv on ( tiv.ind_iva = ar.ind_iva )

		LEFT JOIN compras.compra_nego_promo_det dd on ( dd.id_cab_promo = b.id_cab_promo and dd.id_articulo = b.id_cod_base_desde )

	WHERE

.....

	update temp_trig1 set bonif =

        	case

        	when tipo_negoc between 3 and 7 then round(porc_negoc * costo_uni / 100,3)

        	when tipo_negoc = 8 then round( costo_uni - (pvp - impint) / ( porc_iva/100+1 ) / (1+porc_negoc/100),3)

        	when tipo_negoc = 12 then bonif

        	when tipo_negoc = 13 then costo_uni - bonif

        	else 0

end

	where

	tipo_negoc > 0;

	update temp_trig1

		join compra_nego_promo_det d using ( id_cab_promo, id_promo_det )

		set d.pvp = temp_trig1.pvp,

			d.costo_uni = temp_trig1.costo_uni,

			d.impint = temp_trig1.impint,

			d.bonif = temp_trig1.bonif

	where

	id_promo_det > 0 and codineg = 0;

	delete a

		from temp_trig1 a

		join compras.compra_nego_promo_det b on ( b.id_cab_promo = a.id_cab_promo and b.id_articulo = a.id_articulo );

	INSERT INTO compras.compra_nego_promo_det

		(id_cab_promo,id_articulo,id_proveedor,cant_vendida,cant_vendida_orig,costo_uni,impint,pvp)

	select id_cab_promo,id_articulo,id_proveedor,cant_vendida,cant_vendida_orig,costo_uni,impint,pvp

	from temp_trig1;

        INSERT INTO compras.compra_audit (cod_oper,tabla_relac,valor,login)

        VALUES (1507,'compra_base_promo',OLD.id_base_promo, ifnull(@user,user()));

	drop temporary table if exists temp_trig1;

Comment by Gabriel Gomiz [ 2018-10-25 ]

FYI, we have eliminated the use of the temporary table inside the trigger and the problem dissapears. Our slave now is replicating perfectly. So we can confirm that the bug happens when you use a temporary table inside a trigger.

Comment by Andrei Elkin [ 2018-10-29 ]

Thank you, Gabriel, for the detailed report.

Indeed it looks like DROP TEMPORARY TABLE encroached into a stream of Rows-log events which
must be plain incorrect. The trigger excerpt hints at how to reproduce which we I bet will prove
the DROP gets into binlog caches and for no reason.

Regards,
Andrei

Comment by Gabriel Gomiz [ 2018-10-30 ]

Ok, Andrei, I'm glad that the report was useful. So, if I understand correctly, the bug is on the master, that is writing incorrect binary logs?

Today we found another case with the same error:

2018-10-30 10:37:27 79954 [ERROR] Slave IO thread did not receive an expected Rows-log end-of-statement for event starting at log 'main.011096' position 100826819 whose last block was seen at log 'main.011096' position 100852089. The end-of-statement should have been delivered before the current one at log 'main.011096' position 100852179

Analyzing the binary log, I've found a similar condition. This REPLACE is written (some values are obfuscated):

# at 100826747

#181029 12:50:13 server id 1  end_log_pos 100826747 CRC32 0xf5c0ffb8    Annotate_rows:

#Q> REPLACE INTO bmpj_movimiento (legajo, periodo, tipo_movimiento, importe, cuotas, porcentaje_sueldo, sueldo, ts)

#Q>     SELECT  NAME_CONST('legajo',#####),  NAME_CONST('periodo',######),  NAME_CONST('tipo_movimiento',10),  NAME_CONST('importe',######),  NAME_CONST('cuotas',1),  NAME_CONST('porcentaje_sueldo',0.00),  NAME_CONST('sueldo',##########), SYSDATE(

#181029 12:50:13 server id 1  end_log_pos 100826819 CRC32 0x48aa2113    Table_map: `rrhhs`.`bmpj_movimiento` mapped to number 277

# at 100826819

Then a big Rows-log event:

# at 100826819

# at 100826936

# at 100827026

# at 100827143

# at 100827233

# at 100827350

# at 100827440

# at 100827557

# at 100827647

....

# at 100851972

# at 100852089

# at 100852179

#181029 12:50:13 server id 1  end_log_pos 100852331 CRC32 0x18b2a731    Query   thread_id=6516519   exec_time=0 error_code=0

SET TIMESTAMP=1540828213/*!*/;

DROP TEMPORARY TABLE IF EXISTS `rrhhs`.`tmp_extra` /* generated by server */

/*!*/;

# at 100852331

# at 100852701

#181029 12:50:13 server id 1  end_log_pos 100852701 CRC32 0xd6d317b9    Annotate_rows:

#Q> REPLACE INTO bmpj_movimiento (legajo, periodo, tipo_movimiento, importe, cuotas, porcentaje_sueldo, sueldo, ts)

#Q>     SELECT  NAME_CONST('legajo',######),  NAME_CONST('periodo',#######),  NAME_CONST('tipo_movimiento',##),  NAME_CONST('importe',#####),  NAME_CONST('cuotas',1),  NAME_CONST('porcentaje_sueldo',0.00),  NAME_CONST('sueldo',0.00), SYSDATE(

#181029 12:50:13 server id 1  end_log_pos 100852773 CRC32 0x34189fdf    Table_map: `rrhhs`.`bmpj_movimiento` mapped to number 277

# at 100852773

# at 100856474

# at 100856564

#181029 12:50:13 server id 1  end_log_pos 100856474 CRC32 0x528f9018    Write_rows: table id 277

#181029 12:50:13 server id 1  end_log_pos 100856564 CRC32 0x1d532890    Update_rows: table id 277

#181029 12:50:13 server id 1  end_log_pos 100857185 CRC32 0x2dfffd30    Write_rows: table id 277 flags: STMT_END_F

This "DROP TEMPORARY TABLE IF EXISTS `rrhhs`.`tmp_extra` /* generated by server */" seems out of place. Am I correct?

Hope this helps

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

[MDEV-17490] MariaDB 10.3 slave fails to replicate from a MariaDB 10.2 master Created: 2018-10-18 Updated: 2023-05-02 Resolved: 2023-05-02