From nobody Sun Apr 16 09:12:44 2023 X-Original-To: freebsd-questions@mlmmj.nyi.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2610:1c1:1:606c::19:1]) by mlmmj.nyi.freebsd.org (Postfix) with ESMTP id 4Pzkwz4r3Bz44yVb for ; Sun, 16 Apr 2023 09:12:51 +0000 (UTC) (envelope-from jmc-freebsd2@milibyte.co.uk) Received: from cp160176.hpdns.net (cp160176.hpdns.net [91.238.160.176]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (Client did not present a certificate) by mx1.freebsd.org (Postfix) with ESMTPS id 4Pzkwy3q3gz3J7H for ; Sun, 16 Apr 2023 09:12:50 +0000 (UTC) (envelope-from jmc-freebsd2@milibyte.co.uk) Authentication-Results: mx1.freebsd.org; dkim=pass header.d=milibyte.co.uk header.s=default header.b=Qs0K7YUX; spf=pass (mx1.freebsd.org: domain of jmc-freebsd2@milibyte.co.uk designates 91.238.160.176 as permitted sender) smtp.mailfrom=jmc-freebsd2@milibyte.co.uk; dmarc=none DKIM-Signature: v=1; a=rsa-sha256; q=dns/txt; c=relaxed/relaxed; d=milibyte.co.uk; s=default; h=Content-Transfer-Encoding:Content-Type: MIME-Version:References:In-Reply-To:Message-ID:Date:Subject:To:From:Sender: Reply-To:Cc:Content-ID:Content-Description:Resent-Date:Resent-From: Resent-Sender:Resent-To:Resent-Cc:Resent-Message-ID:List-Id:List-Help: List-Unsubscribe:List-Subscribe:List-Post:List-Owner:List-Archive; bh=i4iIeimpX3zxHbBY1WGncip7TlnaUFZbFce52UTbRN0=; b=Qs0K7YUXa/9I2xApKjwDFxsKYB sdtQcUOhJe4bBRCpZh1lQtzJbbesiUgmEZ8FyQN7K9vakinzBnimzPTpoStZsWcKTE6xOqO4YwVxT pi+fVSZ3Vs1mJ15sT0/BbWDF6sRHc7aO84ak/EmXiv7UB2Nd1B0gB5Mq7bNKL3wqbOu3BWWo3+pd2 eUFUXqd40aMj+07oAhkGCmLW+86FhGWK9f0Q+s33QgH5XoAyM8stiwm35mfOnDMsh9KZzxpe/hHB6 qz7R70SiIErj7GXZjSicSwciwqXfAr75SpNG23xlDE1x1Z44glmR2ebhc1fRoGCoXWphEXjytUcIN aiIaHJ4A==; Received: from [149.86.189.206] (port=41451 helo=curlew.milibyte.co.uk) by cp160176.hpdns.net with esmtpsa (TLS1.2) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.96) (envelope-from ) id 1pnyRB-001c8T-0l for freebsd-questions@freebsd.org; Sun, 16 Apr 2023 10:12:45 +0100 Received: from [127.0.0.1] (helo=curlew.localnet) by curlew.milibyte.co.uk with esmtp (Exim 4.95) (envelope-from ) id 1pnyRB-0000oK-1j for freebsd-questions@freebsd.org; Sun, 16 Apr 2023 10:12:45 +0100 From: Mike Clarke To: freebsd-questions@freebsd.org Subject: Re: MySQL server silently fails to start after upgrading from 5.7.40 to 8.0.32 Date: Sun, 16 Apr 2023 10:12:44 +0100 Message-ID: <5781665.Zv9zXsTiuT@curlew> In-Reply-To: References: <4381878.Iv3B0QcHgC@curlew> List-Id: User questions List-Archive: https://lists.freebsd.org/archives/freebsd-questions List-Help: List-Post: List-Subscribe: List-Unsubscribe: Sender: owner-freebsd-questions@freebsd.org X-BeenThere: freebsd-questions@freebsd.org MIME-Version: 1.0 Content-Type: multipart/alternative; boundary="nextPart2630402.TYJnH3iKXO" Content-Transfer-Encoding: 7Bit X-SA-Exim-Connect-IP: 127.0.0.1 X-SA-Exim-Mail-From: jmc-freebsd2@milibyte.co.uk X-SA-Exim-Scanned: No (on curlew.milibyte.co.uk); SAEximRunCond expanded to false X-YourOrg-MailScanner-Information: Please contact the ISP for more information X-YourOrg-MailScanner-ID: 1pnyRB-001c8T-0l X-YourOrg-MailScanner: Found to be clean X-YourOrg-MailScanner-SpamCheck: X-YourOrg-MailScanner-From: jmc-freebsd2@milibyte.co.uk X-Spam-Status: No X-AntiAbuse: This header was added to track abuse, please include it with any abuse report X-AntiAbuse: Primary Hostname - cp160176.hpdns.net X-AntiAbuse: Original Domain - freebsd.org X-AntiAbuse: Originator/Caller UID/GID - [47 12] / [47 12] X-AntiAbuse: Sender Address Domain - milibyte.co.uk X-Get-Message-Sender-Via: cp160176.hpdns.net: authenticated_id: mailpool@milibyte.co.uk X-Authenticated-Sender: cp160176.hpdns.net: mailpool@milibyte.co.uk X-Source: X-Source-Args: X-Source-Dir: X-Spamd-Result: default: False [-2.49 / 15.00]; NEURAL_HAM_LONG(-1.00)[-1.000]; NEURAL_HAM_MEDIUM(-1.00)[-1.000]; NEURAL_HAM_SHORT(-0.99)[-0.994]; CTE_CASE(0.50)[]; MID_RHS_NOT_FQDN(0.50)[]; R_DKIM_ALLOW(-0.20)[milibyte.co.uk:s=default]; R_SPF_ALLOW(-0.20)[+a]; MIME_GOOD(-0.10)[multipart/alternative,text/plain]; DMARC_NA(0.00)[milibyte.co.uk]; FROM_HAS_DN(0.00)[]; HAS_X_GMSV(0.00)[mailpool@milibyte.co.uk]; TO_MATCH_ENVRCPT_ALL(0.00)[]; RCPT_COUNT_ONE(0.00)[1]; ARC_NA(0.00)[]; RCVD_TLS_LAST(0.00)[]; MLMMJ_DEST(0.00)[freebsd-questions@freebsd.org]; RCVD_COUNT_THREE(0.00)[3]; TO_DN_NONE(0.00)[]; HAS_X_SOURCE(0.00)[]; HAS_X_AS(0.00)[mailpool@milibyte.co.uk]; DKIM_TRACE(0.00)[milibyte.co.uk:+]; FROM_EQ_ENVFROM(0.00)[]; HAS_X_ANTIABUSE(0.00)[]; ASN(0.00)[asn:52148, ipnet:91.238.160.0/22, country:GB]; MIME_TRACE(0.00)[0:+,1:+,2:~]; RCVD_VIA_SMTP_AUTH(0.00)[] X-Rspamd-Queue-Id: 4Pzkwy3q3gz3J7H X-Spamd-Bar: -- X-ThisMailContainsUnwantedMimeParts: N 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"

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.

2023-04-16T08:55:27.499288Z 0 [Note] Skipping generation of RSA key pair as key files are present in data directory.

2023-04-16T08:55:27.499630Z 0 [Note] Server hostname (bind-address): '127.0.0.1'; port: 3306

2023-04-16T08:55:27.499655Z 0 [Note]   - '127.0.0.1' resolves to '127.0.0.1';

2023-04-16T08:55:27.499678Z 0 [Note] Server socket created on IP: '127.0.0.1'.

2023-04-16T08:55:27.508953Z 0 [Note] Failed to start slave threads for channel ''

2023-04-16T08:55:27.526325Z 0 [Warning] Optional native table 'performance_schema'.'processlist' has the wrong structure or is missing.

2023-04-16T08:55:27.526935Z 0 [Note] Event Scheduler: Loaded 0 events

2023-04-16T08:55:27.527032Z 0 [Note] /usr/local/libexec/mysqld: ready for connections.

Version: '5.7.40-log'  socket: '/tmp/mysql.sock'  port: 3306  Source distribution


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


--

Mike Clarke

--nextPart2630402.TYJnH3iKXO--