[MDEV-26932] upgrade wizard never finishes at Phase 9/10 and hit "InnoDB: Upgrade after a crash is not supported" after restart Created: 2021-10-29  Updated: 2022-01-31  Resolved: 2022-01-31

Status: Closed
Project: MariaDB Server
Component/s: None
Affects Version/s: 10.5.12
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Allen Lee (Inactive) Assignee: Allen Lee (Inactive)
Resolution: Incomplete Votes: 0
Labels: None
Environment:

Windows

Attachments: Text File Update-MariaDB-10.4.21-auf-10.5.12_2.log     PNG File image-2021-10-29-11-28-57-526.png     File my.ini    
Issue Links:
Duplicate
duplicates MDEV-26325 mysqld process hangs when stopped aft... Closed
Relates
relates to MDEV-23136 InnoDB init fail after upgrade from 1... Closed

 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



 Comments   
Comment by Daniel Black [ 2021-10-29 ]

The Aria recovery and ibdata1 not writable make it look like an existing mysqld.exe is already running. Try terminating that process first if it exists.

Comment by Marko Mäkelä [ 2021-10-29 ]

wlad, can you please analyze this?

I would suspect that the 10.4 server was forcibly killed for some reason. (Is there some timeout for the shutdown?)

The startup message that says that upgrade from a crash is not supported identifies the version of the server with which ib_logfile0 was created (or the log was last resized), if that version was MySQL 5.7.9 or any later 5.7.x release, or anything later than MariaDB 10.2.2. The first 512 bytes of the ib_logfile0 are never modified during normal operation.

I do not know whether file locking on Windows would still prevent multiple servers to be started on the same data file, but I assume and hope so. On other systems, MDEV-24393 recently changed the default to not acquire any advisory locks (except for some Aria file).

Comment by Vladislav Vaintroub [ 2021-10-29 ]

The issue with "never finishes" is "MDEV-26325 Shutdown hangs whenever named pipes were used for connections." Apparently, I suggested to re-release 10.5.12, because it broke all named pipe connections (and upgrade_service, and upgrade_wizard would use such named pipe to communicate with a server), but issue was not considered important enough for re-release.
So, I'd think that database runs in 10.4, until 10.5.13 is released, which is soon.

The "must be writable" message, would most probably stem from an instance of mysqld.exe which is still up, and could not shutdown. The user would need to kill it , via taskkill /PID:<pid> /F from elevated command prompt)

Comment by Marko Mäkelä [ 2021-11-29 ]

I believe that the affected version is reported wrong. The problem should not be that we refuse to start up an upgraded server when crash recovery is needed, but that the server before the upgrade was apparently forcibly killed.

When it comes to the 10.4 server that was apparently hung during shutdown, wlad should be able to help to produce a crash dump or something that would allow us to determine and fix the cause of that hang.

Comment by Vladislav Vaintroub [ 2021-11-29 ]

I think I will repeat myself here, in case it was not clear first time,

Everyone who installed 10.5.12 was affected by mysql_upgrade_service, and upgrade wizard hang.
I suggested that release would be reverted, yet the higher-ups, and the QA did not find it to be important enough.
This was fixed in MDEV-26325, which was caused by a buggy fix for MDEV-18353

This does not need to be debugged anymore, it was already debugged, and fixed.

mysql_upgrade_service is is only procedure we support on Windows, when it comes to services. If it does not involve Windows service, it can be upgraded like elsewhere - you best do an offline backup, you start new mysqld on the old datadir, and run mysql_upgrade.
It should be that simple.

Deviations and improvisation, like installing 10.5 with service, and then copying 10.4 data to 10.5 datadir while server is still online (this is what the original reported did, from what I've heard), are not appreciated by Innodb and will be punished with "Crash upgrade is not supported".

As for guidance - use 10.5.13, where mysql_upgrade_service was fixed.

Comment by Vladislav Vaintroub [ 2021-11-29 ]

I'm changing assignee to allen.lee@mariadb.com to confirm that this is a duplicate, and to confirm the supported procedure below works, for 10.5.13 or later. It did not work in 10.5.12, and we know that, and I explained that. And then this can be closed as duplicate.

Upgrade procedure

From the elevated command line (cmd started with "Run as Administrator")

"C:\Program Files\MariaDB 10.5\bin\mysql_upgrade_service.exe" --service=<servicename>

That's the whole supported procedure.

Comment by Marko Mäkelä [ 2021-12-31 ]

Even after the 10.4 server was shut down correctly according to the server error log, the 10.5 server would refuse to start up, claiming that crash recovery is needed.

An upgrade succeeded after the parameter innodb_log_file_size was changed in the server configuration, and the 10.4 server was restarted and shut down. (The log file size change forces the log to be rebuilt on server startup.)

After the 10.4 log file was rebuilt, the 10.5 server would detect that the log file is logically empty, and allow the upgrade. Unfortunately, I did not get a copy of the problematic 10.4 log file, so this problem was not fixed.

Generated at Thu Feb 08 09:49:02 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.