I haven't actually tried to run/debug this, but I've looked at the code a
bit. Let me explain what's happening in the demo program first. (Thanks for
the nice clean demo BTW!)
You call start_serving_pipe() and yield to ensure its callback is entered.
This creates a native pipe and wraps it in a Future ('f', set on line 157
of windows_events.py in the current Tulip repo head). The Future will be
completed if/when an incoming connection is accepted, but your program
never gets there. Instead, you close the server object. This will (IIUC)
cause the Future to get an exception. The normal flow (if the event loop
weren't stopped) would be for this exception to wake up the callback. The
callback calls f.result() (line 149) which raises that exception. The
exception is caught in the "except OSError" clause (line 158) and since the
'pipe' local is still None at this point, no exception is logged.
But when you stop the loop, the callback never runs (it is stuck in the
loop's _ready queue). Then you close the loop and exit the program, and
everything gets GC'ed. At some point this discovers the Future with the
exception set. Its callback has been scheduled but not yet called (and it
will never be called). Because of this the Future's exception is logged in
the way you see ("Future/Task exception was never retrieved").
I think the most reasonable response is to declare that there is a bug in
asyncio -- it shouldn't log unretrieved exceptions before the callbacks
have run, since a typical callback will retrieve the exception and hence
silence the log (perhaps substituting a different exception if the callback
doesn't handle it).
Looking at the code of set_exception() (in future.py, line 316) it looks
like in the Python 3.3 branch of the code, the tb logger isn't activated
until after all scheduled callbacks have also run (the event loop promises
that callbacks scheduled with call_soon() will be run in the order they
were scheduled). But in the 3.4 branch it immediately sets the
_log_traceback flag.
I have two suggestions for how you can verify my theory:
- If my analysis is right, you won't see this issue with Python 3.3.
- For Python 3.4, it could perhaps be fixed by putting the
"self._log_traceback = True" call in a callback and scheduling that. Here's
a tentative patch to try that:
diff -r 86fc55b570ff asyncio/futures.py
--- a/asyncio/futures.py Thu Mar 06 01:00:03 2014 +0100
+++ b/asyncio/futures.py Fri Mar 14 11:30:30 2014 -0700
@@ -314,7 +314,9 @@
self._state = _FINISHED
self._schedule_callbacks()
if _PY34:
- self._log_traceback = True
+ def _set_log_traceback():
+ self._log_traceback = True
+ self._loop.call_soon(_set_log_traceback)
else:
self._tb_logger = _TracebackLogger(exception, self._loop)
# Arrange for the logger to be activated after all callbacks
Unfortunately this also causes a lot of spurious warnings about unretrieved
exceptions when running the test suite (but no test failures!) -- possibly
the test suite is at fault, depending too strongly on what exactly happens
when (a common fault in the Tulip test suite, alas).
Maybe we can think of a local fix in the Windows pipe code?
On Thu, Mar 13, 2014 at 5:47 AM, Juraj Ivančić <[email protected]>wrote:
> While using pipe server from asyncio (Windows/ProactorEventLoop) I ran
> into the following exception on shutdown:
>
> Future/Task exception was never retrieved
> future: _OverlappedFuture<exception=BrokenPipeError(32, 'The pipe has
> been ended', None, 109, None)>
> Traceback (most recent call last):
> File "c:\Python34\lib\asyncio\windows_events.py", line 428, in _poll
> value = callback(transferred, key, ov)
> File "c:\Python34\lib\asyncio\windows_events.py", line 304, in finish
> ov.getresult()
> BrokenPipeError: [WinError 109] The pipe has been ended
>
> Tried with:
>
> Python 3.4.0rc3 (v3.4.0rc3:8a81cdab3e9d, Mar 9 2014, 20:24:29) [MSC
> v.1600 32 bit (Intel)] on win32
>
> Attached is a minimal repro, together with a workaround.
>
> Is this a tulip/asyncio bug?
>
>
--
--Guido van Rossum (python.org/~guido)
