MySQL Bugs: #47412: Valgrind warnings / user can read uninitalized memory using SP variables

Bug #47412	Valgrind warnings / user can read uninitalized memory using SP variables
Submitted:	17 Sep 14:24	Modified:	11 Nov 16:58
Reporter:	Philip Stoev
Status:	Closed
Category:	Server	Severity:	S2 (Serious)
Version:	5.1+	OS:	Any
Assigned to:	Georgi Kodinov	Target Version:	5.1+
Triage:	Triaged: D2 (Serious)

Description:
When testing SIGNAL/RESIGNAL, it was observed that sometimes the client will get a
corrupted error message, which may contain memory contents that the user is not supposed
to see (hence the Private flag for this bug).

A subsequent test run with Valgrind revealed numerous warnings, including, but not
limited to, backtraces connected to handling of user variables inside stored procedures:

==7333== Conditional jump or move depends on uninitialised value(s)
==7333==    at 0xA42079: my_longlong10_to_str_8bit (ctype-simple.c:923)
==7333==    by 0x6697A0: String::set_int(long long, bool, charset_info_st*)
(sql_string.cc:102)
==7333==    by 0x5A7B9D: String::set(long long, charset_info_st*) (sql_string.h:162)
==7333==    by 0x5C5DA2: user_var_entry::val_str(char*, String*, unsigned)
(item_func.cc:4203)
==7333==    by 0x5C5F0E: Item_func_get_user_var::val_str(String*) (item_func.cc:4646)
==7333==    by 0x8B3907: assign_condition_item(st_mem_root*, char const*, THD*, Item*,
String*) (sql_signal.cc:246)
==7333==    by 0x8B3B5E: Sql_cmd_common_signal::eval_signal_informations(THD*,
MYSQL_ERROR*) (sql_signal.cc:326)
==7333==    by 0x8B4185: Sql_cmd_common_signal::raise_condition(THD*, MYSQL_ERROR*)
(sql_signal.cc:431)
==7333==    by 0x8B4537: Sql_cmd_signal::execute(THD*) (sql_signal.cc:466)
==7333==    by 0x68AEBE: mysql_execute_command(THD*) (sql_parse.cc:4820)
==7333==    by 0x8713A4: sp_instr_stmt::exec_core(THD*, unsigned*) (sp_head.cc:2926)
==7333==    by 0x8715D4: sp_lex_keeper::reset_lex_and_exec_core(THD*, unsigned*, bool,
sp_instr*) (sp_head.cc:2751)
==7333==    by 0x877889: sp_instr_stmt::execute(THD*, unsigned*) (sp_head.cc:2864)
==7333==    by 0x8738F7: sp_head::execute(THD*) (sp_head.cc:1248)
==7333==    by 0x87474C: sp_head::execute_procedure(THD*, List<Item>*) (sp_head.cc:1988)
==7333==    by 0x6898C7: mysql_execute_command(THD*) (sql_parse.cc:4400)

How to repeat:
Unfortunately, at this time, automatic test case simplification for Valgrind warnings is
not available. Instead, I will upload a 793K-line mysqltest test that provides numerous
warnings to work on. Please run this test until all warnings have been silenced.

If this approach would not work, please let me know and I will work with you to figure
out some other way to handle those bugs.

Based on IRC chat with pstoev, the bug seems triggered when the random expression used in
the test is a user variable.

Valgrind log for the first few dozen failures 

bug47412.log">http://mysql-systemqa.s3.amazonaws.com/bug47412.log

Mysqltest case (note, very long, may take a while to run to completion)

bug47412.test.zip">http://mysql-systemqa.s3.amazonaws.com/bug47412.test.zip

Thank you for the test case.

Verified with similar errors as in log attached in mysql-next-mr tree.

Sql_cmd_common_signal does not exists in log of my run.

valgrind log in next-mr

Attachment: mysqld.1.err.next-mr (application/octet-stream, text), 17.21 KiB.

PRELIMINARY ANALYSIS:

Based on the log file from this run:
  [17 Sep 16:01] Philip Stoev
  Valgrind log for the first few dozen failures 
  bug47412.log">http://mysql-systemqa.s3.amazonaws.com/bug47412.log

and based on the log file from this run:
 [17 Sep 21:45] Sveta Smirnova
 Thank you for the test case.
 Verified with similar errors as in log attached in mysql-next-mr tree.

the issue can be reproduced:
- in the tree that contain the SIGNAL statement, but when *not* executing
  the signal statement
- in a tree that does not contain any changes made by signal/resignal at all

As a result, the SIGNAL/RESIGNAL code is not the root cause,
and the bug is an existing defect that was exposed by the tests performed
during the SIGANL/RESIGNAL QA.

In my case test was running as `./mtr --valgrind --record bug47412` I got syntax error in
result file about SIGNAL

Based on the recent input (reproducible in 5.1) please re-triage.

mysqld log from version where signal is released

Attachment: mysqld.1.err.next-mr-signal.tar.gz (application/x-gzip, text), 19.07 KiB.

Bug is repeatable as described in mysql-next-mr-alik

triage: adding SR51MRU tag as exists in 5.1 as well

Please provide a test case for the 5.1 server

Hi Philip,

I will generate some handy replay scripts for Joro.

1. If you have a script t/abc.test but no (checked) file
   with expected results
1.1 Take care the last line of the script is
       exit;
1.2 remove any r/abc.result
    If there is such a file and if it differs from the test
    protocol we get a message about this difference but no
    valgrind output!
1.3 Run 
     ./mtr --skip-ndb --no-check-testcases \
           --valgrind-mysqld abc
1.4 You will get something like
    TEST   RESULT   TIME (ms)
    --------------------------------------------------
    worker[1] Using MTR_BUILD_THREAD 250, with reserved ports 12500..12509
    DROP SCHEMA IF EXISTS testdb;
    ...
    DROP SCHEMA testdb;
    main.bug47412_1c  [ fail ]  Found warnings/errors in server log file!
    ...
    mysqltest: Logging to ''.
    ...
    mysqltest: Start processing test commands 
               from './include/check-warnings.test' ...
               ...
    0x6ABCB4: Protocol_text::store_long(long long) (protocol.cc:906)
    0xB2F049: int10_to_str (int2str.c:156)
    0xB2F070: int10_to_str (int2str.c:162)
    0x4E3788B: (within /lib64/libpthread-2.8.so)
    0x4C2560E: malloc (in /usr/lib64/valgrind/amd64-linux/vgpreload_memcheck.so)
    ...
    ^ Found warnings!!
    Failed 1/1 tests, 0.00% were successful.
    ...
2. bug47412.test.zip">http://mysql-systemqa.s3.amazonaws.com/bug47412.test.zip
   can be used for replaying the 5.1 related problems on 5.1.
   The statements using SIGNAL/RESIGNAL fail, but this is not
   important.
I will put the minimal tests into the next comment.

I do not know if the MTR output contains all suspicious
valgrind related things.
log/mysqld.1.err contains a lot more

My environment:
- mysql-5.1-bugteam Tue 2009-10-06 revno: 3146
- ./BUILD/compile-pentium64-valgrind-max
- Linux OpenSuSE 11.0 (64 Bit)
- Intel Core2Duo
======================================================
Script 1:
-disable_warnings
DROP SCHEMA IF EXISTS testdb;
--enable_warnings

CREATE SCHEMA testdb;
USE testdb;
DELIMITER |;
CREATE FUNCTION f2 () RETURNS INTEGER
BEGIN
   DECLARE CONTINUE HANDLER FOR SQLSTATE '42000' SET @aux = 1;
   RETURN f_not_exists () ;
END|
CREATE PROCEDURE p3 ( arg1 VARCHAR(32) )
BEGIN
   CALL p_not_exists ( );
END|
DELIMITER ;|
--error ER_SP_DOES_NOT_EXIST
CALL p3 ( f2 () );

DROP SCHEMA testdb;
exit;

MTR valgrind output 1:
0xB31AB7: my_longlong10_to_str_8bit (ctype-simple.c:894)
0xB31B0A: my_longlong10_to_str_8bit (ctype-simple.c:907)
========================================================
Script 2:
--disable_warnings
DROP SCHEMA IF EXISTS testdb;
--enable_warnings

CREATE SCHEMA testdb;
USE testdb;
DELIMITER |;
CREATE FUNCTION f2 () RETURNS INTEGER
BEGIN
   DECLARE CONTINUE HANDLER FOR SQLSTATE '42000' SET @aux = 1;
   RETURN f_not_exists () ;
END|
CREATE PROCEDURE p3 ( arg2 INTEGER )
BEGIN
   CALL p_not_exists ( );
END|
DELIMITER ;|
--error ER_SP_DOES_NOT_EXIST
CALL p3 ( f2 () );

DROP SCHEMA testdb;
exit;

Difference between script 1 and 2:
   Parameter of p3 is VARCHAR or INTHEGER

MTR valgrind output 2:
0x683482: Field_long::store(long long, bool) (field.cc:3717)
0x6834A0: Field_long::store(long long, bool) (field.cc:3719)
0x6834BA: Field_long::store(long long, bool) (field.cc:3724)
============================================================
Script 3:
--disable_warnings
DROP SCHEMA IF EXISTS testdb;
--enable_warnings

CREATE SCHEMA testdb;
USE testdb;
DELIMITER |;
CREATE FUNCTION f2 () RETURNS INTEGER
BEGIN
   DECLARE CONTINUE HANDLER FOR SQLSTATE '42000' SET @aux = 1;
   RETURN f_not_exists () ;
END|
DELIMITER ;|
SELECT f2 ();

DROP SCHEMA testdb;

MTR valgrind output:
0x6ABCB4: Protocol_text::store_long(long long) (protocol.cc:906)
0xB2F049: int10_to_str (int2str.c:156)
0xB2F070: int10_to_str (int2str.c:162)
0x4E3788B: (within /lib64/libpthread-2.8.so)
0x4C2560E: malloc (in /usr/lib64/valgrind/amd64-linux/vgpreload_memcheck.so)

It is to be assumed that
- the fixes for the first three minimal tests
  will not remove all issues which were reported
- additional minimal tests have to be derived from
  the initial fat test
Therefore I ticked the additional QA needed flag.

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

3152 Georgi Kodinov	2009-10-08
      Bug #47412: Valgrind warnings / user can read uninitalized memory using 
      SP variables
      
      A function call may end without throwing an error or without setting 
      the return value. This can happen when e.g. an error occurs while 
      calculating the return value.
      
      Fixed by setting the return value to NULL before executing the function
      body.

I tried the patch on mysql-5.1-bugteam and
the initial "monster" test passed without
valgrind warnings.
Unticking "Additional QA test needed".

Sent a review by e-mail.

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

3152 Georgi Kodinov	2009-10-26
      Bug #47412: Valgrind warnings / user can read uninitalized memory using 
      SP variables
      
      A function call may end without throwing an error or without setting 
      the return value. This can happen when e.g. an error occurs while 
      calculating the return value.
      
      Fixed by setting the value to NULL when error occurs during evaluation
      of an expression.

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

3197 Georgi Kodinov	2009-10-26
      Bug #47412: Valgrind warnings / user can read uninitalized memory using 
      SP variables
      
      A function call may end without throwing an error or without setting 
      the return value. This can happen when e.g. an error occurs while 
      calculating the return value.
      
      Fixed by setting the value to NULL when error occurs during evaluation
      of an expression.

Pushed into 5.1.41 (revid:joro@sun.com-20091104092152-qz96bzlf2o1japwc) (version source
revid:kristofer.pettersson@sun.com-20091103162305-08l4gkeuif2ozsoj) (merge vers: 5.1.41)
(pib:13)

Pushed into 6.0.14-alpha (revid:alik@sun.com-20091110093407-rw5g8dys2baqkt67) (version
source revid:alik@sun.com-20091109080109-7dxapd5y5pxlu08w) (merge vers: 6.0.14-alpha)
(pib:13)

Pushed into 5.5.0-beta (revid:alik@sun.com-20091109115615-nuohp02h8mdrz8m2) (version
source revid:alik@sun.com-20091105092041-sp6eyod7sdlfuj3b) (merge vers: 5.5.0-beta)
(pib:13)

Noted in 5.1.41, 5.5.0, 6.0.14 changelogs.

A function call could end without throwing an error or setting the
return value. For example, this could happen when an error occurred
while calculating the return value. This is fixed by setting the
value to NULL when an error occurs during evaluation of an
expression.