The FreeBSD-AMD64 bot shows an error in test_logging:

http://www.python.org/dev/buildbot/all/builders/AMD64%20FreeBSD%208.2%203.x/builds/243/steps/test/logs/stdio

Exception in thread Thread-281:
Traceback (most recent call last):
  File "/usr/home/buildbot/buildarea/3.x.krah-freebsd/build/Lib/threading.py", line 737, in _bootstrap_inner
    self.run()
  File "/usr/home/buildbot/buildarea/3.x.krah-freebsd/build/Lib/threading.py", line 690, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/home/buildbot/buildarea/3.x.krah-freebsd/build/Lib/test/test_logging.py", line 726, in serve_forever
    asyncore.loop(poll_interval, map=self.sockmap)
  File "/usr/home/buildbot/buildarea/3.x.krah-freebsd/build/Lib/asyncore.py", line 214, in loop
    poll_fun(timeout, map)
  File "/usr/home/buildbot/buildarea/3.x.krah-freebsd/build/Lib/asyncore.py", line 144, in poll
    r, w, e = select.select(r, w, e, timeout)
select.error: (9, 'Bad file descriptor')

Traceback (most recent call last):
  File "/usr/home/buildbot/buildarea/3.x.krah-freebsd/build/Lib/logging/handlers.py", line 1053, in emit
    h.getresponse()    #can't do anything with the result
  File "/usr/home/buildbot/buildarea/3.x.krah-freebsd/build/Lib/http/client.py", line 1046, in getresponse
    response.begin()
  File "/usr/home/buildbot/buildarea/3.x.krah-freebsd/build/Lib/http/client.py", line 346, in begin
    version, status, reason = self._read_status()
  File "/usr/home/buildbot/buildarea/3.x.krah-freebsd/build/Lib/http/client.py", line 316, in _read_status
    raise BadStatusLine(line)
http.client.BadStatusLine: ''
Logged from file test_logging.py, line 1493
/usr/home/buildbot/buildarea/3.x.krah-freebsd/build/Lib/logging/__init__.py:837: ResourceWarning: unclosed <socket.socket object, fd=6, family=2, type=1, proto=6>
  self.emit(record)
Traceback (most recent call last):
  File "/usr/home/buildbot/buildarea/3.x.krah-freebsd/build/Lib/logging/handlers.py", line 1053, in emit
    h.getresponse()    #can't do anything with the result
  File "/usr/home/buildbot/buildarea/3.x.krah-freebsd/build/Lib/http/client.py", line 1046, in getresponse
    response.begin()
  File "/usr/home/buildbot/buildarea/3.x.krah-freebsd/build/Lib/http/client.py", line 346, in begin
    version, status, reason = self._read_status()
  File "/usr/home/buildbot/buildarea/3.x.krah-freebsd/build/Lib/http/client.py", line 316, in _read_status
    raise BadStatusLine(line)
http.client.BadStatusLine: ''
Logged from file test_logging.py, line 1493

I've made recent changes in test_logging to improve coverage, but these errors were not being raised on my local development machine (Ubuntu Jaunty). They have recently started occurring on my machine, too, so at the moment I'm suspecting some other change which is causing an interaction with test_logging.

I've attached a smaller script which shows up the error. It's not tiny, but tests the SMTP and HTTP handler tests which show the failures mentioned in Stefan's post.

The rest isn't actually failing - it's just that a spurious BadStatusLine exception appears to be being raised.

The change which causes the apparently spurious messages is one made by Senthil: 25298224cb25 - with the earlier revision 1ac03e071d65 the messages don't occur, as you can see here:

vinay@eta-jaunty:~/projects/python/default$ hg update -r 69980
merging Lib/test/test_logging.py
5 files updated, 1 files merged, 0 files removed, 0 files unresolved
vinay@eta-jaunty:~/projects/python/default$ python3.3 Lib/test/regrtest.py test_logging
[1/1] test_logging
1 test OK.
[131048 refs]
vinay@eta-jaunty:~/projects/python/default$ hg update -r 69981
4 files updated, 0 files merged, 0 files removed, 0 files unresolved
vinay@eta-jaunty:~/projects/python/default$ python3.3 Lib/test/regrtest.py test_logging
[1/1] test_logging
Traceback (most recent call last):
  File "/home/vinay/projects/python/default/Lib/logging/handlers.py", line 1053, in emit
    h.getresponse()    #can't do anything with the result
  File "/home/vinay/projects/python/default/Lib/http/client.py", line 1046, in getresponse
    response.begin()
  File "/home/vinay/projects/python/default/Lib/http/client.py", line 346, in begin
    version, status, reason = self._read_status()
  File "/home/vinay/projects/python/default/Lib/http/client.py", line 316, in _read_status
    raise BadStatusLine(line)
http.client.BadStatusLine: ''
Logged from file test_logging.py, line 1484
/home/vinay/projects/python/default/Lib/logging/__init__.py:837: ResourceWarning: unclosed <socket.socket object, fd=4, family=2, type=1, proto=6>
  self.emit(record)
Traceback (most recent call last):
  File "/home/vinay/projects/python/default/Lib/logging/handlers.py", line 1053, in emit
    h.getresponse()    #can't do anything with the result
  File "/home/vinay/projects/python/default/Lib/http/client.py", line 1046, in getresponse
    response.begin()
  File "/home/vinay/projects/python/default/Lib/http/client.py", line 346, in begin
    version, status, reason = self._read_status()
  File "/home/vinay/projects/python/default/Lib/http/client.py", line 316, in _read_status
    raise BadStatusLine(line)
http.client.BadStatusLine: ''
Logged from file test_logging.py, line 1484
/home/vinay/projects/python/default/Lib/logging/__init__.py:837: ResourceWarning: unclosed <socket.socket object, fd=4, family=2, type=1, proto=6>
  self.emit(record)
1 test OK.
[131005 refs]

We might have two issues here. On FreeBSD the select.error occurs
reliably starting with r69723 (when the tests were added):

[buildbot@freebsd-amd64 /usr/home/buildbot/cpython]$ ./python -m test -uall test_logging
[1/1] test_logging
/usr/home/buildbot/cpython/Lib/logging/handlers.py:475: ResourceWarning: unclosed <socket.socket object, fd=3, family=2, type=1, proto=0>
  self.retryTime = now + self.retryPeriod
/usr/home/buildbot/cpython/Lib/logging/handlers.py:475: ResourceWarning: unclosed <socket.socket object, fd=3, family=2, type=1, proto=0>
  self.retryTime = now + self.retryPeriod
Exception in thread Thread-9:
Traceback (most recent call last):
  File "/usr/home/buildbot/cpython/Lib/threading.py", line 737, in _bootstrap_inner
    self.run()
  File "/usr/home/buildbot/cpython/Lib/threading.py", line 690, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/home/buildbot/cpython/Lib/test/test_logging.py", line 667, in serve_forever
    asyncore.loop(poll_interval, map=self.sockmap)
  File "/usr/home/buildbot/cpython/Lib/asyncore.py", line 214, in loop
    poll_fun(timeout, map)
  File "/usr/home/buildbot/cpython/Lib/asyncore.py", line 144, in poll
    r, w, e = select.select(r, w, e, timeout)
select.error: (9, 'Bad file descriptor')

Maybe this link to the revision works: 2ab07776510c

I could reproduce the BadStatusLine exception using Vinay's server_test.py. I see that the exception is triggered by logging package when it is trying to http.client's getresponse() before it is ready. The previous commit 25298224cb25 was on http.server (client code was not involved) and surprised at how it could be a trigger. Shall provide updates after further investigation.

Ok, I'll leave the BadStatusLine problem for Senthil to investigate. I have reproduced the problem with the SMTP server on FreeBSD, but this problem does not occur on Linux and I'm not sure why it would fail on FreeBSD.

I've attached a script, smtp_test.py, which does not involve logging code at all, just smtpd, smtplib and other support code. This runs without errors on Linux (Ubuntu Jaunty) and Windows 7 but fails with "bad file descriptor" on my test machine running FreeBSD 8 (32-bit).

Added Giampaolo to nosy as he may be able to spot the problem.

New changeset b365036b17c2 by Vinay Sajip in branch 'default':
Issue #12039: Now suppress spurious select.error raised on FreeBSD when the server (an asyncore.dispatcher) is closed.
http://hg.python.org/cpython/rev/b365036b17c2

I've done a bit more investigating, and the select.error is raised in the server thread when the main thread closes the SMTP server (asyncore.dispatcher). I've modified the server code to swallow the error if the server has been closed.

This closes the issue as far as the select.error is concerned - leaving open for Senthil's follow-up on BadStatusLine.

Additional information point for Senthil: In the case where the BadStatusLine is raised, the server is sending a 200 OK status response but there is no actual response data - only headers.

New changeset 204e027dfa98 by Vinay Sajip in branch 'default':
Issue #12039: Add end_headers() call to avoid BadStatusLine.
http://hg.python.org/cpython/rev/204e027dfa98

The errors seem to have gone away now, but there is still apparently a behaviour change - previously there was no error when a end_headers() call was omitted when handling a request, but now apparently an end_headers() call is needed to avoid the error.

Either omitting the end_headers() call was always an error but previously undetected, or the requirement to always call end_headers() is new and this should be documented. I'm not sure which of these is the case, but leaving open since I think the http.server documentation ought to be changed. Apart from this I think the issue can be closed.

On Tue, May 10, 2011 at 09:12:58AM +0000, Vinay Sajip wrote:
> Either omitting the end_headers() call was always an error but
> previously undetected, or the requirement to always call
> end_headers() is new and this should be documented. I'm not sure
> which of these is the case, but leaving open since I think the
> http.server documentation ought to be changed. Apart from this I

end_headers was added 3.2, so that all the headers can be cached and
sent at once instead of writing one header at a time to the output
stream. This is a new change in 3.3, where end_header calls
flush_header which does the job of writing and clearing the cache.

The need to call end_header always is new (at least from 3.2, because
I see the http.server code itself using end_header at the end whenever
it uses send_header)

Following is the information in the updated docs.

.. method:: send_header(keyword, value)

         Adds the HTTP header to an internal buffer which will be
         written to the output stream when either :meth:`end_headers`
         or :meth:`flush_headers` is invoked. 

I think, a little change in wording saying that end_headers or
flush_headers MUST BE called would make it more prominent.

@Senthil - are you planning to make the documentation change, or should I?

On Tue, May 10, 2011 at 02:06:48PM +0000, Vinay Sajip wrote:
> @Senthil - are you planning to make the documentation change, or should I?

I shall do it, Vinay.

Thanks!

New changeset d59ec3aa442e by Senthil Kumaran in branch 'default':
Issue #12039 - Update the http.server.rst with the requirement to call `end_headers` after calling `send_header`.
http://hg.python.org/cpython/rev/d59ec3aa442e

Senthil: Almost, but not quite. end_headers() needs to be called even if send_header() isn't called (though it may be being called behind the scenes, that's not necessarily obvious to a user).

In my original unit-testing code, I had only

request.send_response(200)

and that caused a failure. My code now has to read

request.send_response(200)
request.end_headers()

No send_header() in sight! Perhaps the end_header() call requirement should also be mentioned in the docs on send_response().

Hi Vinay, 

Normally, when one uses send_response() call, it is most often followed with
(multiple) send_header() calls and I updated the documentation keeping that in
mind.

Just calling of send_response() without any send_header and end_headers was an
interesting use-case and I started thinking if http.server's behavior should
change in order to support such a use-case.  But such a thing does not play
well with our recent change of caching and sending the headers.  For instance,
send_header and end_headers call might still be expected after send_response
and in which case, server's sending of headers would break. ( It would send it
two '\r\n' separated chunks, which is undesirable).

I think, it is best to add a note after send_response that it should be
followed by an end_header if the sever does not want to send any more headers.

I shall update this information.

Thanks!

New changeset 4651bf40af8d by Senthil Kumaran in branch 'default':
issue12039 - update the documentation of send_response method in http.server.rst.
http://hg.python.org/cpython/rev/4651bf40af8d