Description of problem: Repeated error "There was an error during the CUPS operation: 'server-error-internal-error'" when I try to create a remote Windows-attached printer. I've just installed FC6 and updates, and this is the first printer I've tried to install. Same error also occurred with the distro before updates. Version-Release number of selected component (if applicable): cups-1.2.5-2.fc6.8 foomatic-3.0.2-39.1.fc6 system-config-printer-0.7.35-1.fc6 How reproducible: Every time. Steps to Reproduce: 1. Run system-config-printer (from Gnome: System->Administration->Printing) 2. Click on New 3. Fill in Printer Name (=dj930c). Also I filled in both optional fields if it's important: Description=DeskJet 930C on Dell; Location=Study 4. Forward 5. Select Windows Printer via SAMBA 6. Click on triangle next to workgroup name to list servers 7. Double-click on server PSERVER to list its printers (odd - it doesn't have a triangle next to the server name until you double-click on the name - never mind, might be something else): share name on PSERVER is dj930c 8. Type in to field smb:// the string PSERVER/dj930c 9. Click Verify - printer is accessible 10. Forward 11. Select HP 12. Forward 13. Select DeskJet 930C and the foomatic HP-DeskJet_930C-hpijs.ppd driver. 14. Forward. 15. Apply 16. CUPS server error dialog appears. See Actual results below. Actual results: CUPS server error There was an error during the CUPS operation: 'server-error-internal-error'. Expected results: On FC2 it added the printer and produced a dialog to print a test page. Not sure exactly what it's supposed to do on FC6, but I expect it's something similar. Additional info: /var/log/cups/error_log contains as a result of above: <snip> E [17/Nov/2006:13:10:16 +1100] cupsdAuthorize: Local authentication certificate not found! I [17/Nov/2006:13:10:16 +1100] Started "/usr/lib/cups/daemon/cups-deviced" (pid=5156) E [17/Nov/2006:13:18:36 +1100] cupsdAuthorize: Local authentication certificate not found! E [17/Nov/2006:13:18:36 +1100] CUPS-Add-Modify-Printer: Unauthorized I [17/Nov/2006:13:18:36 +1100] Setting dj930cX device-uri to "smb:///co3045019-a/dj930c" (was "file:/dev/null".) E [17/Nov/2006:13:19:06 +1100] copy_model: empty PPD file! <snip> Also saw this reported at http://www.redhat.com/archives/fedora-list/2006-October/msg04098.html, but couldn't find a current bug report by searching for the obvious keywords.
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.