[feisty] cupsd leaking file descriptors

Binary package hint: cupsys

Just recently I upgraded from edgy to feisty. On my first attempt to print something, e.g. a screen shapshot with ksnapshot, I got this error:

----------------------------------------
A print error occurred. Error message received from system:

cupsdoprint -P 'dj3650_lokal' -J '' -H '/var/run/cups/cups.sock:631' -U 'mstreibe' -o ' copies=1 multiple-document-handling=separate-documents-collated-copies orientation-requested=3' '/tmp/kde-mstreibe/kdeprint_tWCY4exm' : execution failed with message:

client-error-request-value-too-long
----------------------------------------

The reason for this appears to be that cupsd has run out of file descriptors, as lsof shows:

root@mario:~ # lsof -p 1067
COMMAND PID USER FD TYPE DEVICE SIZE NODE NAME
   :
cupsd 1067 cupsys 0r CHR 1,9 3994 /dev/urandom
cupsd 1067 cupsys 1u IPv4 385377 TCP localhost:ipp (LISTEN)
cupsd 1067 cupsys 2u unix 0xd5e3c040 385378 /var/run/cups/cups.sock
cupsd 1067 cupsys 3r FIFO 0,6 385380 pipe
cupsd 1067 cupsys 4w FIFO 0,6 385380 pipe
cupsd 1067 cupsys 5r FIFO 0,6 385382 pipe
cupsd 1067 cupsys 6r FIFO 0,6 385389 pipe
   :
cupsd 1067 cupsys 1020r FIFO 0,6 579798 pipe
cupsd 1067 cupsys 1021r FIFO 0,6 579801 pipe
cupsd 1067 cupsys 1022r FIFO 0,6 579808 pipe
root@mario:~ # strace -fp 1067
Process 1067 attached - interrupt to quit
select(1024, [1 2 3 8], [], NULL, {6, 200000}) = 1 (in [8], left {3, 996000})
time(NULL) = 1180034409
read(8, "INFO: Connecting to 192.168.1.33"..., 1023) = 119
getuid32() = 105
open("/var/lib/dbus/machine-id", O_RDONLY) = 1023
fstat64(1023, {st_mode=S_IFREG|0644, st_size=33, ...}) = 0
read(1023, "444f869f6c3f6f0159c52200464c02b9"..., 33) = 33
close(1023) = 0
pipe(0xbfdb8940) = -1 EMFILE (Too many open files) <<<<<<
time(NULL) = 1180034409
select(1024, [1 2 3 8], [], NULL, {1, 0}) = 0 (Timeout)
root@mario:~ #

After restarting cups, I can print again, at least for a while, until cupsd has run out of file descriptors again.

cups version:

root@mario:~ # dpkg -l | grep cupsys
ii cupsys 1.2.8-0ubuntu8 Common UNIX Printing System(tm) - server
ii cupsys-bsd 1.2.8-0ubuntu8 Common UNIX Printing System(tm) - BSD comman
ii cupsys-client 1.2.8-0ubuntu8 Common UNIX Printing System(tm) - client pro
ii cupsys-common 1.2.8-0ubuntu8 Common UNIX Printing System(tm) - common fil
ii cupsys-driver-gutenprint 5.0.0.99.1-0ubuntu2 printer drivers for CUPS
ii libcupsys2 1.2.8-0ubuntu8 Common UNIX Printing System(tm) - libs
root@mario:~ #

A syscall trace revealed that the file descriptor is leaked from a pipe to dbus-launch, which is frequently forked from cupsd:

root@mario:~ # ps -ef | grep cupsd
cupsys 2621 1 0 21:22 ? 00:00:00 /usr/sbin/cupsd
root@mario:~ # strace -fp 2621
Process 2621 attached - interrupt to quit
select(1024, [1 2 3 8], [], NULL, {9, 476000}) = 1 (in [8], left {4, 32000})
time(NULL) = 1180034580
read(8, "INFO: Connecting to 192.168.1.33"..., 1023) = 119
getuid32() = 105
open("/var/lib/dbus/machine-id", O_RDONLY) = 11
fstat64(11, {st_mode=S_IFREG|0644, st_size=33, ...}) = 0
read(11, "444f869f6c3f6f0159c52200464c02b9"..., 33) = 33
close(11) = 0
pipe([11, 12]) = 0 <<<<<<<<<<<
clone(Process 2640 attached
child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb7b62708) = 2640
[pid 2621] close(12) = 0 <<<<<<<<<<<
[pid 2621] read(11, <unfinished ...>
   :
[pid 2640] execve("/usr/bin/dbus-launch", ["dbus-launch", "--autolaunch", "444f869f6c3f6f0159c52200464c0200"..., "--binary-syntax"], [/* 17 vars */]) = 0
   :
pid 2640] write(2, "Autolaunch error: X11 initializa"..., 45) = 45
[pid 2640] exit_group(1) = ?
Process 2640 detached
<... read resumed> "", 1024) = 0
--- SIGCHLD (Child exited) @ 0 (0) ---
sigreturn() = ? (mask now [])
waitpid(2640, [{WIFEXITED(s) && WEXITSTATUS(s) == 1}], 0) = 2640
time(NULL) = 1180034580
waitpid(-1, 0xbfffb664, WNOHANG) = 0
select(1024, [1 2 3 8], [], NULL, {1, 0}) = 0 (Timeout)

I don't know what this Autolaunch error from dbus-launch means, may be related. The IP 192.168.1.33 is the local host, where a local printer is connected.

However, cupsd opens a pipe for dbus-launch, which in the above trace returns fd's 11 and 12. fd 12 is closed right after forking, but fd 11 is not closed at all. So with each invokation of dbus-launch (which occurs 2x every 30 sec), cupsd leaks one file descriptor. This happens without sending any print requests.