mysql fails to start on debian startup (systemd), but starting manually works

Question

I have a weird issue with MySQL on a Debian (Jessie) server.

When the server is restarted, systemd will try to start mysqld, but it fails (looks like the port 3306 is already used, but I don't see why it would).

However, if I SSH to the server only minutes later and run sudo systemctl start mysql it will succeed.

The issue can be reproduced each time I restart the server.

Anyone already had this issue, or any guess what could prevent MySQL to start correctly? I could add a delay before starting MySQL after reboot, but I'd like to understand what is going on, and actually I'm not even sure that would fix the issue.

Here is the result of sudo systemctl status mysql -l after reboot:

● mysql.service - LSB: Start and stop the mysql database server daemon
   Loaded: loaded (/etc/init.d/mysql)
   Active: failed (Result: exit-code) since Fri 2017-09-01 21:54:44 CEST; 1min 41s ago
  Process: 581 ExecStart=/etc/init.d/mysql start (code=exited, status=1/FAILURE)

Sep 01 21:54:06 gimli systemd[1]: Starting LSB: Start and stop the mysql database server daemon...
Sep 01 21:54:44 gimli mysql[581]: Starting MySQL database server: mysqld . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . failed!
Sep 01 21:54:44 gimli systemd[1]: mysql.service: control process exited, code=exited status=1
Sep 01 21:54:44 gimli systemd[1]: Failed to start LSB: Start and stop the mysql database server daemon.
Sep 01 21:54:44 gimli systemd[1]: Unit mysql.service entered failed state.

and the corresponding log from /var/log/mysql/error.log

170901 21:54:16 [Warning] Using unique option prefix myisam-recover instead of myisam-recover-options is deprecated and will be removed in a future release. Please use the full name instead.
170901 21:54:16 [Note] Plugin 'FEDERATED' is disabled.
170901 21:54:17 InnoDB: The InnoDB memory heap is disabled
170901 21:54:17 InnoDB: Mutexes and rw_locks use GCC atomic builtins
170901 21:54:17 InnoDB: Compressed tables use zlib 1.2.8
170901 21:54:17 InnoDB: Using Linux native AIO
170901 21:54:17 InnoDB: Initializing buffer pool, size = 128.0M
170901 21:54:17 InnoDB: Completed initialization of buffer pool
170901 21:54:17 InnoDB: highest supported file format is Barracuda.
170901 21:54:22  InnoDB: Waiting for the background threads to start
170901 21:54:23 InnoDB: 5.5.57 started; log sequence number 351234412
170901 21:54:23 [Note] Server hostname (bind-address): '192.168.1.14'; port: 3306
170901 21:54:23 [Note]   - '192.168.1.14' resolves to '192.168.1.14';
170901 21:54:23 [Note] Server socket created on IP: '192.168.1.14'.
170901 21:54:23 [ERROR] Can't start server: Bind on TCP/IP port: Cannot assign requested address
170901 21:54:23 [ERROR] Do you already have another mysqld server running on port: 3306 ?
170901 21:54:23 [ERROR] Aborting

170901 21:54:23  InnoDB: Starting shutdown...
170901 21:54:24  InnoDB: Shutdown completed; log sequence number 351234412
170901 21:54:24 [Note] /usr/sbin/mysqld: Shutdown complete

However, if I run sudo systemctl start mysql manually, it works correctly:

170901 22:01:36 [Warning] Using unique option prefix myisam-recover instead of myisam-recover-options is deprecated and will be removed in a future release. Please use the full name instead.
170901 22:01:36 [Note] Plugin 'FEDERATED' is disabled.
170901 22:01:36 InnoDB: The InnoDB memory heap is disabled
170901 22:01:36 InnoDB: Mutexes and rw_locks use GCC atomic builtins
170901 22:01:36 InnoDB: Compressed tables use zlib 1.2.8
170901 22:01:36 InnoDB: Using Linux native AIO
170901 22:01:36 InnoDB: Initializing buffer pool, size = 128.0M
170901 22:01:36 InnoDB: Completed initialization of buffer pool
170901 22:01:36 InnoDB: highest supported file format is Barracuda.
170901 22:01:36  InnoDB: Waiting for the background threads to start
170901 22:01:37 InnoDB: 5.5.57 started; log sequence number 351234412
170901 22:01:37 [Note] Server hostname (bind-address): '192.168.1.14'; port: 3306
170901 22:01:37 [Note]   - '192.168.1.14' resolves to '192.168.1.14';
170901 22:01:37 [Note] Server socket created on IP: '192.168.1.14'.
170901 22:01:37 [Note] Event Scheduler: Loaded 0 events
170901 22:01:37 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.5.57-0+deb8u1'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  (Debian)

To my knowledge, the systemd script has not been modified (it's the one that comes with the Debian mysql package), and as far as I know, it never worked correctly. The 3306 port is not supposed to be used by another process.

Answer 1

Apparently the problem was that the network interface was not up at the time mysql starts. This is probably related to DHCP taking a bit of time.

At least, now that I set the interface to static IP, I don't observe the mysql issue anymore (again, reproducible on every startup), so that solved the problem.

Here is the procedure to set a static IP on debian:

1. Make sure you have physical access to your server (power button, keyboard, screen) before attempting to mess with the network since you could loose the ssh ability
2. edit /etc/network/interfaces

3. replace iface eth0 inet dhcp by:

   iface eth0 inet static
       address 192.168.1.14
       network 192.168.1.0
       netmask 255.255.255.0
       broadcast 192.168.1.255
       gateway 192.168.1.1
   

4. reboot (note: restarting the network should be enough, for example with systemctl restart networking, but in my case I lost connection but couldn't reconnect without restarting the server with the power button)

In this example I assign the static IP 192.168.1.14 and gateway 192.168.1.1

Of course this is only a workaround, the real issue being that mysql should wait for the network interface to be up, but I don't know systemd well enough to do that.

Answer 2

Try to SSH into the server right after rebooting and running netstat -lp | grep 3306 as root to check what program is actually listening on that port so you can further debug the issue.