Problem with FUJI XEROX ApeosPort Multifunction Device and the "Expect: 100-continue header"

[Duncan McEwan]

Hi,

Sorry for the length of this post.  I wanted to provide enough information to allow others more knowledgeable than me to determine if the following analysis is correct, and/or what can be done to fix/workaround the issue described here.

We recently upgraded from an earlier version of CUPS (sorry - not sure which right now - probably 1.3.9 or 1.4.3) to 1.4.4 and started noticing a delay of around two minutes when printing via IPP to our Fuji Xerox photocopiers.

Our CUPS server is running on NetBSD 5.1 on i386, though I don't think that is important here.

I've tracked this down as far as my limited knowledge of the HTTP and IPP protocols will allow, using tcpdump to get a packet trace and a version of the IPP backend with debugging compiled in and CUPS_DEBUG_LEVEL set to 10.

The output from the ipp backend without the extra level 10 debugging contains the following extract:

...
INFO: Connecting to printer...
STATE: -connecting-to-device
INFO: Connected to printer...
ATTR: marker-levels=50,75,75,75,100,100,100,100,100,1,100,10,100,100,100,100,1,100,100,100,100,0
WARNING: recoverable: Network host 'co256-copier.ecs.vuw.ac.nz' is busy; will retry in 5 seconds...
WARNING: recoverable: Network host 'co256-copier.ecs.vuw.ac.nz' is busy; will retry in 10 seconds...
WARNING: recoverable: Network host 'co256-copier.ecs.vuw.ac.nz' is busy; will retry in 15 seconds...
WARNING: recoverable: Network host 'co256-copier.ecs.vuw.ac.nz' is busy; will retry in 20 seconds...
WARNING: recoverable: Network host 'co256-copier.ecs.vuw.ac.nz' is busy; will retry in 25 seconds...
WARNING: recoverable: Network host 'co256-copier.ecs.vuw.ac.nz' is busy; will retry in 30 seconds...
STATE: none
INFO: recovered:
INFO: Printer busy; will retry in 10 seconds...
NOTICE: Print file accepted - job ID 10.
INFO: Waiting for job to complete...
STATE: none
PAGE: total 1
...

The full debugging trace is available at http://ecs.victoria.ac.nz/~duncan/co256-copier-cups-trace.txt (1.6MB in size).

The tcpdump trace is at http://ecs.victoria.ac.nz/~duncan/co256-copier.dump (90KB).  I've used wireshark to analyse this, but I'm not sure if this will work on a non-NetBSD system.

>From the above, the ~2 minute delay is obviously related to the "Network host ... is busy' message repeated six times with the increasing delay each time.

>From the CUPS trace and the tcpdump trace and looking at the code here is what I *think* is happening.

1) CUPS sends a Get-Printer-Attributes request, with the "Expect: 100-continue" header set.

2) Instead of responding with "100 continue", the printer responds to the actual request with an "HTTP/1.1 200 OK".

3) CUPS gets confused by this and so retransmits the request after an (increasing delay).

4) Eventually the printer gets tired of this game and sends a TCP RST, which causes the IPP backend to see a different error, so it breaks out of this loop and goes on to transmit the file to be printed.  A similar problem seems to occur again regarding handling the "Expect: 100-continue" header, but I guess by now the data has been sent and so the file gets printed...

That's a very quick summary of what I think the code in backend/ipp.c, cups/request.c and cups/http.c appears to be doing.

I am far from an expert in the IPP and/or HTTP protocols, but I did have a quick read of rfc2616 and found the following passage:

    An origin server MAY omit a 100 (Continue) response if it has
    already received some or all of the request body for the
    corresponding request.

I think this may be the case here.  From the debugging output, it seems that CUPS sends the actual IPP Get-Printer-Attributes request in the same packet as the HTTP header with "Expect: 100-continue".  From rfc2616, it seems that the normal use would be to send the header and then the subsequent request once the "100 continue" response was received.

As an aside, I'm not sure why CUPS is bothering with the "Expect: 100-continue" header in this case, as the Get-Printer-Attributes request is not large.  I can see that it might be useful to include it in the "Print-Job" request if the file to be printed is big.

I did search old forum postings and found STR #1407, in which it is said:

    The strategy we are using in CUPS 1.2 is to send the Expect header but
    only wait 1 second for the 100-continue response. If we don't get a
    response, we continue as if we got the response...

I think the problem here may be that instead of getting no response and therefore continuing as if one had been received, CUPS gets the "HTTP/1.1 200 OK", which might confuse it (though I haven't had a careful look at the relevant code to see if this is indeed the case).

While investigating this issue, I noticed something that is most likely not at all related to the main problem described above.  In the tcpdump trace wireshark flagged some "Malformed" IPP Request packets.  I believe these are related to the "cupsGetResponse: Finishing chunked POST..." messages in the debug trace.  The odd thing is that CUPS doesn't seem to be sending the preceeding requests using the chunked encoding format, which is perhaps what is causing wireshark to flag those packets as being malformed?

Thanks,

Duncan