large jobs on slow printer loop forever

[Helge Blischke]

The first relevant error message in your log seems to be an "interrupted
system call" (4), and 
the lpd backend then tries to print the file again. The print server
then refuses the
control file with errno 108 which means (on Linux) "cannot send after
transport endpoint
shutdown"

To do further diagnosis, you should try to strace the lpd backend to see
what happens 
during the backend sending the data file for the first time.

Helge



Rainer Hubovsky wrote:
> 
> Hi,
> 
> I use CUPS 1.1.18, Rel. 56 with SuSE 8.0. We have an Epson LQ-870 connected
> to the network with a Planet FPS-5P-D Printserver.
> 
> We use an accounting application via telnet and whenever we send a job to
> the printer which is more than app. 40 pages the job gets printed without
> problems but then gets printed again and again until we kill the job.
> 
> I already told the printserver that it is connected to a slow printer and
> disabled bi-directional data flow bat that didn't help.
> 
> Below are the relevant parts of the error.log. The ID is 40245.
> 
> Do you have a clue what the problem might be?
> 
> Thanks a lot!!
> 
> Cheers.
>   +rainer
> 
> I [02/Sep/2004:12:26:14 +0200] Job 40245 queued on 'nadel1' by 'fac'.
> D [02/Sep/2004:12:26:14 +0200] Job 40245 hold_until = 0
> D [02/Sep/2004:12:26:14 +0200] StartJob(40245, 0x80a4af8)
> D [02/Sep/2004:12:26:14 +0200] StartJob() id = 40245, file = 0/1
> D [02/Sep/2004:12:26:14 +0200] StartJob: Sending job to queue tagged as
> raw...
> D [02/Sep/2004:12:26:14 +0200] job-sheets=none,none
> D [02/Sep/2004:12:26:14 +0200] banner_page = 0
> D [02/Sep/2004:12:26:14 +0200] StartJob: argv =
> "nadel1","40245","fac","(stdin)","1
> ","","/var/spool/cups/d40245-001"
> D [02/Sep/2004:12:26:14 +0200] StartJob: envp =
> "PATH=/usr/lib/cups/filter:/bin:/us
> +rainer/bin","SOFTWARE=CUPS/1.1","USER=root","CHARSET=iso-8859-1",\
> "LANG=en","","PPD=/etc/
> cups/ppd/nadel1.ppd","CUPS_SERVERROOT=/etc/cups","RIP_MAX_CACHE=8m",\
> "TMPDIR=/var/sool/cups/tmp","CONTENT_TYPE=application/octet-stream",\
> "DEVICE_URI=lpd://192.168.16.206/lp1","PRINTER=nadel1",\
> "CUPS_DATADIR=/usr/share/cups","CUPS_FONTPATH=/usr/share/cups/fonts","","",""
> D [02/Sep/2004:12:26:14 +0200] StartJob: statusfds = 6, 7
> D [02/Sep/2004:12:26:14 +0200] StartJob: filterfds[1] = 8, -1
> D [02/Sep/2004:12:26:14 +0200] StartJob: backend =
> "/usr/lib/cups/backend/lpd"
> D [02/Sep/2004:12:26:14 +0200] StartJob: filterfds[0] = -1, 9
> D [02/Sep/2004:12:26:14 +0200] start_process("/usr/lib/cups/backend/lpd",
> 0xbfff18d
> 0, 0xbfff0d80, 8, 9, 7)
> I [02/Sep/2004:12:26:14 +0200] Started backend /usr/lib/cups/backend/lpd
> (PID 17583
> ) for job 40245.
> D [02/Sep/2004:12:26:14 +0200] ProcessIPPRequest: 5 status_code=0
> D [02/Sep/2004:12:26:14 +0200] CloseClient() 5
> D [02/Sep/2004:12:26:14 +0200] [Job 40245] lpd_command 02 lp1
> D [02/Sep/2004:12:26:14 +0200] [Job 40245] Sending command string (5
> bytes)...
> D [02/Sep/2004:12:26:14 +0200] [Job 40245] Reading command status...
> D [02/Sep/2004:12:26:14 +0200] [Job 40245] lpd_command returning 0
> D [02/Sep/2004:12:26:14 +0200] [Job 40245] Control file is:
> D [02/Sep/2004:12:26:14 +0200] [Job 40245] Hgemba01srv01
> D [02/Sep/2004:12:26:14 +0200] [Job 40245] Pfac
> D [02/Sep/2004:12:26:14 +0200] [Job 40245] J_stdin_
> D [02/Sep/2004:12:26:14 +0200] [Job 40245] ldfA583gemba01srv01
> D [02/Sep/2004:12:26:14 +0200] [Job 40245] UdfA583gemba01srv01
> D [02/Sep/2004:12:26:14 +0200] [Job 40245] N_stdin_
> D [02/Sep/2004:12:26:14 +0200] [Job 40245] lpd_command 02 77
> cfA583gemba01srv01
> D [02/Sep/2004:12:26:14 +0200] [Job 40245] Sending command string (23
> bytes)...
> D [02/Sep/2004:12:26:14 +0200] [Job 40245] Reading command status...
> D [02/Sep/2004:12:26:14 +0200] [Job 40245] lpd_command returning 0
> D [02/Sep/2004:12:26:14 +0200] [Job 40245] lpd_command 03 133410
> dfA583gemba01srv01
> D [02/Sep/2004:12:26:14 +0200] [Job 40245] Sending command string (27
> bytes)...
> D [02/Sep/2004:12:26:14 +0200] [Job 40245] Reading command status...
> D [02/Sep/2004:12:26:14 +0200] [Job 40245] lpd_command returning 0
> D [02/Sep/2004:12:30:50 +0200] AcceptClient() 5 from localhost:631.
> D [02/Sep/2004:12:30:50 +0200] ReadClient() 5 POST / HTTP/1.1
> D [02/Sep/2004:12:30:50 +0200] ProcessIPPRequest: 5 status_code=0
> D [02/Sep/2004:12:30:50 +0200] CloseClient() 5
> E [02/Sep/2004:12:31:20 +0200] [Job 40245] Remote host did not accept data
> file (4)
> D [02/Sep/2004:12:31:50 +0200] [Job 40245] lpd_command 02 lp1
> D [02/Sep/2004:12:31:50 +0200] [Job 40245] Sending command string (5
> bytes)...
> D [02/Sep/2004:12:31:50 +0200] [Job 40245] Reading command status...
> D [02/Sep/2004:12:31:50 +0200] [Job 40245] lpd_command returning -1
> D [02/Sep/2004:12:31:50 +0200] [Job 40245] Control file is:
> D [02/Sep/2004:12:31:50 +0200] [Job 40245] Hgemba01srv01
> D [02/Sep/2004:12:31:50 +0200] [Job 40245] Pfac
> D [02/Sep/2004:12:31:50 +0200] [Job 40245] J_stdin_
> D [02/Sep/2004:12:31:50 +0200] [Job 40245] UdfA583gemba01srv01
> D [02/Sep/2004:12:31:50 +0200] [Job 40245] N_stdin_
> D [02/Sep/2004:12:31:50 +0200] [Job 40245] lpd_command 02 57
> cfA583gemba01srv01
> D [02/Sep/2004:12:31:50 +0200] [Job 40245] Sending command string (23
> bytes)...
> D [02/Sep/2004:12:31:50 +0200] [Job 40245] Reading command status...
> D [02/Sep/2004:12:31:50 +0200] [Job 40245] lpd_command returning 108
> E [02/Sep/2004:12:31:50 +0200] [Job 40245] Remote host did not accept
> control file
> (112)
> D [02/Sep/2004:12:32:20 +0200] [Job 40245] lpd_command 02 lp1
> D [02/Sep/2004:12:32:20 +0200] [Job 40245] Sending command string (5
> bytes)...
> D [02/Sep/2004:12:32:20 +0200] [Job 40245] Reading command status...
> D [02/Sep/2004:12:32:20 +0200] [Job 40245] lpd_command returning -1
> D [02/Sep/2004:12:32:20 +0200] [Job 40245] Control file is:
> D [02/Sep/2004:12:32:20 +0200] [Job 40245] Hgemba01srv01
> D [02/Sep/2004:12:32:20 +0200] [Job 40245] Pfac
> D [02/Sep/2004:12:32:20 +0200] [Job 40245] J_stdin_
> D [02/Sep/2004:12:32:20 +0200] [Job 40245] UdfA583gemba01srv01
> D [02/Sep/2004:12:32:20 +0200] [Job 40245] N_stdin_
> D [02/Sep/2004:12:32:20 +0200] [Job 40245] lpd_command 02 57
> cfA583gemba01srv01
> D [02/Sep/2004:12:32:20 +0200] [Job 40245] Sending command string (23
> bytes)...
> D [02/Sep/2004:12:32:20 +0200] [Job 40245] Reading command status...
> D [02/Sep/2004:12:32:20 +0200] [Job 40245] lpd_command returning 108
> E [02/Sep/2004:12:32:20 +0200] [Job 40245] Remote host did not accept
> control file (112)
> .
> .
> .
> D [02/Sep/2004:12:32:50 +0200] [Job 40245] lpd_command 02 lp1
> D [02/Sep/2004:12:32:50 +0200] [Job 40245] Sending command string (5
> bytes)...
> D [02/Sep/2004:12:32:50 +0200] [Job 40245] Reading command status...
> D [02/Sep/2004:12:32:50 +0200] [Job 40245] lpd_command returning -1
> D [02/Sep/2004:12:32:50 +0200] [Job 40245] Control file is:
> D [02/Sep/2004:12:32:50 +0200] [Job 40245] Hgemba01srv01
> D [02/Sep/2004:12:32:50 +0200] [Job 40245] Pfac
> D [02/Sep/2004:12:32:50 +0200] [Job 40245] J_stdin_
> D [02/Sep/2004:12:32:50 +0200] [Job 40245] UdfA583gemba01srv01
> D [02/Sep/2004:12:32:50 +0200] [Job 40245] N_stdin_
> D [02/Sep/2004:12:32:50 +0200] [Job 40245] lpd_command 02 57
> cfA583gemba01srv01
> D [02/Sep/2004:12:32:50 +0200] [Job 40245] Sending command string (23
> bytes)...
> D [02/Sep/2004:12:32:50 +0200] [Job 40245] Reading command status...
> D [02/Sep/2004:12:32:50 +0200] [Job 40245] lpd_command returning 108
> E [02/Sep/2004:12:32:50 +0200] [Job 40245] Remote host did not accept
> control file
> (112)
> .
> .
> .
> and so on...

-- 
H.Blischke at srz-berlin.de
H.Blischke at srz-berlin.com
H.Blischke at acm.org