[cups.bugs] [MOD] STR #3791: CUPS ipp backend doesn't handle printers that don't send 100-continue

Mon Feb 7 23:03:40 PST 2011

DO NOT REPLY TO THIS MESSAGE.  INSTEAD, POST ANY RESPONSES TO THE LINK BELOW.

[STR New]

This is a bug report based on an investigation I've carried out that is
reported in a series of postings in cups.bugs with the title "Problem 
with FUJI XEROX ApeosPort MultifunctionDevice and the "Expect: 
100-continue header".

A brief summary of the problem is that we have a bunch of the above
mentioned photocopier/printers which don't seem to return the "100 
continue" response when CUPS sends a "Get-Printer-Attributes" request 
that includes the HTTP "Expect: 100-continue" header.  This causes CUPS 
to get out of sync with the printer, reading bogus data, which causes a 
delay of around two minutes before it finally gets back in sync and is 
able to send a "Print-Job".

I don't know the HTTP or IPP protocol standards well enough to know 
whether this printer behaviour is legal or not.  But regardless, I 
believe there are bugs in the CUPS ipp implementation that cause it to 
not handle the situation as well as it should do.

As a result of my postings to cups.bugs, the bug report STR #3778 was
filed.  This fixed a side issue that I had noted in my postings, but not
the main problem I was describing, though it did alter the way the
problem occurred slightly.

Also, as a result of STR #3778 I redid my tests on a 1.5 svn trunk 
version of CUPS and although the behaviour changed slightly the problem 
still occured in a roughly similar way.  The following description is 
based on the testing I've done on the 1.5 trunk including the STR #3778 
fixes.

1) The CUPS ipp driver calls cupsDoRequest(), which calls 
   cupsDoIORequest() which calls cupsSendRequest() to send 
   Get-Printer-Attributes with "Expect: 100-continue" in the http header

2) CUPS waits for the printer to respond with "100 continue", but 
   instead the printer responds with "HTTP/1.1 200 OK" followed by the 
   printer attributes that were requested.

3) cupsSendRequest() calls _httpUpdate() to read the response.  This
   calls httpGets() which reads the HTTP header into http->buffer and 
   then returns "HTTP/1.1 200 OK" line.  At this point I don't think the
   IPP portion of the response is buffered because it was sent by the
   printer in a separate segment and so CUPS hasn't read it yet, but I
   don't believe that matters to what happens next.

4) cupsGetResponse() is called by cupsDoIORequest().  Because 
   http->status is 200 rather than the 100 that it is expected to be if 
   the printer had responded with "100 continue", the loop calling 
   httpUpdate() doesn't get executed to read the rest of the HTTP 
   header.  So then ippRead() is called which I believe is expecting to 
   see the IPP portion of the packet, but instead sees the remainder of 
   the http header still stored in http->buffer.  The following extract 
   from a debug trace shows this:

        03:20:03.829 cupsSendRequest: Waiting for 100-continue...
        03:20:03.829 _httpWait(http=0xbb531000, msec=1000, usessl=1)
        03:20:03.836 _httpWait: returning with nfds=1, errno=2...
        03:20:03.836 _httpUpdate(http=0xbb531000, status=0xbfbe9004),
state=HTTP_POST_SEND
        03:20:03.836 httpGets(line=0xbfbe0fb8, length=32768,
http=0xbb531000)
        03:20:03.836 httpGets: read 158 bytes...
        03:20:03.836 httpGets: Returning "HTTP/1.1 200 OK"
        03:20:03.836 _httpUpdate: Got "HTTP/1.1 200 OK"
        03:20:03.836 cupsSendRequest: status=200
        03:20:03.836 cupsDoIORequest: status=200
        03:20:03.836 cupsGetResponse(http=0xbb531000, resource="/ipp")
        03:20:03.836 cupsGetResponse: Update loop, http->status=200...
        03:20:03.836 cupsGetResponse: status=200
        03:20:03.836 ippNew()
        03:20:03.836 ippNew: Returning 0xbb401130
        03:20:03.836 ippRead(http=0xbb531000, ipp=0xbb401130),
data_remaining=0
        03:20:03.836 ippRead: http->state=7, http->used=141
        03:20:03.836 ippReadIO(src=0xbb531000, cb=0xbbbb374d, blocking=1,
parent=0x0, ipp=0xbb401130)
        03:20:03.836 ippReadIO: ipp->state=0
        03:20:03.836 ippReadIO: version=67.97
        03:20:03.836 ippReadIO: op_status=6368
        03:20:03.836 ippReadIO: request_id=1697465199
        03:20:03.836 ippReadIO: ipp->current=0x0, ipp->prev=0x0
        03:20:03.836 ippReadIO: value tag=6e(UNKNOWN)
        03:20:03.836 ippReadIO: name length=29810
        03:20:03.836 httpRead2(http=0xbb531000, buffer=0xbb40e082,
length=29680)
        03:20:03.836 httpRead2: data_remaining=-141
        03:20:03.836 ippReadIO: unable to read name!
        03:20:03.836 cupsGetResponse: IPP read error!
        03:20:03.836 ippDelete(ipp=0xbb401130)
        03:20:03.836 _cupsSetError:
last_error=server-error-service-unavailable, last_status_message="(null)"

   Note the bogus version that gets reported.  The characters 67 and 97
   correspond to the characters "C" and "a", which look to me like the
   next part of the HTTP headers "Cache-Control: ...".  However, the
   attempt to read the IPP response has caused the remaining part of
   the HTTP header in http->buffer to be consumed.

5) The failure to read a valid IPP header and the return of the error 
   status "server-error-service-unavailable" causes cupsDoIORequest() to 
   retry the cupsSendRequest().  This again results in calls to 
   _httpUpdate() and httpGets().  By now the IPP portion of the printers 
   response has arrived and so this data is read into http->buffer by    
   ipp_read_http().  A debug trace shows the following:

       ...
       03:20:03.836 cupsSendRequest: Waiting for 100-continue...
       03:20:03.836 _httpWait(http=0xbb531000, msec=1000, usessl=1)
       03:20:03.837 _httpWait: returning with nfds=1, errno=0...
       03:20:03.837 _httpUpdate(http=0xbb531000, status=0xbfbe9004),
state=HTTP_POST_SEND
       03:20:03.837 httpGets(line=0xbfbe0fb8, length=32768,
http=0xbb531000)
       03:20:03.837 httpGets: read 691 bytes...
       03:20:03.837 httpGets: Returning "2a7"
       03:20:03.837 _httpUpdate: Got "2a7"
       03:20:03.837 _httpUpdate: Bad response line "2a7"!
       03:20:03.837 cupsSendRequest: status=-1
       03:20:03.837 cupsDoIORequest: status=-1
       03:20:03.837 httpFlush(http=0xbb531000), state=HTTP_POST_SEND
       03:20:03.837 httpRead2(http=0xbb531000, buffer=0xbfbe7018,
length=8192)
       03:20:03.837 httpRead2: data_remaining=0
       03:20:03.837 cupsDoIORequest: status=-1
       03:20:03.837 cupsArrayAdd(a=0xbb4030c0, e=0xbb407060)
       03:20:03.837 _cupsSetError: last_error=server-error-internal-error,
last_status_message="Unknown"
       ...

   From a tcpdump wire trace I have the "2a7" that is read corresponds 
   to the chunk length of the chunked response from the printer.  This 
   time there isn't even a valid HTTP header buffered in http->buffer, 
   which results in -1 (HTTP_ERROR) being returned to cupsDoIORequest().  
   This is mapped into "server-error-internal-error" and results in 
   cupsDoIORequest() breaking out of its while loop and eventually 
   returning back to the ipp backend.

6) The ipp backend sees the internal error indication, sleeps for 10 
   seconds and then retries.  The second of the above two error 
   situations reoccurs several times with successive portions of the 
   printers first IPP response being misinterpreted as HTTP headers.

7) Eventually the entire first buffered response is consumed and so the
   next response is read.  I'm not 100% sure what happens that is 
   different this time, but it appears from my debug trace that valid
   HTTP and IPP responses are read and so the Get-Printer-Attributes 
   request finally succeeds.

8) Now the ipp backend attempts to send a "Validate-Job" request.  This
   fails, I believe for the same reasons that the original
   Get-Printer-Attributes request failed, and so ipp aborts the entire
   print attempt.

With the CUPS 1.4.4 that I originally started this investigation with
the situation was a little different.

Prior to the fix for STR #3778 going in, the call to _httpUpdate() was 
actually a call to httpUpdate() and so the consuming of data from 
http->buffer was a little different.  But a similar situation where data 
was read from the buffer and incorrectly interpreted as an HTTP header 
was observed.

Also, no "Validate-Job" request was sent, so the print job actually 
succeeded eventually, after a delay of approximately two minutes.  I can 
provide more details of the sequence of events for this version if 
required.  But I figured if the problem could be solved for the 1.5
trunk version first, then a similar fix for the 1.4 branch might be
fairly obvious, without needing to go through all that detail...

It may be the case that these printers are violating the RFC by not 
sending "100 continue" when a they receive a request with an "Expect: 
100-continue" header.  From my quick reading of the RFC, it seemed that 
this behaviour was legal as long as an entire request had been received, 
but there could be subtleties that I missed.  Regardless, hopefully the 
CUPS software can at least be fixed to detect this situation and report 
it correctly.

Thanks,

Duncan

Link: http://www.cups.org/str.php?L3791
Version: 1.4-current