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

    • Type: Bug
    • Status: Closed (View Workflow)
    • Priority: Major
    • Resolution: Incomplete
    • Affects Version/s: 10.5.12
    • Fix Version/s: N/A
    • Component/s: None
    • Labels:
      None
    • Environment:
      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

          Issue Links

            Activity

              People

              Assignee:
              allen.lee@mariadb.com Allen Lee
              Reporter:
              allen.lee@mariadb.com Allen Lee
              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.