classification
Title: test_logging: bad file descriptor on FreeBSD bot
Type: behavior Stage:
Components: Tests Versions: Python 3.3
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: giampaolo.rodola, orsenthil, python-dev, skrah, vinay.sajip
Priority: normal Keywords: buildbot

Created on 2011-05-09 18:00 by skrah, last changed 2011-05-11 12:24 by vinay.sajip. This issue is now closed.

Files
File name Uploaded Description Edit
server_test.py vinay.sajip, 2011-05-09 20:32 Smaller script which shows up BadStatusLine errors
smtp_test.py vinay.sajip, 2011-05-09 23:58 Script which runs on Linux, Windows but fails on FreeBSD 8
Messages (21)
msg135622 - (view) Author: Stefan Krah (skrah) * (Python committer) Date: 2011-05-09 18:00
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
msg135639 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2011-05-09 20:29
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.
msg135640 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2011-05-09 20:32
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.
msg135645 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2011-05-09 20:51
The rest isn't actually failing - it's just that a spurious BadStatusLine exception appears to be being raised.
msg135647 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2011-05-09 21:01
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]
msg135653 - (view) Author: Stefan Krah (skrah) * (Python committer) Date: 2011-05-09 21:32
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')
msg135654 - (view) Author: Stefan Krah (skrah) * (Python committer) Date: 2011-05-09 21:34
Maybe this link to the revision works: 2ab07776510c
msg135665 - (view) Author: Senthil Kumaran (orsenthil) * (Python committer) Date: 2011-05-09 23:45
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.
msg135670 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2011-05-09 23:58
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.
msg135678 - (view) Author: Roundup Robot (python-dev) (Python triager) Date: 2011-05-10 06:48
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
msg135679 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2011-05-10 06:49
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.
msg135682 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2011-05-10 07:05
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.
msg135689 - (view) Author: Roundup Robot (python-dev) (Python triager) Date: 2011-05-10 08:10
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
msg135691 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2011-05-10 09:12
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.
msg135696 - (view) Author: Senthil Kumaran (orsenthil) * (Python committer) Date: 2011-05-10 10:07
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.
msg135702 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2011-05-10 14:06
@Senthil - are you planning to make the documentation change, or should I?
msg135705 - (view) Author: Senthil Kumaran (orsenthil) * (Python committer) Date: 2011-05-10 14:15
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!
msg135758 - (view) Author: Roundup Robot (python-dev) (Python triager) Date: 2011-05-11 03:46
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
msg135760 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2011-05-11 06:42
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().
msg135762 - (view) Author: Senthil Kumaran (orsenthil) * (Python committer) Date: 2011-05-11 07:53
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!
msg135763 - (view) Author: Roundup Robot (python-dev) (Python triager) Date: 2011-05-11 08:04
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
History
Date User Action Args
2011-05-11 12:24:06vinay.sajipsetstatus: open -> closed
resolution: fixed
2011-05-11 08:04:42python-devsetmessages: + msg135763
2011-05-11 07:53:07orsenthilsetmessages: + msg135762
2011-05-11 06:42:18vinay.sajipsetmessages: + msg135760
2011-05-11 03:46:02python-devsetmessages: + msg135758
2011-05-10 14:15:49orsenthilsetmessages: + msg135705
2011-05-10 14:06:41vinay.sajipsetmessages: + msg135702
2011-05-10 10:07:54orsenthilsetmessages: + msg135696
2011-05-10 09:12:57vinay.sajipsetmessages: + msg135691
2011-05-10 08:10:16python-devsetmessages: + msg135689
2011-05-10 07:05:05vinay.sajipsetmessages: + msg135682
2011-05-10 06:49:45vinay.sajipsetmessages: + msg135679
2011-05-10 06:48:39python-devsetnosy: + python-dev
messages: + msg135678
2011-05-09 23:58:15vinay.sajipsetfiles: + smtp_test.py
nosy: + giampaolo.rodola
messages: + msg135670

2011-05-09 23:45:22orsenthilsetmessages: + msg135665
2011-05-09 21:34:17skrahsetmessages: + msg135654
2011-05-09 21:32:11skrahsetmessages: + msg135653
2011-05-09 21:01:55vinay.sajipsetnosy: + orsenthil
messages: + msg135647
2011-05-09 20:51:08vinay.sajipsetmessages: + msg135645
2011-05-09 20:32:32vinay.sajipsetfiles: + server_test.py

messages: + msg135640
2011-05-09 20:29:37vinay.sajipsetmessages: + msg135639
2011-05-09 18:01:58skrahsetkeywords: + buildbot
2011-05-09 18:00:45skrahcreate