From 1ad4dd3fa34b5679d0d3c6464ee565ae359c62fb Mon Sep 17 00:00:00 2001 From: Victor Stinner Date: Thu, 10 Jan 2019 11:23:26 +0100 Subject: [PATCH 1/3] IocpProactor: prevent modification if closed (GH-11494) * _wait_for_handle(), _register() and _unregister() methods of IocpProactor now raise an exception if closed * Add "closed" to IocpProactor.__repr__() * Simplify IocpProactor.close() (cherry picked from commit 9b07681c09182d4b9d23cd52566a4992b8afecbb) --- Lib/asyncio/windows_events.py | 28 ++++++++++++++++++++++------ 1 file changed, 22 insertions(+), 6 deletions(-) diff --git a/Lib/asyncio/windows_events.py b/Lib/asyncio/windows_events.py index 2ec542764375e9b..4615b6417c94328 100644 --- a/Lib/asyncio/windows_events.py +++ b/Lib/asyncio/windows_events.py @@ -392,10 +392,16 @@ def __init__(self, concurrency=0xffffffff): self._unregistered = [] self._stopped_serving = weakref.WeakSet() + def _check_closed(self): + if self._iocp is None: + raise RuntimeError('IocpProactor is closed') + def __repr__(self): - return ('<%s overlapped#=%s result#=%s>' - % (self.__class__.__name__, len(self._cache), - len(self._results))) + info = ['overlapped#=%s' % len(self._cache), + 'result#=%s' % len(self._results)] + if self._iocp is None: + info.append('closed') + return '<%s %s>' % (self.__class__.__name__, " ".join(info)) def set_loop(self, loop): self._loop = loop @@ -602,6 +608,8 @@ def _wait_cancel(self, event, done_callback): return fut def _wait_for_handle(self, handle, timeout, _is_cancel): + self._check_closed() + if timeout is None: ms = _winapi.INFINITE else: @@ -644,6 +652,8 @@ def _register_with_iocp(self, obj): # that succeed immediately. def _register(self, ov, obj, callback): + self._check_closed() + # Return a future which will be set with the result of the # operation when it completes. The future's value is actually # the value returned by callback(). @@ -680,6 +690,7 @@ def _unregister(self, ov): already be signalled (pending in the proactor event queue). It is also safe if the event is never signalled (because it was cancelled). """ + self._check_closed() self._unregistered.append(ov) def _get_accept_socket(self, family): @@ -749,6 +760,10 @@ def _stop_serving(self, obj): self._stopped_serving.add(obj) def close(self): + if self._iocp is None: + # already closed + return + # Cancel remaining registered operations. for address, (fut, ov, obj, callback) in list(self._cache.items()): if fut.cancelled(): @@ -771,14 +786,15 @@ def close(self): context['source_traceback'] = fut._source_traceback self._loop.call_exception_handler(context) + # wait until all cancelled overlapped future complete while self._cache: if not self._poll(1): logger.debug('taking long time to close proactor') self._results = [] - if self._iocp is not None: - _winapi.CloseHandle(self._iocp) - self._iocp = None + + _winapi.CloseHandle(self._iocp) + self._iocp = None def __del__(self): self.close() From 5d7001237d27bc2e026f808f1314ea9decee7122 Mon Sep 17 00:00:00 2001 From: Victor Stinner Date: Tue, 15 Jan 2019 11:48:00 +0100 Subject: [PATCH 2/3] bpo-34323: Enhance IocpProactor.close() log (GH-11555) IocpProactor.close() now uses time to decide when to log: wait 1 second before the first log, then log every second. Log also the number of seconds since close() was called. (cherry picked from commit b1e45739d832e1e402a563c6727defda92e193b7) --- Lib/asyncio/windows_events.py | 18 +++++++++++++++--- .../2019-01-14-17-34-36.bpo-34323.CRErrt.rst | 3 +++ 2 files changed, 18 insertions(+), 3 deletions(-) create mode 100644 Misc/NEWS.d/next/Library/2019-01-14-17-34-36.bpo-34323.CRErrt.rst diff --git a/Lib/asyncio/windows_events.py b/Lib/asyncio/windows_events.py index 4615b6417c94328..a27aed4410b1448 100644 --- a/Lib/asyncio/windows_events.py +++ b/Lib/asyncio/windows_events.py @@ -7,6 +7,7 @@ import msvcrt import socket import struct +import time import weakref from . import events @@ -786,10 +787,21 @@ def close(self): context['source_traceback'] = fut._source_traceback self._loop.call_exception_handler(context) - # wait until all cancelled overlapped future complete + # Wait until all cancelled overlapped complete: don't exit with running + # overlapped to prevent a crash. Display progress every second if the + # loop is still running. + msg_update = 1.0 + start_time = time.monotonic() + next_msg = start_time + msg_update while self._cache: - if not self._poll(1): - logger.debug('taking long time to close proactor') + if next_msg <= time.monotonic(): + logger.debug('IocpProactor.close(): ' + 'loop is running after closing for %.1f seconds', + time.monotonic() - start_time) + next_msg = time.monotonic() + msg_update + + # handle a few events, or timeout + self._poll(msg_update) self._results = [] diff --git a/Misc/NEWS.d/next/Library/2019-01-14-17-34-36.bpo-34323.CRErrt.rst b/Misc/NEWS.d/next/Library/2019-01-14-17-34-36.bpo-34323.CRErrt.rst new file mode 100644 index 000000000000000..59269244cc47b72 --- /dev/null +++ b/Misc/NEWS.d/next/Library/2019-01-14-17-34-36.bpo-34323.CRErrt.rst @@ -0,0 +1,3 @@ +:mod:`asyncio`: Enhance ``IocpProactor.close()`` log: wait 1 second before +the first log, then log every second. Log also the number of seconds since +``close()`` was called. From 56ac6801920abebcab31375cc15b5b90faf4399c Mon Sep 17 00:00:00 2001 From: Victor Stinner Date: Tue, 15 Jan 2019 12:13:48 +0100 Subject: [PATCH 3/3] bpo-11555: Enhance IocpProactor.close() log again (GH-11563) Add repr(self) to the log to display the number of pending overlapped in the log. (cherry picked from commit b91140fdb17472d03a7b7971f143c08a40fde923) --- Lib/asyncio/windows_events.py | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/Lib/asyncio/windows_events.py b/Lib/asyncio/windows_events.py index a27aed4410b1448..e3778688ab5be48 100644 --- a/Lib/asyncio/windows_events.py +++ b/Lib/asyncio/windows_events.py @@ -795,9 +795,8 @@ def close(self): next_msg = start_time + msg_update while self._cache: if next_msg <= time.monotonic(): - logger.debug('IocpProactor.close(): ' - 'loop is running after closing for %.1f seconds', - time.monotonic() - start_time) + logger.debug('%r is running after closing for %.1f seconds', + self, time.monotonic() - start_time) next_msg = time.monotonic() + msg_update # handle a few events, or timeout