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

Crash on DROP DATABASE due to out-of-bounds result from InnoDB SUBSTR() function

Details

    Description

      Workflow
      1. Bootstrap and start DB server  MariaDB 10.5.14
           origin/10.5 2776635cb98d35867447d375fdc04a44ef11a697 2021-12-16
           Maybe problematic: innodb_undo_tablespaces=3 , innodb_undo_log_truncate=ON
      2. Create some initial data and run some DDL/DML in one session.
           Maybe problematic:  TRUNCATE TABLE , ALTER TABLE ADD/DROP FOREIGN KEY
      3. Dump schemas and table data
      4. Send SIGTERM to DB server and wait till its finished
      5. Restart with 10.7.2
          origin/10.7 92a4e76a2c1c15fb44dc0cb05e06d5aa408a8e35 2021-12-14
      6. Run the upgrade script   bin/mysql_upgrade
           # 2021-12-20T18:50:38 [2705670] | [rr 2761342 49673][rr 2761342 49677]==2761342==ERROR: AddressSanitizer: heap-buffer-overflow on address 0x602000009bb7 at pc 0x7e864e7cbd00 bp 0x595748e692a0 sp 0x595748e68a48
      # 2021-12-20T18:50:38 [2705670] | [rr 2761342 49680][rr 2761342 49682]READ of size 19 at 0x602000009bb7 thread T16
      # 2021-12-20T18:50:38 [2705670] | [rr 2761342 55570]    #0 0x7e864e7cbcff  (/lib/x86_64-linux-gnu/libasan.so.5+0xdacff)
      # 2021-12-20T18:50:38 [2705670] | [rr 2761342 55604]    #1 0x5649c7645c4d in cmp_data(unsigned long, unsigned long, unsigned char const*, unsigned long, unsigned char const*, unsigned long) /data/Server/10.7A/storage/innobase/rem/rem0cmp.cc:322
      # 2021-12-20T18:50:38 [2705670] | [rr 2761342 55608]    #2 0x5649c764137f in cmp_data_data(unsigned long, unsigned long, unsigned char const*, unsigned long, unsigned char const*, unsigned long) /data/Server/10.7A/storage/innobase/rem/rem0cmp.cc:378
      # 2021-12-20T18:50:38 [2705670] | [rr 2761342 55620]    #3 0x5649c7a3872e in cmp_dfield_dfield /data/Server/10.7A/storage/innobase/include/rem0cmp.ic:49
      # 2021-12-20T18:50:38 [2705670] | [rr 2761342 55622]    #4 0x5649c7a39770 in eval_cmp(func_node_t*) /data/Server/10.7A/storage/innobase/eval/eval0eval.cc:183
      # 2021-12-20T18:50:38 [2705670] | [rr 2761342 55624]    #5 0x5649c7a3aa0a in eval_func(func_node_t*) /data/Server/10.7A/storage/innobase/eval/eval0eval.cc:595
      # 2021-12-20T18:50:38 [2705670] | [rr 2761342 55634]    #6 0x5649c7a3b694 in eval_exp /data/Server/10.7A/storage/innobase/include/eval0eval.ic:117
      # 2021-12-20T18:50:38 [2705670] | [rr 2761342 55636]    #7 0x5649c7a3bb68 in if_step(que_thr_t*) /data/Server/10.7A/storage/innobase/eval/eval0proc.cc:48
      # 2021-12-20T18:50:38 [2705670] | [rr 2761342 55656]    #8 0x5649c7631bc1 in que_thr_step /data/Server/10.7A/storage/innobase/que/que0que.cc:611
      # 2021-12-20T18:50:38 [2705670] | [rr 2761342 55658]    #9 0x5649c7632328 in que_run_threads_low /data/Server/10.7A/storage/innobase/que/que0que.cc:709
      # 2021-12-20T18:50:38 [2705670] | [rr 2761342 55660]    #10 0x5649c76324ca in que_run_threads(que_thr_t*) /data/Server/10.7A/storage/innobase/que/que0que.cc:729
      # 2021-12-20T18:50:38 [2705670] | [rr 2761342 55662]    #11 0x5649c76327f0 in que_eval_sql(pars_info_t*, char const*, trx_t*) /data/Server/10.7A/storage/innobase/que/que0que.cc:768
      # 2021-12-20T18:50:38 [2705670] | [rr 2761342 55702]    #12 0x5649c7357604 in innodb_drop_database /data/Server/10.7A/storage/innobase/handler/ha_innodb.cc:1504
      # 2021-12-20T18:50:38 [2705670] | [rr 2761342 55729]    #13 0x5649c6ad849e in dropdb_handlerton /data/Server/10.7A/sql/handler.cc:826
      # 2021-12-20T18:50:38 [2705670] | [rr 2761342 55741]    #14 0x5649c6345e45 in plugin_foreach_with_mask(THD*, char (*)(THD*, st_plugin_int**, void*), int, unsigned int, void*) /data/Server/10.7A/sql/sql_plugin.cc:2509
      # 2021-12-20T18:50:38 [2705670] | [rr 2761342 55743]    #15 0x5649c6ad84d7 in ha_drop_database(char const*) /data/Server/10.7A/sql/handler.cc:833
      # 2021-12-20T18:50:38 [2705670] | [rr 2761342 55747]    #16 0x5649c61e7ff8 in drop_database_objects(THD*, st_mysql_const_lex_string const*, st_mysql_const_lex_string const*, bool) /data/Server/10.7A/sql/sql_db.cc:987
      # 2021-12-20T18:50:38 [2705670] | [rr 2761342 55749]    #17 0x5649c61e8c27 in mysql_rm_db_internal /data/Server/10.7A/sql/sql_db.cc:1132
      # 2021-12-20T18:50:38 [2705670] | [rr 2761342 55751]    #18 0x5649c61e9f5d in mysql_rm_db(THD*, st_mysql_const_lex_string const*, bool) /data/Server/10.7A/sql/sql_db.cc:1307
      # 2021-12-20T18:50:38 [2705670] | [rr 2761342 55765]    #19 0x5649c62deceb in mysql_execute_command(THD*, bool) /data/Server/10.7A/sql/sql_parse.cc:5179
      # 2021-12-20T18:50:38 [2705670] | [rr 2761342 55775]    #20 0x5649c636f5d3 in Prepared_statement::execute(String*, bool) /data/Server/10.7A/sql/sql_prepare.cc:5210
      # 2021-12-20T18:50:38 [2705670] | [rr 2761342 55785]    #21 0x5649c636ab72 in Prepared_statement::execute_loop(String*, bool, unsigned char*, unsigned char*) /data/Server/10.7A/sql/sql_prepare.cc:4633
      # 2021-12-20T18:50:38 [2705670] | [rr 2761342 55787]    #22 0x5649c6364f28 in mysql_sql_stmt_execute(THD*) /data/Server/10.7A/sql/sql_prepare.cc:3684
      # 2021-12-20T18:50:38 [2705670] | [rr 2761342 55789]    #23 0x5649c62d5d38 in mysql_execute_command(THD*, bool) /data/Server/10.7A/sql/sql_parse.cc:3960
      # 2021-12-20T18:50:38 [2705670] | [rr 2761342 55791]    #24 0x5649c62f0ffa in mysql_parse(THD*, char*, unsigned int, Parser_state*) /data/Server/10.7A/sql/sql_parse.cc:8028
      # 2021-12-20T18:50:38 [2705670] | [rr 2761342 55793]    #25 0x5649c62c92bf in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool) /data/Server/10.7A/sql/sql_parse.cc:1894
      # 2021-12-20T18:50:38 [2705670] | [rr 2761342 55795]    #26 0x5649c62c6697 in do_command(THD*, bool) /data/Server/10.7A/sql/sql_parse.cc:1402
      # 2021-12-20T18:50:38 [2705670] | [rr 2761342 55801]    #27 0x5649c66f9577 in do_handle_one_connection(CONNECT*, bool) /data/Server/10.7A/sql/sql_connect.cc:1418
      # 2021-12-20T18:50:38 [2705670] | [rr 2761342 55803]    #28 0x5649c66f8e03 in handle_one_connection /data/Server/10.7A/sql/sql_connect.cc:1312
      # 2021-12-20T18:50:38 [2705670] | [rr 2761342 55811]    #29 0x7f6f2f0b8608 in start_thread /build/glibc-eX1tMB/glibc-2.31/nptl/pthread_create.c:477
      # 2021-12-20T18:50:38 [2705670] | [rr 2761342 55813]    #30 0x725523e1f292 in __clone (/lib/x86_64-linux-gnu/libc.so.6+0x122292)
      ...
      # 2021-12-20T18:50:38 [2705670] | Query (0x62900004b2d0): DROP DATABASE IF EXISTS performance_schema
      # 2021-12-20T18:50:38 [2705670] | [rr 2761342 73077]
      # 2021-12-20T18:50:38 [2705670] | Connection ID (thread ID): 13
      # 2021-12-20T18:50:38 [2705670] | [rr 2761342 73079]Status: NOT_KILLED
       
      pluto:/data/results/1640025904/TBR-1315/rqg.log
           Protocol of the RQG run
      pluto:/data/results/1640025904/TBR-1315/dev/shm/rqg/1640025904/154/1/data_orig
           Copy of the data directory made after the SIGTERM and before the restart with 10.7.
      cd /data/results/1640025904/TBR-1315/dev/shm/rqg/1640025904/154/1/rr/
      _RR_TRACE_DIR="." rr replay --mark-stdio mysqld-1 # Fate of the DB server (10.5) till arrival of SIGTERM
      _RR_TRACE_DIR="." rr replay --mark-stdio mysqld-2 # Fate of the DB server (10.7) till ASAN failure
       
      RQG
      ===
      # git clone https://github.com/mleich1/rqg --branch experimental RQG
      #
      # GIT_SHOW: HEAD -> experimental, origin/experimental 62e549d1b378ee71215e439c95eb5b1519434137 2021-12-20T18:19:03+01:00
      # rqg.pl  : Version 4.0.4 (2021-12)
      #
      # $RQG_HOME/rqg.pl \
      # --gendata=conf/mariadb/fk_truncate.zz \
      # --grammar=conf/mariadb/fk_truncate.yy \
      # --mysqld=--loose-innodb_lock_schedule_algorithm=fcfs \
      # --mysqld=--loose-idle_write_transaction_timeout=0 \
      # --mysqld=--loose-idle_transaction_timeout=0 \
      # --mysqld=--loose-idle_readonly_transaction_timeout=0 \
      # --mysqld=--connect_timeout=60 \
      # --mysqld=--interactive_timeout=28800 \
      # --mysqld=--slave_net_timeout=60 \
      # --mysqld=--net_read_timeout=30 \
      # --mysqld=--net_write_timeout=60 \
      # --mysqld=--loose-table_lock_wait_timeout=50 \
      # --mysqld=--wait_timeout=28800 \
      # --mysqld=--lock-wait-timeout=86400 \
      # --mysqld=--innodb-lock-wait-timeout=50 \
      # --no-mask \
      # --queries=10000000 \
      # --seed=random \
      # --reporters=Backtrace \
      # --reporters=ErrorLog \
      # --reporters=Deadlock1 \
      # --reporters=Upgrade1 \
      # --validators=None \
      # --mysqld=--log_output=none \
      # --mysqld=--log_bin_trust_function_creators=1 \
      # --mysqld=--loose-debug_assert_on_not_freed_memory=0 \
      # --engine=InnoDB \
      # --restart_timeout=240 \
      # --upgrade-test \
      # --mysqld=--plugin-load-add=file_key_management.so \
      # --mysqld=--loose-file-key-management-filename=$RQG_HOME/conf/mariadb/encryption_keys.txt \
      # --duration=120 \
      # --mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 \
      # --mysqld=--loose-innodb_read_only_compressed=OFF \
      # --mysqld=--loose-innodb-sync-debug \
      # --mysqld=--innodb_stats_persistent=off \
      # --mysqld=--innodb_adaptive_hash_index=off \
      # --mysqld=--log-bin \
      # --mysqld=--sync-binlog=1 \
      # --mysqld=--loose-innodb_evict_tables_on_commit_debug=off \
      # --mysqld=--loose-max-statement-time=30 \
      # --threads=1 \
      # --mysqld=--innodb-use-native-aio=0 \
      # --mysqld=--loose-gdb \
      # --mysqld=--loose-debug-gdb \
      # --rr=Extended \
      # --rr_options=--chaos --wait \
      # --mysqld=--innodb_undo_tablespaces=3 \
      # --mysqld=--innodb_undo_log_truncate=ON \
      # --vardir_type=fast \
      # --mysqld=--innodb_page_size=4K \
      # --mysqld=--innodb-buffer-pool-size=256M \
      # --no_mask \
      # --mtr-build-thread=883 \
      # --batch \
      # <certain local settings>
      
      

      Attachments

        Issue Links

          Activity

            mleich, thank you. This is due to a bug in the implementation of SUBSTR() in the internal SQL interpreter of InnoDB. In MDEV-25691 I rewrote ha_innobase::drop_database() (the hopefully redundant DROP DATABASE garbage collector that would drop any InnoDB tables for which .frm files did not exist) to directly invoke the internal SQL interpreter. The relevant expression is:

            IF TO_BINARY(SUBSTR(fk, 0, LENGTH(:db)))<>TO_BINARY(:db)
            

            In the rr replay trace, fk has the value test/fk (length: 7 bytes) and :db has the value performance_schema (length: 19 bytes), from the DROP DATABASE statement. The implementation of SUBSTR appears to return a pointer to the string, but wrongly extend the length to 19 bytes. An attempt to read these 19 bytes would then make ASAN unhappy.

            I reproduced the crash in an ASAN build with the following:

            --source include/have_innodb.inc
            CREATE TABLE t1(a INT PRIMARY KEY) ENGINE=InnoDB;
            CREATE TABLE t2(a INT PRIMARY KEY REFERENCES t1(a)) ENGINE=InnoDB;
            CREATE DATABASE somewhat_longer_name_to_cause_trouble;
            DROP DATABASE somewhat_longer_name_to_cause_trouble;
            DROP TABLE t2,t1;
            

            I fixed this test case by fixing the SUBSTR implementation (eval_substr()) so that it will trim the length so that no data past the original end of the string will be returned.

            marko Marko Mäkelä added a comment - mleich , thank you. This is due to a bug in the implementation of SUBSTR() in the internal SQL interpreter of InnoDB. In MDEV-25691 I rewrote ha_innobase::drop_database() (the hopefully redundant DROP DATABASE garbage collector that would drop any InnoDB tables for which .frm files did not exist) to directly invoke the internal SQL interpreter. The relevant expression is: IF TO_BINARY(SUBSTR(fk, 0, LENGTH(:db)))<>TO_BINARY(:db) In the rr replay trace, fk has the value test/fk (length: 7 bytes) and :db has the value performance_schema (length: 19 bytes), from the DROP DATABASE statement. The implementation of SUBSTR appears to return a pointer to the string, but wrongly extend the length to 19 bytes. An attempt to read these 19 bytes would then make ASAN unhappy. I reproduced the crash in an ASAN build with the following: --source include/have_innodb.inc CREATE TABLE t1(a INT PRIMARY KEY ) ENGINE=InnoDB; CREATE TABLE t2(a INT PRIMARY KEY REFERENCES t1(a)) ENGINE=InnoDB; CREATE DATABASE somewhat_longer_name_to_cause_trouble; DROP DATABASE somewhat_longer_name_to_cause_trouble; DROP TABLE t2,t1; I fixed this test case by fixing the SUBSTR implementation ( eval_substr() ) so that it will trim the length so that no data past the original end of the string will be returned.

            People

              marko Marko Mäkelä
              mleich Matthias Leich
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

                  Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.