Printing suspended with HPLJ5000

Sun May 28 22:57:39 PDT 2006

Hi there,

I have a Linux box (FC4) with CUPS 1.1.23-15.4 installed. I use it to print PDFs mainly, and may print >1000 daily at peak season. I have hooked up a HPLJ5000 locally via parallel port, and the PDFs are printing fine. Weird thing is, sometimes the printer is halted in the middle of a print job (say 4 pages in total, print the 1st 2 and then suddenly stops), so other print jobs following got queued up and users complained not being able to receive any outputs... then I cancelled that job and the others got printed straight away; I even tried to submit that same PDF and no problem printing at all...

Below is a log extract of that particular job:

--- begins here ---
D [29/May/2006:13:01:27 +0800] AcceptClient: 2 from localhost:631.
D [29/May/2006:13:01:28 +0800] ReadClient: 2 POST / HTTP/1.1
D [29/May/2006:13:01:28 +0800] ProcessIPPRequest: 2 status_code=1
D [29/May/2006:13:01:28 +0800] ReadClient: 2 POST / HTTP/1.1
D [29/May/2006:13:01:28 +0800] ProcessIPPRequest: 2 status_code=1
D [29/May/2006:13:01:28 +0800] ReadClient: 2 POST / HTTP/1.1
D [29/May/2006:13:01:28 +0800] ProcessIPPRequest: 2 status_code=0
D [29/May/2006:13:01:28 +0800] CloseClient: 2
D [29/May/2006:13:01:28 +0800] AcceptClient: 2 from localhost:631.
D [29/May/2006:13:01:28 +0800] ReadClient: 2 POST /printers/hplj5000 HTTP/1.1
D [29/May/2006:13:01:28 +0800] print_job: auto-typing file...
D [29/May/2006:13:01:28 +0800] print_job: request file type is application/pdf.
D [29/May/2006:13:01:28 +0800] CancelJob: id = 3617
D [29/May/2006:13:01:28 +0800] check_quotas: requesting-user-name = 'uucp'
D [29/May/2006:13:01:28 +0800] print_job: requesting-user-name = 'uucp'
I [29/May/2006:13:01:28 +0800] Adding start banner page "none" to job 4122.
I [29/May/2006:13:01:28 +0800] Adding end banner page "none" to job 4122.
I [29/May/2006:13:01:28 +0800] Job 4122 queued on 'hplj5000' by 'uucp'.
D [29/May/2006:13:01:28 +0800] Job 4122 hold_until = 0
D [29/May/2006:13:01:28 +0800] StartJob(4122, 0x9985e10)
D [29/May/2006:13:01:28 +0800] StartJob() id = 4122, file = 0/1
D [29/May/2006:13:01:28 +0800] job-sheets=none,none
D [29/May/2006:13:01:28 +0800] banner_page = 0
D [29/May/2006:13:01:28 +0800] StartJob: argv = "hplj5000","4122","uucp","fax000003470.pdf","1","media=A4 portrait PageSize=A4 HPOption_PaperPolicy=NearestSizeAdjust InstalledMemory=28MB PageRegion InputSlot=Auto","/var/spool/cups/d04122-001"
D [29/May/2006:13:01:28 +0800] StartJob: envp[0]="PATH=/usr/lib/cups/filter:/bin:/usr/bin"
D [29/May/2006:13:01:28 +0800] StartJob: envp[1]="SOFTWARE=CUPS/1.1"
D [29/May/2006:13:01:28 +0800] StartJob: envp[2]="USER=root"
D [29/May/2006:13:01:28 +0800] StartJob: envp[3]="CHARSET=iso-8859-1"
D [29/May/2006:13:01:28 +0800] StartJob: envp[4]="LANG=c-"
D [29/May/2006:13:01:28 +0800] StartJob: envp[5]="PPD=/etc/cups/ppd/hplj5000.ppd"
D [29/May/2006:13:01:28 +0800] StartJob: envp[6]="CUPS_SERVERROOT=/etc/cups"
D [29/May/2006:13:01:28 +0800] StartJob: envp[7]="RIP_MAX_CACHE=8m"
D [29/May/2006:13:01:28 +0800] StartJob: envp[8]="TMPDIR=/var/spool/cups/tmp"
D [29/May/2006:13:01:28 +0800] StartJob: envp[9]="CONTENT_TYPE=application/pdf"
D [29/May/2006:13:01:28 +0800] StartJob: envp[10]="DEVICE_URI=parallel:/dev/lp0"
D [29/May/2006:13:01:28 +0800] StartJob: envp[11]="PRINTER=hplj5000"
D [29/May/2006:13:01:28 +0800] StartJob: envp[12]="CUPS_DATADIR=/usr/share/cups"
D [29/May/2006:13:01:28 +0800] StartJob: envp[13]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [29/May/2006:13:01:28 +0800] StartJob: envp[14]="CUPS_SERVER=localhost"
D [29/May/2006:13:01:28 +0800] StartJob: envp[15]="IPP_PORT=631"
D [29/May/2006:13:01:28 +0800] StartJob: statusfds = [ 8 9 ]
D [29/May/2006:13:01:28 +0800] StartJob: filterfds[1] = [ 10 -1 ]
D [29/May/2006:13:01:28 +0800] StartJob: filter = "/usr/lib/cups/filter/pdftops"
D [29/May/2006:13:01:28 +0800] StartJob: filterfds[0] = [ 11 12 ]
D [29/May/2006:13:01:28 +0800] start_process("/usr/lib/cups/filter/pdftops", 0xbfa52b20, 0xbfa52098, 10, 12, 9)
I [29/May/2006:13:01:28 +0800] Started filter /usr/lib/cups/filter/pdftops (PID 13675) for job 4122.
D [29/May/2006:13:01:28 +0800] StartJob: filter = "/usr/lib/cups/filter/pstops"
D [29/May/2006:13:01:28 +0800] StartJob: filterfds[1] = [ 10 13 ]
D [29/May/2006:13:01:28 +0800] start_process("/usr/lib/cups/filter/pstops", 0xbfa52b20, 0xbfa52098, 11, 13, 9)
I [29/May/2006:13:01:28 +0800] Started filter /usr/lib/cups/filter/pstops (PID 13676) for job 4122.
D [29/May/2006:13:01:28 +0800] StartJob: backend = "/usr/lib/cups/backend/parallel"
D [29/May/2006:13:01:28 +0800] StartJob: filterfds[0] = [ -1 11 ]
D [29/May/2006:13:01:28 +0800] start_process("/usr/lib/cups/backend/parallel", 0xbfa52b20, 0xbfa52098, 10, 11, 9)
I [29/May/2006:13:01:28 +0800] Started backend /usr/lib/cups/backend/parallel (PID 13677) for job 4122.
D [29/May/2006:13:01:28 +0800] ProcessIPPRequest: 2 status_code=0
D [29/May/2006:13:01:28 +0800] CloseClient: 2
D [29/May/2006:13:01:28 +0800] [Job 4122] pdftops - opened PPD file "/etc/cups/ppd/hplj5000.ppd"...
D [29/May/2006:13:01:28 +0800] [Job 4122] Page = 595x842; 13,12 to 582,830
D [29/May/2006:13:01:28 +0800] [Job 4122] pdftops - level = 2, width = 595, length = 842
D [29/May/2006:13:01:28 +0800] [Job 4122] slowcollate=0, slowduplex=0, sloworder=0
D [29/May/2006:13:01:28 +0800] [Job 4122] 0 %%Creator: xpdf/pdftops 2.03
D [29/May/2006:13:01:28 +0800] [Job 4122] 0 %%LanguageLevel: 2
D [29/May/2006:13:01:28 +0800] [Job 4122] 0 %%DocumentSuppliedResources: (atend)
D [29/May/2006:13:01:28 +0800] [Job 4122] 0 %%DocumentMedia: plain 595 842 0 () ()
D [29/May/2006:13:01:28 +0800] [Job 4122] 0 %%BoundingBox: 0 0 595 842
D [29/May/2006:13:01:28 +0800] [Job 4122] 0 %%Pages: 1
D [29/May/2006:13:01:28 +0800] [Job 4122] 0 %%BoundingBox: 0 0 595 842
D [29/May/2006:13:01:28 +0800] [Job 4122] 0 %%EndComments
D [29/May/2006:13:01:28 +0800] [Job 4122] 0 %%BeginDefaults
D [29/May/2006:13:01:28 +0800] [Job 4122] 0 %%PageMedia: plain
D [29/May/2006:13:01:28 +0800] [Job 4122] 0 %%EndDefaults
D [29/May/2006:13:01:28 +0800] [Job 4122] 0 %%BeginProlog
D [29/May/2006:13:01:28 +0800] [Job 4122] 0 %%BeginResource: procset xpdf 2.03 0
D [29/May/2006:13:01:28 +0800] [Job 4122] 0 %%EndResource
D [29/May/2006:13:01:28 +0800] [Job 4122] 0 %%EndProlog
D [29/May/2006:13:01:28 +0800] [Job 4122] 0 %%BeginSetup
D [29/May/2006:13:01:28 +0800] [Job 4122] 0 %%BeginResource: font OSVQBP+Times-Roman
D [29/May/2006:13:01:29 +0800] [Job 4122] 0 %%EndResource
D [29/May/2006:13:01:29 +0800] [Job 4122] 0 %%EndSetup
D [29/May/2006:13:01:29 +0800] [Job 4122] 0 %%Page: 1 1
D [29/May/2006:13:01:29 +0800] [Job 4122] 0 %%Page: 1 1
D [29/May/2006:13:01:29 +0800] [Job 4122] pw = 568.3, pl = 817.7
D [29/May/2006:13:01:29 +0800] [Job 4122] PageLeft = 13.4, PageRight = 581.8
D [29/May/2006:13:01:29 +0800] [Job 4122] PageTop = 829.7, PageBottom = 12.1
D [29/May/2006:13:01:29 +0800] [Job 4122] PageWidth = 595.0, PageLength = 842.0
D [29/May/2006:13:01:29 +0800] [Job 4122] 0 %%PageBoundingBox: 0 0 612 792
D [29/May/2006:13:01:29 +0800] [Job 4122] 0 %%BeginPageSetup
D [29/May/2006:13:01:29 +0800] [Job 4122] 0 %%PageOrientation: Portrait
D [29/May/2006:13:01:29 +0800] [Job 4122] 0 %%EndPageSetup
D [29/May/2006:13:01:29 +0800] [Job 4122] 0 %%PageTrailer
D [29/May/2006:13:01:29 +0800] [Job 4122] 0 %%Trailer
D [29/May/2006:13:01:29 +0800] [Job 4122] Saw Trailer!
D [29/May/2006:13:01:29 +0800] [Job 4122] Saw EOF!
D [29/May/2006:13:01:29 +0800] UpdateJob: job 4122, file 0 is complete.
D [29/May/2006:13:01:29 +0800] CancelJob: id = 4122
D [29/May/2006:13:01:29 +0800] StopJob: id = 4122, force = 0
D [29/May/2006:13:01:29 +0800] StopJob: printer state is 3
D [29/May/2006:13:05:27 +0800] AcceptClient: 2 from localhost:631.
D [29/May/2006:13:05:27 +0800] ReadClient: 2 POST / HTTP/1.1
D [29/May/2006:13:05:27 +0800] ProcessIPPRequest: 2 status_code=1
D [29/May/2006:13:05:27 +0800] ReadClient: 2 POST / HTTP/1.1
D [29/May/2006:13:05:27 +0800] ProcessIPPRequest: 2 status_code=1
D [29/May/2006:13:05:27 +0800] ReadClient: 2 POST / HTTP/1.1
D [29/May/2006:13:05:27 +0800] ProcessIPPRequest: 2 status_code=0
D [29/May/2006:13:05:27 +0800] CloseClient: 2
D [29/May/2006:13:05:27 +0800] AcceptClient: 2 from localhost:631.
D [29/May/2006:13:05:27 +0800] ReadClient: 2 POST /printers/hplj5000 HTTP/1.1
D [29/May/2006:13:05:27 +0800] print_job: auto-typing file...
D [29/May/2006:13:05:27 +0800] print_job: request file type is application/pdf.
D [29/May/2006:13:05:27 +0800] CancelJob: id = 3618
D [29/May/2006:13:05:27 +0800] check_quotas: requesting-user-name = 'uucp'
D [29/May/2006:13:05:27 +0800] print_job: requesting-user-name = 'uucp'
I [29/May/2006:13:05:27 +0800] Adding start banner page "none" to job 4123.
I [29/May/2006:13:05:27 +0800] Adding end banner page "none" to job 4123.
I [29/May/2006:13:05:27 +0800] Job 4123 queued on 'hplj5000' by 'uucp'.
D [29/May/2006:13:05:27 +0800] Job 4123 hold_until = 0
D [29/May/2006:13:05:27 +0800] StartJob(4123, 0x9985e10)
D [29/May/2006:13:05:27 +0800] StartJob() id = 4123, file = 0/1
D [29/May/2006:13:05:27 +0800] job-sheets=none,none
D [29/May/2006:13:05:27 +0800] banner_page = 0
D [29/May/2006:13:05:27 +0800] StartJob: argv = "hplj5000","4123","uucp","fax000003471.pdf","1","media=A4 portrait PageSize=A4 HPOption_PaperPolicy=NearestSizeAdjust InstalledMemory=28MB PageRegion InputSlot=Auto","/var/spool/cups/d04123-001"
D [29/May/2006:13:05:27 +0800] StartJob: envp[0]="PATH=/usr/lib/cups/filter:/bin:/usr/bin"
D [29/May/2006:13:05:27 +0800] StartJob: envp[1]="SOFTWARE=CUPS/1.1"
D [29/May/2006:13:05:27 +0800] StartJob: envp[2]="USER=root"
D [29/May/2006:13:05:27 +0800] StartJob: envp[3]="CHARSET=iso-8859-1"
D [29/May/2006:13:05:27 +0800] StartJob: envp[4]="LANG=c-"
D [29/May/2006:13:05:27 +0800] StartJob: envp[5]="PPD=/etc/cups/ppd/hplj5000.ppd"
D [29/May/2006:13:05:27 +0800] StartJob: envp[6]="CUPS_SERVERROOT=/etc/cups"
D [29/May/2006:13:05:27 +0800] StartJob: envp[7]="RIP_MAX_CACHE=8m"
D [29/May/2006:13:05:27 +0800] StartJob: envp[8]="TMPDIR=/var/spool/cups/tmp"
D [29/May/2006:13:05:27 +0800] StartJob: envp[9]="CONTENT_TYPE=application/pdf"
D [29/May/2006:13:05:27 +0800] StartJob: envp[10]="DEVICE_URI=parallel:/dev/lp0"
D [29/May/2006:13:05:27 +0800] StartJob: envp[11]="PRINTER=hplj5000"
D [29/May/2006:13:05:27 +0800] StartJob: envp[12]="CUPS_DATADIR=/usr/share/cups"
D [29/May/2006:13:05:27 +0800] StartJob: envp[13]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [29/May/2006:13:05:27 +0800] StartJob: envp[14]="CUPS_SERVER=localhost"
D [29/May/2006:13:05:27 +0800] StartJob: envp[15]="IPP_PORT=631"
D [29/May/2006:13:05:27 +0800] StartJob: statusfds = [ 8 9 ]
D [29/May/2006:13:05:27 +0800] StartJob: filterfds[1] = [ 10 -1 ]
D [29/May/2006:13:05:27 +0800] StartJob: filter = "/usr/lib/cups/filter/pdftops"
D [29/May/2006:13:05:27 +0800] StartJob: filterfds[0] = [ 11 12 ]
D [29/May/2006:13:05:27 +0800] start_process("/usr/lib/cups/filter/pdftops", 0xbfa52b20, 0xbfa52098, 10, 12, 9)
I [29/May/2006:13:05:27 +0800] Started filter /usr/lib/cups/filter/pdftops (PID 14074) for job 4123.
D [29/May/2006:13:05:27 +0800] StartJob: filter = "/usr/lib/cups/filter/pstops"
D [29/May/2006:13:05:27 +0800] StartJob: filterfds[1] = [ 10 13 ]
D [29/May/2006:13:05:27 +0800] start_process("/usr/lib/cups/filter/pstops", 0xbfa52b20, 0xbfa52098, 11, 13, 9)
I [29/May/2006:13:05:27 +0800] Started filter /usr/lib/cups/filter/pstops (PID 14075) for job 4123.
D [29/May/2006:13:05:27 +0800] StartJob: backend = "/usr/lib/cups/backend/parallel"
D [29/May/2006:13:05:27 +0800] StartJob: filterfds[0] = [ -1 11 ]
D [29/May/2006:13:05:27 +0800] start_process("/usr/lib/cups/backend/parallel", 0xbfa52b20, 0xbfa52098, 10, 11, 9)
I [29/May/2006:13:05:27 +0800] Started backend /usr/lib/cups/backend/parallel (PID 14076) for job 4123.
D [29/May/2006:13:05:27 +0800] ProcessIPPRequest: 2 status_code=0
D [29/May/2006:13:05:27 +0800] CloseClient: 2
D [29/May/2006:13:05:27 +0800] [Job 4123] Page = 595x842; 13,12 to 582,830
D [29/May/2006:13:05:27 +0800] [Job 4123] pdftops - opened PPD file "/etc/cups/ppd/hplj5000.ppd"...
D [29/May/2006:13:05:27 +0800] [Job 4123] pdftops - level = 2, width = 595, length = 842
D [29/May/2006:13:05:27 +0800] [Job 4123] slowcollate=0, slowduplex=0, sloworder=0
D [29/May/2006:13:05:27 +0800] [Job 4123] 0 %%Creator: xpdf/pdftops 2.03
D [29/May/2006:13:05:27 +0800] [Job 4123] 0 %%LanguageLevel: 2
D [29/May/2006:13:05:27 +0800] [Job 4123] 0 %%DocumentSuppliedResources: (atend)
D [29/May/2006:13:05:27 +0800] [Job 4123] 0 %%DocumentMedia: plain 595 842 0 () ()
D [29/May/2006:13:05:27 +0800] [Job 4123] 0 %%BoundingBox: 0 0 595 842
D [29/May/2006:13:05:27 +0800] [Job 4123] 0 %%Pages: 2
D [29/May/2006:13:05:27 +0800] [Job 4123] 0 %%BoundingBox: 0 0 595 842
D [29/May/2006:13:05:27 +0800] [Job 4123] 0 %%EndComments
D [29/May/2006:13:05:27 +0800] [Job 4123] 0 %%BeginDefaults
D [29/May/2006:13:05:27 +0800] [Job 4123] 0 %%PageMedia: plain
D [29/May/2006:13:05:27 +0800] [Job 4123] 0 %%EndDefaults
D [29/May/2006:13:05:27 +0800] [Job 4123] 0 %%BeginProlog
D [29/May/2006:13:05:27 +0800] [Job 4123] 0 %%BeginResource: procset xpdf 2.03 0
D [29/May/2006:13:05:27 +0800] [Job 4123] 0 %%EndResource
D [29/May/2006:13:05:27 +0800] [Job 4123] 0 %%EndProlog
D [29/May/2006:13:05:27 +0800] [Job 4123] 0 %%BeginSetup
D [29/May/2006:13:05:27 +0800] [Job 4123] 0 %%BeginResource: font ONWDGJ+Times-Roman
D [29/May/2006:13:05:27 +0800] [Job 4123] 0 %%EndResource
D [29/May/2006:13:05:27 +0800] [Job 4123] 0 %%EndSetup
D [29/May/2006:13:05:27 +0800] [Job 4123] 0 %%Page: 1 1
D [29/May/2006:13:05:27 +0800] [Job 4123] 0 %%Page: 1 1
D [29/May/2006:13:05:27 +0800] [Job 4123] pw = 568.3, pl = 817.7
D [29/May/2006:13:05:27 +0800] [Job 4123] PageLeft = 13.4, PageRight = 581.8
D [29/May/2006:13:05:27 +0800] [Job 4123] PageTop = 829.7, PageBottom = 12.1
D [29/May/2006:13:05:27 +0800] [Job 4123] PageWidth = 595.0, PageLength = 842.0
D [29/May/2006:13:05:27 +0800] [Job 4123] 0 %%PageBoundingBox: 0 0 612 792
D [29/May/2006:13:05:27 +0800] [Job 4123] 0 %%BeginPageSetup
D [29/May/2006:13:05:27 +0800] [Job 4123] 0 %%PageOrientation: Portrait
D [29/May/2006:13:05:27 +0800] [Job 4123] 0 %%EndPageSetup
D [29/May/2006:13:05:28 +0800] [Job 4123] 0 %%nk9>"!I0MF;P]XX'>[r=SVa&PeRNMk]EU+&*P@&mIbO\d0G`EQUO8dS)#5Ullt`
D [29/May/2006:13:05:28 +0800] [Job 4123] 0 %%ttp,>h!mUdn0M=D9%:qca1P&^j'hm0GJ'8J0B<Ulu(HoLebT,a(`m#S?'=P"?87
D [29/May/2006:13:05:29 +0800] [Job 4123] 0 %%PageTrailer
D [29/May/2006:13:05:29 +0800] [Job 4123] 0 %%Page: 2 2
D [29/May/2006:13:05:29 +0800] [Job 4123] pw = 568.3, pl = 817.7
D [29/May/2006:13:05:29 +0800] [Job 4123] PageLeft = 13.4, PageRight = 581.8
D [29/May/2006:13:05:29 +0800] [Job 4123] PageTop = 829.7, PageBottom = 12.1
D [29/May/2006:13:05:29 +0800] [Job 4123] PageWidth = 595.0, PageLength = 842.0
D [29/May/2006:13:05:29 +0800] [Job 4123] 0 %%PageBoundingBox: 0 0 612 792
D [29/May/2006:13:05:29 +0800] [Job 4123] 0 %%BeginPageSetup
D [29/May/2006:13:05:29 +0800] [Job 4123] 0 %%PageOrientation: Portrait
D [29/May/2006:13:05:29 +0800] [Job 4123] 0 %%EndPageSetup
D [29/May/2006:13:11:04 +0800] AcceptClient: 2 from localhost:631.
D [29/May/2006:13:11:04 +0800] ReadClient: 2 POST / HTTP/1.1
D [29/May/2006:13:11:04 +0800] ProcessIPPRequest: 2 status_code=1
D [29/May/2006:13:11:04 +0800] ReadClient: 2 POST / HTTP/1.1
D [29/May/2006:13:11:04 +0800] ProcessIPPRequest: 2 status_code=1
D [29/May/2006:13:11:04 +0800] ReadClient: 2 POST / HTTP/1.1
D [29/May/2006:13:11:04 +0800] ProcessIPPRequest: 2 status_code=0
D [29/May/2006:13:11:04 +0800] CloseClient: 2
D [29/May/2006:13:11:04 +0800] AcceptClient: 2 from localhost:631.
D [29/May/2006:13:11:04 +0800] ReadClient: 2 POST /printers/hplj5000 HTTP/1.1
D [29/May/2006:13:11:04 +0800] print_job: auto-typing file...
D [29/May/2006:13:11:04 +0800] print_job: request file type is application/pdf.
D [29/May/2006:13:11:04 +0800] CancelJob: id = 3619
D [29/May/2006:13:11:04 +0800] check_quotas: requesting-user-name = 'uucp'
D [29/May/2006:13:11:04 +0800] print_job: requesting-user-name = 'uucp'
I [29/May/2006:13:11:04 +0800] Adding start banner page "none" to job 4124.
I [29/May/2006:13:11:04 +0800] Adding end banner page "none" to job 4124.
I [29/May/2006:13:11:04 +0800] Job 4124 queued on 'hplj5000' by 'uucp'.
D [29/May/2006:13:11:04 +0800] Job 4124 hold_until = 0
D [29/May/2006:13:11:04 +0800] ProcessIPPRequest: 2 status_code=0
D [29/May/2006:13:11:04 +0800] CloseClient: 2
D [29/May/2006:13:13:46 +0800] AcceptClient: 2 from localhost:631.
D [29/May/2006:13:13:46 +0800] ReadClient: 2 POST / HTTP/1.1
D [29/May/2006:13:13:46 +0800] ProcessIPPRequest: 2 status_code=1
D [29/May/2006:13:13:46 +0800] ReadClient: 2 POST / HTTP/1.1
D [29/May/2006:13:13:46 +0800] ProcessIPPRequest: 2 status_code=1
D [29/May/2006:13:13:46 +0800] ReadClient: 2 POST / HTTP/1.1
D [29/May/2006:13:13:46 +0800] ProcessIPPRequest: 2 status_code=0
D [29/May/2006:13:13:46 +0800] CloseClient: 2
D [29/May/2006:13:13:46 +0800] AcceptClient: 2 from localhost:631.
D [29/May/2006:13:13:46 +0800] ReadClient: 2 POST /printers/hplj5000 HTTP/1.1
D [29/May/2006:13:13:46 +0800] print_job: auto-typing file...
D [29/May/2006:13:13:46 +0800] print_job: request file type is application/pdf.
D [29/May/2006:13:13:46 +0800] CancelJob: id = 3620
D [29/May/2006:13:13:46 +0800] check_quotas: requesting-user-name = 'uucp'
D [29/May/2006:13:13:46 +0800] print_job: requesting-user-name = 'uucp'
I [29/May/2006:13:13:46 +0800] Adding start banner page "none" to job 4125.
I [29/May/2006:13:13:46 +0800] Adding end banner page "none" to job 4125.
I [29/May/2006:13:13:46 +0800] Job 4125 queued on 'hplj5000' by 'uucp'.
D [29/May/2006:13:13:46 +0800] Job 4125 hold_until = 0
D [29/May/2006:13:13:46 +0800] ProcessIPPRequest: 2 status_code=0
D [29/May/2006:13:13:46 +0800] CloseClient: 2
D [29/May/2006:13:14:56 +0800] AcceptClient: 2 from localhost:631.
D [29/May/2006:13:14:56 +0800] ReadClient: 2 POST / HTTP/1.1
D [29/May/2006:13:14:56 +0800] ProcessIPPRequest: 2 status_code=1
D [29/May/2006:13:14:56 +0800] ReadClient: 2 POST / HTTP/1.1
D [29/May/2006:13:14:56 +0800] ProcessIPPRequest: 2 status_code=1
D [29/May/2006:13:14:56 +0800] ReadClient: 2 POST / HTTP/1.1
D [29/May/2006:13:14:56 +0800] ProcessIPPRequest: 2 status_code=0
D [29/May/2006:13:14:56 +0800] CloseClient: 2
D [29/May/2006:13:14:56 +0800] AcceptClient: 2 from localhost:631.
D [29/May/2006:13:14:56 +0800] ReadClient: 2 POST /printers/hplj5000 HTTP/1.1
D [29/May/2006:13:14:56 +0800] print_job: auto-typing file...
D [29/May/2006:13:14:56 +0800] print_job: request file type is application/pdf.
D [29/May/2006:13:14:56 +0800] CancelJob: id = 3621
D [29/May/2006:13:14:56 +0800] check_quotas: requesting-user-name = 'uucp'
D [29/May/2006:13:14:56 +0800] print_job: requesting-user-name = 'uucp'
I [29/May/2006:13:14:56 +0800] Adding start banner page "none" to job 4126.
I [29/May/2006:13:14:56 +0800] Adding end banner page "none" to job 4126.
I [29/May/2006:13:14:56 +0800] Job 4126 queued on 'hplj5000' by 'uucp'.
D [29/May/2006:13:14:56 +0800] Job 4126 hold_until = 0
D [29/May/2006:13:14:56 +0800] ProcessIPPRequest: 2 status_code=0
D [29/May/2006:13:14:56 +0800] CloseClient: 2
D [29/May/2006:13:16:04 +0800] AcceptClient: 2 from localhost:631.
D [29/May/2006:13:16:04 +0800] ReadClient: 2 POST / HTTP/1.1
D [29/May/2006:13:16:04 +0800] ProcessIPPRequest: 2 status_code=1
D [29/May/2006:13:16:04 +0800] ReadClient: 2 POST / HTTP/1.1
D [29/May/2006:13:16:04 +0800] ProcessIPPRequest: 2 status_code=1
D [29/May/2006:13:16:04 +0800] ReadClient: 2 POST / HTTP/1.1
D [29/May/2006:13:16:04 +0800] ProcessIPPRequest: 2 status_code=0
D [29/May/2006:13:16:04 +0800] CloseClient: 2
D [29/May/2006:13:16:04 +0800] AcceptClient: 2 from localhost:631.
D [29/May/2006:13:16:04 +0800] ReadClient: 2 POST /printers/hplj5000 HTTP/1.1
D [29/May/2006:13:16:04 +0800] print_job: auto-typing file...
D [29/May/2006:13:16:04 +0800] print_job: request file type is application/pdf.
D [29/May/2006:13:16:04 +0800] CancelJob: id = 3623
D [29/May/2006:13:16:04 +0800] check_quotas: requesting-user-name = 'uucp'
D [29/May/2006:13:16:04 +0800] print_job: requesting-user-name = 'uucp'
I [29/May/2006:13:16:04 +0800] Adding start banner page "none" to job 4127.
I [29/May/2006:13:16:04 +0800] Adding end banner page "none" to job 4127.
I [29/May/2006:13:16:04 +0800] Job 4127 queued on 'hplj5000' by 'uucp'.
D [29/May/2006:13:16:04 +0800] Job 4127 hold_until = 0
D [29/May/2006:13:16:04 +0800] ProcessIPPRequest: 2 status_code=0
D [29/May/2006:13:16:04 +0800] CloseClient: 2
D [29/May/2006:13:17:26 +0800] AcceptClient: 2 from localhost:631.
D [29/May/2006:13:17:26 +0800] ReadClient: 2 POST / HTTP/1.1
D [29/May/2006:13:17:26 +0800] ProcessIPPRequest: 2 status_code=1
D [29/May/2006:13:17:26 +0800] ReadClient: 2 POST / HTTP/1.1
D [29/May/2006:13:17:26 +0800] ProcessIPPRequest: 2 status_code=1
D [29/May/2006:13:17:26 +0800] ReadClient: 2 POST / HTTP/1.1
D [29/May/2006:13:17:26 +0800] ProcessIPPRequest: 2 status_code=0
D [29/May/2006:13:17:26 +0800] CloseClient: 2
D [29/May/2006:13:17:26 +0800] AcceptClient: 2 from localhost:631.
D [29/May/2006:13:17:26 +0800] ReadClient: 2 POST /printers/hplj5000 HTTP/1.1
D [29/May/2006:13:17:26 +0800] print_job: auto-typing file...
D [29/May/2006:13:17:26 +0800] print_job: request file type is application/pdf.
D [29/May/2006:13:17:26 +0800] CancelJob: id = 3624
D [29/May/2006:13:17:26 +0800] check_quotas: requesting-user-name = 'uucp'
D [29/May/2006:13:17:26 +0800] print_job: requesting-user-name = 'uucp'
I [29/May/2006:13:17:26 +0800] Adding start banner page "none" to job 4128.
I [29/May/2006:13:17:26 +0800] Adding end banner page "none" to job 4128.
I [29/May/2006:13:17:26 +0800] Job 4128 queued on 'hplj5000' by 'uucp'.
D [29/May/2006:13:17:26 +0800] Job 4128 hold_until = 0
D [29/May/2006:13:17:26 +0800] ProcessIPPRequest: 2 status_code=0
D [29/May/2006:13:17:26 +0800] CloseClient: 2
--- ends here ---

As you can see here, Job# 4122 got printed fine; the next one #4123 is the problematic one, causing those the follows (i.e. 4124 - 4128) to queue up...

I have no clue what causes it, as I still can't find a way to repeat the problem... could someone please help? Thanks a million!!

Regards,
Raymond.