classification
Title: Neverending warnings from asyncore
Type: behavior Stage: test needed
Components: Library (Lib) Versions: Python 2.7
process
Status: closed Resolution: accepted
Dependencies: Superseder:
Assigned To: josiahcarlson Nosy List: ajaksu2, akuchling, alexer, anadelonbrin, giampaolo.rodola, gregory.p.smith, josiahcarlson, tim.peters
Priority: normal Keywords: patch

Created on 2005-03-11 00:34 by anadelonbrin, last changed 2009-04-01 15:27 by brett.cannon. This issue is now closed.

Files
File name Uploaded Description Edit
unnamed brett.cannon, 2009-03-31 15:09
async_no_warn.patch josiahcarlson, 2009-03-31 18:16
Messages (28)
msg24529 - (view) Author: Tony Meyer (anadelonbrin) Date: 2005-03-11 00:34
Changes in asyncore from 2.3 to 2.4 mean that
asyncore.poll() now passes all the sockets in the map
to select.select() to be checked for errors, which is
probably a good thing.  If an error occurs, then
handle_expt() is called, which by default logs the error.

asyncore.dispatcher creates nonblocking sockets.  When
connect_ex() is called on a nonblocking socket, it will
probably return EWOULDBLOCK (connecting takes time),
which may mean the connection is successful, or may not
(asyncore dispatcher keeps going assuming all is well).

If the connection is not successful, and then
asyncore.loop() is called, then select.select() will
indicate that there is an error with the socket (can't
connect) and the error will be logged.

The trouble is that asyncore.loop then keeps going, and
will log this error again.  My not-that-fast system
here gets about 10,000 logged messages per second with
a single socket in the asyncore map.

There are ways to avoid this:

  (1) if the socket is blocking when connect()ing (and
then nonblocking afterwards) an error is raised if the
connect fails.

  (2) Before calling asyncore.loop(), the caller can
run through all the sockets, checking that they are ok.

  (3) handle_expt() can be overridden with a function
that repairs or removes the socket from the map (etc)

However, I'm not convinced that this is good behavior
for asyncore to have, by default.  On Windows,
select.select() will only indicate an error when trying
to connect (nonblocking) or if SO_OOBINLINE is
disabled, but this may not be the case (i.e. errors can
occur at other times) with other platforms, right? 
Unless the error is temporary, asyncore will by default
start streaming (extremely fast) a lot of "warning:
unhandled exception" (not very helpful an error
message, either) messages.  Even if the error only
lasts a minute, that could easily result in 10,000
warnings being logged.

Do any of the python developers agree that this is a
flaw?  I'm happy to work up a patch for whatever the
desired solution is, if so.
msg24530 - (view) Author: Josiah Carlson (josiahcarlson) * (Python triager) Date: 2005-05-31 07:03
Logged In: YES 
user_id=341410

Option 1 is not really an option in any case where a large
number of connections are opened (so I don't believe should
be the default).

From what I understand, certain methods are supposed to be
overridden in a subclass if someone using a class wants
different behavior.

In this case, I believe you can perform either option 2 or 3
in your own code to avoid the thousands of logged lines;
either by creating your own loop() function, or by creating
a subclass of dispatcher and implementing a handle_expt()
method that does as you desire.
msg24531 - (view) Author: Tony Meyer (anadelonbrin) Date: 2005-05-31 07:15
Logged In: YES 
user_id=552329

Yes this problem is easily solved by subclassing.  However I 
firmly believe that it is a terrible default behaviour, and that it's 
likely to hit many asyncore users.  A class shouldn't have to 
be subclassed to be usable (ignoring virtual classes and all 
that), and that really is the case here.

The simplest solution would be to change the handler to not 
log the message.  Or log the message once per socket or 
something.
msg24532 - (view) Author: Josiah Carlson (josiahcarlson) * (Python triager) Date: 2005-05-31 07:31
Logged In: YES 
user_id=341410

I hate to point out the obvious, but dispatcher is wholly
unusable without subclassing.  How would you get data
to/from a connection without replacing handle_read,
handle_write?  How do you handle the case when you want to
connect to someone else or accept connections from someone
else without overloading handle_connect or handle_accept?
msg24533 - (view) Author: Tony Meyer (anadelonbrin) Date: 2005-05-31 07:42
Logged In: YES 
user_id=552329

dispatcher is not at all unusable without subclassing.  You 
can get data with recv() and send it with send() etc.  It can be 
treated as a thin wrapper around socket objects.  Yes, you 
will want to subclass it to get more useful behaviour than you 
can get from a basic socket.  I don't see that this means that 
you should be required to override the handle_expt() function, 
though.  As much as possible a class should provide 
sensible methods, so that overriding is kept to a minimum.

At the very least, this is a documentation error, since the 
documentation states:

"""
handle_expt( ) 

Called when there is out of band (OOB) data for a socket 
connection. This will almost never happen, as OOB is 
tenuously supported and rarely used. 
"""

"Almost never" is completely wrong.
msg24534 - (view) Author: Josiah Carlson (josiahcarlson) * (Python triager) Date: 2005-05-31 19:34
Logged In: YES 
user_id=341410

You seem to be unwilling to subclass asyncore.dispatcher to
extend its functionality, and the only reason you have given
as to why you are unwilling is "As much as possible a class
should provide sensible methods, so that overriding is kept
to a minimum." (I personally subclass dispatcher and its
async_chat derivative qutie often)

Now, in the case of the other standard socket server and
client framework in the Python standard library, namely the
SocketServer module and its derivatives, you will find
extending the functionality of those classes is via
subclassing and overriding methods as necessary.

To me, when two 'competing' methods of generating socket
servers and clients in the standard library offer the same
method of extension of their base functionality, then
perhaps that is what should be done.  The fact that
basically all of the standard library is subclassable (some
C modules are exceptions to the rule, but should be fixed in
Python 2.5), including types in the base language, further
suggests to me that subclassing is the standard mechanism
for extending the functionality of a class, regardless of
its usefulness in its base state.

In regards to the documentation, it seems to be that
whenever an object has an error, the handle_expt() method is
called (in spending two minutes reading the source). 
Whether or not those errors are rare, perhaps debatable
(I've not seen any in years), but it seems to be
application-specific as to what behavior the socket should
have in the case of an error (you may want to close, I may
want to report the error and reconnect, etc.).
msg24535 - (view) Author: Tony Meyer (anadelonbrin) Date: 2005-06-03 01:38
Logged In: YES 
user_id=552329

I am not at all unwilling (and this isn't a problem for me
personally - the issue here is whether this is good for
Python in general) to subclass.  Deciding to subclass does
*not* mean that you should have to replace all functions in
the parent class.  If you did, then there would be little
point in subclassing at all.  Sensible default behaviour
should be provided as methods of classes.  The current
behaviour of the handle_expt() method is not sensible.  It
essentially forces the user to override that method, even if
they have no interest in handling errors (e.g. and would
normally just override handle_read and handle_write).

This is *not* rare.  You haven't seen any in years, because
this was a change introduced in Python 2.4, which hasn't
been released for even one year yet.  I agree that the
desired behaviour will be application specific.  But what is
the point of having default behaviour that will essentially
crash the program/system running it?  Having default
behaviour be "pass" would be more useful.  At the very
least, this is a problem that many people (compared to the
number that will use asyncore) will come across and should
be reflected as such in the documentation.

If you haven't replicated this problem on your system so
that you understand it, please do.  I am happy to provide a
simple script to demonstrate, if necessary.
msg24536 - (view) Author: Tim Peters (tim.peters) * (Python committer) Date: 2005-06-03 02:02
Logged In: YES 
user_id=31435

I agree the change in default behavior here was at least 
questionable, and spent more than a week of my 
own "dealing with consequences" of 2.4 asyncore changes in 
ZODB and Zope.

Assigning to Andrew, since it looks like he made the change 
in question here.  Andrew, why did this change?  How can it 
be improved?

I don't think Tony has mentioned it here, but when 
SpamBayes was first released with Python 2.4, it was a 
disaster because some users found their hard drives literally 
filled with gigabytes of mysterious "warning: unhandled 
exception" messages.
msg24537 - (view) Author: A.M. Kuchling (akuchling) * (Python committer) Date: 2005-06-09 15:41
Logged In: YES 
user_id=11375

What change to asyncore caused the problem?
msg24538 - (view) Author: Tim Peters (tim.peters) * (Python committer) Date: 2005-06-09 16:11
Logged In: YES 
user_id=31435

My guess is rev 1.57.
msg24539 - (view) Author: Josiah Carlson (josiahcarlson) * (Python triager) Date: 2007-01-06 23:11
Can I get any pointers as to a conversion from CVS to SVN version numbers, or does anyone remember which change is the issue?
msg81703 - (view) Author: Daniel Diniz (ajaksu2) (Python triager) Date: 2009-02-12 01:38
Josiah: that'd be around rev36408, as  1.53 corresponds to rev36033
(from the log and issue 957240)
msg81722 - (view) Author: Josiah Carlson (josiahcarlson) * (Python triager) Date: 2009-02-12 05:03
Considering that we're looking at 2.7 and 3.1, I think that  
(paraphrased) "logging fallout from changes to 2.4" are a bit out-of-
date.  People who have continued to use asyncore/asynchat in the last 4 
years have already changed their code.  People who write new code 
already deal with the logging.

Does anyone have a compelling reason as to why we shouldn't just close 
this bug?
msg81731 - (view) Author: Tony Meyer (anadelonbrin) Date: 2009-02-12 08:10
None of my arguments have really changed since 2.4.  I still believe 
that this is a poor choice of default behaviour (and if it is meant to 
be overridden to be useable, then 'pass' or 'raise 
NotYetImplementedError' would be a better choice).

However, my impression is that nothing I say will convince you of that, 
so I'll give up on that.  It would have been interesting to hear from 
Andrew the reason for the code.

However, this is definitely a documentation bug (as outlined 
previously), and so should be fixed, not closed.  I can provide a patch 
if it stands a chance of being accepted.
msg81732 - (view) Author: Gregory P. Smith (gregory.p.smith) * (Python committer) Date: 2009-02-12 08:18
A documentation patch would be appreciated, thanks!
msg84769 - (view) Author: Aleksi Torhamo (alexer) * Date: 2009-03-31 12:37
Please correct me, if i'm wrong, but this seems to be a real bug, caused
by people thinking that handle_expt is something like handle_error.

As Tony stated, the docs say that handle_expt is called when out-of-band
data arrives, and that is - i think - correct.
poll, which uses select, calls _exception -> handle_expt_event with fds
from the third set of select. The manpage select_tut(2) has example
code, which has a comment indicating that the third set is supposed to
contain sockets with OOB data.
poll2, however, calls readwrite, which calls handle_expt_event on error
conditions. Furthermore, it calls handle_read_event on POLLPRI, which
(according to the manpage of poll(2)) is supposed to indicate OOB data
when using poll.

Since handle_error is intended for python exceptions, currently there is
no proper method to call on POLLERR and POLLNVAL, unless handle_close is
called. With POLLNVAL, handle_close seems like the correct thing to do
(manpage says it indicates that fd is not open.) With POLLERR, i have no
idea. Manpage says "Error condition", but from that, it's hard to say
whether it refers to a temporary error condition or not.

So, i think readwrite should look something like this:
(Assuming POLLERR -> handle_close, otherwise a new handler would
probably have to be introduced)

if flags & select.POLLPRI:
    obj.handle_expt_event()
if flags & select.POLLIN:
    obj.handle_read_event()
if flags & select.POLLOUT:
    obj.handle_write_event()
if flags & (select.POLLERR | select.POLLNVAL | select.POLLHUP):
    obj.handle_close()
msg84773 - (view) Author: Giampaolo Rodola' (giampaolo.rodola) * (Python committer) Date: 2009-03-31 13:16
@Aleksy
http://bugs.python.org/issue4501
msg84779 - (view) Author: Aleksi Torhamo (alexer) * Date: 2009-03-31 13:39
Sorry for the noise.

I just registered, and started going through the open issues for
asyncore in order. I'll read them all through before commenting on the
next one..

I also bumped to this:
http://groups.google.com/group/python-dev2/browse_thread/thread/eec1ddadefe09fd8/a38270231620870e?lnk=gst&q=asyncore

It seems lots of things i have been thinking about have already been
done, but the whole asyncore is at a standstill. Any pointers on where i
should look if i want to help with doing something to the current state
of affairs?

Thanks.
msg84797 - (view) Author: Brett Cannon (brett.cannon) * (Python committer) Date: 2009-03-31 15:09
On Tue, Mar 31, 2009 at 06:39, Aleksi Torhamo <report@bugs.python.org>wrote:

>
> Aleksi Torhamo <alexerion+pythonbugs@gmail.com<alexerion%2Bpythonbugs@gmail.com>>
> added the comment:
>
> Sorry for the noise.
>
> I just registered, and started going through the open issues for
> asyncore in order. I'll read them all through before commenting on the
> next one..
>
> I also bumped to this:
>
> http://groups.google.com/group/python-dev2/browse_thread/thread/eec1ddadefe09fd8/a38270231620870e?lnk=gst&q=asyncore
>
> It seems lots of things i have been thinking about have already been
> done, but the whole asyncore is at a standstill. Any pointers on where i
> should look if i want to help with doing something to the current state
> of affairs?
>
> Thanks.

Beyond looking at what is in trunk, nothing specific comes to mind.
msg84826 - (view) Author: Josiah Carlson (josiahcarlson) * (Python triager) Date: 2009-03-31 16:30
Your analysis WRT handle_expt_event() is correct.  I've been meaning to 
fix that for a while, but I forgot to do it in 2.6/3.0 with all of the 
other changes/fixes.  Looking at the docs, you are also right about 
POLLNVAL.

I also don't *know* what to do when presented with POLLERR, but few 
socket errors are transient (transient errors should be handled by the 
underlying stacks), so I agree with you that they should just be closed.

I went ahead and made the changes as you have suggested, and also made 
the same change with the select-based loop.  Errors on the socket just 
result in closing the socket, resulting in _exception() -> close().

Thinking about it, I've also had a change of heart, and added a 
frozenset object called 'ignore_log_types', which specifies the log 
types to ignore.  By default it is populated with 'warning', which 
squelches all currently existing "unhandled * event" bits.  If you use 
self.log(arg) or self.log_info(one_arg), those lines are unchanged.  
Handle_error() uses the "error" type, which is also nice, but which you 
can also suppress with ease (though you really should be logging them so 
you can fix your code).

I've attached a version that I think is pretty reasonable.  Comments?  
Questions?
msg84839 - (view) Author: Aleksi Torhamo (alexer) * Date: 2009-03-31 17:07
The _exception() -> close() change seems to be wrong. The third set of
select() is supposed to represent oob data, so the previous use in the
select-based loop should have been correct?

Other than that, i can't see anything wrong with it.

Maybe handle_expt_event should be reverted to the old one, that just
calls handle_expt, too? The current version seems to assume that it is
called on socket error conditions.
msg84850 - (view) Author: Josiah Carlson (josiahcarlson) * (Python triager) Date: 2009-03-31 18:16
You are right.  Handling OOB data is within the "exceptional condition" 
that the select document specifies.

I've added a check for error conditions within handle_expt_event(), 
which induces a handle_close() on discovery of an error, handle_expt() 
otherwise.

One thing to consider is that when there is OOB data, and when 
handle_expt() isn't overridden, we will get churn because that data will 
never be read from the socket.  I'm thinking about tossing a 
handle_close() as part of the default handle_expt() call.

Attached is an updated patch without the handle_close() in 
handle_expt().
msg84855 - (view) Author: Aleksi Torhamo (alexer) * Date: 2009-03-31 18:34
Ah, you're right. I hadn't thought about the exceptional condition being
used to signal anything besides OOB.

Looks really good to me.

s/close/_exception/ in the select-based poll(), and i don't have
anything more to add.
msg84879 - (view) Author: Josiah Carlson (josiahcarlson) * (Python triager) Date: 2009-03-31 19:34
Fixed the close() call and committed to trunk.  Python 2.6 tests pass 
with the new version of the library.  Calling it good :) .
msg84892 - (view) Author: Giampaolo Rodola' (giampaolo.rodola) * (Python committer) Date: 2009-03-31 20:32
I still get some occasional EBADF failures when running pyftpdlib test
suite by using poll().
I think that it makes more sense moving the:

        if flags & (select.POLLHUP | select.POLLERR | select.POLLNVAL):
            obj.handle_close()

...lines at the top and return if handle_close() is called, as I did in
the patch attached to issue 4501, which is:


        if flags & (select.POLLHUP | select.POLLERR | select.POLLNVAL):
            obj.handle_close()
        else:
            if flags & select.POLLIN:
                obj.handle_read_event()
            if flags & select.POLLOUT:
                obj.handle_write_event()
            if flags & select.POLLPRI:
                obj.handle_expt_event()
msg84893 - (view) Author: Giampaolo Rodola' (giampaolo.rodola) * (Python committer) Date: 2009-03-31 20:34
...after all no read/write methods should be called after the socket has
been closed.
msg84928 - (view) Author: Josiah Carlson (josiahcarlson) * (Python triager) Date: 2009-03-31 21:49
Good point Giampaolo.  Fixed and committed.
msg84936 - (view) Author: Giampaolo Rodola' (giampaolo.rodola) * (Python committer) Date: 2009-03-31 22:26
If you're talking about r70904 then you did a different thing than the
one I suggested.
History
Date User Action Args
2009-04-01 15:27:07brett.cannonsetnosy: - brett.cannon
2009-03-31 22:26:49giampaolo.rodolasetmessages: + msg84936
2009-03-31 21:49:50josiahcarlsonsetmessages: + msg84928
2009-03-31 20:34:38giampaolo.rodolasetmessages: + msg84893
2009-03-31 20:32:47giampaolo.rodolasetmessages: + msg84892
2009-03-31 19:34:33josiahcarlsonsetstatus: open -> closed
keywords: - needs review
resolution: accepted
messages: + msg84879
2009-03-31 18:34:33alexersetmessages: + msg84855
2009-03-31 18:16:40josiahcarlsonsetfiles: - async_no_warn.patch
2009-03-31 18:16:32josiahcarlsonsetfiles: + async_no_warn.patch

messages: + msg84850
2009-03-31 17:07:12alexersetmessages: + msg84839
2009-03-31 16:30:32josiahcarlsonsetkeywords: + needs review, patch
files: + async_no_warn.patch
messages: + msg84826

versions: + Python 2.7, - Python 2.6
2009-03-31 15:09:26brett.cannonsetfiles: + unnamed

messages: + msg84797
2009-03-31 13:39:47alexersetmessages: + msg84779
2009-03-31 13:16:22giampaolo.rodolasetmessages: + msg84773
2009-03-31 12:37:37alexersetnosy: + alexer
messages: + msg84769
2009-02-12 08:18:56gregory.p.smithsetnosy: + gregory.p.smith
messages: + msg81732
2009-02-12 08:10:38anadelonbrinsetmessages: + msg81731
2009-02-12 05:03:40josiahcarlsonsetmessages: + msg81722
2009-02-12 01:38:12ajaksu2setnosy: + ajaksu2
messages: + msg81703
stage: test needed
2009-02-11 03:04:37ajaksu2setnosy: + brett.cannon
type: behavior
versions: + Python 2.6, - Python 2.4
2008-10-01 11:40:18giampaolo.rodolasetnosy: + giampaolo.rodola
2008-01-19 20:50:25akuchlingsetassignee: akuchling -> josiahcarlson
2005-03-11 00:34:47anadelonbrincreate