[MDEV-11004] Unable to start (Segfault or os error 2) when encryption key missing Created: 2016-10-10  Updated: 2016-11-29  Resolved: 2016-10-29

Status: Closed
Project: MariaDB Server
Component/s: Encryption, Storage Engine - InnoDB, Storage Engine - XtraDB
Affects Version/s: 10.1.18
Fix Version/s: 10.1.19

Type: Bug Priority: Critical
Reporter: Richard Oakham Assignee: Jan Lindström (Inactive)
Resolution: Fixed Votes: 0
Labels: innodb
Environment:

Debian Jessie (up to date as of 10/10/16), MariaDB 10.1.18, 24GB RAM, 16 core Intel processor, 2TB data (90% free)

Attachments: Text File gdb.txt     Text File logset01.txt     Text File logset02.txt     Text File logset03.txt     File my.cnf    
Issue Links:
Relates
relates to MDEV-11423 Crashes on startup with Assert failur... Closed

 Description   

Updated to MariaDB 10.1.18 on a development server, tables are encrypted using DAR encyption with key 1 for system use, and key 19 for specific table use.

Prior to 10.1.18 you could start the server with only key 1 available (this file is always available on the server), and it would fail to access any other encrypted table but still start up. We would then restart with both keys available to get access to the main data files. This method enabled updates to work correctly (apt-get update) without the data being available on restart (protection against someone gaining root access to the server, key19 is only installed for data restarts after upgrades and then removed from the system)

With 10.1.18 the restart without key 19 fails with OS error number 2 - as if the file cannot be accessed - but it can access the file, as shown by accessing with key 19 present which works as expected (full startup). This breaks doing updates however because the update does not have key 19, only key 1.

Even after starting with both keys, and then doing a formal shutdown, a restart without key 19 fails. This is different from previous behaviour.

Expected behaviour: MariaDB starts up but the tables encrypted with a missing key are not available until the key is provided at restart.

Note with log below it doesn't matter what table name or database name it is, moving a reported "broken" table out (so that the tablespace gets updated without that table) simply moves the issue to the next file or database, depending on what it is trying to open.

Log entries

Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: 2016-10-10 10:05:02 140127700760512 [Note] /usr/sbin/mysqld (mysqld 10.1.18-MariaDB-1~jessie) starting as process 7976 ...
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: 2016-10-10 10:05:02 140127700760512 [Note] InnoDB: Using mutexes to ref count buffer pool pages
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: 2016-10-10 10:05:02 140127700760512 [Note] InnoDB: The InnoDB memory heap is disabled
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: 2016-10-10 10:05:02 140127700760512 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: 2016-10-10 10:05:02 140127700760512 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: 2016-10-10 10:05:02 140127700760512 [Note] InnoDB: Compressed tables use zlib 1.2.8
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: 2016-10-10 10:05:02 140127700760512 [Note] InnoDB: Using Linux native AIO
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: 2016-10-10 10:05:02 140127700760512 [Note] InnoDB: Using SSE crc32 instructions
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: 2016-10-10 10:05:02 140127700760512 [Note] InnoDB: Initializing buffer pool, size = 256.0M
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: 2016-10-10 10:05:02 140127700760512 [Note] InnoDB: Completed initialization of buffer pool
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: 2016-10-10 10:05:02 140127700760512 [Note] InnoDB: Highest supported file format is Barracuda.
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: 2016-10-10 10:05:02 140127700760512 [Note] InnoDB: The log sequence numbers 515406752801 and 515406752801 in ibdata files do not match the log sequence number 515406752811 in the ib_logfiles!
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: 2016-10-10 10:05:02 140127700760512 [Note] InnoDB: Database was not shutdown normally!
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: 2016-10-10 10:05:02 140127700760512 [Note] InnoDB: Starting crash recovery.


Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: 2016-10-10 10:05:02 140127700760512 [Note] InnoDB: Reading tablespace information from the .ibd files...
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: 2016-10-10 10:05:02 140127700760512 [ERROR] InnoDB: Tablespace id 3770 is encrypted but encryption service or used key_id 19 is not available. Can't continue opening tablespace.
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: 2016-10-10 10:05:02 140127700760512 [ERROR] InnoDB: table encrypted but encryption service not available. in tablespace ./[DB Name]/[Table name].ibd (table [DB Name]/[Table name])
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: 2016-10-10 10:05:02 140127700760512 [Note] InnoDB: Page size:1024 Pages to analyze:64
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: 2016-10-10 10:05:02 140127700760512 [Note] InnoDB: Page size: 1024, Possible space_id count:0
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: 2016-10-10 10:05:02 140127700760512 [Note] InnoDB: Page size:2048 Pages to analyze:48
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: 2016-10-10 10:05:02 140127700760512 [Note] InnoDB: Page size: 2048, Possible space_id count:0
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: 2016-10-10 10:05:02 140127700760512 [Note] InnoDB: Page size:4096 Pages to analyze:24
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: 2016-10-10 10:05:02 140127700760512 [Note] InnoDB: Page size: 4096, Possible space_id count:0
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: 2016-10-10 10:05:02 140127700760512 [Note] InnoDB: Page size:8192 Pages to analyze:12
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: 2016-10-10 10:05:02 140127700760512 [Note] InnoDB: Page size: 8192, Possible space_id count:0
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: 2016-10-10 10:05:02 140127700760512 [Note] InnoDB: Page size:16384 Pages to analyze:6
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: 2016-10-10 10:05:02 140127700760512 [Note] InnoDB: VALID: space:3770 page_no:0 page_size:16384
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: 2016-10-10 10:05:02 140127700760512 [Note] InnoDB: VALID: space:3770 page_no:1 page_size:16384
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: 2016-10-10 10:05:02 140127700760512 [Note] InnoDB: VALID: space:3770 page_no:2 page_size:16384
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: 2016-10-10 10:05:02 140127700760512 [Note] InnoDB: VALID: space:3770 page_no:3 page_size:16384
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: 2016-10-10 10:05:02 140127700760512 [Note] InnoDB: Page size: 16384, Possible space_id count:1
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: 2016-10-10 10:05:02 140127700760512 [Note] InnoDB: space_id:3770, Number of pages matched: 4/4 (16384)
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: 2016-10-10 10:05:02 140127700760512 [Note] InnoDB: Chosen space:3770
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: 2016-10-10 10:05:02 140127700760512 [Note] InnoDB: Restoring page 0 of tablespace 3770


Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: 2016-10-10 10:05:02 140127700760512 [Warning] InnoDB: Doublewrite does not have page_no=0 of space: 3770
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: 2016-10-10 10:05:02 7f7205d3b7c0  InnoDB: Operating system error number 2 in a file operation.
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: InnoDB: The error means the system cannot find the path specified.
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: InnoDB: If you are installing InnoDB, remember that you must create
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: InnoDB: directories yourself, InnoDB does not create them.
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: InnoDB: Error: could not open single-table tablespace file ./eroster/achieve_dispgroup.ibd
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: InnoDB: We do not continue the crash recovery, because the table may become
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: InnoDB: corrupt if we cannot apply the log records in the InnoDB log to it.
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: InnoDB: To fix the problem and start mysqld:
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: InnoDB: 1) If there is a permission problem in the file and mysqld cannot
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: InnoDB: open the file, you should modify the permissions.
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: InnoDB: 2) If the table is not needed, or you can restore it from a backup,
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: InnoDB: then you can remove the .ibd file, and InnoDB will do a normal
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: InnoDB: crash recovery and ignore that table.
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: InnoDB: 3) If the file system or the disk is broken, and you cannot remove
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: InnoDB: the .ibd file, you can set innodb_force_recovery > 0 in my.cnf
 
Oct 10 10:05:02 gc-vd-eroster01 mysqld[7976]: InnoDB: and force InnoDB to continue crash recovery here.



 Comments   
Comment by Richard Oakham [ 2016-10-10 ]

Addit:

The update process (apt-get update) will fail as follows:

Setting up mariadb-server-10.1 (10.1.18+maria-1~jessie) ...
Job for mariadb.service failed. See 'systemctl status mariadb.service' and 'journalctl -xn' for details.
invoke-rc.d: initscript mysql, action "start" failed.
dpkg: error processing package mariadb-server-10.1 (--configure):
subprocess installed post-installation script returned error exit status 1
dpkg: dependency problems prevent configuration of mariadb-server:
mariadb-server depends on mariadb-server-10.1 (= 10.1.18+maria-1~jessie); however:
Package mariadb-server-10.1 is not configured yet.

Comment by Elena Stepanova [ 2016-10-11 ]

Oakham,
Which version did you have before upgrading to 10.1.18?

Provided error log relates to the case when the server was started after a crash or otherwise unclean shutdown. I can reproduce this refusal to start, but it's not new, at least 10.1.17 behaves the same way.
However, you mentioned that it happens even after a normal shutdown and restart. This part I cannot reproduce. Could you please paste or attach the error log showing it? The part where we can see the shutdown, restart and the error.
Please also attach your cnf file(s).

Comment by Richard Oakham [ 2016-10-12 ]

Log files attached with annotations as to what I was doing at the time. All my annotations start **

Also updated the title of this bug, because of the SegFaults showing.

logset01 - Original upgrade attempt, followed by starting up with one key, both keys, back to one key (both Signal 11 and OS Error 2 failures to start), moving one data directory out of access to see if the issue was that dir or all databases
logset02 - Equivalent single and dual key startup from non-upgraded server (10.1.17)
logset03 - Attempts today to single and dual key start, back to Signal 11 failures, put back the moved data directory, still failing to start without keys whereas 10.1.17 lists the errors but starts
my.cnf - Configuration file as requested

Comment by Elena Stepanova [ 2016-10-12 ]

Oakham, thanks for all the data, we'll review it in detail shortly.

At the first glance, the root problem here is the crash with SIGSEGV. After it happens, the next server startup causes InnoDB recovery, which fails with "We do not continue the crash recovery" etc. According to the error text, this part (not continuing recovery without all the keys) is intentional – maybe it can be reconsidered, but it's not new. On a previous version, you didn't have the crash, hence there was no need in recovery, hence the failure to recover was never triggered.

But the crash is apparently new, and it obviously mustn't happen.

Comment by Richard Oakham [ 2016-10-12 ]

Hi.
Thanks for reviewing. I will test more today please let me know if there is more info i can gather for you

Comment by Richard Oakham [ 2016-10-12 ]

Added a GDB thread backtrace of the sigsegv occurring - debug build using 10.1 branch from Git

Comment by Elena Stepanova [ 2016-10-12 ]

Thanks for this. Assigning to jplindst, as the full stacktrace might be enough for him to see the reason of the problem.

Comment by Richard Oakham [ 2016-10-18 ]

Hi - is there anything else I can add to this to help track it down?

Comment by Jan Lindström (Inactive) [ 2016-10-29 ]

commit 885577fb10cba63a4a140bd91257a3cd2b402159
Author: Jan Lindström <jan.lindstrom@mariadb.com>
Date: Thu Oct 27 14:51:10 2016 +0300

MDEV-11004: Unable to start (Segfault or os error 2) when encryption key missing

Two problems:

(1) When pushing warning to sql-layer we need to check that thd != NULL
to avoid NULL-pointer reference.

(2) At tablespace key rotation if used key_id is not found from
encryption plugin tablespace should not be rotated.

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