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

Bug #1130611 reported by Will Crawford
10
This bug affects 1 person
Affects Status Importance Assigned to Milestone
upstart (Ubuntu)
New
Undecided
Unassigned

Bug Description

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?

Revision history for this message
Will Crawford (billcrawford1970) wrote :

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

affects: upstart → upstart (Ubuntu)
Revision history for this message
Steve Langasek (vorlon) wrote :

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.

Revision history for this message
Will Crawford (billcrawford1970) wrote :

 · 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.

Revision history for this message
Will Crawford (billcrawford1970) wrote :

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 ...

Revision history for this message
Steve Langasek (vorlon) wrote :

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.

Revision history for this message
TJ (tj) wrote :

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

Revision history for this message
Dominic Raferd (dominic-timedicer) wrote :

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.

Revision history for this message
Dominic Raferd (dominic-timedicer) wrote :

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.

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.