Bug #43885 main.variables-big fails because of warnings within the server log
Submitted: 26 Mar 2009 14:27 Modified: 3 Apr 2009 23:32
Reporter: Matthias Leich Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Logging Severity:S3 (Non-critical)
Version:5.1 OS:Any (debug builds on 64-bit only?)
Assigned to: Tatiana Azundris Nuernberg
Triage: Triaged: D3 (Medium)

[26 Mar 2009 14:27] Matthias Leich
Description:
Tree: mysql-5.1-bugteam 
      Last changesset March 2009
      compile-pentium64-debug-max
OS: OpenSuSE Linux 11,0 64 Bit

./mtr --big variables-big
....

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

TEST                RESULT   TIME (ms)
-----------------------------------------
...
main.variables-big  [ fail ]  Found warnings/errors in server log file!
...

mysqltest: Start processing test commands from
           './include/check-warnings.test' ...
<slightly edited>
File is mysql-test/var/log/mysqld.1.err
  Error: Memory allocated at my_alloc.c:129 was
         overrun, discovered at 'sql_base.cc:2927'
  Error: Memory allocated at my_alloc.c:129 was
         overrun, discovered at 'table.cc:1651'
....
  Error: Memory allocated at my_alloc.c:129 was
         overrun, discovered at 'my_alloc.c:355'
^ Found warnings!!
mysqltest: ... Done processing test commands.
mysqltest: Test has succeeded!
ok
...
------------------------------------------------------------
The servers were restarted 0 times
Spent 0.000 of 267 seconds executing testcases
mysql-test-run: WARNING: Got errors/warnings while running tests, please examine '...mysql-test/var/log/warnings' for details.

Failed 1/1 tests, 0.00% were successful.

Failing test(s): main.variables-big

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

The IMHO suspicious things:
1. This test passes in 5.0 and 6.0 without warnings
   within the protocol or the server log.
   Why do we have this difference between 5.0 and 5.1?
   Note: 32 Bit binary on 32 Bit OS shows warnings
2. Let's assume that the server behaviour in 5.1 is from
   the technical point of view correct and the messages
   within mysqld.1.err are warnings.
   But why
   - says mysqld.1.err "Error" and not "Warning"
   - are there no warnings within the test protocol
     like
     SET SESSION transaction_prealloc_size=<value>;
     +Warnings:
     +Warning 1292 Truncated incorrect transaction_prealloc_size value:
     Note: Warnings will be disabled when I push the
           fix for Bug#43383 main.variables-big : 
                             Weak testing code and result

I will disable the test in 5.1 because of this bug.

How to repeat:
See above

Suggested fix:
1. If the current behaviour in 5.1 cannot be avoided
   than MTR's processing of warnings has to be adjusted
   so that we don't get a false alarm.
2. If the current behaviour in 5.1 is a server bug than
   please fix it.
[26 Mar 2009 16:04] Valerii Kravchuk
Test fails for me on Mac OS X in main 5.1 tree from bzr, but with different message in the error log:

CURRENT_TEST: main.variables-big
090326 18:56:36 [Warning] The syntax '--log' is deprecated and will be removed in MySQL 7.0. Please use '--general_log'/'--general_log_file' instead.
090326 18:56:36 [Warning] The syntax '--log_slow_queries' is deprecated and will be removed in MySQL 7.0. Please use '--slow_query_log'/'--slow_query_log_file' instead.
090326 18:56:36 [Warning] Setting lower_case_table_names=2 because file system for /Users/openxs/dbs/5.1/mysql-test/var/mysqld.1/data/ is case insensitive
090326 18:56:36 [Note] Plugin 'InnoDB' disabled by command line option
090326 18:56:36 [Note] Event Scheduler: Loaded 0 events
090326 18:56:36 [Note] /Users/openxs/dbs/5.1/libexec/mysqld: ready for connections.
Version: '5.1.34-debug-log'  socket: '/Users/openxs/dbs/5.1/mysql-test/var/tmp/mysqld.1.sock'  port: 12500  Source distribution
mysqld(35220,0xb0063000) malloc: *** mmap(size=3221229568) failed (error code=12)
*** error: can't allocate region
*** set a breakpoint in malloc_error_break to debug

and because of content mismatch:

main.variables-big                       [ fail ]
        Test ended at 2009-03-26 17:56:51

CURRENT_TEST: main.variables-big
--- /Users/openxs/dbs/5.1/mysql-test/r/variables-big.result	2009-03-18 21:46:39.000000000 +0300
+++ /Users/openxs/dbs/5.1/mysql-test/r/variables-big.reject	2009-03-26 18:56:51.000000000 +0300
@@ -1,20 +1,24 @@
 set session transaction_prealloc_size=1024*1024*1024*1;
 show processlist;
 Id	User	Host	db	Command	Time	State	Info
-1	root	localhost	test	Query	0	NULL	show processlist
+2	root	localhost	test	Query	0	NULL	show processlist
 set session transaction_prealloc_size=1024*1024*1024*2;
 show processlist;
 Id	User	Host	db	Command	Time	State	Info
-1	root	localhost	test	Query	0	NULL	show processlist
+2	root	localhost	test	Query	0	NULL	show processlist
 set session transaction_prealloc_size=1024*1024*1024*3;
 show processlist;
 Id	User	Host	db	Command	Time	State	Info
-1	root	localhost	test	Query	0	NULL	show processlist
+2	root	localhost	test	Query	0	NULL	show processlist
 set session transaction_prealloc_size=1024*1024*1024*4;
+Warnings:
+Warning	1292	Truncated incorrect transaction_prealloc_size value: '4294967296'
 show processlist;
 Id	User	Host	db	Command	Time	State	Info
-1	root	localhost	test	Query	0	NULL	show processlist
+2	root	localhost	test	Query	0	NULL	show processlist
 set session transaction_prealloc_size=1024*1024*1024*5;
+Warnings:
+Warning	1292	Truncated incorrect transaction_prealloc_size value: '5368709120'
 show processlist;
 Id	User	Host	db	Command	Time	State	Info
-1	root	localhost	test	Query	0	NULL	show processlist
+2	root	localhost	test	Query	0	NULL	show processlist

mysqltest: Result content mismatch
[26 Mar 2009 18:12] Matthias Leich
Hi,

thank you for trying the test on Mac OS X in main 5.1 tree.
So the bug might be limited to the 5.1 bug team tree
or Linux or is your Mac OSX 32 Bit?
The problem with the content of processlist.id
and under some situations processlist.time is
known and will be fixed by the patch for
Bug#43383 main.variables-big : Weak testing code and result
[27 Mar 2009 15:07] Matthias Leich
Tests with actual trees on Linux show:
mysql-5.1 (main) 2009-03-19 no bug
mysql-5.1-bugteam 2009-03-27 this bug
[27 Mar 2009 15:48] Matthias Leich
5.1 main tree 2009-03-27 16:34:48 +0200
revno: 2851
-----------
Now we have the same problem in main.
[28 Mar 2009 8:27] Tatiana Azundris Nuernberg
I'm stealing this one, it's a code bug.
[28 Mar 2009 10:45] 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/70764

2850 Tatiana A. Nurnberg	2009-03-28
      Bug#43885: main.variables-big fails because of warnings within the server log
      
      Malloc-failsafes used 32-bit sizes, which was
      sadly insufficient on 64-bit. (Problem should
      only have been visible in debug-builds on 64-bit.)
      
      Uses 64-bit size now.
     @ mysys/safemalloc.c
        32-bit size is not good enough on 64-bit machines.
[30 Mar 2009 10:15] Matthias Leich
I can confirm that the proposed patch fixes the
problem on my box
- OpenSuSE Linux 11.0 64 Bit
- mysql-5.1-bugteam
- ./BUILD/compile-pentium64-debug-max
[3 Apr 2009 23:32] Paul Dubois
Noted in 5.1.33, 6.0.11 changelogs.

On 64-bit debug builds, code in safemalloc resulted in errors due to
use of a 32-bit value for 64-bit allocations.