[MDEV-12636] SELECT UNION writes garbage tail of VARCHAR column into internal temporary table Created: 2017-04-29  Updated: 2018-06-11  Resolved: 2018-06-11

Status: Closed
Project: MariaDB Server
Component/s: Optimizer, Storage Engine - Aria, Tests
Affects Version/s: 10.1, 10.2
Fix Version/s: 10.1.33, 10.2.15

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Oleksandr Byelkin
Resolution: Duplicate Votes: 0
Labels: None

Issue Links:
Relates
relates to MDEV-11649 Uninitialized field fts_token->positi... Closed
relates to MDEV-12676 InnoDB FTS duplicate key error Closed
Sprint: 10.1.24, 10.2.10, 10.2.11

 Description   

Might be related to MDEV-5518 / https://bugs.mysql.com/bug.php?id=73819

http://buildbot.askmonty.org/buildbot/builders/work-amd64-valgrind/builds/10024/steps/test/logs/stdio

innodb_fts.fulltext_misc 'innodb_plugin' w1 [ fail ]  Found warnings/errors in server log file!
 
        Test ended at 2017-04-27 13:05:34
 
line
 
==1037== Thread 22:
 
==1037== Syscall param write(buf) points to uninitialised byte(s)
 
==1037==    at 0x4E42B1D: ??? (in /lib64/libpthread-2.18.so)
 
==1037==    by 0xF1EB0B: my_write (my_write.c:49)
 
==1037==    by 0xEF31ED: inline_mysql_file_write (mysql_file.h:1131)
 
==1037==    by 0xEF5E79: _my_b_cache_write (mf_iocache.c:1643)
 
==1037==    by 0xEF66D4: my_b_flush_io_cache (mf_iocache.c:1843)
 
==1037==    by 0xEF68C2: end_io_cache (mf_iocache.c:1902)
 
==1037==    by 0xA8A5A5: maria_extra (ma_extra.c:164)
 
==1037==    by 0xA4547A: ha_maria::extra(ha_extra_function) (ha_maria.cc:2583)
 
==1037==    by 0x6F5367: select_union::flush() (sql_union.cc:111)
 
==1037==    by 0x6F7C07: st_select_lex_unit::exec() (sql_union.cc:849)
 
==1037==    by 0x6F5045: mysql_union(THD*, LEX*, select_result*, st_select_lex_unit*, unsigned long) (sql_union.cc:39)
 
==1037==    by 0x658035: handle_select(THD*, LEX*, select_result*, unsigned long) (sql_select.cc:362)
 
==1037==  Address 0x183197eb is 11 bytes inside a block of size 131,080 alloc'd
 
==1037==    at 0x4C280F3: malloc (vg_replace_malloc.c:299)
 
==1037==    by 0xF178DA: my_malloc (my_malloc.c:101)
 
==1037==    by 0xEF3B76: init_io_cache (mf_iocache.c:272)
 
==1037==    by 0xA8A512: maria_extra (ma_extra.c:145)
 
==1037==    by 0xA4547A: ha_maria::extra(ha_extra_function) (ha_maria.cc:2583)
 
==1037==    by 0x6F5590: select_union::create_result_table(THD*, List<Item>*, bool, unsigned long long, char const*, bool, bool, bool) (sql_union.cc:168)
 
==1037==    by 0x6F6AFE: st_select_lex_unit::prepare(THD*, select_result*, unsigned long) (sql_union.cc:585)
 
==1037==    by 0x6F502B: mysql_union(THD*, LEX*, select_result*, st_select_lex_unit*, unsigned long) (sql_union.cc:37)
 
==1037==    by 0x658035: handle_select(THD*, LEX*, select_result*, unsigned long) (sql_select.cc:362)
 
==1037==    by 0x627253: execute_sqlcom_select(THD*, TABLE_LIST*) (sql_parse.cc:5920)
 
==1037==    by 0x61D721: mysql_execute_command(THD*) (sql_parse.cc:2979)
 
==1037==    by 0x62A952: mysql_parse(THD*, char*, unsigned int, Parser_state*) (sql_parse.cc:7343)



 Comments   
Comment by Marko Mäkelä [ 2017-05-05 ]

This could have a common root cause with MDEV-11649.

Comment by Elena Stepanova [ 2017-08-10 ]

Reproducible locally (Jessie 8.8 64-bit, valgrind-3.12.0.SVN, gcc (Debian 4.9.2-10) 4.9.2) on the current 10.1 tree:

10.1 535910ae5f20e36405631030e9c0eb22fe40a7c4

 
$ perl ./mtr innodb_fts.fulltext_misc --valgrind --mem
 
 
 
innodb_fts.fulltext_misc 'innodb_plugin' [ fail ]  Found warnings/errors in server log file!
 
        Test ended at 2017-08-10 13:24:26
 
line
 
==18242== Thread 22:
 
==18242== Syscall param write(buf) points to uninitialised byte(s)
 
==18242==    at 0x4E481AD: ??? (syscall-template.S:84)
 
==18242==    by 0xEDA948: my_write (my_write.c:49)
 
==18242==    by 0xEAF5DF: inline_mysql_file_write (mysql_file.h:1131)
 
==18242==    by 0xEB2266: _my_b_cache_write (mf_iocache.c:1643)
 
==18242==    by 0xEB2ACB: my_b_flush_io_cache (mf_iocache.c:1843)
 
==18242==    by 0xEB2CB9: end_io_cache (mf_iocache.c:1902)
 
==18242==    by 0xA38CAA: maria_extra (ma_extra.c:165)
 
==18242==    by 0x9F3C94: ha_maria::extra(ha_extra_function) (ha_maria.cc:2583)
 
==18242==    by 0x6B4BFB: select_union::flush() (sql_union.cc:111)
 
==18242==    by 0x6B7534: st_select_lex_unit::exec() (sql_union.cc:864)
 
==18242==    by 0x6B48D3: mysql_union(THD*, LEX*, select_result*, st_select_lex_unit*, unsigned long) (sql_union.cc:39)
 
==18242==    by 0x616AD8: handle_select(THD*, LEX*, select_result*, unsigned long) (sql_select.cc:362)
 
==18242==    by 0x5E5EFA: execute_sqlcom_select(THD*, TABLE_LIST*) (sql_parse.cc:5924)
 
==18242==    by 0x5DC3CB: mysql_execute_command(THD*) (sql_parse.cc:2981)
 
==18242==    by 0x5E9608: mysql_parse(THD*, char*, unsigned int, Parser_state*) (sql_parse.cc:7344)
 
==18242==    by 0x5D8565: dispatch_command(enum_server_command, THD*, char*, unsigned int) (sql_parse.cc:1484)
 
==18242==  Address 0x1873704b is 11 bytes inside a block of size 131,080 alloc'd
 
==18242==    at 0x4C2BBAF: malloc (vg_replace_malloc.c:299)
 
==18242==    by 0xED3927: my_malloc (my_malloc.c:101)
 
==18242==    by 0xEAFF5C: init_io_cache (mf_iocache.c:272)
 
==18242==    by 0xA38C13: maria_extra (ma_extra.c:145)
 
==18242==    by 0x9F3C94: ha_maria::extra(ha_extra_function) (ha_maria.cc:2583)
 
==18242==    by 0x6B4E17: select_union::create_result_table(THD*, List<Item>*, bool, unsigned long long, char const*, bool, bool, bool) (sql_union.cc:168)
 
==18242==    by 0x6B6426: st_select_lex_unit::prepare(THD*, select_result*, unsigned long) (sql_union.cc:598)
 
==18242==    by 0x6B48B9: mysql_union(THD*, LEX*, select_result*, st_select_lex_unit*, unsigned long) (sql_union.cc:37)
 
==18242==    by 0x616AD8: handle_select(THD*, LEX*, select_result*, unsigned long) (sql_select.cc:362)
 
==18242==    by 0x5E5EFA: execute_sqlcom_select(THD*, TABLE_LIST*) (sql_parse.cc:5924)
 
==18242==    by 0x5DC3CB: mysql_execute_command(THD*) (sql_parse.cc:2981)
 
==18242==    by 0x5E9608: mysql_parse(THD*, char*, unsigned int, Parser_state*) (sql_parse.cc:7344)
 
==18242==    by 0x5D8565: dispatch_command(enum_server_command, THD*, char*, unsigned int) (sql_parse.cc:1484)
 
==18242==    by 0x5D7302: do_command(THD*) (sql_parse.cc:1106)
 
==18242==    by 0x714C78: do_handle_one_connection(THD*) (sql_connect.cc:1349)
 
==18242==    by 0x7149DC: handle_one_connection (sql_connect.cc:1261)
 
^ Found warnings in /data/bld/10.1-valgrind/mysql-test/var/log/mysqld.1.err
 
ok

Comment by Marko Mäkelä [ 2017-08-10 ]

With vgdb, I got the following stack trace with parameter values:

#0  0x0000000004e481ad in write () at ../sysdeps/unix/syscall-template.S:84
 
#1  0x00000000010ff470 in my_write (Filedes=65, 
    Buffer=0x10f28f98 "\375\001\061", Count=24, MyFlags=36)
 
    at /mariadb/10.2/mysys/my_write.c:49
 
#2  0x00000000010d38be in inline_mysql_file_write (
 
    src_file=0x147d610 "/mariadb/10.2/mysys/mf_iocache.c", src_line=1733, 
    file=65, buffer=0x10f28f98 "\375\001\061", count=24, flags=36)
 
    at /mariadb/10.2/include/mysql/psi/mysql_file.h:1131
 
#3  0x00000000010d68c3 in _my_b_cache_write (info=0x10ce2108, 
    Buffer=0x10f28f98 "\375\001\061", Count=24)
 
    at /mariadb/10.2/mysys/mf_iocache.c:1733
 
#4  0x00000000010d7133 in my_b_flush_io_cache (info=0x10ce2108, 
    need_append_buffer_lock=0) at /mariadb/10.2/mysys/mf_iocache.c:1933
 
#5  0x00000000010d7325 in end_io_cache (info=0x10ce2108)
 
    at /mariadb/10.2/mysys/mf_iocache.c:1992
 
#6  0x0000000000f70e08 in maria_extra (info=0x10ce1ca8, 
    function=HA_EXTRA_NO_CACHE, extra_arg=0x0)
 
    at /mariadb/10.2/storage/maria/ma_extra.c:165
 
---Type <return> to continue, or q <return> to quit---
 
#7  0x0000000000f2bee8 in ha_maria::extra (this=0x1ca9fe80, 
    operation=HA_EXTRA_NO_CACHE)
 
    at /mariadb/10.2/storage/maria/ha_maria.cc:2597
 
#8  0x00000000007a212c in select_union::flush (this=0x1caa3950)
 
    at /mariadb/10.2/sql/sql_union.cc:135
 
#9  0x00000000007a5390 in st_select_lex_unit::exec (this=0x13b7c040)
 
    at /mariadb/10.2/sql/sql_union.cc:1009
 
#10 0x00000000007a1d1a in mysql_union (thd=0x13b78558, lex=0x13b7bf78, 
    result=0x1ca9a300, unit=0x13b7c040, setup_tables_done_option=0)
 
    at /mariadb/10.2/sql/sql_union.cc:41
 
#11 0x00000000006fcb9a in handle_select (thd=0x13b78558, lex=0x13b7bf78, 
    result=0x1ca9a300, setup_tables_done_option=0)
 
    at /mariadb/10.2/sql/sql_select.cc:351
 
#12 0x00000000006c8007 in execute_sqlcom_select (thd=0x13b78558, 
    all_tables=0xc995920) at /mariadb/10.2/sql/sql_parse.cc:6444
 
#13 0x00000000006bdd23 in mysql_execute_command (thd=0x13b78558)
 
    at /mariadb/10.2/sql/sql_parse.cc:3458
 
#14 0x00000000006cb9b3 in mysql_parse (thd=0x13b78558, 
    rawbuf=0x10d9f250 "SELECT * FROM t1 UNION SELECT * FROM t1\nORDER BY MATCH(a) AGAINST ('+abc' IN BOOLEAN MODE)", length=90, parser_state=0x412e1f0, 
    is_com_multi=false, is_next_command=false)
 
    at /mariadb/10.2/sql/sql_parse.cc:7880

After killing the server at this spot, I will get:

CURRENT_TEST: innodb_fts.fulltext_misc
 
mysqltest: At line 186: query 'SELECT * FROM t1 UNION SELECT * FROM t1
 
ORDER BY MATCH(a) AGAINST ('+abc' IN BOOLEAN MODE)' failed: 2013: Lost connection to MySQL server during query

With the attached patch, the test completes without any Valgrind or server error whatsoever (not even on shutdown):

diff --git a/mysql-test/suite/innodb_fts/t/fulltext_misc.test b/mysql-test/suite/innodb_fts/t/fulltext_misc.test
 
index 25690ddc1d9..bc84143c30c 100644
 
--- a/mysql-test/suite/innodb_fts/t/fulltext_misc.test
 
+++ b/mysql-test/suite/innodb_fts/t/fulltext_misc.test
 
@@ -183,7 +183,7 @@ SELECT * FROM t1 UNION SELECT * FROM t1
 
 
 --echo # Should not crash
 
 --sorted_result
 
-SELECT * FROM t1 UNION SELECT * FROM t1
 
+SELECT * FROM t1
 
   ORDER BY MATCH(a) AGAINST ('+abc' IN BOOLEAN MODE);
 
 
 # FIXME: Valgrind in MySQL code _MI_WRITE_BLOB_RECORD, bug #13389854

I suppose that also the result to the client would be written to write() and instrumented by Valgrind, so InnoDB cannot be the culprit here.

The problem seems to be in the UNION execution instead. Whoever fixes this should also uncomment the following statement in the test:

# FIXME: Valgrind in MySQL code _MI_WRITE_BLOB_RECORD, bug #13389854
 
#--echo # Should not crash
 
#(SELECT * FROM t1) UNION (SELECT * FROM t1)
 
#  ORDER BY MATCH(a) AGAINST ('+abc' IN BOOLEAN MODE);

Comment by Marko Mäkelä [ 2017-09-13 ]

Reduced test case:

--source include/have_innodb.inc
 
CREATE TABLE t1 (a VARCHAR(10), FULLTEXT KEY a (a)) ENGINE = InnoDB;
 
INSERT INTO t1 VALUES (1),(2);
 
SELECT * FROM t1 UNION SELECT * FROM t1
 
ORDER BY MATCH(a) AGAINST ('+abc' IN BOOLEAN MODE);
 
DROP TABLE t1;

Relevant configuration: cmake -DWITH_VALGRIND=ON -DWITH_ASAN=OFF -DCMAKE_BUILD_TYPE=Debug

With MyISAM instead of InnoDB, it does not fail, but that could be because MyISAM is not calling VALGRIND_MAKE_MEM_UNDEFINED.
My guess: The optimizer could be writing a garbage part of a record to an internal temporary table.
Please debug with vgdb use monitor get_vbits to find out which bytes are flagged as uninitialized.

The problem seems to be the UNION. A plain SELECT with or without the ORDER BY will execute just fine.

It would seem to me that the issue is that the uninitialized tail of VARCHAR columns is being written to a temporary table. With CHAR(10) instead of VARCHAR(10), the test passes just fine.

Please refer to Bug#12835650 VARCHAR maximum length performance impact.
It seems that in MySQL, the Valgrind warnings were suppressed, instead of fixing the problem. For example: Bug#12856915 VALGRIND FAILURE IN FILESORT/CREATE_SORT_INDEX

Comment by Oleksandr Byelkin [ 2017-09-15 ]

5.5 & 10.0 has no features used in the test suite

Comment by Marko Mäkelä [ 2017-09-15 ]

Does the test case really require FULLTEXT INDEX? Note that 10.0 should support FULLTEXT INDEX for InnoDB tables. 5.5 does not, but the problem should be repeatable there with a different type of query if you define UNIV_DEBUG_VALGRIND inside InnoDB.
Note: if the UNION is not optimized away in the following (I did not test), it should repeat also with that:

--source include/have_innodb.inc
 
CREATE TABLE t1 (a VARCHAR(10)) ENGINE = InnoDB;
 
INSERT INTO t1 VALUES (1),(2);
 
SELECT * FROM t1 UNION SELECT * FROM t1;

Comment by Oleksandr Byelkin [ 2017-10-10 ]

It is not repeatable on 5.5 without FULLTEXT INDEX.

Comment by Oleksandr Byelkin [ 2017-10-10 ]

in 10.0 FT expressions prohibited in last "union branch" (whatever does mean in the comment) so it is also not repeatable.

Comment by Oleksandr Byelkin [ 2017-11-06 ]

If remove "binary mode" it return error that can not find fulltext index and it looks correct, why it do not need index in binary mode.

Comment by Oleksandr Byelkin [ 2017-11-06 ]

it appeared that boolean mode allow absence of index.

internal temporary table table is aria, returned value of match is the same independent of original type of the table, but bug reproduceble only with innodb as t1 table.

Comment by Oleksandr Byelkin [ 2017-11-06 ]

It is 2 SELECTs with number 3, probably again problem of reset counter of SELECTs because of the error

Comment by Oleksandr Byelkin [ 2018-06-08 ]

The problem is fixed. the fact that bisect can't find normally the commit which fixed it it came form merge.

Also query in one of the test proposed here start return incorrect usage of FT and also the fact that it was not repeatable without FT and binary patch in particular makes me think that problem was there.

So I will just uncomment commented out test in fulltext_misc

Comment by Oleksandr Byelkin [ 2018-06-08 ]

OK, bisect was done incorrectly.
here is patch which fixed the problem:
HEAD ist jetzt bei b20f821e072 Fix Innodb ASAN error on init
b20f821e0723c27d6ce121aafb2eb6c6d89bcd57 is the first bad commit
commit b20f821e0723c27d6ce121aafb2eb6c6d89bcd57
Author: Vicențiu Ciorbaru <vicentiu@mariadb.org>
Date: Wed Jan 24 15:18:36 2018 +0200

Fix Innodb ASAN error on init

Backport 7c03edf2fe66855a8ce8f2575c3aaf66af975377 from xtradb to innodb

Generated at Thu Feb 08 07:59:16 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.