[MDEV-8724] Assertion `rc == 0' failed in ma_decrypt on reading an Aria table Created: 2015-09-01  Updated: 2016-02-02  Resolved: 2016-01-28

Status: Closed
Project: MariaDB Server
Component/s: Encryption, Storage Engine - Aria
Affects Version/s: 10.1
Fix Version/s: 10.1.11

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Michael Widenius
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Relates
Sprint: 10.1.11

 Description   
Comment

Test flow:

  1. - start server with key file containing key 1;
  2. - create an encrypted Aria table, insert some data;
  3. - restart server without key 1;
  4. - repair the table (it appears to be corrupted, repair deletes the data);
  5. - insert some more data;
  6. - restart again with key 1;
  7. - try to read from the table
  8. => assertion failure

Test case

 
--exec echo "wait" > $MYSQLTEST_VARDIR/tmp/mysqld.1.expect
 
--shutdown_server
 
--source include/wait_until_disconnected.inc
 
 
 
--write_file $MYSQLTEST_VARDIR/keys1.txt
 
1;770A8A65DA156D24EE2A093277530142
 
EOF
 
 
 
--exec echo "restart:--aria-encrypt-tables=1 --plugin-load-add=file_key_management.so --file-key-management --file-key-management-filename=$MYSQLTEST_VARDIR/keys1.txt" > $MYSQLTEST_VARDIR/tmp/mysqld.1.expect
 
--enable_reconnect
 
--source include/wait_until_connected_again.inc
 
 
 
CREATE TABLE t1 (i INT, KEY(i)) ENGINE=Aria;
 
INSERT INTO t1 VALUES (1);
 
 
 
--exec echo "wait" > $MYSQLTEST_VARDIR/tmp/mysqld.1.expect
 
--shutdown_server
 
--source include/wait_until_disconnected.inc
 
 
 
--write_file $MYSQLTEST_VARDIR/keys2.txt
 
2;770A8A65DA156D24EE2A093277530143
 
EOF
 
 
 
--exec echo "restart:--aria-encrypt-tables=1 --plugin-load-add=file_key_management.so --file-key-management --file-key-management-filename=$MYSQLTEST_VARDIR/keys2.txt" > $MYSQLTEST_VARDIR/tmp/mysqld.1.expect
 
--enable_reconnect
 
--source include/wait_until_connected_again.inc
 
 
 
repair table t1;
 
 
 
INSERT INTO t1 VALUES (2);
 
 
 
--exec echo "wait" > $MYSQLTEST_VARDIR/tmp/mysqld.1.expect
 
--shutdown_server
 
--source include/wait_until_disconnected.inc
 
 
 
--exec echo "restart:--aria-encrypt-tables=1 --plugin-load-add=file_key_management.so --file-key-management --file-key-management-filename=$MYSQLTEST_VARDIR/keys1.txt" > $MYSQLTEST_VARDIR/tmp/mysqld.1.expect
 
--enable_reconnect
 
--source include/wait_until_connected_again.inc
 
 
 
select * from t1;
 

10.1/storage/maria/ma_crypt.c:493: ma_decrypt: Assertion `rc == 0' failed.
 
150901 19:49:25 [ERROR] mysqld got signal 6 ;

Stack trace from 10.1 8ea9b8c0b168b3e5aad08886477d8726531abcd5

 
#6  0x00007fdfce578311 in *__GI___assert_fail (assertion=0x7fdfd1a5268b "rc == 0", file=<optimized out>, line=493, function=0x7fdfd1a526d8 "ma_decrypt") at assert.c:81
 
#7  0x00007fdfd15fdcbc in ma_decrypt (crypt_data=0x7fdfc5631230, src=0x7fdfc5581080 "", dst=0x7fdfc7804080 "", size=8172, pageno=1, lsn=4294976334, key_version=0) at 10.1/storage/maria/ma_crypt.c:493
 
#8  0x00007fdfd15fd27c in ma_crypt_data_post_read_hook (res=0, args=0x7fdfd0957680) at 10.1/storage/maria/ma_crypt.c:230
 
#9  0x00007fdfd15eacd2 in read_block (pagecache=0x7fdfd2a4c560, block=0x7fdfc80601b0, primary=1 '\001') at 10.1/storage/maria/ma_pagecache.c:2720
 
#10 0x00007fdfd15ec2d3 in pagecache_read (pagecache=0x7fdfd2a4c560, file=0x7fdfc563d498, pageno=1, level=0, buff=0x7fdfc563a070 "\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245"..., type=PAGECACHE_LSN_PAGE, lock=PAGECACHE_LOCK_LEFT_UNLOCKED, page_link=0x7fdfd0957740) at 10.1/storage/maria/ma_pagecache.c:3396
 
#11 0x00007fdfd163562b in _ma_scan_block_record (info=0x7fdfc563d070, record=0x7fdfcdc16388 "\377\217\217\217\217\245\245\245\377\245\245\245\245\245\245\245\250c\301\315\337\177", record_pos=0, skip_deleted=1 '\001') at 10.1/storage/maria/ma_blockrec.c:5501
 
#12 0x00007fdfd161bf91 in maria_scan (info=0x7fdfc563d070, record=0x7fdfcdc16388 "\377\217\217\217\217\245\245\245\377\245\245\245\245\245\245\245\250c\301\315\337\177") at 10.1/storage/maria/ma_scan.c:54
 
#13 0x00007fdfd15c62e4 in ha_maria::rnd_next (this=0x7fdfc547d088, buf=0x7fdfcdc16388 "\377\217\217\217\217\245\245\245\377\245\245\245\245\245\245\245\250c\301\315\337\177") at 10.1/storage/maria/ha_maria.cc:2445
 
#14 0x00007fdfd10ee356 in handler::ha_rnd_next (this=0x7fdfc547d088, buf=0x7fdfcdc16388 "\377\217\217\217\217\245\245\245\377\245\245\245\245\245\245\245\250c\301\315\337\177") at 10.1/sql/handler.cc:2581
 
#15 0x00007fdfd10ef6d7 in handler::read_first_row (this=0x7fdfc547d088, buf=0x7fdfcdc16388 "\377\217\217\217\217\245\245\245\377\245\245\245\245\245\245\245\250c\301\315\337\177", primary_key=64) at 10.1/sql/handler.cc:2776
 
#16 0x00007fdfd0f32c3f in handler::ha_read_first_row (this=0x7fdfc547d088, buf=0x7fdfcdc16388 "\377\217\217\217\217\245\245\245\377\245\245\245\245\245\245\245\250c\301\315\337\177", primary_key=64) at 10.1/sql/sql_class.h:5378
 
#17 0x00007fdfd0f1d642 in join_read_system (tab=0x7fdfc54e5048) at 10.1/sql/sql_select.cc:18624
 
#18 0x00007fdfd0f1d249 in join_read_const_table (thd=0x7fdfc7472070, tab=0x7fdfc54e5048, pos=0x7fdfc54e5598) at 10.1/sql/sql_select.cc:18520
 
#19 0x00007fdfd0ef8a31 in make_join_statistics (join=0x7fdfc54e4948, tables_list=..., keyuse_array=0x7fdfc54e4c48) at 10.1/sql/sql_select.cc:3668
 
#20 0x00007fdfd0ef07a7 in JOIN::optimize_inner (this=0x7fdfc54e4948) at 10.1/sql/sql_select.cc:1358
 
#21 0x00007fdfd0eef65e in JOIN::optimize (this=0x7fdfc54e4948) at 10.1/sql/sql_select.cc:1021
 
#22 0x00007fdfd0ef7817 in mysql_select (thd=0x7fdfc7472070, rref_pointer_array=0x7fdfc74763d0, tables=0x7fdfc54e4268, wild_num=1, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2147748608, result=0x7fdfc54e4928, unit=0x7fdfc7475a68, select_lex=0x7fdfc7476158) at 10.1/sql/sql_select.cc:3329
 
#23 0x00007fdfd0eed849 in handle_select (thd=0x7fdfc7472070, lex=0x7fdfc74759a0, result=0x7fdfc54e4928, setup_tables_done_option=0) at 10.1/sql/sql_select.cc:371
 
#24 0x00007fdfd0ebe02d in execute_sqlcom_select (thd=0x7fdfc7472070, all_tables=0x7fdfc54e4268) at 10.1/sql/sql_parse.cc:5832
 
#25 0x00007fdfd0eb41d4 in mysql_execute_command (thd=0x7fdfc7472070) at 10.1/sql/sql_parse.cc:2949
 
#26 0x00007fdfd0ec15ef in mysql_parse (thd=0x7fdfc7472070, rawbuf=0x7fdfc54e4088 "select * from t1", length=16, parser_state=0x7fdfd09591a0) at 10.1/sql/sql_parse.cc:7208
 
#27 0x00007fdfd0eb0373 in dispatch_command (command=COM_QUERY, thd=0x7fdfc7472070, packet=0x7fdfc9bc6071 "select * from t1", packet_length=16) at 10.1/sql/sql_parse.cc:1475
 
#28 0x00007fdfd0eaf099 in do_command (thd=0x7fdfc7472070) at 10.1/sql/sql_parse.cc:1097
 
#29 0x00007fdfd0fe31e9 in do_handle_one_connection (thd_arg=0x7fdfc7472070) at 10.1/sql/sql_connect.cc:1350
 
#30 0x00007fdfd0fe2f3a in handle_one_connection (arg=0x7fdfc7472070) at 10.1/sql/sql_connect.cc:1262
 
#31 0x00007fdfd15a774f in pfs_spawn_thread (arg=0x7fdfcdc235f0) at 10.1/storage/perfschema/pfs.cc:1860
 
#32 0x00007fdfd0593b50 in start_thread (arg=<optimized out>) at pthread_create.c:304
 
#33 0x00007fdfce62895d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112



 Comments   
Comment by Michael Widenius [ 2016-01-28 ]

The assert happens because in debug mode we always crash if we found something that should not happen with encryption to make it easier to debug this.

I will fix this so that the assert only happens in debug builds if --debug-assert-on-error is set.

Comment by Michael Widenius [ 2016-01-28 ]

Fix pushed to 10.1 tree.

Comment by Elena Stepanova [ 2016-01-28 ]

[1/28/16 14:08] <elenst> montywi: generally, "if we found something that should not happen" is kind of a definition of a bug
[1/28/16 14:09] <elenst> montywi: so, maybe if it really should not happen, better to keep the assert, and to make sure it does not happen when it should not?
[1/28/16 14:10] <elenst> i mean, seriously. If it can happen, there should be no assert, debug or not debug; and it it should not happen, the assert is valid, but the current behavior is not
[1/28/16 14:11] <elenst> hiding the assert conditionally only complicates the problem

Comment by Michael Widenius [ 2016-02-02 ]

In this particular case the assert was for something that should never happen in normal operations, especially in our test environment (for which most of the asserts are done).

In normal operations, decryption an encryption shouldn't fail. It only failed in this case because of 'wrong usage' when someone wrongly changes a key to something else.

The --debug-assert-on-error flag is something that was proposed a couple a years ago to achieve a middle ground; Give an SQL error for things that could be caused by a user, even doing wrong things but an assert otherwise to make it easier to debug things.

The one thing we didn't do before was to have --debug-assert-on-error on as default for mysql-test-run. Maybe it's time to do that.

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