librarian.txt fails sometimes

[Jonathan Lange]

A run of the test suite just failed with this error:

======================================================================
FAILURE: lib/canonical/launchpad/doc/librarian.txt (subunit.RemotedTestCase)
----------------------------------------------------------------------
_StringException: Text attachment: traceback
------------
Traceback (most recent call last):
 File "/usr/lib/python2.6/unittest.py", line 279, in run
   testMethod()
 File "/usr/lib/python2.6/doctest.py", line 2152, in runTest
   raise self.failureException(self.format_failure(new.getvalue()))
AssertionError: Failed doctest test for librarian.txt
 File "lib/canonical/launchpad/ftests/../doc/librarian.txt", line 0

----------------------------------------------------------------------
File "lib/canonical/launchpad/ftests/../doc/librarian.txt", line 476, in librarian.txt
Failed example:
   aid = client.addFile('test.txt', 0, StringIO(''), 'text/plain',
       allow_zero_length=True)
Exception raised:
   Traceback (most recent call last):
     File "/usr/lib/python2.6/doctest.py", line 1248, in __run
       compileflags, 1) in test.globs
     File "<doctest librarian.txt[143]>", line 2, in <module>
       allow_zero_length=True)
     File "/var/launchpad/test/lib/canonical/librarian/client.py", line 166, in addFile
       self._sendLine('')
     File "/var/launchpad/test/lib/canonical/librarian/client.py", line 100, in _sendLine
       self._checkError()
     File "/var/launchpad/test/lib/canonical/librarian/client.py", line 96, in _checkError
       raise UploadFailed('Server said: ' + response)
   UploadFailed: Server said: 200
----------------------------------------------------------------------
File "lib/canonical/launchpad/ftests/../doc/librarian.txt", line 480, in librarian.txt
Failed example:
   f.read()
Differences (ndiff with -expected +actual):
   - ''
   + 'This is some data'

------------

devel was passing at the time, and the branch simply upgraded Launchpad to use Twisted 11.0.0, which had been known to work on a previous test run.

[Stuart Bishop (stub)]

This seems like a genuine bug in the Librarian, and I suspect will be causing uploads to randomly fail on production too. Do we see them in the OOPS reports?

_checkError sees the socket still has data to be read, but when it looks, the data that awaits is a success code. The Librarian is emitting a success code when one is not expected, and normally this passes because the check is made immediately after sending information to the Librarian and the Librarian will have normally not had time yet to process the information and respond.

[Stuart Bishop (stub)]

Or perhaps the success response was destined for a previous request but wasn't consumed, eg. by arriving too late.

[Martin Pool (mbp)]

I just saw the same failure in an unrelated branch.

[Abel Deuring (adeuring)]

This looks as being caused by a very fast response from the server:

The client wants to upload a zero-length file, so it only needs to send the header lines, and to finish the headers with an empty line. No other data will be transferred.

The exception is raised in _checkError(), called from _sendLine('') in addFile(). That's the empty line saying "all headers sent". Since no further data is sent, the server can respond immediately, but the client considers any response seen in the _checkError() call in _sendLine() as an error notification.

We should simply not do the error check in the _sendLine('') call when a zero-length file is uploaded. The 200 response is correct, but it is supposed to be read at line 188 in addFile()