Bug #48340 rpl_cross_version: Found warnings/errors in server log file!
Submitted: 27 Oct 2009 7:42 Modified: 12 Mar 2010 17:06
Reporter: Daogang Qu Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Replication Severity:S3 (Non-critical)
Version:5.1+ OS:Any
Assigned to: Luis Soares CPU Architecture:Any
Triage: Triaged: D2 (Serious)

[27 Oct 2009 7:42] Daogang Qu
Description:
rpl.rpl_cross_version                    [ fail ]  Found warnings/errors in server log file!
        Test ended at 2009-10-26 00:26:40
mysqltest: Logging to ''.
mysqltest: Results saved in ''.
mysqltest: Connecting to server localhost:13000 (socket /export/home2/pb2/test/sb_1-884023-1256498343.82/tmp/aN5s2FSE4I/mysqld.1.sock) as 'root', connection 'default', attempt 0 ...
mysqltest: ... Connected.
mysqltest: Start processing test commands from './include/check-warnings.test' ...
line
==30332== Thread 4:
==30332== Conditional jump or move depends on uninitialised value(s)
==30332==    at 0x80BC85: write_execute_load_query_log_event(THD*, sql_exchange*, char const*, char const*, enum_duplicates, bool, bool, int) (sql_load.cc:638)
==30332==    by 0x80D9CC: mysql_load(THD*, sql_exchange*, TABLE_LIST*, List<Item>&, List<Item>&, List<Item>&, enum_duplicates, bool, bool) (sql_load.cc:592)
==30332==    by 0x7939B6: Load_log_event::do_apply_event(st_net*, Relay_log_info const*, bool) (log_event.cc:4668)
==30332==    by 0x7994A8: Execute_load_log_event::do_apply_event(Relay_log_info const*) (log_event.cc:6563)
==30332==    by 0x84A083: Log_event::apply_event(Relay_log_info const*) (log_event.h:1059)
==30332==    by 0x843F82: apply_event_and_update_pos(Log_event*, THD*, Relay_log_info*) (slave.cc:2136)
==30332==    by 0x844477: exec_relay_log_event(THD*, Relay_log_info*) (slave.cc:2277)
==30332==    by 0x844FA9: handle_slave_sql (slave.cc:3023)
==30332==    by 0x3895A06366: start_thread (in /lib64/libpthread-2.5.so)
==30332==    by 0x3894ED30AC: clone (in /lib64/libc-2.5.so)
^ Found warnings in /export/home2/pb2/test/sb_1-884023-1256498343.82/mysql-5.5.0-beta-linux-x86_64-test/mysql-test/var-n_mix/log/mysqld.1.err
mysqltest: ... Done processing test commands.
mysqltest: Test has succeeded!
ok

 - saving '/export/home2/pb2/test/sb_1-884023-1256498343.82/mysql-5.5.0-beta-linux-x86_64-test/mysql-test/var-n_mix/log/rpl.rpl_cross_version/' to '/export/home2/pb2/test/sb_1-884023-1256498343.82/mysql-5.5.0-beta-linux-x86_64-test/mysql-test/var-n_mix/log/rpl.rpl_cross_version/'

Retrying test, attempt(2/3)...

How to repeat:
http://pb2.norway.sun.com/web.py?template=mysql_show_test_failure&test_failure_id=2413446
[2 Nov 2009 10:24] Daogang Qu
The failure is found on test-valgrind-linux-x86_64 (tyr79) platform base on 'mysql-5.1-bugteam' tree.
[17 Nov 2009 14:34] Luis Soares
Hi,

I could repeat this using the following steps:

bzr clone $MY_LOCAL_CLONES_DIR/mysql-5.1-bugteam
cd mysql-5.1-bugteam
./BUILD/compile-pentium64-valgrind-max
cd mysql-test
perl mysql-test-run.pl --mysqld=--binlog-format=mix --valgrind --valgrind-options="--gen-suppressions=all --show-reachable=yes" rpl_cross_version

The original error is reported by PB2 on a valgrind run, more
precisely, on mysql-5.1-bugteam tree. This is still failing in
PB2. Details for recent failure:

Where 	Build 	Test 	Run 	Suite 	Case 	Mode 	When
mysql-5.1-bugteam
686585	binary-debug_valgrind-linux-x86_64-tar-gz
686668 tyr33	test-valgrind-linux-x86_64
689896 tyr77	n_mix	rpl	rpl_cross_version	None	2009-11-13 13:20:23

rpl.rpl_cross_version                    [ exp-fail ]  Found warnings/errors in server log file!
        Test ended at 2009-11-14 13:56:48
mysqltest: Logging to ''.
mysqltest: Results saved in ''.
mysqltest: Connecting to server localhost:13010 (socket /export/home2/pb2/test/sb_1-966965-1258180371.12/tmp/0T4PmhlCcD/mysqld.1.sock) as 'root', connection 'default', attempt 0 ...
mysqltest: ... Connected.
mysqltest: Start processing test commands from './include/check-warnings.test' ...
line
==24854== Thread 4:
==24854== Conditional jump or move depends on uninitialised value(s)
==24854==    at 0x8145CA: write_execute_load_query_log_event(THD*, sql_exchange*, char const*, char const*, enum_duplicates, bool, bool, int) (sql_load.cc:620)
==24854==    by 0x816220: mysql_load(THD*, sql_exchange*, TABLE_LIST*, List<Item>&, List<Item>&, List<Item>&, enum_duplicates, bool, bool) (sql_load.cc:555)
==24854==    by 0x79FBFA: Load_log_event::do_apply_event(st_net*, Relay_log_info const*, bool) (log_event.cc:4673)
==24854==    by 0x7A56F2: Execute_load_log_event::do_apply_event(Relay_log_info const*) (log_event.cc:6568)
==24854==    by 0x852BF3: Log_event::apply_event(Relay_log_info const*) (log_event.h:1059)
==24854==    by 0x84CB62: apply_event_and_update_pos(Log_event*, THD*, Relay_log_info*) (slave.cc:2136)
==24854==    by 0x84D057: exec_relay_log_event(THD*, Relay_log_info*) (slave.cc:2277)
==24854==    by 0x84DB7B: handle_slave_sql (slave.cc:3023)
==24854==    by 0x3F6D606366: start_thread (in /lib64/libpthread-2.5.so)
==24854==    by 0x3F6CAD30AC: clone (in /lib64/libc-2.5.so)
^ Found warnings in /export/home2/pb2/test/sb_1-966965-1258180371.12/mysql-5.1.41-linux-x86_64-test/mysql-test/var-n_mix/log/mysqld.1.err
mysqltest: ... Done processing test commands.
mysqltest: Test has succeeded!
[17 Nov 2009 15:25] Miguel Solorzano
Verified according Luis's instructions:

miguel@quetzal3:~/bzr/5.1-bugteam$ cd mysql-test                                                                                   
miguel@quetzal3:~/bzr/5.1-bugteam/mysql-test$ perl mysql-test-run.pl --mysqld=--binlog-format=mix --valgrind --valgrind-options="--gen-suppressions=all --show-reachable=yes" rpl_cross_version                                                                       
Logging: mysql-test-run.pl  --mysqld=--binlog-format=mix --valgrind --valgrind-options=--gen-suppressions=all --show-reachable=yes rpl_cross_version                                                                                                                  
091117 13:22:24 [Note] Plugin 'FEDERATED' is disabled.                                                                             
091117 13:22:24 [Note] Plugin 'ndbcluster' is disabled.                                                                            
MySQL Version 5.1.41                                                                                                               
Using binlog format 'mix'                                                                                                          
Turning on valgrind for all executables                                                                                            
Running valgrind with options " --gen-suppressions=all --show-reachable=yes --quiet "                                              
Checking supported features...                                                                                                     
 - using ndbcluster when necessary, mysqld supports it                                                                             
 - SSL connections supported                                                                                                       
 - binaries are debug compiled                                                                                                     
Using "../libtool" when running valgrind or debugger                                                                               
Collecting tests...                                                                                                                
 - adding combinations for rpl                                                                                                     
vardir: /home/miguel/bzr/5.1-bugteam/mysql-test/var                                                                                
Removing old var directory...                                                                                                      
Creating var directory '/home/miguel/bzr/5.1-bugteam/mysql-test/var'...                                                            
Installing system database...                                                                                                      
Using server port 57390                                                                                                            

==============================================================================

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

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
rpl.rpl_cross_version                    [ fail ]  Found warnings/errors in server log file!
        Test ended at 2009-11-17 13:22:52                                                   
mysqltest: Logging to ''.                                                                   
mysqltest: Results saved in ''.                                                             
mysqltest: Connecting to server localhost:13000 (socket /home/miguel/bzr/5.1-bugteam/mysql-test/var/tmp/mysqld.1.sock) as 'root', connection 'default', attempt 0 ...                                                                                                 
mysqltest: ... Connected.                                                                                                          
mysqltest: Start processing test commands from './include/check-warnings.test' ...                                                 
line                                                                                                                               
==13366== Thread 4:                                                                                                                
==13366== Conditional jump or move depends on uninitialised value(s)                                                               
==13366==    at 0x85719B: write_execute_load_query_log_event(THD*, sql_exchange*, char c
[24 Nov 2009 20:04] 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/91471

3201 Luis Soares	2009-11-24
      BUG#48340: rpl_cross_version: Found warnings/errors in server log file!
      
      Valgrind reports a conditional jump that depends on uninitialized
      data while doing a LOAD DATA and for this test case only. This
      test case, tests that loading data from a 4.0 or 4.1 instance
      into a 5.1 instance is working. As such it handles old binary log
      with a different set of events than currently 5.1 codebase uses.
      See the following reference for details:
      
      http://forge.mysql.com/wiki/MySQL_Internals_Binary_Log#LOAD_DATA_INFILE_Events
      
      Problem:
       
       The server is handling an Execute_load_log_event, which results
       in reading a Load_log_event from the binary log and applying
       it. When applying the Load_log_event, some variable setup is
       done and then mysql_load is called. Late in mysql_load
       execution, if not in row mode logging, the event is
       binlogged write_execute_load_query_log_event.
      
       In write_execute_load_query_log_event, thd->lex->local_file is
       inspected. The problem is that it has not been set before in the
       execution stack. This causes valgrind to report the warning.
      
      Fix: 
        
       We fix this by initializing thd->lex->local_file to be the same
       as the value of Load_log_event::local_fname, when lex_start is
       called inside Load_log_event::do_apply_event.
[1 Dec 2009 8:40] Daogang Qu
The 'rpl_cross_version' test case is added to experimental test list due to
the bug#48340.
[19 Dec 2009 8:28] 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:32] 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:36] 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:47] Paul Dubois
Noted in 5.5.1, 6.0.14 changelogs.

Valgrind warnings related to binary logging of LOAD DATA INFILE
statements were corrected. 

Setting report to NDI pending push to 5.1.x, Celosia.
[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-20091206233607-ae6i2ffhx270bp5u) (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:20] 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:34] 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:51] 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:06] Paul Dubois
Fixed in earlier 5.1.x, 5.5.x.