Re: MySQL server silently fails to start after upgrading from 5.7.40 to 8.0.32

From: Mike Clarke <jmc-freebsd2_at_milibyte.co.uk>
Date: Sun, 16 Apr 2023 09:12:44 UTC
On Saturday, 15 April 2023 17:29:10 BST Andrea Venturoli wrote:
> On 4/15/23 18:25, Mike Clarke wrote:
> > After upgrading packages to the the new quarterly release mysql was
> > upgraded to 8.0.32 and it fails to start and does not produce any
> > failure message on the console and I couldn't find any relevant failure
> > message anywhere in /var/logs.
> 
> What's in /var/db/mysql/{hostname}.err?
> 
>   bye
> 	av.

Here's the results for mysql8

########################################################

2023-04-16T08:47:33.6NZ mysqld_safe Logging to '/var/db/mysql/curlew.err'.
2023-04-16T08:47:33.6NZ mysqld_safe Starting mysqld daemon with databases from /var/
db/mysql
2023-04-16T08:47:33.068413Z 0 [Warning] [MY-010140] [Server] Could not increase 
number of max_open_files to more than 22500 (request: 32929)
2023-04-16T08:47:33.068419Z 0 [Warning] [MY-010142] [Server] Changed limits: 
table_open_cache: 11169 (requested 16384)
2023-04-16T08:47:33.256168Z 0 [Warning] [MY-010915] [Server] 'NO_ZERO_DATE', 
'NO_ZERO_IN_DATE' and 'ERROR_FOR_DIVISION_BY_ZERO' sql modes should be used with 
strict mode. They will be merged with strict mode in a future release.
2023-04-16T08:47:33.257337Z 0 [System] [MY-010116] [Server] /usr/local/libexec/mysqld 
(mysqld 8.0.32) starting as process 6221
2023-04-16T08:47:33.284373Z 1 [System] [MY-011012] [Server] Starting upgrade of data 
directory.
2023-04-16T08:47:33.284397Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has 
started.
2023-04-16T08:47:33.375843Z 1 [ERROR] [MY-012263] [InnoDB] The Auto-extending 
innodb_system data file '/var/db/mysql/ibdata1' is of a different size 5248 pages (rounded 
down to MB) than specified in the .cnf file: initial 8192 pages, max 0 (relevant if non-zero) 
pages!
2023-04-16T08:47:33.375885Z 1 [ERROR] [MY-012960] [InnoDB] Cannot create redo log 
files because data files are corrupt or the database was not shut down cleanly after 
creating the data files.
2023-04-16T08:47:33.376512Z 1 [ERROR] [MY-011013] [Server] Failed to initialize DD 
Storage Engine.
2023-04-16T08:47:33.376689Z 0 [ERROR] [MY-010020] [Server] Data Dictionary initialization 
failed.
2023-04-16T08:47:33.376712Z 0 [ERROR] [MY-010119] [Server] Aborting
2023-04-16T08:47:33.378196Z 0 [System] [MY-010910] [Server] /usr/local/libexec/mysqld: 
Shutdown complete (mysqld 8.0.32)  Source distribution.
2023-04-16T08:47:33.6NZ mysqld_safe mysqld from pid file /var/db/mysql/curlew.pid 
ended

########################################################

And for comparison a successful run with mysql5
Both attempts were using the same /var/db/mysql directory, just running from different 
BEs

########################################################

2023-04-16T08:55:27.6NZ mysqld_safe Logging to '/var/db/mysql/curlew.err'.
2023-04-16T08:55:27.6NZ mysqld_safe Starting mysqld daemon with databases from /var/
db/mysql
2023-04-16T08:55:27.086768Z 0 [Warning] Could not increase number of max_open_files 
to more than 22500 (request: 32929)
2023-04-16T08:55:27.086994Z 0 [Warning] Changed limits: table_open_cache: 11169 
(requested 16384)
2023-04-16T08:55:27.230557Z 0 [Warning] 'NO_ZERO_DATE', 'NO_ZERO_IN_DATE' and 
'ERROR_FOR_DIVISION_BY_ZERO' sql modes should be used with strict mode. They will be 
merged with strict mode in a future release.
2023-04-16T08:55:27.230570Z 0 [Warning] 'NO_AUTO_CREATE_USER' sql mode was not set.
2023-04-16T08:55:27.232719Z 0 [Note] /usr/local/libexec/mysqld (mysqld 5.7.40-log) 
starting as process 2549 ...
2023-04-16T08:55:27.260268Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic 
builtins
2023-04-16T08:55:27.260300Z 0 [Note] InnoDB: Uses event mutexes
2023-04-16T08:55:27.260306Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is 
used for memory barrier
2023-04-16T08:55:27.260310Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.12
2023-04-16T08:55:27.261017Z 0 [Note] InnoDB: Number of pools: 1
2023-04-16T08:55:27.263020Z 0 [Note] InnoDB: Using CPU crc32 instructions
2023-04-16T08:55:27.264182Z 0 [Note] InnoDB: Initializing buffer pool, total size = 1G, 
instances = 8, chunk size = 128M
2023-04-16T08:55:27.345406Z 0 [Note] InnoDB: Completed initialization of buffer pool
2023-04-16T08:55:27.358251Z 0 [Note] InnoDB: Highest supported file format is 
Barracuda.
2023-04-16T08:55:27.400071Z 0 [Note] InnoDB: Creating shared tablespace for temporary 
tables
2023-04-16T08:55:27.400147Z 0 [Note] InnoDB: Setting file '/var/db/mysql/ibtmp1' size to 
128 MB. Physically writing the file full; Please wait ...
2023-04-16T08:55:27.400513Z 0 [Note] InnoDB: Progress in MB:
 100
2023-04-16T08:55:27.431472Z 0 [Note] InnoDB: File '/var/db/mysql/ibtmp1' size is now 128 
MB.
2023-04-16T08:55:27.432024Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 
redo rollback segment(s) are active.
2023-04-16T08:55:27.432035Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are 
active.
2023-04-16T08:55:27.432315Z 0 [Note] InnoDB: Waiting for purge to start
2023-04-16T08:55:27.485973Z 0 [Note] InnoDB: 5.7.40 started; log sequence number 
22374147655
2023-04-16T08:55:27.486178Z 0 [Note] InnoDB: Loading buffer pool(s) from /var/db/
mysql/ib_buffer_pool
2023-04-16T08:55:27.487254Z 0 [Note] Plugin 'FEDERATED' is disabled.
2023-04-16T08:55:27.496762Z 0 [Note] InnoDB: Buffer pool(s) load completed at 230416  
9:55:27
2023-04-16T08:55:27.497845Z 0 [Note] Found ca.pem, server-cert.pem and server-key.pem 
in data directory. Trying to enable SSL support using them.
2023-04-16T08:55:27.497858Z 0 [Note] Skipping generation of SSL certificates as certificate 
files are present in data directory.
2023-04-16T08:55:27.497863Z 0 [Warning] A deprecated TLS version TLSv1 is enabled. 
Please use TLSv1.2 or higher.
2023-04-16T08:55:27.497867Z 0 [Warning] A deprecated TLS version TLSv1.1 is enabled. 
Please use TLSv1.2 or higher.
2023-04-16T08:55:27.499114Z 0 [Warning] CA certificate ca.pem is self signed.