Waiting for printer to finish - error

Wed Dec 15 05:25:43 PST 2004

Well, it seems that the printer isn't giving anything back to the
socket backend. It may well be that the printer requires some more
PJL commands to talk back anything (a @PLJ JOB or the like).

Your could either edit the printer's PPD and add PJL the 
appropriate statements to the *JCLBegin: value, or simly use hpnpf
as backend:

  lpadmin -p sdlpgreg -E -v hpnpf://sdlpgreg:9100

You get an additional /var/log/cups/status_log.sdlpgreg file
which collects alle the INFO:... lines and, very useful, any
messages (including errors) the PostScript interpreter prints
to its standard output or standard error.

Helge

peter at castandcrew.com wrote:
> 
> Sorry for the late response.
> 
> Well, hpnpf actually worked. What I mean is
> that if I use hpnpf command the printer goes back
> to ready state. Btw, the printer is HP LaserJet 4050N.
> 
> Here is the test result step by step:
> 
>  lpadmin -p sdlpgreg -E -v socket://sdlpgreg:9100
>  ./hpnpf -x sdlpgreg -vW -l test_print.log testfile
> 
> The test file printed successfully and the printer went back to ready
> state.
> 
> ==> Stdout of hpnpf command:
> ===
> [48,sduser-p1:peter] # ./hpnpf -x sdlpgreg -vW -l test_print.log testfile
> Connecting to sdlpgreg ... connected
> Sending file testfile
> 
> token = @PJL USTATUS PAGE
> token = 1
> token = ID=93
> token = @PJL USTATUS JOB
> token = END
> token = NAME="sduser.23498"
> token = PAGES=0
> token = ID=94
> token = RESULT=OK
> ===
> 
> ==> hpnpf log file test_print.log
> ===
> 18:31:50 hpnpf[23498] OpenLog: logging started
> 18:31:50 hpnpf[23498] Process: entered
> 18:31:50 hpnpf[23498] ResolveAddress: sdlpgreg
> 18:31:50 hpnpf[23498] OpenSocket: entered
> 18:31:50 hpnpf[23498] OpenSocket: using 16K send buffer
> 18:31:50 hpnpf[23498] MakeConnection: 10.1.1.104, port 9100
> 18:31:50 hpnpf[23498] DoNonBlocking: non-blocking on
> 18:31:50 hpnpf[23498] Process: sending file testfile
> 18:31:50 hpnpf[23498] SendFile: entered (TBCP=0)
> 18:31:50 hpnpf[23498] SendFile: 20 bytes read from host
> 18:31:50 hpnpf[23498] SendFile: 0 bytes read from host
> 18:31:50 hpnpf[23498] SendFile: 20 bytes written to socket
> 18:31:50 hpnpf[23498] DoNonBlocking: non-blocking off
> 18:32:05 hpnpf[23498] Process: 30 bytes read from socket
> 18:32:05 hpnpf[23498] @PJL USTATUS PAGE
> 18:32:05 hpnpf[23498] 1
> 18:32:05 hpnpf[23498] ID=93
> 18:32:05 hpnpf[23498] Process: 72 bytes read from socket
> 18:32:05 hpnpf[23498] @PJL USTATUS JOB
> 18:32:05 hpnpf[23498] END
> 18:32:05 hpnpf[23498] NAME="sduser.23498"
> 18:32:05 hpnpf[23498] PAGES=0
> 18:32:05 hpnpf[23498] ID=94
> 18:32:05 hpnpf[23498] RESULT=OK
> 18:32:05 hpnpf[23498] Process: read EOF on socket
> 18:32:05 hpnpf[23498] StopLog: logging stopped
> ===
> 
> After printing with hpnpf the lpstat -t command shows that the printer
> is idle. That is what I need but without using hpnpf utility. :-)
> 
> Thank you Helge for your response.
> 
> If there is anything I can do to help debugging this problem
> please let me know.
> 
> Thanks
> Peter Blajev
> 
> Helge Blischke wrote:
> > Hm, the status message should read "Ready to print" or something like
> > this.
> > It seems that the printer isn't giving any reply (perhaps an old
> > JetDirect firmweare?),
> > or the socket backend in 1.1.22 is broken.
> >
> > Perhaps you try out the hpnpf backend (see the links on the CUPS web
> > site) and report
> > what that is logging.
> >
> > Helge
> >
> >
> > peter at castandcrew.com wrote:
> > >
> > > Hi,
> > >
> > > I just install CUPS-1.1.22 on a RedHat 9 box.
> > > I compiled it and installed it from source. Everything went smoothly.
> > > Got no errors.
> > >
> > > Before I start the server here is what I changed in cupsd.conf:
> > >   FileDevice Yes
> > >   PreserveJobHistory No
> > >
> > > The only printer I added is a network HP LaserJet 4050
> > >   lpadmin -p sdlpgreg -E -v socket://sdlpgreg:9100
> > >
> > > To test printing I ran this command:
> > >   echo "test" | lp -d sdlpgreg
> > >
> > > The page printed but here is the output of lpstat command:
> > >   scheduler is running
> > >   system default destination: sdlpgreg
> > >   device for sdlpgreg: socket://sdlpgreg:9100
> > >   sdlpgreg accepting requests since Jan 01 00:00
> > >   printer sdlpgreg is idle.  enabled since Jan 01 00:00
> > >         Print file sent, waiting for printer to finish...
> > >
> > > The message "Print file sent, waiting for printer to finish..." stays there
> > > until CUPS is restarted.
> > >
> > > In general everything print but what makes people complain is when they
> > > print from Windows (through SAMBA) the print queue icon stays in the system
> > > tray and never go away even if there is nothing in the queue.
> > >
> > > I assume the CUPS message and the print icon problem are related, aren't they?
> > >
> > > The previous version of CUPS I use is 1.1.18 and have no problems there.
> > >
> > > Please, any suggestions, tips, anything that may help.
> > >
> > > Thank you for your time and for the great product.
> > > Peter
> > >
> > > Here is the log output of the print command:
> > > ====
> > > D [09/Dec/2004:14:40:55 -0800] AcceptClient: 5 from localhost:631.
> > > D [09/Dec/2004:14:40:55 -0800] ReadClient: 5 POST / HTTP/1.1
> > > D [09/Dec/2004:14:40:55 -0800] ProcessIPPRequest: 5 status_code=1
> > > D [09/Dec/2004:14:40:55 -0800] ReadClient: 5 POST / HTTP/1.1
> > > D [09/Dec/2004:14:40:55 -0800] ProcessIPPRequest: 5 status_code=1
> > > D [09/Dec/2004:14:40:55 -0800] ReadClient: 5 POST / HTTP/1.1
> > > D [09/Dec/2004:14:40:55 -0800] ProcessIPPRequest: 5 status_code=0
> > > D [09/Dec/2004:14:40:55 -0800] CloseClient: 5
> > > D [09/Dec/2004:14:40:55 -0800] AcceptClient: 5 from localhost:631.
> > > D [09/Dec/2004:14:40:55 -0800] ReadClient: 5 POST /printers/sdlpgreg HTTP/1.1
> > > D [09/Dec/2004:14:40:55 -0800] print_job: auto-typing file...
> > > D [09/Dec/2004:14:40:55 -0800] print_job: request file type is text/plain.
> > > D [09/Dec/2004:14:40:55 -0800] check_quotas: requesting-user-name = 'root'
> > > D [09/Dec/2004:14:40:55 -0800] print_job: requesting-user-name = 'root'
> > > I [09/Dec/2004:14:40:55 -0800] Adding start banner page "none" to job 3.
> > > I [09/Dec/2004:14:40:55 -0800] Adding end banner page "none" to job 3.
> > > I [09/Dec/2004:14:40:55 -0800] Job 3 queued on 'sdlpgreg' by 'root'.
> > > D [09/Dec/2004:14:40:55 -0800] Job 3 hold_until = 0
> > > D [09/Dec/2004:14:40:55 -0800] StartJob(3, 0x8089288)
> > > D [09/Dec/2004:14:40:55 -0800] StartJob() id = 3, file = 0/1
> > > D [09/Dec/2004:14:40:55 -0800] StartJob: Sending job to queue tagged as raw...
> > > D [09/Dec/2004:14:40:55 -0800] job-sheets=none,none
> > > D [09/Dec/2004:14:40:55 -0800] banner_page = 0
> > > D [09/Dec/2004:14:40:55 -0800] StartJob: argv = "sdlpgreg","3","root","(stdin)","1","","/var/spool/cups/d00003-001"
> > > D [09/Dec/2004:14:40:55 -0800] StartJob: envp[0]="PATH=/usr/lib/cups/filter:/bin:/usr/bin"
> > > D [09/Dec/2004:14:40:55 -0800] StartJob: envp[1]="SOFTWARE=CUPS/1.1"
> > > D [09/Dec/2004:14:40:55 -0800] StartJob: envp[2]="USER=root"
> > > D [09/Dec/2004:14:40:55 -0800] StartJob: envp[3]="CHARSET=iso-8859-1"
> > > D [09/Dec/2004:14:40:55 -0800] StartJob: envp[4]="LANG=en"
> > > D [09/Dec/2004:14:40:55 -0800] StartJob: envp[5]="TZ=America/Los_Angeles"
> > > D [09/Dec/2004:14:40:55 -0800] StartJob: envp[6]="PPD=/etc/cups/ppd/sdlpgreg.ppd"
> > > D [09/Dec/2004:14:40:55 -0800] StartJob: envp[7]="CUPS_SERVERROOT=/etc/cups"
> > > D [09/Dec/2004:14:40:55 -0800] StartJob: envp[8]="RIP_MAX_CACHE=8m"
> > > D [09/Dec/2004:14:40:55 -0800] StartJob: envp[9]="TMPDIR=/var/spool/cups/tmp"
> > > D [09/Dec/2004:14:40:55 -0800] StartJob: envp[10]="CONTENT_TYPE=text/plain"
> > > D [09/Dec/2004:14:40:55 -0800] StartJob: envp[11]="DEVICE_URI=socket://sdlpgreg:9100"
> > > D [09/Dec/2004:14:40:55 -0800] StartJob: envp[12]="PRINTER=sdlpgreg"
> > > D [09/Dec/2004:14:40:55 -0800] StartJob: envp[13]="CUPS_DATADIR=/usr/share/cups"
> > > D [09/Dec/2004:14:40:55 -0800] StartJob: envp[14]="CUPS_FONTPATH=/usr/share/cups/fonts"
> > > D [09/Dec/2004:14:40:55 -0800] StartJob: envp[15]="CUPS_SERVER=localhost"
> > > D [09/Dec/2004:14:40:55 -0800] StartJob: envp[16]="IPP_PORT=631"
> > > D [09/Dec/2004:14:40:55 -0800] StartJob: statusfds = [ 7 8 ]
> > > D [09/Dec/2004:14:40:55 -0800] StartJob: filterfds[1] = [ 9 -1 ]
> > > D [09/Dec/2004:14:40:55 -0800] StartJob: backend = "/usr/lib/cups/backend/socket"
> > > D [09/Dec/2004:14:40:55 -0800] StartJob: filterfds[0] = [ -1 10 ]
> > > D [09/Dec/2004:14:40:55 -0800] start_process("/usr/lib/cups/backend/socket", 0xbffef160, 0xbffee4d0, 9, 10, 8)
> > > I [09/Dec/2004:14:40:55 -0800] Started backend /usr/lib/cups/backend/socket (PID 26921) for job 3.
> > > D [09/Dec/2004:14:40:55 -0800] ProcessIPPRequest: 5 status_code=0
> > > D [09/Dec/2004:14:40:55 -0800] CloseClient: 5
> > > D [09/Dec/2004:14:40:55 -0800] UpdateJob: job 3, file 0 is complete.
> > > D [09/Dec/2004:14:40:55 -0800] CancelJob: id = 3
> > > D [09/Dec/2004:14:40:55 -0800] StopJob: id = 3, force = 0
> > > D [09/Dec/2004:14:40:55 -0800] StopJob: printer state is 3
> > > ===
> >
> > --
> > Helge Blischke
> > Softwareentwicklung
> > SRZ Berlin | Firmengruppe besscom
> > http://www.srz.de
> > tel: +49 30 75301-360

-- 
Helge Blischke
Softwareentwicklung
SRZ Berlin | Firmengruppe besscom
http://www.srz.de
tel: +49 30 75301-360