Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-17738

Server crashes in Item::delete_self on closing connection after unsuccessful PS

    Details

      Description

      Please also see MDEV-17741, it is likely to have the same or closely related root cause. If it is so, please make sure both are fixed at the same time

      SET SQL_MODE='STRICT_ALL_TABLES';
      PREPARE stmt FROM "CREATE TABLE ps AS SELECT 1 FROM DUAL WHERE 'foo' && 0";
      --error ER_TRUNCATED_WRONG_VALUE
      EXECUTE stmt;
       
      --source include/restart_mysqld.inc
       
      # Cleanup
      SELECT 'All done';
      

      10.2 7e75643778

      #3  <signal handler called>
      #4  0x000055d3b8bef52b in Item::delete_self (this=0x7f2c9415e8d0) at /data/src/10.2/sql/item.h:1848
      #5  0x000055d3b8be64ac in Query_arena::free_items (this=0x7f2c94006618) at /data/src/10.2/sql/sql_class.cc:3467
      #6  0x000055d3b8c5377f in Prepared_statement::~Prepared_statement (this=0x7f2c94006600, __in_chrg=<optimized out>) at /data/src/10.2/sql/sql_prepare.cc:3827
      #7  0x000055d3b8c5390e in Prepared_statement::~Prepared_statement (this=0x7f2c94006600, __in_chrg=<optimized out>) at /data/src/10.2/sql/sql_prepare.cc:3836
      #8  0x000055d3b8be6b9d in delete_statement_as_hash_key (key=0x7f2c94006600) at /data/src/10.2/sql/sql_class.cc:3608
      #9  0x000055d3b95d663b in my_hash_free_elements (hash=0x7f2c94002598) at /data/src/10.2/mysys/hash.c:129
      #10 0x000055d3b95d6755 in my_hash_reset (hash=0x7f2c94002598) at /data/src/10.2/mysys/hash.c:171
      #11 0x000055d3b8be6fe9 in Statement_map::reset (this=0x7f2c94002598) at /data/src/10.2/sql/sql_class.cc:3740
      #12 0x000055d3b8bdfd65 in THD::free_connection (this=0x7f2c94000b00) at /data/src/10.2/sql/sql_class.cc:1442
      #13 0x000055d3b8b48017 in unlink_thd (thd=0x7f2c94000b00) at /data/src/10.2/sql/mysqld.cc:2922
      #14 0x000055d3b8b48494 in one_thread_per_connection_end (thd=0x7f2c94000b00, put_in_cache=true) at /data/src/10.2/sql/mysqld.cc:3063
      #15 0x000055d3b8d77236 in do_handle_one_connection (connect=0x55d3bbca6930) at /data/src/10.2/sql/sql_connect.cc:1354
      #16 0x000055d3b8d76eda in handle_one_connection (arg=0x55d3bbca6930) at /data/src/10.2/sql/sql_connect.cc:1241
      #17 0x000055d3b919a53c in pfs_spawn_thread (arg=0x55d3bbc0a0b0) at /data/src/10.2/storage/perfschema/pfs.cc:1862
      #18 0x00007f2cacc67494 in start_thread (arg=0x7f2ca5265700) at pthread_create.c:333
      #19 0x00007f2cab04593f in clone () from /lib/x86_64-linux-gnu/libc.so.6
      

      If I replace server restart with DEALLOCATE, other strange things happen:

      SET SQL_MODE='STRICT_ALL_TABLES';
      PREPARE stmt FROM "CREATE TABLE ps AS SELECT 1 FROM DUAL WHERE 'foo' && 0";
      --error ER_TRUNCATED_WRONG_VALUE
      EXECUTE stmt;
       
      DEALLOCATE PREPARE stmt;
       
      # Cleanup
      SELECT 'All done';
      

      PREPARE stmt FROM "CREATE TABLE ps AS SELECT 1 FROM DUAL WHERE 'foo' && 0";
      Warnings:
      Warning	1292	Truncated incorrect INTEGER value: 'foo'
      EXECUTE stmt;
      ERROR 22007: Truncated incorrect INTEGER value: 'foo'
      DEALLOCATE PREPARE stmt;
      bug.t4a                                  [ fail ]
              Test ended at 2018-11-16 14:26:37
       
      CURRENT_TEST: bug.t4a
      mysqltest: At line 6: query 'DEALLOCATE PREPARE stmt' failed: 1243: Unknown prepared statement handler (stmt) given to DEALLOCATE PREPARE
      

      So, the statement gets prepared (even although with a warning), it attempts to be executed (even although with an error), but by DEALLOCATE it seems to have disappeared.

      Same test case with ASAN:

      10.2 861038f2e8

      ==11339==ERROR: AddressSanitizer: use-after-poison on address 0x62b00002c250 at pc 0x55719e64f8be bp 0x7f7ea3e09980 sp 0x7f7ea3e09978
      READ of size 8 at 0x62b00002c250 thread T5
          #0 0x55719e64f8bd in Query_arena::free_items() /data/src/10.2/sql/sql_class.cc:3464
          #1 0x55719e7531f1 in Prepared_statement::~Prepared_statement() /data/src/10.2/sql/sql_prepare.cc:3839
          #2 0x55719e753671 in Prepared_statement::~Prepared_statement() /data/src/10.2/sql/sql_prepare.cc:3848
          #3 0x55719e650db2 in delete_statement_as_hash_key /data/src/10.2/sql/sql_class.cc:3608
          #4 0x55719fcdefcd in my_hash_free_elements /data/src/10.2/mysys/hash.c:129
          #5 0x55719fcdf2a7 in my_hash_reset /data/src/10.2/mysys/hash.c:171
          #6 0x55719e6515e7 in Statement_map::reset() /data/src/10.2/sql/sql_class.cc:3740
          #7 0x55719e63ef6f in THD::free_connection() /data/src/10.2/sql/sql_class.cc:1442
          #8 0x55719e4ef6ce in unlink_thd(THD*) /data/src/10.2/sql/mysqld.cc:2922
          #9 0x55719e4effa2 in one_thread_per_connection_end(THD*, bool) /data/src/10.2/sql/mysqld.cc:3063
          #10 0x55719ea2d6fa in do_handle_one_connection(CONNECT*) /data/src/10.2/sql/sql_connect.cc:1354
          #11 0x55719ea2ceed in handle_one_connection /data/src/10.2/sql/sql_connect.cc:1241
          #12 0x55719f447a63 in pfs_spawn_thread /data/src/10.2/storage/perfschema/pfs.cc:1862
          #13 0x7f7eb0070493 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x7493)
          #14 0x7f7eae67193e in __clone (/lib/x86_64-linux-gnu/libc.so.6+0xe893e)
       
      0x62b00002c250 is located 8272 bytes inside of 24716-byte region [0x62b00002a200,0x62b00003028c)
      allocated by thread T5 here:
          #0 0x7f7eb02da73f in malloc (/usr/lib/x86_64-linux-gnu/libasan.so.1+0x5473f)
          #1 0x55719fd6ac4b in sf_malloc /data/src/10.2/mysys/safemalloc.c:118
          #2 0x55719fd39ea2 in my_malloc /data/src/10.2/mysys/my_malloc.c:101
          #3 0x55719fd19c9a in init_alloc_root /data/src/10.2/mysys/my_alloc.c:78
          #4 0x55719e9aac24 in init_sql_alloc(st_mem_root*, unsigned int, unsigned int, unsigned long) /data/src/10.2/sql/thr_malloc.cc:64
          #5 0x55719e7529e9 in Prepared_statement::Prepared_statement(THD*) /data/src/10.2/sql/sql_prepare.cc:3768
          #6 0x55719e74d8a4 in mysql_sql_stmt_prepare(THD*) /data/src/10.2/sql/sql_prepare.cc:2805
          #7 0x55719e6f49a3 in mysql_execute_command(THD*) /data/src/10.2/sql/sql_parse.cc:3496
          #8 0x55719e710977 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /data/src/10.2/sql/sql_parse.cc:8013
          #9 0x55719e6eb361 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /data/src/10.2/sql/sql_parse.cc:1824
          #10 0x55719e6e8405 in do_command(THD*) /data/src/10.2/sql/sql_parse.cc:1378
          #11 0x55719ea2d4d8 in do_handle_one_connection(CONNECT*) /data/src/10.2/sql/sql_connect.cc:1335
          #12 0x55719ea2ceed in handle_one_connection /data/src/10.2/sql/sql_connect.cc:1241
          #13 0x55719f447a63 in pfs_spawn_thread /data/src/10.2/storage/perfschema/pfs.cc:1862
          #14 0x7f7eb0070493 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x7493)
       
      Thread T5 created by T0 here:
          #0 0x7f7eb02a9bba in pthread_create (/usr/lib/x86_64-linux-gnu/libasan.so.1+0x23bba)
          #1 0x55719f44802b in spawn_thread_v1 /data/src/10.2/storage/perfschema/pfs.cc:1912
          #2 0x55719e4e537e in inline_mysql_thread_create /data/src/10.2/include/mysql/psi/mysql_thread.h:1239
          #3 0x55719e4fa31b in create_thread_to_handle_connection(CONNECT*) /data/src/10.2/sql/mysqld.cc:6466
          #4 0x55719e4faa20 in create_new_thread /data/src/10.2/sql/mysqld.cc:6536
          #5 0x55719e4fba37 in handle_connections_sockets() /data/src/10.2/sql/mysqld.cc:6811
          #6 0x55719e4f9870 in mysqld_main(int, char**) /data/src/10.2/sql/mysqld.cc:6085
          #7 0x55719e4e371f in main /data/src/10.2/sql/main.cc:25
          #8 0x7f7eae5a92b0 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x202b0)
       
      SUMMARY: AddressSanitizer: use-after-poison /data/src/10.2/sql/sql_class.cc:3464 Query_arena::free_items()
      Shadow bytes around the buggy address:
        0x0c567fffd7f0: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
        0x0c567fffd800: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
        0x0c567fffd810: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
        0x0c567fffd820: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
        0x0c567fffd830: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
      =>0x0c567fffd840: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7[f7]f7 f7 f7 f7 f7
        0x0c567fffd850: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
        0x0c567fffd860: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
        0x0c567fffd870: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
        0x0c567fffd880: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
        0x0c567fffd890: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
      Shadow byte legend (one shadow byte represents 8 application bytes):
        Addressable:           00
        Partially addressable: 01 02 03 04 05 06 07 
        Heap left redzone:       fa
        Heap right redzone:      fb
        Freed heap region:       fd
        Stack left redzone:      f1
        Stack mid redzone:       f2
        Stack right redzone:     f3
        Stack partial redzone:   f4
        Stack after return:      f5
        Stack use after scope:   f8
        Global redzone:          f9
        Global init order:       f6
        Poisoned by user:        f7
        Contiguous container OOB:fc
        ASan internal:           fe
      ==11339==ABORTING
      

      On some reason, the crash is only reproducible on 10.2.

        Attachments

          Issue Links

            Activity

              People

              • Assignee:
                bar Alexander Barkov
                Reporter:
                elenst Elena Stepanova
              • Votes:
                0 Vote for this issue
                Watchers:
                1 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: