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

10.2 wrongly recognizes 10.1.10 innodb_encrypt_log=ON data as after-crash and refuses to start

Details

    Description

      The attached data directory was created by server 10.1.10 from release x86_64 new libc bintar which was run with the following options:

      --no-defaults \
      		 
      --file-key-management \
      		 
      --file-key-management-filename=/data/bld/10.2/mysql-test/std_data/keys.txt \
      		 
      --plugin-load-add=file_key_management.so \
      		 
      --innodb-encrypt-tables --innodb-encrypt-log \
      		 
      --innodb-encryption-threads=4 \
      		 
      --aria-encrypt-tables=1 \
      		 
      --encrypt-tmp-disk-tables=1 \
      		 
      --encrypt-binlog \
      		 
      --innodb-page-size=8K \
      		 
      --innodb-compression-algorithm=zlib \
      		 
      --loose-innodb-file-format=Barracuda \
      		 
      --loose-innodb-file-per-table=1 \
      		 
      --loose-lock-wait-timeout=20 \
      		 
      --loose-innodb-lock-wait-timeout=10 \
      		 
      --loose-innodb_log_compressed_pages=on

      A bunch of tables were created, then DML was run for ~1 minute, then the server was shutdown normally. The error log confirming it is attached, as well as the general log in case it's needed.

      Current 10.2 with the same server options refuses to start on this data, saying

      2017-09-18 16:59:14 140600868909120 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
      		 
      2017-09-18 16:59:14 140600868909120 [Note] InnoDB: Completed initialization of buffer pool
      		 
      2017-09-18 16:59:14 140600128263936 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
      		 
      2017-09-18 16:59:14 140600868909120 [Note] InnoDB: Highest supported file format is Barracuda.
      		 
      2017-09-18 16:59:14 140600868909120 [ERROR] InnoDB: Upgrade after a crash is not supported. This redo log was created before MariaDB 10.2.2, and it appears corrupted. Please follow the instructions at http://dev.mysql.com/doc/refman/5.7/en/upgrading.html
      		 
      2017-09-18 16:59:14 140600868909120 [ERROR] InnoDB: Plugin initialization aborted at srv0start.cc[2232] with error Data structure corruption

      Current 10.1 does start, and does not say anything about crash recovery, only

      2017-09-18 16:45:56 140340660551808 [Note] InnoDB: Initializing buffer pool, size = 128.0M
      		 
      2017-09-18 16:45:56 140340660551808 [Note] InnoDB: Completed initialization of buffer pool
      		 
      2017-09-18 16:45:56 140340660551808 [Note] InnoDB: Highest supported file format is Barracuda.
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 0 from 0x8000 to 0x100
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 3 from 0x8000 to 0x100
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 2 from 0x8000 to 0x100
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 1 from 0x8000 to 0x100
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 15 from 0x8000 to 0x100
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 16 from 0x8000 to 0x100
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 17 from 0x8027 to 0x127
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 18 from 0x8361 to 0x10121
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 19 from 0x80e1 to 0x10121
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 20 from 0x84e1 to 0x10121
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 21 from 0x8361 to 0x10121
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 22 from 0x80e1 to 0x10121
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 23 from 0x84e1 to 0x10121
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 24 from 0x8361 to 0x10121
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 25 from 0x80e1 to 0x10121
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 26 from 0x84e1 to 0x10121
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 27 from 0x8000 to 0x100
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 28 from 0x8000 to 0x100
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 29 from 0x8027 to 0x127
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 30 from 0x8361 to 0x10121
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 31 from 0x80e1 to 0x10121
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 32 from 0x84e1 to 0x10121
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 33 from 0x8361 to 0x10121
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 34 from 0x80e1 to 0x10121
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 35 from 0x84e1 to 0x10121
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 36 from 0x8361 to 0x10121
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 37 from 0x80e1 to 0x10121
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 38 from 0x84e1 to 0x10121
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 39 from 0x8000 to 0x100
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 40 from 0x8000 to 0x100
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 41 from 0x8027 to 0x127
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 42 from 0x8361 to 0x10121
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 43 from 0x80e1 to 0x10121
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 44 from 0x84e1 to 0x10121
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 45 from 0x8361 to 0x10121
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 46 from 0x80e1 to 0x10121
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 47 from 0x84e1 to 0x10121
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 48 from 0x8361 to 0x10121
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 49 from 0x80e1 to 0x10121
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 50 from 0x84e1 to 0x10121
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 6 from 0x8000 to 0x100
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 7 from 0x8000 to 0x100
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 8 from 0x8000 to 0x100
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 9 from 0x8000 to 0x100
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 10 from 0x8000 to 0x100
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 11 from 0x8000 to 0x100
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 12 from 0x8000 to 0x100
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 13 from 0x8000 to 0x100
      		 
      2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 14 from 0x8000 to 0x100
      		 
      2017-09-18 16:45:58 140340660551808 [Note] InnoDB: 128 rollback segment(s) are active.
      		 
      2017-09-18 16:45:58 140340660551808 [Note] InnoDB: Waiting for purge to start
      		 
      2017-09-18 16:45:58 140340660551808 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.36-82.1 started; log sequence number 9116907

      (similar with InnoDB plugin).

      Note: The data has been split into two archives, one with ib_logfileX files, the other with everything else; it's just to allow archives to fit into JIRA limitation, everything is from the same test run, just put ib_logfiles back to the datadir.

      Attachments

        1. data_without_ib_logfiles.tar.gz
          8.22 MB
        2. ib_logfiles.tar.gz
          8.03 MB
        3. mysql.err_orig
          33 kB
        4. mysql.log.gz
          917 kB

        Issue Links

          is caused by

          Task - A task that needs to be done. MDEV-11782 Redefine the innodb_encrypt_log format

          • Major - Major loss of function.
          • Closed

          Activity

            Ascending order - Click to sort in descending order
            marko Marko Mäkelä added a comment -

            I tested the ib_logfiles.tar.gz in 10.1. The crypt_info.size() actually is 6 and not 5, as I would have expected. Because the upgrade code in 10.2 uses an array of 5 elements, it is missing the encryption information for the checkpoint number 19, which is what is needed for parsing the log.

            marko Marko Mäkelä added a comment - I tested the ib_logfiles.tar.gz in 10.1. The crypt_info.size() actually is 6 and not 5, as I would have expected. Because the upgrade code in 10.2 uses an array of 5 elements, it is missing the encryption information for the checkpoint number 19, which is what is needed for parsing the log.
            marko Marko Mäkelä added a comment -

            Another problem is that in 10.1, the log block checksum is not valid, but it is not checked either!
            If I call log_block_checksum_is_ok_or_old_format() after the decryption took place in log_decrypt_after_read(), a message would be emitted to the error log:

            BROKEN: block: 17807 checkpoint: 19 1daf6b82 82ffa2f9

            So, we have to stop validating the checksum when upgrading an encrypted redo log of MariaDB 10.1. With that change, MariaDB 10.2 will perform an upgrade on the redo log as desired.

            marko Marko Mäkelä added a comment - Another problem is that in 10.1, the log block checksum is not valid, but it is not checked either! If I call log_block_checksum_is_ok_or_old_format()  after the decryption took place in log_decrypt_after_read() , a message would be emitted to the error log: BROKEN: block: 17807 checkpoint: 19 1daf6b82 82ffa2f9 So, we have to stop validating the checksum when upgrading an encrypted redo log of MariaDB 10.1. With that change, MariaDB 10.2 will perform an upgrade on the redo log as desired.
            marko Marko Mäkelä added a comment -

            My first fix broke the upgrade from MariaDB 10.1 in some cases, because my revised code would return an error if the encryption key corresponding to the current checkpoint number is not found. MariaDB 10.1 would actually use the first encryption key in this case. This logic was added as part of MDEV-9422 (MariaDB 10.1.13), which also disabled the encryption key rotation. My second fix addresses that.

            marko Marko Mäkelä added a comment - My first fix broke the upgrade from MariaDB 10.1 in some cases, because my revised code would return an error if the encryption key corresponding to the current checkpoint number is not found. MariaDB 10.1 would actually use the first encryption key in this case. This logic was added as part of MDEV-9422 (MariaDB 10.1.13), which also disabled the encryption key rotation. My second fix addresses that.

            People

              marko Marko Mäkelä
              elenst Elena Stepanova
              Votes:
              0 Vote for this issue
              Watchers:
              2 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.