Bug 216065

Thanks for the report.  Firstly, what does 'ls -lR /etc/cups/' say, as root?

Tim,

ls -lR /etc/cups output is:

/etc/cups:
total 128
-rw------- 1 root lp     82 Nov 15 20:43 classes.conf
-rw------- 1 root lp      0 Oct  6 01:43 classes.conf.O
-rw-r--r-- 1 root lp      0 Nov  7 03:10 client.conf
-rw-r----- 1 root lp   1758 Nov 16 20:41 cupsd.conf
-rw-r----- 1 root lp   2472 Nov  7 03:10 cupsd.conf.default
-rw-r----- 1 root lp   2472 Nov  7 03:10 cupsd.conf.O
drwxr-xr-x 2 root root 4096 Nov  7 03:10 interfaces
-rw-r--r-- 1 root root 4579 Nov  7 03:10 mime.convs
-rw-r--r-- 1 root root 6223 Nov  7 03:10 mime.types
-rw-r--r-- 1 root lp    239 Nov  7 03:10 pdftops.conf
drwxr-xr-x 2 root lp   4096 Nov 17 13:31 ppd
-rw------- 1 root lp    360 Nov 17 13:31 printers.conf
-rw------- 1 root lp    391 Nov 17 12:20 printers.conf.O
-rw-r--r-- 1 root root  947 Nov  7 03:10 pstoraster.convs
-rw-r--r-- 1 root lp     69 Nov  7 03:10 snmp.conf
drwx------ 2 root lp   4096 Nov  7 03:10 ssl

/etc/cups/interfaces:
total 0

/etc/cups/ppd:
total 0

/etc/cups/ssl:
total 0

Thanks.  Now please do the follow, as root.

Edit /etc/cups/cupsd.conf and change the LogLevel line to read:

  LogLevel debug2

Stop CUPS:

  /sbin/service cups stop

Clear out the error log:

  >/var/log/cups/error_log

Start CUPS:

  /sbin/service cups start

Then try adding the queue again and then attach the /var/log/cups/error_log file
here when it fails.  Thanks.

Created attachment 141687 [details]
copy of /var/log/cups/error_log

Needed info attached above. (Creating attachment seemed to erase comment and
close without changing status)

Okay, here's what's going wrong:

d [21/Nov/2006:07:28:11 +1100] copy_model(con=0x9fafbf0, from="foomatic:HP-DeskJ
et_930C-hpijs.ppd", to="/etc/cups/ppd/dj930c.ppd")
D [21/Nov/2006:07:28:11 +1100] copy_model: Running "cups-driverd cat foomatic:HP
-DeskJet_930C-hpijs.ppd"...
d [21/Nov/2006:07:28:11 +1100] cupsdStartProcess("/usr/lib/cups/daemon/cups-driv
erd", 0xbfbad9bc, 0xbfbad82c, -1, 13, 8)
E [21/Nov/2006:07:28:41 +1100] copy_model: empty PPD file!
D [21/Nov/2006:07:28:41 +1100] CUPS-Add-Modify-Printer server-error-internal-err
or: Unable to copy PPD file!

The foomatic CUPS driver isn't providing a PPD file for some reason.

Please run this command:

/usr/lib/cups/daemon/cups-driverd cat foomatic:HP-DeskJet_930C-hpijs.ppd

What output do you get? (I get a PPD file.)

I get a PPD file.

I ran the command as follows:

time /usr/lib/cups/daemon/cups-driverd cat foomatic:HP-DeskJet_930C-hpijs.ppd
>/tmp/bugOutput.ppd

real    0m52.589s
user    0m10.845s
sys     0m6.408s

(it's a PII 350MHz machine, hence the long time taken)

Looks from the log above that copy_model waits only 30 seconds for the ppd file
to appear? So it's not waiting long enough.

Confirmed: the 30 second timeout is the problem.

I downloaded cups-1.2.5 source and rebuilt cupsd with a hardwired 90 second
timeout. I recreated the printer queue and it worked. Had to first delete the
dud left over from the last effort.

But what's the reason for this? Presumably 30 seconds worked OK before? Even on
ancient hardware like this? So has foomatic suddenly become slower in 3.0.2? (I
didn't check what the previous foomatic rev was in FC 5, and I don't know how to
do that anyway).

Also, a hardwired 90 second timeout is a little tough on those with modern
hardware. Shouldn't the timeout be scaled by processor speed? Maybe use
something like bogomips? I'm just checking out a crude way of doing that by
scanning /proc/cpuinfo.

Sorry, I left out that the 30 second timeout is in scheduler/ipp.c

Thanks for the analysis!  Reported upstream.

In FC5 system-config-printer was getting foomatic to generate the PPD itself
first before setting it up as a CUPS queue; in FC6 we are telling CUPS to do it all.

I've built a CUPS package with a longer timeout, but I'm going to change the
component of this bug to foomatic to see if we can speed that up.

Two possible high-level outcomes here: foomatic can't made faster (bad), or it
can (maybe good). If it can, maybe it can't be made faster for a a considerable
time (bad, although the work-around is as you've done, rebuild the CUPS package
with a longer timeout.

From CUPS STR 2113: "Waiting longer than 30 seconds will cause another
Denial-of-Service."

I don't fully understand the reasoning behind that. I assume that cupsd can't
process other requests while creating a new printer queue, and waiting a long
time for foomatic to generate a PPD file is a potential denial of service.

I would have thought that 30 seconds was long enough to contribute to that, and
IMHO it's too long to wait on a fast processor anyway. One of our dual Xeons at
work will generate the same PPD in 5 to 6 seconds. Maybe other PPDs could take
longer.

I don't think the timeout should be increased across the board. What I'd prefer
is that the timeout be made *less* than 30 seconds for fast processors, and
*more* than 30 seconds for slower processors, probably with a hard minimum of 5
to 10 seconds.

My PC's bogomips = 871.93 (350MHz PII). The dual 3.0GHz Xeon at work has
bogomips = 6000 on each CPU. Guessing, 30 seconds is probably an ample timeout
for an Intel machine about 1.0GHz, so probably about 2000 bogomips. Given
bogomips isn't perfect and probably differs between architectures it would all
be a bit arbitrary anyway.

Anyway, let's see how the foomatic avenue pans out.

*** Bug 195801 has been marked as a duplicate of this bug. ***

Closing.  I don't think I'll ever get to this.