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

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Critical
Resolution: Fixed
Affects Version/s: 10.1.18
Fix Version/s: 10.1.19
Component/s: Encryption, Storage Engine - InnoDB, Storage Engine - XtraDB
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)

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.

Attachments

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

logset01.txt
243 kB
2016-10-12 00:25
logset02.txt
321 kB
2016-10-12 00:25
logset03.txt
116 kB
2016-10-12 00:25
my.cnf
5 kB
2016-10-12 00:25
gdb.txt
60 kB
2016-10-12 23:19

Issue Links

relates to

MDEV-11423 Crashes on startup with Assert failure (6) on load with missing encryption key,

Closed

Activity

Ascending order - Click to sort in descending order

Richard Oakham created issue - 2016-10-10 00:42

Richard Oakham added a comment - 2016-10-10 21:45

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.

Richard Oakham added a comment - 2016-10-10 21:45 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.

Elena Stepanova made changes - 2016-10-11 22:08

Field	Original Value	New Value
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.	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 {noformat} 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. {noformat} {noformat} 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 {noformat} {noformat} 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. {noformat}

Elena Stepanova added a comment - 2016-10-11 22:13

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

Elena Stepanova added a comment - 2016-10-11 22:13 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).

Elena Stepanova made changes - 2016-10-11 22:13

Labels

innodb

innodb need_feedback

Richard Oakham added a comment - 2016-10-12 00:25

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

Richard Oakham added a comment - 2016-10-12 00:25 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

Richard Oakham made changes - 2016-10-12 00:25

Attachment		logset01.txt [ 42699 ]
Attachment		logset02.txt [ 42700 ]
Attachment		logset03.txt [ 42701 ]
Attachment		my.cnf [ 42702 ]

Richard Oakham made changes - 2016-10-12 00:26

Summary

Unable to start (os error 2) when encryption key missing

Unable to start (Segfault or os error 2) when encryption key missing

Richard Oakham made changes - 2016-10-12 00:27

Labels

innodb need_feedback

innodb

Elena Stepanova added a comment - 2016-10-12 12:59

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.

Elena Stepanova added a comment - 2016-10-12 12:59 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.

Richard Oakham added a comment - 2016-10-12 20:17

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

Richard Oakham added a comment - 2016-10-12 20:17 Hi. Thanks for reviewing. I will test more today please let me know if there is more info i can gather for you

Richard Oakham added a comment - 2016-10-12 23:19

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

Richard Oakham added a comment - 2016-10-12 23:19 Added a GDB thread backtrace of the sigsegv occurring - debug build using 10.1 branch from Git

Richard Oakham made changes - 2016-10-12 23:19

Attachment

gdb.txt [ 42703 ]

Elena Stepanova added a comment - 2016-10-12 23:29

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

Elena Stepanova added a comment - 2016-10-12 23:29 Thanks for this. Assigning to jplindst , as the full stacktrace might be enough for him to see the reason of the problem.

Elena Stepanova made changes - 2016-10-12 23:29

Fix Version/s		10.1 [ 16100 ]
Assignee		Jan Lindström [ jplindst ]
Priority	Major [ 3 ]	Critical [ 2 ]

Richard Oakham added a comment - 2016-10-18 01:16

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

Richard Oakham added a comment - 2016-10-18 01:16 Hi - is there anything else I can add to this to help track it down?

Jan Lindström (Inactive) made changes - 2016-10-27 05:39

Status

Open [ 1 ]

In Progress [ 3 ]

Jan Lindström (Inactive) made changes - 2016-10-27 12:02

Fix Version/s		10.1.19 [ 22111 ]
Fix Version/s	10.1 [ 16100 ]

Jan Lindström (Inactive) added a comment - 2016-10-29 07:13

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.

Jan Lindström (Inactive) added a comment - 2016-10-29 07:13 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.

Jan Lindström (Inactive) made changes - 2016-10-29 07:13

Component/s		Storage Engine - InnoDB [ 10129 ]
Component/s		Storage Engine - XtraDB [ 10135 ]
Resolution		Fixed [ 1 ]
Status	In Progress [ 3 ]	Closed [ 6 ]

Richard Oakham made changes - 2016-11-29 23:56

Link

This issue relates to ~~MDEV-11423~~ [ ~~MDEV-11423~~ ]

Sergei Golubchik made changes - 2021-12-06 21:43

Workflow

MariaDB v3 [ 77730 ]

MariaDB v4 [ 151041 ]

People

Assignee:: Jan Lindström (Inactive)

Reporter:: Richard Oakham

Votes:: 0 Vote for this issue

Watchers:: 3 Start watching this issue

Dates

Created:: 2016-10-10 00:42

Updated:: 2016-11-29 23:56

Resolved:: 2016-10-29 07:13

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.

MariaDB Server

Details

Description

Attachments

Attachments

Issue Links

Activity

People

Dates

Git Integration