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. [code] [root@proxysql ~]# ls -hal /var/lib/proxysql/proxysql.log* -rw-------. 1 root root 4.9K Jan 30 18:47 /var/lib/proxysql/proxysql.log [/code] I created a pretty basic default logrotate configuration to ensure my logfile rotates on a daily basis and five rotations are kept before expiring. [code] [root@proxysql ~]# cat /etc/logrotate.d/proxysql /var/lib/proxysql/proxysql.log { missingok daily notifempty compress create 0600 root root rotate 5 } [/code]
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! [code] [root@proxysql ~]# 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 ... [/code] 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. [code] [root@proxysql ~]# 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 [/code] 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. [code] [root@proxysql ~]# 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 [/code] 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. [code] [root@proxysql ~]# 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) ... [/code] 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. [code] [root@proxysql ~]# 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) [root@proxysql ~]# 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 [root@proxysql ~]# 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 [/code]
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" [code] [root@proxysql ~]# mysql -h 127.0.0.1 -P 6032 -uadmin -padmin ... mysql> PROXYSQL FLUSH LOGS; Query OK, 0 rows affected (0.00 sec) [/code] 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! [code] [root@proxysql ~]# 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 ... [root@proxysql ~]# 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 [root@proxysql ~]# 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 [/code]
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. [code] [root@proxysql ~]# mysql --defaults-file=/etc/proxysql.my.cnf --execute="PROXYSQL FLUSH LOGS" [root@proxysql ~]# cat /etc/proxysql.my.cnf [client] host = 127.0.0.1 port = 6032 user = admin password = admin [root@proxysql ~]# mysql_config_editor set --login-path=proxysql-admin --host=127.0.0.1 --port=6032 --user=admin -p Enter password: [root@proxysql ~]# mysql_config_editor print --login-path=proxysql-admin [proxysql-admin] user = admin password = ***** host = 127.0.0.1 port = 6032 [root@proxysql ~]# mysql --login-path=proxysql-admin --execute="PROXYSQL FLUSH LOGS;" [/code] We can put this command in the postrotate section of the logrotate configuration to execute after rotation but before the compression phase. [code] [root@proxysql ~]# 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 } [/code] Let's test to see if it works. [code] [root@proxysql ~]# 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 [root@proxysql ~]# 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 [root@proxysql ~]# 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 [/code]
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.
Matthias has been passionate about computers since the age of 10. He has been working with them ever since. Currently he's a Principal Consultant at Pythian where he's is providing technical thought-leadership for the Open Source Databases team. Together with the team he works to provide the best possible service to the customers.
