Upstart does not reopen /var/log/upstart/* logfiles upon log rotation

[lanzz]

Note: this issue is reported from a 12.04 system, but I've confirmed the same behavior on a 14.04 system.

Logrotate configuration for Upstart logs has no postrotate action:

/var/log/upstart/*.log {
        daily
        missingok
        rotate 7
        compress
        notifempty
 nocreate
}

As a result, when logs are rotated, upstart keeps open handles on deleted log files instead of reopening the new log files:

# lsof -p1 | fgrep /var/log/upstart
. . .
init 1 root 8w REG 253,1 62 789436 /var/log/upstart/dbus.log.1 (deleted)
. . .

From this point on, all subsequent log messages are lost, delivered into a deleted file.

I could not find a way to get the upstart init process to reopen its log files, short of restarting _all_ services that log to /var/log/upstart/*.log files, which does not seem like a good solution at all.

ProblemType: Bug
DistroRelease: Ubuntu 12.04
Package: upstart 1.5-0ubuntu7.2
ProcVersionSignature: Ubuntu 3.2.0-60.91-generic 3.2.55
Uname: Linux 3.2.0-60-generic x86_64
ApportVersion: 2.0.1-0ubuntu17.6
Architecture: amd64
Date: Thu Jul 31 10:43:25 2014
InstallationMedia: Ubuntu-Server 10.04.4 LTS "Lucid Lynx" - Release amd64 (20120214.2)
MarkForUpload: True
ProcEnviron:
 LC_CTYPE=en_US.UTF-8
 TERM=xterm-256color
 PATH=(custom, no user)
 LANG=en_GB.UTF-8
 SHELL=/bin/bash
SourcePackage: upstart
UpgradeStatus: Upgraded to precise on 2013-10-23 (280 days ago)

[James Hunt (jamesodhunt)]

This is incorrect - Upstart does reopen log files when a job produces output *after* the log file has been deleted.

So in normal operation, logrotate will run and say rotate foo.log to foo.log.1.gz. At this point, the file associated with the fd for foo.log will indeed show as deleted. But, if and only if that job produces any further output Upstart will recreate foo.log. If the job produces no further output the log will not be recreated. Once the job has stopped, the fd associated with the deleted file will be closed.

If this is not what you are seeing please provide further details.

[Daniel Snider (daniel-snider)]

I'm seeing this issue as well.

We currently use pserve with the "console" log handler [1]. This console output should be redirected to /var/log/upstart/foo.log but it isn't after the log is rotated. We are logging every second (see example log statement[2]) but the logging stops after I force a logrotation with "logrotate -v -f /etc/logrotate.d/upstart". Even with the logrotate directive "create" no new logs are written.

[1] http://docs.pylonsproject.org/docs/pyramid/en/latest/narr/logging.html
[2] [pid: 3378209|app: 0|req: 4/4] 10.35.20.2 () {28 vars in 344 bytes} [Thu Mar 12 20:58:30 2015] GET /nc/v1/nodes => generated 4174 bytes in 6 msecs (HTTP/1.0 200) 2 headers in 88 bytes (1 switches on core 3)

[Daniel Snider (daniel-snider)]

NVM. I've tracked my problem down to something else. Sorry!

[Daniel Snider (daniel-snider)]

I wasn't actually logging to stdout/console.

[Arthur O'Dwyer (arthur-j-odwyer)]

I'm seeing basically the same symptom: /etc/logrotate.d/upstart contains "compress" without "delaycompress", which means that logrotate attempts to compress /var/log/upstart/*.log while Upstart is still writing to those files. The result is "gzip: stdin: file size changed while zipping". I believe that at least PART of the appropriate solution is to add "delaycompress" and/or "copytruncate" to /etc/logrotate.d/upstart; however, logrotate might also need to notify Upstart that the file has moved via SIGHUP or some such.

I'm using Ubuntu 14.04.2 LTS.

I do not see the same bug on Ubuntu 12.04.5 LTS; however, I also do not see /lib/systemd/systemd-logind in the output of "ps aux", and I believe that's the particular Upstart service which is trying to log during the gzip.

[Vahid Mardani (vahid-mardani)]

Useful thread

[Andrew Bogott (andrewbogott)]

I'm seeing this issue as well. The logrotate script either needs a delaycompress or there needs to be a postrotate action.

[Antonio Messina (arcimboldo)]

We have the same issue. Using "delaycompress" suppresses the "gzip: stdin: file size changed while zipping" error but upstart will continue to write on .1 file until this is actually gzipped, which is quite annoying.

[Walter (wdoekes)]

A google search turned up this as the most likely candidate for my logrotate+gzip issues.

I'm going to try this for a workaround:

/var/log/upstart/*.log {
        daily
        missingok
        rotate 7
        compress
        notifempty
        nocreate

# Added by wjd 2017-03 for launchpad bug #1350782
        delaycompress
        sharedscripts
        postrotate
                lsof | awk '/ \/var\/log\/upstart\/.*\.log.+/{print $9}' | sed -e 's#.*/##;s#\..*##' | xargs -IX service X restart >/dev/null
        endscript
}

[Михаїл Т. (mi+launchpad)]

> awk | sed

As a general rule, you never need more than a single of awk, sed, grep, cut in the same pipeline. Also, xargs (on Linux) would generate a silly error-message (which cron will dutifully e-mail to you), if no matching open files were found. The improved (and less prone to race-conditions) expression for the same would be:

postrotate
         lsof | awk '
                  $9 ~ /^\/var\/log\/upstart\/.*\.log.+/ {
                           service = gensub("^.*/(.*).log.*", "\\1", $9);
                           system("service " service " restart")
                  }
         '
endscript

But, you only need lsof if you insist on sharedscripts (which is not in there in the default file installed by the upstart package).

If you do NOT add the sharedscripts-verb, you can bypass the entire lsof part, because the full path of the log being rotated will be passed to the postrotate-script as the first argument:

postrotate
         service=${1##*/}
         service=${service%.log*}
         service $service restart
endscript

You can also insert special handling for some of the services easier this way, for example:

         case $service in
         fpm*)
                 exit 0
                 ;;
         .....
         esac