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

upgrade wizard never finishes at Phase 9/10 and hit "InnoDB: Upgrade after a crash is not supported" after restart

    XMLWordPrintable

Details

    • Bug
    • Status: Closed (View Workflow)
    • Major
    • Resolution: Incomplete
    • 10.5.12
    • N/A
    • None
    • None
    • Windows

    Description

      I was trying to upgrade mariadb 10.4.17 to mariadb 10.5.12.
      Did clean shutdown with innodb_fast_shutdown=0.

      2021-10-29 11:10:44 0 [Note] InnoDB: Mutexes and rw_locks use Windows interlocked functions
      		 
      2021-10-29 11:10:44 0 [Note] InnoDB: Uses event mutexes
      		 
      2021-10-29 11:10:44 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
      		 
      2021-10-29 11:10:44 0 [Note] InnoDB: Number of pools: 1
      		 
      2021-10-29 11:10:44 0 [Note] InnoDB: Using SSE2 crc32 instructions
      		 
      2021-10-29 11:10:44 0 [Note] InnoDB: Initializing buffer pool, total size = 32G, instances = 8, chunk size = 128M
      		 
      2021-10-29 11:10:45 0 [Note] InnoDB: Completed initialization of buffer pool
      		 
      2021-10-29 11:10:45 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
      		 
      2021-10-29 11:10:45 0 [Note] InnoDB: Creating shared tablespace for temporary tables
      		 
      2021-10-29 11:10:45 0 [Note] InnoDB: Setting file '.\ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
      		 
      2021-10-29 11:10:45 0 [Note] InnoDB: File '.\ibtmp1' size is now 12 MB.
      		 
      2021-10-29 11:10:45 0 [Note] InnoDB: Waiting for purge to start
      		 
      2021-10-29 11:10:45 0 [Note] InnoDB: 10.4.17 started; log sequence number 68309599253; transaction id 7015348
      		 
      2021-10-29 11:10:45 0 [Note] Plugin 'FEEDBACK' is disabled.
      		 
      2021-10-29 11:10:45 0 [Note] Reading of all Master_info entries succeeded
      		 
      2021-10-29 11:10:45 0 [Note] Added new Master_info '' to hash table
      		 
      2021-10-29 11:10:45 0 [Note] C:\Program Files\MariaDB 10.4\bin\mysqld.exe: ready for connections.
      		 
      Version: '10.4.17-MariaDB'  socket: ''  port: 0  mariadb.org binary distribution
      		 
      2021-10-29 11:10:46 0 [Note] C:\Program Files\MariaDB 10.4\bin\mysqld.exe (initiated by: unknown): Normal shutdown
      		 
      2021-10-29 11:10:46 0 [Note] Event Scheduler: Purging the queue. 0 events
      		 
      2021-10-29 11:10:46 0 [Note] InnoDB: FTS optimize thread exiting.
      		 
      2021-10-29 11:10:46 0 [Note] InnoDB: Starting shutdown...
      		 
      2021-10-29 11:10:47 0 [Note] InnoDB: Shutdown completed; log sequence number 68309599262; transaction id 7015349
      		 
      2021-10-29 11:10:47 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
      		 
      2021-10-29 11:10:47 0 [Note] C:\Program Files\MariaDB 10.4\bin\mysqld.exe: Shutdown complete

      • ran mariadb-10.5.12-winx64.msi to upgrade the existing 10.4.17( instance name : MariaDB-10417)
      • all phase passed until 9 out of 10 as below

      Looking at mariadb error log

      2021-10-29 11:10:47 0 [Note] InnoDB: Uses event mutexes
      		 
      2021-10-29 11:10:47 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
      		 
      2021-10-29 11:10:47 0 [Note] InnoDB: Number of pools: 1
      		 
      2021-10-29 11:10:47 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
      		 
      2021-10-29 11:10:47 0 [Note] InnoDB: Initializing buffer pool, total size = 34359738368, chunk size = 134217728
      		 
      2021-10-29 11:10:48 0 [Note] InnoDB: Completed initialization of buffer pool
      		 
      2021-10-29 11:10:48 0 [Note] InnoDB: Upgrading redo log: 5368709120 bytes; LSN=68309599274
      		 
      2021-10-29 11:10:48 0 [Note] InnoDB: Starting to delete and rewrite log file.
      		 
      2021-10-29 11:10:48 0 [Note] InnoDB: Setting log file .\ib_logfile101 size to 5368709120 bytes
      		 
      2021-10-29 11:10:48 0 [Note] InnoDB: Renaming log file .\ib_logfile101 to .\ib_logfile0
      		 
      2021-10-29 11:10:48 0 [Note] InnoDB: New log file created, LSN=68309599274
      		 
      2021-10-29 11:10:48 0 [Note] InnoDB: 128 rollback segments are active.
      		 
      2021-10-29 11:10:48 0 [Note] InnoDB: Creating shared tablespace for temporary tables
      		 
      2021-10-29 11:10:48 0 [Note] InnoDB: Setting file '.\ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
      		 
      2021-10-29 11:10:48 0 [Note] InnoDB: File '.\ibtmp1' size is now 12 MB.
      		 
      2021-10-29 11:10:48 0 [Note] InnoDB: 10.5.12 started; log sequence number 68309599262; transaction id 7015348
      		 
      2021-10-29 11:10:48 0 [Note] Plugin 'FEEDBACK' is disabled.
      		 
      2021-10-29 11:10:48 0 [Note] Reading of all Master_info entries succeeded
      		 
      2021-10-29 11:10:48 0 [Note] Added new Master_info '' to hash table
      		 
      2021-10-29 11:10:48 0 [Note] C:\Program Files\MariaDB 10.5\bin\mysqld.exe: ready for connections.
      		 
      Version: '10.5.12-MariaDB'  socket: ''  port: 0  mariadb.org binary distribution
      		 
      2021-10-29 11:10:50 0 [Note] C:\Program Files\MariaDB 10.5\bin\mysqld.exe (initiated by: unknown): Normal shutdown

      And windows event log shows

      C:\Program Files\MariaDB 10.4\bin\mysqld.exe: ready for connections.
      		 
      Version: '10.4.17-MariaDB'  socket: ''  port: 0  mariadb.org binary distribution
      		 
      C:\Program Files\MariaDB 10.4\bin\mysqld.exe (initiated by: unknown): Normal shutdown
      		 
      Event Scheduler: Purging the queue. 0 events
      		 
      InnoDB: FTS optimize thread exiting.
      		 
      InnoDB: Starting shutdown...
      		 
      InnoDB: Shutdown completed; log sequence number 68309599262; transaction id 7015349
      		 
      InnoDB: Removed temporary tablespace data file: "ibtmp1"
      		 
      C:\Program Files\MariaDB 10.4\bin\mysqld.exe: Shutdown complete
      		 
      C:\Program Files\MariaDB 10.5\bin\mysqld.exe (mysqld 10.5.12-MariaDB) starting as process 32860 ...
      		 
      InnoDB: Uses event mutexes
      		 
      InnoDB: Compressed tables use zlib 1.2.11
      		 
      InnoDB: Using crc32 + pclmulqdq instructions
      		 
      InnoDB: Number of pools: 1
      		 
      InnoDB: Initializing buffer pool, total size = 34359738368, chunk size = 134217728
      		 
      InnoDB: Completed initialization of buffer pool
      		 
      InnoDB: Upgrading redo log: 5368709120 bytes; LSN=68309599274
      		 
      InnoDB: Starting to delete and rewrite log file.
      		 
      InnoDB: Setting log file .\ib_logfile101 size to 5368709120 bytes
      		 
      InnoDB: Renaming log file .\ib_logfile101 to .\ib_logfile0
      		 
      InnoDB: New log file created, LSN=68309599274
      		 
      InnoDB: 128 rollback segments are active.
      		 
      InnoDB: Creating shared tablespace for temporary tables
      		 
      InnoDB: File '.\ibtmp1' size is now 12 MB.
      		 
      InnoDB: Setting file '.\ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
      		 
      Plugin 'FEEDBACK' is disabled.
      		 
      InnoDB: 10.5.12 started; log sequence number 68309599262; transaction id 7015348
      		 
      Reading of all Master_info entries succeeded
      		 
      Added new Master_info '' to hash table
      		 
      C:\Program Files\MariaDB 10.5\bin\mysqld.exe: ready for connections.
      		 
      Version: '10.5.12-MariaDB'  socket: ''  port: 0  mariadb.org binary distribution
      		 
      C:\Program Files\MariaDB 10.5\bin\mysqld.exe (initiated by: unknown): Normal shutdown

      At that point, I confirmed mariadb-10417 was stopped in services.msc.
      Since upgrade wizard did not move foward, I've cancelled it by clicking cancel button and upgrade wizard disappeared. No more logs were logged after upgrade wizard cancellation.

      After a couple of effort restart the mariadb service. it still failed with the following error.

      2021-10-29 11:42:45 0 [Note] InnoDB: Uses event mutexes
      		 
      2021-10-29 11:42:45 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
      		 
      2021-10-29 11:42:45 0 [Note] InnoDB: Number of pools: 1
      		 
      2021-10-29 11:42:45 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
      		 
      2021-10-29 11:42:45 0 [Note] InnoDB: Initializing buffer pool, total size = 34359738368, chunk size = 134217728
      		 
      2021-10-29 11:42:46 0 [Note] InnoDB: Completed initialization of buffer pool
      		 
      2021-10-29 11:42:46 0 [Note] InnoDB: 128 rollback segments are active.
      		 
      2021-10-29 11:42:46 0 [Note] InnoDB: Creating shared tablespace for temporary tables
      		 
      2021-10-29 11:42:46 0 [Note] InnoDB: Setting file '.\ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
      		 
      2021-10-29 11:42:46 0 [Note] InnoDB: File '.\ibtmp1' size is now 12 MB.
      		 
      2021-10-29 11:42:46 0 [Note] InnoDB: 10.5.12 started; log sequence number 68309637872; transaction id 7015367
      		 
      2021-10-29 11:42:46 0 [Note] Plugin 'FEEDBACK' is disabled.
      		 
      2021-10-29 11:42:46 0 [Note] Reading of all Master_info entries succeeded
      		 
      2021-10-29 11:42:46 0 [Note] Added new Master_info '' to hash table
      		 
      2021-10-29 11:42:46 0 [Note] C:\Program Files\MariaDB 10.5\bin\mysqld.exe: ready for connections.
      		 
      Version: '10.5.12-MariaDB'  socket: ''  port: 0  mariadb.org binary distribution
      		 
      2021-10-29 11:42:48 0 [Note] C:\Program Files\MariaDB 10.5\bin\mysqld.exe (initiated by: unknown): Normal shutdown
      		 
      2021-10-29 11:44:58 0 [Note] mysqld.exe: Aria engine: starting recovery
      		 
      recovered pages: 0% 12% 23% 35% 45% 57% 68% 79% 89% 99% 100% (0.0 seconds); 
      2021-10-29 11:44:58 0 [Note] mysqld.exe: Aria engine: recovery done
      		 
      2021-10-29 11:44:58 0 [ERROR] InnoDB: The innodb_system data file 'ibdata1' must be writable
      		 
      2021-10-29 11:44:58 0 [ERROR] InnoDB: The innodb_system data file 'ibdata1' must be writable
      		 
      2021-10-29 11:44:58 0 [ERROR] Plugin 'InnoDB' init function returned error.
      		 
      2021-10-29 11:44:58 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
      		 
      2021-10-29 11:44:58 0 [Note] Plugin 'FEEDBACK' is disabled.
      		 
      2021-10-29 11:44:58 0 [Note] Zerofilling moved table:  '.\mysql\plugin'
      		 
      2021-10-29 11:44:58 0 [ERROR] Unknown/unsupported storage engine: InnoDB
      		 
      2021-10-29 11:44:58 0 [ERROR] Aborting
      		 
      2021-10-29 11:46:00 0 [ERROR] InnoDB: The innodb_system data file 'ibdata1' must be writable
      		 
      2021-10-29 11:46:00 0 [ERROR] InnoDB: The innodb_system data file 'ibdata1' must be writable
      		 
      2021-10-29 11:46:00 0 [ERROR] Plugin 'InnoDB' init function returned error.
      		 
      2021-10-29 11:46:00 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
      		 
      2021-10-29 11:46:00 0 [Note] Plugin 'FEEDBACK' is disabled.
      		 
      2021-10-29 11:46:00 0 [ERROR] Unknown/unsupported storage engine: InnoDB
      		 
      2021-10-29 11:46:00 0 [ERROR] Aborting
      		 
       
      		 
      2021-10-29 11:50:31 0 [ERROR] InnoDB: The innodb_system data file 'ibdata1' must be writable
      		 
      2021-10-29 11:50:31 0 [ERROR] InnoDB: The innodb_system data file 'ibdata1' must be writable
      		 
      2021-10-29 11:50:31 0 [ERROR] Plugin 'InnoDB' init function returned error.
      		 
      2021-10-29 11:50:31 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
      		 
      2021-10-29 11:50:31 0 [Note] Plugin 'FEEDBACK' is disabled.
      		 
      2021-10-29 11:50:31 0 [ERROR] Unknown/unsupported storage engine: InnoDB
      		 
      2021-10-29 11:50:31 0 [ERROR] Aborting
      		 
       
      		 
      2021-10-29 11:53:19 0 [ERROR] InnoDB: The innodb_system data file 'ibdata1' must be writable
      		 
      2021-10-29 11:53:19 0 [ERROR] InnoDB: The innodb_system data file 'ibdata1' must be writable
      		 
      2021-10-29 11:53:19 0 [ERROR] Plugin 'InnoDB' init function returned error.
      		 
      2021-10-29 11:53:19 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
      		 
      2021-10-29 11:53:19 0 [Note] Plugin 'FEEDBACK' is disabled.
      		 
      2021-10-29 11:53:19 0 [ERROR] Unknown/unsupported storage engine: InnoDB
      		 
      2021-10-29 11:53:19 0 [ERROR] Aborting

      Attachments

        1. image-2021-10-29-11-28-57-526.png
          33 kB
          Allen Lee
        2. my.ini
          15 kB
          Allen Lee
        3. Update-MariaDB-10.4.21-auf-10.5.12_2.log
          0.1 kB
          Allen Lee

        Issue Links

          duplicates

          Bug - A problem which impairs or prevents the functions of the product. MDEV-26325 mysqld process hangs when stopped after executing mysql_upgrade

          • Blocker - Blocks development and/or testing work, production could not run.
          • Closed
          relates to

          Bug - A problem which impairs or prevents the functions of the product. MDEV-23136 InnoDB init fail after upgrade from 10.4 to 10.5

          • Major - Major loss of function.
          • Closed

          Activity

            People

              allen.lee@mariadb.com Allen Lee (Inactive)
              allen.lee@mariadb.com Allen Lee (Inactive)
              Votes:
              0 Vote for this issue
              Watchers:
              7 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.