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

Server without encryption configs crashes if selecting from an implicitly encrypted table

Details

    Description

      In my.cnf:

      plugin-load-add=file_key_management.so
      file-key-management-filename = /var/lib/mysql/keys.txt
      innodb-encrypt-tables

      Create table:

      create table t5 (
          -> `intcol1` int(32) DEFAULT NULL,
          ->   `intcol2` int(32) DEFAULT NULL,
          ->   `charcol1` varchar(128) DEFAULT NULL,
          ->   `charcol2` varchar(128) DEFAULT NULL,
          ->   `charcol3` varchar(128) DEFAULT NULL
          -> ) ENGINE=InnoDB DEFAULT CHARSET=latin1;

      Insert some data:

      insert into t5 values (1,2,'maria','db','encryption');

      Data is encrypted (e.g., sample from xxd output):

      00044d0: 58a9 8252 4e9e 94d8 cd28 0755 3645 7eed  X..RN....(.U6E~.
      00044e0: 455c 054c 22b4 baa4 f507 8bd4 0e20 e509  E\.L"........ ..
      00044f0: 1d16 a362 dba4 ae16 7243 a465 15d2 4713  ...b....rC.e..G.
      0004500: f9ce 5426 5dcb fe4c 91ff 9985 69b9 7226  ..T&]..L....i.r&
      0004510: c72d 4a4e fa4e 039f c7d5 f296 9035 b3bc  .-JN.N.......5..

      Configs removed from my.cnf:

      #plugin-load-add=file_key_management.so
      #file-key-management-filename = /var/lib/mysql/keys.txt
      #innodb-encrypt-tables

      Server restarted:

      service mysql restart
      Restarting mysql (via systemctl):                          [  OK  ]

      Table created explicitly with encryption via alter statement gives appropriate error message:

      select * from mysqlslap.t1\G
      ERROR 1296 (HY000): Got error 192 'Table encrypted but decryption failed. This could be because correct encryption management plugin is not loaded, used encryption key is not available or encryption method does not match.' from InnoDB

      That table's alter and definition are as follows:

      alter table mysqlslap.t1 encrypted='yes' `encryption_key_id`=1;
      ...
      CREATE TABLE `t1` (
        `intcol1` int(32) DEFAULT NULL,
        `intcol2` int(32) DEFAULT NULL,
        `charcol1` varchar(128) DEFAULT NULL,
        `charcol2` varchar(128) DEFAULT NULL,
        `charcol3` varchar(128) DEFAULT NULL
      ) ENGINE=InnoDB DEFAULT CHARSET=latin1 `encrypted`='yes' `encryption_key_id`=1

      Table encrypted implicitly via innodb-encrypt-tables crashes the server:

      select * from mysqlslap.t5\G
      ERROR 2013 (HY000): Lost connection to MySQL server during query

      From the error log:

      2016-02-13 21:28:47 7fc4d5e96b00  InnoDB: Dump of the ibuf bitmap page:
      2016-02-13 21:28:47 7fc4d5e96b00 InnoDB: Page dump in ascii and hex (16384 bytes):
       len 16384; hex 4324d13a000000010000000000000000000000000caec7a90005...
      InnoDB: End of page dump
      2016-02-13 21:28:47 7fc4d5e96b00 InnoDB: uncompressed page, stored checksum i
      n field1 1676373080, calculated checksums for field1: crc32 607276543, innodb
       237301233, none 3735928559, stored checksum in field2 4195245356, calculated
       checksums for field2: crc32 607276543, innodb 4195245356, none 3735928559, p
      age LSN 0 212786341, low 4 bytes of LSN at page end 212786341, page number (i
      f stored to page already) 3, space id (if created with >= MySQL-4.1.1 and sto
      red already) 2039
      InnoDB: page type 17855 meaning INDEX
      InnoDB: Page may be an index page where index id is 13434390939941133065
      InnoDB: Error: corruption in the tablespace. Bitmap shows insert
      InnoDB: buffer records to page n:o 3 though the page
      InnoDB: type is 17855, which is not an index leaf page!
      InnoDB: We try to resolve the problem by skipping the insert buffer
      InnoDB: merge for this page. Please run CHECK TABLE on your tables
      InnoDB: to determine if they are corrupt after this.
      InnoDB: Please submit a detailed bug report to http://bugs.mysql.com
       
      InnoDB: Next record offset is nonsensical 57565 in record at offset 101
      InnoDB: rec address 0x7fc4bedac065, space id 2039, page 3
      2016-02-13 21:28:47 7fc4d5e96b00 InnoDB: Page dump in ascii and hex (16384 bytes):
       len 16384; hex 63eb6c5800000003ffffff...
      InnoDB: End of page dump
      2016-02-13 21:28:47 7fc4d5e96b00 InnoDB: uncompressed page, stored checksum in field1 1676373080, calculated checksums for field1: crc32 607276543, innodb 237301233, none 3735928559, stored checksum in field2 4195245356, calculated checksums for field2: crc32 607276543, innodb 4195245356, none 3735928559, page LSN 0 212786341, low 4 bytes of LSN at page end 212786341, page number (if stored to page already) 3, space id (if created with >= MySQL-4.1.1 and stored already) 2039
      InnoDB: page type 17855 meaning INDEX
      InnoDB: Page may be an index page where index id is 13434390939941133065
      2016-02-13 21:28:47 7fc4d5e96b00  InnoDB: Assertion failure in thread 140483379161856 in file page0page.ic line 780
      InnoDB: We intentionally generate a memory trap.
      InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
      InnoDB: If you get repeated assertion failures or crashes, even
      InnoDB: immediately after the mysqld startup, there may be
      InnoDB: corruption in the InnoDB tablespace. Please refer to
      InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
      InnoDB: about forcing recovery.
      160213 21:28:47 [ERROR] mysqld got signal 6 ;
      This could be because you hit a bug. It is also possible that this binary
      or one of the libraries it was linked against is corrupt, improperly built,
      or misconfigured. This error can also be caused by malfunctioning hardware.
       
      To report this bug, see http://kb.askmonty.org/en/reporting-bugs
       
      We will try our best to scrape up some info that will hopefully help
      diagnose the problem, but since we have already crashed,
      something is definitely wrong and this may fail.
       
      Server version: 10.1.11-MariaDB-log
      key_buffer_size=134217728
      read_buffer_size=131072
      max_used_connections=1
      max_threads=153
      thread_count=1
      It is possible that mysqld could use up to
      key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 467110 K  bytes of memory
      Hope that's ok; if not, decrease some variables in the equation.
       
      Thread pointer: 0x0x7fc4b6a71008
      Attempting backtrace. You can use the following information to find out
      where mysqld died. If you see no messages after this, something went
      terribly wrong...
      stack_bottom = 0x7fc4d5e96130 thread_stack 0x48400
      /usr/sbin/mysqld(my_print_stacktrace+0x2e)[0x7fc4d69e0cce]
      /usr/sbin/mysqld(handle_fatal_signal+0x38d)[0x7fc4d650e49d]
      /lib64/libpthread.so.0(+0xf100)[0x7fc4d5b2e100]
      /lib64/libc.so.6(gsignal+0x37)[0x7fc4d3c865f7]
      mysys/stacktrace.c:247(my_print_stacktrace)[0x7fc4d3c87ce8]
      include/page0page.ic:780(page_rec_get_next_low)[0x7fc4d67b6c89]
      row/row0sel.cc:4189(row_search_for_mysql(unsigned char*, unsigned long, row_prebuilt_t*, unsigned long, unsigned long))[0x7fc4d6751f10]
      handler/ha_innodb.cc:9603(ha_innobase::index_read(unsigned char*, unsigned char const*, unsigned int, ha_rkey_function))[0x7fc4d668c9da]
      handler/ha_innodb.cc:10033(ha_innobase::index_first(unsigned char*))[0x7fc4d66721e7]
      handler/ha_innodb.cc:10126(ha_innobase::rnd_next(unsigned char*))[0x7fc4d668e8ca]
      sql/handler.cc:2577(handler::ha_rnd_next(unsigned char*))[0x7fc4d6512d37]
      sql/records.cc:470(rr_sequential(READ_RECORD*))[0x7fc4d6615580]
      /usr/sbin/mysqld(_Z10sub_selectP4JOINP13st_join_tableb+0x169)[0x7fc4d63c7eb9]
      sql/sql_select.cc:18279(sub_select(JOIN*, st_join_table*, bool))[0x7fc4d63d5b0d]
      sql/sql_select.cc:3228(JOIN::exec_inner())[0x7fc4d63e585c]
      sql/sql_select.cc:2519(JOIN::exec())[0x7fc4d63e7854]
      sql/sql_select.cc:3453(mysql_select(THD*, Item***, TABLE_LIST*, unsigned int, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, unsigned long long, select_result*, st_select_lex_unit*, st_select_lex*))[0x7fc4d63e3ef2]
      sql/sql_select.cc:384(handle_select(THD*, LEX*, select_result*, unsigned long))[0x7fc4d63e49d5]
      /usr/sbin/mysqld(+0x428521)[0x7fc4d6387521]
      sql/sql_parse.cc:5904(execute_sqlcom_select)[0x7fc4d63930f1]
      sql/sql_parse.cc:7304(mysql_parse(THD*, char*, unsigned int, Parser_state*))[0x7fc4d639686e]
      sql/sql_parse.cc:1488(dispatch_command(enum_server_command, THD*, char*, unsigned int))[0x7fc4d6399d2b]
      sql/sql_parse.cc:1111(do_command(THD*))[0x7fc4d639a5a9]
      sql/sql_connect.cc:1349(do_handle_one_connection(THD*))[0x7fc4d645d78a]
      sql/sql_connect.cc:1263(handle_one_connection)[0x7fc4d645d960]
      /lib64/libpthread.so.0(+0x7dc5)[0x7fc4d5b26dc5]
      /lib64/libc.so.6(clone+0x6d)[0x7fc4d3d4721d]
       
      Trying to get some variables.
      Some pointers may be invalid and cause the dump to abort.
      Query (0x7fc4b6af6020): select * from mysqlslap.t5
      Connection ID (thread ID): 3
      Status: NOT_KILLED
      Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=on,exists_to_in=on
       
      The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
      information that should help you find out what is causing the crash.

      Note it is recoverable in this case by changing back the configs in the my.cnf:

      plugin-load-add=file_key_management.so
      file-key-management-filename = /var/lib/mysql/keys.txt
      innodb-encrypt-tables

      Restarting the server:

      service mysql restart
      Restarting mysql (via systemctl):                          [  OK  ]

      Selecting from the encrypted table:

      MariaDB [(none)]> select * from mysqlslap.t5 limit 1\G
      *************************** 1. row ***************************
       intcol1: 1
       intcol2: 2
      charcol1: maria
      charcol2: db
      charcol3: encryption

      Attachments

        Activity

          valerie@opengroupware.ch, thanks for the report.

          2016-02-15 17:50:49 7f51a184cb00  InnoDB: Assertion failure in thread 139988578913024 in file btr0cur.cc line 1023
          InnoDB: Failing assertion: index->id == btr_page_get_index_id(page)

          Stack trace from 10.1 commit d80b8442a68093106e00a9a38b7b2c593002a72c

          #5  0x00007f93a295c538 in abort () from /lib64/libc.so.6
          #6  0x00005651659c77e7 in ibuf_merge_or_delete_for_page (block=0x7f93871dfe80, space=4, page_no=3, zip_size=0, update_ibuf_bitmap=1) at /src/1
          0.1/storage/xtradb/ibuf/ibuf0ibuf.cc:4776
          #7  0x0000565165b6f617 in buf_page_io_complete (bpage=0x7f93871dfe80) at /src/10.1/storage/xtradb/buf/buf0buf.cc:4840
          #8  0x0000565165b8d35b in buf_read_page_low (err=0x7f93a4c0302c, sync=true, mode=132, space=4, zip_size=0, unzip=0, tablespace_version=7, offs
          et=3, trx=0x0, rbpage=0x7f93a4c030a8) at /src/10.1/storage/xtradb/buf/buf0rea.cc:262
          #9  0x0000565165b8d7dd in buf_read_page (space=4, zip_size=0, offset=3, trx=0x0, bpage=0x7f93a4c030a8) at /src/10.1/storage/xtradb/buf/buf0rea
          .cc:474
          #10 0x0000565165b6b019 in buf_page_get_gen (space=4, zip_size=0, offset=3, rw_latch=3, guess=0x0, mode=10, file=0x56516600b8d0 "/src/10.1/storage/xtradb/include/btr0pcur.ic", line=522, mtr=0x7f93a4c03a00, err=0x7f93a4c03184) at /src/10.1/storage/xtradb/buf/buf0buf.cc:2942
          #11 0x0000565165b3f2e3 in btr_cur_open_at_index_side_func (from_left=true, index=0x7f93a168a378, latch_mode=1, cursor=0x7f93a16990f0, level=0, file=0x56516600b8d0 "/src/10.1/storage/xtradb/include/btr0pcur.ic", line=522, mtr=0x7f93a4c03a00) at /src/10.1/storage/xtradb/btr/btr0cur.cc:990
          #12 0x0000565165aaa945 in btr_pcur_open_at_index_side (from_left=true, index=0x7f93a168a378, latch_mode=1, pcur=0x7f93a16990f0, init_pcur=false, level=0, mtr=0x7f93a4c03a00) at /src/10.1/storage/xtradb/include/btr0pcur.ic:522
          #13 0x0000565165ab27e9 in row_search_for_mysql (buf=0x7f937f229e88 "\377", mode=1, prebuilt=0x7f93a1699078, match_mode=0, direction=0) at /src/10.1/storage/xtradb/row/row0sel.cc:4187
          #14 0x0000565165979add in ha_innobase::index_read (this=0x7f93a165c888, buf=0x7f937f229e88 "\377", key_ptr=0x0, key_len=0, find_flag=HA_READ_AFTER_KEY) at /src/10.1/storage/xtradb/handler/ha_innodb.cc:9603
          #15 0x000056516597ab42 in ha_innobase::index_first (this=0x7f93a165c888, buf=0x7f937f229e88 "\377") at /src/10.1/storage/xtradb/handler/ha_innodb.cc:10028
          #16 0x000056516597ad1a in ha_innobase::rnd_next (this=0x7f93a165c888, buf=0x7f937f229e88 "\377") at /src/10.1/storage/xtradb/handler/ha_innodb.cc:10123
          #17 0x00005651657be329 in handler::ha_rnd_next (this=0x7f93a165c888, buf=0x7f937f229e88 "\377") at /src/10.1/sql/handler.cc:2577
          #18 0x00005651658fa3b5 in rr_sequential (info=0x7f93a16340a8) at /src/10.1/sql/records.cc:470
          #19 0x00005651655e921c in join_init_read_record (tab=0x7f93a1633fe8) at /src/10.1/sql/sql_select.cc:19182
          #20 0x00005651655e7196 in sub_select (join=0x7f93a1632a40, join_tab=0x7f93a1633fe8, end_of_records=false) at /src/10.1/sql/sql_select.cc:18278
          #21 0x00005651655e6a6a in do_select (join=0x7f93a1632a40, fields=0x7f937f263520, table=0x0, procedure=0x0) at /src/10.1/sql/sql_select.cc:17936
          #22 0x00005651655c1a8d in JOIN::exec_inner (this=0x7f93a1632a40) at /src/10.1/sql/sql_select.cc:3228
          #23 0x00005651655bed31 in JOIN::exec (this=0x7f93a1632a40) at /src/10.1/sql/sql_select.cc:2518
          #24 0x00005651655c22e4 in mysql_select (thd=0x7f937f25f2f0, rref_pointer_array=0x7f937f263680, tables=0x7f93a1632358, wild_num=1, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2147748608, result=0x7f93a1632a20, unit=0x7f937f262d08, select_lex=0x7f937f263408) at /src/10.1/sql/sql_select.cc:3451
          #25 0x00005651655b7d89 in handle_select (thd=0x7f937f25f2f0, lex=0x7f937f262c40, result=0x7f93a1632a20, setup_tables_done_option=0) at /src/10.1/sql/sql_select.cc:384
          #26 0x0000565165588133 in execute_sqlcom_select (thd=0x7f937f25f2f0, all_tables=0x7f93a1632358) at /src/10.1/sql/sql_parse.cc:5903
          #27 0x000056516557e20d in mysql_execute_command (thd=0x7f937f25f2f0) at /src/10.1/sql/sql_parse.cc:2962
          #28 0x000056516558b77a in mysql_parse (thd=0x7f937f25f2f0, rawbuf=0x7f93a1632188 "select * from t5", length=16, parser_state=0x7f93a4c05630) at /src/10.1/sql/sql_parse.cc:7303
          #29 0x000056516557a474 in dispatch_command (command=COM_QUERY, thd=0x7f937f25f2f0, packet=0x7f937f27bab1 "", packet_length=16) at /src/10.1/sql/sql_parse.cc:1488
          #30 0x00005651655791a6 in do_command (thd=0x7f937f25f2f0) at /src/10.1/sql/sql_parse.cc:1109
          #31 0x00005651656ae798 in do_handle_one_connection (thd_arg=0x7f937f25f2f0) at /src/10.1/sql/sql_connect.cc:1349
          #32 0x00005651656ae4fc in handle_one_connection (arg=0x7f937f25f2f0) at /src/10.1/sql/sql_connect.cc:1261
          #33 0x00007f93a489d0a4 in start_thread () from /lib64/libpthread.so.0
          #34 0x00007f93a2a0b04d in clone () from /lib64/libc.so.6

          elenst Elena Stepanova added a comment - valerie@opengroupware.ch , thanks for the report. 2016-02-15 17:50:49 7f51a184cb00 InnoDB: Assertion failure in thread 139988578913024 in file btr0cur.cc line 1023 InnoDB: Failing assertion: index->id == btr_page_get_index_id(page) Stack trace from 10.1 commit d80b8442a68093106e00a9a38b7b2c593002a72c #5 0x00007f93a295c538 in abort () from /lib64/libc.so.6 #6 0x00005651659c77e7 in ibuf_merge_or_delete_for_page (block=0x7f93871dfe80, space=4, page_no=3, zip_size=0, update_ibuf_bitmap=1) at /src/1 0.1/storage/xtradb/ibuf/ibuf0ibuf.cc:4776 #7 0x0000565165b6f617 in buf_page_io_complete (bpage=0x7f93871dfe80) at /src/10.1/storage/xtradb/buf/buf0buf.cc:4840 #8 0x0000565165b8d35b in buf_read_page_low (err=0x7f93a4c0302c, sync=true, mode=132, space=4, zip_size=0, unzip=0, tablespace_version=7, offs et=3, trx=0x0, rbpage=0x7f93a4c030a8) at /src/10.1/storage/xtradb/buf/buf0rea.cc:262 #9 0x0000565165b8d7dd in buf_read_page (space=4, zip_size=0, offset=3, trx=0x0, bpage=0x7f93a4c030a8) at /src/10.1/storage/xtradb/buf/buf0rea .cc:474 #10 0x0000565165b6b019 in buf_page_get_gen (space=4, zip_size=0, offset=3, rw_latch=3, guess=0x0, mode=10, file=0x56516600b8d0 "/src/10.1/storage/xtradb/include/btr0pcur.ic", line=522, mtr=0x7f93a4c03a00, err=0x7f93a4c03184) at /src/10.1/storage/xtradb/buf/buf0buf.cc:2942 #11 0x0000565165b3f2e3 in btr_cur_open_at_index_side_func (from_left=true, index=0x7f93a168a378, latch_mode=1, cursor=0x7f93a16990f0, level=0, file=0x56516600b8d0 "/src/10.1/storage/xtradb/include/btr0pcur.ic", line=522, mtr=0x7f93a4c03a00) at /src/10.1/storage/xtradb/btr/btr0cur.cc:990 #12 0x0000565165aaa945 in btr_pcur_open_at_index_side (from_left=true, index=0x7f93a168a378, latch_mode=1, pcur=0x7f93a16990f0, init_pcur=false, level=0, mtr=0x7f93a4c03a00) at /src/10.1/storage/xtradb/include/btr0pcur.ic:522 #13 0x0000565165ab27e9 in row_search_for_mysql (buf=0x7f937f229e88 "\377", mode=1, prebuilt=0x7f93a1699078, match_mode=0, direction=0) at /src/10.1/storage/xtradb/row/row0sel.cc:4187 #14 0x0000565165979add in ha_innobase::index_read (this=0x7f93a165c888, buf=0x7f937f229e88 "\377", key_ptr=0x0, key_len=0, find_flag=HA_READ_AFTER_KEY) at /src/10.1/storage/xtradb/handler/ha_innodb.cc:9603 #15 0x000056516597ab42 in ha_innobase::index_first (this=0x7f93a165c888, buf=0x7f937f229e88 "\377") at /src/10.1/storage/xtradb/handler/ha_innodb.cc:10028 #16 0x000056516597ad1a in ha_innobase::rnd_next (this=0x7f93a165c888, buf=0x7f937f229e88 "\377") at /src/10.1/storage/xtradb/handler/ha_innodb.cc:10123 #17 0x00005651657be329 in handler::ha_rnd_next (this=0x7f93a165c888, buf=0x7f937f229e88 "\377") at /src/10.1/sql/handler.cc:2577 #18 0x00005651658fa3b5 in rr_sequential (info=0x7f93a16340a8) at /src/10.1/sql/records.cc:470 #19 0x00005651655e921c in join_init_read_record (tab=0x7f93a1633fe8) at /src/10.1/sql/sql_select.cc:19182 #20 0x00005651655e7196 in sub_select (join=0x7f93a1632a40, join_tab=0x7f93a1633fe8, end_of_records=false) at /src/10.1/sql/sql_select.cc:18278 #21 0x00005651655e6a6a in do_select (join=0x7f93a1632a40, fields=0x7f937f263520, table=0x0, procedure=0x0) at /src/10.1/sql/sql_select.cc:17936 #22 0x00005651655c1a8d in JOIN::exec_inner (this=0x7f93a1632a40) at /src/10.1/sql/sql_select.cc:3228 #23 0x00005651655bed31 in JOIN::exec (this=0x7f93a1632a40) at /src/10.1/sql/sql_select.cc:2518 #24 0x00005651655c22e4 in mysql_select (thd=0x7f937f25f2f0, rref_pointer_array=0x7f937f263680, tables=0x7f93a1632358, wild_num=1, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2147748608, result=0x7f93a1632a20, unit=0x7f937f262d08, select_lex=0x7f937f263408) at /src/10.1/sql/sql_select.cc:3451 #25 0x00005651655b7d89 in handle_select (thd=0x7f937f25f2f0, lex=0x7f937f262c40, result=0x7f93a1632a20, setup_tables_done_option=0) at /src/10.1/sql/sql_select.cc:384 #26 0x0000565165588133 in execute_sqlcom_select (thd=0x7f937f25f2f0, all_tables=0x7f93a1632358) at /src/10.1/sql/sql_parse.cc:5903 #27 0x000056516557e20d in mysql_execute_command (thd=0x7f937f25f2f0) at /src/10.1/sql/sql_parse.cc:2962 #28 0x000056516558b77a in mysql_parse (thd=0x7f937f25f2f0, rawbuf=0x7f93a1632188 "select * from t5", length=16, parser_state=0x7f93a4c05630) at /src/10.1/sql/sql_parse.cc:7303 #29 0x000056516557a474 in dispatch_command (command=COM_QUERY, thd=0x7f937f25f2f0, packet=0x7f937f27bab1 "", packet_length=16) at /src/10.1/sql/sql_parse.cc:1488 #30 0x00005651655791a6 in do_command (thd=0x7f937f25f2f0) at /src/10.1/sql/sql_parse.cc:1109 #31 0x00005651656ae798 in do_handle_one_connection (thd_arg=0x7f937f25f2f0) at /src/10.1/sql/sql_connect.cc:1349 #32 0x00005651656ae4fc in handle_one_connection (arg=0x7f937f25f2f0) at /src/10.1/sql/sql_connect.cc:1261 #33 0x00007f93a489d0a4 in start_thread () from /lib64/libpthread.so.0 #34 0x00007f93a2a0b04d in clone () from /lib64/libc.so.6

          I could not fully repeat exactly the same assertion but find two others that could also affect. Can you explain more thoroughly steps to repeat above assertion?

          commit 36ca65b73bcd0152680c88e09558bbe1237577ee
          Author: Jan Lindström <jan.lindstrom@mariadb.com>
          Date: Wed Feb 17 12:32:07 2016 +0200

          MDEV-9559: Server without encryption configs crashes if selecting from an implicitly encrypted table

          There was two problems. Firstly, if page in ibuf is encrypted but
          decrypt failed we should not allow InnoDB to start because
          this means that system tablespace is encrypted and not usable.
          Secondly, if page decrypt is detected we should return false
          from buf_page_decrypt_after_read.

          jplindst Jan Lindström (Inactive) added a comment - I could not fully repeat exactly the same assertion but find two others that could also affect. Can you explain more thoroughly steps to repeat above assertion? commit 36ca65b73bcd0152680c88e09558bbe1237577ee Author: Jan Lindström <jan.lindstrom@mariadb.com> Date: Wed Feb 17 12:32:07 2016 +0200 MDEV-9559 : Server without encryption configs crashes if selecting from an implicitly encrypted table There was two problems. Firstly, if page in ibuf is encrypted but decrypt failed we should not allow InnoDB to start because this means that system tablespace is encrypted and not usable. Secondly, if page decrypt is detected we should return false from buf_page_decrypt_after_read.

          Can you explain more thoroughly steps to repeat above assertion?

          Getting one or another failure seems to be the matter of timing or luck, or both. By executing steps below, I received the exact same assertion failure as in the initial description twice, but I also received different failures by doing exactly the same (naturally, with somewhat different delays between start, SQL commands, restart, SQL queries).

          • start CentOS 7 64-bit machine last upgraded on 2016-02-11, no MariaDB/MySQL server installed
          • add MariaDB 10.1 repo to YUM repo list
          • run sudo yum install MariaDB-server MariaDB-client
          • take mysql-test/std_data/keys.txt from the recent 10.1 tree and put it into /var/lib/mysql/keys.txt
          • add the following options in the beginning of [mysqld] section in /etc/my.cnf.d/server.cnf file

            plugin-load-add=file_key_management.so
            file-key-management-filename = /var/lib/mysql/keys.txt
            innodb-encrypt-tables

          • run sudo service mysql restart
          • run mysql -uroot
          • execute the following set of SQL commands:

            drop database if exists mysqlslap;
            create database mysqlslap;
            use mysqlslap;
             
            create table t1 (
             `intcol1` int(32) DEFAULT NULL,
               `intcol2` int(32) DEFAULT NULL,
               `charcol1` varchar(128) DEFAULT NULL,
               `charcol2` varchar(128) DEFAULT NULL,
               `charcol3` varchar(128) DEFAULT NULL
             ) ENGINE=InnoDB DEFAULT CHARSET=latin1;
             
            alter table mysqlslap.t1 encrypted='yes' `encryption_key_id`=1;
             
            create table t5 (
             `intcol1` int(32) DEFAULT NULL,
               `intcol2` int(32) DEFAULT NULL,
               `charcol1` varchar(128) DEFAULT NULL,
               `charcol2` varchar(128) DEFAULT NULL,
               `charcol3` varchar(128) DEFAULT NULL
             ) ENGINE=InnoDB DEFAULT CHARSET=latin1;
             
            insert into t1 values (1,2,'maria','db','encryption');
            insert into t5 values (1,2,'maria','db','encryption');

          • wait a bit (time can vary)
          • close the client
          • comment the above 3 options in /etc/my.cnf.d/server.cnf
          • run sudo service mysql restart
          • wait a bit (time can vary)
          • run mysql -uroot
          • run the queries

            select * from mysqlslap.t1\G
            select * from mysqlslap.t5\G

            at this point, server always crashes. The assertion failure can be different, one of them is in file page0page.ic line 780.

          elenst Elena Stepanova added a comment - Can you explain more thoroughly steps to repeat above assertion? Getting one or another failure seems to be the matter of timing or luck, or both. By executing steps below, I received the exact same assertion failure as in the initial description twice, but I also received different failures by doing exactly the same (naturally, with somewhat different delays between start, SQL commands, restart, SQL queries). start CentOS 7 64-bit machine last upgraded on 2016-02-11, no MariaDB/MySQL server installed add MariaDB 10.1 repo to YUM repo list run sudo yum install MariaDB-server MariaDB-client take mysql-test/std_data/keys.txt from the recent 10.1 tree and put it into /var/lib/mysql/keys.txt add the following options in the beginning of [mysqld] section in /etc/my.cnf.d/server.cnf file plugin-load-add=file_key_management.so file-key-management-filename = /var/lib/mysql/keys.txt innodb-encrypt-tables run sudo service mysql restart run mysql -uroot execute the following set of SQL commands: drop database if exists mysqlslap; create database mysqlslap; use mysqlslap;   create table t1 ( `intcol1` int(32) DEFAULT NULL, `intcol2` int(32) DEFAULT NULL, `charcol1` varchar(128) DEFAULT NULL, `charcol2` varchar(128) DEFAULT NULL, `charcol3` varchar(128) DEFAULT NULL ) ENGINE=InnoDB DEFAULT CHARSET=latin1;   alter table mysqlslap.t1 encrypted='yes' `encryption_key_id`=1;   create table t5 ( `intcol1` int(32) DEFAULT NULL, `intcol2` int(32) DEFAULT NULL, `charcol1` varchar(128) DEFAULT NULL, `charcol2` varchar(128) DEFAULT NULL, `charcol3` varchar(128) DEFAULT NULL ) ENGINE=InnoDB DEFAULT CHARSET=latin1;   insert into t1 values (1,2,'maria','db','encryption'); insert into t5 values (1,2,'maria','db','encryption'); wait a bit (time can vary) close the client comment the above 3 options in /etc/my.cnf.d/server.cnf run sudo service mysql restart wait a bit (time can vary) run mysql -uroot run the queries select * from mysqlslap.t1\G select * from mysqlslap.t5\G at this point, server always crashes. The assertion failure can be different, one of them is in file page0page.ic line 780 .

          Commit above fixes at least following:

          #0  0x00007f0ec67b3101 in __pthread_kill (threadid=<optimized out>, signo=6) at ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c:61
          61      ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c: No such file or directory.
          #0  0x00007f0ec67b3101 in __pthread_kill (threadid=<optimized out>, signo=6) at ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c:61
          #1  0x00007f0ec793a436 in my_write_core (sig=6) at /home/jan/mysql/10.1-bug/mysys/stacktrace.c:456
          #2  0x00007f0ec72e540d in handle_fatal_signal (sig=6) at /home/jan/mysql/10.1-bug/sql/signal_handler.cc:273
          #3  <signal handler called>
          #4  0x00007f0ec42e9107 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
          #5  0x00007f0ec42ea4e8 in __GI_abort () at abort.c:89
          #6  0x00007f0ebf5c99ed in buf_page_print (read_buf=0x7f0ebdd48000 "\352\266\232\b", zip_size=0, flags=0) at /home/jan/mysql/10.1-bug/storage/innobase/buf/buf0buf.cc:990
          #7  0x00007f0ebf58c624 in btr_corruption_report (block=0x7f0ebda66988, index=0x7f0e8413a528) at /home/jan/mysql/10.1-bug/storage/innobase/btr/btr0btr.cc:83
          #8  0x00007f0ebf58c815 in btr_root_block_get (index=0x7f0e8413a528, mode=2, mtr=0x7f0eb47a9f00) at /home/jan/mysql/10.1-bug/storage/innobase/btr/btr0btr.cc:752
          #9  0x00007f0ebf58c900 in btr_root_get (index=0x7f0e8413a528, mtr=0x7f0eb47a9f00) at /home/jan/mysql/10.1-bug/storage/innobase/btr/btr0btr.cc:778
          #10 0x00007f0ebf58d6f2 in btr_get_size_and_reserved (index=0x7f0e8413a528, flag=2, used=0x7f0eb47a9ec8, mtr=0x7f0eb47a9f00) at /home/jan/mysql/10.1-bug/storage/innobase/btr/btr0btr.cc:1275
          #11 0x00007f0ebf58d5e7 in btr_get_size (index=0x7f0e8413a528, flag=2, mtr=0x7f0eb47a9f00) at /home/jan/mysql/10.1-bug/storage/innobase/btr/btr0btr.cc:1239
          #12 0x00007f0ebf629df3 in dict_stats_update_transient_for_index (index=0x7f0e8413a528) at /home/jan/mysql/10.1-bug/storage/innobase/dict/dict0stats.cc:889
          #13 0x00007f0ebf62a047 in dict_stats_update_transient (table=0x7f0e84139358) at /home/jan/mysql/10.1-bug/storage/innobase/dict/dict0stats.cc:970
          #14 0x00007f0ebf62e8ef in dict_stats_update (table=0x7f0e84139358, stats_upd_option=DICT_STATS_RECALC_TRANSIENT) at /home/jan/mysql/10.1-bug/storage/innobase/dict/dict0stats.cc:3392
          #15 0x00007f0ebf691e74 in dict_stats_init (table=0x7f0e84139358) at /home/jan/mysql/10.1-bug/storage/innobase/include/dict0stats.ic:174
          #16 0x00007f0ebf698995 in ha_innodb::open (this=0x7f0e840284e8, name=0x7f0e841346a0 "./test/t5", mode=2, test_if_locked=18) at /home/jan/mysql/10.1-bug/storage/innobase/handler/ha_innodb.cc:5644
          #17 0x00007f0ec72eb0d6 in handler::ha_open (this=0x7f0e840284e8, table_arg=0x7f0e840278b0, name=0x7f0e841346a0 "./test/t5", mode=2, test_if_locked=18) at /home/jan/mysql/10.1-bug/sql/handler.cc:2500
          #18 0x00007f0ec71a0828 in open_table_from_share (thd=0x7f0ecafe4580, share=0x7f0e841341c8, alias=0x7f0e84013c70 "t5", db_stat=39, prgflag=44, ha_open_flags=18, outparam=0x7f0e840278b0, is_create_table=false) at /home/jan/mysql/10.1-bug/sql/table.cc:2927
          #19 0x00007f0ec704ab61 in open_table (thd=0x7f0ecafe4580, table_list=0x7f0e84013c78, ot_ctx=0x7f0eb47ab4c0) at /home/jan/mysql/10.1-bug/sql/sql_base.cc:2558
          #20 0x00007f0ec704d394 in open_and_process_table (thd=0x7f0ecafe4580, lex=0x7f0ecafe7ed0, tables=0x7f0e84013c78, counter=0x7f0eb47ab554, flags=0, prelocking_strategy=0x7f0eb47ab5d0, has_prelocking_list=false, ot_ctx=0x7f0eb47ab4c0) at /home/jan/mysql/10.1-bug/sql/sql_base.cc:4068
          #21 0x00007f0ec704e40f in open_tables (thd=0x7f0ecafe4580, options=..., start=0x7f0eb47ab538, counter=0x7f0eb47ab554, flags=0, prelocking_strategy=0x7f0eb47ab5d0) at /home/jan/mysql/10.1-bug/sql/sql_base.cc:4579
          #22 0x00007f0ec704f64a in open_and_lock_tables (thd=0x7f0ecafe4580, options=..., tables=0x7f0e84013c78, derived=true, flags=0, prelocking_strategy=0x7f0eb47ab5d0) at /home/jan/mysql/10.1-bug/sql/sql_base.cc:5241
          #23 0x00007f0ec7043205 in open_and_lock_tables (thd=0x7f0ecafe4580, tables=0x7f0e84013c78, derived=true, flags=0) at /home/jan/mysql/10.1-bug/sql/sql_base.h:530
          #24 0x00007f0ec70bb3a2 in execute_sqlcom_select (thd=0x7f0ecafe4580, all_tables=0x7f0e84013c78) at /home/jan/mysql/10.1-bug/sql/sql_parse.cc:5824
          #25 0x00007f0ec70b193e in mysql_execute_command (thd=0x7f0ecafe4580) at /home/jan/mysql/10.1-bug/sql/sql_parse.cc:2962
          #26 0x00007f0ec70beeaa in mysql_parse (thd=0x7f0ecafe4580, rawbuf=0x7f0e84013aa8 "select * from t5", length=16, parser_state=0x7f0eb47ac620) at /home/jan/mysql/10.1-bug/sql/sql_parse.cc:7303
          #27 0x00007f0ec70adb93 in dispatch_command (command=COM_QUERY, thd=0x7f0ecafe4580, packet=0x7f0ecafeafa1 "select * from t5", packet_length=16) at /home/jan/mysql/10.1-bug/sql/sql_parse.cc:1488
          #28 0x00007f0ec70ac8ca in do_command (thd=0x7f0ecafe4580) at /home/jan/mysql/10.1-bug/sql/sql_parse.cc:1109
          #29 0x00007f0ec71e11f0 in do_handle_one_connection (thd_arg=0x7f0ecafe4580) at /home/jan/mysql/10.1-bug/sql/sql_connect.cc:1349
          #30 0x00007f0ec71e0f54 in handle_one_connection (arg=0x7f0ecafe4580) at /home/jan/mysql/10.1-bug/sql/sql_connect.cc:1261
          #31 0x00007f0ec74c7230 in pfs_spawn_thread (arg=0x7f0ecaff0130) at /home/jan/mysql/10.1-bug/storage/perfschema/pfs.cc:1860
          #32 0x00007f0ec67ae0a4 in start_thread (arg=0x7f0eb47adb00) at pthread_create.c:309
          #33 0x00007f0ec439a04d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

          and crash at ibuf_merge_or_delete_for_page on earlier comment.

          jplindst Jan Lindström (Inactive) added a comment - Commit above fixes at least following: #0 0x00007f0ec67b3101 in __pthread_kill (threadid=<optimized out>, signo=6) at ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c:61 61 ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c: No such file or directory. #0 0x00007f0ec67b3101 in __pthread_kill (threadid=<optimized out>, signo=6) at ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c:61 #1 0x00007f0ec793a436 in my_write_core (sig=6) at /home/jan/mysql/10.1-bug/mysys/stacktrace.c:456 #2 0x00007f0ec72e540d in handle_fatal_signal (sig=6) at /home/jan/mysql/10.1-bug/sql/signal_handler.cc:273 #3 <signal handler called> #4 0x00007f0ec42e9107 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56 #5 0x00007f0ec42ea4e8 in __GI_abort () at abort.c:89 #6 0x00007f0ebf5c99ed in buf_page_print (read_buf=0x7f0ebdd48000 "\352\266\232\b", zip_size=0, flags=0) at /home/jan/mysql/10.1-bug/storage/innobase/buf/buf0buf.cc:990 #7 0x00007f0ebf58c624 in btr_corruption_report (block=0x7f0ebda66988, index=0x7f0e8413a528) at /home/jan/mysql/10.1-bug/storage/innobase/btr/btr0btr.cc:83 #8 0x00007f0ebf58c815 in btr_root_block_get (index=0x7f0e8413a528, mode=2, mtr=0x7f0eb47a9f00) at /home/jan/mysql/10.1-bug/storage/innobase/btr/btr0btr.cc:752 #9 0x00007f0ebf58c900 in btr_root_get (index=0x7f0e8413a528, mtr=0x7f0eb47a9f00) at /home/jan/mysql/10.1-bug/storage/innobase/btr/btr0btr.cc:778 #10 0x00007f0ebf58d6f2 in btr_get_size_and_reserved (index=0x7f0e8413a528, flag=2, used=0x7f0eb47a9ec8, mtr=0x7f0eb47a9f00) at /home/jan/mysql/10.1-bug/storage/innobase/btr/btr0btr.cc:1275 #11 0x00007f0ebf58d5e7 in btr_get_size (index=0x7f0e8413a528, flag=2, mtr=0x7f0eb47a9f00) at /home/jan/mysql/10.1-bug/storage/innobase/btr/btr0btr.cc:1239 #12 0x00007f0ebf629df3 in dict_stats_update_transient_for_index (index=0x7f0e8413a528) at /home/jan/mysql/10.1-bug/storage/innobase/dict/dict0stats.cc:889 #13 0x00007f0ebf62a047 in dict_stats_update_transient (table=0x7f0e84139358) at /home/jan/mysql/10.1-bug/storage/innobase/dict/dict0stats.cc:970 #14 0x00007f0ebf62e8ef in dict_stats_update (table=0x7f0e84139358, stats_upd_option=DICT_STATS_RECALC_TRANSIENT) at /home/jan/mysql/10.1-bug/storage/innobase/dict/dict0stats.cc:3392 #15 0x00007f0ebf691e74 in dict_stats_init (table=0x7f0e84139358) at /home/jan/mysql/10.1-bug/storage/innobase/include/dict0stats.ic:174 #16 0x00007f0ebf698995 in ha_innodb::open (this=0x7f0e840284e8, name=0x7f0e841346a0 "./test/t5", mode=2, test_if_locked=18) at /home/jan/mysql/10.1-bug/storage/innobase/handler/ha_innodb.cc:5644 #17 0x00007f0ec72eb0d6 in handler::ha_open (this=0x7f0e840284e8, table_arg=0x7f0e840278b0, name=0x7f0e841346a0 "./test/t5", mode=2, test_if_locked=18) at /home/jan/mysql/10.1-bug/sql/handler.cc:2500 #18 0x00007f0ec71a0828 in open_table_from_share (thd=0x7f0ecafe4580, share=0x7f0e841341c8, alias=0x7f0e84013c70 "t5", db_stat=39, prgflag=44, ha_open_flags=18, outparam=0x7f0e840278b0, is_create_table=false) at /home/jan/mysql/10.1-bug/sql/table.cc:2927 #19 0x00007f0ec704ab61 in open_table (thd=0x7f0ecafe4580, table_list=0x7f0e84013c78, ot_ctx=0x7f0eb47ab4c0) at /home/jan/mysql/10.1-bug/sql/sql_base.cc:2558 #20 0x00007f0ec704d394 in open_and_process_table (thd=0x7f0ecafe4580, lex=0x7f0ecafe7ed0, tables=0x7f0e84013c78, counter=0x7f0eb47ab554, flags=0, prelocking_strategy=0x7f0eb47ab5d0, has_prelocking_list=false, ot_ctx=0x7f0eb47ab4c0) at /home/jan/mysql/10.1-bug/sql/sql_base.cc:4068 #21 0x00007f0ec704e40f in open_tables (thd=0x7f0ecafe4580, options=..., start=0x7f0eb47ab538, counter=0x7f0eb47ab554, flags=0, prelocking_strategy=0x7f0eb47ab5d0) at /home/jan/mysql/10.1-bug/sql/sql_base.cc:4579 #22 0x00007f0ec704f64a in open_and_lock_tables (thd=0x7f0ecafe4580, options=..., tables=0x7f0e84013c78, derived=true, flags=0, prelocking_strategy=0x7f0eb47ab5d0) at /home/jan/mysql/10.1-bug/sql/sql_base.cc:5241 #23 0x00007f0ec7043205 in open_and_lock_tables (thd=0x7f0ecafe4580, tables=0x7f0e84013c78, derived=true, flags=0) at /home/jan/mysql/10.1-bug/sql/sql_base.h:530 #24 0x00007f0ec70bb3a2 in execute_sqlcom_select (thd=0x7f0ecafe4580, all_tables=0x7f0e84013c78) at /home/jan/mysql/10.1-bug/sql/sql_parse.cc:5824 #25 0x00007f0ec70b193e in mysql_execute_command (thd=0x7f0ecafe4580) at /home/jan/mysql/10.1-bug/sql/sql_parse.cc:2962 #26 0x00007f0ec70beeaa in mysql_parse (thd=0x7f0ecafe4580, rawbuf=0x7f0e84013aa8 "select * from t5", length=16, parser_state=0x7f0eb47ac620) at /home/jan/mysql/10.1-bug/sql/sql_parse.cc:7303 #27 0x00007f0ec70adb93 in dispatch_command (command=COM_QUERY, thd=0x7f0ecafe4580, packet=0x7f0ecafeafa1 "select * from t5", packet_length=16) at /home/jan/mysql/10.1-bug/sql/sql_parse.cc:1488 #28 0x00007f0ec70ac8ca in do_command (thd=0x7f0ecafe4580) at /home/jan/mysql/10.1-bug/sql/sql_parse.cc:1109 #29 0x00007f0ec71e11f0 in do_handle_one_connection (thd_arg=0x7f0ecafe4580) at /home/jan/mysql/10.1-bug/sql/sql_connect.cc:1349 #30 0x00007f0ec71e0f54 in handle_one_connection (arg=0x7f0ecafe4580) at /home/jan/mysql/10.1-bug/sql/sql_connect.cc:1261 #31 0x00007f0ec74c7230 in pfs_spawn_thread (arg=0x7f0ecaff0130) at /home/jan/mysql/10.1-bug/storage/perfschema/pfs.cc:1860 #32 0x00007f0ec67ae0a4 in start_thread (arg=0x7f0eb47adb00) at pthread_create.c:309 #33 0x00007f0ec439a04d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111 and crash at ibuf_merge_or_delete_for_page on earlier comment.

          Thank you for the fix.

          In the latest version, 10.1.12, I see the following error message when attempting to select from an implicitly encrypted table if encryption configs have been removed as described above:

          ERROR 1296 (HY000): Got error 192 'Table encrypted but decryption failed. This could be because correct encryption management plugin is not loaded, used encryption key is not available or encryption method does not match.' from InnoDB
          

          The server does not crash.

          This error message is expected behavior. Thank you again.

          valerie@opengroupware.ch Valerie Parham-Thompson added a comment - Thank you for the fix. In the latest version, 10.1.12, I see the following error message when attempting to select from an implicitly encrypted table if encryption configs have been removed as described above: ERROR 1296 (HY000): Got error 192 'Table encrypted but decryption failed. This could be because correct encryption management plugin is not loaded, used encryption key is not available or encryption method does not match.' from InnoDB The server does not crash. This error message is expected behavior. Thank you again.

          People

            jplindst Jan Lindström (Inactive)
            valerie@opengroupware.ch Valerie Parham-Thompson
            Votes:
            0 Vote for this issue
            Watchers:
            4 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.