MySQL Bugs: #109301: MySQL 5.7 -> 8.0.31 Page old data size XXX new data size YYY error

Bug #109301	MySQL 5.7 -> 8.0.31 Page old data size XXX new data size YYY error
Submitted:	6 Dec 2022 23:05	Modified:	8 Dec 2022 4:36
Reporter:	Michael Kotlyar	Email Updates:
Status:	Can't repeat	Impact on me:	None
Category:	MySQL Server	Severity:	S2 (Serious)
Version:	8.0.31	OS:	Fedora
Assigned to:		CPU Architecture:	Any

Description:
The error in the docker container is as follows:

```
2022-12-06 15:32:42+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 8.0.31-1.el8 started.
2022-12-06 15:32:43+00:00 [Note] [Entrypoint]: Switching to dedicated user 'mysql'
2022-12-06 15:32:43+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 8.0.31-1.el8 started.
'/var/lib/mysql/mysql.sock' -> '/var/run/mysqld/mysqld.sock'
2022-12-06T15:32:44.188677Z 0 [Warning] [MY-011068] [Server] The syntax '--skip-host-cache' is deprecated and will be removed in a future release. Please use SET GLOBAL host_cache_size=0 instead.
2022-12-06T15:32:44.188712Z 0 [Warning] [MY-011068] [Server] The syntax '--ssl=off' is deprecated and will be removed in a future release. Please use --tls-version='' instead.
2022-12-06T15:32:44.191422Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.0.31) starting as process 1
2022-12-06T15:32:44.205377Z 0 [Warning] [MY-013907] [InnoDB] Deprecated configuration parameters innodb_log_file_size and/or innodb_log_files_in_group have been used to compute innodb_redo_log_capacity=536870912. Please use innodb_redo_log_capacity instead.
2022-12-06T15:32:44.212479Z 1 [System] [MY-011012] [Server] Starting upgrade of data directory.
2022-12-06T15:32:44.212935Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2022-12-06T15:32:46.312616Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
2022-12-06T15:33:56.311947Z 2 [System] [MY-011003] [Server] Finished populating Data Dictionary tables with data.
2022-12-06T15:34:06.992442Z 5 [System] [MY-013381] [Server] Server upgrade from '50700' to '80031' started.
2022-12-06T15:34:40.125835Z 5 [System] [MY-013381] [Server] Server upgrade from '50700' to '80031' completed.
2022-12-06T15:34:40.352882Z 0 [Warning] [MY-011810] [Server] Insecure configuration for --pid-file: Location '/var/run/mysqld' in the path is accessible to all OS users. Consider choosing a different directory.
2022-12-06T15:34:40.402358Z 0 [Warning] [MY-011302] [Server] Plugin mysqlx reported: 'Failed at SSL configuration: "SSL context is not usable without certificate and private key"'
2022-12-06T15:34:40.402545Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Bind-address: '::' port: 33060, socket: /var/run/mysqld/mysqlx.sock
2022-12-06T15:34:40.402715Z 0 [System] [MY-010931] [Server] /usr/sbin/mysqld: ready for connections. Version: '8.0.31'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  MySQL Community Server - GPL.
2022-12-06T15:36:42.303026Z 219 [ERROR] [MY-011855] [InnoDB] Page old data size 7549 new data size 8141, page old max ins size 8629 new max ins size 8037
2022-12-06T15:36:42.306087Z 219 [ERROR] [MY-011856] [InnoDB] Submit a detailed bug report to http://bugs.mysql.com
2022-12-06T15:36:42.306114Z 219 [ERROR] [MY-013183] [InnoDB] Assertion failure: btr0cur.cc:4024:page_zip || optim_err != DB_UNDERFLOW thread 140423759312640
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/8.0/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
2022-12-06T15:36:42Z UTC - mysqld got signal 6 ;
Most likely, you have hit a bug, but this error can also be caused by malfunctioning hardware.
BuildID[sha1]=3500d72a2d80e886c3a43a71eac12ad351dd2329
Thread pointer: 0x7fb67c0f4ad0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 7fb6f44aac50 thread_stack 0x100000
/usr/sbin/mysqld(my_print_stacktrace(unsigned char const*, unsigned long)+0x41) [0x2128961]
/usr/sbin/mysqld(print_fatal_signal(int)+0x387) [0xfd60b7]
/usr/sbin/mysqld(my_server_abort()+0x7e) [0xfd620e]
/usr/sbin/mysqld(my_abort()+0xe) [0x212287e]
/usr/sbin/mysqld(ut_dbg_assertion_failed(char const*, char const*, unsigned long)+0x33a) [0x242255a]
/usr/sbin/mysqld(btr_cur_pessimistic_update(unsigned long, btr_cur_t*, unsigned long**, mem_block_info_t**, mem_block_info_t*, big_rec_t**, upd_t*, unsigned long, que_thr_t*, unsigned long, unsigned long, mtr_t*, btr_pcur_t*)+0xf0e) [0x246692e]
/usr/sbin/mysqld() [0x23a5369]
/usr/sbin/mysqld() [0x23a5fed]
/usr/sbin/mysqld(row_upd_step(que_thr_t*)+0xb28) [0x23aafe8]
/usr/sbin/mysqld() [0x2372a41]
/usr/sbin/mysqld(ha_innobase::update_row(unsigned char const*, unsigned char*)+0x360) [0x2239700]
/usr/sbin/mysqld(handler::ha_update_row(unsigned char const*, unsigned char*)+0x20b) [0x10ebb6b]
/usr/sbin/mysqld(UpdateRowsIterator::DoDelayedUpdates(bool*, bool*)+0x7d5) [0xf448f5]
/usr/sbin/mysqld(UpdateRowsIterator::Read()+0x1ad) [0xf44b0d]
/usr/sbin/mysqld(Query_expression::ExecuteIteratorQuery(THD*)+0x29b) [0xf3f2ab]
/usr/sbin/mysqld(Query_expression::execute(THD*)+0x30) [0xf3f620]
/usr/sbin/mysqld(Sql_cmd_dml::execute(THD*)+0x189) [0xecb9a9]
/usr/sbin/mysqld(mysql_execute_command(THD*, bool)+0xb32) [0xe68ce2]
/usr/sbin/mysqld(dispatch_sql_command(THD*, Parser_state*)+0x41a) [0xe6c66a]
/usr/sbin/mysqld(dispatch_command(THD*, COM_DATA const*, enum_server_command)+0xd4c) [0xe6d91c]
/usr/sbin/mysqld(do_command(THD*)+0x207) [0xe6fbf7]
/usr/sbin/mysqld() [0xfc6060]
/usr/sbin/mysqld() [0x28eb2f9]
/lib64/libpthread.so.0(+0x81df) [0x7fb766c8e1df]
/lib64/libc.so.6(clone+0x43) [0x7fb76523edd3]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7fb67c594250): UPDATE redcated dbname INNER JOIN redcated tmp ON tmp.id = dbname.id SET dbname.event_id = tmp.new_event_id
Connection ID (thread ID): 219
Status: NOT_KILLED
```

Here is the conf file being used:

```
[client]
port = 3306
default-character-set = utf8mb4
loose-local-infile = 1

[mysqld]
local_infile = ON
default_time_zone = +00:00
character-set-server = utf8mb4
collation-server = utf8mb4_unicode_ci
character-set-client-handshake = false
transaction-isolation = READ-COMMITTED

# User is ignored when systemd is used (fedora >= 15).
user = mysql

# disable ssl
ssl = 0

# disable reverse DNS lookups per connection
# https://dev.mysql.com/doc/refman/8.0/en/server-system-variables.html#sysvar_skip_name_reso...
skip_name_resolve

# Memory settings.
max_allowed_packet = 64M
table_open_cache = 256
sort_buffer_size = 1M
thread_cache_size = 8
tmp_table_size = 1M

# Other settings.
wait_timeout = 28800
max_connections = 300

# InnoDB settings.
innodb_file_per_table = 1
innodb_buffer_pool_size = 1G
innodb_log_file_size = 256M
innodb_flush_log_at_trx_commit = 0
innodb_lock_wait_timeout = 50
innodb_autoinc_lock_mode = 2

server-id         = 12345
#log_bin           = mysql-bin
#binlog_format     = row
#expire_logs_days  = 10
log_bin_trust_function_creators = 1

[mysqldump]
quick
max_allowed_packet = 64M

[mysqld_safe]
pid-file = /var/run/mysqld/mysqld.pid
```

How to repeat:
Repetition steps: Perform inplace upgrade of MySQL 5.7 -> 8.0.31, start MySQL 8.0.31 docker container. Everything worked just fine with 5.7 pre update

Hi Mr. Kotiyar,

Thank you for your bug report.

We have all upgraded from 5.7 to the latest 8.0 many, many times and have encountered no problems or only warnings, such as you have got.

That page size that is reported means that your files have undergone some heavy corruption. Best solution for you is to start 8.0 on the new datadir and backup from your last mysqldump.

Hi,

Actually, there is a workaround. Please, read the error messages carefully.

You can start 8.0 with a default InnoDB page size of 16384.

Still, the values that are displayed point to some heavy corruption.

The innodb_page_size is already set to 16348 when checking:

mysql> show variables like 'innodb_page_size';
+------------------+-------+
| Variable_name    | Value |
+------------------+-------+
| innodb_page_size | 16384 |
+------------------+-------+
1 row in set (0.00 sec)

Is there anything specific that could be causing such a corruption of data to occur? The mysqldump is taken from a 5.7 database and included in the data directory for upgrade, and works fine while using a mysql 5.7 docker container.

When using 8.0.31, these errors begin to surface.

the fatal error occurs during reorganizing an index page: the sum of the sizes of the records  is inconsistent in the old page and new page before and after reorganization

I would like to include one additional piece of information: The mysql database successfully upgrades the database from 5.7 -> 8.0.31 on initial startup.

The part of the workflow it begins to fail is a few minutes later when we begin to run MySQL migrations with Flyway on the mysql database (see the timestamp difference in the original error message, it is a few minutes between mysql successfully finishing the upgrade up to the point where crashes begin to occur).

For clarification: we are running MySQL via Docker locally and start out with a clean slate. The mysqldump from 5.7 is mounted as a volume and successfully upgraded when the 8.0.31 image launches. 

A few minutes later as you can see in the timestamp is when the crashing begins - which is subsequently about the time the migrations begin to run in the Flyway migration process. 

Is it possible that certain queries can corrupt the data, or is it reasonable to assume the data is already corrupted before migrations begin executing?

And typically here is the kind of log we see on the migration side:

```
Database: jdbc:mysql://mysql:3306 (MySQL 8.0) 
Successfully validated 73 migrations (execution time 00:03.714s) 
Current version of schema `...`: 20220707103000 
outOfOrder mode is active. Migration of schema `...` may not be reproducible. 
Migrating schema `...` to version 20221020140100 - ... 
DB: Unknown table 'dbname.tblname1' (SQL State: 42S02 - Error Code: 1051) 
DB: Unknown table 'dbname.tblname2' (SQL State: 42S02 - Error Code: 1051) 
Migrating schema `...` to version 20221121134100 - ... 
Migrating schema `...` to version 20221124164100 - ... 
DB: Unknown table 'dbname.tblname3' (SQL State: 42S02 - Error Code: 1051) 
Unable to rollback transaction 
```

At this point the mysql server crashes:

```
2022-12-08T00:17:10.295890Z 0 [System] [MY-010931] [Server] /usr/sbin/mysqld: ready for connections. Version: '8.0.31'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  MySQL Community Server - GPL.
2022-12-08T00:20:14Z UTC - mysqld got signal 11 ;
Most likely, you have hit a bug, but this error can also be caused by malfunctioning hardware.
BuildID[sha1]=3500d72a2d80e886c3a43a71eac12ad351dd2329
Thread pointer: 0x7fd2240edec0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 7fd28c3a8c50 thread_stack 0x100000
/usr/sbin/mysqld(my_print_stacktrace(unsigned char const*, unsigned long)+0x41) [0x2128961]
/usr/sbin/mysqld(print_fatal_signal(int)+0x387) [0xfd60b7]
/usr/sbin/mysqld(handle_fatal_signal+0xa5) [0xfd6175]
/lib64/libpthread.so.0(+0x12cf0) [0x7fd2fda7dcf0]
/usr/sbin/mysqld() [0x23939c7]
/usr/sbin/mysqld(row_sel_store_mysql_rec(unsigned char*, row_prebuilt_t*, unsigned char const*, dtuple_t const*, bool, dict_index_t const*, dict_index_t const*, unsigned long const*, bool, lob::undo_vers_t*, mem_block_info_t*&)+0x2e8) [0x2397038]
/usr/sbin/mysqld(row_search_mvcc(unsigned char*, page_cur_mode_t, row_prebuilt_t*, unsigned long, unsigned long)+0x2426) [0x239d796]
/usr/sbin/mysqld(ha_innobase::index_read(unsigned char*, unsigned char const*, unsigned int, ha_rkey_function)+0x3e6) [0x2230466]
/usr/sbin/mysqld(handler::ha_index_read_map(unsigned char*, unsigned char const*, unsigned long, ha_rkey_function)+0x3a1) [0x10ec391]
/usr/sbin/mysqld(EQRefIterator::Read()+0x10b) [0x13b9f0b]
/usr/sbin/mysqld(NestedLoopIterator::Read()+0x31) [0x13aba01]
/usr/sbin/mysqld(UpdateRowsIterator::Read()+0x4a) [0xf449aa]
/usr/sbin/mysqld(Query_expression::ExecuteIteratorQuery(THD*)+0x29b) [0xf3f2ab]
/usr/sbin/mysqld(Query_expression::execute(THD*)+0x30) [0xf3f620]
/usr/sbin/mysqld(Sql_cmd_dml::execute(THD*)+0x189) [0xecb9a9]
/usr/sbin/mysqld(mysql_execute_command(THD*, bool)+0xb32) [0xe68ce2]
/usr/sbin/mysqld(dispatch_sql_command(THD*, Parser_state*)+0x41a) [0xe6c66a]
/usr/sbin/mysqld(dispatch_command(THD*, COM_DATA const*, enum_server_command)+0xd4c) [0xe6d91c]
/usr/sbin/mysqld(do_command(THD*)+0x207) [0xe6fbf7]
/usr/sbin/mysqld() [0xfc6060]
/usr/sbin/mysqld() [0x28eb2f9]
/lib64/libpthread.so.0(+0x81df) [0x7fd2fda731df]
/lib64/libc.so.6(clone+0x43) [0x7fd2fc023dd3]
```

With this particular crash, the container was able to restart back up again  using "XA Crash Recovery"

```
2022-12-08 00:20:17+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 8.0.31-1.el8 started.
2022-12-08 00:20:19+00:00 [Note] [Entrypoint]: Switching to dedicated user 'mysql'
2022-12-08 00:20:19+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 8.0.31-1.el8 started.
'/var/lib/mysql/mysql.sock' -> '/var/run/mysqld/mysqld.sock'
2022-12-08T00:20:23.212995Z 0 [Warning] [MY-011068] [Server] The syntax '--skip-host-cache' is deprecated and will be removed in a future release. Please use SET GLOBAL host_cache_size=0 instead.
2022-12-08T00:20:23.213043Z 0 [Warning] [MY-011068] [Server] The syntax '--ssl=off' is deprecated and will be removed in a future release. Please use --tls-version='' instead.
2022-12-08T00:20:23.241810Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.0.31) starting as process 1
2022-12-08T00:20:23.264821Z 0 [Warning] [MY-013907] [InnoDB] Deprecated configuration parameters innodb_log_file_size and/or innodb_log_files_in_group have been used to compute innodb_redo_log_capacity=536870912. Please use innodb_redo_log_capacity instead.
2022-12-08T00:20:23.274025Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2022-12-08T00:20:27.986120Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
2022-12-08T00:20:31.907529Z 0 [System] [MY-010229] [Server] Starting XA crash recovery...
2022-12-08T00:20:31.952515Z 0 [System] [MY-010232] [Server] XA crash recovery finished.
2022-12-08T00:20:32.415566Z 0 [Warning] [MY-011810] [Server] Insecure configuration for --pid-file: Location '/var/run/mysqld' in the path is accessible to all OS users. Consider choosing a different directory.
2022-12-08T00:20:32.952244Z 0 [Warning] [MY-011302] [Server] Plugin mysqlx reported: 'Failed at SSL configuration: "SSL context is not usable without certificate and private key"'
2022-12-08T00:20:32.952698Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Bind-address: '::' port: 33060, socket: /var/run/mysqld/mysqlx.sock
2022-12-08T00:20:32.953081Z 0 [System] [MY-010931] [Server] /usr/sbin/mysqld: ready for connections. Version: '8.0.31'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  MySQL Community Server - GPL.
```

And as one more additional note, most of these migrations which appear to be initially crashing all have the usage of "TEMPORARY TABLE" in the queries.