Properly document multiprocessing's logging support, resolve outstanding issues with the custom levels

5 files changed, 82 insertions, 20 deletions

diff --git a/Doc/library/multiprocessing.rst b/Doc/library/multiprocessing.rst
index ee92a7c..3d66d14 100644
--- a/Doc/library/multiprocessing.rst
+++ b/Doc/library/multiprocessing.rst
@@ -1859,30 +1859,74 @@ handler type) for messages from different processes to get mixed up.
    Returns the logger used by :mod:`multiprocessing`.  If necessary, a new one
    will be created.
 
-   When first created the logger has level :data:`logging.NOTSET` and has a
-   handler which sends output to :data:`sys.stderr` using format
-   ``'[%(levelname)s/%(processName)s] %(message)s'``.  (The logger allows use of
-   the non-standard ``'%(processName)s'`` format.)  Message sent to this logger
-   will not by default propagate to the root logger.
+   When first created the logger has level :data:`logging.NOTSET` and no
+   default handler. Messages sent to this logger will not by default propagate
+   to the root logger.
 
    Note that on Windows child processes will only inherit the level of the
    parent process's logger -- any other customization of the logger will not be
    inherited.
 
+.. currentmodule:: multiprocessing
+.. function:: log_to_stderr()
+
+   This function performs a call to :func:`get_logger` but in addition to
+   returning the logger created by get_logger, it adds a handler which sends
+   output to :data:`sys.stderr` using format
+   ``'[%(levelname)s/%(processName)s] %(message)s'``.
+
 Below is an example session with logging turned on::
 
     >>> import multiprocessing, logging
-    >>> logger = multiprocessing.get_logger()
+    >>> logger = multiprocessing.log_to_stderr()
     >>> logger.setLevel(logging.INFO)
     >>> logger.warning('doomed')
     [WARNING/MainProcess] doomed
     >>> m = multiprocessing.Manager()
     [INFO/SyncManager-1] child process calling self.run()
-    [INFO/SyncManager-1] manager bound to '\\\\.\\pipe\\pyc-2776-0-lj0tfa'
+    [INFO/SyncManager-1] created temp directory /.../pymp-Wh47O_
+    [INFO/SyncManager-1] manager serving at '/.../listener-lWsERs'
     >>> del m
     [INFO/MainProcess] sending shutdown message to manager
     [INFO/SyncManager-1] manager exiting with exitcode 0
 
+In addition to having these two logging functions, the multiprocessing also
+exposes two additional logging level attributes. These are  :const:`SUBWARNING`
+and :const:`SUBDEBUG`. The table below illustrates where theses fit in the
+normal level hierarchy.
+
++----------------+----------------+
+| Level          | Numeric value  |
++================+================+
+| ``SUBWARNING`` | 25             |
++----------------+----------------+
+| ``SUBDEBUG``   | 5              |
++----------------+----------------+
+
+For a full table of logging levels, see the :mod:`logging` module.
+
+These additional logging levels are used primarily for certain debug messages
+within the multiprocessing module. Below is the same example as above, except
+with :const:`SUBDEBUG` enabled::
+
+    >>> import multiprocessing, logging
+    >>> logger = multiprocessing.log_to_stderr()
+    >>> logger.setLevel(multiprocessing.SUBDEBUG)
+    >>> logger.warning('doomed')
+    [WARNING/MainProcess] doomed
+    >>> m = multiprocessing.Manager()
+    [INFO/SyncManager-1] child process calling self.run()
+    [INFO/SyncManager-1] created temp directory /.../pymp-djGBXN
+    [INFO/SyncManager-1] manager serving at '/.../pymp-djGBXN/listener-knBYGe'
+    >>> del m
+    [SUBDEBUG/MainProcess] finalizer calling ...
+    [INFO/MainProcess] sending shutdown message to manager
+    [DEBUG/SyncManager-1] manager received shutdown message
+    [SUBDEBUG/SyncManager-1] calling <Finalize object, callback=unlink, ...
+    [SUBDEBUG/SyncManager-1] finalizer calling <built-in function unlink> ...
+    [SUBDEBUG/SyncManager-1] calling <Finalize object, dead>
+    [SUBDEBUG/SyncManager-1] finalizer calling <function rmtree at 0x5aa730> ...
+    [INFO/SyncManager-1] manager exiting with exitcode 0
 
 The :mod:`multiprocessing.dummy` module
 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
diff --git a/Lib/multiprocessing/__init__.py b/Lib/multiprocessing/__init__.py
index 10be01a..4fb0bd0 100644
--- a/Lib/multiprocessing/__init__.py
+++ b/Lib/multiprocessing/__init__.py
@@ -48,7 +48,7 @@ __all__ = [
     'allow_connection_pickling', 'BufferTooShort', 'TimeoutError',
     'Lock', 'RLock', 'Semaphore', 'BoundedSemaphore', 'Condition',
     'Event', 'Queue', 'JoinableQueue', 'Pool', 'Value', 'Array',
-    'RawValue', 'RawArray'
+    'RawValue', 'RawArray', 'SUBDEBUG', 'SUBWARNING',
     ]
 
 __author__ = 'R. Oudkerk (r.m.oudkerk@gmail.com)'
@@ -61,6 +61,7 @@ import os
 import sys
 
 from multiprocessing.process import Process, current_process, active_children
+from multiprocessing.util import SUBDEBUG, SUBWARNING
 
 #
 # Exceptions
diff --git a/Lib/multiprocessing/util.py b/Lib/multiprocessing/util.py
index 2e7a2ac..632adb1 100644
--- a/Lib/multiprocessing/util.py
+++ b/Lib/multiprocessing/util.py
@@ -17,7 +17,8 @@ from multiprocessing.process import current_process, active_children
 __all__ = [
     'sub_debug', 'debug', 'info', 'sub_warning', 'get_logger',
     'log_to_stderr', 'get_temp_dir', 'register_after_fork',
-    'is_exiting', 'Finalize', 'ForkAwareThreadLock', 'ForkAwareLocal'
+    'is_exiting', 'Finalize', 'ForkAwareThreadLock', 'ForkAwareLocal',
+    'SUBDEBUG', 'SUBWARNING',
     ]
 
 #
@@ -57,19 +58,27 @@ def get_logger():
     Returns logger used by multiprocessing
     '''
     global _logger
+    import logging, atexit
 
-    if not _logger:
-        import logging, atexit
+    logging._acquireLock()
+    try:
+        if not _logger:
 
-        # XXX multiprocessing should cleanup before logging
-        if hasattr(atexit, 'unregister'):
-            atexit.unregister(_exit_function)
-            atexit.register(_exit_function)
-        else:
-            atexit._exithandlers.remove((_exit_function, (), {}))
-            atexit._exithandlers.append((_exit_function, (), {}))
+            _logger = logging.getLogger(LOGGER_NAME)
+            _logger.propagate = 0
+            logging.addLevelName(SUBDEBUG, 'SUBDEBUG')
+            logging.addLevelName(SUBWARNING, 'SUBWARNING')
+
+            # XXX multiprocessing should cleanup before logging
+            if hasattr(atexit, 'unregister'):
+                atexit.unregister(_exit_function)
+                atexit.register(_exit_function)
+            else:
+                atexit._exithandlers.remove((_exit_function, (), {}))
+                atexit._exithandlers.append((_exit_function, (), {}))
 
-        _logger = logging.getLogger(LOGGER_NAME)
+    finally:
+        logging._releaseLock()
 
     return _logger
 
@@ -79,14 +88,17 @@ def log_to_stderr(level=None):
     '''
     global _log_to_stderr
     import logging
+
     logger = get_logger()
     formatter = logging.Formatter(DEFAULT_LOGGING_FORMAT)
     handler = logging.StreamHandler()
     handler.setFormatter(formatter)
     logger.addHandler(handler)
-    if level is not None:
+
+    if level:
         logger.setLevel(level)
     _log_to_stderr = True
+    return _logger
 
 #
 # Function returning a temp directory which will be removed on exit
diff --git a/Misc/ACKS b/Misc/ACKS
index 0acf585..cfa769c 100644
--- a/Misc/ACKS
+++ b/Misc/ACKS
@@ -783,3 +783,4 @@ Siebren van der Zee
 Uwe Zessin
 Tarek ZiadŽ
 Peter Åstrand
+Jesse Noller
diff --git a/Misc/NEWS b/Misc/NEWS
index 0b5f801..4fc5d5e 100644
--- a/Misc/NEWS
+++ b/Misc/NEWS
@@ -145,6 +145,10 @@ Core and Builtins
 Library
 -------
 
+- Fix and properly document the multiprocessing module's logging
+  support, expose the internal levels and provide proper usage
+  examples.
+
 - Issue #1672332: fix unpickling of subnormal floats, which was
   producing a ValueError on some platforms.