mysql-server causes logrotate.service to fail at boot

Bug #1850980 reported by Gargoyle
8
This bug affects 1 person
Affects Status Importance Assigned to Milestone
mysql-8.0 (Ubuntu)
Triaged
Medium
Lena Voytek

Bug Description

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.

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

I've crated a merge request to improve the postrotate script to more accurately detect the difference between mysqld not running and a problem with the configured debian-sys-maint config:-

https://salsa.debian.org/mariadb-team/mysql/merge_requests/29

This will prevent the logrotate service from reporting a startup failure during boot if mysqld is not read to accept connections at the time the postrotate script is run.

However, it will not prevent the potential situation where log files have been rotated but "mysqladmin flush-logs" is not called (because the postrotate script thinks mysqld is not running).

Revision history for this message
Andreas Hasenack (ahasenack) wrote :

Thanks for filing this bug in Ubuntu, and for your troubleshooting and the debian MR.

The logrotate systemd service is actually triggered by a timer, and not by a reboot specifically. You can view when it last run, and when it will run, with the command "systemctl list-timers".

Regarding your troubleshooting and fix, it sounds reasonable. I would probably just check the exit status of the ping command, though.

Let's see what debian has to say on that MR.

Changed in mysql-8.0 (Ubuntu):
status: New → Triaged
importance: Undecided → Low
Revision history for this message
Gargoyle (g-rgoyle) wrote :

Thanks for the feedback, Andreas.

If the logrotate service is ONLY supposed to be triggered via the timer, then that could be a separate bug as it is definitely running on every boot on my 19.10 install.

I took the exit status of the ping command from the man page for mysqladmin and also performed some basic testing. As far as I can tell, it works as expected even during MySQL start-up.

Revision history for this message
Christian Ehrhardt  (paelzer) wrote :

It has a /etc/cron.daily/logrotate that exits early in favor of the systemd timer if systemd is present.
And the timer looks normal to me:
Sat 2019-11-09 00:00:00 UTC 15h left Fri 2019-11-08 00:00:30 UTC 8h ago logrotate.timer logrotate.service

It is using:
OnCalendar=daily

It has no config for onBoot or such.
I think that makes it trigger if the boot is the first activity of a given day per [1][2]

As Andreas said, Let's see what debian has to say on that MR.

[1]: https://www.freedesktop.org/software/systemd/man/systemd.time.html#Calendar%20Events
[2]: https://www.freedesktop.org/software/systemd/man/systemd.timer.html#

Revision history for this message
Christian Ehrhardt  (paelzer) wrote :

Hi,
I come by trying to close or revive bugs that were dormant for too long.
The PR in Debian [1] has been refreshed a few times, but essentially on the mariadb side got replaced by [2].

I think it is time to revisit this for mysql/Ubuntu.
Therefore let me bump this bug with the commend and bump importance as there is prior art we might be able to use as base for this.

[1]: https://salsa.debian.org/mariadb-team/mysql/-/merge_requests/29
[2]: https://salsa.debian.org/mariadb-team/mariadb-10.5/-/commit/341c6595eacbe6dfd8c0c5c3fff2dfb183da8d44

Changed in mysql-8.0 (Ubuntu):
importance: Low → Medium
Revision history for this message
Lena Voytek (lvoytek) wrote :

I'll get this going in Debian and Ubuntu, thanks!

Changed in mysql-8.0 (Ubuntu):
assignee: nobody → Lena Voytek (lvoytek)
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.