MASTER [Feisty] cupsd leaking file descriptors (was: Multiple jobs are not printed)

[cubells]

When I send more than one job to printer, only the first job is printed.
Then I have to restart cupsys in order to be able to print the rest of jobs.

It is a simple solution but it could be a annoying solution for a new gnu/linux user.

I have a 116 Mb error_log file with a lot of lines like this:
E [06/May/2007:10:43:18 +0200] Unable to accept client connection - Too many open files.

My system: Feisty
My printer: Epson Sytlus Color 600
Cupsys: 1.2.8-0ubuntu8

[Pekka Jääskeläinen (pekka-jaaskelainen)]

I'm seeing a similar bug after upgrade to Feisty. Seems like quite nasty regression.

[misan (misan)]

Seems like Bug #113060 in cupsys (dupe)

[misan (misan)]

I was asked to provide the output of lsof when the problem happened to me.

[Alan (alanrr-sr-yahoo)]

Same here, and after some time
lsof below... var directory has been filled by the log

[Alan (alanrr-sr-yahoo)]

Sorry, forgot details

Ubuntu feisty, 64 bits, up to date (17/May/07)
Printer: Epson Stylus Color CX4100 (in Brazil) usb

[misan (misan)]

Hi,

I'm including the output of my error_log once the problem is happening (now with the debug2 option activated). It goes over and over like the lines below till the harddisk is full (not funny):

d [22/May/2007:15:40:35 +0200] is_cgi: Returning 0...
D [22/May/2007:15:40:35 +0200] write_file: 1023 file=-1
D [22/May/2007:15:40:35 +0200] cupsdCloseClient: 1023
d [22/May/2007:15:40:35 +0200] cupsdCloseClient: Removing fd 1023 from InputSet and OutputSet...
d [22/May/2007:15:40:35 +0200] cupsdAcceptClient(lis=0x80a3758) 2 Clients = 1
D [22/May/2007:15:40:35 +0200] cupsdAcceptClient: 1023 from localhost:631 (IPv4)
d [22/May/2007:15:40:35 +0200] cupsdAcceptClient: 1023 connected to server on 127.0.0.1:631
d [22/May/2007:15:40:35 +0200] cupsdAcceptClient: Adding fd 1023 to InputSet...
d [22/May/2007:15:40:35 +0200] cupsdAcceptClient(lis=0x80a3758) 2 Clients = 2
E [22/May/2007:15:40:35 +0200] Unable to accept client connection - Too many open files.
d [22/May/2007:15:40:35 +0200] cupsdReadClient: 1023, used=0, file=-1 state=0
D [22/May/2007:15:40:35 +0200] cupsdReadClient: 1023 GET /printers/Business-Inkjet-2600.ppd HTTP/1.1
d [22/May/2007:15:40:35 +0200] cupsdFindBest: uri = "/printers/Business-Inkjet-2600"...
d [22/May/2007:15:40:35 +0200] cupsdFindBest: Location CUPS_INTERNAL_BROWSE_ACL Limit 0
d [22/May/2007:15:40:35 +0200] cupsdFindBest: Location /admin/conf Limit 7f
d [22/May/2007:15:40:35 +0200] cupsdFindBest: Location /admin Limit 7f
d [22/May/2007:15:40:35 +0200] cupsdFindBest: Location / Limit 7f
d [22/May/2007:15:40:35 +0200] cupsdFindBest: best = /
d [22/May/2007:15:40:35 +0200] cupsdAuthorize: con->uri="/printers/Business-Inkjet-2600.ppd", con->best=0x80a3b68(/)
d [22/May/2007:15:40:35 +0200] cupsdAuthorize: Authorization=""
D [22/May/2007:15:40:35 +0200] cupsdAuthorize: No authentication data provided.
d [22/May/2007:15:40:35 +0200] cupsdIsAuthorized: con->uri="/printers/Business-Inkjet-2600.ppd", con->best=0x80a3b68(/)
d [22/May/2007:15:40:35 +0200] cupsdIsAuthorized: level=AUTH_ANON, type=AUTH_NONE, satisfy=AUTH_SATISFY_ALL, num_names=0
d [22/May/2007:15:40:35 +0200] cupsdIsAuthorized: auth=AUTH_ALLOW...
d [22/May/2007:15:40:35 +0200] get_file: 1023 filename=/etc/cups/ppd/Business-Inkjet-2600.ppd size=47078
d [22/May/2007:15:40:35 +0200] is_cgi(con=0x814a5c0, filename="/etc/cups/ppd/Business-Inkjet-2600.ppd", filestats=0xbfeca7a8, type=unknown/unknown)
d [22/May/2007:15:40:35 +0200] is_cgi: Returning 0...
D [22/May/2007:15:40:35 +0200] write_file: 1023 file=-1
D [22/May/2007:15:40:35 +0200] cupsdCloseClient: 1023
d [22/May/2007:15:40:35 +0200] cupsdCloseClient: Removing fd 1023 from InputSet and OutputSet...
d [22/May/2007:15:40:35 +0200] cupsdAcceptClient(lis=0x80a3758) 2 Clients = 1
D [22/May/2007:15:40:35 +0200] cupsdAcceptClient: 1023 from localhost:631 (IPv4)
d [22/May/2007:15:40:35 +0200] cupsdAcceptClient: 1023 connected to server on 127.0.0.1:631
d [22/May/2007:15:40:35 +0200] cupsdAcceptClient: Adding fd 1023 to InputSet...
d [22/May/2007:15:40:35 +0200] cupsdAcceptClient(lis=0x80a3758) 2 Clients = 2
E [22/May/2007:15:40:35 +0200] Unable to accept client connection - Too many open files.
d [22/May/2007:15:40:35 +0200] cupsd...

[Till Kamppeter (till-kamppeter)]

Can you run

sudo lsof -p `pidof cupsd`

and post the output.

[misan (misan)]

Sorry, I can't do this now as I restarted cupsys once the problem hit me,
but I'll do next time it strike me.

On 5/22/07, Till Kamppeter <email address hidden> wrote:
>
> Can you run
>
> sudo lsof -p `pidof cupsd`
>
> and post the output.
>
> --
> Multiple jobs are not printed
> https://bugs.launchpad.net/bugs/112803
> You received this bug notification because you are a direct subscriber
> of a duplicate bug.
>

[misan (misan)]

Here you have the output requested (as it failed again).

On 5/22/07, Till Kamppeter <email address hidden> wrote:
>
> Can you run
>
> sudo lsof -p `pidof cupsd`
>
> and post the output.
>
> --
> Multiple jobs are not printed
> https://bugs.launchpad.net/bugs/112803
> You received this bug notification because you are a direct subscriber
> of a duplicate bug.
>

[MauricioZ (mauricio-zunino)]

Hi,

my name is Mauricio and i would like join with you the problem that i haven too. The problem is that cupsys open to many files when there are more than one work in the queue ), that we know, why don´t close is the question. If you send a lot of files to the printer and execute this command "lsof |grep cupsys | wc -l " you see for each file cupsys open others that don´t close, that only resetting cups close the files. I'm so sorry about my languaje, it's because English isn't my first languaje. I wait that you can understand me.

[Till Kamppeter (till-kamppeter)]

Reported upstream:

http://www.cups.org/str.php?L2396

[Till Kamppeter (till-kamppeter)]

Can you try the newest CUPS version by doing the following:

Download the attached files into one directory.
Do

sudo apt-get install build-essential
sudo apt-get build-dep cupsys
dpkg-source -x cupsys_1.2.11-2ubuntu1.dsc
cd cupsys-1.2.11
dpkg-buildpackage -rfakeroot
cd ..
sudo dpkg -i *.deb

and try again. Does this solve your problem.

[cubells (cubells)]

I've installed the newest cups version:

$ sudo aptitude show cupsys
Paquet: cupsys
Estat: instal·lat
Instal·lat automàticament: no
Versió: 1.2.11-2ubuntu1
Prioritat: opcional
Secció: net
Mantenidor: Ubuntu Core Developers <email address hidden>
Mida descomprimit: 8569k
....

and I'll try again...

[cubells (cubells)]

Hi,
I've tried it by sending about ten jobs into my printer queue and it works.

All jobs are printed and I haven't had to restart cupsys.

And I don't get any cups error message. Not even a line.

Thanks!

[misan (misan)]

It was missing from my last post.

[Till Kamppeter (till-kamppeter)]

Thank you, then this bug is fixed in Gutsy.

[maxschulz (max-schulz-deactivatedaccount)]

Does that mean there will be no official cupsys upgrade in feisty?

[Markus Jonskog (omljud)]

In which version is this fixed? I'm using Gutsy and cupsys 1.2.11-2ubuntu1 and have the problem with too many open files and the log getting filled with:
Unable to accept client connection - Too many open files.
Unable to create job status pipes - Too many open files.

It can work fine for a couple of hours, and then suddenly the log file is growing like crazy.

[maxschulz (max-schulz-deactivatedaccount)]

What you see is more probably bug 116673. While it has been marked as a
duplicate of this one, I doubt this is true. I also updated to 1.2.11
(in feisty), but still see the problem.

https://bugs.launchpad.net/ubuntu/+source/cupsys/+bug/116673

[cubells (cubells)]

Markus said:
>>In which version is this fixed? I'm using Gutsy and cupsys 1.2.11-2ubuntu1 and have the problem with too many open files

Cupsys 1.2.11-2ubuntu1 fixed that problem in my Feisty: https://bugs.launchpad.net/ubuntu/+source/cupsys/+bug/112803/comments/17

Now I have no problem with my printer...

[Kirk Steffensen (kirk-steffensen)]

I think that what Till said should read:

sudo apt-get install build-essential fakeroot
sudo apt-get build-dep cupsys
sudo dpkg-source -x cupsys_1.2.11-2ubuntu1.dsc
cd cupsys-1.2.11
sudo dpkg-buildpackage -rfakeroot
cd ..
sudo dpkg -i *.deb

Thanks1

[Sean Clarke (sean-clarke)]

Is there going to be an official backport/fix for Fiesty ?

[Kirk Steffensen (kirk-steffensen)]

I have changed the status of this bug back to "Confirmed" from "Fixed Released" because I'm still seeing it after updating my Feisty to cupsys_1.2.11-2ubuntu1. (Pascal De Vuyst asked in bug 118356 that we put comments in this bug report instead of one of the duplicates, but it doesn't make sense to add confirming comments to a closed bug, so I'm reopening it.)

Last night I upgraded our Edubuntu Feisty server to 1.2.11 per the instructions above. No problems on the compile. But this morning cupsys stopped and began filling /etc/var/cups/error_log as others have reported. I caught it at 11 GB, but past experience says it was on its way to filling the partition.

Here are the first few lines of the cups error_log:

E [07/Jun/2007:11:37:03 +0300] PID 14024 (/usr/lib/cups/filter/pstops) stopped with status 24!
E [07/Jun/2007:11:37:03 +0300] PID 14025 (/usr/lib/cups/backend/lpd) stopped with status 24!
E [07/Jun/2007:11:38:01 +0300] Unable to create job status pipes - Too many open files.
E [07/Jun/2007:11:38:32 +0300] Unable to create job status pipes - Too many open files.
E [07/Jun/2007:11:38:33 +0300] Unable to accept client connection - Too many open files.
E [07/Jun/2007:11:38:33 +0300] Unable to accept client connection - Too many open files.
E [07/Jun/2007:11:38:33 +0300] Unable to accept client connection - Too many open files.
E [07/Jun/2007:11:38:33 +0300] Unable to accept client connection - Too many open files.
E [07/Jun/2007:11:38:33 +0300] Unable to accept client connection - Too many open files.
E [07/Jun/2007:11:38:33 +0300] Unable to accept client connection - Too many open files.

The last line repeats for the rest of the file at several hundred KB per minute.

I forgot to do an lsof while cups was dead. The next time it dies, I will do it. Is there any other information that would be helpful for troubleshooting?

Thanks for looking into this.

[Kirk Steffensen (kirk-steffensen)]

cupsys_1.2.11-2ubuntu1 is currently running. It has opened many FIFO pipes that it has not closed. It hasn't crashed yet, but experience shows that it will soon.

I've attached an output from "lsof -p $(pidof cupsys)". This shows about 700 open pipes. About 50 jobs have been printed since cupsd was restarted.

I'm running two printers, both over the network: HP 1022N and Minolta Pi3500.

Hope this helps. Please let me know any other diagnostics to try.

[cubells (cubells)]

I have not had any problem since I installed cupsys 1.2.11-2ubuntu1 as Till said...

If you need any information about my system to compare, you only have to say it...

[Kirk Steffensen (kirk-steffensen)]

I forgot to say that I'm running the AMD64 kernel. Doesn't seem like it should matter, but you never know.

(As a temporary work-around, I've added a cron job to root's crontab that restarts cupsys every 10 minutes. It works for now, but is not very elegant.)

Thanks.

[Carey (carey)]

I am also experiencing this exact problem. So I followed Kirk's instructions to upgrade to 1.2.11, but just like Kirk, it does not fix the problem for me. The problem persists with cupsys 1.2.11.

$ apt-cache policy cupsys
  Installed: 1.2.11-2ubuntu1

$ tail -f /var/log/cups/error_log
E [09/Jun/2007:16:14:05 +1000] Unable to accept client connection - Too many open files.

[cubells (cubells)]

Now we have a new cups version: 1.2.11-2ubuntu2
http://packages.ubuntu.com/gutsy/net/cupsys

Can you try it??

[Carey (carey)]

How would be the best way to try this new version?

[cubells (cubells)]

Download the gutsy package and install it...

or follow Kirk's instructions with:

http://launchpadlibrarian.net/7950345/cupsys_1.2.11.orig.tar.gz
http://launchpadlibrarian.net/7950346/cupsys_1.2.11-2ubuntu2.diff.gz
http://launchpadlibrarian.net/7950347/cupsys_1.2.11-2ubuntu2.dsc

[Kirk Steffensen (kirk-steffensen)]

Sorry, no joy with cupsys_1.2.11-2ubuntu2...

Compile and install went well again, but then it had the exact same symptoms. It's still spawning about 10 FIFO pipes per job that it never closes.

Flavor: Edubuntu
Version: 7.04
Kernel: AMD64

Thanks for continuing to look into this.

[Blade (johnblade)]

Yes I've had to have cups restart every minute to work on a server. I'm looking into trying to install the previous edgy version for a workaround.

[Blade (johnblade)]

Recompiling Edgy's cupsys 1.2.4 works as a workaround. Was tired of restarting cups servers.

# wget http://launchpadlibrarian.net/4710126/cupsys_1.2.4.orig.tar.gz
# wget http://launchpadlibrarian.net/4710127/cupsys_1.2.4-2ubuntu3.diff.gz
# wget http://launchpadlibrarian.net/4710128/cupsys_1.2.4-2ubuntu3.dsc
# dpkg-source -x cupsys_cupsys_1.2.4-2ubuntu3.dsc
# cd cupsys-1.2.4
# dpkg-buildpackage -rfakeroot
# cd ..
# sudo dpkg -i *.deb

This is a fairly serious error though. Without a workaround it prevents ubuntu 7.10 to be even considered as a printing server.

[Blade (johnblade)]

Recompiling Edgy's cupsys 1.2.4 works as a workaround. Was tired of restarting cups servers.

# wget http://launchpadlibrarian.net/4710126/cupsys_1.2.4.orig.tar.gz
# wget http://launchpadlibrarian.net/4710127/cupsys_1.2.4-2ubuntu3.diff.gz
# wget http://launchpadlibrarian.net/4710128/cupsys_1.2.4-2ubuntu3.dsc
# dpkg-source -x cupsys_cupsys_1.2.4-2ubuntu3.dsc
# cd cupsys-1.2.4
# dpkg-buildpackage -rfakeroot
# cd ..
# sudo dpkg -i *.deb

This is a fairly serious error though. Without a workaround it prevents ubuntu 7.04 to be even considered as a printing server.

[Sebastian Berthold (sleif)]

Hello, the same problem on my cups server:

cups version from feisty and current gutsy

Ubuntu Version: 7.04
Linux 2.6.19-4-server #2 SMP Thu Apr 5 06:07:34 UTC 2007 i686 GNU/Linux (xen domU)

[MauricioZ (mauricio-zunino)]

I tried with cups 1.2.4 as did you say Blade, but it then had the exact same symptoms in my system Feisty (7.04). Cups still crash!

Mauricio

[Markus Jonskog (omljud)]

Same here. Upgraded from edgy to feisty and the problem showed up. Upgraded to cups to 1.2.11. Still problems. Upgraded whole machine to gutsy. No good. Downgraded cups in gutsy to 1.2.4. Still same problem.

[MauricioZ (mauricio-zunino)]

I FOUND THE SOLUTION!!! or at least the way to make that cups work... You have to run in a XTERM (this is important, non in a text console, have to be in a XTERM )..."invoke-rc-d cupys restart". The service "cupsys" have to start in a graphic ambient, for example gnome like i do.. I am using cups 1.2.11 and this is working ... It is not a solucion for this bug, but is a way to make run fine....

Saludos
Mauricio

[diaboflo (ubuntu-diaboflo)]

i upgrade to cupsys_1.2.11 following Kirks instruction but it stops working:

A print error occurred. Error message received from system:

cupsdoprint -P 'FLO_HP_1200' -J 'Haupttext.ps' -H '/var/run/cups/cups.sock:631' -U 'flo' -o ' copies=1 media=A4,Normal,Upper multiple-document-handling=separate-documents-collated-copies sides=one-sided' '/tmp/kde-flo/kdeprint_AoE6TN4W' : execution failed with message:

client-error-request-value-too-long

[Till Kamppeter (till-kamppeter)]

I posted another upstream bug report:

http://www.cups.org/str.php?L2415

Can everyone who has still the file descriptor leaking problem supply his error_log (set "LogLevel" to "debug" in /etc/cups/cupsd.conf and restart CUPS with "/etc/init.d/cupsys restart") and cupsd.conf?

[Kirk Steffensen (kirk-steffensen)]

Till,

Just to clarify, do you only need the error log up to the point where it starts endlessly repeating?

[Till Kamppeter (till-kamppeter)]

Yes, from the repeats include only one and tell what is repeating.

[Till Kamppeter (till-kamppeter)]

Can you please supply everything asked for by Mike Sweet (author of CUPS) in the upostream bug report?

http://www.cups.org/str.php?L2415

[Till Kamppeter (till-kamppeter)]

Pitti, can you check whether this problem can be caused by your non-root patches?

[maxschulz (max-schulz-deactivatedaccount)]

OK here we go. At the moment it looks like the problem only exists when
I boot up the system, on first start of cupsys. After restarting cupsys
it doesn't seem to leak anymore.

At the moment, after 20min uptime, cupsd already has 62 file descriptors
open:

cupsd 6260 cupsys 0r CHR 1,9 3993 /dev/urandom
cupsd 6260 cupsys 1u REG 8,2 6774 130708
/var/log/cups/error_log
cupsd 6260 cupsys 2u IPv4 23369 TCP localhost:ipp
(LISTEN)
cupsd 6260 cupsys 3u unix 0xf78dae40 23370
/var/run/cups/cups.sock
cupsd 6260 cupsys 4r FIFO 0,6 23372 pipe
cupsd 6260 cupsys 5w FIFO 0,6 23372 pipe
[...]
cupsd 6260 cupsys 60r FIFO 0,6 29564 pipe
cupsd 6260 cupsys 61r FIFO 0,6 29747 pipe
cupsd 6260 cupsys 62r FIFO 0,6 29750 pipe

cupsd.conf is attached. My printers.conf:

# Printer configuration file for CUPS v1.2.4
# Written by cupsd on 2007-04-02 13:29
<Printer dj3650>
Info HP DeskJet 3650 hpijs
DeviceURI ipp://192.168.1.33:631/printers/dj3650
State Idle
StateTime 1174661163
Accepting Yes
Shared Yes
JobSheets none none
QuotaPeriod 0
PageLimit 0
KLimit 0
OpPolicy default
ErrorPolicy retry-job
</Printer>
<DefaultPrinter dj3650_lokal>
Info HP Deskjet 3650
Location Büro
DeviceURI hp:/usb/deskjet_3600?serial=TH38K110V16B
State Idle
StateTime 1175513390
Accepting Yes
Shared Yes
JobSheets none none
QuotaPeriod 0
PageLimit 0
KLimit 0
OpPolicy default
ErrorPolicy retry-job
</Printer>

/var/log/cups/error_log looks like this:

D [21/Jun/2007:07:58:02 +0200] Discarding unused printer-state-changed
event...
I [21/Jun/2007:07:58:02 +0200] Saving job cache file
"/var/cache/cups/job.cache"...
I [21/Jun/2007:07:58:02 +0200] Listening to 127.0.0.1:631 (IPv4)
I [21/Jun/2007:07:58:02 +0200] Listening to /var/run/cups/cups.sock (Domain)
I [21/Jun/2007:07:58:02 +0200] Loaded configuration file
"/etc/cups/cupsd.conf"
I [21/Jun/2007:07:58:02 +0200] Using default TempDir of
/var/spool/cups/tmp...
I [21/Jun/2007:07:58:02 +0200] Cleaning out old temporary files in
"/var/spool/cups/tmp"...
I [21/Jun/2007:07:58:02 +0200] Configured for up to 100 clients.
I [21/Jun/2007:07:58:02 +0200] Allowing up to 100 client connections per
host.
I [21/Jun/2007:07:58:02 +0200] Using policy "default" as the default!
I [21/Jun/2007:07:58:02 +0200] Full reload is required.
I [21/Jun/2007:07:58:02 +0200] Loaded MIME database from
'/usr/share/cups/mime:/etc/cups': 34 types, 39 filters...
D [21/Jun/2007:07:58:02 +0200] Loading printer dj3650...
D [21/Jun/2007:07:58:02 +0200] Loading printer dj3650_lokal...
D [21/Jun/2007:07:58:02 +0200] cupsdLoadRemoteCache: Not loading remote
cache.
I [21/Jun/2007:07:58:02 +0200] Loading job cache file
"/var/cache/cups/job.cache"...
D [21/Jun/2007:07:58:02 +0200] Loading job 2 from cache...
D [21/Jun/2007:07:58:02 +0200] Loading job 3 from cache...
D [21/Jun/2007:07:58:02 +0200] Loading job 4 from cache...
D [21/Jun/2007:07:58:02 +0200] Loading job 5 from cache...
D [21/Jun/2007:07:58:02 +0200] Loading job 6 from cache...
D [21/Jun/2007:07:58:02 +0200] Loading job 7 from cache...
D [21/Jun/20...

[MauricioZ (mauricio-zunino)]

I remove /etc/rc2.d/S19cupsys and i do "invoke-rc.d cupsys" with a system call when load my X program.. I work in kiosko mode with only one program running. If you don´t have this option to start cups, I recommend that you make an script that execute this at at the beginning of Xsession, it does not matter if start more of once. To probe that this really work, remove /etc/rc2.d/S19cupsys (if you load rc2) and probe start the service from the Xsession in an Xterm... and you will see that the "pipe", "the open files" will not accumulate. I´m sorry by my english...

Saludos
Mauricio

[Till Kamppeter (till-kamppeter)]

mstreibe, and anyone else who has reported this problem, can you please set the LogLevel to "debug2" (not simply "debug") in cupsd.conf, restart CUPS again (or reboot) and then supply the error_log as soon as the problem occures again? The extra info which "debug2" supplies is very important.

[maxschulz (max-schulz-deactivatedaccount)]

I have no idea why but at the moment cupsd is not leaking file
descriptors anymore here. I'll provide the data as soon as I see the
problem again.

[DonB (donbivens)]

I can confirm that this is not fixed in the latest updates on Gutsy. What makes this really difficult is my customer has a proprietary app on SCO that we ported to Linux and I setup SAMBA and told him all about Linux goodness but his printing dies a couple times a day now :(

[cubells (cubells)]

==> Till:

Here you have attached my error_log file (+28 Mb without compression ) after set the LogLevel to debug2 in cupsd.conf and I can confirm that the bug is not fixed.

I've also attached the output from "sudo lsof | grep cupsys" and a capture when the bug is on and I try to print from Evince.

I wish it was useful for solving the problem...

If you need any data

 If you need any other data, only you have to say it because I can replay the bug... Now I hnow how...

[Till Kamppeter (till-kamppeter)]

Thank you. I have reopened the issue upstream at

http://www.cups.org/str.php?L2438

and attached all your files.

[Jens Braeuer (jens-braeuer)]

The issue also has a ticket in the debian bugtracker: http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=425944

[Till Kamppeter (till-kamppeter)]

We need a test with a CUPS version which does not have the numerous patches as the Ubuntu version has.

Can you try the following:

Download

http://www.openprinting.org/download/printdriver/RPMS/i486/cups-1.2.11-1lsb3.1.i486.rpm

or

http://www.openprinting.org/download/printdriver/RPMS/x86_64/cups-1.2.11-1lsb3.1.x86_64.rpm

depending on whether you are using the 32-bit or 64-bit PC platform.

Convert the package to the Debian format:

sudo apt-get install alien
sudo alien --scripts cups-*.rpm

Install this package:

sudo dpkg -i cups_*.deb

Transfer your print queues to the new CUPS:

sudo cp /etc/cups/printers.conf /etc/opt/cups/
sudo cp /etc/cups/ppd/*.ppd /etc/opt/cups/ppd/

Stop the system's CUPS

/etc/init.d/cupsys stop

and start the new CUPS

/etc/init.d/cups start

(NOTE: only "cups" not "cupsys" here).

Try to print and observe whether the memory leak appears again.

[Till Kamppeter (till-kamppeter)]

I forgot one thing:

Before installing the CUPS package, you need to install the LSB compatibility package:

sudo apt-get install lsb

[Till Kamppeter (till-kamppeter)]

See Mike's comment and my last comment in

http://www.cups.org/str.php?L2438

I have looked into the patches of the Ubuntu CUPS package and the relevant patch (8 KB) is attached. The patch separates the verification of the credentials into an external program which runs SUID root (as CUPS runs as user in Ubuntu). Username and password are sent via a pipe to the standard input of the external program (newly introduced function "cupsdCallPamAuthHelper()"). It seems that this pipe is not correctly closed.

The patch is one of Martin Pitt's non-root mode patches, therefore assigning to Martin Pitt.

[Till Kamppeter (till-kamppeter)]

I think this bug is worth an SRU. It breaks an important function of Feisty (Printing) and the fix is probably small (inside an 8-KB patch).

[cubells (cubells)]

==> Till

Just in case, I've tried your instructions:
$ sudo aptitude install lsb
I've downloaded http://www.openprinting.org/download/printdriver/RPMS/i486/cups-1.2.11-1lsb3.1.i486.rpm
$ sudo alien --scripts *.rpm
$ sudo dpkg -i *.deb
$ sudo cp /etc/cups/printers.conf /etc/opt/cups/
$ sudo cp /etc/cups/ppd/*.ppd /etc/opt/cups/ppd/
$ sudo /etc/init.d/cupsys stop
* Stopping Common Unix Printing System: cupsd [ OK ]
$ sudo /etc/init.d/cups start
cups: started scheduler.

And I can't print!!

[Martin Pitt (pitti)]

I just uploaded

 cupsys (1.2.12-1ubuntu1) gutsy; urgency=low
 .
   * Merge to Debian's svn head to get upstream fixes.
   * debian/patches/10_external_pam_helper.dpatch: Close pipes in the case of
     errors, too. This can not really be responsible for the mess in #112803,
     but should be fixed anyway.

This fixes the only pipe handling bugs that I can see. In the 'normal' case, pipes were already closed properly in that patch.

I am not able to reproduce the issue. I tried a standard USB printer and a file:// target, tried on the command line with and without specifying a host, tried printing from a Gnome app (gedit), and played around with administrative commands in the web interface. None of these actions produced additional FIFOs (just the two that are always open, and an additional one when a print job was running).

Do you use remote or local printing? Can someone please attach /etc/cups/cupsd.conf and /etc/cups/printers.conf, and maybe even a detailled recipe for reproducing this?

[cubells (cubells)]

==> Martin

Here you have attached the files you have requested...

To reproduce this bug only I have to send to the printer many different jobs consecutively with an interval of some seconds.

For example, the last time I reproduce the bug, I send 10 jobs with an interval of 4/5 seconds...

My printer is a Epson Stylus color 600, a serial printer...

[cubells (cubells)]

Sorry: I use local printing..

[Christian Niessner (ubuntu-christian-niessner)]

Hi There,

i'm joining this thread because i also have this problem on some of my cups machines. I have several cups servers running, and the 'socket eating' problem only occures on some of them, not on all.

I started debugging by myself and discovered that my fd eating problem is originated from dbus. I strace'd cupsd and discovered following (on the 'fd eating machin'):

every time when i spool a job, libdbus seems to executes dbus-launch:

pipe([15, 16]) = 0
clone(Process 4232 attached
child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb7c0c918) = 4232
[pid 4229] close(16) = 0
[pid 4229] read(15, <unfinished ...>
[pid 4232] open("/dev/null", O_RDWR) = 17
[pid 4232] close(15) = 0
[pid 4232] close(0) = 0
[pid 4232] close(1) = 0
[pid 4232] close(2) = 0
[pid 4232] dup2(17, 0) = 0
[pid 4232] dup2(16, 1) = 1
[pid 4232] dup2(17, 2) = 2
[pid 4232] close(17) = 0
[pid 4232] close(16) = 0
[pid 4232] execve("/usr/bin/dbus-launch", ["dbus-launch", "--autolaunch", "c240c094f96d50bd8cca400046655800"...,
"--binary-syntax"], [/* 17 vars */]) = 0
[pid 4232] brk(0) = 0x804e000
[removed lots of stuff]
[pid 4232] mprotect(0xb7e98000, 4096, PROT_READ) = 0
[pid 4232] munmap(0xb7f8f000, 15871) = 0
[pid 4232] brk(0) = 0x804e000
[pid 4232] brk(0x806f000) = 0x806f000
[pid 4232] write(2, "Autolaunch error: X11 initializa"..., 45) = 45
[pid 4232] exit_group(1) = ?
Process 4232 detached
<... read resumed> "", 1024) = 0
--- SIGCHLD (Child exited) @ 0 (0) ---
sigreturn() = ? (mask now [])
waitpid(4232, [{WIFEXITED(s) && WEXITSTATUS(s) == 1}], 0) = 4232
time(NULL) = 1181048565
write(4, "D [05/Jun/2007:15:02:45 +0200] D"..., 70) = 70

after that, fd 15 stays open. ( 15 -> pipe:[60116] )
I think this is rather a libdbus bug not a cups bug.

on my 'good' machine i see an initinal connect to /var/run/dbus/system_bus_socket during startup and that's it. no further dbus-launch forks and so on.

I have no idea why it works for some machines and for some not. dbus itself is up and running on all machines.

can somebody also experiencing fd eating verify this issue by doing following:

/etc/init.d/cupsd stop
strace -f cupsd 2>strace.log
lp /etc/hosts (on other terminal)
and then have a look into the strace.log if there are dbus-launch calls or not?

thanks,
    chris

[Frank (fdelin)]

I only found out about this bug last night as we were putting the new Fiesty print server into production. I ran the strace and also see execve("/usr/bin/dbus-launch" in my log.

[maxschulz (max-schulz-deactivatedaccount)]

I have documented the same some time ago in another bug report, see

https://bugs.launchpad.net/ubuntu/+source/cupsys/+bug/116673

But for some reason I don't see this problem anymore on my system. My
cupsd now has 5 open files while it is idle. Something must have changed
 in the configuration but I'm not able to track this back.

[Joachim Schwender (jschwender)]

I am running here clustered X-terminal servers with cups on it as print service. I have the problem with feisty version as well as with the 1.2.11 (compiled as recommended above). I can contribute this: when i have a stalled print job, i see one additional pipe handle each time cups tries to reprint or reconnect to the printer. This way i the open file number is exceeded within minutes, you can watch it online. A cupsys force-reload brings the number of pipes back to two. Until the bug is fixed i have a small script driven by cron which does this reload when the number of pipes exceeds 50. That is not nice, but it prevents cups from getting quickly unusable. With Debian Etch file servers i do not see a similar problem. I desperately hope that someone can fix this...soon.

[Joachim Schwender (jschwender)]

I should mention that the two debian etch boxes on which cups is ok, uses version 1.2.12 with a reduced set of debian patches:

02_configure.dpatch
03_clean.dpatch
06_disable_backend_setuid.dpatch
08_cupsd.conf.conf.d.dpatch
09_runasuser.dpatch
11_pam.dpatch
12_quiesce_ipp_logging.dpatch
19_cupsaccept.dpatch
47_pid.dpatch
53_usr_share_ppd_support.dpatch
54_cups-config_modeldir.dpatch
60_device_uri.dpatch
64_driverfolder.dpatch
67_printcap.dpatch
68_edit-config.dpatch
I did not test the debian package. When i find the time, i will try to compile same version on kubuntu to see if that works.

[schweini (schweini)]

I tried Blades workaound (installing Edgys package), but i just get a bunch of build-errors.<br>
<br>
Can anybody confirm or deny that this will soon be fixed in the regular (K)Ubunto repos? Im deploying a couple of small buisiness servers, and was planing on using Kubuntu, but iĺl have to wait til at least printing is working fine. And its quite a drag to restart cups via cron every couple of minutes, just in case.

So, anyone have a rough date on when this will get deployed? according to the debian ticket, it seems rather easy to resolve...

[hugortega (hugortega)]

Just in case, meanwhile the fix is released, an ugly but effective script to restart the cupsd when the number of pipes is high:

-------------------
#! /bin/bash

pipes=$(sudo lsof -p `pidof cupsd` | grep pipe | wc -l)
maxpipes=30
if [[ $pipes -gt $maxpipes ]] ; then
  echo "Reiniciando servidor CUPS"
  date >> /var/log/cups/restart4pipes.log
  /etc/init.d/cupsys restart
fi
-------------------

Of course, you can drive the file with cron... this script logs the date and time of the events.

Any news about the fix?... I'm trying to introduce ubuntu server as the default server in my company, but those things are not exactly the best publicity :D ... anyway, thanks for ubuntu people...

[Martin Pitt (pitti)]

hi,

schweini [2007-07-24 22:14 -0000]:
> So, anyone have a rough date on when this will get deployed? according
> to the debian ticket, it seems rather easy to resolve...

So far I was unable to reproduce the bug, and the Debian ticket
suspected the pam helper as the culprit, which was not confirmed.

So until a developer can actually reproduce this, there is no firm
schedule. As soon as we have a solution, we will deploy it for Feisty
as well, of course.

[Christian Niessner (ubuntu-christian-niessner)]

Hi Martin,
Hi all,

I investigated a bit more, and (at least for my setups) it seems that libdbus is the culprit.

In my setup, there are several cups servers up and running. The on running on my Workstation works fine - and my workstation is a 'full grown installation' with X-Servers, Gnome and all that stuff.

But the stripped down printservers suffer from this problem. I think it depends on what is installed and what not.

I recompiled cups packages (the original feisty ones and 1.2.12 from gusty) with --disable-dbus and the file descriptor leak was gone for all my systems.

On one system that was previously working with the original feisty packages, the fd leaking started after installing additional printer drivers (cups-driver-gutenprint - and i think hpijs). The dependencies pulled lots of other packages - f.i. some xorg/x11 related libs. After that, cups (or libdbus) tries to start dbus-launch, which itself complains something like "Autolaunch error: X11 initializa"... - (see my previous strace post).

i attach a list of installed packages of one of my servers. don't get confused - the installed cups packages are mine, taken from gusty and compiled with dbus disabled on feisty. But the fd leak starts as soon as i install the original feisty packages.

Hope this helps reproducing the bug. I also could do some further debugging / investigation if needed. Shall we involve dbus people?

have a nice day,
      chris

[Joachim Schwender (jschwender)]

I have also compiled a package from 1.2.12 and added those patches from 1.2.11 (gusty) that patched successfully, but compiled with --enable-dbus, and it works! The number of file descriptors is back to 2 after each print job. I have installed cups-driver-gutenprint, as well as hplip hpijs. And i cannot find a message "Autolaunch error: X11 ini....." in my log files.

[cubells (cubells)]

==> So until a developer can actually reproduce this, there is no firm schedule. (Martin said)

See the file I've attached, please.

To reproduce the bug in my work computer I've just:

1) opened the file document.odt with OpenOffice.org writer.
2) clicked in "Print directly" icon
3) closed the Openoffice.org writer
4) opened the file document.odt with OpenOffice.org writer.
5) clicked in "Print directly" icon
6) closed the Openoffice.org writer
7) ...

and so on about ten times.

So, the bug "works" on my home and on my work computer, that is, I can reproduce the bug in a <b>different computer</b>, in <a>a different lan</b>, in <b>a different printer</b>, and with <b>a very different sotware installed</b>.

My printer at work is a usb printer: Epson stylus D78. So, I can reproduce the bug in a serial and in a usb printer.

I've attached 3 different files: lsof.before and error_log.before,
files that I can logged <b>before</b> uninstalling cups (exactly the following packages: cupsys, bluez-cups, cups-pdf, cupsys-driver-gutenprint, hplip, ubuntu-desktop) (bug is off).

lsof.after and error_log.after, files that I can logged <b>after</b> reinstalling cups (exactly the following packages: hpijs-ppds, python-imaging, python-qt3, python-reportlab, python-sip4, bluez-cups, cupsys, cupsys-driver-gutenprint, hplip, ubuntu-desktop), but without restart my computer (bug is off).

And finally: lsof.bug and error_log.bug, files that I can logged after restart my computer.

At lsof_error_bug I've reproduced the bug twice: from the time 11:54 to 12:26 aprox., and from the time 12:26 to the end of the file.

Both times, cups stops printing after 6-9 jobs printed.
Both times, I've obtained the same cups error: Unable to create job filter pipes - Too many open files.
Both times, I've had to restart cups to be able to print again.

In any moment, I've obtained any message error about dbus.

I've attached my dpkg-selections to compare with Christian logs...

Something more?

[Martin Pitt (pitti)]

I still could not determine how to trigger that problem with a normal system, however, with some incredible hideous hacks in dbus I was able to force this condition (calling dbus-launch).

I verified that the problem is indeed that _dbus_get_autolaunch_address() does not close the reading end of the pipe in dbus 1.0.2.

This has been fixed in gutsy recently with dbus 1.1.1. The patch for Feisty is trivial, will prepare an SRU now.

[Martin Pitt (pitti)]

Thanks a lot to everyone for your help with debugging this!

I uploaded a fixed dbus to feisty-proposed, it should be available in about two hours. Can you please test the packages from feisty-proposed and confirm that they fix this issue? If we get some confirmations, the package can go to feisty-updates next Thursday.

I attach the debdiff used for this stable release update.

[Martin Pitt (pitti)]

dbus (1.0.2-1ubuntu4) feisty-proposed; urgency=low

  * Add debian/patches/02_dbus-launch_close_pipe.patch:
    - _dbus_get_autolaunch_address(): When calling dbus-launch fails,
       close the reading end of the pipe.
    - This caused a serious fd leak in programs like cups when they repeatedly
      try to send dbus messages, dbus is not running, and dbus-launch is not
      available or otherwise fails to execute.
    - LP: #112803

 -- Martin Pitt <email address hidden> Thu, 26 Jul 2007 11:08:35 +0200

[Roberto (roberto-colnaghi)]

Hi folks, I'm new around here.
I have the same problem, but I noticed that cupsys doesn't depend on dbus, in fact I don't even have it installed on my server. So, I'm wondering how a dbus update can solve the problem. Am I missing something?
Roberto

[Martin Pitt (pitti)]

Hi Roberto,

Roberto Colnaghi [2007-07-26 11:28 -0000]:
> Hi folks, I'm new around here. I have the same problem, but I
> noticed that cupsys doesn't depend on dbus, in fact I don't even
> have it installed on my server. So, I'm wondering how a dbus update
> can solve the problem. Am I missing something?

It depends on libdbus-1-3, which is at fault here. It tries to start a
dbus instance, fails (because dbus itself is not installed), and
forgets to clean up the pipes.

[Roberto (roberto-colnaghi)]

Thank you Martin. So, either the problem lies in libdbus-1-3, and this is the package that should be updated, or cupsys requires dbus, but the dependency is not present, so a cupsys package update (to include the dependency) is needed.

Roberto

[Martin Pitt (pitti)]

Hi Roberto,

Roberto Colnaghi [2007-07-26 13:26 -0000]:
> Thank you Martin. So, either the problem lies in libdbus-1-3, and this
> is the package that should be updated, or cupsys requires dbus, but the
> dependency is not present, so a cupsys package update (to include the
> dependency) is needed.

The problem *is* in libdbus-1-3. Sorry for the confusion if I was
unclear. I was speaking about the source package 'dbus' sometimes
(which produces the library, too).

cupsys should not depend on dbus at all. It should just provide the
notification service if dbus is installed.

[Frank (fdelin)]

Thanks Martin. Will this patch result in a new package being released or do I need to manually compile this?

Thanks,

Frank

[cubells (cubells)]

Hi all,

I've tested the packages from feisty-proposed twice and i can confirm that the bug is fixed!!

My cups server works correctly and I can print all my jobs without having to restart cupsys.

Thanks a lot!!

[Frank (fdelin)]

Hi all,

I also got the libdbus-1-3_1.0.2-1ubuntu4_amd64.deb from proposed and installed it.

Everything looks ok, a wc -l of my lsof -p stayed steady at 43 as I shot a dozen or so jobs at it.

Thanks so much.

[Michael Vogt (mvo)]

I installed the update today for SRU verficiation, it installs/works fine for me. I can not reproduce the original bug, but I'm happy to set it to verification-done on the grounds that two community people already reported that it fixes the bug and that Martin was able to reproduce the bug and verify the fix.

[Roberto (roberto-colnaghi)]

I've installed the package on Friday the 27th of July , and this seems to have solved the problem on our server too.
Roberto

[Martin Pitt (pitti)]

Closing invalid cupsys task (whoever added it).

[Martin Pitt (pitti)]

Copied dbus to feisty-updates.

[hugortega (hugortega)]

I installed the patch in 2 servers (ubuntu server 7.04) and everything is OK now... thank you very much to all people who contributed to the fix.

EOF

[Li Tong (li-airotech)]

Hi, I am new here, can someone tell me where I can find the patch talked about in this thread? Thanks!!