[MDEV-22691] MSAN use-of-uninitialized-value in test maria.maria-recovery2 Created: 2020-05-25  Updated: 2020-07-01  Resolved: 2020-06-15

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - Aria
Affects Version/s: 10.5
Fix Version/s: 10.5.4

Type: Bug Priority: Major
Reporter: Marko Mäkelä Assignee: Michael Widenius
Resolution: Fixed Votes: 0
Labels: Aria, recovery, statistics

Issue Links:
Blocks
blocks MDEV-20377 Make WITH_MSAN more usable Closed
Relates
relates to MDEV-22690 MSAN use-of-uninitialized-value in op... Closed

 Description   

The test {{maria.maria-recovery2} fails as follows:

10.5 d8ea11a33fba12331c98c04ff44c815a662faccb

 
CURRENT_TEST: maria.maria-recovery2
 
mysqltest: At line 70: query 'delete from t1 where b="b"' failed: 2013: Lost connection to MySQL server during query

In the server error log, we have the following:

10.5 d8ea11a33fba12331c98c04ff44c815a662faccb

 
Version: '10.5.4-MariaDB-debug-log'  socket: '/dev/shm/10.5-msan/mysql-test/var/tmp/1/mysqld.1.sock'  port: 16000  Source distribution
 
lex_end: enter: lex: 0x72b00002df68
 
Query_arena::free_items: info: free item: 0x72b0000311a8
 
Item::cleanup: enter: this: 0x72b0000311a8
 
dispatch_command: info: query ready
 
net_send_ok: info: affected_rows: 0  id: 0  status: 2  warning_count: 0
 
vio_is_blocking: exit: 0
 
…
 
alloc_root: exit: ptr: 0x72b000031eb8
 
SQL_SELECT::test_quick_select: enter: keys_to_use: 18446744073709551615  prev_tables: 0  const_tables: 0
 
SQL_SELECT::test_quick_select: info: records: 3
 
SQL_SELECT::test_quick_select: info: ==404750==WARNING: MemorySanitizer: use-of-uninitialized-value
 
    #0 0x5633313f8b71 in my_gcvt /mariadb/10.5m/strings/dtoa.c:294:19
 
    #1 0x563331409cd3 in process_dbl_arg /mariadb/10.5m/strings/my_vsnprintf.c:304:10
 
    #2 0x563331409cd3 in my_vsnprintf_ex /mariadb/10.5m/strings/my_vsnprintf.c:694:11
 
    #3 0x5633312e41e7 in DbugVfprintf /mariadb/10.5m/dbug/dbug.c:1332:10
 
    #4 0x5633312e41e7 in _db_doprnt_ /mariadb/10.5m/dbug/dbug.c:1316:3
 
    #5 0x56332f3f185d in SQL_SELECT::test_quick_select(THD*, Bitmap<64u>, unsigned long long, unsigned long long, bool, bool, bool, bool) /mariadb/10.5m/sql/opt_range.cc:2691:3
 
    #6 0x56332f53a5fe in SQL_SELECT::check_quick(THD*, bool, unsigned long long) /mariadb/10.5m/sql/opt_range.h:1654:12
 
    #7 0x56332f53a5fe in mysql_delete(THD*, TABLE_LIST*, Item*, SQL_I_List<st_order>*, unsigned long long, unsigned long long, select_result*) /mariadb/10.5m/sql/sql_delete.cc:500:26
 
    #8 0x56332e0ec30e in mysql_execute_command(THD*) /mariadb/10.5m/sql/sql_parse.cc:4787:11
 
    #9 0x56332e0c22f5 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /mariadb/10.5m/sql/sql_parse.cc:7991:18
 
    #10 0x56332e0b2c79 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /mariadb/10.5m/sql/sql_parse.cc:1874:7
 
    #11 0x56332e0c41ba in do_command(THD*) /mariadb/10.5m/sql/sql_parse.cc:1355:17
 
    #12 0x56332e6e02be in do_handle_one_connection(CONNECT*, bool) /mariadb/10.5m/sql/sql_connect.cc:1411:11
 
    #13 0x56332e6dfaa4 in handle_one_connection /mariadb/10.5m/sql/sql_connect.cc:1313:5
 
    #14 0x56332fb8a2c7 in pfs_spawn_thread /mariadb/10.5m/storage/perfschema/pfs.cc:2201:3
 
    #15 0x7f1e693e8f26 in start_thread nptl/pthread_create.c:479:8
 
    #16 0x7f1e68ec731e in clone misc/../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
 
 
  Uninitialized value was created by an allocation of 'stat_tables' in the stack frame of function '_Z26read_statistics_for_tablesP3THDP10TABLE_LIST'
 
    #0 0x56332e3fd9c0 in read_statistics_for_tables(THD*, TABLE_LIST*) /mariadb/10.5m/sql/sql_statistics.cc:3292
 
 
 
SUMMARY: MemorySanitizer: use-of-uninitialized-value /mariadb/10.5m/strings/dtoa.c:294:19 in my_gcvt
 
Exiting

I can see two problems here.

  1. Apparently something is inadvertently enabling all possible DBUG output.
  2. While we are outputting the data, we seem to notice that the Aria storage engine failed to provide some statistics.
    Here is a snippet of SQL_SELECT::test_quick_select(): 

      if (head->force_index || force_quick_range)
    		 
        scan_time= read_time= DBL_MAX;
    		 
      else
    		 
      {
    		 
        scan_time= rows2double(records) / TIME_FOR_COMPARE;
    		 
        /*
    		 
          The 2 is there to prefer range scans to full table scans.
    		 
          This is mainly to make the test suite happy as many tests has
    		 
          very few rows. In real life tables has more than a few rows and the
    		 
          +2 has no practical effect.
    		 
        */
    		 
        read_time= (double) head->file->scan_time() + scan_time + 2;
    		 
        if (limit < records && read_time < (double) records + scan_time + 1 )
    		 
        {
    		 
          read_time= (double) records + scan_time + 1; // Force to use index
    		 
          notnull_cond= NULL;
    		 
        }
    		 
      }
    		 
     
    		 
      possible_keys.clear_all();
    		 
     
    		 
      DBUG_PRINT("info",("Time to scan table: %g", read_time));

    Apparently, the read_time is uninitialized because head->file->scan_time() was uninitialized. records cannot be uninitialized, because we compared it earlier in this function, without MemorySanitizer complaining.

Please update affectedVersion and fixVersion as you see fit. I only tested this on 10.5.

 Comments   
Comment by Michael Widenius [ 2020-06-08 ]

I can't repeat this, despite trying a many times with a lot of different printf.
MSAN also doesn't work on my system, so I can't repeat this.

I plan to later install a container that will support MSAN, but that has to wait until all other 10.5 bugs are fixed.

Comment by Michael Widenius [ 2020-06-11 ]

This was a bug in MSAN. Marko and I created a safe workaround for this.

Pushed into bb-10.5-monty for testing, soon to be pushed into 10.5

Comment by Michael Widenius [ 2020-06-15 ]

Fix pushed into 10.5 tree

Comment by Marko Mäkelä [ 2020-07-01 ]

This also fixed MDEV-22690.

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