From 25280274960ddbdcecd16448b9687ef111a91dab Mon Sep 17 00:00:00 2001 From: Victor Stinner Date: Mon, 14 Jan 2019 17:24:55 +0100 Subject: [PATCH 1/2] bpo-34323: Enhance IocpProactor.close() log 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. --- 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 bdb9a6e28a86bb..90ceda6d375a2e 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 @@ -802,10 +803,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 still running since %.1f sec', + 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 00000000000000..59269244cc47b7 --- /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 4dbb32b5586a0e6c402b2f707a5c8bfb28c11699 Mon Sep 17 00:00:00 2001 From: Victor Stinner Date: Tue, 15 Jan 2019 11:28:56 +0100 Subject: [PATCH 2/2] Change log message --- Lib/asyncio/windows_events.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/Lib/asyncio/windows_events.py b/Lib/asyncio/windows_events.py index 90ceda6d375a2e..7f264e6f9a07a3 100644 --- a/Lib/asyncio/windows_events.py +++ b/Lib/asyncio/windows_events.py @@ -812,7 +812,7 @@ def close(self): while self._cache: if next_msg <= time.monotonic(): logger.debug('IocpProactor.close(): ' - 'loop is still running since %.1f sec', + 'loop is running after closing for %.1f seconds', time.monotonic() - start_time) next_msg = time.monotonic() + msg_update