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

InnoDB init fail after upgrade from 10.4 to 10.5

Details

    • Bug
    • Status: Closed (View Workflow)
    • Major
    • Resolution: Not a Bug
    • 10.5.4
    • N/A
    • None
    • Ubuntu 20.04 / Linux 5.4.0

    Description

      After an upgrade from 10.4 to 10.5 (following the instructions on https://mariadb.com/kb/en/upgrading-from-mariadb-104-to-mariadb-105/), MariaDB fails to start:

      2020-07-09 19:43:43 0 [Note] InnoDB: Using Linux native AIO
      2020-07-09 19:43:43 0 [Note] InnoDB: Uses event mutexes
      2020-07-09 19:43:43 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
      2020-07-09 19:43:43 0 [Note] InnoDB: Number of pools: 1
      2020-07-09 19:43:43 0 [Note] InnoDB: Using SSE4.2 crc32 instructions
      2020-07-09 19:43:43 0 [Note] mariadbd: O_TMPFILE is not supported on /tmp (disabling future attempts)
      2020-07-09 19:43:43 0 [Note] InnoDB: Initializing buffer pool, total size = 107374182400, chunk size = 134217728
      2020-07-09 19:43:46 0 [Note] InnoDB: Completed initialization of buffer pool
      2020-07-09 19:43:46 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
      2020-07-09 19:43:46 0 [ERROR] InnoDB: Upgrade after a crash is not supported. The redo log was created with MariaDB 10.4.13.
      2020-07-09 19:43:46 0 [ERROR] InnoDB: Plugin initialization aborted with error Generic error
      2020-07-09 19:43:46 0 [Note] InnoDB: Starting shutdown...
      2020-07-09 19:43:49 0 [ERROR] Plugin 'InnoDB' init function returned error.
      2020-07-09 19:43:49 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
      2020-07-09 19:43:49 0 [Note] Plugin 'FEEDBACK' is disabled.
      2020-07-09 19:43:49 0 [ERROR] Failed to initialize plugins.
      2020-07-09 19:43:49 0 [ERROR] Aborting
      

      Output from sudo journalctl -u mariadb.service indicates a problem with max_open_files, but this seems to be just a warning:

      Starting MariaDB 10.5.4 database server...
      Jul 09 19:43:43 nose mariadbd[1527643]: 2020-07-09 19:43:43 0 [Note] /usr/sbin/mariadbd (mysqld 10.5.4-MariaDB-1:10.5.4+maria~bionic-log) starting as process 1527643 ...
      Jul 09 19:43:43 nose mariadbd[1527643]: 2020-07-09 19:43:43 0 [Warning] Could not increase number of max_open_files to more than 16364 (request: 66099)
      Jul 09 19:43:49 nose systemd[1]: mariadb.service: Main process exited, code=exited, status=1/FAILURE
      Jul 09 19:43:49 nose systemd[1]: mariadb.service: Failed with result 'exit-code'.
      Jul 09 19:43:49 nose systemd[1]: Failed to start MariaDB 10.5.4 database server.
      

      Downgrading to 10.4 works.

      InnoDB config:

      innodb-defragment              = 1
      innodb-flush-method            = O_DIRECT
      innodb-log-file-size           = 10G
      innodb-log-buffer-size         = 256M
      innodb-read-io-threads         = 16
      innodb-write-io-threads        = 16
      innodb-flush-log-at-trx-commit = 2
      innodb-flush-neighbors         = 0
      innodb-file-per-table          = 1
      innodb-buffer-pool-size        = 100G
      innodb-compression-algorithm   = zlib
      

      How can get further insight into the problem with InnoDB initialization?

      Attachments

        Issue Links

          Activity

            I'm sorry i don't have ib_logfiles any more, and all our are instances are upgraded to 10.5, so i cannot try to reproduce it easily anymore. I solved it by changing the innodb_log_file_size settings to force a rewrite of the logfile.

            olafbuitelaar Olaf Buitelaar added a comment - I'm sorry i don't have ib_logfiles any more, and all our are instances are upgraded to 10.5, so i cannot try to reproduce it easily anymore. I solved it by changing the innodb_log_file_size settings to force a rewrite of the logfile.

            @marko similar issue, as described here (version numbers differ)

            Going through the process of creating a new slave including upgrade process from MariaDB 10.2.22 (serverOld) to 10.5.12 on a new server (serverNew)

            (as inspired by the brighter mind here )

            1. rsync /var/lib/mysql from serverOld to serverNew
            2. On serverOld: FLUSH TABLES WITH READ LOCK; SHOW MASTER STATUS;
            3. rerun rsync from serverOld to serverNew
            4. Release read lock from serverOld
            5. Start mariadb on serverNew
            6. run mysql_upgrade on serverNew
            7. Celebrate and have a nap

            In actual practice step #5 failed numerous times before what I think is now an okay serverNew

            Innodb settings between serverOld and serverNew

            serverOld

            innodb-flush-method            = O_DIRECT
            innodb-log-files-in-group      = 2
            innodb-log-file-size           = 48M
            innodb-flush-log-at-trx-commit = 2
            innodb-file-per-table          = 1
            innodb-buffer-pool-size        = 128M
            

            serverNew

            innodb-flush-method            = O_DIRECT
            innodb-log-file-size           = 48M
            innodb-flush-log-at-trx-commit = 2
            innodb-file-per-table          = 1
            innodb-buffer-pool-size        = 128M
            

            The only difference is `innodb-log-files-in-group` setting is removed in serverNew, as it has been depricated and removed in 10.5

            Upgrade after crash?

            When attempting to start serverNew, it would fail with the following error:

            [ERROR] InnoDB: Upgrade after a crash is not supported. The redo log was created with MariaDB 10.2.22.
            [ERROR] InnoDB: Plugin initialization aborted with error Generic error
            

            the log file on serverOld showed no evidence of crashing. None the less, I restarted serverOld, and reran the process above. Still the same issue step #5.

            Remove ib_logfile* files

            I then tried forcing the recreation of the redo logs by removing them and then starting up serverNew. This resulted in the following scary errors numerous times:

            [ERROR] InnoDB: Page [page id: space=0, page number=1984] log sequence number 285722576186 is in the future! Current system log sequence number 259573448177.
            [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to https://mariadb.com/kb/en/library/innodb-recovery-modes/ for information about forcing recovery.
            

            innodb_fast_shutdown = 0

            The next attempt started with serverOld being restarted and innodb_fast_shutdown = 0 being set beforehand. I reran the above steps and still got stuck on step #5 with the following error:

            [ERROR] InnoDB: Upgrade after a crash is not supported. The redo log was created with MariaDB 10.2.22.
            [ERROR] InnoDB: Plugin initialization aborted with error Generic error
            

            This time, however, when I removed the ib_logfile* files, we seemed to have an okay startup:

            [Note] InnoDB: Initializing buffer pool, total size = 134217728, chunk size = 134217728
            [Note] InnoDB: Completed initialization of buffer pool
            [Note] InnoDB: Setting log file ./ib_logfile101 size to 50331648 bytes
            [Note] InnoDB: Renaming log file ./ib_logfile101 to ./ib_logfile0
            [Note] InnoDB: New log file created, LSN=288830457728
            [Note] InnoDB: 128 rollback segments are active.
            [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
            [Note] InnoDB: Creating shared tablespace for temporary tables
            [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
            [Note] InnoDB: File './ibtmp1' size is now 12 MB.
            [Note] InnoDB: 10.5.12 started; log sequence number 0; transaction id 3037161218
            [Note] Plugin 'FEEDBACK' is disabled.
            [Note] Recovering after a crash using /var/lib/mysql/mysql-bin
            [Note] Starting crash recovery...
            [Note] Crash recovery finished.
            [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
            [Note] Server socket created on IP: '::'.
            [ERROR] Incorrect definition of table mysql.event: expected column 'sql_mode' at position 14 to have type set('REAL_AS_FLOAT','PIPES_AS_CONCAT','ANSI_QUOTES','IGNORE_SPACE','IGNORE_BAD_TABLE_OPTIONS','ONLY_FULL_GROUP_BY','NO_UNSIGNED_SUBTRACTION','NO_DIR_IN_CREATE','POSTGRESQL','ORACLE','MSSQL','DB2','MAXDB','NO_KEY_OPTIONS','NO_TABLE_OPTIONS','NO_FIELD_OPTIONS','MYSQL323','MYSQL40','ANSI','NO_AUTO_VALUE_ON_ZERO','NO_BACKSLASH_ESCAPES','STRICT_TRANS_TABLES','STRICT_ALL_TABLES','NO_ZERO_IN_DATE','NO_ZERO_DATE','INVALID_DATES','ERROR_FOR_DIVISION_BY_ZERO','TRADITIONAL','NO_AUTO_CREATE_USER','HIGH_NOT_PRECEDENCE','NO_ENGINE_SUBSTITUTION','PAD_CHAR_TO_FULL_LENGTH','EMPTY_STRING_IS_NULL','SIMULTANEOUS_ASSIGNMENT'), found type set('REAL_AS_FLOAT','PIPES_AS_CONCAT','ANSI_QUOTES','IGNORE_SPACE','IGNORE_BAD_TABLE_OPTIONS','ONLY_FULL_GROUP_BY','NO_UNSIGNED_SUBTRACTION','NO_DIR_IN_CREATE','POSTGRESQL','ORACLE','MSSQL','DB2','MAXDB','NO_KEY_OPTIONS','NO_TABLE_OPTIONS','NO_FIELD_OPTIONS','MYSQL323','MYSQL40','ANSI','NO_AUTO_VALU
            [ERROR] mariadbd: Event Scheduler: An error occurred when initializing system tables. Disabling the Event Scheduler.
            [Note] Reading of all Master_info entries succeeded
            [Note] Added new Master_info '' to hash table
            [Note] /usr/sbin/mariadbd: ready for connections.
            Version: '10.5.12-MariaDB-1:10.5.12+maria~focal-log'  socket: '/run/mysqld/mysqld.sock'  port: 3306  mariadb.org binary distribution
            

            Running mysql_upgrade completed without issue.

            I'm not feeling confident that this upgrade is actually okay. removing the ib_logfile* seems questionable as a requirement to get the upgrade done. What should I be doing different?

            michaelcaplan Michael Caplan added a comment - @marko similar issue, as described here (version numbers differ) Going through the process of creating a new slave including upgrade process from MariaDB 10.2.22 (serverOld) to 10.5.12 on a new server (serverNew) (as inspired by the brighter mind here ) rsync /var/lib/mysql from serverOld to serverNew On serverOld: FLUSH TABLES WITH READ LOCK; SHOW MASTER STATUS; rerun rsync from serverOld to serverNew Release read lock from serverOld Start mariadb on serverNew run mysql_upgrade on serverNew Celebrate and have a nap In actual practice step #5 failed numerous times before what I think is now an okay serverNew Innodb settings between serverOld and serverNew serverOld innodb-flush-method = O_DIRECT innodb-log-files-in-group = 2 innodb-log-file-size = 48M innodb-flush-log-at-trx-commit = 2 innodb-file-per-table = 1 innodb-buffer-pool-size = 128M serverNew innodb-flush-method = O_DIRECT innodb-log-file-size = 48M innodb-flush-log-at-trx-commit = 2 innodb-file-per-table = 1 innodb-buffer-pool-size = 128M The only difference is `innodb-log-files-in-group` setting is removed in serverNew, as it has been depricated and removed in 10.5 Upgrade after crash? When attempting to start serverNew, it would fail with the following error: [ERROR] InnoDB: Upgrade after a crash is not supported. The redo log was created with MariaDB 10.2.22. [ERROR] InnoDB: Plugin initialization aborted with error Generic error the log file on serverOld showed no evidence of crashing. None the less, I restarted serverOld, and reran the process above. Still the same issue step #5. Remove ib_logfile* files I then tried forcing the recreation of the redo logs by removing them and then starting up serverNew. This resulted in the following scary errors numerous times: [ERROR] InnoDB: Page [page id: space=0, page number=1984] log sequence number 285722576186 is in the future! Current system log sequence number 259573448177. [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to https://mariadb.com/kb/en/library/innodb-recovery-modes/ for information about forcing recovery. innodb_fast_shutdown = 0 The next attempt started with serverOld being restarted and innodb_fast_shutdown = 0 being set beforehand. I reran the above steps and still got stuck on step #5 with the following error: [ERROR] InnoDB: Upgrade after a crash is not supported. The redo log was created with MariaDB 10.2.22. [ERROR] InnoDB: Plugin initialization aborted with error Generic error This time, however, when I removed the ib_logfile* files, we seemed to have an okay startup: [Note] InnoDB: Initializing buffer pool, total size = 134217728, chunk size = 134217728 [Note] InnoDB: Completed initialization of buffer pool [Note] InnoDB: Setting log file ./ib_logfile101 size to 50331648 bytes [Note] InnoDB: Renaming log file ./ib_logfile101 to ./ib_logfile0 [Note] InnoDB: New log file created, LSN=288830457728 [Note] InnoDB: 128 rollback segments are active. [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1" [Note] InnoDB: Creating shared tablespace for temporary tables [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ... [Note] InnoDB: File './ibtmp1' size is now 12 MB. [Note] InnoDB: 10.5.12 started; log sequence number 0; transaction id 3037161218 [Note] Plugin 'FEEDBACK' is disabled. [Note] Recovering after a crash using /var/lib/mysql/mysql-bin [Note] Starting crash recovery... [Note] Crash recovery finished. [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool [Note] Server socket created on IP: '::'. [ERROR] Incorrect definition of table mysql.event: expected column 'sql_mode' at position 14 to have type set('REAL_AS_FLOAT','PIPES_AS_CONCAT','ANSI_QUOTES','IGNORE_SPACE','IGNORE_BAD_TABLE_OPTIONS','ONLY_FULL_GROUP_BY','NO_UNSIGNED_SUBTRACTION','NO_DIR_IN_CREATE','POSTGRESQL','ORACLE','MSSQL','DB2','MAXDB','NO_KEY_OPTIONS','NO_TABLE_OPTIONS','NO_FIELD_OPTIONS','MYSQL323','MYSQL40','ANSI','NO_AUTO_VALUE_ON_ZERO','NO_BACKSLASH_ESCAPES','STRICT_TRANS_TABLES','STRICT_ALL_TABLES','NO_ZERO_IN_DATE','NO_ZERO_DATE','INVALID_DATES','ERROR_FOR_DIVISION_BY_ZERO','TRADITIONAL','NO_AUTO_CREATE_USER','HIGH_NOT_PRECEDENCE','NO_ENGINE_SUBSTITUTION','PAD_CHAR_TO_FULL_LENGTH','EMPTY_STRING_IS_NULL','SIMULTANEOUS_ASSIGNMENT'), found type set('REAL_AS_FLOAT','PIPES_AS_CONCAT','ANSI_QUOTES','IGNORE_SPACE','IGNORE_BAD_TABLE_OPTIONS','ONLY_FULL_GROUP_BY','NO_UNSIGNED_SUBTRACTION','NO_DIR_IN_CREATE','POSTGRESQL','ORACLE','MSSQL','DB2','MAXDB','NO_KEY_OPTIONS','NO_TABLE_OPTIONS','NO_FIELD_OPTIONS','MYSQL323','MYSQL40','ANSI','NO_AUTO_VALU [ERROR] mariadbd: Event Scheduler: An error occurred when initializing system tables. Disabling the Event Scheduler. [Note] Reading of all Master_info entries succeeded [Note] Added new Master_info '' to hash table [Note] /usr/sbin/mariadbd: ready for connections. Version: '10.5.12-MariaDB-1:10.5.12+maria~focal-log' socket: '/run/mysqld/mysqld.sock' port: 3306 mariadb.org binary distribution Running mysql_upgrade completed without issue. I'm not feeling confident that this upgrade is actually okay. removing the ib_logfile* seems questionable as a requirement to get the upgrade done. What should I be doing different?
            sharpsounds Wesley Oliver added a comment -

            @Michael Caplan

            Your fix of removing ib_logfile* files and innodb_fast_shutdown = 0 worked for me too.
            Different version numbers for me as well. Mine was an incremental upgrade inside a docker environment.

            No data loss as far as I tell.

            thanks for the workaround!

            sharpsounds Wesley Oliver added a comment - @Michael Caplan Your fix of removing ib_logfile* files and innodb_fast_shutdown = 0 worked for me too. Different version numbers for me as well. Mine was an incremental upgrade inside a docker environment. No data loss as far as I tell. thanks for the workaround!

            michaelcaplan, sharpsounds, it is extremely dangerous to ever delete or rename the redo log files. That would remove any quarantee about any changes that may have been written since the latest log checkpoint.

            Furthermore, using regular copying methods such as rsync while InnoDB is running is not safe, except when you know that the buffer pool does not contain any pending changes and that no changes will be applied while copying. Maybe, if you ran another rsync after the first one and it did not report any changes, it might be somewhat safe, but only if you can guarantee that the redo log file is logically empty.

            Note that a command like FLUSH TABLES WITH READ LOCK will not suspend any InnoDB internal writes from background threads. These include merging the change buffer, purging transaction history, applying changes to fulltext indexes, rotating encryption keys, and updating persistent statistics.

            Completing a slow shutdown (shutdown with innodb_fast_shutdown=0) before the upgrade was never a real requirement. Completing a clean shutdown is. If you perform funny steps, you may get funny results, possibly in the form of weird crashes or corruption some time in the future. If CHECK TABLE does not report errors on any table after such an upgrade, you might be safe.

            If you do not want to shut down the old server before upgrading, you can use our backup tool to safely copy the data. Before starting the new server, be sure to run mariabackup --prepare on the backed up data directory.

            marko Marko Mäkelä added a comment - michaelcaplan , sharpsounds , it is extremely dangerous to ever delete or rename the redo log files. That would remove any quarantee about any changes that may have been written since the latest log checkpoint. Furthermore, using regular copying methods such as rsync while InnoDB is running is not safe, except when you know that the buffer pool does not contain any pending changes and that no changes will be applied while copying. Maybe, if you ran another rsync after the first one and it did not report any changes, it might be somewhat safe, but only if you can guarantee that the redo log file is logically empty. Note that a command like FLUSH TABLES WITH READ LOCK will not suspend any InnoDB internal writes from background threads. These include merging the change buffer, purging transaction history, applying changes to fulltext indexes, rotating encryption keys, and updating persistent statistics. Completing a slow shutdown (shutdown with innodb_fast_shutdown=0 ) before the upgrade was never a real requirement. Completing a clean shutdown is. If you perform funny steps, you may get funny results, possibly in the form of weird crashes or corruption some time in the future. If CHECK TABLE does not report errors on any table after such an upgrade, you might be safe. If you do not want to shut down the old server before upgrading, you can use our backup tool to safely copy the data. Before starting the new server, be sure to run mariabackup --prepare on the backed up data directory.

            Note: A bug in the 10.5.12 release causes the upgrade wizard for Microsoft Windows to abruptly kill the 10.4 server, instead of shutting it down gracefully. This would then lead to the 10.5 server refusing to start up.

            marko Marko Mäkelä added a comment - Note: A bug in the 10.5.12 release causes the upgrade wizard for Microsoft Windows to abruptly kill the 10.4 server, instead of shutting it down gracefully. This would then lead to the 10.5 server refusing to start up.

            People

              marko Marko Mäkelä
              crishoj Christian Rishøj
              Votes:
              2 Vote for this issue
              Watchers:
              12 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.