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

Details

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

Description

Warning

Even though this bug is marked "fixed", the problem with wrong binlog position was not fixed until 10.4.32

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-21611 mariabackup should update binlog position in InnoDB during prepare

Open

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

Closed

MDEV-32673 Handle InnoDB binlog position recovery for RESET MASTER or binlog name change

Stalled

Activity

Ascending order - Click to sort in descending order

Sujatha Sivakumar (Inactive) created issue - 2020-04-23 07:23

Marko Mäkelä made changes - 2020-04-23 07:58

Field	Original Value	New Value
Link		This issue is caused by ~~MDEV-15158~~ [ ~~MDEV-15158~~ ]

Marko Mäkelä made changes - 2020-04-23 10:08

Link

This issue blocks ~~MDEV-21117~~ [ ~~MDEV-21117~~ ]

Julien Fritsch made changes - 2020-04-23 13:34

Priority

Major [ 3 ]

Blocker [ 1 ]

Marko Mäkelä made changes - 2020-04-23 16:27

Status

Open [ 1 ]

In Progress [ 3 ]

Marko Mäkelä made changes - 2020-04-23 16:28

Assignee	Marko Mäkelä [ marko ]	Sergei Golubchik [ serg ]
Status	In Progress [ 3 ]	In Review [ 10002 ]

Sergei Golubchik made changes - 2020-05-04 11:53

Priority

Blocker [ 1 ]

Critical [ 2 ]

Sergei Golubchik made changes - 2020-05-04 11:53

Link

This issue blocks MDEV-18959 [ MDEV-18959 ]

Sergei Golubchik made changes - 2020-05-06 09:56

Fix Version/s		10.6 [ 24028 ]
Fix Version/s	10.3 [ 22126 ]
Fix Version/s	10.4 [ 22408 ]
Fix Version/s	10.5 [ 23123 ]

Sergei Golubchik made changes - 2020-05-06 09:56

Priority

Critical [ 2 ]

Major [ 3 ]

Sergei Golubchik made changes - 2020-05-11 18:19

Link

This issue blocks ~~MDEV-21117~~ [ ~~MDEV-21117~~ ]

Julien Fritsch made changes - 2020-11-16 07:39

Priority

Major [ 3 ]

Critical [ 2 ]

Marko Mäkelä made changes - 2021-01-22 14:48

Assignee

Sergei Golubchik [ serg ]

Sujatha Sivakumar [ sujatha.sivakumar ]

Sujatha Sivakumar (Inactive) made changes - 2021-01-25 08:24

Status

In Review [ 10002 ]

Stalled [ 10000 ]

Sujatha Sivakumar (Inactive) made changes - 2021-01-25 08:25

Assignee

Sujatha Sivakumar [ sujatha.sivakumar ]

Marko Mäkelä [ marko ]

Marko Mäkelä made changes - 2021-01-25 08:28

Fix Version/s		10.3.28 [ 25111 ]
Fix Version/s		10.4.18 [ 25110 ]
Fix Version/s		10.5.9 [ 25109 ]
Fix Version/s	10.6 [ 24028 ]
Resolution		Fixed [ 1 ]
Status	Stalled [ 10000 ]	Closed [ 6 ]

Marko Mäkelä made changes - 2021-01-25 10:14

Summary

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

InnoDB may report incorrect binlog position information after RESET MASTER

Marko Mäkelä made changes - 2021-09-03 12:21

Link

This issue relates to ~~MDEV-26322~~ [ ~~MDEV-26322~~ ]

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

Workflow

MariaDB v3 [ 107649 ]

MariaDB v4 [ 157663 ]

Marko Mäkelä made changes - 2022-05-12 09:49

Link

This issue relates to MDEV-21611 [ MDEV-21611 ]

Kristian Nielsen made changes - 2023-11-03 07:52

Assignee	Marko Mäkelä [ marko ]
Resolution	Fixed [ 1 ]
Status	Closed [ 6 ]	Stalled [ 10000 ]

Sergei Golubchik made changes - 2023-11-03 10:38

Priority

Critical [ 2 ]

Major [ 3 ]

Sergei Golubchik made changes - 2023-11-03 10:41

Assignee		Marko Mäkelä [ marko ]
Resolution		Fixed [ 1 ]
Status	Stalled [ 10000 ]	Closed [ 6 ]

Kristian Nielsen made changes - 2023-11-03 15:31

Link

This issue relates to MDEV-32673 [ MDEV-32673 ]

Sergei Golubchik made changes - 2023-11-03 18:25

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.
{code}
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 | |
+-------------------+-----+-------------------+-----------+-------------+------------------------------------------------------+
{code}
Shutdown and restart server

Debug prints: From mysqld.1.err

{code}
****** 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
{code}

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

{code}
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 */ |
+-------------------+-----+-------------------+-----------+-------------+------------------------------------------------------+
{code}

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

{code}
****** 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
{code}

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

{code}
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 */ |
+-------------------+-----+-------------------+-----------+-------------+------------------------------------------------------+
{code}

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

{code}
****** 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
{code}

Following debug prints were used to observe the behavior:
{code}
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);
{code}

{panel:title=Warning|borderStyle=dashed|borderColor=#ccc|bgColor=#FFFFCE|titleBGColor=#F7D6C1}
Even though this bug is marked "closed", the problem with wrong binlog position was not fixed until 10.4.32
{panel}

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.
{code}
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 | |
+-------------------+-----+-------------------+-----------+-------------+------------------------------------------------------+
{code}
Shutdown and restart server

Debug prints: From mysqld.1.err

{code}
****** 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
{code}

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

{code}
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 */ |
+-------------------+-----+-------------------+-----------+-------------+------------------------------------------------------+
{code}

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

{code}
****** 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
{code}

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

{code}
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 */ |
+-------------------+-----+-------------------+-----------+-------------+------------------------------------------------------+
{code}

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

{code}
****** 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
{code}

Following debug prints were used to observe the behavior:
{code}
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);
{code}

Sergei Golubchik made changes - 2023-11-03 18:25

Description

{panel:title=Warning|borderStyle=dashed|borderColor=#ccc|bgColor=#FFFFCE|titleBGColor=#F7D6C1}
Even though this bug is marked "fixed", the problem with wrong binlog position was not fixed until 10.4.32
{panel}

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.
{code}
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 | |
+-------------------+-----+-------------------+-----------+-------------+------------------------------------------------------+
{code}
Shutdown and restart server

Debug prints: From mysqld.1.err

{code}
****** 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
{code}

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

{code}
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 */ |
+-------------------+-----+-------------------+-----------+-------------+------------------------------------------------------+
{code}

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

{code}
****** 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
{code}

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

{code}
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 */ |
+-------------------+-----+-------------------+-----------+-------------+------------------------------------------------------+
{code}

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

{code}
****** 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
{code}

Following debug prints were used to observe the behavior:
{code}
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);
{code}

People

Assignee:: Marko Mäkelä

Reporter:: Sujatha Sivakumar (Inactive)

Votes:: 0 Vote for this issue

Watchers:: 10 Start watching this issue

Dates

Created:: 2020-04-23 07:23

Updated:: 2023-12-11 19:40

Resolved:: 2023-11-03 10:41

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