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
Tags: binlog, End_log_pos, events, innodb, show

[21 Sep 2006 8:36] Paul McCullagh
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()
[21 Sep 2006 9:55] Sveta Smirnova
Thank you for the report.

Verified as described on Linux using last 5.0 and 5.1 BK sources.
[9 Nov 2006 11:50] Bernd Ocklin
Please note that this bug obviously will also affect the Exec_master_log_pos on the slave.
[12 Feb 2007 13:12] Bugs System
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.
[13 Feb 2007 20:25] Guilhem Bichot
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.
[20 Feb 2007 17:52] Jonathan Miller
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
[20 Feb 2007 17:52] Jonathan Miller
Test file

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

[20 Feb 2007 17:53] Jonathan Miller
innodb reject file

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

[20 Feb 2007 17:54] Jonathan Miller
MyISAM Reject

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

[25 Jun 2007 11:13] Guilhem Bichot
some fixes have to be made (and queued again)
[26 Jun 2007 11:35] Bugs System
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.
[27 Jun 2007 4:01] Bugs System
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.
[27 Jun 2007 6:20] Bugs System
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
[27 Jun 2007 9:42] Bugs System
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
[27 Jun 2007 9:43] Bugs System
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
[27 Jun 2007 11:19] Bugs System
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
[27 Jun 2007 11:29] Bugs System
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
[29 Jun 2007 4:31] Bugs System
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
[29 Jun 2007 7:29] Bugs System
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
[29 Jun 2007 9:12] Guilhem Bichot
still "in progress", because one bug in the patch needs to be fixed.
[30 Jun 2007 5:27] Bugs System
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
[2 Jul 2007 5:13] Bugs System
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.
[2 Jul 2007 5:34] Bugs System
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
[6 Jul 2007 6:33] Lars Thalmann
See also BUG#29558.
[9 Jul 2007 6:10] Bugs System
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.
[10 Jul 2007 13:27] Bugs System
Pushed into 5.1.21-beta
[10 Jul 2007 13:28] Bugs System
Pushed into 5.0.46
[10 Jul 2007 16:30] Bugs System
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
[10 Jul 2007 22:57] Paul Dubois
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.
[11 Jul 2007 2:32] Bugs System
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
[19 Jul 2007 15:48] Bugs System
Pushed into 5.1.21-beta
[19 Jul 2007 15:50] Bugs System
Pushed into 5.0.48