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

Encrypted transactional Aria tables remain corrupt after crash recovery, automatic repairment does not work

    XMLWordPrintable

    Details

      Description

      Upon next startup after an intentional crash (during DML flow), Aria recovery does not return any errors:

      10.2 5ec9b88e1111

      2018-12-05 21:46:24 140049823393600 [Note] mysqld: Aria engine: starting recovery
      recovered pages: 0% 10% 20% 30% 40% 50% 60% 70% 80% 90% 89% 99% 100% (17.7 seconds); transactions to roll back: 2 1 0 (0.0 seconds); tables to flush: 54 53 52 51 50 49 48 47 46 45 44 43 42 41 40 39 38 37 36 35 34 33 32 31 30 29 28 27 26 25 24 23 22 21 20 19 18 17 16 15 14 13 12 11 10 9 8 7 6 5 4 3 2 1 0 (1.8 seconds); 
      2018-12-05 21:46:44 140049823393600 [Note] mysqld: Aria engine: recovery done
      2018-12-05 21:46:44 140049823393600 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
      2018-12-05 21:46:44 140049823393600 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
      2018-12-05 21:46:44 140049823393600 [Note] InnoDB: Uses event mutexes
      2018-12-05 21:46:44 140049823393600 [Note] InnoDB: Compressed tables use zlib 1.2.11
      2018-12-05 21:46:44 140049823393600 [Note] InnoDB: Using Linux native AIO
      2018-12-05 21:46:44 140049823393600 [Note] InnoDB: Number of pools: 1
      2018-12-05 21:46:44 140049823393600 [Note] InnoDB: Using SSE2 crc32 instructions
      2018-12-05 21:46:44 140049823393600 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
      2018-12-05 21:46:44 140049823393600 [Note] InnoDB: Completed initialization of buffer pool
      2018-12-05 21:46:44 140049095739136 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
      2018-12-05 21:46:44 140049823393600 [Note] InnoDB: Highest supported file format is Barracuda.
      2018-12-05 21:46:44 140049823393600 [Note] InnoDB: Starting crash recovery from checkpoint LSN=1620006
      2018-12-05 21:46:44 140049823393600 [Note] InnoDB: 128 out of 128 rollback segments are active.
      2018-12-05 21:46:44 140049823393600 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
      2018-12-05 21:46:44 140049823393600 [Note] InnoDB: Creating shared tablespace for temporary tables
      2018-12-05 21:46:44 140049823393600 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
      2018-12-05 21:46:44 140049823393600 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
      2018-12-05 21:46:44 140049823393600 [Note] InnoDB: Waiting for purge to start
      2018-12-05 21:46:44 140049823393600 [Note] InnoDB: 5.7.24 started; log sequence number 1620015
      2018-12-05 21:46:44 140048867514112 [Note] InnoDB: Loading buffer pool(s) from /data/bld/10.2/data/ib_buffer_pool
      2018-12-05 21:46:44 140049823393600 [Note] Plugin 'FEEDBACK' is disabled.
      2018-12-05 21:46:44 140049823393600 [Note] Recovering after a crash using tc.log
      2018-12-05 21:46:44 140049823393600 [Note] Starting crash recovery...
      2018-12-05 21:46:44 140048867514112 [Note] InnoDB: Buffer pool(s) load completed at 181205 21:46:44
      2018-12-05 21:46:44 140049823393600 [Note] Crash recovery finished.
      2018-12-05 21:46:44 140049823393600 [Note] Server socket created on IP: '::'.
      2018-12-05 21:46:44 140049823393600 [Note] Reading of all Master_info entries succeded
      2018-12-05 21:46:44 140049823393600 [Note] Added new Master_info '' to hash table
      2018-12-05 21:46:44 140049823393600 [Note] /data/bld/10.2/bin/mysqld: ready for connections.
      Version: '10.2.20-MariaDB-debug'  socket: '/data/bld/10.2/data/tmp/mysql.sock'  port: 3306  Source distribution
      

      However, further CHECK on a table shows a problem:

      MariaDB [test]> check table oltp16;
      +-------------+-------+----------+-------------------------+
      | Table       | Op    | Msg_type | Msg_text                |
      +-------------+-------+----------+-------------------------+
      | test.oltp16 | check | error    | Found 2315 keys of 2319 |
      | test.oltp16 | check | error    | Corrupt                 |
      +-------------+-------+----------+-------------------------+
      2 rows in set (0.02 sec)
      

      Manual repair works:

      MariaDB [test]> repair table oltp16;
      +-------------+--------+----------+-----------------------------------------------------------+
      | Table       | Op     | Msg_type | Msg_text                                                  |
      +-------------+--------+----------+-----------------------------------------------------------+
      | test.oltp16 | repair | warning  | Duplicate key  1 for record at 3111 against record at 361 |
      | test.oltp16 | repair | warning  | 1 records have been removed                               |
      | test.oltp16 | repair | warning  | Number of rows changed from 2319 to 2317                  |
      | test.oltp16 | repair | status   | OK                                                        |
      +-------------+--------+----------+-----------------------------------------------------------+
      4 rows in set (0.18 sec)
       
      MariaDB [test]> check table oltp16;
      +-------------+-------+----------+-----------------------------------------------------------+
      | Table       | Op    | Msg_type | Msg_text                                                  |
      +-------------+-------+----------+-----------------------------------------------------------+
      | test.oltp16 | check | warning  | Found row where the auto_increment column has the value 0 |
      | test.oltp16 | check | status   | OK                                                        |
      +-------------+-------+----------+-----------------------------------------------------------+
      2 rows in set (0.00 sec)
       
      MariaDB [test]> show create table oltp16 \G
      *************************** 1. row ***************************
             Table: oltp16
      Create Table: CREATE TABLE `oltp16` (
        `k` int(10) unsigned NOT NULL DEFAULT 0,
        `id` int(10) unsigned NOT NULL AUTO_INCREMENT,
        `pad` char(60) NOT NULL DEFAULT '',
        `c` char(120) NOT NULL DEFAULT '',
        PRIMARY KEY (`id`),
        KEY `k` (`k`)
      ) ENGINE=Aria AUTO_INCREMENT=1891959922 DEFAULT CHARSET=latin1 CHECKSUM=1 PAGE_CHECKSUM=0 ROW_FORMAT=PAGE TRANSACTIONAL=1
      1 row in set (0.00 sec)
      

      Setting --aria-recover-options to non-default NORMAL or FORCE does not change anything.

      The datadir after the initial crash, before any attempt to recover, is here:
      ftp://ftp.askmonty.org/public/mdev17913-data.tar.gz

      Unpack and start the server with

      --aria-encrypt-tables=1 --plugin-load-add=file_key_management --file-key-management-filename=`pwd`/mysql-test/std_data/keys.txt
      

      Adjust the path to keys.txt if needed.
      You can also add aria-recover-options of your choice.

      After recovery, run

      check table oltp16;
      

      The general log for the test flow prior to the initial crash is in mysql.log.


      The test to run the complete flow (might require several trials):

      https://github.com/MariaDB/randgen --branch elenst-jira-refs b1facb0360

      perl ./runall-new.pl  --basedir=/data/bld/10.2 --vardir=/dev/shm/vardir --duration=250 --threads=6  --scenario=CrashUpgrade   --redefine=conf/mariadb/bulk_insert.yy  --engine=Aria --grammar=conf/mariadb/generic-dml.yy --gendata=conf/mariadb/oltp-aria.zz --mysqld=--aria-encrypt-tables=1 --grammar=conf/mariadb/generic-dml.yy --gendata=conf/mariadb/oltp-aria.zz --mysqld=--plugin-load-add=file_key_management --mysqld=--file-key-management-filename=/data/bld/keys.txt
      

      RQG branch and revision are important here, you might not have some of the required files in other branches.
      Adjust the paths to basedir and keys file on the command line.

      Couldn't reproduce on 10.1 with the given test, but possibly there is some difference in the test flow.
      Couldn't reproduce so far without encryption.

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              monty Michael Widenius
              Reporter:
              elenst Elena Stepanova
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved: