MySQL Bugs: #49269: mysqltest crashes on 'reap' if query executed after 'send'

Bug #49269	mysqltest crashes on 'reap' if query executed after 'send'
Submitted:	1 Dec 2009 16:30	Modified:	17 Jun 2010 19:28
Reporter:	Sven Sandberg	Email Updates:
Status:	Closed	Impact on me:	None
Category:	Tools: MTR / mysql-test-run	Severity:	S7 (Test Cases)
Version:	5.1	OS:	Any
Assigned to:	Bjørn Munch	CPU Architecture:	Any

Description:
mysqltest crashes if a query is executed between 'send' and 'reap'.

==== BEGIN STACK TRACE ====
Error: Packets out of order (Found: 1, expected 6)
lt-mysqltest: net.c:912: my_real_read: Assertion `0' failed.
mysqltest got signal 6
read_command_buf at 0x8098980 = --reap
conn->name at 0x8729208 = 
Attempting backtrace...
stack_bottom = (nil) thread_stack 0x10000
/home/sven/bzr/debug-max/5.1-bugteam/client/.libs/lt-mysqltest(my_print_stacktrace+0x26)[0x80638d9]
/home/sven/bzr/debug-max/5.1-bugteam/client/.libs/lt-mysqltest[0x80510ab]
/home/sven/bzr/debug-max/5.1-bugteam/client/.libs/lt-mysqltest[0x80510d5]
[0xb7ffc400]
/lib/tls/i686/cmov/libc.so.6(abort+0x188)[0xb7be7098]
/lib/tls/i686/cmov/libc.so.6(__assert_fail+0xee)[0xb7bde5ce]
/home/sven/bzr/debug-max/5.1-bugteam/libmysql_r/.libs/libmysqlclient_r.so.16[0xb7e3692e]
/home/sven/bzr/debug-max/5.1-bugteam/libmysql_r/.libs/libmysqlclient_r.so.16(my_net_read+0x35)[0xb7e36ac9]
/home/sven/bzr/debug-max/5.1-bugteam/libmysql_r/.libs/libmysqlclient_r.so.16(cli_safe_read+0x33)[0xb7e28bce]
/home/sven/bzr/debug-max/5.1-bugteam/libmysql_r/.libs/libmysqlclient_r.so.16[0xb7e2e711]
/home/sven/bzr/debug-max/5.1-bugteam/libmysql_r/.libs/libmysqlclient_r.so.16(mysql_read_query_result+0x19)[0xb7de8d3c]
/home/sven/bzr/debug-max/5.1-bugteam/client/.libs/lt-mysqltest(_Z16run_query_normalP13st_connectionP10st_commandiPciP17st_dynamic_stringS5_+0x176)[0x805f0f0]
/home/sven/bzr/debug-max/5.1-bugteam/client/.libs/lt-mysqltest(_Z9run_queryP13st_connectionP10st_commandi+0x57e)[0x80609c1]
/home/sven/bzr/debug-max/5.1-bugteam/client/.libs/lt-mysqltest(main+0xd65)[0x806202c]
/lib/tls/i686/cmov/libc.so.6(__libc_start_main+0xe5)[0xb7bd0775]
/home/sven/bzr/debug-max/5.1-bugteam/client/.libs/lt-mysqltest[0x804e401]
Writing a core file...

 - saving '/home/sven/bzr/debug-max/5.1-bugteam/mysql-test/var/log/rpl.rpl_sven_37-row/' to '/home/sven/bzr/debug-max/5.1-bugteam/mysql-test/var/log/rpl.rpl_sven_37-row/'
 - found 'core', moving it to '/home/sven/bzr/debug-max/5.1-bugteam/mysql-test/var/log/rpl.rpl_sven_37-row'
 - found 'core' (0/5)

Trying 'dbx' to get a backtrace

Trying 'gdb' to get a backtrace
Core generated by '/home/sven/bzr/debug-max/5.1-bugteam/client/.libs/lt-mysqltest'
Output from gdb follows. The first stack trace is from the failing thread.
The following stack traces are from all threads (so the failing one is
duplicated).
--------------------------

warning: Can't read pathname for load map: Input/output error.
Core was generated by `/home/sven/bzr/debug-max/5.1-bugteam/client/.libs/lt-mysqltest --defaults-file='.
Program terminated with signal 6, Aborted.
[New process 6552]
#0  0xb7ffc430 in __kernel_vsyscall ()
#0  0xb7ffc430 in __kernel_vsyscall ()
#1  0xb7fd71c8 in pthread_kill () from /lib/tls/i686/cmov/libpthread.so.0
#2  0x0806395d in my_write_core (sig=6) at stacktrace.c:310
#3  0x08051112 in signal_handler (sig=6) at mysqltest.cc:7527
#4  <signal handler called>
#5  0xb7ffc430 in __kernel_vsyscall ()
#6  0xb7be56d0 in raise () from /lib/tls/i686/cmov/libc.so.6
#7  0xb7be7098 in abort () from /lib/tls/i686/cmov/libc.so.6
#8  0xb7bde5ce in __assert_fail () from /lib/tls/i686/cmov/libc.so.6
#9  0xb7e3692e in my_real_read (net=0x8078ec0, complen=0xbfe705d4) at net.c:912
#10 0xb7e36ac9 in my_net_read (net=0x8078ec0) at net.c:1005
#11 0xb7e28bce in cli_safe_read (mysql=0x8078ec0) at client.c:691
#12 0xb7e2e711 in cli_read_query_result (mysql=0x8078ec0) at client.c:2803
#13 0xb7de8d3c in mysql_read_query_result (mysql=0x8078ec0) at libmysql.c:5247
#14 0x0805f0f0 in run_query_normal (cn=0x8078ec0, command=0x8739690, flags=2, 
    query=0x872a118 "reap", query_len=4, ds=0x80978cc, ds_warnings=0xbfe7076c)
    at mysqltest.cc:6531
#15 0x080609c1 in run_query (cn=0x8078ec0, command=0x8739690, flags=2)
    at mysqltest.cc:7248
#16 0x0806202c in main (argc=11, argv=0xbfe70b14) at mysqltest.cc:7911

Thread 1 (process 6552):
#0  0xb7ffc430 in __kernel_vsyscall ()
#1  0xb7fd71c8 in pthread_kill () from /lib/tls/i686/cmov/libpthread.so.0
#2  0x0806395d in my_write_core (sig=6) at stacktrace.c:310
#3  0x08051112 in signal_handler (sig=6) at mysqltest.cc:7527
#4  <signal handler called>
#5  0xb7ffc430 in __kernel_vsyscall ()
#6  0xb7be56d0 in raise () from /lib/tls/i686/cmov/libc.so.6
#7  0xb7be7098 in abort () from /lib/tls/i686/cmov/libc.so.6
#8  0xb7bde5ce in __assert_fail () from /lib/tls/i686/cmov/libc.so.6
#9  0xb7e3692e in my_real_read (net=0x8078ec0, complen=0xbfe705d4) at net.c:912
#10 0xb7e36ac9 in my_net_read (net=0x8078ec0) at net.c:1005
#11 0xb7e28bce in cli_safe_read (mysql=0x8078ec0) at client.c:691
#12 0xb7e2e711 in cli_read_query_result (mysql=0x8078ec0) at client.c:2803
#13 0xb7de8d3c in mysql_read_query_result (mysql=0x8078ec0) at libmysql.c:5247
#14 0x0805f0f0 in run_query_normal (cn=0x8078ec0, command=0x8739690, flags=2, 
    query=0x872a118 "reap", query_len=4, ds=0x80978cc, ds_warnings=0xbfe7076c)
    at mysqltest.cc:6531
#15 0x080609c1 in run_query (cn=0x8078ec0, command=0x8739690, flags=2)
    at mysqltest.cc:7248
#16 0x0806202c in main (argc=11, argv=0xbfe70b14) at mysqltest.cc:7911

------------------------------------------------------------
The servers were restarted 0 times
Spent 0.000 of 2 seconds executing testcases

Failed 1/1 tests, 0.00% were successful.

Failing test(s): rpl.rpl_sven_37

The log files in var/log may give you some hint of what went wrong.

If you want to report this error, please read first the documentation
at http://dev.mysql.com/doc/mysql/en/mysql-test-suite.html

mysql-test-run: *** ERROR: there were failing test cases

==== END STACK TRACE ====

I'm probably not supposed to execute queries between send and reap, but it would be nice not to crash.

How to repeat:
--send SELECT 1
SELECT 1;
--reap

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/93047

2866 Bjorn Munch	2009-12-07
      Bug #49269 mysqltest crashes on 'reap' if query executed after 'send'
      Set a flag after send to trap the case

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/96077

2871 Bjorn Munch	2010-01-06
      Bug #49269 mysqltest crashes on 'reap' if query executed after 'send'
      Set a flag after send to trap the case

Found a problem while running full tests: a few tests failed because they do send in one connection, then switch connection without reap. Then when the test goes back to the connection where it did send, the first SQL statement fails.

The library crash apparently doesn't happen here so we should probably allow it by resetting the flag. The tests in question use send because they just need it executed (e.g. a LOCK TABLES) but aren't interested in the reply.

I'm about to push this together with other approved fixes, so will commit a follow-up extra patch.

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/96109

2875 Bjorn Munch	2010-01-06
      Bug #49269 mysqltest crashes on 'reap' if query executed after 'send'
      Small amendment: ignore pending reap when switching connection, add test

Pushed to 5.1-mtr, trunk-mtr, next-mr-mtr, 6.0-codebase-mtr

Nah, that didn't work, I can't allow a new stmt after send after switching connections, as the result appears to be unpredictable.  Also I'm getting a strange error on Windows making it untestable, need to investigate.

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/96232

2876 Bjorn Munch	2010-01-07
      Bug #49269 mysqltest crashes on 'reap' if query executed after 'send'
      Undid amendment allowing pending reap after switching connections
      Moved check for pending reap earlier; failed if running with ps-protocol

Looking again at the crash, I see that mysqltest has actually written:

Error: Packets out of order (Found: 1, expected 6)
lt-mysqltest: net.c:912: my_real_read: Assertion `0' failed.

Didn't notice this at first. The source code is:

---
#ifdef EXTRA_DEBUG
            fflush(stdout);
	    fprintf(stderr,"Error: Packets out of order (Found: %d, expected %d)\n",
		    (int) net->buff[net->where_b + 3],
		    (uint) (uchar) net->pkt_nr);
            fflush(stderr);
            DBUG_ASSERT(0);
#endif
---

So this is an intentional crash when boult with debug, as a consequence of incorrect usage. So I consider this *not* a library bug after all and will not file a separate bug for that.

Adding reap to the test cases, and requiring reap even if a connection has been switched, looks good to me.

Probably also fixes BUG#44042

Also see BUG#20304 which actually should be fixed in the MySQL C API, but I think since the functionality to do 'mysql_read_query_result' + 'mysql_send_query' actually is kind of a hack, it could be fixed in mysqltest by using "flag" like you have done.

Test cases from BUG#49761 looks good.

The combined patched are hard to read, would it be possible to extract the full patch?

Pushed to 5.1-mtr, trunk-mtr, next-mr-mtr, 6.0-codebase-mtr

Pushed into 6.0.14-alpha (revid:alik@sun.com-20100220092844-jh07ayojyxn8uh9p) (version source revid:bjorn.munch@sun.com-20100107122320-dwynu5qnthtduevs) (merge vers: 6.0.14-alpha) (pib:16)

Pushed into 5.5.3-m2 (revid:alik@sun.com-20100220092622-wvhh1vfy5tjq4mhu) (version source revid:bjorn.munch@sun.com-20100107102700-h84tn8kgftqhl430) (merge vers: 5.5.1-m2) (pib:16)

Pushed into mysql-next-mr (revid:alik@sun.com-20100220092730-paoo5t9gcajs5dq8) (version source revid:bjorn.munch@sun.com-20100107102835-5rqkaprayb062452) (pib:16)

Noted in 5.5.3, 6.0.14 changelogs.

mysqltest no longer lets you execute an SQL statement on a connection
after doing a send command, unless you do a reap first. This was
previously accepted but could produce unpredictable results. 

Setting report to Need Merge pending push to 5.1.x, Celosia.

Pushed into 5.1.45 (revid:joro@sun.com-20100301083827-xnimmrjg6bh33o1o) (version source revid:azundris@mysql.com-20100222175719-viuh0f3gdsrkgv0r) (merge vers: 5.1.45) (pib:16)

Noted in 5.1.45 changelog.

Pushed into 5.1.47-ndb-7.0.16 (revid:martin.skold@mysql.com-20100617114014-bva0dy24yyd67697) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)

Pushed into 5.1.47-ndb-6.2.19 (revid:martin.skold@mysql.com-20100617115448-idrbic6gbki37h1c) (version source revid:martin.skold@mysql.com-20100609140708-52rvuyq4q500sxkq) (merge vers: 5.1.45-ndb-6.2.19) (pib:16)

Pushed into 5.1.47-ndb-6.3.35 (revid:martin.skold@mysql.com-20100617114611-61aqbb52j752y116) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)