Bug #48357 SHOW BINLOG EVENTS: Wrong offset or I/O error
Submitted: 27 Oct 2009 18:04 Modified: 12 Mar 2010 17:02
Reporter: Vladislav Vaintroub Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Replication Severity:S3 (Non-critical)
Version:5.1, next-mr OS:Linux (Fedora 11 )
Assigned to: Luis Soares
Triage: Triaged: D3 (Medium)

[27 Oct 2009 18:04] Vladislav Vaintroub
Description:
On recent Fedora 11, I reproducibly getting a lot of binlog errors like the below 

CURRENT_TEST: binlog.binlog_database
mysqltest: In included file "./include/show_binlog_events.inc": At line 35: query '$show_binlog_events' failed: 1220: Error when executing command SHOW BINLOG EVENTS: Wrong offset or I/O error

./mtr --suite=binlog --max-test-fail=0
shows error in 55 of 94 test cases.

The box: 
[vvaintroub@fe2 mysql-test]$ uname -a
Linux fe2 2.6.30.8-64.fc11.x86_64 #1 SMP Fri Sep 25 04:43:32 EDT 2009 x86_64 x86_64 x86_64 GNU/Linux

I have this error on 2 different Fedora 11 machines, one with root partition formatted as ext4 (default), another as ext3. Neither Ubuntu 9.04 nor OpenSuse 11.1 bring this error. 

One thing probably worth mentioning is that Fedora11 has the most recent Linux kernel(2.6.30) and most recent gcc(4.4.1) compared to other Linux distributions.

How to repeat:
Run binlog test suite on Fedora 11 x64
[30 Oct 2009 0:14] Luis Soares
Tried to reproduce the reported test failure without success. I
tried on 4 different hosts: 2 ubuntus and 2 fedoras. Please, find
details below:

  Ubuntu x86 (9.04)
  =================

   - Test results:
     binlog.binlog_database 'row'             [ pass ]    349
     binlog.binlog_database 'stmt'            [ pass ]    173
     binlog.binlog_database 'mix'             [ pass ]    165

   - Kernel:
     .../mysql-next-mr$ uname -a
     Linux mobilos 2.6.28-14-generic #47-Ubuntu SMP Sat Jul 25 01:19:55 UTC 2009 x86_64 GNU/Linux

   - gcc
     .../mysql-next-mr$ gcc -v
     Using built-in specs.
     Target: x86_64-linux-gnu
     Configured with: ../src/configure -v --with-pkgversion='Ubuntu 4.3.3-5ubuntu4' --with-bugurl=file:///usr/share/doc/gcc-4.3/README.Bugs --enable-languages=c,c++,fortran,objc,obj-c++ --prefix=/usr --enable-shared --with-system-zlib --libexecdir=/usr/lib --without-included-gettext --enable-threads=posix --enable-nls --with-gxx-include-dir=/usr/include/c++/4.3 --program-suffix=-4.3 --enable-clocale=gnu --enable-libstdcxx-debug --enable-objc-gc --enable-mpfr --with-tune=generic --enable-checking=release --build=x86_64-linux-gnu --host=x86_64-linux-gnu --target=x86_64-linux-gnu
     Thread model: posix
     gcc version 4.3.3 (Ubuntu 4.3.3-5ubuntu4)

   - FS:
     /dev/sda4 on /home type ext3 (rw,relatime)

  Ubuntu x86_64 (9.10)
  ====================
  
   - Test results:
     binlog.binlog_database 'row'             [ pass ]    141
     binlog.binlog_database 'stmt'            [ pass ]    272
     binlog.binlog_database 'mix'             [ pass ]    209

   - Kernel:
     ...mysql-next-mr/mysql-test$ uname -a
     Linux gaia 2.6.31-14-generic #48-Ubuntu SMP Fri Oct 16 14:05:01 UTC 2009 x86_64 GNU/Linux

   - gcc:
     ...mysql-next-mr/mysql-test$ gcc -v
     Using built-in specs.
     Target: x86_64-linux-gnu
     Configured with: ../src/configure -v --with-pkgversion='Ubuntu 4.4.1-4ubuntu8' --with-bugurl=file:///usr/share/doc/gcc-4.4/README.Bugs --enable-languages=c,c++,fortran,objc,obj-c++ --prefix=/usr --enable-shared --enable-multiarch --enable-linker-build-id --with-system-zlib --libexecdir=/usr/lib --without-included-gettext --enable-threads=posix --with-gxx-include-dir=/usr/include/c++/4.4 --program-suffix=-4.4 --enable-nls --enable-clocale=gnu --enable-libstdcxx-debug --enable-objc-gc --disable-werror --with-arch-32=i486 --with-tune=generic --enable-checking=release --build=x86_64-linux-gnu --host=x86_64-linux-gnu --target=x86_64-linux-gnu
     Thread model: posix
     gcc version 4.4.1 (Ubuntu 4.4.1-4ubuntu8) 

   - FS:
     /dev/mapper/vg--gaia-lv--home on /home type ext3 (rw,relatime)

  Fedora Core 11 x86
  ==================

   - Test results:
     binlog.binlog_database 'row'             [ pass ]    176
     binlog.binlog_database 'stmt'            [ pass ]    165
     binlog.binlog_database 'mix'             [ pass ]    201

   - Kernel:
     [lsoares@fc11dev mysql-test]$ uname -a
     Linux fc11dev 2.6.30.9-90.fc11.i686.PAE #1 SMP Sat Oct 17 11:24:32 EDT 2009 i686 i686 i386 GNU/Linux

   - gcc:
     [lsoares@fc11dev mysql-test]$ gcc -v
     Using built-in specs.
     Target: i586-redhat-linux
     Configured with: ../configure --prefix=/usr --mandir=/usr/share/man --infodir=/usr/share/info --with-bugurl=http://bugzilla.redhat.com/bugzilla --enable-bootstrap --enable-shared --enable-threads=posix --enable-checking=release --with-system-zlib --enable-__cxa_atexit --disable-libunwind-exceptions --enable-languages=c,c++,objc,obj-c++,java,fortran,ada --enable-java-awt=gtk --disable-dssi --enable-plugin --with-java-home=/usr/lib/jvm/java-1.5.0-gcj-1.5.0.0/jre --enable-libgcj-multifile --enable-java-maintainer-mode --with-ecj-jar=/usr/share/java/eclipse-ecj.jar --disable-libjava-multilib --with-ppl --with-cloog --with-tune=generic --with-arch=i586 --build=i586-redhat-linux
     Thread model: posix
     gcc version 4.4.1 20090725 (Red Hat 4.4.1-2) (GCC)

   - FS:
     /dev/mapper/vg_fc11dev-lv_root on / type ext4 (rw)

  Fedora Core 11 x86_64
  =====================

   - Test results:
     binlog.binlog_database 'row'             [ pass ]    158
     binlog.binlog_database 'stmt'            [ pass ]    140
     binlog.binlog_database 'mix'             [ pass ]    134

   - Kernel:
     [lsoares@fc11dev64 mysql-test]$ uname -a
     Linux fc11dev64 2.6.30.9-90.fc11.x86_64 #1 SMP Sat Oct 17 11:25:35 EDT 2009 x86_64 x86_64 x86_64 GNU/Linux

   - gcc:
     [lsoares@fc11dev64 mysql-test]$ gcc -v
     Using built-in specs.
     Target: x86_64-redhat-linux
     Configured with: ../configure --prefix=/usr --mandir=/usr/share/man --infodir=/usr/share/info --with-bugurl=http://bugzilla.redhat.com/bugzilla --enable-bootstrap --enable-shared --enable-threads=posix --enable-checking=release --with-system-zlib --enable-__cxa_atexit --disable-libunwind-exceptions --enable-languages=c,c++,objc,obj-c++,java,fortran,ada --enable-java-awt=gtk --disable-dssi --enable-plugin --with-java-home=/usr/lib/jvm/java-1.5.0-gcj-1.5.0.0/jre --enable-libgcj-multifile --enable-java-maintainer-mode --with-ecj-jar=/usr/share/java/eclipse-ecj.jar --disable-libjava-multilib --with-ppl --with-cloog --with-tune=generic --with-arch_32=i586 --build=x86_64-redhat-linux
     Thread model: posix
     gcc version 4.4.1 20090725 (Red Hat 4.4.1-2) (GCC) 

   - FS:
     /dev/mapper/vg_fc11dev-lv_root on / type ext4 (rw)
[30 Oct 2009 1:25] Vladislav Vaintroub
Maybe it makes sense to add my configure options.
I configured with  ./configure only

On ubuntu everything is ok in my environment too (and on opensuse)
[30 Oct 2009 1:57] Vladislav Vaintroub
Here are exact steps what I do

bzr branch bzr+ssh://bk-internal.mysql.com/bzrroot/server/mysql-next-mr
cd mysql-next-nr
BUILD/autorun.sh
./configure
make
cd mysql-test
perl mysql-test-run.pl --suite=binlog binlog_database

And here is what I get
==============================================================================

TEST                                      RESULT   TIME (ms)
------------------------------------------------------------

binlog.binlog_database 'row'             [ fail ]
        Test ended at 2009-10-30 03:54:25

CURRENT_TEST: binlog.binlog_database
mysqltest: In included file "./include/show_binlog_events.inc": At line 35: query '$show_binlog_events' failed: 1220: Error when executing command SHOW BINLOG EVENTS: Wrong offset or I/O error

The result from queries just before the failure was:
set binlog_format=statement;
reset master;
create database testing_1;
use testing_1;
create table t1 (a int);
create function sf1 (a int) returns int return a+1;
create trigger tr1 before insert on t1 for each row insert into t2 values (2*new.a);
create procedure sp1 (a int) insert into t1 values(a);
drop database testing_1;

 - saving '/home/vvaintroub/bzr/mysql-next-mr/mysql-test/var/log/binlog.binlog_database-row/' to '/home/vvaintroub/bzr/mysql-next-mr/mysql-test/var/log/binlog.binlog_database-row/'

Only  1  of 3 completed.
mysql-test-run: *** ERROR: Not all tests completed
[30 Oct 2009 16:30] Luis Soares
VERIFICATION
============

I was able to reproduce these failures in the platforms using GCC
4.4.x that I mentioned in my comment ealier: "[30 Oct 1:14] Luís
Soares". I followed Wlad's instructions "[30 Oct 2:57] Vladislav
Vaintroub".

  Ubuntu 9.10 (x86_64)
  ====================

binlog.binlog_database 'row'             [ fail ]
        Test ended at 2009-10-30 15:25:14

CURRENT_TEST: binlog.binlog_database
mysqltest: In included file "./include/show_binlog_events.inc": At line 35: query '$show_binlog_events' failed: 1220: Error when executing command SHOW BINLOG EVENTS: Wrong offset or I/O error

The result from queries just before the failure was:
set binlog_format=statement;
reset master;
create database testing_1;
use testing_1;
create table t1 (a int);
create function sf1 (a int) returns int return a+1;
create trigger tr1 before insert on t1 for each row insert into t2 values (2*new.a);
create procedure sp1 (a int) insert into t1 values(a);
drop database testing_1;

  Fedora Core 11 (x86_64)
  =======================

binlog.binlog_database 'row'             [ fail ]
        Test ended at 2009-10-30 16:00:51

CURRENT_TEST: binlog.binlog_database
mysqltest: In included file "./include/show_binlog_events.inc": At line 35: query '$show_binlog_events' failed: 1220: Error when executing command SHOW BINLOG EVENTS: Wrong offset or I/O error

The result from queries just before the failure was:
set binlog_format=statement;
reset master;
create database testing_1;
use testing_1;
create table t1 (a int);
create function sf1 (a int) returns int return a+1;
create trigger tr1 before insert on t1 for each row insert into t2 values (2*new.a);
create procedure sp1 (a int) insert into t1 values(a);
drop database testing_1;

COMMENTS
========

  It seems that GCC 4.4 is stricter on aliasing requirements
[1]. Furthermore, "recent versions of GCC turn on the option
-fstrict-aliasing (which allows alias-based optimizations) by
default with -O2" [2]. This can result in undefined behavior if
aliasing rules are broken, because the compiler assumes that all
changes to variables occur through pointer or references that are
type compatible to the accessed variable [2]. Note that per the
failures reported happened only on binaries built with -O3 and
not on regular debug builds.

As such, to fix this for now, we can probably rely on the use of
"-fno-strict-aliasing" parameter when building MySQL with -O2 (or
higher).

REFERENCES
==========

[1] http://gcc.gnu.org/gcc-4.4/porting_to.html
[2] http://gcc.gnu.org/bugs/ (See section "Casting does not work
    as expected when optimization is turned on.")
[9 Nov 2009 17:36] 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/89843

3195 Luis Soares	2009-11-09
      BUG#48357: SHOW BINLOG EVENTS: Wrong offset or I/O error
      
      In function log_event.cc:Query_log_event::write, there was a cast that
      was triggering undefined behavior. The offending cast is the
      following:
      
        write_str_with_code_and_len((char **)(&start),
                                    catalog, catalog_len, Q_CATALOG_NZ_CODE);
      
      This results in calling write_str_with_code_and_len with first
      argument pointing to a (char **) while "start" is itself a pointer to
      uchar (uchar *). Inside write_str_with_..., the content of start is
      then be updated:
      
        (*dst)+= len;
      
      The instruction above would cause the (*dst) pointer (ie, the "start"
      argument, from the caller point of view, and which actually points to
      uchar instead of pointing to char) to be updated so that it would
      increment catalog_len. However, this seems to break strict-aliasing
      rules ultimately causing the increment and assignment to behave
      unexpectedly.
      
      We fix this by removing the cast and by making the types match.
[12 Nov 2009 22:34] Omer Barnir
triage: setting tag to SR51MRU
[19 Dec 2009 8:27] Bugs System
Pushed into 6.0.14-alpha (revid:alik@sun.com-20091219082307-f3i4fn0tm8trb3c0) (version source revid:alik@sun.com-20091216180721-eoa754i79j4ssd3m) (merge vers: 6.0.14-alpha) (pib:15)
[19 Dec 2009 8:30] Bugs System
Pushed into 5.5.1-m2 (revid:alik@sun.com-20091219082021-f34nq4jytwamozz0) (version source revid:alexey.kopytov@sun.com-20091211164058-ycpe0f20d1c4h1gl) (merge vers: 5.5.0-beta) (pib:15)
[19 Dec 2009 8:34] Bugs System
Pushed into mysql-next-mr (revid:alik@sun.com-20091219082213-nhjjgmphote4ntxj) (version source revid:alik@sun.com-20091216180221-a5ps59gajad3pip9) (pib:15)
[11 Jan 2010 17:40] Paul Dubois
Noted in 5.5.1, 6.0.14 changelogs.

SHOW BINLOG EVENTS could fail with a "Wrong offset or I/O error" error.

Setting report to NDI pending push to 5.1.x, Celosia.
[13 Jan 2010 15:26] Sveta Smirnova
Bug #50045 was marked as duplicate of this one.
[15 Jan 2010 8:58] Bugs System
Pushed into 5.1.43 (revid:joro@sun.com-20100115085139-qkh0i0fpohd9u9p5) (version source revid:luis.soares@sun.com-20091207002814-2dv3o41n0hozvhvy) (merge vers: 5.1.42) (pib:16)
[15 Jan 2010 19:06] Paul Dubois
Noted in 5.1.43 changelog.

Setting report to NDI pending push to Celosia.
[12 Mar 2010 14:05] Bugs System
Pushed into 5.1.44-ndb-7.0.14 (revid:jonas@mysql.com-20100312135944-t0z8s1da2orvl66x) (version source revid:jonas@mysql.com-20100312115609-woou0te4a6s4ae9y) (merge vers: 5.1.44-ndb-7.0.14) (pib:16)
[12 Mar 2010 14:21] Bugs System
Pushed into 5.1.44-ndb-6.2.19 (revid:jonas@mysql.com-20100312134846-tuqhd9w3tv4xgl3d) (version source revid:jonas@mysql.com-20100312060623-mx6407w2vx76h3by) (merge vers: 5.1.44-ndb-6.2.19) (pib:16)
[12 Mar 2010 14:35] Bugs System
Pushed into 5.1.44-ndb-6.3.33 (revid:jonas@mysql.com-20100312135724-xcw8vw2lu3mijrhn) (version source revid:jonas@mysql.com-20100312103652-snkltsd197l7q2yg) (merge vers: 5.1.44-ndb-6.3.33) (pib:16)
[12 Mar 2010 17:02] Paul Dubois
Fixed in earlier 5.1.x, 5.5.x.