Bug 476424
| Summary: | job stays in queue after printing | ||||||||||||||||
|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|
| Product: | [Fedora] Fedora | Reporter: | Jonathan Kamens <jik> | ||||||||||||||
| Component: | cups | Assignee: | Tim Waugh <twaugh> | ||||||||||||||
| Status: | CLOSED ERRATA | QA Contact: | Fedora Extras Quality Assurance <extras-qa> | ||||||||||||||
| Severity: | medium | Docs Contact: | |||||||||||||||
| Priority: | low | ||||||||||||||||
| Version: | 11 | CC: | fifilip, james, jpopelka, skamansam, twaugh | ||||||||||||||
| Target Milestone: | --- | ||||||||||||||||
| Target Release: | --- | ||||||||||||||||
| Hardware: | All | ||||||||||||||||
| OS: | Linux | ||||||||||||||||
| Whiteboard: | |||||||||||||||||
| Fixed In Version: | 1.4-0.rc1.15.fc11 | Doc Type: | Bug Fix | ||||||||||||||
| Doc Text: | Story Points: | --- | |||||||||||||||
| Clone Of: | Environment: | ||||||||||||||||
| Last Closed: | 2009-08-15 08:26:56 UTC | Type: | --- | ||||||||||||||
| Regression: | --- | Mount Type: | --- | ||||||||||||||
| Documentation: | --- | CRM: | |||||||||||||||
| Verified Versions: | Category: | --- | |||||||||||||||
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |||||||||||||||
| Cloudforms Team: | --- | Target Upstream Version: | |||||||||||||||
| Embargoed: | |||||||||||||||||
| Attachments: |
|
||||||||||||||||
What does 'lpstat -t' say? (In reply to comment #0) > There is nothing in /var/log/cups/error_log (it's empty) As in zero bytes? Do you have SELinux enabled, and does /var/log/cups/error_log have the right context? (Try restorecon.) Could you attach /etc/cups/cupsd.conf? I've cleared the job since then, so I can't tell you exactly what lpstat -t says, but I checked before clearing it, and my recollection is that it said that both draft and raw were online and active and that the job hung in the draft queue was "processing." SElinux is disabled. /var/log/cups/error_log is empty because it rolled over since the last time cups was restarted and nothing new has been logged since then. I will attach cupsd.conf. Created attachment 326944 [details]
cupsd.conf file
Can you attach the error_log-200812* file that corresponds to the original problem please? As I said, nothing whatsoever was logged in the error_log when this problem occurred -- it was rolled over before the problem occurred, and it was empty afterwards. So I'm not sure what you're asking for. Sounds like the logging is completely broken for you, although it's working for me. It isn't logrotate, as that would move the old error_log file to error_log-${date}.
Unless we can get logging working for you there are only very limited diagnostic options.
Is it possible for you to re-create the problem and run 'lpstat -t'?
Alternatively, do you still have that strace output? It never got attached to this bug report.
This is getting a little surreal. Logging is working just fine for me. Stuff doesn't get logged in error_log unless CUPS actually thinks there's an error (hence the name) or debugging is enabled. Between when the log file last rolled over, and when the problem described in the ticket occurred, CUPS didn't think anything went wrong, so it didn't log anything in error_log. Therefore there is nothing in error_log or its previous rolled-over incarnations that is relevant to this issue. There is an attachment on this ticket titled "strace log file" which is, in fact, the strace output I mentioned previously. Oh, sorry, missed that strace file (but it doesn't reveal anything of note). Are you able to reproduce this problem on demand? If so, please run the printing troubleshooter (System->Administration->Printing, then Help->Troubleshoot), or else show what 'lpstat -t' says. The new default logging level in CUPS 1.4 is very much less verbose than it was in previous versions, hence my expectation of *something* in the error_log. Will take a bit of getting used to..! If you are not able to run the troubleshooter, or are not able to reproduce the problem on demand, it would be great if you could enable debugging output like this: cupsctl --debug-logging and leave it running like that until you see the problem again, at which point you can attach the error_log file here. Hello, I'm seeing this too, I think, with cups-1.3.9-6.fc10.x86_64. I have a HP DeskJet on an IPP print server, and jobs stick in a "processing" state in the queue after they've completed. This happens with other types of queue, too. [james@rhapsody ~]$ lpstat -t scheduler is running system default destination: double device for colour: socket://137.44.14.238:9100 device for double: hp:/net/HP_LaserJet_4000_Series?ip=137.44.14.164 device for epsonr300: ipp://print.ettle.lan/epsonr300 device for hp895cxi: ipp://print.ettle.lan/hp895cxi device for ml1210: ipp://print.ettle.lan/epsonr300 colour accepting requests since Mon 20 Oct 2008 08:47:26 BST double accepting requests since Mon 20 Oct 2008 08:46:11 BST epsonr300 accepting requests since Wed 17 Dec 2008 18:09:10 GMT hp895cxi accepting requests since Tue 23 Dec 2008 21:13:20 GMT ml1210 accepting requests since Wed 17 Dec 2008 18:07:01 GMT printer colour is idle. enabled since Mon 20 Oct 2008 08:47:26 BST printer double is idle. enabled since Mon 20 Oct 2008 08:46:11 BST printer epsonr300 is idle. enabled since Wed 17 Dec 2008 18:09:10 GMT printer hp895cxi now printing hp895cxi-0. enabled since Tue 23 Dec 2008 21:13:20 GMT Waiting for job to complete... printer ml1210 is idle. enabled since Wed 17 Dec 2008 18:07:01 GMT hp895cxi-100 james 17408 Tue 23 Dec 2008 21:13:03 GMT This is before I cancelled the job in the GNOME printer applet. Attached are access_log and error_log files (taken after the job was cancelled). Created attachment 327771 [details]
access_log after sticky job was cancelled
Created attachment 327772 [details]
error_log after sticky job was cancelled, using cupsctl --debug-logging
I should probably also point out that when I switch to LPD queues, the problem doesn't arise for me... James, please run this command: tcpdump -U -w ipp.pcap -s0 host print.ettle.lan and port 631 to start capturing the IPP network traffic, then submit a job to the queue. After leaving it for a minute or so, cancel the job, then press Control-C to stop the tcpdump command. Then please attach the ipp.pcap file here. Is it any particular type of IPP print server? Jonathan, for you the "remote server" is localhost so the UNIX domain socket will be used, and we can't use tcpdump. Would you be able to capture a complete strace of cupsd spawning the ipp backend? Use 'strace -f' to make sure it follows forks. I think what's happening here is that the ipp backend is in a loop asking for (a) the job attributes, and (b) the printer attributes. If the job attributes show that job-state is 'completed', we finish. For the printer attributes we just report them to the CUPS scheduler. However, in this case (looking at the strace attachment), in reply to the job attributes request we are getting a printer attributes response; and the printer attributes request gets a job attributes response. Somewhere along the way the ipp backend has become confused as to which reply corresponds to which request. I'm not entirely sure how this has happened, although it would be very useful if libcups would guard against it. At the moment it does not, and sets the request ID of each request to 1 instead of having different request IDs in each request and comparing them with the ID in the response. I have been unable to reproduce the issue since the one time it occurred, so there would be no point in stracing cupsd. SOLVED [maybe]! I have been having this same problem for quite a while. All of my documents get stuck in the queue and are "Processing since..." forever. Sometimes they would print after a while. Sometimes they would just disappear! But mostly, they just stayed in the queue. I believe I have found a simple solution: Unplug the printer, wait a minute or so, and plug it back in. I have a HP PSC 750, and noticed in my 'lpstat -t' that there were multiple printers listed - "PSC_750", "PSC_750-16", and "PSC_750-15". I figured something went wrong with some CUPS initialization, and threw a few extra printers in there for good measure. So I unplugged the printer, waited for all the devices to unregister, and plugged it back in. Now my 'lpstat -t' shows just a single PSC_750. This seems to have alleviated some Samba errors with the print queue not being found, as well. Could anyone else who is having this problem please post a report if this solution works for you. It may have been just a fluke, and needs to be tested before putting this bug to rest. [Sorry - I did not think to save a 'before' file of my lpstat out.] hi all i came across this thread, as i have the same problem. after enabling debug logging, following appears in the error log: <submitting the job> D [06/May/2009:11:33:57 +0200] cupsdAcceptClient: 8 from localhost:631 (IPv6) D [06/May/2009:11:33:57 +0200] Report: clients=1 D [06/May/2009:11:33:57 +0200] Report: jobs=4 D [06/May/2009:11:33:57 +0200] Report: jobs-active=0 D [06/May/2009:11:33:57 +0200] Report: printers=15 D [06/May/2009:11:33:57 +0200] Report: printers-implicit=0 D [06/May/2009:11:33:57 +0200] Report: stringpool-string-count=2201 D [06/May/2009:11:33:57 +0200] Report: stringpool-alloc-bytes=11416 D [06/May/2009:11:33:57 +0200] Report: stringpool-total-bytes=40656 D [06/May/2009:11:33:57 +0200] cupsdReadClient: 8 POST / HTTP/1.1 D [06/May/2009:11:33:57 +0200] cupsdAuthorize: No authentication data provided. D [06/May/2009:11:33:57 +0200] CUPS-Get-Printers D [06/May/2009:11:33:57 +0200] cupsdProcessIPPRequest: 8 status_code=0 (successful-ok) D [06/May/2009:11:33:57 +0200] cupsdReadClient: 8 POST / HTTP/1.1 D [06/May/2009:11:33:57 +0200] cupsdAuthorize: No authentication data provided. D [06/May/2009:11:33:57 +0200] CUPS-Get-Classes D [06/May/2009:11:33:57 +0200] cupsdProcessIPPRequest: 8 status_code=0 (successful-ok) D [06/May/2009:11:33:57 +0200] cupsdCloseClient: 8 D [06/May/2009:11:33:57 +0200] cupsdAcceptClient: 8 from localhost:631 (IPv6) D [06/May/2009:11:33:57 +0200] cupsdReadClient: 8 POST /printers/kyozaaltje HTTP/1.1 D [06/May/2009:11:33:57 +0200] cupsdAuthorize: No authentication data provided. D [06/May/2009:11:33:57 +0200] Print-Job ipp://localhost/printers/kyozaaltje D [06/May/2009:11:33:57 +0200] [Job ???] Auto-typing file... I [06/May/2009:11:33:57 +0200] [Job ???] Request file type is application/postscript. D [06/May/2009:11:33:57 +0200] add_job: requesting-user-name="filip" I [06/May/2009:11:33:57 +0200] [Job 5] Adding start banner page "none". D [06/May/2009:11:33:57 +0200] Discarding unused job-created event... I [06/May/2009:11:33:57 +0200] [Job 5] Adding end banner page "none". I [06/May/2009:11:33:57 +0200] [Job 5] File of type application/postscript queued by "filip". D [06/May/2009:11:33:57 +0200] [Job 5] hold_until=0 I [06/May/2009:11:33:57 +0200] [Job 5] Queued on "kyozaaltje" by "filip". D [06/May/2009:11:33:57 +0200] Discarding unused printer-state-changed event... D [06/May/2009:11:33:57 +0200] [Job 5] job-sheets=none,none D [06/May/2009:11:33:57 +0200] [Job 5] banner_page = 0 D [06/May/2009:11:33:57 +0200] [Job 5] argv[0]="kyozaaltje" D [06/May/2009:11:33:57 +0200] [Job 5] argv[1]="5" D [06/May/2009:11:33:57 +0200] [Job 5] argv[2]="filip" D [06/May/2009:11:33:57 +0200] [Job 5] argv[3]="(stdin)" D [06/May/2009:11:33:57 +0200] [Job 5] argv[4]="1" D [06/May/2009:11:33:57 +0200] [Job 5] argv[5]="media=A4 sides=one-sided finishings=3 number-up=1 job-uuid=urn:uuid:37a3d557-3c10-3e46-7b13-7da1eebf9824" D [06/May/2009:11:33:57 +0200] [Job 5] argv[6]="/var/spool/cups/d00005-001" D [06/May/2009:11:33:57 +0200] [Job 5] envp[0]="CUPS_CACHEDIR=/var/cache/cups" D [06/May/2009:11:33:57 +0200] [Job 5] envp[1]="CUPS_DATADIR=/usr/local/share/cups" D [06/May/2009:11:33:57 +0200] [Job 5] envp[2]="CUPS_DOCROOT=/usr/local/share/doc/cups" D [06/May/2009:11:33:57 +0200] [Job 5] envp[3]="CUPS_FONTPATH=/usr/local/share/cups/fonts" D [06/May/2009:11:33:57 +0200] [Job 5] envp[4]="CUPS_REQUESTROOT=/var/spool/cups" D [06/May/2009:11:33:57 +0200] [Job 5] envp[5]="CUPS_SERVERBIN=/usr/local/libexec/cups" D [06/May/2009:11:33:57 +0200] [Job 5] envp[6]="CUPS_SERVERROOT=/usr/local/etc/cups" D [06/May/2009:11:33:57 +0200] [Job 5] envp[7]="CUPS_STATEDIR=/var/run/cups" D [06/May/2009:11:33:57 +0200] [Job 5] envp[8]="PATH=/usr/local/libexec/cups/filter:/usr/local/bin:/usr/local/sbin:/bin:/usr/bin" D [06/May/2009:11:33:57 +0200] [Job 5] envp[9]="SERVER_ADMIN=root.net" D [06/May/2009:11:33:57 +0200] [Job 5] envp[10]="SOFTWARE=CUPS/1.3.9" D [06/May/2009:11:33:57 +0200] [Job 5] envp[11]="TMPDIR=/var/spool/cups/tmp" D [06/May/2009:11:33:57 +0200] [Job 5] envp[12]="USER=root" D [06/May/2009:11:33:57 +0200] [Job 5] envp[13]="CUPS_SERVER=localhost" D [06/May/2009:11:33:57 +0200] [Job 5] envp[14]="CUPS_ENCRYPTION=IfRequested" D [06/May/2009:11:33:57 +0200] [Job 5] envp[15]="IPP_PORT=631" D [06/May/2009:11:33:57 +0200] [Job 5] envp[16]="CHARSET=utf-8" D [06/May/2009:11:33:57 +0200] [Job 5] envp[17]="LANG=en_US.UTF8" D [06/May/2009:11:33:57 +0200] [Job 5] envp[18]="PPD=/usr/local/etc/cups/ppd/kyozaaltje.ppd" D [06/May/2009:11:33:57 +0200] [Job 5] envp[19]="RIP_MAX_CACHE=8m" D [06/May/2009:11:33:57 +0200] [Job 5] envp[20]="CONTENT_TYPE=application/postscript" D [06/May/2009:11:33:57 +0200] [Job 5] envp[21]="DEVICE_URI=ipp://10.153.6.141:631/ipp" D [06/May/2009:11:33:57 +0200] [Job 5] envp[22]="PRINTER=kyozaaltje" D [06/May/2009:11:33:57 +0200] [Job 5] envp[23]="FINAL_CONTENT_TYPE=application/vnd.cups-postscript" I [06/May/2009:11:33:57 +0200] [Job 5] Started filter /usr/local/libexec/cups/filter/pstops (PID 62397) I [06/May/2009:11:33:57 +0200] [Job 5] Started backend /usr/local/libexec/cups/backend/ipp (PID 62398) D [06/May/2009:11:33:57 +0200] Discarding unused job-state-changed event... D [06/May/2009:11:33:57 +0200] cupsdProcessIPPRequest: 8 status_code=0 (successful-ok) D [06/May/2009:11:33:58 +0200] PID 62397 (/usr/local/libexec/cups/filter/pstops) exited with no errors. D [06/May/2009:11:33:58 +0200] [Job 5] Page = 595x842; 12,10 to 583,832 D [06/May/2009:11:33:58 +0200] [Job 5] slow_collate=0, slow_duplex=0, slow_order=0 D [06/May/2009:11:33:58 +0200] [Job 5] Before copy_comments - %!PS-Adobe-2.0 D [06/May/2009:11:33:58 +0200] [Job 5] %!PS-Adobe-2.0 D [06/May/2009:11:33:58 +0200] [Job 5] %%Creator: "barcode", libbarcode sample frontend D [06/May/2009:11:33:58 +0200] [Job 5] %%DocumentPaperSizes: A4 D [06/May/2009:11:33:58 +0200] [Job 5] %%EndComments E [06/May/2009:11:33:58 +0200] [Job 5] No %%BoundingBox: comment in header! E [06/May/2009:11:33:58 +0200] [Job 5] No %%Pages: comment in header! D [06/May/2009:11:33:58 +0200] [Job 5] Before copy_prolog - %%EndProlog D [06/May/2009:11:33:58 +0200] [Job 5] Before copy_setup - %%Page: 1 1 D [06/May/2009:11:33:58 +0200] [Job 5] Before page loop - %%Page: 1 1 D [06/May/2009:11:33:58 +0200] [Job 5] Copying page 1... D [06/May/2009:11:33:58 +0200] Discarding unused job-progress event... D [06/May/2009:11:33:58 +0200] [Job 5] pagew = 571.0, pagel = 822.0 D [06/May/2009:11:33:58 +0200] [Job 5] bboxx = 0, bboxy = 0, bboxw = 595, bboxl = 842 D [06/May/2009:11:33:58 +0200] [Job 5] PageLeft = 12.0, PageRight = 583.0 D [06/May/2009:11:33:58 +0200] [Job 5] PageTop = 832.0, PageBottom = 10.0 D [06/May/2009:11:33:58 +0200] [Job 5] PageWidth = 595.0, PageLength = 842.0 D [06/May/2009:11:33:58 +0200] [Job 5] Wrote 1 pages... D [06/May/2009:11:33:58 +0200] [Job 5] 1 files to send in job... D [06/May/2009:11:33:58 +0200] [Job 5] Connected to 10.153.6.141:631 (IPv4)... D [06/May/2009:11:33:58 +0200] [Job 5] Getting supported attributes... D [06/May/2009:11:33:58 +0200] Discarding unused printer-state-changed event... D [06/May/2009:11:33:58 +0200] cupsdCloseClient: 8 D [06/May/2009:11:34:00 +0200] [Job 5] document-format-supported (2 values) D [06/May/2009:11:34:00 +0200] [0] = "application/octet-stream" D [06/May/2009:11:34:00 +0200] [1] = "text/plain; charset=us-ascii" D [06/May/2009:11:34:00 +0200] [Job 5] printer-uri = "ipp://10.153.6.141:631/ipp" D [06/May/2009:11:34:00 +0200] [Job 5] requesting-user-name = "filip" D [06/May/2009:11:34:00 +0200] [Job 5] job-name = "(stdin)" D [06/May/2009:11:34:00 +0200] Discarding unused printer-state-changed event... N [06/May/2009:11:34:07 +0200] [Job 5] Print file accepted - job ID 15. D [06/May/2009:11:35:03 +0200] Report: clients=0 D [06/May/2009:11:35:03 +0200] Report: jobs=5 D [06/May/2009:11:35:03 +0200] Report: jobs-active=1 D [06/May/2009:11:35:03 +0200] Report: printers=15 D [06/May/2009:11:35:03 +0200] Report: printers-implicit=0 D [06/May/2009:11:35:03 +0200] Report: stringpool-string-count=2247 D [06/May/2009:11:35:03 +0200] Report: stringpool-alloc-bytes=12272 D [06/May/2009:11:35:03 +0200] Report: stringpool-total-bytes=41528 D [06/May/2009:11:36:09 +0200] Report: clients=0 D [06/May/2009:11:36:09 +0200] Report: jobs=5 D [06/May/2009:11:36:09 +0200] Report: jobs-active=1 D [06/May/2009:11:36:09 +0200] Report: printers=15 D [06/May/2009:11:36:09 +0200] Report: printers-implicit=0 D [06/May/2009:11:36:09 +0200] Report: stringpool-string-count=2247 D [06/May/2009:11:36:09 +0200] Report: stringpool-alloc-bytes=12272 D [06/May/2009:11:36:09 +0200] Report: stringpool-total-bytes=41528 D [06/May/2009:11:37:15 +0200] Report: clients=0 D [06/May/2009:11:37:15 +0200] Report: jobs=5 D [06/May/2009:11:37:15 +0200] Report: jobs-active=1 D [06/May/2009:11:37:15 +0200] Report: printers=15 D [06/May/2009:11:37:15 +0200] Report: printers-implicit=0 D [06/May/2009:11:37:15 +0200] Report: stringpool-string-count=2247 D [06/May/2009:11:37:15 +0200] Report: stringpool-alloc-bytes=12272 D [06/May/2009:11:37:15 +0200] Report: stringpool-total-bytes=41528 <lpq command: job is still in queue although printing is done> D [06/May/2009:11:38:11 +0200] cupsdAcceptClient: 8 from localhost:631 (IPv6) D [06/May/2009:11:38:11 +0200] cupsdReadClient: 8 POST / HTTP/1.1 D [06/May/2009:11:38:11 +0200] cupsdAuthorize: No authentication data provided. D [06/May/2009:11:38:11 +0200] CUPS-Get-Printers D [06/May/2009:11:38:11 +0200] cupsdProcessIPPRequest: 8 status_code=0 (successful-ok) D [06/May/2009:11:38:11 +0200] cupsdReadClient: 8 POST / HTTP/1.1 D [06/May/2009:11:38:11 +0200] cupsdAuthorize: No authentication data provided. D [06/May/2009:11:38:11 +0200] CUPS-Get-Classes D [06/May/2009:11:38:11 +0200] cupsdProcessIPPRequest: 8 status_code=0 (successful-ok) D [06/May/2009:11:38:11 +0200] cupsdReadClient: 8 POST / HTTP/1.1 D [06/May/2009:11:38:11 +0200] cupsdAuthorize: No authentication data provided. D [06/May/2009:11:38:11 +0200] Get-Printer-Attributes ipp://localhost/printers/kyozaaltje D [06/May/2009:11:38:11 +0200] cupsdProcessIPPRequest: 8 status_code=0 (successful-ok) D [06/May/2009:11:38:11 +0200] cupsdReadClient: 8 POST / HTTP/1.1 D [06/May/2009:11:38:11 +0200] cupsdAuthorize: No authentication data provided. D [06/May/2009:11:38:11 +0200] Get-Jobs ipp://localhost/printers/kyozaaltje D [06/May/2009:11:38:11 +0200] cupsdProcessIPPRequest: 8 status_code=0 (successful-ok) D [06/May/2009:11:38:11 +0200] cupsdCloseClient: 8 <lprm 5 command> D [06/May/2009:11:38:23 +0200] Report: clients=0 D [06/May/2009:11:38:23 +0200] Report: jobs=5 D [06/May/2009:11:38:23 +0200] Report: jobs-active=1 D [06/May/2009:11:38:23 +0200] Report: printers=15 D [06/May/2009:11:38:23 +0200] Report: printers-implicit=0 D [06/May/2009:11:38:23 +0200] Report: stringpool-string-count=2247 D [06/May/2009:11:38:23 +0200] Report: stringpool-alloc-bytes=12272 D [06/May/2009:11:38:23 +0200] Report: stringpool-total-bytes=41528 D [06/May/2009:11:38:28 +0200] cupsdAcceptClient: 8 from localhost:631 (IPv6) D [06/May/2009:11:38:28 +0200] cupsdReadClient: 8 POST / HTTP/1.1 D [06/May/2009:11:38:28 +0200] cupsdAuthorize: No authentication data provided. D [06/May/2009:11:38:28 +0200] CUPS-Get-Printers D [06/May/2009:11:38:28 +0200] cupsdProcessIPPRequest: 8 status_code=0 (successful-ok) D [06/May/2009:11:38:28 +0200] cupsdReadClient: 8 POST / HTTP/1.1 D [06/May/2009:11:38:28 +0200] cupsdAuthorize: No authentication data provided. D [06/May/2009:11:38:28 +0200] CUPS-Get-Classes D [06/May/2009:11:38:28 +0200] cupsdProcessIPPRequest: 8 status_code=0 (successful-ok) D [06/May/2009:11:38:28 +0200] cupsdReadClient: 8 POST /jobs/ HTTP/1.1 D [06/May/2009:11:38:28 +0200] cupsdAuthorize: No authentication data provided. D [06/May/2009:11:38:28 +0200] Cancel-Job ipp://localhost/jobs/5 D [06/May/2009:11:38:28 +0200] cupsdIsAuthorized: requesting-user-name="filip" D [06/May/2009:11:38:28 +0200] Discarding unused printer-state-changed event... D [06/May/2009:11:38:28 +0200] Discarding unused job-completed event... I [06/May/2009:11:38:28 +0200] [Job 5] Canceled by "filip". D [06/May/2009:11:38:28 +0200] cupsdProcessIPPRequest: 8 status_code=0 (successful-ok) D [06/May/2009:11:38:28 +0200] cupsdCloseClient: 8 D [06/May/2009:11:38:29 +0200] [Job 5] Unloading... cups 1.3.9 is used filip: please only report bugs here when you are using the RPMs provided. I need more information about this, as noted in comment #14. I cannot proceed to diagnose the problem without a TCP capture. This bug appears to have been reported against 'rawhide' during the Fedora 11 development cycle. Changing version to '11'. More information and reason for this action is here: http://fedoraproject.org/wiki/BugZappers/HouseKeeping *PING* I need more information about this, as noted in comment #14. I cannot proceed to diagnose the problem without a TCP capture. Created attachment 351654 [details] Requested data (In reply to comment #14) > James, please run this command: > > tcpdump -U -w ipp.pcap -s0 host print.ettle.lan and port 631 > > to start capturing the IPP network traffic, then submit a job to the queue. > After leaving it for a minute or so, cancel the job, then press Control-C to > stop the tcpdump command. Then please attach the ipp.pcap file here. So sorry this is so late, Tim --- totally missed it. ipp.pcap attached. This is from cups-1.4-0.rc1.7.fc11.x86_64 > Is it any particular type of IPP print server? Edimax PS-3207U James: thank you. Could I ask you one more thing? I can understand how the job gets stuck, and have a fix for it, but I'd like to understand why the job cancellation also gets stuck. Please install cups-debuginfo, the same version as the cups package: yum --enablerepo=updates-testing-debuginfo install cups-debuginfo Then, having done that, restart CUPS: /sbin/service cups restart Then, send a job to the printer again, and after a little while cancel it, as before. Next, take a look to find the process ID of the 'ipp' process, which will be a child of 'cupsd': ps axf Next, attach the debugger to it and find out where it is. First, make a log of the session: script This creates a file 'typescript' containing the transcript of what follows. Now run the debugger: gdb /usr/lib/cups/backend/ipp $PID (replace $PID with the process ID you discovered for the ipp process). At the '(gdb)' prompt, type 'bt' and press enter. You should see a stack trace showing where the execution actually is. Hopefully 'cupsDoIORequest' will be in there somewhere. Now keep entering 'finish' at the (gdb) prompt until it no longer gives you back the prompt. At that point, press Control-C, then enter 'quit'. Finally, back at the shell prompt enter 'exit' and you should see this: Script done, file is typescript Attach the typescript file to this bug report. Sorry the instructions are so lengthy! Created attachment 354250 [details]
Script of gdb backtraces for CUPS IPP backend
(Info requested by Tim in comment above.)
Tim, I'd like to report this to my print server's manufacturer, but I don't know where to begin... I guess here: http://www.edimax.com/en/support_tech.php This is a concise description of the problem: http://cups.org/str.php?L3262 Thanks for the gdb output. cups-1.4-0.rc1.12.fc11 has been submitted as an update for Fedora 11. http://admin.fedoraproject.org/updates/cups-1.4-0.rc1.12.fc11 cups-1.4-0.rc1.12.fc11 has been pushed to the Fedora 11 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: http://admin.fedoraproject.org/updates/F11/FEDORA-2009-8133 cups-1.4-0.rc1.14.fc11 has been pushed to the Fedora 11 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: http://admin.fedoraproject.org/updates/F11/FEDORA-2009-8133 Testing so far on my set-up, this seems fixed --- jobs pop off the queue successfully (CUPS notes correctly that it is "Unable to get job-state for job nnnn!") and it no longer blocks. cups-1.4-0.rc1.15.fc11 has been pushed to the Fedora 11 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: http://admin.fedoraproject.org/updates/F11/FEDORA-2009-8133 cups-1.4-0.rc1.15.fc11 has been pushed to the Fedora 11 stable repository. If problems still persist, please make note of it in this bug report. |
Created attachment 326873 [details] strace log file cups-1.4-0.b1.4.fc11.i386 from rawhide (with mostly other current rawhide packages). Printer "draft" is Generic PCL 5e Printer Foomatic/hpijs. Its device is ipp://localhost/printers/raw. Printer "raw" is a raw printer whose device is socket://dell3000cn:9100. I have a job every morning that fetches and prints a bunch of files for me. Some of those files go through the "draft" printer, while others go through the "color" printer, which is a Generic PCL 6/PCL XL Printer Foomatic/pxlmono which also uses the device ipp://localhost/printers/raw. The jobs send to "draft" and "color" are intermixed with each other. This morning, one job went to "draft", the rest went to "color". The job that went to "draft" printed properly mixed in with all the other printouts. But when I look at the queue for the "draft" printer now, over two hours later, it's still there: $ lpq -Pdraft draft is ready and printing Rank Owner Job File(s) Total Size active jik 16068 (stdin) 23552 bytes There is nothing in /var/log/cups/error_log (it's empty), and there's nothing in /var/log/cups/access_log which would explain this -- all POSTs in access_log show an okay result status. I do see that the "ipp" process for this job seems to still be running: root 6277 0.0 0.1 6076 2308 ? S 07:14 0:00 ipp://localhost/printers/raw 16068 jik (stdin) 1 number-up=1 media=Letter sides=one-sided finishings=3 job-uuid=urn:uuid:fd43a968-328d-3cbf-6819-2bcf45c91674 job-originating-host-name=localhost I just attached to it with strace, and it seems to be trying to send the job over and over again or something. I can't make much sense of it, but I'll attach the log in case you might be able to.