[cups.bugs] cups-lpd 300 second timeout problems

[Curtis Rempel]

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