MySQL Bugs: #109722: Mysql server is not started after starting using "/sbin/service mysqld start"

Bug #109722	Mysql server is not started after starting using "/sbin/service mysqld start"
Submitted:	20 Jan 2023 12:15	Modified:	25 Jan 2023 7:40
Reporter:	Amritha Prabhu	Email Updates:
Status:	Not a Bug	Impact on me:	None
Category:	MySQL Server	Severity:	S3 (Non-critical)
Version:	8.0.31	OS:	Red Hat (RHEL 8.7)
Assigned to:	MySQL Verification Team	CPU Architecture:	x86
Tags:	server not starting

Description:
what we did
-----------
Before starting our java processes, we started our Mysql server using the command "/sbin/service mysqld start" through script. The command is executed but the Mysql server is not started.

what we wanted to happen
------------------------
We expected that Mysql server is started

What happened
-------------
Mysql server is not started and when we checked the status, it showed

[root@VMNMSRHEL8u3-21 logs]# service mysqld status
Redirecting to /bin/systemctl status mysqld.service
● mysqld.service - MySQL Server
   Loaded: loaded (/usr/lib/systemd/system/mysqld.service; disabled; vendor preset: disabled)
   Active: failed (Result: exit-code) since Sun 2023-01-15 14:10:25 IST; 21h ago
     Docs: man:mysqld(8)
http://dev.mysql.com/doc/refman/en/using-systemd.html
  Process: 2243 ExecStart=/usr/sbin/mysqld $MYSQLD_OPTS (code=exited, status=1/FAILURE)
  Process: 2215 ExecStartPre=/usr/bin/mysqld_pre_systemd (code=exited, status=0/SUCCESS)
Main PID: 2243 (code=exited, status=1/FAILURE)
   Status: "Server shutdown complete"
    Error: 17 (File exists)

 

Jan 15 14:08:23 VMNMSRHEL8u3-21 systemd[1]: Starting MySQL Server...
Jan 15 14:10:25 VMNMSRHEL8u3-21 systemd[1]: mysqld.service: Main process exited, code=exited, status=1/FAILURE
Jan 15 14:10:25 VMNMSRHEL8u3-21 systemd[1]: mysqld.service: Failed with result 'exit-code'.
Jan 15 14:10:25 VMNMSRHEL8u3-21 systemd[1]: Failed to start MySQL Server.

After we executed the same start command manually, Mysql server started.

How to repeat:
This issue is not reproducing all the time, so we don't know how to repeat the issue

Hi!

Can you please post content of error logs? 

These should be available in

 /var/log/mysqld.log

Thanks!

Contents of /var/log/mysqld.log file
------------------------------------
2023-01-12T16:13:43.305749Z 0 [System] [MY-010931] [Server] /usr/sbin/mysqld: ready for connections. Version: '8.0.31-commercial'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MySQL Enterprise Server - Commercial.
2023-01-15T08:38:34.119954Z 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-01-15T08:38:34.119997Z 0 [Warning] [MY-010097] [Server] Insecure configuration for --secure-file-priv: Current value does not restrict location of generated files. Consider setting it to a valid, non-empty path.
2023-01-15T08:38:34.120093Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.0.31-commercial) starting as process 2243
2023-01-15T08:38:34.953289Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2023-01-15T08:38:56.681807Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
2023-01-15T08:40:17.877514Z 0 [System] [MY-010229] [Server] Starting XA crash recovery...
2023-01-15T08:40:17.899487Z 0 [System] [MY-010232] [Server] XA crash recovery finished.
2023-01-15T08:40:19.386632Z 0 [Warning] [MY-013829] [Server] Missing data directory for ICU regular expressions: /usr/lib64/mysql/private/.
2023-01-15T08:40:22.505886Z 0 [Warning] [MY-010068] [Server] CA certificate ca.pem is self signed.
2023-01-15T08:40:22.506014Z 0 [System] [MY-013602] [Server] Channel mysql_main configured to support TLS. Encrypted connections are now supported for this channel.
2023-01-15T08:40:22.541290Z 0 [ERROR] [MY-010259] [Server] Another process with pid 2254 is using unix socket file.
2023-01-15T08:40:22.541335Z 0 [ERROR] [MY-010268] [Server] Unable to setup unix socket lock file.
2023-01-15T08:40:22.541404Z 0 [ERROR] [MY-010119] [Server] Aborting
2023-01-15T08:40:25.185290Z 0 [System] [MY-010910] [Server] /usr/sbin/mysqld: Shutdown complete (mysqld 8.0.31-commercial)  MySQL Enterprise Server - Commercial.
2023-01-16T06:10:08.995274Z 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-01-16T06:10:08.995372Z 0 [Warning] [MY-010097] [Server] Insecure configuration for --secure-file-priv: Current value does not restrict location of generated files. Consider setting it to a valid, non-empty path.
2023-01-16T06:10:08.995617Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.0.31-commercial) starting as process 215751
2023-01-16T06:10:09.133755Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2023-01-16T06:10:10.223009Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
2023-01-16T06:10:11.087581Z 0 [Warning] [MY-013829] [Server] Missing data directory for ICU regular expressions: /usr/lib64/mysql/private/.
2023-01-16T06:10:11.101855Z 0 [Warning] [MY-010068] [Server] CA certificate ca.pem is self signed.
2023-01-16T06:10:11.101953Z 0 [System] [MY-013602] [Server] Channel mysql_main configured to support TLS. Encrypted connections are now supported for this channel.
2023-01-16T06:10:11.243189Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Bind-address: '::' port: 33060, socket: /var/run/mysqld/mysqlx.sock
2023-01-16T06:10:11.243490Z 0 [System] [MY-010931] [Server] /usr/sbin/mysqld: ready for connections. Version: '8.0.31-commercial'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MySQL Enterprise Server - Commercial.

Hi,

This is not a bug. You had mysqld already running when you tried to start it again.

Hi,
If mysqld is already running, when we gave mysqld status it shows status as "Active", right?
But it showed 
[root@VMNMSRHEL8u3-21 logs]# service mysqld status
Redirecting to /bin/systemctl status mysqld.service
● mysqld.service - MySQL Server
   Loaded: loaded (/usr/lib/systemd/system/mysqld.service; disabled; vendor preset: disabled)
   Active: failed (Result: exit-code) since Sun 2023-01-15 14:10:25 IST; 21h ago
     Docs: man:mysqld(8)
http://dev.mysql.com/doc/refman/en/using-systemd.html
  Process: 2243 ExecStart=/usr/sbin/mysqld $MYSQLD_OPTS (code=exited, status=1/FAILURE)
  Process: 2215 ExecStartPre=/usr/bin/mysqld_pre_systemd (code=exited, status=0/SUCCESS)
Main PID: 2243 (code=exited, status=1/FAILURE)
   Status: "Server shutdown complete"
    Error: 17 (File exists)

 

Jan 15 14:08:23 VMNMSRHEL8u3-21 systemd[1]: Starting MySQL Server...
Jan 15 14:10:25 VMNMSRHEL8u3-21 systemd[1]: mysqld.service: Main process exited, code=exited, status=1/FAILURE
Jan 15 14:10:25 VMNMSRHEL8u3-21 systemd[1]: mysqld.service: Failed with result 'exit-code'.
Jan 15 14:10:25 VMNMSRHEL8u3-21 systemd[1]: Failed to start MySQL Server.

That is maybe bug in systemd but clearly if you look at your log, mysqld did not start because:

2023-01-15T08:40:22.541290Z 0 [ERROR] [MY-010259] [Server] Another process with pid 2254 is using unix socket file.
2023-01-15T08:40:22.541335Z 0 [ERROR] [MY-010268] [Server] Unable to setup unix socket lock file.

Maybe it was not mysqld holding the socket but you had another process holding on to it, but in 99.9% cases it is mysqld that is running and holding on to this socket.