Ubuntu 20.04 / Linux 5.4.0

It's not clear at all what happened inside InnoDB. As a wild guess could you try innodb-flush-method = fsync?

The clue is in the very first error message:

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.

MDEV-12353 removed all code to parse or apply old-format redo log records.

Could it be that the 10.4 server was not shut down normally, for example because the server hung during the shutdown process? Or did you attempt to start up 10.5 on a backup of a 10.4 data directory without first running mariabackup --prepare with the 10.4 executable?

There also is a theoretical possibility is that the logic for detecting whether the old-format redo log file was cleanly shut down is faulty.

10.4 was shut down cleanly, with innodb_fast_shutdown = 1. Could 0 possibly help?

I'm starting 10.5 on the data directory of 10.4 itself, not a backup.

Is innodb_fast_shutdown = 0 and removing ib_logfile* after shutdown worth a try?

Any other value than innodb_fast_shutdown=2 should be fine. I would like to get a copy of the ib_logfile* files for repeating and analyzing the failure.

I am getting the same error when updating some docker hosts from 10.4 to 10.5 I ran with the default settings, and tried setting innodb_fast_shutdown=0

I tried shutting down correctly on 10.4 but no mater what I do when switching to 10.5 I get this error.
I am pointing to the same data directory.

If I try removing ib_logfile* 10.5 boots but, I get errors like this :

{"line":"2020-07-17 10:50:03 0 [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.","source":"stderr","tag":"0ecdfb21b558"}

{"line":"2020-07-17 10:50:03 0 [ERROR] InnoDB: Page [page id: space=33, page number=3597] log sequence number 231317195 is in the future! Current system log sequence number 124229534.","source":"stderr","tag":"0ecdfb21b558"}

{"line":"2020-07-17 10:50:03 0 [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.","source":"stderr","tag":"0ecdfb21b558"}

{"line":"2020-07-17 10:50:03 0 [ERROR] InnoDB: Page [page id: space=33, page number=3595] log sequence number 231317141 is in the future! Current system log sequence number 124229534.","source":"stderr","tag":"0ecdfb21b558"}

{"line":"2020-07-17 10:50:03 0 [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.","source":"stderr","tag":"0ecdfb21b558"}

{"line":"2020-07-17 10:50:03 0 [ERROR] InnoDB: Page [page id: space=33, page number=3594] log sequence number 231317114 is in the future! Current system log sequence number 124229534.","source":"stderr","tag":"0ecdfb21b558"}

hmn, can you please show the 10.4 server error log messages for the shutdown?

While it is not recommended practice to remove the redo log files under any circumstances, it should be ‘safe’ to remove those files after a clean shutdown of the server up to 10.5. Any messages about the log sequence number being in the future on any data pages suggests that the log had not been shut down properly. (Note: When we finally implement MDEV-11633, there will be no other central place to store the latest log sequence number than the log itself. At that point we must refuse to start up InnoDB if the log files are missing.)

One more thing that you could do for troubleshooting is to start up a debug version of the 10.4 server on a backup copy of the data where the ib_logfile* still exist, using the option --debug=d,ib_log. If you see any messages about log records being parsed or applied, then we know that the redo log was not actually logically empty, or in other words, the server had not been shut down cleanly. Even without a debug server, if you see a startup message

[Note] INNODB: Starting crash recovery from checkpoint LSN=

then you should know that the server had not been shut down cleanly.

My problem was definetly an unclean shutdown.

We are running docker through nomad and it did not send stop signals correctly so after adding timeout and SIGTERM it managed to get a "Shutdown complete" in the log.

Then I could switch to 10.5 and it started updating the files and bootet correctly.

Thank you, hmn! The 10.5 startup code is working as expected for you then.

I do not expect future versions to remove crash-upgrade support from 10.5 any time soon. MDEV-14425 will change the log file format, but I think that we should retain support for upgrading from the 10.5 format.

Also in the past, MariaDB 10.2 removed crash-upgrade support from earlier versions, and MariaDB 10.4 removed crash-upgrade support for the 10.2 innodb_safe_truncate=OFF format that was replaced in MDEV-13564 by something more robust.

On a related note, when upgrading from 10.2 or earlier to 10.3 or later, a slow shutdown is recommended due to undo log format changes that were introduced in MDEV-12288. Failure to execute a shutdown with innodb_fast_shutdown=0 may trigger MDEV-15912.

crishoj, can you please let us know if you have a genuine case where a log file from a clean 10.4 shutdown was incorrectly identified as a nonempty log file by 10.5 startup?

An unclean shutdown may also have been the culprit in my case.

On a second try, the upgrade went smoothly.

2020-07-28 1:36:47 0 [Note] mariadbd: O_TMPFILE is not supported on /tmp (disabling future attempts)
2020-07-28 1:36:48 0 [Note] InnoDB: Initializing buffer pool, total size = 107374182400, chunk size = 134217728
2020-07-28 1:36:50 0 [Note] InnoDB: Completed initialization of buffer pool
2020-07-28 1:36:50 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-28 1:36:50 0 [Note] InnoDB: Upgrading redo log: 10737418240 bytes; LSN=66310146148322
2020-07-28 1:36:50 0 [Note] InnoDB: Starting to delete and rewrite log file.
2020-07-28 1:36:54 0 [Note] InnoDB: Setting log file ./ib_logfile101 size to 10737418240 bytes
2020-07-28 1:36:54 0 [Note] InnoDB: Renaming log file ./ib_logfile101 to ./ib_logfile0
2020-07-28 1:36:54 0 [Note] InnoDB: New log file created, LSN=66310146148322
2020-07-28 1:36:54 0 [Note] InnoDB: 128 rollback segments are active.
2020-07-28 1:36:54 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2020-07-28 1:36:54 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2020-07-28 1:36:54 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2020-07-28 1:36:54 0 [Note] InnoDB: 10.5.4 started; log sequence number 66310146148310; transaction id 136024533273
2020-07-28 1:36:54 0 [Note] InnoDB: Loading buffer pool(s) from /mnt/nvme/mysql/ib_buffer_pool

I had a similar issue, i was running 10.4.14 and on some machines it refused to upgrade to 10.5.7 (running in docker). I was certain the containers did shutdown properly, and during startup it didn't report any redo log's needed to be applied;

shutdown;
2020-11-11 17:50:08 0 [Note] mysqld: ready for connections.
Version: '10.4.16-MariaDB-1:10.4.16+maria~focal' socket: '/var/run/mysqld/mysqld.sock' port: 3306 mariadb.org binary distribution
2020-11-11 17:50:11 0 [Note] InnoDB: Buffer pool(s) load completed at 201111 17:50:11
2020-11-11 17:52:35 0 [Note] mysqld (initiated by: unknown): Normal shutdown
2020-11-11 17:52:35 0 [Note] Event Scheduler: Purging the queue. 0 events
2020-11-11 17:52:35 0 [Note] InnoDB: FTS optimize thread exiting.
2020-11-11 17:52:35 1 [Note] InnoDB: to purge 10 transactions
2020-11-11 17:52:35 0 [Note] InnoDB: Starting shutdown...
2020-11-11 17:52:35 0 [Note] InnoDB: Dumping buffer pool(s) to /var/lib/mysql/ib_buffer_pool
2020-11-11 17:52:35 0 [Note] InnoDB: Buffer pool(s) dump completed at 201111 17:52:35
2020-11-11 17:52:37 0 [Note] InnoDB: Shutdown completed; log sequence number 6999555901289; transaction id 1965950013
2020-11-11 17:52:37 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2020-11-11 17:52:37 0 [Note] mysqld: Shutdown complete

startup:
2020-11-11 17:53:41+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 1:10.5.7+maria~focal started.
2020-11-11 17:53:42+00:00 [Note] [Entrypoint]: Switching to dedicated user 'mysql'
2020-11-11 17:53:42+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 1:10.5.7+maria~focal started.
2020-11-11 17:53:42 0 [Note] mysqld (mysqld 10.5.7-MariaDB-1:10.5.7+maria~focal) starting as process 1 ...
2020-11-11 17:53:42 0 [Warning] The parameter innodb_buffer_pool_instances is deprecated and has no effect.
2020-11-11 17:53:42 0 [Warning] The parameter innodb_page_cleaners is deprecated and has no effect.
2020-11-11 17:53:42 0 [Note] InnoDB: Using Linux native AIO
2020-11-11 17:53:42 0 [Note] InnoDB: Uses event mutexes
2020-11-11 17:53:42 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2020-11-11 17:53:42 0 [Note] InnoDB: Number of pools: 1
2020-11-11 17:53:42 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
2020-11-11 17:53:42 0 [Note] mysqld: O_TMPFILE is not supported on /tmp (disabling future attempts)
2020-11-11 17:53:42 0 [Note] InnoDB: Initializing buffer pool, total size = 9663676416, chunk size = 134217728
2020-11-11 17:53:42 0 [Note] InnoDB: Completed initialization of buffer pool
2020-11-11 17:53:42 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2020-11-11 17:53:42 0 [ERROR] InnoDB: Upgrade after a crash is not supported. The redo log was created with MariaDB 10.4.14.
2020-11-11 17:53:42 0 [ERROR] InnoDB: Plugin initialization aborted with error Generic error
2020-11-11 17:53:42 0 [Note] InnoDB: Starting shutdown...
2020-11-11 17:53:42 0 [ERROR] Plugin 'InnoDB' init function returned error.
2020-11-11 17:53:42 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
2020-11-11 17:53:42 0 [Note] Plugin 'FEEDBACK' is disabled.
2020-11-11 17:53:42 0 [ERROR] Unknown/unsupported storage engine: InnoDB
2020-11-11 17:53:42 0 [ERROR] Aborting

I also deployed all images with innodb-fast-shutdown=0, but to no avail. Intrestingly i tried to upgrade to 10.4.16 first, but the 10.5.7 image reads the redo logs as being from 10.4.14.
To resolve it, i changed the innodb_log_file_size (while still being at 10.4.16), so the log files would be recreated on the next start. Then i upgraded the containers, and all images were able to convert the redo log files.

olafbuitelaar, sorry, I did not notice your message until now. Your log excerpt indicates that the 10.4 server was shut down properly, and yet the 10.5 server refused to start up.

If you or anyone encounter this, please provide:

1. A backup copy of the ib_logfile* files that prevent the 10.5 server from start up.
2. Server error log output from the preceding shutdown of the old server.
3. Server error log output from the failed 10.5 start-up.
4. Server error log output from starting up the old server again (to show that no crash recovery was needed).

If the old server (such as 10.4) startup indicates that crash recovery was in fact needed, then that must be filed as a different bug, affecting the old server’s shutdown.

If the old server startup shows that no recovery was needed, then the 10.5 code that attempts to detect whether the log files are logically empty is wrong. And for that we would need a copy of the ib_logfile* right after the 10.5 startup was refused. A start-up attempt with an older server may ‘ruin’ the evidence that we would need to fix this bug!

If you are absolutely sure that the 10.4 or older server was shut down properly, you can delete the files and start up the 10.5 server. If you just blindly do it, you may end up losing all your InnoDB tables, as reported in MDEV-25414.

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?

@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.

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.