[MDEV-12967] innodb-encryption-threads with scrubbing crashes server - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Major
Resolution: Won't Fix
Affects Version/s: 10.2.6, 10.2(EOL), 10.3(EOL), 10.4(EOL)
Fix Version/s: 10.5.5
Component/s: Encryption, Storage Engine - InnoDB
Labels:
None
Environment:
win7 x64, 32GB ram, SSD

Description

If I set innodb-encryption-threads to any positive number, mariadb crashes a few minutes after the first innodb-background-scrub-data-check-interval occurs, with this in the log:

170601  8:26:17 [ERROR] mysqld got exception 0xc0000005 ;

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 https://mariadb.com/kb/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.2.6-MariaDB-log

key_buffer_size=134217728

read_buffer_size=131072

max_used_connections=0

max_threads=65537

thread_count=12

It is possible that mysqld could use up to

key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 136026 K  bytes of memory

Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x0

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...

mysqld.exe!btr_scrub_free_page()[btr0scrub.cc:683]

mysqld.exe!btr_scrub_recheck_page()[btr0scrub.cc:720]

mysqld.exe!fil_crypt_rotate_page()[fil0crypt.cc:1827]

mysqld.exe!fil_crypt_rotate_pages()[fil0crypt.cc:1913]

mysqld.exe!fil_crypt_thread()[fil0crypt.cc:2160]

kernel32.dll!BaseThreadInitThunk()

ntdll.dll!RtlUserThreadStart()

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.

I have tried different values (0-8) for innodb-encryption-threads and all except 0 caused the crash approx 65 minutes after startup. When I set innodb-background-scrub-data-check-interval to 300, the crash occurs at 7-8 minute after startup, so something would appear to be triggered after, or as a result of, the check interval.
Unsetting (or explicitly setting to 0) innodb-encryption-threads (the only change in config) crash never occurs.

Attachments

- Sort By Name
- Sort By Date
- Ascending
- Descending
- Thumbnails
- List
- Download All

limelight.err
49 kB
2017-06-06 07:11
my.ini
4 kB
2017-06-06 07:11

Issue Links

relates to

MDEV-17596 Assertion `block->page.flush_observer == __null || block->page.flush_observer == observer' failed in buf_flush_note_modification

Closed

Activity

Ascending order - Click to sort in descending order

Elena Stepanova added a comment - 2017-06-05 14:40

Could you please attach your cnf file(s) and the whole error log from server startup till the end of the crash report?
Thanks.

Elena Stepanova added a comment - 2017-06-05 14:40 Could you please attach your cnf file(s) and the whole error log from server startup till the end of the crash report? Thanks.

Andrew Ramsay added a comment - 2017-06-06 07:13

Files attached - the error log shows the change in crash time when I altered innodb_background_scrub_data_check_interval to be 300 in ini file - now commented out for default value

Andrew Ramsay added a comment - 2017-06-06 07:13 Files attached - the error log shows the change in crash time when I altered innodb_background_scrub_data_check_interval to be 300 in ini file - now commented out for default value

Elena Stepanova added a comment - 2017-06-10 20:37

Thanks for the report and provided information, I can reproduce it.

Apparently it affects Windows, but not Linux – at least it crashes reliably for me on Windows and does not crash on Debian Jessie.

Test case
--source include/have_innodb.inc
--source suite/encryption/include/have_file_key_management_plugin.inc

set global innodb_background_scrub_data_uncompressed= on;
set global innodb_background_scrub_data_check_interval= 10;
set global innodb_encrypt_tables= on;
set global innodb_encryption_threads= 1;

create table t2 (pk int auto_increment primary key, t varchar(128)) engine=InnoDB;
insert into t2 values (null, 'foo'),(null, 'bar');
insert into t2 select null, t from t2;
insert into t2 select null, t from t2;
insert into t2 select null, t from t2;
insert into t2 select null, t from t2;
insert into t2 select null, t from t2;
insert into t2 select null, t from t2;
insert into t2 select null, t from t2;
insert into t2 select null, t from t2;
insert into t2 select null, t from t2;
insert into t2 select null, t from t2;
insert into t2 select null, t from t2;
insert into t2 select null, t from t2;
delete from t2;

--sleep 15

set global innodb_background_scrub_data_uncompressed= DEFAULT;
set global innodb_background_scrub_data_check_interval= DEFAULT;
set global innodb_encrypt_tables= DEFAULT;
set global innodb_encryption_threads= DEFAULT;

10.2 b175c41cde
Assertion failed: index, file c:\_home\10.2\storage\innobase\include\dict0dict.ic, line 352
170610 23:21:51 [ERROR] mysqld got exception 0x80000003 ;

mysqld.exe!abort() Line 71 C++
mysqld.exe!common_assert_to_stderr<wchar_t>(const wchar_t * const expression, const wchar_t * const file_name, const unsigned int line_number) Line 149 C++
[Inline Frame] mysqld.exe!common_assert(const wchar_t * const return_address, const wchar_t * const) Line 383 C++
mysqld.exe!_wassert(const wchar_t * expression, const wchar_t * file_name, unsigned int line_number) Line 404 C++
mysqld.exe!dict_index_is_spatial(const dict_index_t * index) Line 352 C++
mysqld.exe!btr_scrub_free_page(btr_scrub_t * scrub_data, buf_block_t * block, mtr_t * mtr) Line 683 C++
mysqld.exe!btr_scrub_recheck_page(btr_scrub_t * scrub_data, buf_block_t * block, btr_scrub_page_allocation_status_t allocated, mtr_t * mtr) Line 720 C++
mysqld.exe!fil_crypt_rotate_page(const key_state_t * key_state, rotate_thread_t * state) Line 1804 C++
mysqld.exe!fil_crypt_rotate_pages(const key_state_t * key_state, rotate_thread_t * state) Line 1906 C++
mysqld.exe!fil_crypt_thread(void * arg) Line 2137 C++

Not reproducible on 10.1 58c56dd7f.

Elena Stepanova added a comment - 2017-06-10 20:37 Thanks for the report and provided information, I can reproduce it. Apparently it affects Windows, but not Linux – at least it crashes reliably for me on Windows and does not crash on Debian Jessie. Test case --source include/have_innodb.inc --source suite/encryption/include/have_file_key_management_plugin.inc set global innodb_background_scrub_data_uncompressed= on ; set global innodb_background_scrub_data_check_interval= 10; set global innodb_encrypt_tables= on ; set global innodb_encryption_threads= 1; create table t2 (pk int auto_increment primary key , t varchar (128)) engine=InnoDB; insert into t2 values ( null , 'foo' ),( null , 'bar' ); insert into t2 select null , t from t2; insert into t2 select null , t from t2; insert into t2 select null , t from t2; insert into t2 select null , t from t2; insert into t2 select null , t from t2; insert into t2 select null , t from t2; insert into t2 select null , t from t2; insert into t2 select null , t from t2; insert into t2 select null , t from t2; insert into t2 select null , t from t2; insert into t2 select null , t from t2; insert into t2 select null , t from t2; delete from t2; --sleep 15 set global innodb_background_scrub_data_uncompressed= DEFAULT ; set global innodb_background_scrub_data_check_interval= DEFAULT ; set global innodb_encrypt_tables= DEFAULT ; set global innodb_encryption_threads= DEFAULT ; 10.2 b175c41cde Assertion failed: index, file c:\_home\10.2\storage\innobase\include\dict0dict.ic, line 352 170610 23:21:51 [ERROR] mysqld got exception 0x80000003 ; mysqld.exe!abort() Line 71 C++ mysqld.exe!common_assert_to_stderr<wchar_t>(const wchar_t * const expression, const wchar_t * const file_name, const unsigned int line_number) Line 149 C++ [Inline Frame] mysqld.exe!common_assert(const wchar_t * const return_address, const wchar_t * const) Line 383 C++ mysqld.exe!_wassert(const wchar_t * expression, const wchar_t * file_name, unsigned int line_number) Line 404 C++ mysqld.exe!dict_index_is_spatial(const dict_index_t * index) Line 352 C++ mysqld.exe!btr_scrub_free_page(btr_scrub_t * scrub_data, buf_block_t * block, mtr_t * mtr) Line 683 C++ mysqld.exe!btr_scrub_recheck_page(btr_scrub_t * scrub_data, buf_block_t * block, btr_scrub_page_allocation_status_t allocated, mtr_t * mtr) Line 720 C++ mysqld.exe!fil_crypt_rotate_page(const key_state_t * key_state, rotate_thread_t * state) Line 1804 C++ mysqld.exe!fil_crypt_rotate_pages(const key_state_t * key_state, rotate_thread_t * state) Line 1906 C++ mysqld.exe!fil_crypt_thread(void * arg) Line 2137 C++ Not reproducible on 10.1 58c56dd7f.

Elena Stepanova added a comment - 2019-09-06 16:20 - edited

Here is a test case which reproduces the same failure on Linux.

It is very similar to the test case from ~~MDEV-17596~~, except that this one has ENCRYPTED=YES for the table instead of --mysqld=--innodb-encrypt-tables as a startup option.

Other instructions from ~~MDEV-17596~~ apply:

The test case is non-deterministic and it uses a loop. Please don't put it into the regression suite, it's for reproducing purposes only.
Run with --repeat=N if it doesn't fail right away. It usually fails for me within 5 attempts. Increasing the number of loops doesn't seem to increase the probability. Make sure the server is restarted between attempts (in the test case below, the commented part of the cleanup makes sure of that).
Run with --mem or on SSD. I don't know if it's reproducible on a spinning disk, the test case takes too long.

Remember to run with encryption options.

Run with

--mysqld=--innodb-encryption-threads=4    --mysqld=--file-key-management  --mysqld=--plugin-load-add=file_key_management --mysqld=--file-key-management-filename=`pwd`/std_data/keys.txt --mysqld=--plugin-load-add=file_key_management --repeat=10 --mem

--source include/have_innodb.inc

SET @scrub.save= @@innodb_background_scrub_data_uncompressed;

--connect (con1,localhost,root,,)

CREATE TABLE t1 (pk INT, a INT, PRIMARY KEY(pk)) ENGINE=InnoDB ENCRYPTED=YES;

INSERT INTO t1 VALUES (1,2),(2,3),(3,4),(4,5),(5,6),(6,7),(7,8),(8,9);

SET GLOBAL innodb_background_scrub_data_uncompressed=ON;

--disconnect con1

--connection default

--let $i= 1000

while ($i)

   --eval ALTER TABLE t1 FORCE /* $i */

   --dec $i

# Cleanup

--delimiter ;

DROP TABLE t1;

# This is intentionally commented, so that when you run with --repeat,

# the server is restarted every time between the runs

# SET GLOBAL innodb_background_scrub_data_uncompressed = @scrub.save;

10.2 41e351f6 debug
3 <signal handler called>
#4 0x00005563c0ca89f8 in dict_index_is_spatial (index=0x0) at /data/src/10.2/storage/innobase/include/dict0dict.ic:290
#5 0x00005563c0caa590 in btr_scrub_free_page (scrub_data=0x7fd06d7f9eb0, block=0x7fd0837a0a40, mtr=0x7fd06d7f9890) at /data/src/10.2/storage/innobase/btr/btr0scrub.cc:680
#6 0x00005563c0caa63d in btr_scrub_recheck_page (scrub_data=0x7fd06d7f9eb0, block=0x7fd0837a0a40, allocated=BTR_SCRUB_PAGE_FREE, mtr=0x7fd06d7f9890) at /data/src/10.2/storage/innobase/btr/btr0scrub.cc:717
#7 0x00005563c0d62435 in fil_crypt_rotate_page (key_state=0x7fd06d7f9e34, state=0x7fd06d7f9e40) at /data/src/10.2/storage/innobase/fil/fil0crypt.cc:1858
#8 0x00005563c0d6287a in fil_crypt_rotate_pages (key_state=0x7fd06d7f9e34, state=0x7fd06d7f9e40) at /data/src/10.2/storage/innobase/fil/fil0crypt.cc:1965
#9 0x00005563c0d6322e in fil_crypt_thread () at /data/src/10.2/storage/innobase/fil/fil0crypt.cc:2194
#10 0x00007fd08ef674a4 in start_thread (arg=0x7fd06d7fa700) at pthread_create.c:456
#11 0x00007fd08d4afd0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97

Stack trace on current 10.4 (slightly different, just enough that JIRA doesn't find the bug upon search):

10.4 899c843f
#3 <signal handler called>
#4 0x0000556f593aec00 in dict_index_t::is_spatial (this=0x0) at /data/src/10.4/storage/innobase/include/dict0mem.h:1121
#5 0x0000556f59670963 in btr_scrub_free_page (scrub_data=0x7f1a96ffceb0, block=0x7f1aba486460, mtr=0x7f1a96ffc8a0) at /data/src/10.4/storage/innobase/btr/btr0scrub.cc:674
#6 0x0000556f59670a0a in btr_scrub_recheck_page (scrub_data=0x7f1a96ffceb0, block=0x7f1aba486460, allocated=BTR_SCRUB_PAGE_FREE, mtr=0x7f1a96ffc8a0) at /data/src/10.4/storage/innobase/btr/btr0scrub.cc:711
#7 0x0000556f5974cf57 in fil_crypt_rotate_page (key_state=0x7f1a96ffce34, state=0x7f1a96ffce40) at /data/src/10.4/storage/innobase/fil/fil0crypt.cc:2068
#8 0x0000556f5974d560 in fil_crypt_rotate_pages (key_state=0x7f1a96ffce34, state=0x7f1a96ffce40) at /data/src/10.4/storage/innobase/fil/fil0crypt.cc:2175
#9 0x0000556f5974e017 in fil_crypt_thread () at /data/src/10.4/storage/innobase/fil/fil0crypt.cc:2399
#10 0x00007f1ac6c984a4 in start_thread (arg=0x7f1a96ffd700) at pthread_create.c:456
#11 0x00007f1ac51dfd0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97

Elena Stepanova added a comment - 2019-09-06 16:20 - edited Here is a test case which reproduces the same failure on Linux. It is very similar to the test case from MDEV-17596 , except that this one has ENCRYPTED=YES for the table instead of --mysqld=--innodb-encrypt-tables as a startup option. Other instructions from MDEV-17596 apply: The test case is non-deterministic and it uses a loop. Please don't put it into the regression suite, it's for reproducing purposes only. Run with --repeat=N if it doesn't fail right away. It usually fails for me within 5 attempts. Increasing the number of loops doesn't seem to increase the probability. Make sure the server is restarted between attempts (in the test case below, the commented part of the cleanup makes sure of that). Run with --mem or on SSD. I don't know if it's reproducible on a spinning disk, the test case takes too long. Remember to run with encryption options. Run with --mysqld=--innodb-encryption-threads=4 --mysqld=--file-key-management --mysqld=--plugin-load-add=file_key_management --mysqld=--file-key-management-filename=`pwd`/std_data/keys.txt --mysqld=--plugin-load-add=file_key_management --repeat=10 --mem --source include/have_innodb.inc SET @scrub.save= @@innodb_background_scrub_data_uncompressed; --connect (con1,localhost,root,,) CREATE TABLE t1 (pk INT , a INT , PRIMARY KEY (pk)) ENGINE=InnoDB ENCRYPTED=YES; INSERT INTO t1 VALUES (1,2),(2,3),(3,4),(4,5),(5,6),(6,7),(7,8),(8,9); SET GLOBAL innodb_background_scrub_data_uncompressed= ON ; --disconnect con1 --connection default --let $i= 1000 while ($i) { --eval ALTER TABLE t1 FORCE /* $i */ --dec $i } # Cleanup --delimiter ; DROP TABLE t1; # This is intentionally commented, so that when you run with --repeat, # the server is restarted every time between the runs # SET GLOBAL innodb_background_scrub_data_uncompressed = @scrub.save; 10.2 41e351f6 debug 3 <signal handler called> #4 0x00005563c0ca89f8 in dict_index_is_spatial (index=0x0) at /data/src/10.2/storage/innobase/include/dict0dict.ic:290 #5 0x00005563c0caa590 in btr_scrub_free_page (scrub_data=0x7fd06d7f9eb0, block=0x7fd0837a0a40, mtr=0x7fd06d7f9890) at /data/src/10.2/storage/innobase/btr/btr0scrub.cc:680 #6 0x00005563c0caa63d in btr_scrub_recheck_page (scrub_data=0x7fd06d7f9eb0, block=0x7fd0837a0a40, allocated=BTR_SCRUB_PAGE_FREE, mtr=0x7fd06d7f9890) at /data/src/10.2/storage/innobase/btr/btr0scrub.cc:717 #7 0x00005563c0d62435 in fil_crypt_rotate_page (key_state=0x7fd06d7f9e34, state=0x7fd06d7f9e40) at /data/src/10.2/storage/innobase/fil/fil0crypt.cc:1858 #8 0x00005563c0d6287a in fil_crypt_rotate_pages (key_state=0x7fd06d7f9e34, state=0x7fd06d7f9e40) at /data/src/10.2/storage/innobase/fil/fil0crypt.cc:1965 #9 0x00005563c0d6322e in fil_crypt_thread () at /data/src/10.2/storage/innobase/fil/fil0crypt.cc:2194 #10 0x00007fd08ef674a4 in start_thread (arg=0x7fd06d7fa700) at pthread_create.c:456 #11 0x00007fd08d4afd0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97 Stack trace on current 10.4 (slightly different, just enough that JIRA doesn't find the bug upon search): 10.4 899c843f #3 <signal handler called> #4 0x0000556f593aec00 in dict_index_t::is_spatial (this=0x0) at /data/src/10.4/storage/innobase/include/dict0mem.h:1121 #5 0x0000556f59670963 in btr_scrub_free_page (scrub_data=0x7f1a96ffceb0, block=0x7f1aba486460, mtr=0x7f1a96ffc8a0) at /data/src/10.4/storage/innobase/btr/btr0scrub.cc:674 #6 0x0000556f59670a0a in btr_scrub_recheck_page (scrub_data=0x7f1a96ffceb0, block=0x7f1aba486460, allocated=BTR_SCRUB_PAGE_FREE, mtr=0x7f1a96ffc8a0) at /data/src/10.4/storage/innobase/btr/btr0scrub.cc:711 #7 0x0000556f5974cf57 in fil_crypt_rotate_page (key_state=0x7f1a96ffce34, state=0x7f1a96ffce40) at /data/src/10.4/storage/innobase/fil/fil0crypt.cc:2068 #8 0x0000556f5974d560 in fil_crypt_rotate_pages (key_state=0x7f1a96ffce34, state=0x7f1a96ffce40) at /data/src/10.4/storage/innobase/fil/fil0crypt.cc:2175 #9 0x0000556f5974e017 in fil_crypt_thread () at /data/src/10.4/storage/innobase/fil/fil0crypt.cc:2399 #10 0x00007f1ac6c984a4 in start_thread (arg=0x7f1a96ffd700) at pthread_create.c:456 #11 0x00007f1ac51dfd0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97

Elena Stepanova added a comment - 2020-07-30 00:42 - edited

Here is yet another variation which will probably never get fixed, adding for a record.

# Run with

# --mysqld=--innodb-encrypt-tables --mysqld=--innodb-encrypt-log --mysqld=--innodb-encryption-threads=4  --mysqld=--file-key-management-filename=`pwd`/std_data/keys.txt --mysqld=--plugin-load-add=file_key_management --repeat=N

# with high enough repeat=N

--source include/have_innodb.inc

CREATE TABLE t1 (a VARCHAR(27126)) ENGINE=InnoDB;

--sleep 3

SET GLOBAL innodb_background_scrub_data_uncompressed= 1;

SHOW CREATE TABLE t1;

CREATE OR REPLACE TABLE t1 (b LINESTRING) ENGINE=InnoDB;

10.3 1656ea28
mysqld: /data/src/10.3/storage/innobase/include/mtr0log.ic:161: byte* mlog_write_initial_log_record_low(mlog_id_t, ulint, ulint, byte, mtr_t): Assertion `type == MLOG_FILE_NAME \|\| type == MLOG_FILE_DELETE \|\| type == MLOG_FILE_CREATE2 \|\| type == MLOG_FILE_RENAME2 \|\| type == MLOG_INDEX_LOAD \|\| type == MLOG_FILE_WRITE_CRYPT_DATA \|\| mtr->is_named_space(space_id)' failed.
200730 3:38:37 [ERROR] mysqld got signal 6 ;

#7 0x00007fd0ba5eef12 in __GI___assert_fail (assertion=0x5561edd53888 "type == MLOG_FILE_NAME \|\| type == MLOG_FILE_DELETE \|\| type == MLOG_FILE_CREATE2 \|\| type == MLOG_FILE_RENAME2 \|\| type == MLOG_INDEX_LOAD \|\| type == MLOG_FILE_WRITE_CRYPT_DATA \|\| mtr->is_named_space(spa"..., file=0x5561edd537d8 "/data/src/10.3/storage/innobase/include/mtr0log.ic", line=161, function=0x5561edd54360 <mlog_write_initial_log_record_low(mlog_id_t, unsigned long, unsigned long, unsigned char, mtr_t)::__PRETTY_FUNCTION__> "byte* mlog_write_initial_log_record_low(mlog_id_t, ulint, ulint, byte, mtr_t)") at assert.c:101
#8 0x00005561ed4f8c53 in mlog_write_initial_log_record_low (type=MLOG_WRITE_STRING, space_id=4278124286, page_no=4278124286, log_ptr=0x7fd094ff8b68 "\356\216\216\265\320\177", mtr=0x7fd094ff88e0) at /data/src/10.3/storage/innobase/include/mtr0log.ic:161
#9 0x00005561ed4f8ec4 in mlog_write_initial_log_record_fast (ptr=0x7fd0afd228bc "s\016\fREt", type=MLOG_WRITE_STRING, log_ptr=0x7fd094ff8b68 "\356\216\216\265\320\177", mtr=0x7fd094ff88e0) at /data/src/10.3/storage/innobase/include/mtr0log.ic:222
#10 0x00005561ed4fa0d2 in mlog_log_string (ptr=0x7fd0afd228bc "s\016\fREt", len=6, mtr=0x7fd094ff88e0) at /data/src/10.3/storage/innobase/mtr/mtr0log.cc:350
#11 0x00005561ed4f9f8b in mlog_write_string (ptr=0x7fd0afd228bc "s\016\fREt", str=0x5561ede44aea <_ZL11CRYPT_MAGIC> "s\016\fREt/data/src/10.3/storage/innobase/include/fil0crypt.h", len=6, mtr=0x7fd094ff88e0) at /data/src/10.3/storage/innobase/mtr/mtr0log.cc:323
#12 0x00005561ed7e5035 in fil_space_crypt_t::write_page0 (this=0x7fd058096930, space=0x7fd058096a70, page=0x7fd0afd20000 "", mtr=0x7fd094ff88e0) at /data/src/10.3/storage/innobase/fil/fil0crypt.cc:404
#13 0x00005561ed7e8b3f in fil_crypt_flush_space (state=0x7fd094ff8e40) at /data/src/10.3/storage/innobase/fil/fil0crypt.cc:1983
#14 0x00005561ed7e8f12 in fil_crypt_complete_rotate_space (state=0x7fd094ff8e40) at /data/src/10.3/storage/innobase/fil/fil0crypt.cc:2059
#15 0x00005561ed7e92d4 in fil_crypt_thread () at /data/src/10.3/storage/innobase/fil/fil0crypt.cc:2162
#16 0x00007fd0bc5774a4 in start_thread (arg=0x7fd094ff9700) at pthread_create.c:456
#17 0x00007fd0ba6abd0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97

Reproducible on 10.2-10.4, not seen on 10.5.

Elena Stepanova added a comment - 2020-07-30 00:42 - edited Here is yet another variation which will probably never get fixed, adding for a record. # Run with # --mysqld=--innodb-encrypt-tables --mysqld=--innodb-encrypt-log --mysqld=--innodb-encryption-threads=4 --mysqld=--file-key-management-filename=`pwd`/std_data/keys.txt --mysqld=--plugin-load-add=file_key_management --repeat=N # with high enough repeat=N --source include/have_innodb.inc CREATE TABLE t1 (a VARCHAR (27126)) ENGINE=InnoDB; --sleep 3 SET GLOBAL innodb_background_scrub_data_uncompressed= 1; SHOW CREATE TABLE t1; CREATE OR REPLACE TABLE t1 (b LINESTRING) ENGINE=InnoDB; 10.3 1656ea28 mysqld: /data/src/10.3/storage/innobase/include/mtr0log.ic:161: byte* mlog_write_initial_log_record_low(mlog_id_t, ulint, ulint, byte*, mtr_t*): Assertion `type == MLOG_FILE_NAME || type == MLOG_FILE_DELETE || type == MLOG_FILE_CREATE2 || type == MLOG_FILE_RENAME2 || type == MLOG_INDEX_LOAD || type == MLOG_FILE_WRITE_CRYPT_DATA || mtr->is_named_space(space_id)' failed. 200730 3:38:37 [ERROR] mysqld got signal 6 ; #7 0x00007fd0ba5eef12 in __GI___assert_fail (assertion=0x5561edd53888 "type == MLOG_FILE_NAME || type == MLOG_FILE_DELETE || type == MLOG_FILE_CREATE2 || type == MLOG_FILE_RENAME2 || type == MLOG_INDEX_LOAD || type == MLOG_FILE_WRITE_CRYPT_DATA || mtr->is_named_space(spa"..., file=0x5561edd537d8 "/data/src/10.3/storage/innobase/include/mtr0log.ic", line=161, function=0x5561edd54360 <mlog_write_initial_log_record_low(mlog_id_t, unsigned long, unsigned long, unsigned char*, mtr_t*)::__PRETTY_FUNCTION__> "byte* mlog_write_initial_log_record_low(mlog_id_t, ulint, ulint, byte*, mtr_t*)") at assert.c:101 #8 0x00005561ed4f8c53 in mlog_write_initial_log_record_low (type=MLOG_WRITE_STRING, space_id=4278124286, page_no=4278124286, log_ptr=0x7fd094ff8b68 "\356\216\216\265\320\177", mtr=0x7fd094ff88e0) at /data/src/10.3/storage/innobase/include/mtr0log.ic:161 #9 0x00005561ed4f8ec4 in mlog_write_initial_log_record_fast (ptr=0x7fd0afd228bc "s\016\fREt", type=MLOG_WRITE_STRING, log_ptr=0x7fd094ff8b68 "\356\216\216\265\320\177", mtr=0x7fd094ff88e0) at /data/src/10.3/storage/innobase/include/mtr0log.ic:222 #10 0x00005561ed4fa0d2 in mlog_log_string (ptr=0x7fd0afd228bc "s\016\fREt", len=6, mtr=0x7fd094ff88e0) at /data/src/10.3/storage/innobase/mtr/mtr0log.cc:350 #11 0x00005561ed4f9f8b in mlog_write_string (ptr=0x7fd0afd228bc "s\016\fREt", str=0x5561ede44aea <_ZL11CRYPT_MAGIC> "s\016\fREt/data/src/10.3/storage/innobase/include/fil0crypt.h", len=6, mtr=0x7fd094ff88e0) at /data/src/10.3/storage/innobase/mtr/mtr0log.cc:323 #12 0x00005561ed7e5035 in fil_space_crypt_t::write_page0 (this=0x7fd058096930, space=0x7fd058096a70, page=0x7fd0afd20000 "", mtr=0x7fd094ff88e0) at /data/src/10.3/storage/innobase/fil/fil0crypt.cc:404 #13 0x00005561ed7e8b3f in fil_crypt_flush_space (state=0x7fd094ff8e40) at /data/src/10.3/storage/innobase/fil/fil0crypt.cc:1983 #14 0x00005561ed7e8f12 in fil_crypt_complete_rotate_space (state=0x7fd094ff8e40) at /data/src/10.3/storage/innobase/fil/fil0crypt.cc:2059 #15 0x00005561ed7e92d4 in fil_crypt_thread () at /data/src/10.3/storage/innobase/fil/fil0crypt.cc:2162 #16 0x00007fd0bc5774a4 in start_thread (arg=0x7fd094ff9700) at pthread_create.c:456 #17 0x00007fd0ba6abd0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97 Reproducible on 10.2-10.4, not seen on 10.5.

Marko Mäkelä added a comment - 2020-08-12 08:57

I believe that the scrubbing feature never worked in its original design. ~~MDEV-15528~~ deprecated and ignored most scrubbing-related parameters and laid the correct groundwork, following the tried-and-true write-ahead-logging protocol. We will first write a log record that a page will be freed, and then the normal page flushing mechanism can take care of overwriting the garbage.

Unfortunately, there was a minor problem related to ~~MDEV-15528~~, and we had to disable part of it in the 10.5.4 release due to correctness concerns. That problem was addressed in the 10.5.5 release, which allowed us to finally close ~~MDEV-8139~~.

Note: undo log pages were never scrubbed in the old non-working design. Also in the new design, they will not be scrubbed most of the time, because some ‘caching’ prevents them from being marked as free.

Marko Mäkelä added a comment - 2020-08-12 08:57 I believe that the scrubbing feature never worked in its original design. MDEV-15528 deprecated and ignored most scrubbing-related parameters and laid the correct groundwork, following the tried-and-true write-ahead-logging protocol. We will first write a log record that a page will be freed, and then the normal page flushing mechanism can take care of overwriting the garbage. Unfortunately, there was a minor problem related to MDEV-15528 , and we had to disable part of it in the 10.5.4 release due to correctness concerns. That problem was addressed in the 10.5.5 release, which allowed us to finally close MDEV-8139 . Note: undo log pages were never scrubbed in the old non-working design. Also in the new design, they will not be scrubbed most of the time, because some ‘caching’ prevents them from being marked as free.

MariaDB Server

innodb-encryption-threads with scrubbing crashes server

Details

Description

Attachments

Attachments

Issue Links

Activity

People

Dates

Git Integration