Merge pull request #1419 from brian-team/logging_with_multiproc

Logging with multiprocessing

brian2/tests/test_logger.py

@@ -0,0 +1,80 @@
+import multiprocessing
+import os
+
+from brian2.utils.logger import BrianLogger, get_logger
+from brian2.core.preferences import prefs
+
+import pytest
+
+logger = get_logger('brian2.tests.test_logger')
+
+@pytest.mark.codegen_independent
+def test_file_logging():
+    logger.error('error message xxx')
+    logger.warn('warning message xxx')
+    logger.info('info message xxx')
+    logger.debug('debug message xxx')
+    logger.diagnostic('diagnostic message xxx')
+    BrianLogger.file_handler.flush()
+    # By default, only >= debug messages should show up
+    assert os.path.isfile(BrianLogger.tmp_log)
+    with open(BrianLogger.tmp_log, 'r') as f:
+        log_content = f.readlines()
+    for level, line in zip(['error', 'warning', 'info', 'debug'], log_content[-4:]):
+        assert 'brian2.tests.test_logger' in line
+        assert f"{level} message xxx" in line
+        assert level.upper() in line
+
+def run_in_process(x):
+    logger.info(f"subprocess info message {x}")
+
+def run_in_process_with_logger(x):
+    prefs.logging.delete_log_on_exit = False
+    BrianLogger.initialize()
+    logger.info(f"subprocess info message {x}")
+    BrianLogger.file_handler.flush()
+    return BrianLogger.tmp_log
+
+@pytest.mark.codegen_independent
+def test_file_logging_multiprocessing():
+    logger.info("info message before multiprocessing")
+
+    with multiprocessing.Pool() as p:
+        p.map(run_in_process, range(3))
+
+    BrianLogger.file_handler.flush()
+    assert os.path.isfile(BrianLogger.tmp_log)
+    with open(BrianLogger.tmp_log, 'r') as f:
+        log_content = f.readlines()
+    # The subprocesses should not have written to the log file
+    assert "info message before multiprocessing" in log_content[-1]
+
+
+@pytest.mark.codegen_independent
+def test_file_logging_multiprocessing_with_loggers():
+    logger.info("info message before multiprocessing")
+
+    with multiprocessing.Pool() as p:
+        log_files = p.map(run_in_process_with_logger, range(3))
+
+    BrianLogger.file_handler.flush()
+    assert os.path.isfile(BrianLogger.tmp_log)
+    with open(BrianLogger.tmp_log, 'r') as f:
+        log_content = f.readlines()
+    # The subprocesses should not have written to the main log file
+    assert "info message before multiprocessing" in log_content[-1]
+
+    # Each subprocess should have their own log file
+    for x, log_file in enumerate(log_files):
+        assert os.path.isfile(log_file)
+        with open(log_file, 'r') as f:
+            log_content = f.readlines()
+        assert f"subprocess info message {x}" in log_content[-1]
+
+    prefs.logging.delete_log_on_exit = True
+
+
+if __name__ == '__main__':
+    test_file_logging()
+    test_file_logging_multiprocessing()
+    test_file_logging_multiprocessing_with_loggers()

brian2/utils/logger.py

@@ -9,6 +9,7 @@
 import atexit
 import logging
 import logging.handlers
+from logging.handlers import RotatingFileHandler
 import os
 import shutil
 import sys
@@ -67,7 +68,7 @@ def log_level_validator(log_level):
             """,
             ),
         file_log_level=BrianPreference(
-            default='DIAGNOSTIC',
+            default='DEBUG',
             docs="""
             What log level to use for the log written to the log file.
             
@@ -324,6 +325,9 @@ class BrianLogger(object):
     #: deleted after the run if no exception occurred), if any
     tmp_script = None
 
+    #: The pid of the process that initialized the logger – used to switch off file logging in
+    #: multiprocessing contexts
+    _pid = None
     def __init__(self, name):
         self.name = name
 
@@ -346,6 +350,12 @@ def _log(self, log_level, msg, name_suffix, once):
         if name_suffix:
             name += f".{name_suffix}"
 
+        # Switch off file logging when using multiprocessing
+        if BrianLogger.tmp_log is not None and BrianLogger._pid != os.getpid():
+            BrianLogger.tmp_log = None
+            logging.getLogger('brian2').removeHandler(BrianLogger.file_handler)
+            BrianLogger.file_handler = None
+
         if once:
             # Check whether this exact message has already been displayed 
             log_tuple = (name, log_level, msg)
@@ -552,16 +562,20 @@ def initialize():
                                                                   suffix='.log',
                                                                   delete=False)
                 BrianLogger.tmp_log = BrianLogger.tmp_log.name
+                # Remove any previously existing file handler
+                if BrianLogger.file_handler is not None:
+                    logger.removeHandler(BrianLogger.file_handler)
                 # Rotate log file after prefs['logging.file_log_max_size'] bytes and keep one copy
-                BrianLogger.file_handler = logging.handlers.RotatingFileHandler(BrianLogger.tmp_log,
-                                                                                mode='a',
-                                                                                maxBytes=prefs['logging.file_log_max_size'],
-                                                                                backupCount=1)
+                BrianLogger.file_handler = RotatingFileHandler(BrianLogger.tmp_log,
+                                                               mode='a',
+                                                               maxBytes=prefs['logging.file_log_max_size'],
+                                                               backupCount=1)
                 BrianLogger.file_handler.setLevel(
                     LOG_LEVELS[prefs['logging.file_log_level'].upper()])
                 BrianLogger.file_handler.setFormatter(logging.Formatter(
                     '%(asctime)s %(levelname)-10s %(name)s: %(message)s'))
                 logger.addHandler(BrianLogger.file_handler)
+                BrianLogger._pid = os.getpid()
             except IOError as ex:
                 warn(f'Could not create log file: {ex}')
 
@@ -592,6 +606,9 @@ def initialize():
                     warn(
                         f'Could not copy script file to temp directory: {ex}')
 
+        if BrianLogger.console_handler is not None:
+            logger.removeHandler(BrianLogger.console_handler)
+
         # create console handler with a higher log level
         BrianLogger.console_handler = logging.StreamHandler()
         BrianLogger.console_handler.setLevel(LOG_LEVELS[prefs['logging.console_log_level']])
@@ -614,18 +631,18 @@ def initialize():
             warn_logger.addHandler(BrianLogger.file_handler)
 
         # Put some standard info into the log file
-        logger.log(DIAGNOSTIC,
+        logger.log(logging.DEBUG,
                    f'Logging to file: {BrianLogger.tmp_log}, copy of main script saved as: {BrianLogger.tmp_script}')
-        logger.log(DIAGNOSTIC, f'Python interpreter: {sys.executable}')
-        logger.log(DIAGNOSTIC, f'Platform: {sys.platform}')
+        logger.log(logging.DEBUG, f'Python interpreter: {sys.executable}')
+        logger.log(logging.DEBUG, f'Platform: {sys.platform}')
         version_infos = {'brian': brian2.__version__,
                          'numpy': numpy.__version__,
                          'scipy': scipy.__version__ if scipy else 'not installed',
                          'sympy': sympy.__version__,
                          'python': sys.version,
                          }
         for _name, _version in version_infos.items():
-            logger.log(DIAGNOSTIC,
+            logger.log(logging.DEBUG,
                        f'{_name} version is: {str(_version)}')
         # Handle uncaught exceptions
         sys.excepthook = brian_excepthook

dev/continuous-integration/run_simple_test.py

@@ -3,6 +3,7 @@
 from brian2 import prefs
 from brian2.tests.test_synapses import test_transmission_simple
 
-prefs.codegen.target = 'cython'
+if __name__ == '__main__':
+    prefs.codegen.target = 'cython'
 
-test_transmission_simple()
+    test_transmission_simple()

dev/continuous-integration/run_test_suite.py

@@ -2,70 +2,73 @@
 Script to run the test suite during automatic testing (easier than putting all
 the logic into Windows batch/bash statements)
 '''
-
+# Importing multiprocessing here seems to fix hangs in the test suite on OS X
+# see https://github.com/scipy/scipy/issues/11835
+import multiprocessing
 import os
 import sys
 
 import numpy as np
 
 import brian2
 
-split_run = os.environ.get('SPLIT_RUN', None)
-standalone = os.environ.get('STANDALONE', 'no').lower() in ['yes', 'true']
-python_version = os.environ.get('PYTHON_VERSION', os.environ.get('PYTHON'))
-# If TRAVIS_OS_NAME is not defined, we are testing on appveyor
-operating_system = os.environ.get('AGENT_OS', 'unknown').lower()
-cross_compiled = os.environ.get('CROSS_COMPILED', 'FALSE').lower() in ['yes', 'true']
-report_coverage = os.environ.get('REPORT_COVERAGE', 'no').lower() in ['yes', 'true']
-dtype_32_bit = os.environ.get('FLOAT_DTYPE_32', 'no').lower() in ['yes', 'true']
-sphinx_dir = os.environ.get('SPHINX_DIR')
-src_dir = os.environ.get('SRCDIR')
+if __name__ == '__main__':
+    split_run = os.environ.get('SPLIT_RUN', None)
+    standalone = os.environ.get('STANDALONE', 'no').lower() in ['yes', 'true']
+    python_version = os.environ.get('PYTHON_VERSION', os.environ.get('PYTHON'))
+    # If TRAVIS_OS_NAME is not defined, we are testing on appveyor
+    operating_system = os.environ.get('AGENT_OS', 'unknown').lower()
+    cross_compiled = os.environ.get('CROSS_COMPILED', 'FALSE').lower() in ['yes', 'true']
+    report_coverage = os.environ.get('REPORT_COVERAGE', 'no').lower() in ['yes', 'true']
+    dtype_32_bit = os.environ.get('FLOAT_DTYPE_32', 'no').lower() in ['yes', 'true']
+    sphinx_dir = os.environ.get('SPHINX_DIR')
+    src_dir = os.environ.get('SRCDIR')
 
-if split_run == '1':
-    targets = ['numpy']
-    independent = True
-elif split_run == '2':
-    targets = ['cython']
-    independent = False
-else:
-    targets = None
-    independent = True
+    if split_run == '1':
+        targets = ['numpy']
+        independent = True
+    elif split_run == '2':
+        targets = ['cython']
+        independent = False
+    else:
+        targets = None
+        independent = True
 
-if operating_system == 'windows' or standalone:
-    in_parallel = []
-else:
-    in_parallel = ['codegen_independent', 'numpy', 'cpp_standalone']
+    if operating_system == 'windows' or standalone:
+        in_parallel = []
+    else:
+        in_parallel = ['codegen_independent', 'numpy', 'cpp_standalone']
 
-if operating_system in ['linux', 'windows_nt']:
-    openmp = True
-else:
-    openmp = False
+    if operating_system in ['linux', 'windows_nt']:
+        openmp = True
+    else:
+        openmp = False
 
-reset_preferences = not cross_compiled
-if dtype_32_bit:
-    float_dtype = np.float32
-else:
-    float_dtype = None
+    reset_preferences = not cross_compiled
+    if dtype_32_bit:
+        float_dtype = np.float32
+    else:
+        float_dtype = None
 
-if standalone:
-    result = brian2.test([],
-                         test_codegen_independent=False,
-                         test_standalone='cpp_standalone',
-                         test_openmp=openmp,
-                         test_in_parallel=in_parallel,
-                         reset_preferences=reset_preferences,
-                         float_dtype=float_dtype,
-                         test_GSL=True,
-                         sphinx_dir=sphinx_dir)
-else:
-    result = brian2.test(targets,
-                         test_codegen_independent=independent,
-                         test_standalone=None,
-                         test_in_parallel=in_parallel,
-                         reset_preferences=reset_preferences,
-                         float_dtype=float_dtype,
-                         test_GSL=True,
-                         sphinx_dir=sphinx_dir)
+    if standalone:
+        result = brian2.test([],
+                             test_codegen_independent=False,
+                             test_standalone='cpp_standalone',
+                             test_openmp=openmp,
+                             test_in_parallel=in_parallel,
+                             reset_preferences=reset_preferences,
+                             float_dtype=float_dtype,
+                             test_GSL=True,
+                             sphinx_dir=sphinx_dir)
+    else:
+        result = brian2.test(targets,
+                             test_codegen_independent=independent,
+                             test_standalone=None,
+                             test_in_parallel=in_parallel,
+                             reset_preferences=reset_preferences,
+                             float_dtype=float_dtype,
+                             test_GSL=True,
+                             sphinx_dir=sphinx_dir)
 
-if not result:
-    sys.exit(1)
+    if not result:
+        sys.exit(1)

docs_sphinx/advanced/logging.rst

@@ -28,14 +28,31 @@ useful for debugging. Each log message has one of the following "log levels":
     Additional information useful when tracking down bugs in Brian itself.
     *Example:* The generated code for a `CodeObject`.
 
-By default, all messages are written to the log file and all messages of level
-``INFO`` and above are displayed on the console. To change what messages are
-displayed, see below.
+By default, all messages with level ``DEBUG`` or above are written to the log file
+and all messages of level ``INFO`` and above are displayed on the console. To change
+what messages are displayed, see below.
 
 .. note:: By default, the log file is deleted after a successful simulation run,
    i.e. when the simulation exited without an error. To keep the log around,
    set the `logging.delete_log_on_exit` preference to ``False``.
 
+Logging and multiprocessing
+---------------------------
+Brian's logging system is not designed for multiple parallel Brian processes
+started via Python's `multiprocessing` module (see the
+:ref:`multiprocessing examples <multiprocessing>`). Log messages that get printed
+from different processes to the console are not printed in a well-defined order and
+do not contain any indication about which processes they are coming from. You might
+therefore consider using e.g. `BrianLogger.log_level_error()` to only show error
+messages before starting the processes and avoid cluttering your console with
+warning and info messages.
+
+To avoid issues when multiple processes try to log to the same log file, file
+logging is automatically switched off for all processes except for the initial
+process. If you need a file log for sub-processes, you can call
+`BrianLogger.initialize()` in each sub-process. This way, each process will log
+to its own file.
+
 Showing/hiding log messages
 ---------------------------
 If you want to change what messages are displayed on the console, you can call a
@@ -66,13 +83,20 @@ Preferences
 You can also change details of the logging system via Brian's :doc:`preferences`
 system. With this mechanism, you can switch the logging to a file off completely
 (by setting `logging.file_log` to ``False``) or have it log less messages (by
-setting `logging.file_log_level` to a level higher than ``DIAGNOSTIC``) -- this
-can be important for long-running simulations where the log might otherwise take
-up a lot of disk space. For a list of all preferences related to logging, see the
-documentation of the `brian2.utils.logger` module.
+setting `logging.file_log_level` to a level higher than ``DEBUG``). To debug
+details of the code generation system, you can also set `logging.file_log_level`
+to ``DIAGNOSTIC``. Note that this will make the log file grow quickly in size. To
+prevent it from filling up the disk, it will only be allowed to grow up to a certain
+size. You can configure the maximum file size with the `logging.file_log_max_size`
+preference.
+
+For a list of all preferences related to logging, see the documentation of the
+`brian2.utils.logger` module.
 
 .. warning:: Most of the logging preferences are only taken into account during
    the initialization of the logging system which takes place as soon as `brian2`
    is imported. Therefore, if you use e.g. `prefs.logging.file_log = False` in
-   your script, this will not have the intended effect! Instead, set these
-   preferences in a file (see :doc:`preferences`).
+   your script, this will not have the intended effect! To make sure these
+   preferences are taken into account, call `BrianLogger.initialize` after
+   setting the preferences. Alternatively, you can set the preferences in a file
+   (see :doc:`preferences`).