[#MDEV-7980] Could not execute Update_rows_v1 event on table xxx_20150210.data_source_prices; Can't find record in 'data_source_prices', Error_code: 1032; handler error HA_ERR_END_OF

[MDEV-7980] Could not execute Update_rows_v1 event on table xxx_20150210.data_source_prices; Can't find record in 'data_source_prices', Error_code: 1032; handler error HA_ERR_END_OF_FILE Created: 2015-04-13 Updated: 2021-08-10
Status:	Open
Project:	MariaDB Server
Component/s:	Replication
Affects Version/s:	10.0.17, 10.3.28
Fix Version/s:	10.3

Type:

Bug

Priority:

Major

Reporter:

Daniel Black

Assignee:

Alexander Barkov

Resolution:

Unresolved

Votes:

Labels:

slave

Environment:

rhel6

Attachments:

gdb-Update_rows_v1.txt

Issue Links:

Relates
relates to	~~MDEV-2562~~	LP:714419 - Replication failures with...	Closed

Description

replication error on 10.0.17 slave with 10.0.17 master. Table had no PK.

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

               Slave_IO_State: Waiting for master to send event

                  Master_Host: 172.16.194.76

                  Master_User: repl

                  Master_Port: 3310

                Connect_Retry: 60

              Master_Log_File: tulwaurt005-mysql-bin.000325

          Read_Master_Log_Pos: 185442169

               Relay_Log_File: tulwaurt009-relay-bin.000026

                Relay_Log_Pos: 835832166

        Relay_Master_Log_File: tulwaurt005-mysql-bin.000309

             Slave_IO_Running: Yes

            Slave_SQL_Running: Yes

              Replicate_Do_DB:

          Replicate_Ignore_DB:

           Replicate_Do_Table:

       Replicate_Ignore_Table: xxx.feed_bettordata_data,xxx_docs.session,xxx_docs.session,xxx.feed_bettordata_data

      Replicate_Wild_Do_Table:

  Replicate_Wild_Ignore_Table:

                   Last_Errno: 1032

                   Last_Error: Could not execute Update_rows_v1 event on table xxx_20150210.data_source_prices; Can't find record in 'data_source_prices', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log tulwaurt005-mysql-bin.000309, end_log_pos 840720938

                 Skip_Counter: 0

          Exec_Master_Log_Pos: 840720516

              Relay_Log_Space: 14811971033

              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: 12433

Master_SSL_Verify_Server_Cert: No

                Last_IO_Errno: 0

                Last_IO_Error:

               Last_SQL_Errno: 1032

               Last_SQL_Error: Could not execute Update_rows_v1 event on table xxx_20150210.data_source_prices; Can't find record in 'data_source_prices', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log tulwaurt005-mysql-bin.000309, end_log_pos 840720938

  Replicate_Ignore_Server_Ids:

             Master_Server_Id: 20076

               Master_SSL_Crl:

           Master_SSL_Crlpath:

                   Using_Gtid: Slave_Pos

                  Gtid_IO_Pos: 3-20076-44284,0-20076-64741091

No sql thread progress between show slave status\G

MariaDB [(none)]> show processlist;

+----+-------------+-----------------+------+---------+--------+--------------------------------------------------------------------------------+------------------+----------+

| Id | User        | Host            | db   | Command | Time   | State                                                                          | Info             | Progress |

+----+-------------+-----------------+------+---------+--------+--------------------------------------------------------------------------------+------------------+----------+

|  3 | system user |                 | NULL | Connect | 363409 | Waiting for prior transaction to start commit before starting next transaction | NULL             |    0.000 |

|  4 | system user |                 | NULL | Connect | 363409 | Waiting for prior transaction to start commit before starting next transaction | NULL             |    0.000 |

|  5 | system user |                 | NULL | Connect | 363408 | Waiting for prior transaction to start commit before starting next transaction | NULL             |    0.000 |

|  6 | system user |                 | NULL | Connect | 404026 | Waiting for work from SQL thread                                               | NULL             |    0.000 |

|  7 | system user |                 | NULL | Connect | 363409 | Waiting for prior transaction to start commit before starting next transaction | NULL             |    0.000 |

|  8 | system user |                 | NULL | Connect | 404026 | Waiting for work from SQL thread                                               | NULL             |    0.000 |

|  9 | system user |                 | NULL | Connect | 363408 | Waiting for prior transaction to start commit before starting next transaction | NULL             |    0.000 |

| 10 | system user |                 | NULL | Connect | 363408 | Waiting for prior transaction to start commit before starting next transaction | NULL             |    0.000 |

| 11 | system user |                 | NULL | Connect | 404026 | Waiting for work from SQL thread                                               | NULL             |    0.000 |

| 12 | system user |                 | NULL | Connect | 363409 | Waiting for prior transaction to start commit before starting next transaction | NULL             |    0.000 |

| 13 | system user |                 | NULL | Connect | 363408 | Waiting for prior transaction to start commit before starting next transaction | NULL             |    0.000 |

| 14 | system user |                 | NULL | Connect | 363408 | Waiting for prior transaction to start commit before starting next transaction | NULL             |    0.000 |

| 15 | system user |                 | NULL | Connect | 363408 | Waiting for prior transaction to start commit before starting next transaction | NULL             |    0.000 |

| 16 | system user |                 | NULL | Connect | 404026 | Waiting for work from SQL thread                                               | NULL             |    0.000 |

| 17 | system user |                 | NULL | Connect | 404026 | Waiting for work from SQL thread                                               | NULL             |    0.000 |

| 18 | system user |                 | NULL | Connect | 363408 | Waiting for prior transaction to start commit before starting next transaction | NULL             |    0.000 |

| 19 | system user |                 | NULL | Connect | 363409 | Waiting for prior transaction to start commit before starting next transaction | NULL             |    0.000 |

| 20 | system user |                 | NULL | Connect | 363408 | Waiting for prior transaction to start commit before starting next transaction | NULL             |    0.000 |

| 21 | system user |                 | NULL | Connect | 363408 | Waiting for prior transaction to start commit before starting next transaction | NULL             |    0.000 |

| 22 | system user |                 | NULL | Connect | 363408 | Waiting for prior transaction to start commit before starting next transaction | NULL             |    0.000 |

| 23 | system user |                 | NULL | Connect |  13502 | Waiting for master to send event                                               | NULL             |    0.000 |

| 24 | system user |                 | NULL | Connect |   2990 | Waiting for room in worker thread event queue                                  | NULL             |    0.000 |

| 40 | openquery   | localhost       | NULL | Sleep   |   9519 |                                                                                | NULL             |    0.000 |

| 44 | openquery   | 127.0.0.1:55730 | NULL | Query   |      0 | init                                                                           | show processlist |    0.000 |

+----+-------------+-----------------+------+---------+--------+--------------------------------------------------------------------------------+------------------+----------+

Took attached gdb backtraces

mysqlbinlog --base64-output=decode-rows --verbose  tulwaurt009-relay-bin.000026 --start-position 835832166 | 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 835832166

#150408 23:38:10 server id 20076  end_log_pos 840720554         GTID 0-20076-42437721

/*!100001 SET @@session.gtid_domain_id=0*//*!*/;

/*!100001 SET @@session.server_id=20076*//*!*/;

/*!100001 SET @@session.gtid_seq_no=42437721*//*!*/;

BEGIN

/*!*/;

# at 835832204

# at 835832278

#150408 23:38:10 server id 20076  end_log_pos 840720854         Table_map: `xxx_20150210`.`data_source_prices` mapped to number 19326

#150408 23:38:10 server id 20076  end_log_pos 840720938         Update_rows: table id 19326 flags: STMT_END_F

### UPDATE `xxx_20150210`.`data_source_prices`

### WHERE

###   @1=6379754

###   @2=1

###   @3=9

###   @4=000000023.600000000

###   @5=2015-04-09 09:07:23

### SET

###   @1=6379754

###   @2=1

###   @3=9

###   @4=000000023.800000000

###   @5=2015-04-09 09:08:10

# at 835832362

#150408 23:38:10 server id 20076  end_log_pos 840720965         Xid = 411642227

COMMIT/*!*/;

# at 835832389

#150408 23:38:10 server id 20076  end_log_pos 840721003         GTID 0-20076-42437722

/*!100001 SET @@session.gtid_seq_no=42437722*//*!*/;

BEGIN

/*!*/;

# at 835832427

# at 835832509

#150408 23:38:10 server id 20076  end_log_pos 840721304         Table_map: `xxx_20150210`.`data_source_prices_history` mapped to number 21912

#150408 23:38:10 server id 20076  end_log_pos 840721360         Write_rows: table id 21912 flags: STMT_END_F

### INSERT INTO `xxx_20150210`.`data_source_prices_history`

### SET

###   @1=6379755

###   @2=1

###   @3=9

###   @4=000000003.200000000

###   @5=2015-04-09 09:07:23

# at 835832565

#150408 23:38:10 server id 20076  end_log_pos 840721387         Xid = 411642228

COMMIT/*!*/;

| data_source_prices | CREATE TABLE `data_source_prices` (

  `market_selection_details_id` int(11) NOT NULL DEFAULT '0',

  `bet_type` int(10) NOT NULL DEFAULT '0',

  `data_source_id` int(11) NOT NULL DEFAULT '0',

  `price` decimal(12,2) NOT NULL DEFAULT '0.00',

  `last_updated` datetime DEFAULT NULL,

  KEY `market_selection_details_id` (`market_selection_details_id`,`bet_type`,`data_source_id`)

) ENGINE=InnoDB DEFAULT CHARSET=utf8 ROW_FORMAT=DYNAMIC |

MariaDB [xxx_20150210]> select * from data_source_prices where market_selection_details_id=6379754 and bet_type=1 and data_source_id=9;

+-----------------------------+----------+----------------+-------+---------------------+

| market_selection_details_id | bet_type | data_source_id | price | last_updated        |

+-----------------------------+----------+----------------+-------+---------------------+

|                     6379754 |        1 |              9 | 23.60 | 2015-04-08 23:37:23 |

+-----------------------------+----------+----------------+-------+---------------------+

record doesn't match on last_updated

On master:

MariaDB [xxx_20150210_schema_test]> show master logs;

+------------------------------+------------+

| Log_name                     | File_size  |

+------------------------------+------------+

| tulwaurt005-mysql-bin.000295 | 1073758494 |

| tulwaurt005-mysql-bin.000296 | 1073742300 |

| tulwaurt005-mysql-bin.000297 | 1073742367 |

| tulwaurt005-mysql-bin.000298 | 1073743137 |

| tulwaurt005-mysql-bin.000299 | 1073745171 |

| tulwaurt005-mysql-bin.000300 | 1073741945 |

| tulwaurt005-mysql-bin.000301 | 1073742118 |

| tulwaurt005-mysql-bin.000302 | 1073742068 |

| tulwaurt005-mysql-bin.000303 | 1073745675 |

| tulwaurt005-mysql-bin.000304 | 1073742497 |

| tulwaurt005-mysql-bin.000305 | 1073741977 |

| tulwaurt005-mysql-bin.000306 | 1073741908 |

| tulwaurt005-mysql-bin.000307 | 1073742723 |

| tulwaurt005-mysql-bin.000308 | 1073742108 |

| tulwaurt005-mysql-bin.000309 | 1073766758 |

| tulwaurt005-mysql-bin.000310 | 1073742006 |

| tulwaurt005-mysql-bin.000311 | 1073742880 |

| tulwaurt005-mysql-bin.000312 | 1073744059 |

| tulwaurt005-mysql-bin.000313 | 1073741975 |

| tulwaurt005-mysql-bin.000314 | 1073743573 |

| tulwaurt005-mysql-bin.000315 | 1073743122 |

| tulwaurt005-mysql-bin.000316 | 1073743058 |

| tulwaurt005-mysql-bin.000317 | 1073742208 |

| tulwaurt005-mysql-bin.000318 | 1073743476 |

| tulwaurt005-mysql-bin.000319 | 1073742423 |

| tulwaurt005-mysql-bin.000320 | 1073742672 |

| tulwaurt005-mysql-bin.000321 | 1073744024 |

| tulwaurt005-mysql-bin.000322 | 1073743039 |

| tulwaurt005-mysql-bin.000323 | 1073742110 |

| tulwaurt005-mysql-bin.000324 | 1073742370 |

| tulwaurt005-mysql-bin.000325 |  274709272 |

+------------------------------+------------+

ls -la /u01/mariadb-10/tulwaurt005-mysql-bin.000309*

-rw-rw----. 1 mysql mysql 1073766758 Apr  9 10:40 /u01/mariadb-10/tulwaurt005-mysql-bin.000309

back on slave:

Stop slave failed - same as ~~MDEV-7126~~

strace -p 52045

Process 52045 attached - interrupt to quit

restart_syscall(<... resuming interrupted call ...>) = 1

fcntl(37, F_GETFL)                      = 0x2 (flags O_RDWR)

fcntl(37, F_SETFL, O_RDWR|O_NONBLOCK)   = 0

accept(37, {sa_family=AF_FILE, NULL}, [2]) = 619

fcntl(37, F_SETFL, O_RDWR)              = 0

fcntl(619, F_SETFL, O_RDONLY|O_NONBLOCK) = 0

setsockopt(619, SOL_IP, IP_TOS, [8], 4) = -1 EOPNOTSUPP (Operation not supported)

mmap(NULL, 299008, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0x7fb83c839000

mprotect(0x7fb83c839000, 4096, PROT_NONE) = 0

clone(child_stack=0x7fb83c880ed0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x7fb83c8819d0, tls=0x7fb83c881700, child_tidptr=0x7fb83c8819d0) = 46312

poll([{fd=36, events=POLLIN}, {fd=37, events=POLLIN}], 2, -1^C <unfinished ...>

Process 52045 detached

kill 52045
kill -9 52045
service mysql start

stop slave; start slave; show slave status\G

               Slave_IO_State: Queueing master event to the relay log

                  Master_Host: 172.16.194.76

                  Master_User: repl

                  Master_Port: 3310

                Connect_Retry: 60

              Master_Log_File: tulwaurt005-mysql-bin.000309

          Read_Master_Log_Pos: 858757740

               Relay_Log_File: tulwaurt009-relay-bin.000002

                Relay_Log_Pos: 791

        Relay_Master_Log_File: tulwaurt005-mysql-bin.000309

             Slave_IO_Running: Yes

            Slave_SQL_Running: No

              Replicate_Do_DB:

          Replicate_Ignore_DB:

           Replicate_Do_Table:

       Replicate_Ignore_Table: xxx.feed_bettordata_data,xxx_docs.session,xxx_docs.session,xxx.feed_bettordata_data

      Replicate_Wild_Do_Table:

  Replicate_Wild_Ignore_Table:

                   Last_Errno: 1032

                   Last_Error: Could not execute Update_rows_v1 event on table xxx_20150210.data_source_prices; Can't find record in 'data_source_prices', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log tulwaurt005-mysql-bin.000309, end_log_pos 840720938

                 Skip_Counter: 0

          Exec_Master_Log_Pos: 840720516

              Relay_Log_Space: 15772314

              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: 0

                Last_IO_Error:

               Last_SQL_Errno: 1032

               Last_SQL_Error: Could not execute Update_rows_v1 event on table xxx_20150210.data_source_prices; Can't find record in 'data_source_prices', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log tulwaurt005-mysql-bin.000309, end_log_pos 840720938

  Replicate_Ignore_Server_Ids:

             Master_Server_Id: 20076

               Master_SSL_Crl:

           Master_SSL_Crlpath:

                   Using_Gtid: Slave_Pos

                  Gtid_IO_Pos: 3-20076-17655,0-20076-42465645

on 005 master

mysqlbinlog  /u01/mariadb-10/tulwaurt005-mysql-bin.000309 --start-position 840720516 | 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

#150408 23:36:17 server id 20076  end_log_pos 248       Start: binlog v 4, server v 10.0.17-MariaDB-log created 150408 23:36:17

BINLOG '

2TUlVQ9sTgAA9AAAAPgAAAAAAAQAMTAuMC4xNy1NYXJpYURCLWxvZwAAAAAAAAAAAAAAAAAAAAAA

AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAA3AAEGggAAAAICAgCAAAACgoKAAAAAAAA

AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA

AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA

AAAAAAAAAAAEEwQAC2l+iA==

'/*!*/;

# at 840720516

#150409  9:08:10 server id 20076  end_log_pos 840720554         GTID 0-20076-42437721

/*!100001 SET @@session.gtid_domain_id=0*//*!*/;

/*!100001 SET @@session.server_id=20076*//*!*/;

/*!100001 SET @@session.gtid_seq_no=42437721*//*!*/;

BEGIN

/*!*/;

# at 840720554

# at 840720780

# at 840720854

#150409  9:08:10 server id 20076  end_log_pos 840720780         Annotate_rows:

#Q> /*wp_r4 (MASTER)*/UPDATE data_source_prices

#Q>                             SET

#Q>                                     price = '23.8',

#Q>                                     last_updated = NOW()

#Q>                             WHERE

#Q>                                     market_selection_details_id = '6379754' AND

#Q>                                     bet_type = '1' AND

#Q>                                     data_source_i

#150409  9:08:10 server id 20076  end_log_pos 840720854         Table_map: `xxx_20150210`.`data_source_prices` mapped to number

#150409  9:08:10 server id 20076  end_log_pos 840720938         Update_rows: table id 19326 flags: STMT_END_F

BINLOG '

4rslVRNsTgAASgAAANZhHDIAAH5LAAAAAAEAD2x1eGJldF8yMDE1MDIxMAASZGF0YV9zb3VyY2Vf

cHJpY2VzAAUDAwP2DAIMAhA=

4rslVRhsTgAAVAAAACpiHDIAAH5LAAAAAAEABf//4OpYYQABAAAACQAAAIAAAAAXPKPW+aFTEgAA

4OpYYQABAAAACQAAAIAAAAAXUPrW+aFTEgAA

'/*!*/;

# at 840720938

#150409  9:08:10 server id 20076  end_log_pos 840720965         Xid = 411642227

COMMIT/*!*/;

# at 840720965

#150409  9:08:10 server id 20076  end_log_pos 840721003         GTID 0-20076-42437722

/*!100001 SET @@session.gtid_seq_no=42437722*//*!*/;

BEGIN

/*!*/;

# at 840721003

# at 840721222

# at 840721304

#150409  9:08:10 server id 20076  end_log_pos 840721222         Annotate_rows:

#Q> /*wp_r4 (MASTER)*/INSERT INTO data_source_prices_history  (`market_selection_details_id`,`bet_type`,`data_source_id`,`price`,`

last_updated`) VALUES ('6379755', '1', '9', '3.20', '2015-04-09 09:07:23')

#150409  9:08:10 server id 20076  end_log_pos 840721304         Table_map: `xxx_20150210`.`data_source_prices_history` mapped t

o number 21912

#150409  9:08:10 server id 20076  end_log_pos 840721360         Write_rows: table id 21912 flags: STMT_END_F

BINLOG '

4rslVRNsTgAAUgAAAJhjHDIAAJhVAAAAAAEAD2x1eGJldF8yMDE1MDIxMAAaZGF0YV9zb3VyY2Vf

cHJpY2VzX2hpc3RvcnkABQMDA/YMAgwCEA==

4rslVRdsTgAAOAAAANBjHDIAAJhVAAAAAAEABf/g61hhAAEAAAAJAAAAgAAAAAMUo9b5oVMSAAA=

'/*!*/;

# at 840721360

#150409  9:08:10 server id 20076  end_log_pos 840721387         Xid = 411642228

COMMIT/*!*/;

# at 840721387

#150409  9:08:10 server id 20076  end_log_pos 840721425         GTID 0-20076-42437723

/*!100001 SET @@session.gtid_seq_no=42437723*//*!*/;

BEGIN

/*!*/;

# at 840721425

# at 840721650

# at 840721724

#150409  9:08:10 server id 20076  end_log_pos 840721650         Annotate_rows:

#Q> /*wp_r4 (MASTER)*/UPDATE data_source_prices

#Q>                             SET

#Q>                                     price = '3.3',

#Q>                                     last_updated = NOW()

#Q>                             WHERE

#Q>                                     market_selection_details_id = '6379755' AND

#Q>                                     bet_type = '1' AND

#Q>                                     data_source_i

#150409  9:08:10 server id 20076  end_log_pos 840721724         Table_map: `xxx_20150210`.`data_source_prices` mapped to number

#150409  9:08:10 server id 20076  end_log_pos 840721808         Update_rows: table id 19326 flags: STMT_END_F

BINLOG '

4rslVRNsTgAASgAAADxlHDIAAH5LAAAAAAEAD2x1eGJldF8yMDE1MDIxMAASZGF0YV9zb3VyY2Vf

cHJpY2VzAAUDAwP2DAIMAhA=

4rslVRhsTgAAVAAAAJBlHDIAAH5LAAAAAAEABf//4OtYYQABAAAACQAAAIAAAAADFKPW+aFTEgAA

4OtYYQABAAAACQAAAIAAAAADHvrW+aFTEgAA

'/*!*/;

# at 840721808

#150409  9:08:10 server id 20076  end_log_pos 840721835         Xid = 411642229

COMMIT/*!*/;

# at 840721835

#150409  9:08:10 server id 20076  end_log_pos 840721873         GTID 0-20076-42437724

set global slave_parallel_threads=0; start slave;

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

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

               Slave_IO_State: Waiting for master to send event

                  Master_Host: 172.16.194.76

                  Master_User: repl

                  Master_Port: 3310

                Connect_Retry: 60

              Master_Log_File: tulwaurt005-mysql-bin.000325

          Read_Master_Log_Pos: 447467956

               Relay_Log_File: tulwaurt009-relay-bin.000002

                Relay_Log_Pos: 791

        Relay_Master_Log_File: tulwaurt005-mysql-bin.000309

             Slave_IO_Running: Yes

            Slave_SQL_Running: No

              Replicate_Do_DB:

          Replicate_Ignore_DB:

           Replicate_Do_Table:

       Replicate_Ignore_Table: xxx.feed_bettordata_data,xxx_docs.session,xxx_docs.session,xxx.feed_bettordata_data

      Replicate_Wild_Do_Table:

  Replicate_Wild_Ignore_Table:

                   Last_Errno: 1032

                   Last_Error: Could not execute Update_rows_v1 event on table xxx_20150210.data_source_prices; Can't find record in 'data_source_prices', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log tulwaurt005-mysql-bin.000309, end_log_pos 840720938

                 Skip_Counter: 0

          Exec_Master_Log_Pos: 840720516

              Relay_Log_Space: 13110413617

              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: 0

                Last_IO_Error:

               Last_SQL_Errno: 1032

               Last_SQL_Error: Could not execute Update_rows_v1 event on table xxx_20150210.data_source_prices; Can't find record in 'data_source_prices', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log tulwaurt005-mysql-bin.000309, end_log_pos 840720938

  Replicate_Ignore_Server_Ids:

             Master_Server_Id: 20076

               Master_SSL_Crl:

           Master_SSL_Crlpath:

                   Using_Gtid: Slave_Pos

                  Gtid_IO_Pos: 3-20076-44284,0-20076-65091365

Comments

Comment by Daniel Black [ 2015-04-13 ]

2015-04-09 09:07:23 from the binlogs and 2015-04-08 23:37:23 in the table.

master:

system_time_zone	ACST
time_zone	SYSTEM

Yes this is a GMT+9.5 timezone.

All other ACST timezone slaves survived.

slave:

system_time_zone	UTC
time_zone	SYSTEM

corrected:

rm     /etc/localtime && ln -s /usr/share/zoneinfo/Australia/Darwin /etc/localtime

service mysql restart

| system_time_zone               | CST               |

| time_zone                      | SYSTEM            |

select @@gtid_slave_pos,@@gtid_current_pos; show slave status\G

+--------------------------------+--------------------------------+

| 3-20076-17655,0-20076-42437720 | 3-20076-17655,0-20076-42437720 |

+--------------------------------+--------------------------------+

1 row in set (0.00 sec)

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

               Slave_IO_State: Waiting for master to send event

                  Master_Host: 172.16.194.76

                  Master_User: repl

                  Master_Port: 3310

                Connect_Retry: 60

              Master_Log_File: tulwaurt005-mysql-bin.000325

          Read_Master_Log_Pos: 613876281

               Relay_Log_File: tulwaurt009-relay-bin.000002

                Relay_Log_Pos: 791

        Relay_Master_Log_File: tulwaurt005-mysql-bin.000309

             Slave_IO_Running: Yes

            Slave_SQL_Running: Yes

              Replicate_Do_DB:

          Replicate_Ignore_DB:

           Replicate_Do_Table:

       Replicate_Ignore_Table:

      Replicate_Wild_Do_Table:

  Replicate_Wild_Ignore_Table:

                   Last_Errno: 1032

                   Last_Error: Could not execute Update_rows_v1 event on table xxx_20150210.data_source_prices; Can't find record in 'data_source_prices', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log tulwaurt005-mysql-bin.000309, end_log_pos 840720938

                 Skip_Counter: 0

          Exec_Master_Log_Pos: 840720516

              Relay_Log_Space: 13241702405

              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: 784

Master_SSL_Verify_Server_Cert: No

                Last_IO_Errno: 0

                Last_IO_Error:

               Last_SQL_Errno: 1032

               Last_SQL_Error: Could not execute Update_rows_v1 event on table xxx_20150210.data_source_prices; Can't find record in 'data_source_prices', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log tulwaurt005-mysql-bin.000309, end_log_pos 840720938

  Replicate_Ignore_Server_Ids:

             Master_Server_Id: 20076

               Master_SSL_Crl:

           Master_SSL_Crlpath:

                   Using_Gtid: Slave_Pos

                  Gtid_IO_Pos: 3-20076-44284,0-20076-65300701

sql thread still not moving gtid slave/current position despite running.

Is an identical TZ name essential for some reason (Master ACST != Slave CST)

[root@tulwaurt005 openquery]# cat    /usr/share/zoneinfo/Australia/Darwin

TZif2

�N����'��T��^x̷]�ͧ@xΠχ"x����ACDTACSTTZif2

����s�X����{p�����N��������'������T������^x����̷]�����ͧ@x����Π����χ"xz�~���       ��LMTACSTACDT

ACST-9:30

[root@tulwaurt009 etc]#  ls -la /usr/share/zoneinfo/Australia/Darwin

-rw-r--r--. 2 root root 288 Oct  3  2013 /usr/share/zoneinfo/Australia/Darwin

[root@tulwaurt009 etc]# cat /usr/share/zoneinfo/Australia/Darwin

TZif�N����'��T��^x̷]�ͧ@xΠχ"x����CSTTZif2

����s�X����{p�����N��������'������T������^x����̷]�����ͧ@x����Π����χ"xz�~�����LMTCST

CST-9:30

Comment by Daniel Black [ 2015-04-13 ]

copyied master TZ file to slave and restarted mysql - no change.

Comment by Elena Stepanova [ 2015-04-15 ]

Hi Daniel,

So, as I understand there are three issues here:

1) the initial failure, mismatch on the datetime value, which looks suspiciously related to the TZ difference;
2) a problem with error handling during parallel replication – even though there was an SQL error, the SQL thread is still kind of running, but the replication is not moving forward;
3) a problem with stopping the slave after that.

Regarding (2):

I remember things like that happened and were fixed before, apparently some cases still remain. I'll see if I can reproduce it.

Regarding (3):

Maybe it's a consequence of (2) – hopefully if I can reproduce (2), (3) will also become apparent...

Regarding (1):

AFAIK, DATETIME shouldn't depend on the timezone. The only "legal" scenario I can think of for this issue to happen is this:

once upon a time, the table had the TIMESTAMP field on master and slave;
'2015-04-09 09:07:23' was inserted into the table on the master, and converted into '2015-04-08 23:37:23' on the slave;
then the table was ALTERed, the column type was switched from TIMESTAMP to DATETIME both on master and slave;
then the day X came, when UPDATE was issued.

Is it in any way possible?

Comment by Daniel Black [ 2015-04-16 ]

Regarding (1):

AFAIK, DATETIME shouldn't depend on the timezone.

I was assuming that too.

The only "legal" scenario I can think of for this issue to happen is this:

once upon a time, the table had the TIMESTAMP field on master and slave;

'2015-04-09 09:07:23' was inserted into the table on the master, and converted into '2015-04-08 23:37:23' on the slave;

then the table was ALTERed, the column type was switched from TIMESTAMP to DATETIME both on master and slave;

then the day X came, when UPDATE was issued.

Nope. Test server was set up a few weeks ago. This field was always a DATETIME.

Comment by Elena Stepanova [ 2015-06-01 ]

danblack,
Has it ever happened again? I mean the initial failure, with datetime values.

bar, knielsen,
As experts in time values and replication, can you think of any scenario that could cause such a problem?

Comment by Daniel Black [ 2015-06-02 ]

no it hasn't happened again. I did correct the TZ difference as above.

Comment by Elena Stepanova [ 2015-09-05 ]

Temporarily assigning to bar to see if he has any ideas on what can cause such a problem.

Comment by Cuchac [ 2020-05-15 ]

Hello,
I can easily reproduce problem 1) - row based replication fails if no UNIQUE key present and servers has different timezones. DATETIME field is not stored with TZ info and RBR replication withou UNIQUE falls back to search using row values. But it does not find mathing row on slave, because no TZ conversion happens and values on master is different than on slave because TZ difference.

This problem really surprised me, because page https://mariadb.com/kb/en/row-based-replication-with-no-primary-key/ does not mention any possible issues with RBR + no UNIQUE.

Do you think it is possible to fix this issue in replication?
At least it would be great to document this issue somewhere so others are not caught by this.

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

[MDEV-7980] Could not execute Update_rows_v1 event on table xxx_20150210.data_source_prices; Can't find record in 'data_source_prices', Error_code: 1032; handler error HA_ERR_END_OF_FILE Created: 2015-04-13 Updated: 2021-08-10