[Python-checkins] bpo-34323: Enhance IocpProactor.close() log (GH-11555)

[Victor Stinner]

https://github.com/python/cpython/commit/b1e45739d832e1e402a563c6727defda92e193b7
commit: b1e45739d832e1e402a563c6727defda92e193b7
branch: master
author: Victor Stinner <vstinner at redhat.com>
committer: GitHub <noreply at github.com>
date: 2019-01-15T11:48:00+01:00
summary:

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.

files:
A Misc/NEWS.d/next/Library/2019-01-14-17-34-36.bpo-34323.CRErrt.rst
M Lib/asyncio/windows_events.py

diff --git a/Lib/asyncio/windows_events.py b/Lib/asyncio/windows_events.py
index bdb9a6e28a86..7f264e6f9a07 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 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 000000000000..59269244cc47
--- /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.