MySQL Bugs: #93156: can not upgrade from MySQL 8.0.11 to 8.0.13

Bug #93156	can not upgrade from MySQL 8.0.11 to 8.0.13
Submitted:	11 Nov 2018 13:45	Modified:	30 Nov 2018 15:11
Reporter:	Ye Jinrong	Email Updates:
Status:	Duplicate	Impact on me:	None
Category:	MySQL Server: Data Dictionary	Severity:	S3 (Non-critical)
Version:	8.0.13	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
start mysql 8.0.13  with the old datadir, and the datadir was ran under mysql 8.0.11.
when i start up with 8.0.13, it raised error when "Execution of server-side SQL statement".
all of the errors message in log:

2018-11-10T15:37:42.345336Z 0 [Warning] [MY-010140] [Server] Could not increase number of max_open_files to more than 7168 (request: 65535)
2018-11-10T15:37:42.611063Z 0 [Note] [MY-010949] [Server] Basedir set to /Volumes/DATA/apps/mysql-8.0.11-macos10.13-x86_64/.
2018-11-10T15:37:42.611095Z 0 [System] [MY-010116] [Server] /Volumes/DATA/apps/mysql-8.0.13-macos10.14-x86_64/bin/mysqld (mysqld 8.0.13) starting as process 72998
2018-11-10T15:37:42.612171Z 0 [ERROR] [MY-010340] [Server] Error message file '/Volumes/DATA/apps/mysql-8.0.11-macos10.13-x86_64/share/english/errmsg.sys' had only 4512 error messages, but it should contain at least 4640 error messages. Check that the above file is the right version for this program!
2018-11-10T15:37:42.614583Z 0 [Warning] [MY-010159] [Server] Setting lower_case_table_names=2 because file system for /Volumes/DATA/mysql/mysql8/ is case insensitive
2018-11-10T15:37:42.616174Z 0 [Warning] [MY-010122] [Server] One can only use the --user switch if running as root
2018-11-10T15:37:42.620211Z 0 [Warning] [MY-012364] [InnoDB] innodb_open_files should not be greater than the open_files_limit.

2018-11-10T15:37:42.620434Z 0 [Note] [MY-010747] [Server] Plugin 'FEDERATED' is disabled.
2018-11-10T15:37:42.622360Z 1 [Note] [MY-012943] [InnoDB] Mutexes and rw_locks use GCC atomic builtins
2018-11-10T15:37:42.622387Z 1 [Note] [MY-012944] [InnoDB] Uses event mutexes
2018-11-10T15:37:42.622397Z 1 [Note] [MY-012945] [InnoDB] GCC builtin __atomic_thread_fence() is used for memory barrier
2018-11-10T15:37:42.622408Z 1 [Note] [MY-012948] [InnoDB] Compressed tables use zlib 1.2.11
2018-11-10T15:37:42.622826Z 1 [Note] [MY-011825] [InnoDB] Number of pools: 1
2018-11-10T15:37:42.622937Z 1 [Note] [MY-012951] [InnoDB] Using CPU crc32 instructions
2018-11-10T15:37:42.623391Z 1 [Note] [MY-012203] [InnoDB] Directories to scan '/Volumes/DATA/mysql/mysql8/ibd;./;undolog;./'
2018-11-10T15:37:42.623535Z 1 [Note] [MY-012204] [InnoDB] Scanning './'
2018-11-10T15:37:42.804495Z 1 [Note] [MY-012208] [InnoDB] Completed space ID check of 248 files.
2018-11-10T15:37:42.805283Z 1 [Note] [MY-012955] [InnoDB] Initializing buffer pool, total size = 128.000000M, instances = 1, chunk size =128.000000M
2018-11-10T15:37:42.813505Z 1 [Note] [MY-012957] [InnoDB] Completed initialization of buffer pool
2018-11-10T15:37:42.867827Z 1 [Note] [MY-013086] [InnoDB] Starting to parse redo log at lsn = 2422046252, whereas checkpoint_lsn = 2422046587
2018-11-10T15:37:42.868659Z 1 [Note] [MY-013083] [InnoDB] Log background threads are being started...
2018-11-10T15:37:42.868846Z 1 [Note] [MY-012532] [InnoDB] Applying a batch of 0 redo log records ...
2018-11-10T15:37:42.868869Z 1 [Note] [MY-012535] [InnoDB] Apply batch completed!
2018-11-10T15:37:42.922063Z 1 [Note] [MY-013040] [InnoDB] Expected to open 10 undo tablespaces but found 127.
2018-11-10T15:37:42.922094Z 1 [Note] [MY-012910] [InnoDB] Opened 127 existing undo tablespaces.
2018-11-10T15:37:43.847910Z 1 [Note] [MY-012923] [InnoDB] Creating shared tablespace for temporary tables
2018-11-10T15:37:43.847943Z 1 [Note] [MY-012275] [InnoDB] Need to create a new innodb_temporary data file 'ibtmp2'.
2018-11-10T15:37:43.848102Z 1 [Note] [MY-012265] [InnoDB] Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2018-11-10T15:37:43.866199Z 1 [Note] [MY-012266] [InnoDB] File './ibtmp1' size is now 12 MB.
2018-11-10T15:37:43.866386Z 1 [Note] [MY-012265] [InnoDB] Setting file './ibtmp2' size to 12 MB. Physically writing the file full; Please wait ...
2018-11-10T15:37:43.893044Z 1 [Note] [MY-012266] [InnoDB] File './ibtmp2' size is now 12 MB.
2018-11-10T15:37:43.893371Z 1 [Note] [MY-011825] [InnoDB] Scanning temp tablespace dir:'./#innodb_temp/'
2018-11-10T15:37:43.933145Z 1 [Note] [MY-013018] [InnoDB] Created 128 and tracked 128 new rollback segment(s) in the temporary tablespace. 128 are now active.
2018-11-10T15:37:43.933698Z 1 [Note] [MY-012976] [InnoDB] 8.0.13 started; log sequence number 2422046587
2018-11-10T15:37:43.943188Z 1 [Note] [MY-011090] [Server] Data dictionary upgrading from version '80011' to '80013'.
2018-11-10T15:37:44.038625Z 1 [Note] [MY-012357] [InnoDB] Reading DD tablespace files
2018-11-10T15:37:44.054222Z 1 [Note] [MY-012356] [InnoDB] Validated 133/133  tablespaces
2018-11-10T15:37:44.054565Z 0 [Note] [MY-011946] [InnoDB] Loading buffer pool(s) from /Volumes/DATA/mysql/mysql8/ib_buffer_pool
2018-11-10T15:37:44.062240Z 0 [Note] [MY-011946] [InnoDB] Buffer pool(s) load completed at 181110 23:37:44
2018-11-10T15:37:44.611058Z 1 [ERROR] [MY-013178] [Server] Execution of server-side SQL statement 'INSERT INTO tables SELECT *, 0 FROM mysql.tables' failed with error code = 1292, error message = 'Incorrect datetime value: '0000-00-00 00:00:00' for column 'created' at row 355'.
2018-11-10T15:37:44.623601Z 0 [ERROR] [MY-010020] [Server] Data Dictionary initialization failed.
2018-11-10T15:37:44.623634Z 0 [ERROR] [MY-010119] [Server] Aborting
2018-11-10T15:37:44.623684Z 0 [Note] [MY-012330] [InnoDB] FTS optimize thread exiting.
2018-11-10T15:37:44.624833Z 0 [Note] [MY-010120] [Server] Binlog end
2018-11-10T15:37:44.625450Z 0 [Note] [MY-010733] [Server] Shutting down plugin 'MyISAM'
2018-11-10T15:37:44.625488Z 0 [Note] [MY-010733] [Server] Shutting down plugin 'InnoDB'
2018-11-10T15:37:44.627202Z 0 [Note] [MY-013072] [InnoDB] Starting shutdown...
2018-11-10T15:37:44.728555Z 0 [Note] [MY-011944] [InnoDB] Dumping buffer pool(s) to /Volumes/DATA/mysql/mysql8/ib_buffer_pool
2018-11-10T15:37:44.730047Z 0 [Note] [MY-011944] [InnoDB] Buffer pool(s) dump completed at 181110 23:37:44
2018-11-10T15:37:45.246043Z 0 [Note] [MY-013084] [InnoDB] Log background threads are being closed...
2018-11-10T15:37:45.670717Z 0 [Note] [MY-012980] [InnoDB] Shutdown completed; log sequence number 2424133904
2018-11-10T15:37:45.671482Z 0 [Note] [MY-012255] [InnoDB] Removed temporary tablespace data file: "ibtmp1"
2018-11-10T15:37:45.672183Z 0 [Note] [MY-012255] [InnoDB] Removed temporary tablespace data file: "ibtmp2"
2018-11-10T15:37:45.672201Z 0 [Note] [MY-010733] [Server] Shutting down plugin 'CSV'
2018-11-10T15:37:45.673617Z 0 [System] [MY-010910] [Server] /Volumes/DATA/apps/mysql-8.0.13-macos10.14-x86_64/bin/mysqld: Shutdown complete (mysqld 8.0.13)  MySQL Community Server - GPL.

How to repeat:
start mysql 8.0.13 with the datadir wich ran under 8.0.11 previous

I could not reproduce this problem. Here's my attempt:

$ dbdeployer deploy single 8.0.11
Database installed in $HOME/sandboxes/msb_8_0_11
run 'dbdeployer usage single' for basic instructions'
. sandbox server started

$ dbdeployer deploy single 8.0.13
Database installed in $HOME/sandboxes/msb_8_0_13
run 'dbdeployer usage single' for basic instructions'
. sandbox server started

$ dbdeployer admin upgrade msb_8_0_11 msb_8_0_13
stop /Users/gmax/sandboxes/msb_8_0_11
stop /Users/gmax/sandboxes/msb_8_0_13
Data directory msb_8_0_11/data moved to msb_8_0_13/data
.. sandbox server started
Checking if update is needed.
Checking server version.
Running queries to upgrade MySQL server.
Upgrading system table data.
Checking system database.
mysql.columns_priv                                 OK
mysql.component                                    OK
mysql.db                                           OK
mysql.default_roles                                OK
mysql.engine_cost                                  OK
mysql.func                                         OK
mysql.general_log                                  OK
mysql.global_grants                                OK
mysql.gtid_executed                                OK
mysql.help_category                                OK
mysql.help_keyword                                 OK
mysql.help_relation                                OK
mysql.help_topic                                   OK
mysql.innodb_index_stats                           OK
mysql.innodb_table_stats                           OK
mysql.password_history                             OK
mysql.plugin                                       OK
mysql.procs_priv                                   OK
mysql.proxies_priv                                 OK
mysql.role_edges                                   OK
mysql.server_cost                                  OK
mysql.servers                                      OK
mysql.slave_master_info                            OK
mysql.slave_relay_log_info                         OK
mysql.slave_worker_info                            OK
mysql.slow_log                                     OK
mysql.tables_priv                                  OK
mysql.time_zone                                    OK
mysql.time_zone_leap_second                        OK
mysql.time_zone_name                               OK
mysql.time_zone_transition                         OK
mysql.time_zone_transition_type                    OK
mysql.user                                         OK
The sys schema is already up to date (version 2.0.0).
Checking databases.
sys.sys_config                                     OK
Upgrade process completed successfully.
Checking if update is needed.

The data directory from msb_8_0_13/data is preserved in msb_8_0_13/data-msb_8_0_13
The data directory from msb_8_0_11/data is now used in msb_8_0_13/data
msb_8_0_11 is not operational and can be deleted

The error log (migrated from the previous version, as the whole data directory was used by 8.0.13) does not say anything bad after the upgrade.

Hello Ye Jinrong,

Thank you for the report.
This is duplicate of Bug #93147, please see Bug #93147.

regards,
Umesh

Hello Ye Jinrong,

I wanted to add a few notes to the comments for this bug, and request your feedback. Based on the odd messages in the mysqld log file, I think that there was a mismatch in the binaries used to start mysqld and the setting for basedir. From this output, it looks as if either the mysqld command or the cnf file had the following setting:

    basedir=/Volumes/DATA/apps/mysql-8.0.11-macos10.13-x86_64

But, the binary used to start the server was:

    /Volumes/DATA/apps/mysql-8.0.13-macos10.14-x86_64/bin/mysqld 

This is noted in the messages in the mysqld log that you included in the bug report:

    2018-11-10T15:37:42.611063Z 0 [Note] [MY-010949] [Server] Basedir set to /Volumes/DATA/apps/mysql-8.0.11-macos10.13-x86_64/.
    2018-11-10T15:37:42.611095Z 0 [System] [MY-010116] [Server] /Volumes/DATA/apps/mysql-8.0.13-macos10.14-x86_64/bin/mysqld (mysqld 8.0.13) starting as process 72998
    2018-11-10T15:37:42.612171Z 0 [ERROR] [MY-010340] [Server] Error message file '/Volumes/DATA/apps/mysql-8.0.11-macos10.13-x86_64/share/english/errmsg.sys' had only 4512 error messages, but it should contain at least 4640 error messages. Check that the above file is the right version for this program!
    [...]
    2018-11-10T15:37:43.933698Z 1 [Note] [MY-012976] [InnoDB] 8.0.13 started; log sequence number 2422046587
    2018-11-10T15:37:43.943188Z 1 [Note] [MY-011090] [Server] Data dictionary upgrading from version '80011' to '80013'.
    2018-11-10T15:37:44.038625Z 1 [Note] [MY-012357] [InnoDB] Reading DD tablespace files
    [...]

This type of mismatch can causes some really odd behavior and very odd messages in the mysqld log.

There is a valid issue related to the error error message that was noted in the bug report:

    2018-11-10T15:37:44.611058Z 1 [ERROR] [MY-013178] [Server] Execution of server-side SQL statement 'INSERT INTO tables SELECT *, 0 FROM mysql.tables' failed with error code = 1292, error message = 'Incorrect datetime value: '0000-00-00 00:00:00' for column 'created' at row 355'.

This issue is covered in the bug:

    https://bugs.mysql.com/bug.php?id=93147 -> Upgrade to 8.0.13 from 8.0.11 fails

Please confirm that my suspicion is either the situation, or somewhat close to what occurred. I want to be sure that you have an explanation for the very odd messages that is not as a result of bug 93147. Once confirmed, the status of this bug will be returned to duplicate of 93147.

Thank you -

Susan

Hi Susan Koerner,
Sorry about the mismatch message.
The reason is that, i start mysqld(MySQL 8.0.13) by a shell script like this:

#!/bin/bash
. ~/.bash_profile
cd /Volumes/DATA/apps/mysql-8.0.13-macos10.14-x86_64
./bin/mysqld --defaults-file=/Volumes/DATA/mysql/mysql8013/my.cnf &

but i forgot to change basedir options on my.cnf, it's old value is:
basedir = /Volumes/DATA/apps/mysql-8.0.11-macos10.13-x86_64

i will re-install 8.0.11 and try upgrade to 8.0.13 once more.
thanks much.

Hi Susan Koerner,

I am sure can not upgrade from 8.0.11 to 8.0.13, and raise the same error messages:

2018-11-30T05:26:22.395725Z 0 [System] [MY-010116] [Server] /Volumes/DATA/apps/mysql-8.0.13-macos10.14-x86_64/bin/mysqld (mysqld 8.0.13) starting as process 38563
2018-11-30T05:26:22.399766Z 0 [Warning] [MY-010159] [Server] Setting lower_case_table_names=2 because file system for /Volumes/DATA/mysql/mysql8011/ is case insensitive
2018-11-30T05:26:23.291750Z 1 [ERROR] [MY-013178] [Server] Execution of server-side SQL statement 'INSERT INTO tables SELECT *, 0 FROM mysql.tables' failed with error code = 1292, error message = 'Incorrect datetime value: '0000-00-00 00:00:00' for column 'created' at row 356'.
2018-11-30T05:26:23.305457Z 0 [ERROR] [MY-010020] [Server] Data Dictionary initialization failed.
2018-11-30T05:26:23.305493Z 0 [ERROR] [MY-010119] [Server] Aborting
2018-11-30T05:26:24.254540Z 0 [System] [MY-010910] [Server] /Volumes/DATA/apps/mysql-8.0.13-macos10.14-x86_64/bin/mysqld: Shutdown complete (mysqld 8.0.13)  MySQL Community Server - GPL.

1. initial mysql 8.0.11
$ ./bin/mysqld --no-defaults --datadir=/Volumes/DATA/mysql/mysql8011 --initialize-insecure

2. start mysql 8.0.11 and check it's version
$ pwd
/Volumes/DATA/apps/mysql-8.0.11-macos10.13-x86_64

$ ./bin/mysqld --no-defaults --datadir=/Volumes/DATA/mysql/mysql8011 --port=3308 --socket=mysql.sock --log-error=error.txt --mysqlx-port=33080 --mysqlx-socket=mysqlx.sock

$ mysqladmin -Smysql.sock ver
mysqladmin  Ver 8.0.13 for macos10.14 on x86_64 (MySQL Community Server - GPL)
...
Server version		8.0.11

3. import dumpfile
$ mysql -Smysql.sock -f < ../yejr.sql

4. shutdown mysql 8.0.11
$ mysqladmin -Smysql.sock shut

5. start mysql 8.0.13 with same datadir
$ pwd
/Volumes/DATA/apps/mysql-8.0.13-macos10.14-x86_64

$ ./bin/mysqld --no-defaults --datadir=/Volumes/DATA/mysql/mysql8011 --port=3308 --socket=mysql.sock --log-error=error.txt --mysqlx-port=33080 --mysqlx-socket=mysqlx.sock

raise error, startup fail.

Hello Ye Jinrong -

I completely understand and agree that the following error causes you to not be able to upgrade:

 2018-11-30T05:26:23.291750Z 1 [ERROR] [MY-013178] [Server] Execution 
 of server-side SQL statement 'INSERT INTO tables SELECT *, 0 FROM 
 mysql.tables' failed with error code = 1292, error message = 'Incorrect 
 datetime value: '0000-00-00 00:00:00' for column 'created' at row 356'.

This error has already been raised and is being tracked in the following bug:

 https://bugs.mysql.com/bug.php?id=93147 -> Upgrade to 8.0.13 from 8.0.11 fails

As a workaround, you can upgrade from 8.0.11 -> 8.0.12 -> 8.0.13.  This is only a problem between 8.0.11 -> 8.0.13.

In my comments to you, I was hoping to help to explain why you received all the other error messages that were in the log. Thanks so much for confirming that there was a mismatch between the mysqld binary and the basedir specified in your original report.

I will close this bug as a duplicate of bug#93147.

Have a great day -

Susan