[cups.bugs] cups-lpd 300 second timeout problems
Curtis Rempel
curtis at telus.net
Tue Oct 7 12:54:11 PDT 2008
I'm troubleshooting an LPD issue with printserver boxes, specifically TrendNet 100-PS3 units.
Recently, jobs sporadically stall for 5 minutes and then print. There have been reports of sporadic network connectivity issues at this location
but I've yet to make a good correlation.
The footprint seems to be when the control file is ready to be sent, status is requested prior to sending the control file.
This is where the 300 second timeout occurs ("command status byte"). After that is just carries on as usual and the job prints. So,
it is "self healing" so to speak, but annoying just the same. This is an intermittment problem, it doesn't happen continuously.
cups version is 1.1.17-13.3.37 on RHEL 3. I'm hesitant to upgrade to a later release as this environment has been stable with no
printing problems for quite some time until recently. I'm not quite sure why this is all of a sudden happening.
I cannot find a cupds.conf parameter to shorten this 300 second timeout period, the parameter "TimeOut" is for retries and not this scenario.
I've looked in the source and the documentation, and unless I've overlooked it, I can't see where this 300 second value is derived from.
Ultimately, if that were able to be reduced, it would only be a stop gap measure, the underlying problem would still exist.
Here is an annotated log snippet at debug2:
1 -basha-2.05b$ grep -n 1044668 error_log
2 328586:d [06/Oct/2008:07:16:56 -0600] copy_banner(0xb72ae008[7], 0x9b1f748[1044668], none)
3 328587:d [06/Oct/2008:07:16:56 -0600] add_file(0xb72ae008[7], 1044668, application/octet-stream)
4 328588:I [06/Oct/2008:07:16:56 -0600] Job 1044668 queued on 'lxdcship4' by 'jennifer'.
5 328589:D [06/Oct/2008:07:16:56 -0600] Job 1044668 hold_until = 0
6 328590:d [06/Oct/2008:07:16:56 -0600] add_job_state_reasons(0xb72ae008[7], 1044668)
7 329210:D [06/Oct/2008:07:16:56 -0600] StartJob(1044668, 0x8f9d7d0)
8 329211:D [06/Oct/2008:07:16:56 -0600] StartJob() id = 1044668, file = 0/1
9 329215:D [06/Oct/2008:07:16:56 -0600] StartJob: argv = "lxdcship4","1044668","jennifer","pk07165636.008","1","","/var/spool/cups/d1044668-001"
10 329241:I [06/Oct/2008:07:16:56 -0600] Started backend /usr/lib/cups/backend/lpd (PID 12957) for job 1044668.
11 329243:I [06/Oct/2008:07:16:56 -0600] [Job 1044668] Attempting to connect to host lx61prt8 for printer lp1
12 329244:I [06/Oct/2008:07:16:57 -0600] [Job 1044668] Connected from port 515...
13 329245:D [06/Oct/2008:07:16:57 -0600] [Job 1044668] lpd_command 02 lp1
Line 13: receive job for queue lp1
14 329246:D [06/Oct/2008:07:16:57 -0600] [Job 1044668] Sending command string (5 bytes)...
15 329247:D [06/Oct/2008:07:16:57 -0600] [Job 1044668] Reading command status...
16 329248:D [06/Oct/2008:07:16:57 -0600] [Job 1044668] lpd_command returning 0
Line 16: success
17 329249:D [06/Oct/2008:07:16:57 -0600] [Job 1044668] Control file is:
18 329250:D [06/Oct/2008:07:16:57 -0600] [Job 1044668] Hlinux4
Line 18: job is from linux4
19 329251:D [06/Oct/2008:07:16:57 -0600] [Job 1044668] Pjennifer
Line 19: jennifer submitted it
20 329252:D [06/Oct/2008:07:16:57 -0600] [Job 1044668] Jpk07165636_008
Line 20: this is the job name for the banner page (if used)
21 329253:D [06/Oct/2008:07:16:57 -0600] [Job 1044668] ldfA957linux4
Line 21: the file to be printed: dfA957linux4 (without filtering control characters)
22 329254:D [06/Oct/2008:07:16:57 -0600] [Job 1044668] UdfA957linux4
Line 22: unlink the file when finished
23 329255:D [06/Oct/2008:07:16:57 -0600] [Job 1044668] Npk07165636_008
Line 23: the name of the source file: pk07165636_008
24 329256:D [06/Oct/2008:07:16:57 -0600] [Job 1044668] lpd_command 02 78 cfA957linux4
Line 24: Sub command - here is the control file. It is 78 bytes. The standard prefix is “cfA”, the job number is 957 and it is coming from linux4
25 329257:D [06/Oct/2008:07:16:57 -0600] [Job 1044668] Sending command string (17 bytes)...
26 329258:D [06/Oct/2008:07:16:57 -0600] [Job 1044668] Reading command status...
Line 26: waiting to see that it is ok to send the control file to the print server
27 331785:W [06/Oct/2008:07:21:57 -0600] [Job 1044668] Remote host did not respond with command status byte after 300 seconds!
Line 27: no answer was received
28 331786:D [06/Oct/2008:07:21:57 -0600] [Job 1044668] lpd_command returning 4
Line 28: non-zero return status = fail
29 331788:D [06/Oct/2008:07:21:57 -0600] UpdateJob: job 1044668, file 0 is complete.
30 331790:D [06/Oct/2008:07:21:57 -0600] StopJob: id = 1044668, force = 0
31 331793:D [06/Oct/2008:07:22:03 -0600] StartJob(1044668, 0x8f9d7d0)
32 331794:D [06/Oct/2008:07:22:03 -0600] StartJob() id = 1044668, file = 0/1
33 331798:D [06/Oct/2008:07:22:03 -0600] StartJob: argv = "lxdcship4","1044668","jennifer","pk07165636.008","1","","/var/spool/cups/d1044668-001"
34 331824:I [06/Oct/2008:07:22:03 -0600] Started backend /usr/lib/cups/backend/lpd (PID 13072) for job 1044668.
35 331826:I [06/Oct/2008:07:22:03 -0600] [Job 1044668] Attempting to connect to host lx61prt8 for printer lp1
36 331827:I [06/Oct/2008:07:22:03 -0600] [Job 1044668] Connected from port 515...
37 331828:D [06/Oct/2008:07:22:03 -0600] [Job 1044668] lpd_command 02 lp1
38 331829:D [06/Oct/2008:07:22:03 -0600] [Job 1044668] Sending command string (5 bytes)...
39 331830:D [06/Oct/2008:07:22:03 -0600] [Job 1044668] Reading command status...
40 331831:D [06/Oct/2008:07:22:03 -0600] [Job 1044668] lpd_command returning 0
41 331832:D [06/Oct/2008:07:22:03 -0600] [Job 1044668] Control file is:
42 331833:D [06/Oct/2008:07:22:03 -0600] [Job 1044668] Hlinux4
43 331834:D [06/Oct/2008:07:22:03 -0600] [Job 1044668] Pjennifer
44 331835:D [06/Oct/2008:07:22:03 -0600] [Job 1044668] Jpk07165636_008
45 331836:D [06/Oct/2008:07:22:03 -0600] [Job 1044668] ldfA072linux4
46 331837:D [06/Oct/2008:07:22:03 -0600] [Job 1044668] UdfA072linux4
47 331838:D [06/Oct/2008:07:22:03 -0600] [Job 1044668] Npk07165636_008
48 331839:D [06/Oct/2008:07:22:03 -0600] [Job 1044668] lpd_command 02 78 cfA072linux4
49 331840:D [06/Oct/2008:07:22:03 -0600] [Job 1044668] Sending command string (17 bytes)...
50 331841:D [06/Oct/2008:07:22:03 -0600] [Job 1044668] Reading command status...
51 331842:D [06/Oct/2008:07:22:03 -0600] [Job 1044668] lpd_command returning 0
Immediate success the second time – proceed to send control file and data
52 331843:I [06/Oct/2008:07:22:03 -0600] [Job 1044668] Sending control file (78 bytes)
53 331844:I [06/Oct/2008:07:22:03 -0600] [Job 1044668] Control file sent successfully
54 331845:D [06/Oct/2008:07:22:03 -0600] [Job 1044668] lpd_command 03 1714 dfA072linux4
55 331846:D [06/Oct/2008:07:22:03 -0600] [Job 1044668] Sending command string (19 bytes)...
56 331847:D [06/Oct/2008:07:22:03 -0600] [Job 1044668] Reading command status...
57 331848:D [06/Oct/2008:07:22:03 -0600] [Job 1044668] lpd_command returning 0
58 331849:I [06/Oct/2008:07:22:03 -0600] [Job 1044668] Sending data file (1714 bytes)
59 331850:I [06/Oct/2008:07:22:03 -0600] [Job 1044668] Spooling LPR job, 0% complete...
60 331851:I [06/Oct/2008:07:22:04 -0600] [Job 1044668] Data file sent successfully
61 331855:D [06/Oct/2008:07:22:04 -0600] UpdateJob: job 1044668, file 0 is complete.
62 331857:D [06/Oct/2008:07:22:04 -0600] CancelJob: id = 1044668
63 331858:D [06/Oct/2008:07:22:04 -0600] StopJob: id = 1044668, force = 0
64 660428:D [06/Oct/2008:12:41:05 -0600] CancelJob: id = 1044668
More information about the cups
mailing list