Bug 583054 - Any interaction with CUPS server takes over minute
Summary: Any interaction with CUPS server takes over minute
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: cups
Version: 12
Hardware: i686
OS: Linux
low
medium
Target Milestone: ---
Assignee: Tim Waugh
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard: abrt_hash:9015b701
Depends On: 579957
Blocks: 590632
TreeView+ depends on / blocked
 
Reported: 2010-04-16 14:40 UTC by Jiri Popelka
Modified: 2010-10-08 20:55 UTC (History)
3 users (show)

Fixed In Version: cups-1.4.4-9.fc12
Doc Type: Bug Fix
Doc Text:
Clone Of: 579957
: 590632 (view as bug list)
Environment:
Last Closed: 2010-09-24 20:43:39 UTC
Type: ---
Embargoed:


Attachments (Terms of Use)

Description Jiri Popelka 2010-04-16 14:40:24 UTC
+++ This bug was initially created as a clone of Bug #579957 +++

comment: I am having constant problems with slow printing.
system-config-printer/Server Settings/Advanced times out with a dialog "CUPS server error/There was an HTTP error: status 1000".
No errors are being logged to /var/log/cups/error_log or /var/log/https/error_log.
httpd and the CUPS scheduler service are both running (automatic at startup).
The only printer is a locally connected BJC4100 driver name STP01419.PPD version 5.2.5.
I have a LAN with 3 computers sharing the one printer.
Printing worked under FC10 and I have only recently upgraded to FC12, with these problems starting right away.
kernel: 2.6.32.10-90.fc12.i686.PAE
release: Fedora release 12 (Constantine)


--- Additional comment from jpopelka on 2010-04-07 12:26:46 CEST ---

Are you able to somehow obtain the troubleshooter output ?
I see s-c-printer crashed when you tried to print test page in troubleshooter, but you write that "I am having constant problems with slow printing".
So you are able to print (and therefore obtain the troubleshooter output), right ?

Are you experiencing the same "slow printing" problems regardless whether you print from the locally connected machine or from some other computer on LAN ?
Or is it different ?

--- Additional comment from owlbrudder on 2010-04-16 01:49:30 CEST ---

Created an attachment (id=406964)
Output from printing troubleshooter

Requested by Jiri Popelka on 7 April 2010

--- Additional comment from owlbrudder on 2010-04-16 01:54:45 CEST ---

(In reply to comment #2)
> Are you able to somehow obtain the troubleshooter output ?
> I see s-c-printer crashed when you tried to print test page in troubleshooter,
> but you write that "I am having constant problems with slow printing".
> So you are able to print (and therefore obtain the troubleshooter output),
> right ?
> 
> Are you experiencing the same "slow printing" problems regardless whether you
> print from the locally connected machine or from some other computer on LAN ?
> Or is it different ?    

Jiri, I have been replying to this via gmail and did not realise I had to work here through Bugzilla - sorry for the delay this has caused. The content of my gmail posts is as follows:

Yes, I have been able to capture troubleshooter output - see attached. I also have the log file, which has timestamps, but it is +/-38Mb - is there any particular part of it you would like to see?.

The "slow printing" problem is this: any interaction with the CUPS server is taking one minute twenty five seconds to one minute forty five seconds, timed using my wrist watch. The document I printed to capture the trouble-shooter output was a page of random text (lorem ipsum) printed from OpenOffice. From the time I clicked Print to the time the printer started was 1:45. During the one-page print, the printer paused twice, each time for +/-1:25. Pointing Firefox to localhost:631 takes over a minute (not accurately timed yet). Connecting over my network takes well over a minute from the time I click 'Print...' until the printer dialog becomes available. It spends this time displaying the progress message "Getting printer information ...". A four-page pdf I printed over the network took over 11 minutes to complete.

Note that the output is correct and all documents have printed correctly, except for an inability to print a test page from the printer configuration/Troubleshooter dialogs.

Note also the same PC and printer did not have this problem under FC10.

Please let me know if there is anything more I can do to help.

I connected the printer to an old IBM T23 notebook (1.3Ghz CPU) and found the delays much shorter. Printing locally caused the same document to start on the printer after only 15 seconds and there was one delay of approx 10 seconds during the print. Printing from a networked notebook took approx 1 minute to start and there were two delays, one of aprox 45 seconds and the other of approx 15 seconds. I can live with these delays, so will set up the T23 as a printer server permanently on my network, but it does not solve the problem of the longer delays and crashes when the printer is connected to my desktop PC(2.8GHz CPU). As a wild idea from left field, has something changed in the parallel port driver in FC12? See also http://forums.fedoraforum.org/showthread.php?p=1351123#post1351123

Could not live with the delays after all, so booted the notebook into WinXP and shared the printer from there. Printing and getting printer properties from networked FC12 boxen is now immediate, so it does seem to be an issue with the FC12 CUPS server somewhere.

Cheers, Doug

Comment 1 Tim Waugh 2010-04-16 14:51:44 UTC
This is what's causing the delay, at a guess:

'D [10/Apr/2010:09:00:20 +1000] cupsdNetIFUpdate: "lo" = localhost:631',
'D [10/Apr/2010:09:00:37 +1000] cupsdNetIFUpdate: "eth0" = 192.168.0.199:631',
'D [10/Apr/2010:09:00:54 +1000] cupsdNetIFUpdate: "virbr0" = 192.168.122.1:631',
'D [10/Apr/2010:09:00:54 +1000] cupsdNetIFUpdate: "lo" = localhost:631',
'D [10/Apr/2010:09:01:11 +1000] cupsdNetIFUpdate: "eth0" = fe80::20a:48ff:fe07:499d%eth0:631',

Perhaps you have a nameserver configured that is not reachable?

Try setting "HostNameLookups off" in /etc/cups/cupsd.conf and see if that makes a difference.

Comment 2 Doug Hutcheson 2010-04-17 01:06:33 UTC
(In reply to comment #1)
> This is what's causing the delay, at a guess:
> 
> 'D [10/Apr/2010:09:00:20 +1000] cupsdNetIFUpdate: "lo" = localhost:631',
> 'D [10/Apr/2010:09:00:37 +1000] cupsdNetIFUpdate: "eth0" = 192.168.0.199:631',
> 'D [10/Apr/2010:09:00:54 +1000] cupsdNetIFUpdate: "virbr0" =
> 192.168.122.1:631',
> 'D [10/Apr/2010:09:00:54 +1000] cupsdNetIFUpdate: "lo" = localhost:631',
> 'D [10/Apr/2010:09:01:11 +1000] cupsdNetIFUpdate: "eth0" =
> fe80::20a:48ff:fe07:499d%eth0:631',
> 
> Perhaps you have a nameserver configured that is not reachable?
> 
> Try setting "HostNameLookups off" in /etc/cups/cupsd.conf and see if that makes
> a difference.    

Tim, thanks for the quick response. I don't know that my answers are going to be helful.

In summary, setting "HostNameLookups off" in /etc/cups/cupsd.conf made no obvious difference and my nameservers seem to be working OK. Details are as follows:

I set "HostNameLookups off" in the cupsd.conf on both the print server (old IBM T23 notebook) and the client (T61 notebook), using the Cups tool on port 631. The service was restarted automatically on both machines.

I checked that ping and ssh were working normally using named hosts, to ensure I had no general DNS issue. All machines on my LAN have hosts files containing details of all the other machines on the LAN and my (limited) understanding is that this takes precedence over DNS lookups.

On the server, it takes 3 seconds for system-config-printer to display the printer properties. From there, it takes 5 seconds from 'Print test page' before the printer starts printing. (When this machine is booted into WinXP, the equivalent actions are as good as immediate).

From the networked notebook, it takes 30 seconds for system-config-printer to display printer properties and the 'Print test page' delay is 55 seconds.

From the networked notebook, printing a test page of lorum ipsem from Open Office took the following times:
From click on Print until printer dialog appears: 4 sec
From click on OK until remote printer commences:1 min 45 sec
During print, two delays of 10 sec and 45 sec respectively.

All these results were duplicated within a small margin of error after I used system-config-network to swap the priority of the two DNS I have recorded, so I am guessing that my general DNS setup is not at fault.

I am not running my own DNS, as I believe that fully qualified entries in my hosts files are sufficient for my small LAN - is that correct?

I will be happy to run any further tests and do anything I can to help. I can only reiterate that exactly the same hardware and network configuration worked fine under FC10.

Cheers, Doug

Comment 3 Tim Waugh 2010-05-06 14:37:16 UTC
There was a changed committed upstream relating to this recently.  Please try cups-1.4.3-5.fc12 which incorporates it:

http://koji.fedoraproject.org/koji/buildinfo?buildID=171926

Download each package you require, then run:

su -c 'yum update --nogpgcheck cups*1.4.3-5*.rpm'

Does that fix it?

Comment 4 Doug Hutcheson 2010-05-08 07:48:48 UTC
(In reply to comment #3)
> There was a changed committed upstream relating to this recently.  Please try
> cups-1.4.3-5.fc12 which incorporates it:
> 
> http://koji.fedoraproject.org/koji/buildinfo?buildID=171926
> 
> Download each package you require, then run:
> 
> su -c 'yum update --nogpgcheck cups*1.4.3-5*.rpm'
> 
> Does that fix it?    

Tim, that plus an idea I got from another thread fixed it. Installing the new version cut the initial delay when printing down to +/-35 seconds. Editing /etc/hosts on the server, to add a line for the server itself at its real IP address (ie on server dennis I added a line of the form '192.168.0.150 dennis dennis.farm.home') cut the initial delay down to less than 5 seconds. I installed the new version on both client and server, but updated /etc/hosts on the server only. I don't know why that line makes a difference - I have never needed it before! Go figure.

As far as I am concerned, the problem is fixed. Thanks very much for your efforts.

Cheers, Doug.

Comment 5 Doug Hutcheson 2010-05-08 07:49:44 UTC
Ooops - forgot the clear the needinfo flag - hope this does it.

Comment 6 Tim Waugh 2010-05-08 12:08:47 UTC
Great, thanks for testing.

Comment 7 Fedora Update System 2010-09-17 16:39:56 UTC
cups-1.4.4-10.fc13 has been submitted as an update for Fedora 13.
https://admin.fedoraproject.org/updates/cups-1.4.4-10.fc13

Comment 8 Fedora Update System 2010-09-17 16:41:14 UTC
cups-1.4.4-9.fc12 has been submitted as an update for Fedora 12.
https://admin.fedoraproject.org/updates/cups-1.4.4-9.fc12

Comment 9 Fedora Update System 2010-09-21 01:36:38 UTC
cups-1.4.4-10.fc13 has been pushed to the Fedora 13 testing repository.  If problems still persist, please make note of it in this bug report.
 If you want to test the update, you can install it with 
 su -c 'yum --enablerepo=updates-testing update cups'.  You can provide feedback for this update here: https://admin.fedoraproject.org/updates/cups-1.4.4-10.fc13

Comment 10 Fedora Update System 2010-09-24 20:43:13 UTC
cups-1.4.4-10.fc13 has been pushed to the Fedora 13 stable repository.  If problems still persist, please make note of it in this bug report.

Comment 11 Fedora Update System 2010-10-08 20:54:48 UTC
cups-1.4.4-9.fc12 has been pushed to the Fedora 12 stable repository.  If problems still persist, please make note of it in this bug report.


Note You need to log in before you can comment on or make changes to this bug.