I have encountered a strange problem, I think... 8^)
If I understand the "waitend" and "waitend_interval" directives:
1) "waitend" makes ifhp wait for the printer to signal that the job has
finished printing. For JetDirect PJL, it sends a PJL code and wait
for the printer to reply favorably.
2) "waitend_interval" specifies how long in between sending the PJL code,
default to 300s on a fresh ifhp install.
For me, I see that this is not the behavior:
Large PS job to HP5M, using the JetDirect protocol, ifhp, and PJL for
job status. The problem is that ifhp seems to exit (code 32) before
the job is done printing, and LPRng thinks that something is wrong,
and retries the job. The printer completely prints the job, however.
This repeats until the job is lprm'ed (I have send_try=300 :-).
After digging, I think what is happening is this:
1) LPRng invokes ifhp to send job (JetDirect 9100, PJL status).
2) ifhp sends jobs, and as soon as the whole file is completely sent,
ifhp goes into Do_waitend()
3) Now, this is a relatively small file, but the print time is some what
long, so after the last byte is sent to the printer, it will still
take about 10 minutes for the printer to finish printing the job.
4) In the mean time, ifhp (Do_waitend) is getting the PJL status back.
At the same time, "timeout" ( interval_t - current_t ) is being counted
down, starting from the "waitend_interval" directive (default to 300s).
5) However, once "timeout" gets close to 0, Do_waitend() terminates
with "JFAIL Do_waitend: no response from printer".
But there IS response from printer--it has been sending back the number of
pages printed every few seconds, and Do_waitend() is collecting the pagecount.
After poking around some more in ifhp.c:Do_waitend(), I narrow things
down to
len = Read_status_timeout( timeout );
And Read_status_timeout() set up a blockng read, with a timer alarm hooked
up to setjmp/sigsetjmp. When there is stuff to read, which is every few
seconds while the printing is going on (PJL pagecount from printer),
it is OK. But at the same time, "timeout" is being down-counted, and
it will come to a time when "timeout" is small (a few seconds), and
Read_status_timeout() will not have anything to read from the printer
before the timer alarm triggers the jump to setjmp(). When that happens,
Read_status_timeout returns -1 to variable "len".
Following that, the "while ( !waitend )" loop is "break"ed. And execution
ends with "JFAIL Do_waitend: no response from printer".
So, in bad ascii time-line diagrams:
A) The way it should be with "waitend" and "waitend_interval=300"
--------------------------------------------------------------
ifhp push out job Do_waitend() waits Do_waitend() waits Do_waitend waits
| | | |
|----------------->|-----300 sec------>|-----300 sec------>|-----300 sec-...
| | | | | | | |
V V V V V V V V
Do_waitend() JSUCC if job end detected
B) The behavior I see
------------------
ifhp push out job Do_waitend() waits Do_waitend() JFAIL
| | |
|----------------->|-----300 sec------>|
| | |
V V V
Do_waitend() JSUCC if job end detected
This problem happens only if it is a long print job with a relatively
small file, since "timeout" starts counting only when Do_waitend() is
called, and Do_waitend() is called only after the last byte is sent.
This problem is made worse if the receiving buffer on the printer is
increased. If the receiving buffer is made very small, the problem
disappears pretty much.
I dunno how to fix this without knowing:
1) if my understanding of "waitend" and "waitend_interval" is correct
2) should Do_waitend() be kludged, or should Read_status_timeout() be kludged
3) how kludging Read_status_timeout() will affect a few other places that
call it
Looking at the code, I _think_
if( len ) break;
should be changed to
if( len ) goto again;
However, that means that it is entirely possible that, for some
misbehaving printers, Do_waitend() can loop forever. So perhaps a master
timeout is needed ("waitend_timeout" ?), but the value to set for the
master timeout is going to be either blackmagic or hand-waving... :-(
Anyone with any idea? Tell me that I just missed a clue the size of
Manhattan somewhere, and I can fix that and go back to my other more
mundane sys admin stuffs. 8^)
Anyway, here's my set up info:
MACHINE: Red Hat Linux 6.2 (pretty stock)
LPRng: LPRng-3.6.24 (compiled it myself, NOT from .rpm)
lpd.conf: pretty stock, except for:
> # Local stuffs
> return_short_status=*
> short_status_length=1
> send_try=300
> send_failure_action=hold
> lpd_printcap_path=/print/etc/printcap
> bp=/print/libexec/filters/attbanner
> use_date
IFHP: ifhp-3.3.21 (compiled it myself again, same behavior with
ifhp-3.4.1 when run from the command line)
ifhp.conf: pretty stock, except for the additional line for my
homebrew filter, and "default_language=unknown" and
"forceconversion"
Printcap:
printer
:cm=HP LaserJet 5M
:sd=/var/spool/lpd/printer
:lp=printer%9100
:ifhp=model=hp5m,of_options=wait_for_banner
:of=/print/libexec/filters/ofhp
:if=/print/libexec/filters/ifhp
:vf=/print/libexec/filters/ifhp -c
And here's the last 80 trace lines of "ifhp -Zduplex
-Tmodel=hp5m,dev=printer%9100,trace,debug=4,waitend_interval=60 < manypages.ps"
(waitend_interval=60 here, but that is just so I don't have to wait the
default 300s :-)
===========================================================================
ifhp 13:53:36.105 [18517] [ 2]='[EMAIL PROTECTED]'
ifhp 13:53:36.105 [18517] [ 3]='job=START'
ifhp 13:53:36.105 [18517] [ 4]='name="PID 18517"'
ifhp 13:53:36.105 [18517] [ 5]='online=TRUE'
ifhp 13:53:36.105 [18517] [ 6]='page=18'
ifhp 13:53:36.105 [18517] [ 7]='pagecount=422460'
ifhp 13:53:36.105 [18517] Find_first_key: cmp 0, mid 3, key 'job', count 8
ifhp 13:53:36.106 [18517] Find_str_value: key 'job', value 'START'
ifhp 13:53:36.106 [18517] Find_first_key: cmp 0, mid 4, key 'name', count 8
ifhp 13:53:36.108 [18517] Find_str_value: key 'name', value '"PID 18517"'
ifhp 13:53:36.108 [18517] Do_waitend: job 'START', name '"PID 18517"', Jobname
'13-52-44.150 PID 18517'
ifhp 13:53:36.108 [18517] Find_first_key: cmp 0, mid 2, key 'echo', count 8
ifhp 13:53:36.108 [18517] Find_str_value: key 'echo', value
'[EMAIL PROTECTED]'
ifhp 13:53:36.108 [18517] Do_waitend: echo '[EMAIL PROTECTED]'
ifhp 13:53:36.108 [18517] Do_waitend: Outlen 0
ifhp 13:53:38.034 [18517] Read_status_line: timeout 8, read() returned 59, count 59
ifhp 13:53:38.034 [18517] Read_status_timeout: read count 59, '@PJL USTATUS TIMED^M
CODE=10001^M
DISPLAY=":"^M
ONLINE=TRUE^M
^L'
ifhp 13:53:38.034 [18517] Put_inbuf_len: buffer '@PJL USTATUS TIMED^M
CODE=10001^M
DISPLAY=":"^M
ONLINE=TRUE^M
^L'
ifhp 13:53:38.034 [18517] Get_inbuf_str: found '@PJL USTATUS TIMED'
ifhp 13:53:38.034 [18517] Pr_status: start str '@PJL USTATUS TIMED', pjlvar '<NULL>'
ifhp 13:53:38.034 [18517] Pr_status: doing PJL status on '@PJL USTATUS TIMED'
ifhp 13:53:38.034 [18517] Split: str '@PJL USTATUS TIMED', sort 0, keysep '<NULL>',
uniq 0, trim 1
ifhp 13:53:38.035 [18517] Pr_status: PJL var 'timed'
ifhp 13:53:38.035 [18517] Get_inbuf_str: found 'CODE=10001'
ifhp 13:53:38.035 [18517] Pr_status: start str 'CODE=10001', pjlvar 'timed'
ifhp 13:53:38.035 [18517] Check_device_status: 'code=10001'
ifhp 13:53:38.035 [18517] Check_device_status: key 'code', value '10001'
ifhp 13:53:38.035 [18517] Find_first_key: cmp 0, mid 0, key 'code', count 8
ifhp 13:53:38.035 [18517] Find_str_value: key 'code', value '10001'
ifhp 13:53:38.035 [18517] Pr_status: setting 'code=10001'
ifhp 13:53:38.035 [18517] Find_last_key: key 'code', cmp 0, mid 0
ifhp 13:53:38.035 [18517] Get_inbuf_str: found 'DISPLAY=":"'
ifhp 13:53:38.035 [18517] Pr_status: start str 'DISPLAY=":"', pjlvar '<NULL>'
ifhp 13:53:38.036 [18517] Check_device_status: 'display=":"'
ifhp 13:53:38.036 [18517] Check_device_status: key 'display', value '":"'
ifhp 13:53:38.036 [18517] Find_first_key: cmp 0, mid 1, key 'display', count 8
ifhp 13:53:38.036 [18517] Find_str_value: key 'display', value '":"'
ifhp 13:53:38.036 [18517] Pr_status: setting 'display=":"'
ifhp 13:53:38.036 [18517] Find_last_key: key 'display', cmp 0, mid 1
ifhp 13:53:38.036 [18517] Get_inbuf_str: found 'ONLINE=TRUE'
ifhp 13:53:38.036 [18517] Pr_status: start str 'ONLINE=TRUE', pjlvar '<NULL>'
ifhp 13:53:38.036 [18517] Check_device_status: 'online=TRUE'
ifhp 13:53:38.036 [18517] Check_device_status: key 'online', value 'TRUE'
ifhp 13:53:38.036 [18517] Find_first_key: cmp 0, mid 5, key 'online', count 8
ifhp 13:53:38.037 [18517] Find_str_value: key 'online', value 'TRUE'
ifhp 13:53:38.037 [18517] Pr_status: setting 'online=TRUE'
ifhp 13:53:38.037 [18517] Find_last_key: key 'online', cmp 0, mid 5
ifhp 13:53:38.037 [18517] Get_inbuf_str: found ''
ifhp 13:53:38.037 [18517] Pr_status: start str '', pjlvar '<NULL>'
ifhp 13:53:38.037 [18517] Get_inbuf_str: final ''
ifhp 13:53:38.037 [18517] Do_waitend: len 0
ifhp 13:53:38.037 [18517] Dump_line_list: Do_waitend - Devstatus - count 8, max 102,
list 0x80739e8
ifhp 13:53:38.037 [18517] [ 0]='code=10001'
ifhp 13:53:38.037 [18517] [ 1]='display=":"'
ifhp 13:53:38.037 [18517] [ 2]='[EMAIL PROTECTED]'
ifhp 13:53:38.038 [18517] [ 3]='job=START'
ifhp 13:53:38.038 [18517] [ 4]='name="PID 18517"'
ifhp 13:53:38.038 [18517] [ 5]='online=TRUE'
ifhp 13:53:38.038 [18517] [ 6]='page=18'
ifhp 13:53:38.038 [18517] [ 7]='pagecount=422460'
ifhp 13:53:38.038 [18517] Find_first_key: cmp 0, mid 3, key 'job', count 8
ifhp 13:53:38.038 [18517] Find_str_value: key 'job', value 'START'
ifhp 13:53:38.038 [18517] Find_first_key: cmp 0, mid 4, key 'name', count 8
ifhp 13:53:38.038 [18517] Find_str_value: key 'name', value '"PID 18517"'
ifhp 13:53:38.038 [18517] Do_waitend: job 'START', name '"PID 18517"', Jobname
'13-52-44.150 PID 18517'
ifhp 13:53:38.038 [18517] Find_first_key: cmp 0, mid 2, key 'echo', count 8
ifhp 13:53:38.039 [18517] Find_str_value: key 'echo', value
'[EMAIL PROTECTED]'
ifhp 13:53:38.039 [18517] Do_waitend: echo '[EMAIL PROTECTED]'
ifhp 13:53:38.039 [18517] Do_waitend: Outlen 0
ifhp 13:53:44.039 [18517] Read_status_line: timeout 6, read() returned -1, count -1
ifhp 13:53:44.039 [18517] Do_waitend: len -1
ifhp 13:53:44.039 [18517] Do_waitend: no response from printer
===== ifhp exits JFAIL here ===============================================
Cheers,
Edwin Lim <[EMAIL PROTECTED]> 973-360-7058 fp c254 ----------------
-----------------------------------------------------------------------------
YOU MUST BE A LIST MEMBER IN ORDER TO POST TO THE LPRNG MAILING LIST
The address you post from MUST be your subscription address
If you need help, send email to [EMAIL PROTECTED] (or lprng-requests
or lprng-digest-requests) with the word 'help' in the body. For the impatient,
to subscribe to a list with name LIST, send mail to [EMAIL PROTECTED]
with: | example:
subscribe LIST <mailaddr> | subscribe lprng-digest [EMAIL PROTECTED]
unsubscribe LIST <mailaddr> | unsubscribe lprng [EMAIL PROTECTED]
If you have major problems, send email to [EMAIL PROTECTED] with the word
LPRNGLIST in the SUBJECT line.
-----------------------------------------------------------------------------
