Ubuntu 16.04 xenial does not rotate nginx and rsyslog logfiles

Written by Claudio Kuenzler - 1 comments

Published on October 10th 2016 - Listed in Linux Nginx

---

I was investigating a curious case when I got a diskspace alert on a Ubuntu 16.04 container running nginx. As you can see in the graphic, the disk usage increased without interruption:

The usage could be pinned down to the nginx log files or log files in general. It turned out they haven't been rotated for quite some time:

root@xenial:~# ls -ltr /var/log/nginx/
total 83756
-rw-r--r-- 1 root     root      184 Jun  6 08:49 error.log.3.gz
-rw-r--r-- 1 root     root   671461 Jun  6 09:03 access.log.6.gz
-rw-r----- 1 www-data adm       459 Jun  6 09:39 error.log.2.gz
-rw-r--r-- 1 root     root      293 Jun  6 10:55 monitoring.error.log.4.gz
-rw-r----- 1 www-data adm     15756 Jun  8 10:02 access.log.5.gz
-rw-r----- 1 www-data adm      1115 Jul  8 12:00 monitoring.error.log.3.gz
-rw-r----- 1 www-data adm   1335195 Jul  8 12:00 access.log.4.gz
-rw-r----- 1 www-data adm      2734 Jul  8 12:46 monitoring.error.log.2.gz
-rw-r----- 1 www-data adm    782316 Jul 26 16:11 access.log.3.gz
-rw-r----- 1 www-data adm    318759 Aug  4 15:05 access.log.2.gz
-rw-r----- 1 www-data adm        65 Aug  4 15:06 error.log.1
-rw-r----- 1 www-data adm         0 Aug  5 06:32 error.log
-rw-r----- 1 www-data adm         0 Aug  5 06:32 access.log
-rw-r----- 1 www-data adm         0 Aug 16 06:51 monitoring.error.log
-rw-r----- 1 www-data adm      9964 Sep  8 16:14 monitoring.error.log.1
-rw-r----- 1 www-data adm  82599120 Oct 10 12:43 access.log.1

Seems to be a logrotate problem because nginx is still logging into the already rotated access.log.1 file.
And a manual enforcing of log rotation doesn't work, because logrotate only wants to rotate log files within /var/log/nginx which end with .log as extension. Yet these files didn't move and are empty - so no log rotation happens here:

root@xenial:~# logrotate -d -f /etc/logrotate.d/nginx
reading config file /etc/logrotate.d/nginx

Handling 1 logs

rotating pattern: /var/log/nginx/*.log  forced from command line (14 rotations)
empty log files are not rotated, old logs are removed
considering log /var/log/nginx/access.log
  log does not need rotating
considering log /var/log/nginx/error.log
  log does not need rotating
considering log /var/log/nginx/monitoring.error.log
  log does not need rotating
not running prerotate script, since no logs will be rotated
not running postrotate script, since no logs were rotated

I checked the logrotate config file for nginx and compared it to the same logrotate file from Ubuntu 14.04 (trusty).
Interestingly there is indeed a difference!

On Ubuntu 16.04 Xenial:

root@xenial:~# cat /etc/logrotate.d/nginx
/var/log/nginx/*.log {
    daily
    missingok
    rotate 14
    compress
    delaycompress
    notifempty
    create 0640 www-data adm
    sharedscripts
    prerotate
        if [ -d /etc/logrotate.d/httpd-prerotate ]; then \
            run-parts /etc/logrotate.d/httpd-prerotate; \
        fi \
    endscript
    postrotate
        invoke-rc.d nginx rotate >/dev/null 2>&1
    endscript
}

And on Ubuntu 14.04 Trusty:

admck@trusty:~$ cat /etc/logrotate.d/nginx
/var/log/nginx/*.log {
    weekly
    missingok
    rotate 52
    compress
    delaycompress
    notifempty
    create 0640 www-data adm
    sharedscripts
    prerotate
        if [ -d /etc/logrotate.d/httpd-prerotate ]; then \
            run-parts /etc/logrotate.d/httpd-prerotate; \
        fi \
    endscript
    postrotate
        [ -s /run/nginx.pid ] && kill -USR1 `cat /run/nginx.pid`
    endscript
}

Take a closer look at the postrotate script. That's the part from logrotate to tell the application (nginx in this case) that the logfiles were rotated and that the previous file handler needs to be closed/renewed.

A manual launch of the postrotate command on the Xenial server shows that this command actually doesn't work at all:

root@xenial:~# invoke-rc.d nginx rotate
initctl: invalid command: rotate
Try `initctl --help' for more information.
invoke-rc.d: initscript nginx, action "rotate" failed.

I adapted the postrotate section in /etc/logrotate.d/nginx on the Ubuntu 16.04 container to this:

    postrotate
        #invoke-rc.d nginx rotate >/dev/null 2>&1
        [ -s /run/nginx.pid ] && kill -USR1 `cat /run/nginx.pid`
    endscript

By the way: When sending a USR1 signal to the nginx process, this will tell nginx to re-open the log files. From http://nginx.org/en/docs/control.html:

TERM, INT    fast shutdown
QUIT    graceful shutdown
HUP    changing configuration, keeping up with a changed time zone (only for FreeBSD and Linux), starting new worker processes with a new configuration, graceful shutdown of old worker processes
USR1    re-opening log files
USR2    upgrading an executable file
WINCH    graceful shutdown of worker processes

I manually sent a the same command as in the logrotate file to nginx but nothing happened:

root@xenial:~# [ -s /run/nginx.pid ] && kill -USR1 `cat /run/nginx.pid`

Only a manual kill worked:

root@xenial:~# kill -USR1 30441

root@xenial:~# ls -ltr /var/log/nginx/
total 83776
-rw-r--r-- 1 root     root      184 Jun  6 08:49 error.log.3.gz
-rw-r--r-- 1 root     root   671461 Jun  6 09:03 access.log.6.gz
-rw-r----- 1 www-data adm       459 Jun  6 09:39 error.log.2.gz
-rw-r--r-- 1 root     root      293 Jun  6 10:55 monitoring.error.log.4.gz
-rw-r----- 1 www-data adm     15756 Jun  8 10:02 access.log.5.gz
-rw-r----- 1 www-data adm      1115 Jul  8 12:00 monitoring.error.log.3.gz
-rw-r----- 1 www-data adm   1335195 Jul  8 12:00 access.log.4.gz
-rw-r----- 1 www-data adm      2734 Jul  8 12:46 monitoring.error.log.2.gz
-rw-r----- 1 www-data adm    782316 Jul 26 16:11 access.log.3.gz
-rw-r----- 1 www-data adm    318759 Aug  4 15:05 access.log.2.gz
-rw-r----- 1 www-data adm        65 Aug  4 15:06 error.log.1
-rw-r----- 1 www-data adm         0 Aug  5 06:32 error.log
-rw-r----- 1 www-data adm         0 Aug 16 06:51 monitoring.error.log
-rw-r----- 1 www-data adm      9964 Sep  8 16:14 monitoring.error.log.1
-rw-r----- 1 www-data adm  82614202 Oct 10 13:01 access.log.1
-rw-r----- 1 www-data adm      1676 Oct 10 13:03 access.log

After a lot of tries, I finally figured out that whatever I put into the postrotate section, nothing was actually executed.
Even a basic service nginx reload wasn't executed:

    postrotate
          service nginx reload
    endscript

I also tested a simple echo output into a file, and this didn't work either:

    postrotate
          echo "bla" > /tmp/bla
    endscript

Now I got two problems instead of one:
1) The original postrotate command which comes from the nginx package in Ubuntu 16.04 is wrong
2) postrotate isn't executed at all it seems

To verify 2) I also checked the "normal" rsyslog logfiles in /var/log and - oh dear - same problem there:

root@xenial:~# ls -ltr /var/log/ | tail -n 3
-rw-rw-r-- 1 root     utmp       292876 Oct 10 12:38 lastlog
-rw-r----- 1 syslog   adm      17691756 Oct 10 13:49 auth.log.1
-rw-r----- 1 syslog   adm       3044902 Oct 10 13:49 syslog.1

Here it's actually the same problem again: postrotate wants to use rc-invoke with the command "rotate" which doesn't exist:

root@xenial:~# cat /etc/logrotate.d/rsyslog | grep -A 2 postrotate
    postrotate
        invoke-rc.d rsyslog rotate > /dev/null
    endscript
--
    postrotate
        invoke-rc.d rsyslog rotate > /dev/null
    endscript

But even after a modification to "restart" instead of "rotate" resulted in the same problem again: postrotate was not executed, when I forced a new log rotation.
So there seems to be a general problem with logrotate in Ubuntu 16.04 xenial :( .
After further research I stumbled across the Debian bug report 734688 which sounds very familiar. It seems that this problem already exists in logrotate for a long time (January 2014) and hasn't been resolved yet.
Several comments confirm the bug still exists in Debian Jessie (on which Ubuntu 16.04 Xenial is based upon). On the Ubuntu side I came across Launchpad bug #1450770 which so far seems to be the closest description to today's discovered logrotate problem.

At the moment I don't know what the best fix (besides an official patch) would be. A workaround would be to disable logrotate completely and do log rotation with cron jobs - but I will go crazy modifying and maintaining the cronjobs.

Update October 11 2016:
Sometimes it's worth to sleep a night over a problem. This morning I saw, that nginx log files were rotated correctly. What did I change? I have set the postrotate command to "service nginx reload" yesterday evening and this morning the logs were rotated:

     postrotate
          service nginx reload
    endscript

root@xenial:~# ls -ltr /var/log/nginx/
total 6296
-rw-r--r-- 1 root     root     184 Jun  6 08:49 error.log.3.gz
-rw-r--r-- 1 root     root  671461 Jun  6 09:03 access.log.7.gz
-rw-r----- 1 www-data adm      459 Jun  6 09:39 error.log.2.gz
-rw-r--r-- 1 root     root     293 Jun  6 10:55 monitoring.error.log.4.gz
-rw-r----- 1 www-data adm    15756 Jun  8 10:02 access.log.6.gz
-rw-r----- 1 www-data adm     1115 Jul  8 12:00 monitoring.error.log.3.gz
-rw-r----- 1 www-data adm  1335195 Jul  8 12:00 access.log.5.gz
-rw-r----- 1 www-data adm     2734 Jul  8 12:46 monitoring.error.log.2.gz
-rw-r----- 1 www-data adm   782316 Jul 26 16:11 access.log.4.gz
-rw-r----- 1 www-data adm   318759 Aug  4 15:05 access.log.3.gz
-rw-r----- 1 www-data adm       65 Aug  4 15:06 error.log.1
-rw-r----- 1 www-data adm        0 Aug  5 06:32 error.log
-rw-r----- 1 www-data adm        0 Aug 16 06:51 monitoring.error.log
-rw-r----- 1 www-data adm     9964 Sep  8 16:14 monitoring.error.log.1
-rw-r----- 1 www-data adm  2299587 Oct 10 13:01 access.log.2.gz
-rw-r----- 1 www-data adm   919857 Oct 11 06:50 access.log.1
-rw-r----- 1 www-data adm    52125 Oct 11 07:52 access.log

So the postrotate scripts run after all. Phew!

But until Ubuntu bugs #940030 (for rsyslog) and #1450770 (for nginx) are fixed, you will have to manually fix the logrotate files and remove the "invoke-rc.d daemon rotate" command with something actually working.

Add a comment

Show form to leave a comment

Comments (newest first)

Ben Curtiss from wrote on Oct 9th, 2019:

I actually found that `invoke-rc.d nginx rotate` didn't work in my case because I had made edits to /etc/init.d/nginx on trusty, and when the nginx-common package was updated during the xenial upgrade, the /etc/init.d/nginx file provided by the xenial package did not replace my manually edited version (because its technically a configuration file).

You can see here that the xenial version of /etc/init.d/nginx included in nginx-common indeed defines a rotate command, and the logrotate.d post-rotate script references this command:

- Xenial nginx /etc/init.d/nginx file: https://git.launchpad.net/ubuntu/+source/nginx/tree/debian/nginx-common.nginx.init?h=applied/ubuntu/xenial-updates#n187
- Xenial nginx /etc/logrotate.d/nginx file: https://git.launchpad.net/ubuntu/+source/nginx/tree/debian/nginx-common.nginx.logrotate?h=applied/ubuntu/xenial-updates#n16

---