Do a last polling before closing the IocpProactor

[Insoleet]

Fix bug #38

[Insoleet]

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]

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]

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

[harvimt]

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

[aknuds1]

@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]

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

[aknuds1]

@harvimt Thanks for the explanation.

[Insoleet]

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]

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

[Insoleet]

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]

@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]

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]

@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]

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

So to say it short : I did some first analysis there : https://github.com/harvimt/quamash/issues/38#issuecomment-140346302

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]

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]

@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]

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]

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]

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

[harvimt]

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 https://github.com/harvimt/quamash/commit/540ab6ab04d93f72fe6c5f60c0a8c8f4f134aad7, 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 https://github.com/harvimt/quamash/pull/44#issuecomment-141827211.

[aknuds1]

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

[aknuds1]

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

[Insoleet]

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]

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]

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

[Insoleet]

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

[aknuds1]

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

[Insoleet]

I think this PR can be closed thanks to @peterazmanov