Comment 0 for bug 1850980

Revision history for this message
Gargoyle (g-rgoyle) wrote :

Description
-----------
During boot, systemd starts logrotate service and mysql server at the same time. However, at "random" the logrotate service will report a failure to run with an error message pointing to the mysql logrotate configuration.

After some digging I found this to be a race condition within the postrotate script within the /etc/logrotate.d/mysql-server configuration file.

The postrotate script first tries to check connectivity to the mysql server using "mysqladmin ping", if that fails it then checks for the existence of a mysqld process using "killall -q -s0 -umysql mysqld". If such a process exists, it assumes that this is a miss-configuration with the debian-sys-maint user and exits with en error (exit 1).

This is not the case though. MySQL is just in the process of starting up, so the mysqld process exists but the server is not yet ready to accept connections.

```
-- Reboot --
Oct 31 09:27:25 ryzen1910 systemd[1]: Starting Rotate log files...
Oct 31 09:27:25 ryzen1910 systemd[1]: logrotate.service: Succeeded.
Oct 31 09:27:25 ryzen1910 systemd[1]: Started Rotate log files.
-- Reboot --
Nov 01 08:11:35 ryzen1910 systemd[1]: Starting Rotate log files...
Nov 01 08:11:35 ryzen1910 logrotate[1528]: error: error running shared postrotate script for '/var/log/mysql.log /var/log/mysql/*log '
Nov 01 08:11:35 ryzen1910 systemd[1]: logrotate.service: Main process exited, code=exited, status=1/FAILURE
Nov 01 08:11:35 ryzen1910 systemd[1]: logrotate.service: Failed with result 'exit-code'.
Nov 01 08:11:35 ryzen1910 systemd[1]: Failed to start Rotate log files.
```

Impact
------
I am not familiar enough with logrotate to know if this has more serious consequences than simply not rotating the logs until the next time logrotate is triggered via cron.

As the service is defined as a "oneshot" type, my assumption is that this is only triggered on boot to overcome the fact that the system could have been powered off at the time logrotate was scheduled to run via cron.

Because it is the postrotate script that fails, mysqld could be in the state where it's log files have been rotated but "mysqladmin flush-logs" has not been triggered.

I guess there could be other consequences of mysqld having it's log file rotated while it is in the process of starting up.

System Details
--------------
Release: Ubuntu 19.10
mysql-server Version: 8.0.17-0ubuntu2

Expected Behaviour
------------------
MySQL's log files will be rotated on boot if needed and mysqld will be requested to flush it's logs.

Actual Behaviour
----------------
MySQL's log files might actually be rotated, but the flush logs command will not be executed.