Date: Sun, 16 Apr 2023 10:12:44 +0100 From: Mike Clarke <jmc-freebsd2@milibyte.co.uk> To: freebsd-questions@freebsd.org Subject: Re: MySQL server silently fails to start after upgrading from 5.7.40 to 8.0.32 Message-ID: <5781665.Zv9zXsTiuT@curlew> In-Reply-To: <a368b7f5-cb74-9cf0-907e-c4633433cab7@netfence.it> References: <4381878.Iv3B0QcHgC@curlew> <a368b7f5-cb74-9cf0-907e-c4633433cab7@netfence.it>
next in thread | previous in thread | raw e-mail | index | archive | help
This is a multi-part message in MIME format.
--nextPart2630402.TYJnH3iKXO
Content-Transfer-Encoding: 7Bit
Content-Type: text/plain; charset="UTF-8"
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.
--nextPart2630402.TYJnH3iKXO
Content-Transfer-Encoding: 7Bit
Content-Type: text/html; charset="UTF-8"
<html>
<head>
<meta http-equiv="content-type" content="text/html; charset=UTF-8">
</head>
<body><p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">On Saturday, 15 April 2023 17:29:10 BST Andrea Venturoli wrote:</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">> On 4/15/23 18:25, Mike Clarke wrote:</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">> > After upgrading packages to the the new quarterly release mysql was</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">> > upgraded to 8.0.32 and it fails to start and does not produce any</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">> > failure message on the console and I couldn't find any relevant failure</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">> > message anywhere in /var/logs.</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">> </p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">> What's in /var/db/mysql/{hostname}.err?</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">> </p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">> bye</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">> av.</p>
<br /><p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">Here's the results for mysql8</p>
<br /><p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">########################################################</p>
<br /><p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:47:33.6NZ mysqld_safe Logging to '/var/db/mysql/curlew.err'.</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:47:33.6NZ mysqld_safe Starting mysqld daemon with databases from /var/db/mysql</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">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)</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:47:33.068419Z 0 [Warning] [MY-010142] [Server] Changed limits: table_open_cache: 11169 (requested 16384)</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">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.</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:47:33.257337Z 0 [System] [MY-010116] [Server] /usr/local/libexec/mysqld (mysqld 8.0.32) starting as process 6221</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:47:33.284373Z 1 [System] [MY-011012] [Server] Starting upgrade of data directory.</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:47:33.284397Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">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!</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">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.</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:47:33.376512Z 1 [ERROR] [MY-011013] [Server] Failed to initialize DD Storage Engine.</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:47:33.376689Z 0 [ERROR] [MY-010020] [Server] Data Dictionary initialization failed.</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:47:33.376712Z 0 [ERROR] [MY-010119] [Server] Aborting</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:47:33.378196Z 0 [System] [MY-010910] [Server] /usr/local/libexec/mysqld: Shutdown complete (mysqld 8.0.32) Source distribution.</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:47:33.6NZ mysqld_safe mysqld from pid file /var/db/mysql/curlew.pid ended</p>
<br /><p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">########################################################</p>
<br /><p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">And for comparison a successful run with mysql5</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">Both attempts were using the same /var/db/mysql directory, just running from different BEs</p>
<br /><p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">########################################################</p>
<br /><p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:55:27.6NZ mysqld_safe Logging to '/var/db/mysql/curlew.err'.</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:55:27.6NZ mysqld_safe Starting mysqld daemon with databases from /var/db/mysql</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:55:27.086768Z 0 [Warning] Could not increase number of max_open_files to more than 22500 (request: 32929)</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:55:27.086994Z 0 [Warning] Changed limits: table_open_cache: 11169 (requested 16384)</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">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.</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:55:27.230570Z 0 [Warning] 'NO_AUTO_CREATE_USER' sql mode was not set.</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:55:27.232719Z 0 [Note] /usr/local/libexec/mysqld (mysqld 5.7.40-log) starting as process 2549 ...</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:55:27.260268Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:55:27.260300Z 0 [Note] InnoDB: Uses event mutexes</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:55:27.260306Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:55:27.260310Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.12</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:55:27.261017Z 0 [Note] InnoDB: Number of pools: 1</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:55:27.263020Z 0 [Note] InnoDB: Using CPU crc32 instructions</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:55:27.264182Z 0 [Note] InnoDB: Initializing buffer pool, total size = 1G, instances = 8, chunk size = 128M</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:55:27.345406Z 0 [Note] InnoDB: Completed initialization of buffer pool</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:55:27.358251Z 0 [Note] InnoDB: Highest supported file format is Barracuda.</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:55:27.400071Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">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 ...</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:55:27.400513Z 0 [Note] InnoDB: Progress in MB:</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;"> 100</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:55:27.431472Z 0 [Note] InnoDB: File '/var/db/mysql/ibtmp1' size is now 128 MB.</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:55:27.432024Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:55:27.432035Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:55:27.432315Z 0 [Note] InnoDB: Waiting for purge to start</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:55:27.485973Z 0 [Note] InnoDB: 5.7.40 started; log sequence number 22374147655</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:55:27.486178Z 0 [Note] InnoDB: Loading buffer pool(s) from /var/db/mysql/ib_buffer_pool</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:55:27.487254Z 0 [Note] Plugin 'FEDERATED' is disabled.</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:55:27.496762Z 0 [Note] InnoDB: Buffer pool(s) load completed at 230416 9:55:27</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">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.</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:55:27.497858Z 0 [Note] Skipping generation of SSL certificates as certificate files are present in data directory.</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:55:27.497863Z 0 [Warning] A deprecated TLS version TLSv1 is enabled. Please use TLSv1.2 or higher.</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:55:27.497867Z 0 [Warning] A deprecated TLS version TLSv1.1 is enabled. Please use TLSv1.2 or higher.</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:55:27.499114Z 0 [Warning] CA certificate ca.pem is self signed.</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:55:27.499288Z 0 [Note] Skipping generation of RSA key pair as key files are present in data directory.</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:55:27.499630Z 0 [Note] Server hostname (bind-address): '127.0.0.1'; port: 3306</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:55:27.499655Z 0 [Note] - '127.0.0.1' resolves to '127.0.0.1';</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:55:27.499678Z 0 [Note] Server socket created on IP: '127.0.0.1'.</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:55:27.508953Z 0 [Note] Failed to start slave threads for channel ''</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:55:27.526325Z 0 [Warning] Optional native table 'performance_schema'.'processlist' has the wrong structure or is missing.</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:55:27.526935Z 0 [Note] Event Scheduler: Loaded 0 events</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">2023-04-16T08:55:27.527032Z 0 [Note] /usr/local/libexec/mysqld: ready for connections.</p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">Version: '5.7.40-log' socket: '/tmp/mysql.sock' port: 3306 Source distribution</p>
<br /><p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">########################################################</p>
<br /><p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">-- </p>
<p style="margin-top:0;margin-bottom:0;margin-left:0;margin-right:0;">Mike Clarke</p>
</body>
</html>
--nextPart2630402.TYJnH3iKXO--
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?5781665.Zv9zXsTiuT>