Problem with FUJIXEROXApeosPort MultifunctionDevice and the "Expect:100-continue header"

[Duncan McEwan]

> In this case I didn't see this particular problem for the
> Get-Printer-Attributes, but it looked like the printer responded before
> receiving all of the document data in the Print-Job request.

OK - I didn't look at that part of the trace very closely so that could easily be the case.

> I think right now the best testing path would be to build the current
> trunk code on your system and test against the printer - run "make test"
> to build and run a test server separate from your production one...

In fact, the testing I've been doing to date has just involved running the ipp backend directly from a shell command line, with appropriate DEVICE_URI, CUPS_DEBUG_LOG and CUPS_DEBUG_LEVEL environment variables set.  So testing a newer version without disrupting our production environment is relatively easy.

I've just done that with a version obtained from SVN a day or so ago using the command "svn co http://svn.easysw.com/public/cups/trunk/ cups".  I also obtained the latest 1.4 branch version using "svn co http://svn.easysw.com/public/cups/branches/branch-1.4/ cups-1.4.x".

Neither versions now transmits the "malformed" IPP packet that resulted from the confusion over whether chunked encoding was being used.  So the fix for STR #3778 works for me!

But both versions still see a sequence of bogus responses from the printer, which I theorised earlier seem to be data from a previously received reply that has been buffered somewhere and the buffer not cleared when a new HTTP/IPP connection is made after the backend has slept.  But despite this similarity, their behaviour is not the same.

The latest 1.4 branch version behaves identically to 1.4.4, producing a sequence of "WARNING: recoverable: Network host 'co256-copier.ecs.vuw.ac.nz' is busy; will retry in XX seconds..." messages before successfully printing the job.

But the version from the trunk goes through a sequence of 10 second delays, without producing the "busy; will retry" diagnostic, before giving up and failing to print.

The difference seems to be that with the 1.4.X branch, the error return caused by reading the bogus packets is mapped into ipp_service_unavailable, whereas in the 1.5 code it is mapped to server-error-internal-error.  This causes a different code path to be executed within the backend itself.  The following is a short extract from the debug log showing (I think) the third attempt to get a valid response
> In this case I didn't see this particular problem for the
> Get-Printer-Attributes, but it looked like the printer responded before
> receiving all of the document data in the Print-Job request.

OK - I didn't look at that part of the trace very closely so that could easily be the case.

> I think right now the best testing path would be to build the current
> trunk code on your system and test against the printer - run "make test"
> to build and run a test server separate from your production one...

In fact, the testing I've been doing to date has just involved running the ipp backend directly from a shell command line, with appropriate DEVICE_URI, CUPS_DEBUG_LOG and CUPS_DEBUG_LEVEL environment variables set.  So testing a newer version without disrupting our production environment is relatively easy.

I've just done that with a version obtained from SVN a day or so ago using the command "svn co http://svn.easysw.com/public/cups/trunk/ cups".  I also obtained the latest 1.4 branch version using "svn co http://svn.easysw.com/public/cups/branches/branch-1.4/ cups-1.4.x".

Neither versions now transmits the "malformed" IPP packet that resulted from the confusion over whether chunked encoding was being used.  So the fix for STR #3778 works for me!

But both versions still see a sequence of bogus HTTP/IPP responses.  I theorised earlier that these seem to be data from a previously received reply that has been buffered somewhere and the buffer was not cleared when a new HTTP/IPP connection was made when the backend retries.

But despite this similarity, their subsequent behaviour is not the same.

The latest 1.4 branch version behaves identically to 1.4.4, producing a sequence of "WARNING: recoverable: Network host 'co256-copier.ecs.vuw.ac.nz' is busy; will retry in XX seconds..." messages, with XX being 5, 10, 15, 20, 25, and 30, before successfully printing the job.

But the version from the trunk goes through a sequence of 10 second delays, without producing the above warning, before giving up and failing to print.

The difference seems to be that with the 1.4.X branch, the error return caused by reading the bogus packets is mapped into "ipp_service_unavailable", whereas in the 1.5 code it is mapped to "server-error-internal-error".  I haven't yet looked at why this difference occurs, but I can see that it causes a different code path to be executed within the backend itself.

The following is a short extract from the debug log showing (I think) the third attempt to get a valid response from the printer to a Get-Printer-Attributes request.

...
03:27:03.710 cupsSendRequest: Waiting for 100-continue...
03:27:03.710 _httpUpdate(http=0xbb531000, status=0xbfbe9014), state=HTTP_POST_SE
ND
03:27:03.710 httpGets(line=0xbfbe0fc8, length=32768, http=0xbb531000)
03:27:03.710 httpGets: Returning "image/tiffI"
03:27:03.710 _httpUpdate: Got "image/tiffI"
03:27:03.710 _httpUpdate: Bad response line "image/tiffI"!
03:27:03.710 cupsSendRequest: status=-1
03:27:03.710 cupsDoIORequest: status=-1
03:27:03.710 httpFlush(http=0xbb531000), state=HTTP_POST_SEND
03:27:03.710 httpRead2(http=0xbb531000, buffer=0xbfbe7028, length=8192)
03:27:03.710 httpRead2: data_remaining=0
03:27:03.710 cupsDoIORequest: status=-1
03:27:03.710 cupsArrayAdd(a=0xbb50c180, e=0xbb516fd0)
03:27:03.710 _cupsSetError: last_error=server-error-internal-error, last_status_
message="Unknown"
03:27:03.710 ippDelete(ipp=0xbb528070)
03:27:03.710 _ippFreeAttr(attr=0xbb50b080)
03:27:03.710 _ippFreeAttr(attr=0xbb50b0c0)
03:27:03.710 _ippFreeAttr(attr=0xbb50b0e0)
03:27:03.710 _ippFreeAttr(attr=0xbb534100)
DEBUG: Get-Printer-Attributes returned server-error-internal-error.
ERROR: Unable to get printer status: Unknown
...

I chose this extract because I thought the "image/tiffI" string that was read was more obviously a fragment of an IPP response packet.  The previous two attempts were logged as:

   03:26:43.700 _httpUpdate: Bad response line "2a7"!
   ...
   03:26:53.702 _httpUpdate: Bad response line "\001"!

I haven't (yet) obtained and analysed a wire trace to see if "2a7\n" and "\001\n" do appear earlier in a response packet that also contains the "image/tiffI\n" string.  If they do, that would indicate that the problem has a similar cause in both the 1.4 branch and the trunk, with the different outcome being due to other changes in the code.  I plan to do this tomorrow, as well as digging deeper in to the code to try to understand where a response packet could be being buffered and whether I can see any situations in which the buffer might not be cleared.

I'll report back if/when I find anything...

Duncan