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

Refuse innodb_read_only startup if crash recovery is needed

    XMLWordPrintable

Details

    • 10.2.4-1, 10.2.4-2

    Description

      I am starting 10.1 server (7e3f3deb41a87, but it was happening with previous builds as well) on a datadir produced by a relatively old 10.0 server (tried 10.0.10 and 10.0.13). The old server was fed some test flow, then normally restarted, then killed.

      When the 10.1 server is started on this datadir in innodb-read-only mode, it notices that crash recovery is needed, but does not refuse to start up as it would usually do; instead, it says that recovery would be skipped, proceeds, and later produces an error message.

      2017-01-16 15:52:51 139938701260672 [Note] InnoDB: Initializing buffer pool, size = 128.0M
      		 
      2017-01-16 15:52:51 139938701260672 [Note] InnoDB: Completed initialization of buffer pool
      		 
      2017-01-16 15:52:51 139938701260672 [Note] InnoDB: Created tablespace for space 0 name ./ibdata1 key_id 1 encryption 0.
      		 
      2017-01-16 15:52:51 139938701260672 [Note] InnoDB: Created tablespace for space 4294967280 name ./ib_logfile0 key_id 0 encryption 0.
      		 
      2017-01-16 15:52:51 139938701260672 [Note] InnoDB: Created tablespace for space 4294967281 name arch_log_space key_id 0 encryption 0.
      		 
      2017-01-16 15:52:51 139938701260672 [Note] InnoDB: Highest supported file format is Barracuda.
      		 
      2017-01-16 15:52:51 139938701260672 [Warning] InnoDB: Recovery skipped, --innodb-read-only set!
      		 
      2017-01-16 15:52:51 139938701260672 [ERROR] InnoDB: We scanned the log up to 0. A checkpoint was at 4239494 and the maximum LSN on a database page was 0. It is possible that the database is now corrupt!
      		 
      2017-01-16 15:52:51 7f4604943780 InnoDB: Error: page 5 log sequence number 4239504
      		 
      InnoDB: is in the future! Current system log sequence number 4239494.
      		 
      InnoDB: Your database may be corrupt or you may have copied the InnoDB
      		 
      InnoDB: tablespace but not the InnoDB log files. See
      		 
      InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
      		 
      InnoDB: for more information.
      		 
      2017-01-16 15:52:51 139938701260672 [Note] InnoDB: Created tablespace for space 3 name mysql/gtid_slave_pos key_id 0 encryption 0.
      		 
      2017-01-16 15:52:51 139938701260672 [Note] InnoDB: Created tablespace for space 2 name mysql/innodb_index_stats key_id 0 encryption 0.
      		 
      2017-01-16 15:52:51 139938701260672 [Note] InnoDB: Created tablespace for space 1 name mysql/innodb_table_stats key_id 0 encryption 0.
      		 
      2017-01-16 15:52:51 139938701260672 [Note] InnoDB: Created tablespace for space 15 name test/oltp1 key_id 0 encryption 0.
      		 
      2017-01-16 15:52:51 139938701260672 [Note] InnoDB: Created tablespace for space 16 name test/oltp2 key_id 0 encryption 0.
      		 
      2017-01-16 15:52:51 139938701260672 [Note] InnoDB: Created tablespace for space 17 name test/oltp3 key_id 0 encryption 0.
      		 
      2017-01-16 15:52:51 139938701260672 [Note] InnoDB: Created tablespace for space 18 name test/oltp4 key_id 0 encryption 0.
      		 
      2017-01-16 15:52:51 139938701260672 [Note] InnoDB: Created tablespace for space 6 name test/t1 key_id 0 encryption 0.
      		 
      2017-01-16 15:52:51 139938701260672 [Note] InnoDB: Created tablespace for space 7 name test/t2 key_id 0 encryption 0.
      		 
      2017-01-16 15:52:51 139938701260672 [Note] InnoDB: Created tablespace for space 8 name test/t3 key_id 0 encryption 0.
      		 
      2017-01-16 15:52:51 139938701260672 [Note] InnoDB: Created tablespace for space 9 name test/t4 key_id 0 encryption 0.
      		 
      2017-01-16 15:52:51 139938701260672 [Note] InnoDB: Created tablespace for space 10 name test/t5 key_id 0 encryption 0.
      		 
      2017-01-16 15:52:51 139938701260672 [Note] InnoDB: Created tablespace for space 11 name test/t6 key_id 0 encryption 0.
      		 
      2017-01-16 15:52:51 139938701260672 [Note] InnoDB: Created tablespace for space 12 name test/t7 key_id 0 encryption 0.
      		 
      2017-01-16 15:52:51 139938701260672 [Note] InnoDB: Created tablespace for space 13 name test/t8 key_id 0 encryption 0.
      		 
      2017-01-16 15:52:51 139938701260672 [Note] InnoDB: Created tablespace for space 14 name test/t9 key_id 0 encryption 0.
      		 
      2017-01-16 15:52:52 139938701260672 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.34-79.1 started; log sequence number 4239494
      		 
      2017-01-16 15:52:52 139938701260672 [Note] Plugin 'FEEDBACK' is disabled.
      		 
      2017-01-16 15:52:53 139938701260672 [Note] Server socket created on IP: '::'.
      		 
      2017-01-16 15:52:53 7f46048f0b00 InnoDB: Error: Column last_update in table "mysql"."innodb_table_stats" is INT UNSIGNED NOT NULL but should be BINARY(4) NOT NULL (type mismatch).
      		 
      2017-01-16 15:52:53 7f46048f0b00 InnoDB: Error: Fetch of persistent statistics requested for table "mysql"."gtid_slave_pos" but the required system tables mysql.innodb_table_stats and mysql.innodb_index_stats are not present or have unexpected structure. Using transient stats instead.
      		 
      2017-01-16 15:52:53 139938700921600 [Note] InnoDB: Read page 0 from tablespace for space 3 name mysql/gtid_slave_pos key_id 0 encryption 0 handle 32.
      		 
      2017-01-16 15:52:53 139938701260672 [Note] /data/bld/10.1/bin/mysqld: ready for connections.
      		 
      Version: '10.1.21-MariaDB-debug'  socket: '/data/bld/10.1/data/tmp/mysql.sock'  port: 3306  Source distribution

      If the same server is started on the same datadir in a non-read-only-mode, it performs the recovery and starts without the error:

      2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Initializing buffer pool, size = 128.0M
      		 
      2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Completed initialization of buffer pool
      		 
      2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Created tablespace for space 0 name ./ibdata1 key_id 1 encryption 0.
      		 
      2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Created tablespace for space 4294967280 name ./ib_logfile0 key_id 0 encryption 0.
      		 
      2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Created tablespace for space 4294967281 name arch_log_space key_id 0 encryption 0.
      		 
      2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Highest supported file format is Barracuda.
      		 
      2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Log scan progressed past the checkpoint lsn 4239494
      		 
      2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Database was not shutdown normally!
      		 
      2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Starting crash recovery.
      		 
      2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Reading tablespace information from the .ibd files...
      		 
      2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Created tablespace for space 6 name test/t1 key_id 0 encryption 0.
      		 
      2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Created tablespace for space 10 name test/t5 key_id 0 encryption 0.
      		 
      2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Created tablespace for space 9 name test/t4 key_id 0 encryption 0.
      		 
      2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Created tablespace for space 13 name test/t8 key_id 0 encryption 0.
      		 
      2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Created tablespace for space 7 name test/t2 key_id 0 encryption 0.
      		 
      2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Created tablespace for space 17 name test/oltp3 key_id 0 encryption 0.
      		 
      2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Created tablespace for space 16 name test/oltp2 key_id 0 encryption 0.
      		 
      2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Created tablespace for space 14 name test/t9 key_id 0 encryption 0.
      		 
      2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Created tablespace for space 11 name test/t6 key_id 0 encryption 0.
      		 
      2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Created tablespace for space 12 name test/t7 key_id 0 encryption 0.
      		 
      2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Created tablespace for space 18 name test/oltp4 key_id 0 encryption 0.
      		 
      2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Created tablespace for space 15 name test/oltp1 key_id 0 encryption 0.
      		 
      2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Created tablespace for space 8 name test/t3 key_id 0 encryption 0.
      		 
      2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Created tablespace for space 2 name mysql/innodb_index_stats key_id 0 encryption 0.
      		 
      2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Created tablespace for space 3 name mysql/gtid_slave_pos key_id 0 encryption 0.
      		 
      2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Created tablespace for space 1 name mysql/innodb_table_stats key_id 0 encryption 0.
      		 
      2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Restoring possible half-written data pages 
      2017-01-16 15:57:40 140552159930240 [Note] InnoDB: from the doublewrite buffer...
      		 
      2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Read page 0 from tablespace for space 16 name test/oltp2 key_id 0 encryption 0 handle 13.
      		 
      2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Read page 0 from tablespace for space 17 name test/oltp3 key_id 0 encryption 0 handle 14.
      		 
      2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Read page 0 from tablespace for space 18 name test/oltp4 key_id 0 encryption 0 handle 15.
      		 
      2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Read page 0 from tablespace for space 14 name test/t9 key_id 0 encryption 0 handle 16.
      		 
      2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Read page 0 from tablespace for space 15 name test/oltp1 key_id 0 encryption 0 handle 17.
      		 
      InnoDB: Doing recovery: scanned up to log sequence number 4239504
      		 
      2017-01-16 15:57:41 140552159930240 [Note] InnoDB: Read page 0 from tablespace for space 3 name mysql/gtid_slave_pos key_id 0 encryption 0 handle 18.
      		 
      2017-01-16 15:57:41 140552159930240 [Note] InnoDB: Read page 0 from tablespace for space 2 name mysql/innodb_index_stats key_id 0 encryption 0 handle 20.
      		 
      2017-01-16 15:57:41 140552159930240 [Note] InnoDB: Read page 0 from tablespace for space 1 name mysql/innodb_table_stats key_id 0 encryption 0 handle 21.
      		 
      2017-01-16 15:57:41 140552159930240 [Note] InnoDB: Read page 0 from tablespace for space 6 name test/t1 key_id 0 encryption 0 handle 22.
      		 
      2017-01-16 15:57:41 140552159930240 [Note] InnoDB: Read page 0 from tablespace for space 7 name test/t2 key_id 0 encryption 0 handle 23.
      		 
      2017-01-16 15:57:41 140552159930240 [Note] InnoDB: Read page 0 from tablespace for space 8 name test/t3 key_id 0 encryption 0 handle 24.
      		 
      2017-01-16 15:57:41 140552159930240 [Note] InnoDB: Read page 0 from tablespace for space 9 name test/t4 key_id 0 encryption 0 handle 25.
      		 
      2017-01-16 15:57:41 140552159930240 [Note] InnoDB: Read page 0 from tablespace for space 10 name test/t5 key_id 0 encryption 0 handle 26.
      		 
      2017-01-16 15:57:41 140552159930240 [Note] InnoDB: Read page 0 from tablespace for space 11 name test/t6 key_id 0 encryption 0 handle 27.
      		 
      2017-01-16 15:57:41 140552159930240 [Note] InnoDB: Read page 0 from tablespace for space 12 name test/t7 key_id 0 encryption 0 handle 28.
      		 
      2017-01-16 15:57:41 140552159930240 [Note] InnoDB: Read page 0 from tablespace for space 13 name test/t8 key_id 0 encryption 0 handle 29.
      		 
      2017-01-16 15:57:42 140552159930240 [Note] InnoDB: 128 rollback segment(s) are active.
      		 
      2017-01-16 15:57:42 140552159930240 [Note] InnoDB: Waiting for purge to start
      		 
      2017-01-16 15:57:42 140552159930240 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.34-79.1 started; log sequence number 4239504
      		 
      2017-01-16 15:57:43 140551395473152 [Note] InnoDB: Dumping buffer pool(s) not yet started

      Attachments

        Issue Links

          relates to

          Bug - A problem which impairs or prevents the functions of the product. MDEV-12700 Allow innodb_read_only startup without prior slow shutdown

          • Major - Major loss of function.
          • Closed

          Bug - A problem which impairs or prevents the functions of the product. MDEV-15202 innodb.log_file_size failed in buildbot - Can't initiate database recovery, running in read-only-mode

          • Major - Major loss of function.
          • Closed

          Activity

            People

              marko Marko Mäkelä
              elenst Elena Stepanova
              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.