[MDEV-13537] InnoDB: Failing assertion: event after recovery with encrypted/compressed tables Created: 2017-08-15  Updated: 2021-10-26  Resolved: 2021-10-26

Status: Closed
Project: MariaDB Server
Component/s: Encryption, Storage Engine - InnoDB
Affects Version/s: 10.1
Fix Version/s: 10.1.27, 10.2.9, 10.3.2

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: None

Attachments: File data.tar.gz     File mysql.log.gz    
Issue Links:
Relates
relates to MDEV-8575 MySQL refuse to start after a crash Closed

 Description   

10.1 48fe832650ae2dc0c2eaa957abfa959b0a2670aa

 
2017-08-15 17:47:15 140020824916096 [Note] InnoDB: Highest supported file format is Barracuda.
 
2017-08-15 17:47:15 140020824916096 [Note] InnoDB: Starting crash recovery from checkpoint LSN=5650983
 
2017-08-15 17:47:15 140020824916096 [Note] InnoDB: Restoring possible half-written data pages from the doublewrite buffer...
 
2017-08-15 17:47:16 140020824916096 [Note] InnoDB: Starting final batch to recover 181 pages from redo log
 
2017-08-15 17:47:17 140020824916096 [Note] InnoDB: 128 rollback segment(s) are active.
 
2017-08-15 17:47:17 140020824916096 [Note] InnoDB: Waiting for purge to start
 
2017-08-15 17:47:17 140020824916096 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.36-82.1 started; log sequence number 5713096
 
2017-08-15 17:47:18 7f592387c080  InnoDB: Assertion failure in thread 140020824916096 in file os0sync.cc line 339
 
InnoDB: Failing assertion: event
 
InnoDB: We intentionally generate a memory trap.


#4  0x00007f59214f93fa in abort () from /lib/x86_64-linux-gnu/libc.so.6
 
#5  0x00005627ba5ab0e7 in os_event_set (event=0x0) at /data/src/10.1/storage/xtradb/os/os0sync.cc:339
 
#6  0x00005627ba787604 in fil_crypt_get_latest_key_version (crypt_data=0x7f5920c3ab78) at /data/src/10.1/storage/xtradb/fil/fil0crypt.cc:194
 
#7  0x00005627ba788101 in fil_encrypt_buf (crypt_data=0x7f5920c3ab78, space=1, offset=1, lsn=5693532, src_frame=0x7f590d7c2000 "X", <incomplete sequence \353\230>, zip_size=0, dst_frame=0x7f5902718000 "") at /data/src/10.1/storage/xtradb/fil/fil0crypt.cc:589
 
#8  0x00005627ba7884ba in fil_space_encrypt (space=0x7f590efb4c78, offset=1, lsn=5693532, src_frame=0x7f590d7c2000 "X", <incomplete sequence \353\230>, dst_frame=0x7f5902718000 "") at /data/src/10.1/storage/xtradb/fil/fil0crypt.cc:700
 
#9  0x00005627ba70c272 in buf_page_encrypt_before_write (space=0x7f590efb4c78, bpage=0x7f5905b55408, src_frame=0x7f590d7c2000 "X", <incomplete sequence \353\230>) at /data/src/10.1/storage/xtradb/buf/buf0buf.cc:6336
 
#10 0x00005627ba717f23 in buf_flush_write_block_low (bpage=0x7f5905b55408, flush_type=BUF_FLUSH_LIST, sync=false) at /data/src/10.1/storage/xtradb/buf/buf0flu.cc:954
 
#11 0x00005627ba718533 in buf_flush_page (buf_pool=0x7f5920c91478, bpage=0x7f5905b55408, flush_type=BUF_FLUSH_LIST, sync=false) at /data/src/10.1/storage/xtradb/buf/buf0flu.cc:1130
 
#12 0x00005627ba718b05 in buf_flush_try_neighbors (space=1, offset=3, flush_type=BUF_FLUSH_LIST, n_flushed=35, n_to_flush=100) at /data/src/10.1/storage/xtradb/buf/buf0flu.cc:1345
 
#13 0x00005627ba718e2a in buf_flush_page_and_try_neighbors (bpage=0x7f5905b549f8, flush_type=BUF_FLUSH_LIST, n_to_flush=100, count=0x7fff2e1ab8b8) at /data/src/10.1/storage/xtradb/buf/buf0flu.cc:1433
 
#14 0x00005627ba719914 in buf_do_flush_list_batch (buf_pool=0x7f5920c91478, min_n=100, lsn_limit=18446744073709551615) at /data/src/10.1/storage/xtradb/buf/buf0flu.cc:1762
 
#15 0x00005627ba719cab in buf_flush_batch (buf_pool=0x7f5920c91478, flush_type=BUF_FLUSH_LIST, min_n=100, lsn_limit=18446744073709551615, limited_lru_scan=false, n=0x7fff2e1ab990) at /data/src/10.1/storage/xtradb/buf/buf0flu.cc:1838
 
#16 0x00005627ba71a3d7 in buf_flush_list (min_n=18446744073709551614, lsn_limit=18446744073709551615, n_processed=0x7fff2e1abc18) at /data/src/10.1/storage/xtradb/buf/buf0flu.cc:2118
 
#17 0x00005627ba580522 in log_preflush_pool_modified_pages (new_oldest=18446744073709551615) at /data/src/10.1/storage/xtradb/log/log0log.cc:1863
 
#18 0x00005627ba58180a in log_make_checkpoint_at (lsn=18446744073709551615, write_always=1) at /data/src/10.1/storage/xtradb/log/log0log.cc:2347
 
#19 0x00005627ba675a1f in innobase_start_or_create_for_mysql () at /data/src/10.1/storage/xtradb/srv/srv0start.cc:3091
 
#20 0x00005627ba506008 in innobase_init (p=0x7f5920c36a70) at /data/src/10.1/storage/xtradb/handler/ha_innodb.cc:4452
 
#21 0x00005627ba1d3183 in ha_initialize_handlerton (plugin=0x7f5920f24880) at /data/src/10.1/sql/handler.cc:513
 
#22 0x00005627b9faecb0 in plugin_initialize (tmp_root=0x7fff2e1af930, plugin=0x7f5920f24880, argc=0x5627bb22f7f0 <remaining_argc>, argv=0x7f5920c33438, options_only=false) at /data/src/10.1/sql/sql_plugin.cc:1406
 
#23 0x00005627b9faf899 in plugin_init (argc=0x5627bb22f7f0 <remaining_argc>, argv=0x7f5920c33438, flags=2) at /data/src/10.1/sql/sql_plugin.cc:1684
 
#24 0x00005627b9ece1f7 in init_server_components () at /data/src/10.1/sql/mysqld.cc:5154
 
#25 0x00005627b9ecf262 in mysqld_main (argc=13, argv=0x7f5920c33438) at /data/src/10.1/sql/mysqld.cc:5741
 
#26 0x00005627b9ec4930 in main (argc=12, argv=0x7fff2e1b06c8) at /data/src/10.1/sql/main.cc:25

To reproduce, unpack the attached datadir and start the server on it with the options as below (don't forget to change the path for file-key-management-filename to keys.txt from MTR.

--no-defaults \
 
--file-key-management \
 
--file-key-management-filename=/data/bld/encryption_keys.txt \
 
--plugin-load-add=file_key_management.so \
 
--innodb-encrypt-tables \
 
--innodb-encryption-threads=4 \
 
--innodb-page-size=8K

This is how the data directory was produced:

  • a recent 10.1 server with the same options was started;
  • some tables were created, some of them with PAGE_COMPRESSED;
  • the tables were populated with 0-1000 rows;
  • concurrent DML in 4 threads was run for ~2 minutes;
  • the server was SIGKILLed while the DML was running

The general log of everything that happened on the server before the crash is attached.

Reproducible on non-debug builds as well.

 Comments   
Comment by Marko Mäkelä [ 2021-10-26 ]

It turns out that this had been fixed as part of MDEV-13591, by adding a condition around the os_event_set() call in fil_crypt_get_latest_key_version(). It is even mentioned in the commit message.

Generated at Thu Feb 08 08:06:21 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.