Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-11004

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

    XMLWordPrintable

Details

    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

        1. gdb.txt
          60 kB
        2. logset01.txt
          243 kB
        3. logset02.txt
          321 kB
        4. logset03.txt
          116 kB
        5. my.cnf
          5 kB

        Issue Links

          relates to

          Bug - A problem which impairs or prevents the functions of the product. MDEV-11423 Crashes on startup with Assert failure (6) on load with missing encryption key,

          • Major - Major loss of function.
          • Closed

          Activity

            People

              jplindst Jan Lindström (Inactive)
              Oakham Richard Oakham
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

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