client-error-bad-request with some IPP print jobs

[Adam Nielsen]

Hi,

I've discovered that when printing certain PDF files under Linux to a CUPS printer I get a strange 'client-error-bad-request' message, and CUPS stops the printer.  This means that any 'bad' jobs like these aren't ignored/skipped, but they hold up everyone else's print jobs.  I have to go in by hand to the CUPS admin page and cancel the offending job, then start the printer, and only then the other queued jobs will resume printing.

Does anyone know why this happens?  I'm printing to a local CUPS printer, which is configured via IPP to connect to a remote print server (also running CUPS) which is in turn configured to send jobs direct to the printer via IPP.  My local CUPS doesn't have a problem with the jobs, but the remote CUPS seems to be getting an IPP error from the printer itself which is causing it to refuse further print jobs.

I set the log level to 'debug' and the relevant section is below.  The offending job is actually printed successfully, so I'm wondering whether the problem is that the job completes and is removed from the printer *before* CUPS has a chance to query its status, so when the printer says 'job not found' CUPS gets confused.

Any ideas?

Thanks,
Adam.

D [13/Feb/2006:09:27:48 +1000] AcceptClient: 5 from 192.168.173.208:631.
D [13/Feb/2006:09:27:48 +1000] ReadClient: 5 POST /printers/ricoh1060 HTTP/1.1
D [13/Feb/2006:09:27:48 +1000] ProcessIPPRequest: 5 status_code=1
D [13/Feb/2006:09:27:48 +1000] ReadClient: 5 POST /printers/ricoh1060 HTTP/1.1
D [13/Feb/2006:09:27:48 +1000] print_job: request file type is application/vnd.cups-raw.
D [13/Feb/2006:09:27:48 +1000] check_quotas: requesting-user-name = 'adam'
D [13/Feb/2006:09:27:48 +1000] print_job: requesting-user-name = 'adam'
D [13/Feb/2006:09:27:48 +1000] Adding default job-sheets values "none,none"...
I [13/Feb/2006:09:27:48 +1000] Adding start banner page "none" to job 653.
I [13/Feb/2006:09:27:48 +1000] Adding end banner page "none" to job 653.
I [13/Feb/2006:09:27:48 +1000] Job 653 queued on 'ricoh1060' by 'adam'.
D [13/Feb/2006:09:27:48 +1000] Job 653 hold_until = 0
D [13/Feb/2006:09:27:48 +1000] StartJob(653, 0x8152ce0)
D [13/Feb/2006:09:27:48 +1000] StartJob() id = 653, file = 0/1
D [13/Feb/2006:09:27:48 +1000] job-sheets=none,none
D [13/Feb/2006:09:27:48 +1000] banner_page = 0
D [13/Feb/2006:09:27:48 +1000] StartJob: argv = "ricoh1060","653","adam","Acro000Eip1hI","1","","/var/spool/cups/d00653-001"
D [13/Feb/2006:09:27:48 +1000] StartJob: envp[0]="PATH=/usr/lib/cups/filter:/bin:/usr/bin"
D [13/Feb/2006:09:27:48 +1000] StartJob: envp[1]="SOFTWARE=CUPS/1.1"
D [13/Feb/2006:09:27:48 +1000] StartJob: envp[2]="USER=root"
D [13/Feb/2006:09:27:48 +1000] StartJob: envp[3]="CHARSET=iso-8859-1"
D [13/Feb/2006:09:27:48 +1000] StartJob: envp[4]="LANG=en_US"
D [13/Feb/2006:09:27:48 +1000] StartJob: envp[5]="PPD=/etc/cups/ppd/ricoh1060.ppd"
D [13/Feb/2006:09:27:48 +1000] StartJob: envp[6]="CUPS_SERVERROOT=/etc/cups"
D [13/Feb/2006:09:27:48 +1000] StartJob: envp[7]="RIP_MAX_CACHE=8m"
D [13/Feb/2006:09:27:48 +1000] StartJob: envp[8]="TMPDIR=/var/spool/cups/tmp"
D [13/Feb/2006:09:27:48 +1000] StartJob: envp[9]="CONTENT_TYPE=application/vnd.cups-raw"
D [13/Feb/2006:09:27:48 +1000] StartJob: envp[10]="DEVICE_URI=ipp://ricoh1060.research.uq.edu.au/printer"
D [13/Feb/2006:09:27:48 +1000] StartJob: envp[11]="PRINTER=ricoh1060"
D [13/Feb/2006:09:27:48 +1000] StartJob: envp[12]="CUPS_DATADIR=/usr/share/cups"
D [13/Feb/2006:09:27:48 +1000] StartJob: envp[13]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [13/Feb/2006:09:27:48 +1000] StartJob: envp[14]="CUPS_SERVER=localhost"
D [13/Feb/2006:09:27:48 +1000] StartJob: envp[15]="IPP_PORT=631"
D [13/Feb/2006:09:27:48 +1000] StartJob: statusfds = [ 7 8 ]
D [13/Feb/2006:09:27:48 +1000] StartJob: filterfds[1] = [ 9 -1 ]
D [13/Feb/2006:09:27:48 +1000] StartJob: backend = "/usr/lib/cups/backend/ipp"
D [13/Feb/2006:09:27:48 +1000] StartJob: filterfds[0] = [ -1 10 ]
D [13/Feb/2006:09:27:48 +1000] start_process("/usr/lib/cups/backend/ipp", 0xbfb67a60, 0xbfb66dd0, 9, 10, 8)
I [13/Feb/2006:09:27:48 +1000] Started backend /usr/lib/cups/backend/ipp (PID 3447) for job 653.
D [13/Feb/2006:09:27:48 +1000] ProcessIPPRequest: 5 status_code=0
D [13/Feb/2006:09:27:48 +1000] ReadClient: 5 POST /printers/ricoh1060 HTTP/1.1
D [13/Feb/2006:09:27:48 +1000] ProcessIPPRequest: 5 status_code=1
D [13/Feb/2006:09:27:48 +1000] CloseClient: 5
D [13/Feb/2006:09:27:49 +1000] [Job 653] Getting supported attributes...
D [13/Feb/2006:09:27:49 +1000] [Job 653] document-format-supported (1 values)
D [13/Feb/2006:09:27:49 +1000] [Job 653] [0] = "application/octet-stream"
D [13/Feb/2006:09:27:49 +1000] [Job 653] printer-uri = "ipp://ricoh1060:631/printer"
D [13/Feb/2006:09:27:49 +1000] [Job 653] requesting-user-name = "adam"
D [13/Feb/2006:09:27:49 +1000] [Job 653] job-name = "Acro000Eip1hI"
N [13/Feb/2006:09:27:49 +1000] [Job 653] : Print file accepted - job ID 789.
E [13/Feb/2006:09:27:49 +1000] [Job 653] Unable to get job 789 attributes (client-error-bad-request)!
E [13/Feb/2006:09:27:49 +1000] PID 3447 stopped with status 1!
D [13/Feb/2006:09:27:49 +1000] UpdateJob: job 653, file 0 is complete.
D [13/Feb/2006:09:27:49 +1000] StopJob: id = 653, force = 0
I [13/Feb/2006:09:27:49 +1000] Saving printers.conf...
D [13/Feb/2006:09:27:49 +1000] StopJob: printer state is 5