Jobs disappear and not printed

Fri May 11 03:58:26 PDT 2007

Katya wrote:
> Hello,
> 
> I've got such problem: I send job for printing in two printers hp4 and hp5, hp4 is all right, but hp5 is not. In lpq -Php5 I see this job-id, then it disappears, but printer doesn't print this job. I restart printer manually and everything is OK, printer starts printing. But what's the reason of such problem? I've got cups 1.2.10, HP LaserJet 8000 Ni as hp5
> Here is an extract from error-log:
> I [08/May/2007:13:23:59 +0400] Adding start banner page "none" to job 348.
> I [08/May/2007:13:23:59 +0400] Adding end banner page "none" to job 348.
> I [08/May/2007:13:23:59 +0400] Job 348 queued on "hp5" by "shrek".
> D [08/May/2007:13:23:59 +0400] Job 348 hold_until = 0
> D [08/May/2007:13:23:59 +0400] [Job 348] argv[0]="hp5"
> D [08/May/2007:13:23:59 +0400] [Job 348] argv[1]="348"
> D [08/May/2007:13:23:59 +0400] [Job 348] argv[2]="shrek"
> D [08/May/2007:13:23:59 +0400] [Job 348] argv[3]="Безымянный1"
> D [08/May/2007:13:23:59 +0400] [Job 348] argv[4]="1"
> D [08/May/2007:13:23:59 +0400] [Job 348] argv[5]="Resolution=600x1200dpi HPUserName=FileSharingName HPJobName=DocName MediaType=Plain noManualFeed InputSlot=Upper PageSize=A4 Duplex=None HPwmBrightness=Medium HPwmTextMessage=Draft HPwmFontName=HelveticaB HPwmTextAngle=Deg45 HPwmTextStyle=Medium HPwmFontSize=pt48 HPwmPages=AllPages number-up=1 OutputBin=Upper job-uuid=urn:uuid:7cf36900-9980-3a7b-4eb4-234686566ae2"
> D [08/May/2007:13:23:59 +0400] [Job 348] argv[6]="/var/spool/cups/d00348-001"
> D [08/May/2007:13:23:59 +0400] [Job 348] envp[0]="CUPS_CACHEDIR=/var/cache/cups"
> D [08/May/2007:13:23:59 +0400] [Job 348] envp[1]="CUPS_DATADIR=/usr/share/cups"
> D [08/May/2007:13:23:59 +0400] [Job 348] envp[2]="CUPS_DOCROOT=/usr/share/doc/cups-1.2.10"
> D [08/May/2007:13:23:59 +0400] [Job 348] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts"
> D [08/May/2007:13:23:59 +0400] [Job 348] envp[4]="CUPS_REQUESTROOT=/var/spool/cups"
> D [08/May/2007:13:23:59 +0400] [Job 348] envp[5]="CUPS_SERVERBIN=/usr/lib/cups"
> D [08/May/2007:13:23:59 +0400] [Job 348] envp[6]="CUPS_SERVERROOT=/etc/cups"
> D [08/May/2007:13:23:59 +0400] [Job 348] envp[7]="CUPS_STATEDIR=/var/run/cups"
> D [08/May/2007:13:23:59 +0400] [Job 348] envp[8]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
> D [08/May/2007:13:23:59 +0400] [Job 348] envp[9]="SERVER_ADMIN=root at qcl4.ihep.su"
> D [08/May/2007:13:23:59 +0400] [Job 348] envp[10]="SOFTWARE=CUPS/1.2.10"
> D [08/May/2007:13:23:59 +0400] [Job 348] envp[11]="TMPDIR=/var/spool/cups/tmp"
> D [08/May/2007:13:23:59 +0400] [Job 348] envp[12]="USER=root"
> D [08/May/2007:13:23:59 +0400] [Job 348] envp[13]="CUPS_SERVER=/var/run/cups/cups.sock"
> D [08/May/2007:13:23:59 +0400] [Job 348] envp[14]="CUPS_ENCRYPTION=IfRequested"
> D [08/May/2007:13:23:59 +0400] [Job 348] envp[15]="IPP_PORT=631"
> D [08/May/2007:13:23:59 +0400] [Job 348] envp[16]="CHARSET=utf-8"
> D [08/May/2007:13:23:59 +0400] [Job 348] envp[17]="LANG=ru_RU"
> D [08/May/2007:13:23:59 +0400] [Job 348] envp[18]="PPD=/etc/cups/ppd/hp5.ppd"
> D [08/May/2007:13:23:59 +0400] [Job 348] envp[19]="RIP_MAX_CACHE=8m"
> D [08/May/2007:13:23:59 +0400] [Job 348] envp[20]="CONTENT_TYPE=application/postscript"
> D [08/May/2007:13:23:59 +0400] [Job 348] envp[21]="DEVICE_URI=jasmine:socket://172.22.1.5"
> D [08/May/2007:13:23:59 +0400] [Job 348] envp[22]="PRINTER=hp5"
> D [08/May/2007:13:23:59 +0400] [Job 348] envp[23]="FINAL_CONTENT_TYPE=application/vnd.cups-postscript"
> I [08/May/2007:13:23:59 +0400] Started filter /usr/lib/cups/filter/pstops (PID 8352) for job 348.
> I [08/May/2007:13:23:59 +0400] Started backend /usr/lib/cups/backend/jasmine (PID 8353) for job 348.
> D [08/May/2007:13:23:59 +0400] [Job 348] Page = 595x842; 12,12 to 583,829
> D [08/May/2007:13:23:59 +0400] [Job 348] slow_collate=0, slow_duplex=0, slow_order=0
> D [08/May/2007:13:23:59 +0400] [Job 348] Before copy_comments - %!PS-Adobe-3.0
> D [08/May/2007:13:23:59 +0400] [Job 348] %!PS-Adobe-3.0
> D [08/May/2007:13:23:59 +0400] [Job 348] %%BoundingBox: (atend)
> D [08/May/2007:13:23:59 +0400] [Job 348] %%Creator: OpenOffice.org 2.0
> D [08/May/2007:13:23:59 +0400] [Job 348] %%For: shrek
> D [08/May/2007:13:23:59 +0400] [Job 348] %%CreationDate: Tue May  8 13:22:53 2007
> D [08/May/2007:13:23:59 +0400] [Job 348] %%Title: ??????????1
> D [08/May/2007:13:23:59 +0400] [Job 348] %%LanguageLevel: 2
> D [08/May/2007:13:23:59 +0400] [Job 348] %%DocumentData: Clean7Bit
> D [08/May/2007:13:23:59 +0400] [Job 348] %%Pages: (atend)
> D [08/May/2007:13:23:59 +0400] [Job 348] %%PageOrder: Ascend
> D [08/May/2007:13:23:59 +0400] [Job 348] %%EndComments
> D [08/May/2007:13:23:59 +0400] [Job 348] Before copy_prolog - %%BeginProlog
> D [08/May/2007:13:23:59 +0400] [Job 348] Before copy_setup - %%BeginSetup
> D [08/May/2007:13:23:59 +0400] [Job 348] Before page loop - %%Page: 1 1
> D [08/May/2007:13:23:59 +0400] [Job 348] Copying page 1...
> D [08/May/2007:13:23:59 +0400] [Job 348] pagew = 571.0, pagel = 817.4
> D [08/May/2007:13:23:59 +0400] [Job 348] bboxw = 595, bboxl = 842
> D [08/May/2007:13:23:59 +0400] [Job 348] PageLeft = 12.0, PageRight = 583.0
> D [08/May/2007:13:23:59 +0400] [Job 348] PageTop = 829.4, PageBottom = 12.0
> D [08/May/2007:13:23:59 +0400] [Job 348] PageWidth = 595.0, PageLength = 842.0
> D [08/May/2007:13:23:59 +0400] [Job 348] Wrote 1 pages...
> D [08/May/2007:13:23:59 +0400] [Job 348] Unknown Value type 0x13 for key "time-at-completed". Performing no transformation. at /usr/lib/perl5/site_perl/5.8.8/Net/IPP/IPPRequest.pm line 230
> D [08/May/2007:13:24:00 +0400] [Job 348] Connected to 172.22.1.5:9100 (IPv4)...
> D [08/May/2007:13:24:00 +0400] [Job 348] backendRunLoop(print_fd=4, device_fd=5, use_bc=1)
> D [08/May/2007:13:24:00 +0400] [Job 348] Read 8192 bytes of print data...
> D [08/May/2007:13:24:00 +0400] [Job 348] Wrote 8192 bytes of print data...
> D [08/May/2007:13:24:00 +0400] [Job 348] Read 8192 bytes of print data...
> D [08/May/2007:13:24:00 +0400] [Job 348] Wrote 8192 bytes of print data...
> D [08/May/2007:13:24:00 +0400] [Job 348] Read 8192 bytes of print data...
> D [08/May/2007:13:24:00 +0400] [Job 348] Wrote 8192 bytes of print data...
> D [08/May/2007:13:24:00 +0400] [Job 348] Read 8192 bytes of print data...
> D [08/May/2007:13:24:00 +0400] [Job 348] Wrote 8192 bytes of print data...
> D [08/May/2007:13:24:00 +0400] [Job 348] Read 8192 bytes of print data...
> D [08/May/2007:13:24:00 +0400] [Job 348] Wrote 8192 bytes of print data...
> D [08/May/2007:13:24:00 +0400] [Job 348] Read 8192 bytes of print data...
> D [08/May/2007:13:24:00 +0400] [Job 348] Wrote 8192 bytes of print data...
> D [08/May/2007:13:24:00 +0400] [Job 348] Read 8192 bytes of print data...
> D [08/May/2007:13:24:00 +0400] [Job 348] Wrote 8192 bytes of print data...
> D [08/May/2007:13:24:00 +0400] [Job 348] Read 8192 bytes of print data...
> D [08/May/2007:13:24:00 +0400] [Job 348] Wrote 8192 bytes of print data...
> D [08/May/2007:13:24:00 +0400] [Job 348] Read 8192 bytes of print data...
> D [08/May/2007:13:24:00 +0400] [Job 348] Wrote 8192 bytes of print data...
> D [08/May/2007:13:24:00 +0400] [Job 348] Read 8192 bytes of print data...
> D [08/May/2007:13:24:00 +0400] [Job 348] Wrote 8192 bytes of print data...
> D [08/May/2007:13:24:00 +0400] [Job 348] Read 8192 bytes of print data...
> D [08/May/2007:13:24:00 +0400] [Job 348] Wrote 8192 bytes of print data...
> D [08/May/2007:13:24:00 +0400] [Job 348] Read 8192 bytes of print data...
> D [08/May/2007:13:24:00 +0400] [Job 348] Wrote 8192 bytes of print data...
> D [08/May/2007:13:24:00 +0400] [Job 348] Read 8192 bytes of print data...
> D [08/May/2007:13:24:00 +0400] [Job 348] Wrote 8192 bytes of print data...
> D [08/May/2007:13:24:00 +0400] [Job 348] Read 8192 bytes of print data...
> D [08/May/2007:13:24:00 +0400] [Job 348] Wrote 8192 bytes of print data...
> D [08/May/2007:13:24:00 +0400] [Job 348] Read 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Wrote 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Read 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Wrote 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Read 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Wrote 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Read 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Wrote 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Read 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Wrote 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Read 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Wrote 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Read 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Wrote 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Read 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Wrote 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Read 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Wrote 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Read 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Wrote 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Read 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Wrote 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Read 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Wrote 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Read 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Wrote 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Read 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Wrote 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Read 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Wrote 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Read 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Wrote 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Read 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Wrote 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Read 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Wrote 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Read 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Wrote 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Read 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Wrote 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Read 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Wrote 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Read 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Wrote 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Read 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Wrote 8192 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Read 6329 bytes of print data...
> D [08/May/2007:13:24:01 +0400] [Job 348] Wrote 6329 bytes of print data...
> D [08/May/2007:13:24:02 +0400] [Job 348] File 0 is complete.
> D [08/May/2007:13:24:03 +0400] Unloading job 348...
> D [08/May/2007:13:29:00 +0400] Loading job 348 from cache...
> D [10/May/2007:10:20:44 +0400] [CGI] Got PPD file: "/var/spool/cups/tmp/4642b9bc348b3"
> D [10/May/2007:10:32:14 +0400] Loading job 348 from cache...
> D [10/May/2007:11:43:37 +0400] Loading attributes for job 348...
> D [10/May/2007:11:45:59 +0400] Unloading job 348...
> D [10/May/2007:14:13:58 +0400] Loading job 348 from cache...
> D [10/May/2007:14:34:30 +0400] Loading attributes for job 348...
> D [10/May/2007:14:35:35 +0400] Unloading job 348...
> 
> 
> 

I don't know the backend named "jasmine", but I suspect the
Perl diagnostic message stems from that:
---snip---
D [08/May/2007:13:23:59 +0400] [Job 348] Unknown Value type 0x13 for key "time-at-completed". 
Performing no transformation. at /usr/lib/perl5/site_perl/5.8.8/Net/IPP/IPPRequest.pm line 230
---snip---
You should check what the backend in question does in case of such errors;
it is, naturally, implementation dependent.

Helge


-- 
Helge Blischke
Softwareentwicklung

H.Blischke at acm.org