[3.7] bpo-34323: Enhance IocpProactor.close() log (GH-11565)

vstinner · web-flow · commit d5a6adf6285e · 2019-01-15T13:05:28.000+01:00
* 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 9b07681) * 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 b1e4573) * bpo-34323: 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 b91140f)
diff --git 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
@@ -392,10 +393,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 +609,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 +653,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 +691,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 +761,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 +787,25 @@ def close(self):
                             context['source_traceback'] = fut._source_traceback
                         self._loop.call_exception_handler(context)
 
+        # 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('%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
+            self._poll(msg_update)
 
         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()
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
@@ -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.

Original file line number	Diff line number	Diff line change
`@@ -0,0 +1,3 @@`
	`1`	+:mod:`asyncio`: Enhance ``IocpProactor.close()`` log: wait 1 second before
	`2`	`+the first log, then log every second. Log also the number of seconds since`
	`3`	+``close()`` was called.