Bug #103477 Server unusable if server is killed when ALTER TABLESPACE operation is in progre
Submitted: 26 Apr 2021 7:38 Modified: 27 Apr 2021 12:48
Reporter: Satya Bodapati (OCA) Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S6 (Debug Builds)
Version:8.0.24 OS:Any
Assigned to: CPU Architecture:Any

[26 Apr 2021 7:38] Satya Bodapati 
Description:
Please run the attached mtr testcase on debug build and see that server crashes with assertion ut_a(err == DB_SUCCESS) on recovery.

Note that the assertion is release build assertion. The assertion fails because server cannot decrypt an encrypted page on async io (aio) read during recovery.

Multiple issues exist:
1. Server can write encrypted pages before Page 0 is flushed (the core)
2. Server writes an un-encrypted copy in dblwr but writes encrypted in actual tablespace
3. Server cannot recover after a crash

Thread 1 (Thread 0x7fb51ffff700 (LWP 117897)):
#0  __pthread_kill (threadid=<optimized out>, signo=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56
#1  0x0000558282d36b19 in my_write_core (sig=6) at /home/satya/WORK/mysql-8.0/mysys/stacktrace.cc:308
#2  0x000055828175d92b in handle_fatal_signal (sig=6) at /home/satya/WORK/mysql-8.0/sql/signal_handler.cc:171
#3  <signal handler called>
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#5  0x00007fb53f618859 in __GI_abort () at abort.c:79
#6  0x000055828320034e in ut_dbg_assertion_failed (expr=0x558285016b0d "err == DB_SUCCESS", file=0x5582850165b0 "/home/satya/WORK/mysql-8.0/storage/innobase/fil/fil0fil.cc", line=8192) at /home/satya/WORK/mysql-8.0/storage/innobase/ut/ut0dbg.cc:98
#7  0x00005582833e994a in fil_aio_wait (segment=5) at /home/satya/WORK/mysql-8.0/storage/innobase/fil/fil0fil.cc:8192
#8  0x00005582831616f3 in io_handler_thread (segment=5) at /home/satya/WORK/mysql-8.0/storage/innobase/srv/srv0start.cc:278
#9  0x000055828317ceb8 in std::__invoke_impl<void, void (*&)(unsigned long), unsigned long&> (__f=@0x7fb51fffeb90: 0x558283161699 <io_handler_thread(ulint)>) at /usr/include/c++/9/bits/invoke.h:60
#10 0x000055828317cdfc in std::__invoke<void (*&)(unsigned long), unsigned long&> (__fn=@0x7fb51fffeb90: 0x558283161699 <io_handler_thread(ulint)>) at /usr/include/c++/9/bits/invoke.h:95
#11 0x000055828317cd27 in std::_Bind<void (*(unsigned long))(unsigned long)>::__call<void, , 0ul>(std::tuple<>&&, std::_Index_tuple<0ul>) (this=0x7fb51fffeb90, __args=...) at /usr/include/c++/9/functional:400
#12 0x000055828317cc4d in std::_Bind<void (*(unsigned long))(unsigned long)>::operator()<, void>() (this=0x7fb51fffeb90) at /usr/include/c++/9/functional:484
#13 0x000055828317cb84 in Runnable::operator()<void (*)(unsigned long), unsigned long> (this=0x7fb53446d2d8, f=@0x7fb53446d2d0: 0x558283161699 <io_handler_thread(ulint)>) at /home/satya/WORK/mysql-8.0/storage/innobase/include/os0thread-create.h:101
#14 0x000055828317ca60 in std::__invoke_impl<void, Runnable, void (*)(unsigned long), unsigned long> (__f=...) at /usr/include/c++/9/bits/invoke.h:60
#15 0x000055828317c983 in std::__invoke<Runnable, void (*)(unsigned long), unsigned long> (__fn=...) at /usr/include/c++/9/bits/invoke.h:95
#16 0x000055828317c893 in std::thread::_Invoker<std::tuple<Runnable, void (*)(unsigned long), unsigned long> >::_M_invoke<0ul, 1ul, 2ul> (this=0x7fb53446d2c8) at /usr/include/c++/9/thread:244
#17 0x000055828317c819 in std::thread::_Invoker<std::tuple<Runnable, void (*)(unsigned long), unsigned long> >::operator() (this=0x7fb53446d2c8) at /usr/include/c++/9/thread:251
#18 0x000055828317c7ea in std::thread::_State_impl<std::thread::_Invoker<std::tuple<Runnable, void (*)(unsigned long), unsigned long> > >::_M_run (this=0x7fb53446d2c0) at /usr/include/c++/9/thread:195
#19 0x00007fb53fa25d84 in ?? () from /lib/x86_64-linux-gnu/libstdc++.so.6
#20 0x00007fb53ffd7609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#21 0x00007fb53f715293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

How to repeat:
On debug build

./mtr --mem main.encryption_crash

Suggested fix:
diff --git a/storage/innobase/fsp/fsp0fsp.cc b/storage/innobase/fsp/fsp0fsp.cc
index 2325af7769e..ebcdb860785 100644
--- a/storage/innobase/fsp/fsp0fsp.cc
+++ b/storage/innobase/fsp/fsp0fsp.cc
@@ -4262,16 +4262,6 @@ static dberr_t init_before_encrypt_processing(fil_space_t *space,
       space_id, space->flags, 0, Encryption::ENCRYPT_IN_PROGRESS, true, &mtr);
   mtr_commit(&mtr);
 
-  /* Set encryption for tablespace */
-  rw_lock_x_lock(&space->latch);
-  err = fil_set_encryption(space_id, Encryption::AES, key, iv);
-  rw_lock_x_unlock(&space->latch);
-
-  if (err != DB_SUCCESS) {
-    ut_ad(false);
-    return err;
-  }
-
   /* Make sure encryption information is persisted on disk. Following scenario:
   [1] Encryption key is written on page 0 but Page 0 is not flushed.
   [2] page P is encrypted with K1 and flushed on disk.
@@ -4282,6 +4272,16 @@ static dberr_t init_before_encrypt_processing(fil_space_t *space,
   buf_LRU_flush_or_remove_pages(space_id, BUF_REMOVE_FLUSH_WRITE, nullptr,
                                 false);
 
+  /* Set encryption for tablespace */
+  rw_lock_x_lock(&space->latch);
+  err = fil_set_encryption(space_id, Encryption::AES, key, iv);
+  rw_lock_x_unlock(&space->latch);
+
+  if (err != DB_SUCCESS) {
+    ut_ad(false);
+    return err;
+  }
+
   /* Set encryption operation in progress flag */
[26 Apr 2021 7:38] Satya Bodapati 
testcase

Attachment: 0001-testcase.patch (text/x-patch), 5.88 KiB.
[26 Apr 2021 7:45] Satya Bodapati 
Explanation:

In init_before_encrypt_processing() we intend to write page 0 with encryption information but the encryption info is already set to in-memory tablespace structure (fil_space_t) before the buf_LRU_flush_or_remove_pages(). This flush call was supposed to write only page 0 with encryption header (and NOT write tablespace pages as encrypted)

in-memory encryption is already set (fil_set_encryption()), if there are any dirty pages in flush list, any page will be written encrypted before Page 0 encryption is written.

Since space->flags doesn't have encryption flag set, the pages written into DBLWR are unencrypted, while the actual page in tablesapce is written encrypted. (fil_io_set_encryption())

During recovery, if there is redo on a page, we do a async read. Since the page is encrypted without the encryption information on page 0 (and the redo processing doesn't reach to read encryption information), we cannot decrypt the page. Hence ASYNC IO fails
[26 Apr 2021 7:47] Satya Bodapati 
update title
[26 Apr 2021 15:52] Satya Bodapati 
exists on 8.0.24 too
[27 Apr 2021 12:48] MySQL Verification Team 
Hello Satya,

Thank you for the report and feedback.

regards,
Umesh