mysql-server causes logrotate.service to fail at boot

Bug #1850980 reported by Gargoyle on 2019-11-01
8
This bug affects 1 person
Affects Status Importance Assigned to Milestone
mysql-8.0 (Ubuntu)
Low
Unassigned

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) on 2019-11-01
description: updated
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).

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
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.

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#

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers