Do a last polling before closing the IocpProactor #44

Insoleet · 2015-09-15T17:26:39Z

Fix bug #38

Get latest quamash works

Insoleet · 2015-09-15T17:38:29Z

Ok this pull request removes the exception of bug #38 but it's not perfect. I get the following errors after more testing, sometimes :

Traceback (most recent call last):
  File "D:\Anaconda3\lib\asyncio\windows_events.py", line 749, in __del__
    self.close()
  File "D:\Dev\Code\quamash\quamash\_windows.py", line 73, in close
    self._poll(1)
  File "D:\Dev\Code\quamash\quamash\_windows.py", line 92, in _poll
    status = _overlapped.GetQueuedCompletionStatus(self._iocp, ms)

I guess there are some checks to do in the polling side ?

harvimt · 2015-09-15T17:55:58Z

If you could rebase this, that would be great,
something like:
git rebase upstream/master
check to make sure it worked
git push -f

this should get rid of the pointless merge commit

Insoleet · 2015-09-15T18:02:44Z

Ok but my fix is not ready yet. I think I'll need your help on the IOCP side.

harvimt · 2015-09-15T18:04:40Z

@aknuds1 actually wrote the IOCP code, but I'll try my best.

aknuds1 · 2015-09-15T18:06:32Z

@Insoleet Maybe I can help, hit me. I think first of all though, I'd like to see a test corresponding to why this fix is needed.

harvimt · 2015-09-15T18:09:10Z

This is meant to fix #38 which are all warnings Windows logs during shutdown, but don't actually prevent any functionality.

aknuds1 · 2015-09-15T18:09:58Z

@harvimt Thanks for the explanation.

Insoleet · 2015-09-15T18:10:04Z

This simple test does raise an error when closing the loop on Windows :

import sys
import unittest
import asyncio
import aiohttp
import time
import logging
import quamash
from quamash import QApplication


class Bug(unittest.TestCase):
    def setUp(self):
        self.qapplication = QApplication([])
        self.lp = quamash.QEventLoop(self.qapplication)
        asyncio.set_event_loop(self.lp)

    def tearDown(self):
        try:
            self.lp.close()
        finally:
            asyncio.set_event_loop(None)

    def test_bug(self):
        @asyncio.coroutine
        def waiting():
            yield from asyncio.sleep(1)
        self.lp.run_until_complete(waiting())


if __name__ == '__main__':
    logging.basicConfig(stream=sys.stderr)
    logging.getLogger().setLevel(logging.DEBUG)
    unittest.main()

The complete output is the following :

D:\Anaconda3\python.exe D:\Dev\Code\quamash\bug.py
DEBUG:asyncio:Using proactor: IocpProactor
DEBUG:quamash.QEventLoop:Registering callback <bound method QEventLoop._loop_self_reading of <QEventLoop running=False closed=False debug=False>> to be invoked with arguments () after 0 second(s)
DEBUG:quamash.QEventLoop:Adding callback <Handle BaseProactorEventLoop._loop_self_reading()> with delay 0
DEBUG:asyncio:Using proactor: _IocpProactor
D:\Anaconda3\lib\asyncio\proactor_events.py:467: ResourceWarning: unclosed <socket.socket fd=592, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('127.0.0.1', 61606), raddr=('127.0.0.1', 61607)>
  self._ssock, self._csock = self._socketpair()
D:\Anaconda3\lib\asyncio\proactor_events.py:467: ResourceWarning: unclosed <socket.socket fd=576, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('127.0.0.1', 61607), raddr=('127.0.0.1', 61606)>
  self._ssock, self._csock = self._socketpair()
DEBUG:quamash.QEventLoop:Registering callback <bound method QEventLoop._loop_self_reading of <QEventLoop running=False closed=False debug=False>> to be invoked with arguments () after 0 second(s)
DEBUG:quamash.QEventLoop:Adding callback <Handle BaseProactorEventLoop._loop_self_reading()> with delay 0
DEBUG:quamash.QEventLoop:Running <generator object waiting at 0x00000000040E2C18> until complete
DEBUG:quamash.QEventLoop:Registering callback <bound method Task._step of <Task pending coro=<waiting() running at D:\Dev\Code\quamash\bug.py:24>>> to be invoked with arguments () after 0 second(s)
DEBUG:quamash.QEventLoop:Adding callback <Handle Task._step()> with delay 0
DEBUG:quamash._windows._EventPoller:Starting (proactor: <_IocpProactor overlapped#=0 result#=0>)...
DEBUG:quamash._windows._EventWorker:Thread started
DEBUG:quamash.QEventLoop:Starting Qt event loop
DEBUG:quamash.QEventLoop:Callback timer fired, calling <Handle BaseProactorEventLoop._loop_self_reading()>
DEBUG:quamash.QEventLoop:Callback timer fired, calling <Handle BaseProactorEventLoop._loop_self_reading()>
DEBUG:quamash.QEventLoop:Callback timer fired, calling <Handle Task._step()>
DEBUG:quamash.QEventLoop:Registering callback <bound method Future._set_result_unless_cancelled of <Future pending>> to be invoked with arguments (None,) after 1 second(s)
DEBUG:quamash.QEventLoop:Adding callback <Handle Future._set_result_unless_cancelled(None)> with delay 1
DEBUG:quamash.QEventLoop:Callback timer fired, calling <Handle Future._set_result_unless_cancelled(None)>
DEBUG:quamash.QEventLoop:Registering callback <bound method Task._wakeup of <Task pending coro=<waiting() running at D:\Dev\Code\quamash\bug.py:26> wait_for=<Future finished result=None> cb=[QEventLoop.run_until_complete.<locals>.stop() at D:\Dev\Code\quamash\quamash\__init__.py:283]>> to be invoked with arguments (<Future finished result=None>,) after 0 second(s)
DEBUG:quamash.QEventLoop:Adding callback <Handle Task._wakeup(<Future finished result=None>)> with delay 0
DEBUG:quamash.QEventLoop:Callback timer fired, calling <Handle Task._wakeup(<Future finished result=None>)>
DEBUG:quamash.QEventLoop:Registering callback <function QEventLoop.run_until_complete.<locals>.stop at 0x00000000040EF048> to be invoked with arguments (<Task finished coro=<waiting() done, defined at D:\Dev\Code\quamash\bug.py:24> result=None>,) after 0 second(s)
DEBUG:quamash.QEventLoop:Adding callback <Handle QEventLoop.run_until_complete.<locals>.stop(<Task finishe...> result=None>) at D:\Dev\Code\quamash\quamash\__init__.py:283> with delay 0
DEBUG:quamash.QEventLoop:Callback timer fired, calling <Handle QEventLoop.run_until_complete.<locals>.stop(<Task finishe...> result=None>) at D:\Dev\Code\quamash\quamash\__init__.py:283>
DEBUG:quamash.QEventLoop:Stopping event loop...
DEBUG:quamash.QEventLoop:Stopped event loop
DEBUG:quamash.QEventLoop:Qt event loop ended with result 0
DEBUG:quamash._windows._EventPoller:Stopping worker thread...
DEBUG:quamash._windows._EventWorker:Exiting thread
DEBUG:quamash.QEventLoop:Future <Task finished coro=<waiting() done, defined at D:\Dev\Code\quamash\bug.py:24> result=None> finished running
DEBUG:quamash.QEventLoop:Closing event loop...
DEBUG:quamash.QEventLoop:Registering callback <bound method QEventLoop._loop_self_reading of <QEventLoop running=False closed=False debug=False>> to be invoked with arguments (<_OverlappedFuture cancelled>,) after 0 second(s)
DEBUG:quamash.QEventLoop:Adding callback <Handle BaseProactorEventLoop._loop_self_reading(<_OverlappedFuture cancelled>)> with delay 0
DEBUG:quamash._windows._IocpProactor:Closing
DEBUG:quamash.QEventLoop:Default exception handler executing
ERROR:quamash.QEventLoop:Cancelling an overlapped future failed
future: <_OverlappedFuture pending overlapped=<pending, 0x3fdb550> cb=[BaseProactorEventLoop._loop_self_reading()]>
Traceback (most recent call last):
  File "D:\Anaconda3\lib\asyncio\windows_events.py", line 62, in _cancel_overlapped
    self._ov.cancel()
OSError: [WinError 6] Descripteur non valide
DEBUG:quamash.QEventLoop:Registering callback <bound method QEventLoop._loop_self_reading of <QEventLoop running=False closed=False debug=False>> to be invoked with arguments (<_OverlappedFuture cancelled>,) after 0 second(s)
DEBUG:quamash.QEventLoop:Adding callback <Handle BaseProactorEventLoop._loop_self_reading(<_OverlappedFuture cancelled>)> with delay 0
DEBUG:asyncio:taking long time to close proactor
.
----------------------------------------------------------------------
Ran 1 test in 1.045s

OK

I'm not at all an expert of the Microsoft world, but our app needs to support Windows that's why I try to fix this error...
Note that with PyQt 5.5, Qt will abort when any exception is not catched anymore. So this will start to get critical if we still have quamash raising exceptions...

Thanks for your help ! (and I love your lib by the way :) )

aknuds1 · 2015-09-15T18:19:13Z

@Insoleet I guess your test could verify that there are no logged errors? Then it should fail it would seem.

Insoleet · 2015-09-15T18:24:40Z

I can't catch this exception from the test because it's catched by PyQt stack (raised after a quamash signal I guess ?). The test is just a simple use case to show the problem...

aknuds1 · 2015-09-15T18:26:32Z

@Insoleet Can't you detect that an error has been logged? There's this log line: ERROR:quamash.QEventLoop:Cancelling an overlapped future failed.

Insoleet · 2015-09-15T18:36:02Z

Oh you are right.

import sys
import unittest
import asyncio
import time
import logging
import quamash
from quamash import QApplication


class Bug(unittest.TestCase):
    def setUp(self):
        self.qapplication = QApplication([])
        self.lp = quamash.QEventLoop(self.qapplication)
        asyncio.set_event_loop(self.lp)
        self.except_raised = False
        self.lp.set_exception_handler(lambda loop, context: self.exception_handler(loop, context))

    def exception_handler(self, loop, context):
        self.except_raised = True

    def test_bug(self):
        @asyncio.coroutine
        def waiting():
            yield from asyncio.sleep(1)

        self.lp.run_until_complete(waiting())
        try:
            self.lp.close()
        finally:
            asyncio.set_event_loop(None)
        self.assertFalse(self.except_raised)



if __name__ == '__main__':
    logging.basicConfig(stream=sys.stderr)
    logging.getLogger().setLevel(logging.DEBUG)
    unittest.main()

aknuds1 · 2015-09-15T18:40:04Z

@Insoleet That solution was a bit different from what I initially envisioned, but if it works I think it's better since it's more direct in detecting an exception.

Insoleet · 2015-09-15T18:49:24Z

Well as soon as we can reproduce the error... :)

So to say it short :
I did some first analysis there : #38 (comment)

Also, polling seems to help solving the bug, at least in simple cases like this one. But the unit test suite of our app raise another error after forcing a polling when closing the IocpProactor :

.Exception ignored in: <bound method _IocpProactor.__del__ of <_IocpProactor overlapped#=0 result#=0>>
Traceback (most recent call last):
  File "D:\Anaconda3\lib\asyncio\windows_events.py", line 749, in __del__
    self.close()
  File "D:\Dev\Code\quamash\quamash\_windows.py", line 73, in close
    self._poll(1)
  File "D:\Dev\Code\quamash\quamash\_windows.py", line 92, in _poll
    status = _overlapped.GetQueuedCompletionStatus(self._iocp, ms)
TypeError: must be integer<K>, not None

Insoleet · 2015-09-17T09:26:53Z

You can notice that running this test never ends. Before the exception is raised, a callback is added in quamash.QEventLoop, but it is never called. The callback is supposed to call the "QEventLoop._loop_self_reading".

The callback is added when canceling the overlapped future :
https://github.com/python/asyncio/blob/master/asyncio/windows_events.py#L62
https://github.com/python/asyncio/blob/master/asyncio/futures.py#L227

The callback uses self._loop.call_soon(callback, self), and thus calls the QEventLoop's call_soon. The callback is never called because, for some reason, the timers are never triggered.

aknuds1 · 2015-09-17T09:49:41Z

@Insoleet Do you need help figuring this out? I've got a busy day ahead of me though, so can't make any promises today at least.

Insoleet · 2015-09-17T09:53:23Z

Yes, this is quite a hard bug. I'm not sure if it's because of quamash reimplementation of IocpProactor, or if it's asyncio having problems...

Closing the loop freezes on this line :
https://github.com/python/asyncio/blob/master/asyncio/windows_events.py#L739
The while is never left, because the _cache is never empty, because quamash's polling never pops items from the cache. In fact, reading the _overlapped.GetQueuedCompletionStatusalways returns None :
https://github.com/harvimt/quamash/blob/master/quamash/_windows.py#L91

If you have any idea, or try to replicate my analysis by your side that'd be great...

Insoleet · 2015-09-17T10:03:59Z

Oh it seems to be a compatibility problem with aiohttp.

The test I suggested earlier is not freezing. But our app tests are. So I tried the following simple test :

import sys
import unittest
import asyncio
import aiohttp
import logging
import quamash
from quamash import QApplication


class Bug(unittest.TestCase):
    def setUp(self):
        self.qapplication = QApplication([])
        self.lp = quamash.QEventLoop(self.qapplication)
        asyncio.set_event_loop(self.lp)
        self.except_raised = False
        self.lp.set_exception_handler(lambda loop, context: self.exception_handler(loop, context))

    def exception_handler(self, loop, context):
        self.except_raised = True

    def test_bug(self):
        @asyncio.coroutine
        def waiting():
            response = yield from aiohttp.get("http://forum.ucoin.io")
            yield from response.release()
            yield from asyncio.sleep(1)

        self.lp.run_until_complete(waiting())
        try:
            self.lp.close()
        finally:
            asyncio.set_event_loop(None)
        self.assertFalse(self.except_raised)



if __name__ == '__main__':
    logging.basicConfig(stream=sys.stderr)
    logging.getLogger().setLevel(logging.DEBUG)
    unittest.main()

Which sometimes never ends.

aknuds1 · 2015-09-20T19:52:08Z

Eh, nevermind, it's Windows of course. Going to see if I can bring that up.

harvimt · 2015-09-20T20:04:45Z

This is a problem with IOCP, I think it only exists on windows.

On Sun, Sep 20, 2015 at 12:52 PM, Arve Knudsen notifications@github.com
wrote:

@Insoleet https://github.com/Insoleet I just ran your latest test on OS
X with Quamash 540ab6a
540ab6a,
Python 3.5.0, PyQt 5.5 and aiohttp 0.17.3. There were no errors that I
could see. Is there any particular way to reproduce?

—
Reply to this email directly or view it on GitHub
#44 (comment).

aknuds1 · 2015-09-20T20:08:34Z

@harvimt Yep, I noticed right after (oops). Have to refresh my Windows installation now, after not using it for a long time.

aknuds1 · 2015-09-20T20:12:02Z

But @Insoleet, you say that the test only sometimes hangs? Is there a way to reproduce deterministically?

Insoleet · 2015-09-20T21:12:57Z

I did not find a way to provoke the bug 100% of times... But it happened really often. My appveyor tests instance were almost all freezing for example.

aknuds1 · 2015-09-20T21:21:28Z

I just tested with Python 3.4.0, Quamash 540ab6a, PyQt 5.4.0 and aiohttp 0.17.3 on Windows 8.1, several times. The test doesn't hang for me.

aknuds1 · 2015-09-20T21:21:58Z

@Insoleet, can you integrate https://github.com/Insoleet/quamash/pull/2? It fixes an exception due to polling while closing.

Handle disposed IOCP handle while closing

Insoleet · 2015-09-21T09:46:10Z

Well, even after your patch, the test hangs here (Windows 7). The test hangs when we are trying to close the loop.

aknuds1 · 2015-09-21T11:10:49Z

@Insoleet Yes, the patch doesn't solve that, it fixes another issue.

Insoleet · 2015-11-19T07:47:32Z

I think this PR can be closed thanks to @peterazmanov

Insoleet added 3 commits September 15, 2015 15:11

Merge pull request #1 from harvimt/master

75f6119

Get latest quamash works

Fix windows error #38

9770b83

Force a last polling when closing IOCP

d9f64d2

graingert and others added 3 commits September 20, 2015 23:14

asyncio

553baea

Remove deprecation warning

3fa3269

Detect disposed IOCP handle

53f7dd6

Merge pull request #2 from aknuds1/last-polling

35692c9

Handle disposed IOCP handle while closing

peterazmanov mentioned this pull request Nov 18, 2015

_IocpProactor implementation causes race condition (on Windows) #55

Closed

Insoleet closed this Nov 19, 2015

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Do a last polling before closing the IocpProactor #44

Do a last polling before closing the IocpProactor #44

Insoleet commented Sep 15, 2015

Insoleet commented Sep 15, 2015

harvimt commented Sep 15, 2015

Insoleet commented Sep 15, 2015

harvimt commented Sep 15, 2015

aknuds1 commented Sep 15, 2015

harvimt commented Sep 15, 2015

aknuds1 commented Sep 15, 2015

Insoleet commented Sep 15, 2015

aknuds1 commented Sep 15, 2015

Insoleet commented Sep 15, 2015

aknuds1 commented Sep 15, 2015

Insoleet commented Sep 15, 2015

aknuds1 commented Sep 15, 2015

Insoleet commented Sep 15, 2015

Insoleet commented Sep 17, 2015

aknuds1 commented Sep 17, 2015

Insoleet commented Sep 17, 2015

Insoleet commented Sep 17, 2015

aknuds1 commented Sep 20, 2015

harvimt commented Sep 20, 2015

aknuds1 commented Sep 20, 2015

aknuds1 commented Sep 20, 2015

Insoleet commented Sep 20, 2015

aknuds1 commented Sep 20, 2015

aknuds1 commented Sep 20, 2015

Insoleet commented Sep 21, 2015

aknuds1 commented Sep 21, 2015

Insoleet commented Nov 19, 2015

Do a last polling before closing the IocpProactor #44

Do a last polling before closing the IocpProactor #44

Conversation

Insoleet commented Sep 15, 2015

Insoleet commented Sep 15, 2015

harvimt commented Sep 15, 2015

Insoleet commented Sep 15, 2015

harvimt commented Sep 15, 2015

aknuds1 commented Sep 15, 2015

harvimt commented Sep 15, 2015

aknuds1 commented Sep 15, 2015

Insoleet commented Sep 15, 2015

aknuds1 commented Sep 15, 2015

Insoleet commented Sep 15, 2015

aknuds1 commented Sep 15, 2015

Insoleet commented Sep 15, 2015

aknuds1 commented Sep 15, 2015

Insoleet commented Sep 15, 2015

Insoleet commented Sep 17, 2015

aknuds1 commented Sep 17, 2015

Insoleet commented Sep 17, 2015

Insoleet commented Sep 17, 2015

aknuds1 commented Sep 20, 2015

harvimt commented Sep 20, 2015

aknuds1 commented Sep 20, 2015

aknuds1 commented Sep 20, 2015

Insoleet commented Sep 20, 2015

aknuds1 commented Sep 20, 2015

aknuds1 commented Sep 20, 2015

Insoleet commented Sep 21, 2015

aknuds1 commented Sep 21, 2015

Insoleet commented Nov 19, 2015