| 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: | |
| Category: | MySQL Server: Replication | Severity: | S3 (Non-critical) |
| Version: | 5.1+ | OS: | Any |
| Assigned to: | Luis Soares | CPU Architecture: | Any |
[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]
MySQL Verification Team
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.
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