[MDEV-28679] After upgrade to 10.7.3-1 with enabled data-at-rest encryption unable to restore dump file. Created: 2022-05-27  Updated: 2022-07-26  Resolved: 2022-07-26

Status: Closed
Project: MariaDB Server
Component/s: Encryption, Storage Engine - InnoDB
Affects Version/s: 10.7.3, 10.7.4, 10.7, 10.8
Fix Version/s: 10.7.5, 10.8.4

Type: Bug Priority: Major
Reporter: Christopher Mähler Assignee: Thirunarayanan Balathandayuthapani
Resolution: Fixed Votes: 0
Labels: None

Attachments: File crash.sql     Text File error.log    
Issue Links:
Relates
relates to MDEV-24621 In bulk insert, pre-sort and build in... Closed
relates to MDEV-28321 After upgrade to 10.7.3-1 and renabli... Closed

 Description   

After an upgrade from 10.6.7 to 10.7.3 we have attempted to export and import a dump. This fails on import with errors like "ERROR 2013 (HY000) at line 13654: Lost connection to server during query". The mariadb crashed on import (error log attached). We than upgraded to 10.7.4 and the import fails too.

This issue has only manifested with data-at-rest encryption enabled and key checks settings in dump file on an table with more than 58254 table rows (example dump attached).

Data at rest encryption was enabled with:

File Key Management

plugin_load_add = file_key_management
 
file_key_management_filename = /etc/mysql/enc/keys.enc
 
file_key_management_filekey = FILE:/etc/mysql/enc/.key
 
file_key_management_encryption_algorithm = aes_cbc

InnoDB/XtraDB Encryption

encrypt_binlog            = ON
 
encrypt_tmp_disk_tables   = ON
 
encrypt_tmp_files         = ON
 
innodb_encrypt_log        = ON
 
innodb_encrypt_tables     = ON
 
innodb_encryption_threads = 2



 Comments   
Comment by Elena Stepanova [ 2022-05-27 ]

Thanks for the report and the test case, reproducible as described.
For the failure to happen, the following options are enough, otherwise default:

--innodb-encrypt-log=1  --plugin-load-add=file_key_management --file_key_management_filename=`pwd`/mysql-test/std_data/keys.txt

The problem is apparently related to bulk insert, as it only happens with UNIQUE_CHECKS=0, FOREIGN_KEY_CHECKS=0 which mysqldump sets.

10.7 61727fa4

 
#3  <signal handler called>
 
#4  0x00007fe99c8ad0d3 in ?? () from /lib/x86_64-linux-gnu/libcrypto.so.1.1
 
#5  0x00007fe99c986ddc in ?? () from /lib/x86_64-linux-gnu/libcrypto.so.1.1
 
#6  0x00007fe99c995e8b in ?? () from /lib/x86_64-linux-gnu/libcrypto.so.1.1
 
#7  0x00005634ebf5071e in MyCTX::update (this=0x7fe984a13d00, src=0x7fe9760f3000 "\001", slen=1048576, dst=0x0, dlen=0x7fe984a13fe0) at /data/src/10.7/mysys_ssl/my_crypt.cc:83
 
#8  0x00005634ebf50aab in MyCTX_nopad::update (this=0x7fe984a13d00, src=0x7fe9760f3000 "\001", slen=1048576, dst=0x0, dlen=0x7fe984a13fe0) at /data/src/10.7/mysys_ssl/my_crypt.cc:147
 
#9  0x00005634ebf50253 in my_aes_crypt_update (ctx=0x7fe984a13d00, src=0x7fe9760f3000 "\001", slen=1048576, dst=0x0, dlen=0x7fe984a13fe0) at /data/src/10.7/mysys_ssl/my_crypt.cc:308
 
#10 0x00007fe99c16dc14 in ctx_update (ctx=0x7fe984a13d00, src=0x7fe9760f3000 "\001", slen=1048576, dst=0x0, dlen=0x7fe984a13fe0) at /data/src/10.7/plugin/file_key_management/file_key_management_plugin.cc:145
 
#11 0x00005634ec14bc27 in encryption_crypt (src=0x7fe9760f3000 "\001", slen=1048576, dst=0x0, dlen=0x7fe984a14078, key=0x5634eda919c0 <info+32> "\264\233\347\332\071P\330dş\357d7\336Y\325\316\301", <incomplete sequence \314>, klen=16, iv=0x7fe984a14080 "", ivlen=16, flags=3, key_id=1, key_version=1) at /data/src/10.7/include/mysql/service_encryption.h:119
 
#12 0x00005634ec14cf54 in log_tmp_block_encrypt (src=0x7fe9760f3000 "\001", size=1048576, dst=0x0, offs=0, encrypt=true) at /data/src/10.7/storage/innobase/log/log0crypt.cc:410
 
#13 0x00005634ec1fb526 in row_merge_write (fd=..., offset=0, buf=0x7fe9760f3000, crypt_buf=0x0, space=5) at /data/src/10.7/storage/innobase/row/row0merge.cc:1303
 
#14 0x00005634ec209f1a in row_merge_bulk_t::write_to_tmp_file (this=0x7fe94c0755c0, index_no=0) at /data/src/10.7/storage/innobase/row/row0merge.cc:5154
 
#15 0x00005634ec20a123 in row_merge_bulk_t::bulk_insert_buffered (this=0x7fe94c0755c0, row=..., ind=..., trx=0x7fe987218b80) at /data/src/10.7/storage/innobase/row/row0merge.cc:5216
 
#16 0x00005634ec1f09b6 in trx_mod_table_time_t::bulk_insert_buffered (this=0x7fe94c023980, entry=..., index=..., trx=0x7fe987218b80) at /data/src/10.7/storage/innobase/include/trx0trx.h:510
 
#17 0x00005634ec1ee59c in row_ins_index_entry (index=0x7fe94c071e78, entry=0x7fe94c070c78, thr=0x7fe94cc4f088) at /data/src/10.7/storage/innobase/row/row0ins.cc:3284
 
#18 0x00005634ec1eee93 in row_ins_index_entry_step (node=0x7fe94cc4ee70, thr=0x7fe94cc4f088) at /data/src/10.7/storage/innobase/row/row0ins.cc:3457
 
#19 0x00005634ec1ef3cf in row_ins (node=0x7fe94cc4ee70, thr=0x7fe94cc4f088) at /data/src/10.7/storage/innobase/row/row0ins.cc:3604
 
#20 0x00005634ec1efcd7 in row_ins_step (thr=0x7fe94cc4f088) at /data/src/10.7/storage/innobase/row/row0ins.cc:3750
 
#21 0x00005634ec212ede in row_insert_for_mysql (mysql_rec=0x7fe94cc4dc88 "\377\217", <incomplete sequence \343>, prebuilt=0x7fe94cc4e978, ins_mode=ROW_INS_NORMAL) at /data/src/10.7/storage/innobase/row/row0mysql.cc:1318
 
#22 0x00005634ec053685 in ha_innobase::write_row (this=0x7fe94cc4e110, record=0x7fe94cc4dc88 "\377\217", <incomplete sequence \343>) at /data/src/10.7/storage/innobase/handler/ha_innodb.cc:7896
 
#23 0x00005634ebc82b41 in handler::ha_write_row (this=0x7fe94cc4e110, buf=0x7fe94cc4dc88 "\377\217", <incomplete sequence \343>) at /data/src/10.7/sql/handler.cc:7546
 
#24 0x00005634eb8758b0 in write_record (thd=0x7fe94c000db8, table=0x7fe94c06c9a8, info=0x7fe984a14c90, sink=0x0) at /data/src/10.7/sql/sql_insert.cc:2161
 
#25 0x00005634eb87256f in mysql_insert (thd=0x7fe94c000db8, table_list=0x7fe94c0157f0, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=false, result=0x0) at /data/src/10.7/sql/sql_insert.cc:1132
 
#26 0x00005634eb8c616d in mysql_execute_command (thd=0x7fe94c000db8, is_called_from_prepared_stmt=false) at /data/src/10.7/sql/sql_parse.cc:4562
 
#27 0x00005634eb8d1ac7 in mysql_parse (thd=0x7fe94c000db8, rawbuf=0x7fe94c0f4260 "INSERT INTO `test` VALUES\n(1),\n(2),\n(3),\n(4),\n(5),\n(6),\n(7),\n(8),\n(9),\n(10),\n(11),\n(12),\n(13),\n(14),\n(15),\n(16),\n(17),\n(18),\n(19),\n(20),\n(21),\n(22),\n(23),\n(24),\n(25),\n(26),\n(27),\n(28),\n(29),\n(30),\n(31"..., length=513213, parser_state=0x7fe984a15500) at /data/src/10.7/sql/sql_parse.cc:8027
 
#28 0x00005634eb8be154 in dispatch_command (command=COM_QUERY, thd=0x7fe94c000db8, packet=0x7fe94c0761a9 "INSERT INTO `test` VALUES\n(1),\n(2),\n(3),\n(4),\n(5),\n(6),\n(7),\n(8),\n(9),\n(10),\n(11),\n(12),\n(13),\n(14),\n(15),\n(16),\n(17),\n(18),\n(19),\n(20),\n(21),\n(22),\n(23),\n(24),\n(25),\n(26),\n(27),\n(28),\n(29),\n(30),\n(31"..., packet_length=513213, blocking=true) at /data/src/10.7/sql/sql_parse.cc:1894
 
#29 0x00005634eb8bcb4f in do_command (thd=0x7fe94c000db8, blocking=true) at /data/src/10.7/sql/sql_parse.cc:1407
 
#30 0x00005634eba8dcea in do_handle_one_connection (connect=0x5634ee981ad8, put_in_cache=true) at /data/src/10.7/sql/sql_connect.cc:1418
 
#31 0x00005634eba8d989 in handle_one_connection (arg=0x5634ee9e0bc8) at /data/src/10.7/sql/sql_connect.cc:1312
 
#32 0x00005634ebf77ff0 in pfs_spawn_thread (arg=0x5634ee8f2a08) at /data/src/10.7/storage/perfschema/pfs.cc:2201
 
#33 0x00007fe99c7f4ea7 in start_thread (arg=<optimized out>) at pthread_create.c:477
 
#34 0x00007fe99c3f3def in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Comment by Marko Mäkelä [ 2022-05-27 ]

elenst, thank you for the analysis. I think that this should be related to MDEV-24621.

Comment by Thirunarayanan Balathandayuthapani [ 2022-07-18 ]

Patch is in bb-10.7-MDEV-28242

Comment by Marko Mäkelä [ 2022-07-25 ]

OK to push. I plan to separately push the DBUG_RETURN fix to 10.3. Good that someone is building without -DWITH_DBUG_TRACE=OFF as long as that instrumentation exists.

Generated at Thu Feb 08 10:02:39 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.