Issue 12039: test_logging: bad file descriptor on FreeBSD bot (original) (raw)
Created on 2011-05-09 18:00 by skrah, last changed 2022-04-11 14:57 by admin. This issue is now closed.
Messages (21)
Author: Stefan Krah (skrah) * 
Date: 2011-05-09 18:00
The FreeBSD-AMD64 bot shows an error in test_logging:
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
Author: Vinay Sajip (vinay.sajip) *
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.
Author: Vinay Sajip (vinay.sajip) *
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.
Author: Vinay Sajip (vinay.sajip) *
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.
Author: Vinay Sajip (vinay.sajip) *
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]
Author: Stefan Krah (skrah) *
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')
Author: Stefan Krah (skrah) *
Date: 2011-05-09 21:34
Maybe this link to the revision works: 2ab07776510c
Author: Senthil Kumaran (orsenthil) *
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.
Author: Vinay Sajip (vinay.sajip) *
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.
Author: Roundup Robot (python-dev) 
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
Author: Vinay Sajip (vinay.sajip) *
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.
Author: Vinay Sajip (vinay.sajip) *
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.
Author: Roundup Robot (python-dev)
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
Author: Vinay Sajip (vinay.sajip) *
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.
Author: Senthil Kumaran (orsenthil) *
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.
Author: Vinay Sajip (vinay.sajip) *
Date: 2011-05-10 14:06
@Senthil - are you planning to make the documentation change, or should I?
Author: Senthil Kumaran (orsenthil) *
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!
Author: Roundup Robot (python-dev)
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
Author: Vinay Sajip (vinay.sajip) *
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().
Author: Senthil Kumaran (orsenthil) *
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!
Author: Roundup Robot (python-dev)
Date: 2011-05-11 08:04
New changeset 4651bf40af8d by Senthil Kumaran in branch 'default': - update the documentation of send_response method in http.server.rst. http://hg.python.org/cpython/rev/4651bf40af8d
History
Date
User
Action
Args
2022-04-11 14:57:17
admin
set
github: 56248
2011-05-11 12:24:06
vinay.sajip
set
status: open -> closed
resolution: fixed
2011-05-11 08:04:42
python-dev
set
messages: +
2011-05-11 07:53:07
orsenthil
set
messages: +
2011-05-11 06:42:18
vinay.sajip
set
messages: +
2011-05-11 03:46:02
python-dev
set
messages: +
2011-05-10 14:15:49
orsenthil
set
messages: +
2011-05-10 14:06:41
vinay.sajip
set
messages: +
2011-05-10 10:07:54
orsenthil
set
messages: +
2011-05-10 09:12:57
vinay.sajip
set
messages: +
2011-05-10 08:10:16
python-dev
set
messages: +
2011-05-10 07:05:05
vinay.sajip
set
messages: +
2011-05-10 06:49:45
vinay.sajip
set
messages: +
2011-05-10 06:48:39
python-dev
set
nosy: + python-dev
messages: +
2011-05-09 23:58:15
vinay.sajip
set
files: + smtp_test.py
nosy: + giampaolo.rodola
messages: +
2011-05-09 23:45:22
orsenthil
set
messages: +
2011-05-09 21:34:17
skrah
set
messages: +
2011-05-09 21:32:11
skrah
set
messages: +
2011-05-09 21:01:55
vinay.sajip
set
nosy: + orsenthil
messages: +
2011-05-09 20:51:08
vinay.sajip
set
messages: +
2011-05-09 20:32:32
vinay.sajip
set
files: + server_test.py
messages: +
2011-05-09 20:29:37
vinay.sajip
set
messages: +
2011-05-09 18:01:58
skrah
set
keywords: + buildbot
2011-05-09 18:00:45
skrah
create