Public bug reported:
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 and the logrotate.service reports an error in starting up.
** Affects: mysql-8.0 (Ubuntu)
Importance: Undecided
Status: New
** Description changed:
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.
+ MySQL's log files might actually be rotated, but the flush logs command will
not be executed and the logrotate.service reports an error in starting up.
--
You received this bug notification because you are a member of Ubuntu
Bugs, which is subscribed to Ubuntu.
https://bugs.launchpad.net/bugs/1850980
Title:
mysql-server causes logrotate.service to fail at boot
To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/mysql-8.0/+bug/1850980/+subscriptions
--
ubuntu-bugs mailing list
[email protected]
https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs
