Upstart never closes /var/log/upstart/mysql.log

[Will Crawford]

I ran "init u" after noticing a lingering FD to a log file that lsof showed as "(deleted)". However because the file handle is never closed, and the log files get logrotate'd it keeps happening, like so:

init 1 root 11w REG 252,0 3532 394558 /var/log/upstart/mysql.log.1 (deleted)

It's possible this might be fixed by a version update, as I noticed there were closed bugs relating to "leaked" file descriptors?

[Will Crawford (billcrawford1970)]

I can't see where to specify that this is in Precise?

[Steve Langasek (vorlon)]

Why are you expecting upstart to close this file? There is no logrotate integration for /var/log/upstart log files in the Ubuntu package; if you've added logrotate rules that rotate logfiles without restarting the associated services, this seems to be the expected behavior.

Now, we probably do want to integrate logrotate with upstart; but this is clearly not the way to do it. We probably need a new initctl interface to ask upstart to reopen log files for individual jobs without restarting the actual job processes.

[Will Crawford (billcrawford1970)]

 · Because upstart opened it.
 · Because it has closed all the others in /var/log/upstart except that one.
 · Which makes it look like there's some reason this particular one is "special".
 · I haven't added anything to anything.
 · ... sure, it's probably an issue that whatever is rotating the logs needs to restart init, but _why_ is the file descriptor still open, when the mysql service has been up for more than two days?
 · This could, for all I know, be a bug in the mysql service config file. I'm just reporting the oddity that this one log file seems to have been left open.

[Will Crawford (billcrawford1970)]

I suspect this is more likely some artifact of how the /etc/init/mysql.conf service file is written, but I have no idea how to go about debugging this ...

[Steve Langasek (vorlon)]

So apparently I was quite badly mistaken; not only does upstart integrate with logrotate, I seem to have added the support for that to the package myself.

Anyway, yes, we don't want upstart to still be logging to deleted files; so either upstart needs to detect that the file has been moved/deleted and reopen its log (which rings a bell with me - maybe this is how it's supposed to work), or it needs to be sent a signal by the logrotate rule telling it to reopen the logs on a per-service basis.

[TJ (tj)]

I suspect I've just hit this issue while working within a chroot.

After a suspend/resume cycle the external device hosting the file-systems mounted in the chroot are generating kernel read errors.

One file-system could not be umount-ed because a file was in use:

$ sudo ls -l /proc/1/fd/ | grep target
l-wx------ 1 root root 64 Feb 10 14:42 13 -> /target/var/log/upstart/ureadahead-other.log

The job was stopped but the file remained open:

$ initctl status ureadahead-other
ureadahead-other start/killed, process 803

$ ps -efly | grep 803
S tj 1058 2828 0 80 0 940 2361 pipe_w 15:59 pts/4 00:00:00 grep --color=auto 803

$ sudo initctl start
## hangs indefinitely and needs Ctrl+C to exit

[Dominic Raferd (dominic-timedicer)]

I confirm this problem in ubuntu 14.04:
$ sudo lsof|grep deleted|grep -Ev "/(dev|tmp|run)"
init 1 root 10w REG 252,4 778 131190 /var/log/upstart/mysql.log.1 (deleted)

An effect (and how I noticed it) is that when I take LVM snapshot of the underlying volume I get warning messages in dmesg:
$ dmesg -T
...
[Fri Mar 6 06:02:19 2015] bio: create slab <bio-1> at 1
[Fri Mar 6 06:02:19 2015] EXT4-fs (dm-6): 1 orphan inode deleted
[Fri Mar 6 06:02:19 2015] EXT4-fs (dm-6): recovery complete
...

So the orphan inode in the snapshot (i.e. dm-6) gets deleted but it remains in the underlying volume.

[Dominic Raferd (dominic-timedicer)]

oops, looks like I spoke too soon. The report from dmesg mentioned in my previous comment has gone away on reboot. I believe the cause may have been a fault in my /etc/rc.local file, which may not have been completing. This is fixed now.