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

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Critical
Resolution: Incomplete
Affects Version/s: 10.2.17, 10.2.18, 10.3.10, 10.8.5, 10.4.28
Fix Version/s: N/A
Component/s: Replication, Server
Labels:
- binlog
- replication
- slave
Environment:
CentOS 7.x

Description

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

Attachments

Issue Links

blocks

MDEV-17420 MariaDB slave 10.2 leaks temporary tables

Closed

Activity

Ascending order - Click to sort in descending order

Gabriel Gomiz created issue - 2018-10-18 12:59

Gabriel Gomiz made changes - 2018-10-18 12:59

Field	Original Value	New Value
Link		This issue blocks ~~MDEV-17420~~ [ ~~MDEV-17420~~ ]

Daniel Black made changes - 2018-10-18 22:24

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

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:

{noformat}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{noformat}

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:

{noformat}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{noformat}

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

Daniel Black added a comment - 2018-10-18 22:31

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.

Daniel Black added a comment - 2018-10-18 22:31 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.

Elena Stepanova made changes - 2018-10-18 23:04

Labels

binlog replication slave

binlog need_feedback replication slave

Gabriel Gomiz added a comment - 2018-10-18 23:30

# 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.

Gabriel Gomiz added a comment - 2018-10-18 23:30 # 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.

Gabriel Gomiz added a comment - 2018-10-24 14:35 - edited

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?

Gabriel Gomiz added a comment - 2018-10-24 14:35 - edited 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?

Elena Stepanova made changes - 2018-10-24 14:42

Labels

binlog need_feedback replication slave

binlog replication slave

Gabriel Gomiz added a comment - 2018-10-24 15:43

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;

Gabriel Gomiz added a comment - 2018-10-24 15:43 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;

Elena Stepanova made changes - 2018-10-25 12:27

Assignee

Andrei Elkin [ elkin ]

Gabriel Gomiz added a comment - 2018-10-25 13:50

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.

Gabriel Gomiz added a comment - 2018-10-25 13:50 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.

Andrei Elkin added a comment - 2018-10-29 15:17

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

Andrei Elkin added a comment - 2018-10-29 15:17 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

Gabriel Gomiz added a comment - 2018-10-30 13:55

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

Gabriel Gomiz added a comment - 2018-10-30 13:55 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

Elena Stepanova made changes - 2018-11-28 01:04

Fix Version/s		10.2 [ 14601 ]
Fix Version/s		10.3 [ 22126 ]

Sergei Golubchik made changes - 2019-03-29 12:04

Fix Version/s

10.4 [ 22408 ]

Sergei Golubchik made changes - 2021-12-06 21:33

Workflow

MariaDB v3 [ 90165 ]

MariaDB v4 [ 140983 ]

Ralf Gebhardt made changes - 2022-08-04 08:40

Fix Version/s

10.2 [ 14601 ]

Pon Suresh Pandian (Inactive) made changes - 2023-03-02 16:39

Affects Version/s

10.8.5 [ 28308 ]

Allen Lee (Inactive) made changes - 2023-03-19 22:31

Affects Version/s

10.4.28 [ 28509 ]

Julien Fritsch made changes - 2023-03-27 12:38

Priority

Major [ 3 ]

Critical [ 2 ]

Andrei Elkin made changes - 2023-03-27 14:01

Assignee	Andrei Elkin [ elkin ]	suresh ramagiri [ suresh.ramagiri@mariadb.com ]
Status	Open [ 1 ]	Needs Feedback [ 10501 ]

Julien Fritsch made changes - 2023-04-27 14:23

Fix Version/s

10.3 [ 22126 ]

Julien Fritsch made changes - 2023-05-02 06:37

Fix Version/s		N/A [ 14700 ]
Fix Version/s	10.4 [ 22408 ]
Resolution		Incomplete [ 4 ]
Status	Needs Feedback [ 10501 ]	Closed [ 6 ]

Jira Automation (IT) made changes - 2024-07-04 04:17

Zendesk Related Tickets

165626 172355

People

Assignee:: suresh ramagiri

Reporter:: Gabriel Gomiz

Votes:: 0 Vote for this issue

Watchers:: 8 Start watching this issue

Dates

Created:: 2018-10-18 12:59

Updated:: 2024-07-07 23:38

Resolved:: 2023-05-02 06:37

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.

MariaDB Server

Details

Description

Attachments

Issue Links

Activity

People

Dates

Git Integration