AssertionErrors in httplib

[smontanaro]

BPO	666219
Nosy	@smontanaro

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = None
closed_at = <Date 2004-02-17.20:46:54.000>
created_at = <Date 2003-01-11.14:23:23.000>
labels = ['library']
title = 'AssertionErrors in httplib'
updated_at = <Date 2004-02-17.20:46:54.000>
user = 'https://github.com/smontanaro'

bugs.python.org fields:

activity = <Date 2004-02-17.20:46:54.000>
actor = 'nicolary'
assignee = 'jhylton'
closed = True
closed_date = None
closer = None
components = ['Library (Lib)']
creation = <Date 2003-01-11.14:23:23.000>
creator = 'skip.montanaro'
dependencies = []
files = []
hgrepos = []
issue_num = 666219
keywords = []
message_count = 10.0
messages = ['14007', '14008', '14009', '14010', '14011', '14012', '14013', '14014', '14015', '14016']
nosy_count = 4.0
nosy_names = ['jhylton', 'skip.montanaro', 'showme1949', 'nicolary']
pr_nums = []
priority = 'high'
resolution = 'fixed'
stage = None
status = 'closed'
superseder = None
type = None
url = 'https://bugs.python.org/issue666219'
versions = ['Python 2.3']

[smontanaro]

I've recently noticed AssertionErrors being raised by
httplib.LineAndFileWrapper.read(). It happens reliably when the server
exits unexpectedly. Here's an example of an AssertionError in an
xmlrpclib client when I kill the server it's talking to:

    Traceback (most recent call last):
      File "qa.py", line 22, in ?
        x = s.query(tmpl, st, en, radius, age)
      File "/Users/skip/local/lib/python2.3/xmlrpclib.py", line 985, in __call__
        return self.__send(self.__name, args)
      File "/Users/skip/local/lib/python2.3/xmlrpclib.py", line 1269, in __request
        verbose=self.__verbose
      File "/Users/skip/local/lib/python2.3/xmlrpclib.py", line 1036, in request
        return self._parse_response(h.getfile(), sock)
      File "/Users/skip/local/lib/python2.3/xmlrpclib.py", line 1165, in _parse_response
        response = file.read(1024)
      File "/Users/skip/local/lib/python2.3/httplib.py", line 1150, in read
        assert not self._line_consumed and self._line_left
    AssertionError

I don't see a problem with raising an exception in this situation. I just
wonder if AssertionError is the best exception to raise (unless of course, the cause is a logic error in the httplib code). If an exception
is being raised because the server went away, I think it would be
better to raise IncompleteRead.

[jhylton]

Logged In: YES
user_id=31392

It's definitely the case that an AssertionError shouldn't be
raised. It was my intention that the assert never fail. Do
you know which part of the assert fails? Perhaps you could
change the assert to print the values of _line_consumed and
_line_left and run some more tests.
I can't figure out how this goes wrong.

Also, do you know when the server is sending an HTTP/0.9
response? I wonder if there's a bug somewhere else and the
client is guessing the wrong protocol version for the response.

[jhylton]

Logged In: YES
user_id=31392

Any more info Skip?

[smontanaro]

Logged In: YES
user_id=44345

No, sorry, I haven't looked more deeply into the problem. I did investigate
far enough to also see that the code was in the HTTP/0.9 weeds and am
befuddled about why it would be there. It's using the vanilla xmlrpclib
module at both ends. I'll try to spend a little time today.

S

[smontanaro]

Logged In: YES
user_id=44345

Sorry for the delay on this. I think I'm closing in on the
problem. I've been using Tim O'Malley's timeoutsocket
module for quite awhile. I noticed the same problem today
when using the new timeout feature in the socket module.
Libraries like xmlrpclib use makefile() to get a file object
to play with. File objects don't play well with timeouts
because the socket is in non-blocking mode. I think what
happens here is that the first line of HTTPResponse.
_read_status sets line to the empty string because of the
timeout setting. Tracing through the code which follows
makes it clear that control will wind up in the HTTP/0.9
chunk of code.

Maybe it's worth adding a test for line == "" after the
readline() call:

        line = self.fp.readline()
        if self.debuglevel > 0:
            print "reply:", repr(line)
        if line == "":
            raise BadStatusLine(line)

That would distinguish an error reading from an 0.9 server
(which would return something with that first readline()
call).

[jhylton]

Logged In: YES
user_id=31392

We can provoke this error by setting a very small timeout,
right?

[smontanaro]

Logged In: YES
user_id=44345

[small timeout?]

Not since the changes to the makefile() changes to socket.py (or at least
not always). If the timeout is shorter than the response time you now can
get a socket.error:

>>> socket.setdefaulttimeout(0.05)
>>> manatee = xmlrpclib.ServerProxy("http://manatee.mojam.com:5007")
>>> manatee.noop()
Traceback (most recent call last):
  File "<stdin>", line 1, in ?
  File "/Users/skip/local/lib/python2.3/xmlrpclib.py", line 1021, in __call__
    return self.__send(self.__name, args)
  File "/Users/skip/local/lib/python2.3/xmlrpclib.py", line 1308, in __request
    verbose=self.__verbose
  File "/Users/skip/local/lib/python2.3/xmlrpclib.py", line 1056, in request
    errcode, errmsg, headers = h.getreply()
  File "/Users/skip/local/lib/python2.3/httplib.py", line 1019, in getreply
    response = self._conn.getresponse()
  File "/Users/skip/local/lib/python2.3/httplib.py", line 770, in getresponse
    response.begin()
  File "/Users/skip/local/lib/python2.3/httplib.py", line 268, in begin
    version, status, reason = self._read_status()
  File "/Users/skip/local/lib/python2.3/httplib.py", line 230, in _read_status
    line = self.fp.readline()
  File "/Users/skip/local/lib/python2.3/socket.py", line 321, in readline
    data = recv(1)
socket.error: (35, 'Resource temporarily unavailable')

I think you may still get the assertion error if the timeout is sufficient to
allow some of the response to be read, but not all of it (though that's just
a guess).

I suspect we're better off just closing this with either "postponed" or
"won't fix" at this point.

[showme1949]

Logged In: YES
user_id=811410

OK, I saw this problem pretty in several programs (mine or
others). So I deed some search, here is a log that shown
self._line_consumed, self._line_left, self._line and
self._line_offset with bittorrent.

It is pretty obvious when the assert happens, we have a empty
self._line before we even start to read. Maybe because the
other end closed on us without sending any data.

A suggusted fix is to append 'and len(self._line) != 0' to
the end of assert.
-------------- My log on the assert -------
==== line_consumeed, line_left ===
0
0

0
=== self._line, line_offset ===

Exception in thread Thread-3:
Traceback (most recent call last):
  File "/usr/lib/python2.2/threading.py", line 414, in
__bootstrap
    self.run()
  File "/usr/lib/python2.2/threading.py", line 402, in run
    apply(self.__target, self.__args, self.__kwargs)
  File
"/usr/lib/python2.2/site-packages/BitTorrent/Rerequester.py",
line 76, in rer
equest
    r = h.read()
  File "/usr/lib/python2.2/httplib.py", line 1148, in read
    assert not self._line_consumed and self._line_left
AssertionError

[jhylton]

Logged In: YES
user_id=31392

Thanks for the comment, showme1949. It's obvious that the
assertion fails in this case. Fixed by raising an exception
earlier.