Bug 476424 - job stays in queue after printing
job stays in queue after printing
Status: CLOSED ERRATA
Product: Fedora
Classification: Fedora
Component: cups (Show other bugs)
11
All Linux
low Severity medium
: ---
: ---
Assigned To: Tim Waugh
Fedora Extras Quality Assurance
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2008-12-14 09:49 EST by Jonathan Kamens
Modified: 2009-08-15 04:26 EDT (History)
5 users (show)

See Also:
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 04:26:56 EDT
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
strace log file (71.03 KB, text/plain)
2008-12-14 09:49 EST, Jonathan Kamens
no flags Details
cupsd.conf file (4.07 KB, text/plain)
2008-12-15 08:58 EST, Jonathan Kamens
no flags Details
access_log after sticky job was cancelled (26.67 KB, text/plain)
2008-12-23 16:21 EST, James
no flags Details
error_log after sticky job was cancelled, using cupsctl --debug-logging (56.12 KB, text/plain)
2008-12-23 16:22 EST, James
no flags Details
Requested data (4.07 MB, application/octet-stream)
2009-07-14 15:04 EDT, James
no flags Details
Script of gdb backtraces for CUPS IPP backend (8.36 KB, text/plain)
2009-07-18 07:37 EDT, James
no flags Details


External Trackers
Tracker ID Priority Status Summary Last Updated
CUPS Bugs and Features 3262 None None None Never

  None (edit)
Description Jonathan Kamens 2008-12-14 09:49:02 EST
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.
Comment 1 Tim Waugh 2008-12-15 05:18:49 EST
What does 'lpstat -t' say?
Comment 2 Tim Waugh 2008-12-15 05:21:49 EST
(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?
Comment 3 Jonathan Kamens 2008-12-15 08:57:36 EST
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.
Comment 4 Jonathan Kamens 2008-12-15 08:58:15 EST
Created attachment 326944 [details]
cupsd.conf file
Comment 5 Tim Waugh 2008-12-19 09:00:51 EST
Can you attach the error_log-200812* file that corresponds to the original problem please?
Comment 6 Jonathan Kamens 2008-12-19 09:07:34 EST
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.
Comment 7 Tim Waugh 2008-12-19 09:38:19 EST
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.
Comment 8 Jonathan Kamens 2008-12-19 10:39:20 EST
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.
Comment 9 Tim Waugh 2008-12-19 10:57:30 EST
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.
Comment 10 James 2008-12-23 16:20:30 EST
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).
Comment 11 James 2008-12-23 16:21:19 EST
Created attachment 327771 [details]
access_log after sticky job was cancelled
Comment 12 James 2008-12-23 16:22:08 EST
Created attachment 327772 [details]
error_log after sticky job was cancelled, using cupsctl --debug-logging
Comment 13 James 2008-12-23 16:29:26 EST
I should probably also point out that when I switch to LPD queues, the problem doesn't arise for me...
Comment 14 Tim Waugh 2009-01-29 10:49:22 EST
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.
Comment 15 Jonathan Kamens 2009-01-29 11:13:25 EST
I have been unable to reproduce the issue since the one time it occurred, so there would be no point in stracing cupsd.
Comment 16 Samuel C. Tyler 2009-02-11 08:02:46 EST
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.]
Comment 17 filip 2009-05-06 05:52:45 EDT
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@fnix.nsn-intra.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
Comment 18 Tim Waugh 2009-05-06 06:45:44 EDT
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.
Comment 19 Bug Zapper 2009-06-09 06:15:48 EDT
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
Comment 20 Tim Waugh 2009-06-09 07:08:16 EDT
*PING*

I need more information about this, as noted in comment #14.  I cannot proceed
to diagnose the problem without a TCP capture.
Comment 21 James 2009-07-14 15:04:55 EDT
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
Comment 22 Tim Waugh 2009-07-15 09:01:49 EDT
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!
Comment 23 James 2009-07-18 07:37:39 EDT
Created attachment 354250 [details]
Script of gdb backtraces for CUPS IPP backend

(Info requested by Tim in comment above.)
Comment 24 James 2009-07-20 06:21:10 EDT
Tim, I'd like to report this to my print server's manufacturer, but I don't know where to begin...
Comment 25 Tim Waugh 2009-07-20 06:54:09 EDT
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.
Comment 26 Fedora Update System 2009-07-29 12:16:39 EDT
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
Comment 27 Fedora Update System 2009-07-31 14:01:33 EDT
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
Comment 28 Fedora Update System 2009-08-07 01:07:32 EDT
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
Comment 29 James 2009-08-10 11:00:42 EDT
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.
Comment 30 Fedora Update System 2009-08-11 18:40:13 EDT
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
Comment 31 Fedora Update System 2009-08-15 04:26:06 EDT
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.

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