[MDEV-22351] InnoDB may report incorrect binlog position information after RESET MASTER - Jira

XML

Word

Printable

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Critical
Resolution: Fixed
Affects Version/s: 10.3, 10.4, 10.5
Fix Version/s: 10.3.28, 10.4.18, 10.5.9
Component/s: Storage Engine - InnoDB
Labels:
None

Description

RESET MASTER should be propagated to InnoDB to actually clear all information from the rseg header pages.

Observation:

Start a server with binary log option being enabled.
Create a simple table and insert couple of rows.

MariaDB [test]> show binlog events;

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

| Log_name          | Pos | Event_type        | Server_id | End_log_pos | Info                                                 |

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

| master-bin.000001 |   4 | Format_desc       |         1 |         256 | Server ver: 10.3.23-MariaDB-debug-log, Binlog ver: 4 |

| master-bin.000001 | 256 | Gtid_list         |         1 |         285 | []                                                   |

| master-bin.000001 | 285 | Binlog_checkpoint |         1 |         329 | master-bin.000001                                    |

| master-bin.000001 | 329 | Gtid              |         1 |         371 | GTID 0-1-1                                           |

| master-bin.000001 | 371 | Query             |         1 |         481 | use `test`; create table t ( f int ) engine=innodb   |

| master-bin.000001 | 481 | Gtid              |         1 |         523 | BEGIN GTID 0-1-2                                     |

| master-bin.000001 | 523 | Query             |         1 |         620 | use `test`; insert into t values (10)                |

| master-bin.000001 | 620 | Xid               |         1 |         651 | COMMIT /* xid=7 */                                   |

| master-bin.000001 | 651 | Gtid              |         1 |         693 | BEGIN GTID 0-1-3                                     |

| master-bin.000001 | 693 | Query             |         1 |         790 | use `test`; insert into t values (20)                |

| master-bin.000001 | 790 | Xid               |         1 |         821 | COMMIT /* xid=8 */                                   |

| master-bin.000001 | 821 | Stop              |         1 |         844 |                                                      |

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

Shutdown and restart server

Debug prints: From mysqld.1.err

****** BEFORE *********

----TRX_RSEG: binlog name:./master-bin.000001

----TRX_RSEG: binlog_offset:651

----recovered_binlog_name:

----recovered_binlog_offset:0

****** AFTER *********

----TRX_RSEG: binlog name:./master-bin.000001

----TRX_RSEG: binlog_offset:651

----recovered_binlog_name:./master-bin.000001

----recovered_binlog_offset:651

****** BEFORE *********

----TRX_RSEG: binlog name:./master-bin.000001

----TRX_RSEG: binlog_offset:821

----recovered_binlog_name:./master-bin.000001

----recovered_binlog_offset:651

****** AFTER *********

----TRX_RSEG: binlog name:./master-bin.000001

----TRX_RSEG: binlog_offset:821

----recovered_binlog_name:./master-bin.000001

----recovered_binlog_offset:821

Execute RESET MASTER on restarted server. // This will clear existing binary logs and a fresh 'master-bin.000001' is created.

MariaDB [test]> RESET MASTER;

Query OK, 0 rows affected (0.002 sec)

MariaDB [test]> create table t2( f int) engine=innodb;

Query OK, 0 rows affected (0.006 sec)

MariaDB [test]> insert into t2 values (30);

Query OK, 1 row affected (0.003 sec)

MariaDB [test]> show binlog events;

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

| Log_name          | Pos | Event_type        | Server_id | End_log_pos | Info                                                 |

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

| master-bin.000001 |   4 | Format_desc       |         1 |         256 | Server ver: 10.3.23-MariaDB-debug-log, Binlog ver: 4 |

| master-bin.000001 | 256 | Gtid_list         |         1 |         285 | []                                                   |

| master-bin.000001 | 285 | Binlog_checkpoint |         1 |         329 | master-bin.000001                                    |

| master-bin.000001 | 329 | Gtid              |         1 |         371 | GTID 0-1-1                                           |

| master-bin.000001 | 371 | Query             |         1 |         480 | use `test`; create table t2( f int) engine=innodb    |

| master-bin.000001 | 480 | Gtid              |         1 |         522 | BEGIN GTID 0-1-2                                     |

| master-bin.000001 | 522 | Query             |         1 |         620 | use `test`; insert into t2 values (30)               |

| master-bin.000001 | 620 | Xid               |         1 |         651 | COMMIT /* xid=9 */                                   |

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

Shutdown and restart. Observe the following output.
'recovered_binlog_name' and 'position' are still referring to old 'master-bin.000001' and '821'.

****** BEFORE *********

----TRX_RSEG: binlog name:./master-bin.000001

----TRX_RSEG: binlog_offset:651

----recovered_binlog_name:

----recovered_binlog_offset:0

****** AFTER *********

----TRX_RSEG: binlog name:./master-bin.000001

----TRX_RSEG: binlog_offset:651

----recovered_binlog_name:./master-bin.000001

----recovered_binlog_offset:651

****** BEFORE *********

----TRX_RSEG: binlog name:./master-bin.000001

----TRX_RSEG: binlog_offset:821

----recovered_binlog_name:./master-bin.000001

----recovered_binlog_offset:651

****** AFTER *********

----TRX_RSEG: binlog name:./master-bin.000001

----TRX_RSEG: binlog_offset:821

----recovered_binlog_name:./master-bin.000001

----recovered_binlog_offset:821

Shutdown and restart server.

A new binary log is created.
Now do a DML. With this latest binlog file name and pos are 'master-bin.000002' and pos=514

MariaDB [test]> show binlog events in 'master-bin.000002';

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

| Log_name          | Pos | Event_type        | Server_id | End_log_pos | Info                                                 |

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

| master-bin.000002 |   4 | Format_desc       |         1 |         256 | Server ver: 10.3.23-MariaDB-debug-log, Binlog ver: 4 |

| master-bin.000002 | 256 | Gtid_list         |         1 |         299 | [0-1-2]                                              |

| master-bin.000002 | 299 | Binlog_checkpoint |         1 |         343 | master-bin.000002                                    |

| master-bin.000002 | 343 | Gtid              |         1 |         385 | BEGIN GTID 0-1-3                                     |

| master-bin.000002 | 385 | Query             |         1 |         483 | use `test`; insert into t2 VALUES (40)               |

| master-bin.000002 | 483 | Xid               |         1 |         514 | COMMIT /* xid=5 */                                   |

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

shutdown and restart. Since 'TRX_RSEG' file and pos are > 'recovered_binlog_name/offset' the 'recovered_binlog_name/offset' get proper assignments.

****** BEFORE *********

----TRX_RSEG: binlog name:./master-bin.000002

----TRX_RSEG: binlog_offset:514

----recovered_binlog_name:

----recovered_binlog_offset:0

****** AFTER *********

----TRX_RSEG: binlog name:./master-bin.000002

----TRX_RSEG: binlog_offset:514

----recovered_binlog_name:./master-bin.000002

----recovered_binlog_offset:514

****** BEFORE *********

----TRX_RSEG: binlog name:./master-bin.000001

----TRX_RSEG: binlog_offset:651

----recovered_binlog_name:./master-bin.000002

----recovered_binlog_offset:514

****** AFTER *********

----TRX_RSEG: binlog name:./master-bin.000001

----TRX_RSEG: binlog_offset:651

----recovered_binlog_name:./master-bin.000002

----recovered_binlog_offset:514

****** BEFORE *********

----TRX_RSEG: binlog name:./master-bin.000001

----TRX_RSEG: binlog_offset:821

----recovered_binlog_name:./master-bin.000002

----recovered_binlog_offset:514

****** AFTER *********

----TRX_RSEG: binlog name:./master-bin.000001

----TRX_RSEG: binlog_offset:821

----recovered_binlog_name:./master-bin.000002

----recovered_binlog_offset:514

Following debug prints were used to observe the behavior:

diff --git a/storage/innobase/trx/trx0rseg.cc b/storage/innobase/trx/trx0rseg.cc

index 46fb2680371..842718ce81d 100644

--- a/storage/innobase/trx/trx0rseg.cc

+++ b/storage/innobase/trx/trx0rseg.cc

@@ -453,6 +453,14 @@ trx_rseg_mem_restore(trx_rseg_t* rseg, trx_id_t& max_trx_id, mtr_t* mtr)

         if (rseg_header[TRX_RSEG_BINLOG_NAME]) {

             const char* binlog_name = reinterpret_cast<const char*>

                 (rseg_header) + TRX_RSEG_BINLOG_NAME;

+            fprintf(stderr,"****** BEFORE *********\n");

+            fprintf(stderr,"----TRX_RSEG: binlog name:%s\n", binlog_name);

+            fprintf(stderr,"----TRX_RSEG: binlog_offset:%lu\n",

+                 mach_read_from_8(rseg_header + TRX_RSEG_BINLOG_OFFSET));

+            fprintf(stderr,"----recovered_binlog_name:%s\n",

+                trx_sys.recovered_binlog_filename);

+            fprintf(stderr,"----recovered_binlog_offset:%lu\n",

+                trx_sys.recovered_binlog_offset);

             compile_time_assert(TRX_RSEG_BINLOG_NAME_LEN == sizeof

                         trx_sys.recovered_binlog_filename);

@@ -478,6 +486,14 @@ trx_rseg_mem_restore(trx_rseg_t* rseg, trx_id_t& max_trx_id, mtr_t* mtr)

                         = binlog_offset;

+            fprintf(stderr,"****** AFTER *********\n");

+            fprintf(stderr,"----TRX_RSEG: binlog name:%s\n", binlog_name);

+            fprintf(stderr,"----TRX_RSEG: binlog_offset:%lu\n",

+                 mach_read_from_8(rseg_header + TRX_RSEG_BINLOG_OFFSET));

+            fprintf(stderr,"----recovered_binlog_name:%s\n",

+                trx_sys.recovered_binlog_filename);

+            fprintf(stderr,"----recovered_binlog_offset:%lu\n",

+                trx_sys.recovered_binlog_offset);

Attachments

Issue Links

blocks

MDEV-18959 Engine transaction recovery through persistent binlog

Stalled

is caused by

MDEV-15158 On commit, do not write to the TRX_SYS page

Closed

relates to

MDEV-26322 Last binlog file and position are "empty" in mariabackup --prepare output

Confirmed

Activity

People

Assignee:: Marko Mäkelä

Reporter:: Sujatha Sivakumar

Votes:: 0 Vote for this issue

Watchers:: 7 Start watching this issue

Dates

Created:: 2020-04-23 07:23

Updated:: 2021-09-03 12:21

Resolved:: 2021-01-25 08:28