Rotating your ProxySQL log files

Recently I received several questions about rotating log files for ProxySQL, so I decided to draft it up as a blog post. Let me go by this using an example.

In my testing lab, I have set up a fairly default ProxySQL (version 1.4.13) service. The default location for the proxysql.log is in /var/lib/proxysql.

[[email protected] ~]# ls -hal /var/lib/proxysql/proxysql.log*
-rw-------. 1 root root 4.9K Jan 30 18:47 /var/lib/proxysql/proxysql.log

I created a pretty basic default logrotate configuration to ensure my logfile rotates on a daily basis and five rotations are kept before expiring.

[[email protected] ~]# cat /etc/logrotate.d/proxysql
/var/lib/proxysql/proxysql.log {
missingok
daily
notifempty
compress
create 0600 root root
rotate 5
}

First attempt

Let’s check whether this is actually the correct file that is used that we will be rotating. As it turned out it is!

[[email protected] ~]# lsof | grep proxysql.log
proxysql 2361 root 1w REG 8,1 5010 1705843 /var/lib/proxysql/proxysql.log
proxysql 2361 root 2w REG 8,1 5010 1705843 /var/lib/proxysql/proxysql.log
proxysql 2361 2362 root 1w REG 8,1 5010 1705843 /var/lib/proxysql/proxysql.log
proxysql 2361 2362 root 2w REG 8,1 5010 1705843 /var/lib/proxysql/proxysql.log
...

Now the time has come to test our logrotate configuration. We use the force option (-f) to ensure it actually does something and we use the verbose option (-v) so it will tell us what it’s doing.

[[email protected] ~]# logrotate -fv /etc/logrotate.d/proxysql
reading config file /etc/logrotate.d/proxysql
Allocating hash table for state file, size 15360 B
Handling 1 logs
rotating pattern: /var/lib/proxysql/proxysql.log forced from command line (5 rotations)
empty log files are not rotated, old logs are removed
considering log /var/lib/proxysql/proxysql.log
log needs rotating
rotating log /var/lib/proxysql/proxysql.log, log->rotateCount is 5
dateext suffix '-20190130'
glob pattern '-[0-9][0-9][0-9][0-9][0-9][0-9][0-9][0-9]'
renaming /var/lib/proxysql/proxysql.log.5.gz to /var/lib/proxysql/proxysql.log.6.gz (rotatecount 5, logstart 1, i 5),
old log /var/lib/proxysql/proxysql.log.5.gz does not exist
...
renaming /var/lib/proxysql/proxysql.log.0.gz to /var/lib/proxysql/proxysql.log.1.gz (rotatecount 5, logstart 1, i 0),
old log /var/lib/proxysql/proxysql.log.0.gz does not exist
log /var/lib/proxysql/proxysql.log.6.gz doesn't exist -- won't try to dispose of it
fscreate context set to system_u:object_r:var_lib_t:s0
renaming /var/lib/proxysql/proxysql.log to /var/lib/proxysql/proxysql.log.1
creating new /var/lib/proxysql/proxysql.log mode = 0600 uid = 0 gid = 0
compressing log with: /bin/gzip
set default create context to system_u:object_r:var_lib_t:s0
set default create context

As the output above shows, our configuration looks fine. It rotated all log files to the next number (5 -> 6, 4 -> 5, etc). It tried to dispose of the 6th iteration but since that did not exist in our case, all seems fine. Let us check the ProxySQL log location to verify.

[[email protected] ~]# ls -hal /var/lib/proxysql/proxysql.log*
-rw-------. 1 root root 0 Jan 30 18:48 /var/lib/proxysql/proxysql.log
-rw-------. 1 root root 995 Jan 30 18:47 /var/lib/proxysql/proxysql.log.1.gz

Yup! All seems good! Or is it? Why would this blog post be necessary if a default logrotate would work?

The problem

Let’s check the active (open) log file in the lsof output.

[[email protected] ~]# lsof | grep proxysql.log
proxysql 2361 root 1w REG 8,1 5010 1705843 /var/lib/proxysql/proxysql.log.1 (deleted)
proxysql 2361 root 2w REG 8,1 5010 1705843 /var/lib/proxysql/proxysql.log.1 (deleted)
proxysql 2361 2362 root 1w REG 8,1 5010 1705843 /var/lib/proxysql/proxysql.log.1 (deleted)
proxysql 2361 2362 root 2w REG 8,1 5010 1705843 /var/lib/proxysql/proxysql.log.1 (deleted)
...

We now see that the proxysql process still has the old log file open which is marked as deleted. From the ls output earlier, we confirmed that the file it is referencing does not exist anymore.

We can see the open file descriptor in the proc-filesystem and we can even read the contents of that deleted file, but this is not our expected behavior.

[[email protected] ~]# ls -hal /proc/2361/fd | grep log
l-wx------. 1 root root 64 Jan 30 17:34 1 -> /var/lib/proxysql/proxysql.log.1 (deleted)
l-wx------. 1 root root 64 Jan 30 17:34 2 -> /var/lib/proxysql/proxysql.log.1 (deleted)
[[email protected] ~]# tail -5 /proc/2361/fd/1
2019-01-30 18:58:54 [INFO] ProxySQL version 1.4.13-15-g69d4207
2019-01-30 18:58:54 [INFO] Detected OS: Linux proxysql 3.10.0-957.1.3.el7.x86_64 #1 SMP Thu Nov 29 14:49:43 UTC 2018 x86_64
[[email protected] ~]# tail -5 /proc/2361/fd/2
2019-01-30 18:58:54 [INFO] ProxySQL version 1.4.13-15-g69d4207
2019-01-30 18:58:54 [INFO] Detected OS: Linux proxysql 3.10.0-957.1.3.el7.x86_64 #1 SMP Thu Nov 29 14:49:43 UTC 2018 x86_64

The solution

As with most log files, we need to make the software flush the log file, which basically means closing and re-opening the file internally. This resets the file descriptor and allows the old to be removed.

To do so, we will need to use the ProxySQL admin interface using the MySQL client to issue the command “PROXYSQL FLUSH LOGS”

[[email protected] ~]# mysql -h 127.0.0.1 -P 6032 -uadmin -padmin
...
mysql> PROXYSQL FLUSH LOGS;
Query OK, 0 rows affected (0.00 sec)

As you can see in the output below, my proxysql.log file which was 0 bytes after the rotation, is in use by the process and has grown to 187 bytes which means some content was added. If we now check the contents of the log file we see that it is proxysql that actually started writing to it. Yay!

[[email protected] ~]# lsof | grep proxysql.log
proxysql 2361 root 1w REG 8,1 876 1705843 /var/lib/proxysql/proxysql.log
proxysql 2361 root 2w REG 8,1 876 1705843 /var/lib/proxysql/proxysql.log
proxysql 2361 2362 root 1w REG 8,1 876 1705843 /var/lib/proxysql/proxysql.log
proxysql 2361 2362 root 2w REG 8,1 876 1705843 /var/lib/proxysql/proxysql.log
...
[[email protected] ~]# ls -hal /var/lib/proxysql/proxysql.log*
-rw-------. 1 root root 187 Jan 30 18:50 /var/lib/proxysql/proxysql.log
-rw-------. 1 root root 995 Jan 30 18:47 /var/lib/proxysql/proxysql.log.1.gz
[[email protected] ~]# cat /var/lib/proxysql/proxysql.log
2019-01-30 18:50:57 [INFO] ProxySQL version 1.4.13-15-g69d4207
2019-01-30 18:50:57 [INFO] Detected OS: Linux proxysql 3.10.0-957.1.3.el7.x86_64 #1 SMP Thu Nov 29 14:49:43 UTC 2018 x86_64

Let’s make logrotate do the flushing

We now have all the components to put this together. For an automated approach, we can use a my.cnf file or we can use the mysql_config_editor, which is provided with Oracle’s MySQL community edition client, to create a login path. Either one will work fine to make a scripted connection to the proxysql admin interface.

[[email protected] ~]# mysql --defaults-file=/etc/proxysql.my.cnf --execute="PROXYSQL FLUSH LOGS"
[[email protected] ~]# cat /etc/proxysql.my.cnf
[client]
host = 127.0.0.1
port = 6032
user = admin
password = admin
[[email protected] ~]# mysql_config_editor set --login-path=proxysql-admin --host=127.0.0.1 --port=6032 --user=admin -p
Enter password:
[[email protected] ~]# mysql_config_editor print --login-path=proxysql-admin
[proxysql-admin]
user = admin
password = *****
host = 127.0.0.1
port = 6032
[[email protected] ~]# mysql --login-path=proxysql-admin --execute="PROXYSQL FLUSH LOGS;"

We can put this command in the postrotate section of the logrotate configuration to execute after rotation but before the compression phase.

[[email protected] ~]# cat /etc/logrotate.d/proxysql
/var/lib/proxysql/proxysql.log {
missingok
daily
notifempty
compress
postrotate
/usr/bin/mysql --defaults-file=/etc/proxysql.my.cnf --execute="PROXYSQL FLUSH LOGS"
endscript
create 0600 root root
rotate 5
}

Let’s test to see if it works.

[[email protected] ~]# ls -hal /var/lib/proxysql/proxysql.log*
-rw-------. 1 root root 876 Jan 30 18:58 /var/lib/proxysql/proxysql.log
-rw-------. 1 root root 995 Jan 30 18:47 /var/lib/proxysql/proxysql.log.1.gz
[[email protected] ~]# logrotate -fv /etc/logrotate.d/proxysql
reading config file /etc/logrotate.d/proxysql
Allocating hash table for state file, size 15360 B
Handling 1 logs
rotating pattern: /var/lib/proxysql/proxysql.log forced from command line (5 rotations)
...
renaming /var/lib/proxysql/proxysql.log to /var/lib/proxysql/proxysql.log.1
creating new /var/lib/proxysql/proxysql.log mode = 0600 uid = 0 gid = 0
running postrotate script
compressing log with: /bin/gzip
set default create context to system_u:object_r:var_lib_t:s0
set default create context
[[email protected] ~]# ls -hal /var/lib/proxysql/proxysql.log*
-rw-------. 1 root root 187 Jan 30 18:58 /var/lib/proxysql/proxysql.log
-rw-------. 1 root root 241 Jan 30 18:58 /var/lib/proxysql/proxysql.log.1.gz
-rw-------. 1 root root 995 Jan 30 18:47 /var/lib/proxysql/proxysql.log.2.gz

Conclusion

As with most software that uses log files, it is necessary to take action after the rotation to make the daemon “flush” its handle to the files. This way the old files are no longer in use and the new files will be. ProxySQL provides us with the tools to do this, but you have to make sure to actually use them.