MySQL Bugs: #22540: Incorrect value in column End_log_pos of SHOW BINLOG EVENTS using InnoDB

Bug #22540	Incorrect value in column End_log_pos of SHOW BINLOG EVENTS using InnoDB
Submitted:	21 Sep 2006 8:36	Modified:	10 Jul 2007 22:57
Reporter:	Paul McCullagh (Basic Quality Contributor) (OCA)	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server	Severity:	S2 (Serious)
Version:	5.1.11, 5.0 BK	OS:	Linux (Linux)
Assigned to:	Tatiana Azundris Nuernberg	CPU Architecture:	Any
Tags:	binlog, End_log_pos, events, innodb, show

Description:
The value in the End_log_pos column for a SHOW BINLOG EVENTS is set to the size of the event, not the end offset of the event as required. This bug only occurs when using a transactional engine like PBXT or InnoDB.

How to repeat:
Execute the following statements. Note that the value in the End_log_pos column for the event "insert into t1 values (1)" is 88. It should be 289.

reset master;
create table t1(n int) engine=innodb;
insert into t1 values (1);
drop table t1;
SHOW BINLOG EVENTS FROM 0;

+-------------------+-----+-------------+-----------+-------------+--------------------------------------------------+
| Log_name          | Pos | Event_type  | Server_id | End_log_pos | Info                                             |
+-------------------+-----+-------------+-----------+-------------+--------------------------------------------------+
| master-bin.000001 |   4 | Format_desc |         1 |         102 | Server ver: 5.1.12-beta-debug-log, Binlog ver: 4 | 
| master-bin.000001 | 102 | Query       |         1 |         201 | use `test`; create table t1(n int) engine=innodb | 
| master-bin.000001 | 201 | Query       |         1 |          88 | use `test`; insert into t1 values (1)            | 
| master-bin.000001 | 289 | Xid         |         1 |         316 | COMMIT /* xid=6 */                               | 
| master-bin.000001 | 316 | Query       |         1 |         392 | use `test`; drop table t1                        | 
+-------------------+-----+-------------+-----------+-------------+--------------------------------------------------+

Suggested fix:
I think the problem is that the binlog is written after the transaction is auto-committed. To fix the problem, write the binlog before auto-commit, if possible.

I spent some time debugging this because I thought it was a problem with PBXT. Here are my results:

End_log_pos is set to the size of the record because in the file 'log_event.cc', function 

bool Log_event::write_header(IO_CACHE* file, ulong event_data_length)

my_b_safe_tell(file) returns the value 0 in the following assignment:

log_pos= my_b_safe_tell(file)+data_written;

my_b_safe_tell(file) returns 0 because, after the INSERT, the function reinit_io_cache() (file mf_iocache.c) is called as follows:

reinit_io_cache(trans_log, WRITE_CACHE, (my_off_t) 0, 0, 1); // cannot fail

which results in 'pos_in_file' being set to 0 in the following assignment:

info->pos_in_file=seek_offset;

The call stack looks like this, at the time of the assignment:

mysql_insert()
ha_autocommit_or_rollback()
ha_commit_stmt()
TC_LOG_BINLOG::log()
binlog_end_trans()
reinit_io_cache()

Thank you for the report.

Verified as described on Linux using last 5.0 and 5.1 BK sources.

Please note that this bug obviously will also affect the Exec_master_log_pos on the slave.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/19686

ChangeSet@1.2408, 2007-02-12 14:13:05+01:00, tnurnberg@mysql.com +3 -0
  Bug #22540: Incorrect value in column End_log_pos of SHOW BINLOG EVENTS using InnoDB
  
  fix output for SHOW BINLOG EVENTS so that end_log_pos is given correctly
  even within transactions. this is a purely cosmetic change and not required
  for correct operation.

this wrong end_log_pos (88) is a critical problem.
Because the event is not prefixed with a BEGIN event, the replication slave will set its Exec_master_log_pos to 88. So this value may later be used by a user or script into a CHANGE MASTER TO MASTER_LOG_FILE which will fail because there is no event at position 88 in the master's binlog.
For example, mysqldump prepares such a CHANGE MASTER command, which may be incorrect.

Hi,

I created a small test case as part of other bug test cases that shows this pretty well. Using RBR with InnoDB and MyISAM show different results.

The InnoDB run shows several Incorrect value in column End_log_pos, where the MyISAM runs show correct values.

Test and reject files attached.
/Jeb

Test file

Attachment: rpl_test.test (application/octet-stream, text), 4.19 KiB.

innodb reject file

Attachment: rpl_test_innodb.reject (application/octet-stream, text), 7.57 KiB.

MyISAM Reject

Attachment: rpl_test_myisam.reject (application/octet-stream, text), 7.36 KiB.

some fixes have to be made (and queued again)

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/29576

ChangeSet@1.2503, 2007-06-25 18:41:17+02:00, tnurnberg@sin.intern.azundris.com +1 -0
  Bug#22540: Incorrect value in column End_log_pos of SHOW BINLOG EVENTS using InnoDB
  
  end_log_pos data within a transaction are relative to
  the start of the transaction rather than absolute.
  we fix those groups in situ before writing the log out.
  
  additional comments and handling for groups with very
  large single events, as suggested by Guilhem.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/29662

ChangeSet@1.2510, 2007-06-27 04:32:34+02:00, tnurnberg@sin.intern.azundris.com +1 -0
  Bug#22540: Incorrect value in column End_log_pos of SHOW BINLOG EVENTS using InnoDB
   
  end_log_pos data within a transaction are relative to
  the start of the transaction rather than absolute.
  we fix those groups in situ before writing the log out.
   
  additional comments and handling for groups with very
  large single events, as suggested by Guilhem.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/29667

ChangeSet@1.2516, 2007-06-27 08:18:24+02:00, tnurnberg@sin.intern.azundris.com +2 -0
  Merge rkalimullin@bk-internal.mysql.com:/home/bk/mysql-5.0-maint
  into  mysql.com:/home/ram/work/b29079/b29079.5.0
  ---
  Bug #22540: Incorrect value in column End_log_pos of SHOW BINLOG EVENTS using InnoDB
  
  fix binlog-writing so that end_log_pos is given correctly even
  within transactions for both SHOW BINLOG and SHOW MASTER STATUS,
  that is as absolute values (from log start) rather than relative
  values (from transaction's start).
  ---
  Merge tnurnberg@bk-internal.mysql.com:/home/bk/mysql-5.0-maint
  into  sin.intern.azundris.com:/home/tnurnberg/22540/50-22540
  ---
  Bug#22540: Incorrect value in column End_log_pos of SHOW BINLOG EVENTS using InnoDB
  
  end_log_pos data within a transaction are relative to
  the start of the transaction rather than absolute.
  we fix those groups in situ before writing the log out.
  
  additional comments and handling for groups with very
  large single events, as suggested by Guilhem.
  ---
  Merge bk-internal.mysql.com:/home/bk/mysql-5.0-maint
  into  amd64.(none):/src/bug24732/my50-bug24732
  ---
  Merge maint1.mysql.com:/data/localhome/tsmith/bk/50
  into  maint1.mysql.com:/data/localhome/tsmith/bk/maint/50
  ---
  Bug#22540: Incorrect value in column End_log_pos of SHOW BINLOG EVENTS using InnoDB
   
  end_log_pos data within a transaction are relative to
  the start of the transaction rather than absolute.
  we fix those groups in situ before writing the log out.
   
  additional comments and handling for groups with very
  large single events, as suggested by Guilhem.
  ---
  Merge tnurnberg@bk-internal.mysql.com:/home/bk/mysql-5.0-maint
  into  sin.intern.azundris.com:/home/tnurnberg/22540/50-22540
  ---
  Merge tnurnberg@bk-internal.mysql.com:/home/bk/mysql-5.1-maint
  into  sin.intern.azundris.com:/home/tnurnberg/22540/51-22540
  ---
  Merge sin.intern.azundris.com:/home/tnurnberg/22540/50-22540
  into  sin.intern.azundris.com:/home/tnurnberg/22540/51-22540

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/29684

ChangeSet@1.2517, 2007-06-27 09:31:47+02:00, tnurnberg@sin.intern.azundris.com +1 -0
  Bug#22540: Incorrect value in column End_log_pos of SHOW BINLOG EVENTS using InnoDB
  
  windows fixies

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/29685

ChangeSet@1.2506, 2007-06-27 09:30:29+02:00, tnurnberg@sin.intern.azundris.com +1 -0
  Bug#22540: Incorrect value in column End_log_pos of SHOW BINLOG EVENTS using InnoDB
  
  windows fixies

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/29691

ChangeSet@1.2509, 2007-06-27 13:19:28+02:00, tnurnberg@sin.intern.azundris.com +1 -0
  Bug#22540: Incorrect value in column End_log_pos of SHOW BINLOG EVENTS using InnoDB
  
  Windows fixies

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/29693

ChangeSet@1.2522, 2007-06-27 13:23:58+02:00, tnurnberg@sin.intern.azundris.com +1 -0
  Bug#22540: Incorrect value in column End_log_pos of SHOW BINLOG EVENTS using InnoDB
  
  windows fixies

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/29921

ChangeSet@1.2509, 2007-06-25 09:23:30+02:00, tnurnberg@sin.intern.azundris.com +3 -0
  Bug #22540: Incorrect value in column End_log_pos of SHOW BINLOG EVENTS using InnoDB
  
  fix binlog-writing so that end_log_pos is given correctly even
  within transactions for both SHOW BINLOG and SHOW MASTER STATUS,
  that is as absolute values (from log start) rather than relative
  values (from transaction's start).
  ---
  Merge sin.intern.azundris.com:/home/tnurnberg/22540/50-22540
  into  sin.intern.azundris.com:/home/tnurnberg/22540/51-22540
  ---
  Merge tnurnberg@bk-internal.mysql.com:/home/bk/mysql-5.1-maint
  into  sin.intern.azundris.com:/home/tnurnberg/22540/51-22540

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/29927

ChangeSet@1.2525, 2007-06-29 09:28:51+02:00, msvensson@pilot.(none) +2 -0
  Bug#22540 Incorrect value in column End_log_pos of SHOW BINLOG EVENTS using InnoDB
   - Update test results for --binlog-format=row

still "in progress", because one bug in the patch needs to be fixed.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/30004

ChangeSet@1.2502, 2007-06-25 09:21:55+02:00, tnurnberg@sin.intern.azundris.com +3 -0
  Bug #22540: Incorrect value in column End_log_pos of SHOW BINLOG EVENTS using InnoDB
  
  fix binlog-writing so that end_log_pos is given correctly even
  within transactions for both SHOW BINLOG and SHOW MASTER STATUS,
  that is as absolute values (from log start) rather than relative
  values (from transaction's start).
  ---
  Merge tnurnberg@bk-internal.mysql.com:/home/bk/mysql-5.0-maint
  into  sin.intern.azundris.com:/home/tnurnberg/22540/50-22540

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/30050

ChangeSet@1.2509, 2007-07-02 07:13:40+02:00, tnurnberg@sin.intern.azundris.com +3 -0
  Bug#22540: Incorrect value in column End_log_pos of SHOW BINLOG EVENTS using InnoDB
  
  minor fixes to appease pushbuild.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/30051

ChangeSet@1.2531, 2007-07-02 07:34:42+02:00, tnurnberg@sin.intern.azundris.com +3 -0
  Bug#22540: Incorrect value in column End_log_pos of SHOW BINLOG EVENTS using InnoDB
  
  minor fixes to appease pushbuild.
  ---
  Merge sin.intern.azundris.com:/home/tnurnberg/22540/50-22540
  into  sin.intern.azundris.com:/home/tnurnberg/22540/51-22540

See also BUG#29558.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/30514

ChangeSet@1.2510, 2007-07-09 08:11:38+02:00, tnurnberg@mysql.com +3 -0
  Bug#22540: Incorrect value in column End_log_pos of SHOW BINLOG EVENTS using InnoDB
  
  dollin' it up for Guilhem ;) -- test streamlined,
  better comments, faster code, add'l assert.

Pushed into 5.1.21-beta

Pushed into 5.0.46

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/30619

ChangeSet@1.2534, 2007-07-10 18:31:50+02:00, tnurnberg@mysql.com +1 -0
  Bug#22540: Incorrect value in column End_log_pos of SHOW BINLOG EVENTS using InnoDB
  
  streamlining the test

Noted in 5.0.46, 5.1.21 changelogs.

SHOW BINLOG EVENTS displayed incorrect values of End_log_pos for
events associated with transactional storage engines.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/30647

ChangeSet@1.2554, 2007-07-11 04:33:19+02:00, tnurnberg@mysql.com +1 -0
  Bug#22540: Incorrect value in column End_log_pos of SHOW BINLOG EVENTS using InnoDB
  
  Streamlining test for RBR

Pushed into 5.1.21-beta

Pushed into 5.0.48