logging: add a logging_config trait

* Closes ipython#688
* Allows fine configuration of logging via a `logging.config.dictConfig`.
* Changes the default log level from WARN to DEBUG and the default log
  handler level from undefined to WARN.

traitlets/config/application.py

@@ -4,16 +4,17 @@
 # Distributed under the terms of the Modified BSD License.
 
 
+from collections import defaultdict, OrderedDict
+from contextlib import suppress
+from copy import deepcopy
 import functools
 import json
 import logging
+from logging.config import dictConfig
 import os
 import pprint
 import re
 import sys
-import warnings
-from collections import OrderedDict, defaultdict
-from copy import deepcopy
 from textwrap import dedent
 
 from traitlets.config.configurable import Configurable, SingletonConfigurable
@@ -38,6 +39,7 @@
     observe_compat,
 )
 from traitlets.utils.text import indent, wrap_paragraphs
+from traitlets.utils.nested_update import nested_update
 
 from ..utils import cast_unicode
 from ..utils.importstring import import_item
@@ -196,16 +198,6 @@ def _classes_inc_parents(self, classes=None):
         help="Set the log level by value or name.",
     ).tag(config=True)
 
-    @observe("log_level")
-    @observe_compat
-    def _log_level_changed(self, change):
-        """Adjust the log level when log_level is set."""
-        new = change.new
-        if isinstance(new, str):
-            new = getattr(logging, new)
-            self.log_level = new
-        self.log.setLevel(new)
-
     _log_formatter_cls = LevelFormatter
 
     log_datefmt = Unicode(
@@ -217,30 +209,77 @@ def _log_level_changed(self, change):
         help="The Logging format template",
     ).tag(config=True)
 
-    @observe("log_datefmt", "log_format")
-    @observe_compat
-    def _log_format_changed(self, change):
-        """Change the log formatter when log_format is set."""
-        _log_handler = self._get_log_handler()
-        if not _log_handler:
-            warnings.warn(
-                f"No Handler found on {self.log}, setting log_format will have no effect",
-                RuntimeWarning,
-            )
-            return
-        _log_formatter = self._log_formatter_cls(fmt=self.log_format, datefmt=self.log_datefmt)
-        _log_handler.setFormatter(_log_formatter)
-
-    @default("log")
-    def _log_default(self):
-        """Start logging for this application.
+    def get_default_logging_config(self):
+        """Return the base logging configuration.
 
         The default is to log to stderr using a StreamHandler, if no default
-        handler already exists.  The log level starts at logging.WARN, but this
-        can be adjusted by setting the ``log_level`` attribute.
+        handler already exists.
+
+        The log handler level starts at logging.WARN, but this can be adjusted
+        by setting the ``log_level`` attribute.
+
+        The ``logging_config`` trait is merged into this allowing for finer
+        control of logging.
+
         """
+        config = {
+            'version': 1,
+            'handlers': {
+                'console': {
+                    'class': 'logging.StreamHandler',
+                    'formatter': 'console',
+                    'level': logging.getLevelName(self.log_level),
+                    'stream': 'ext://sys.stderr',
+                },
+            },
+            'formatters': {
+                'console': {
+                    'class': (
+                        f'{self._log_formatter_cls.__module__}'
+                        f'.{self._log_formatter_cls.__name__}'
+                    ),
+                    'format': self.log_format,
+                    'datefmt': self.log_datefmt,
+                },
+            },
+            'loggers': {
+                self.__class__.__name__: {
+                    'level': 'DEBUG',
+                    'handlers': ['console'],
+                }
+            },
+            'disable_existing_loggers': False,
+        }
+
+        if sys.executable and sys.executable.endswith('pythonw.exe'):
+            # disable logging
+            # (this should really go to a file, but file-logging is only
+            # hooked up in parallel applications)
+            del config['handlers']['loggers']
+
+        return config
+
+    @observe('log_datefmt', 'log_format', 'log_level', 'logging_config')
+    def _observe_logging_change(self, change):
+        # convert log level strings to ints
+        log_level = self.log_level
+        if isinstance(log_level, str):
+            self.log_level = getattr(logging, log_level)
+        self._configure_logging()
+
+    @observe('log', type='default')
+    def _observe_logging_default(self, change):
+        self._configure_logging()
+
+    def _configure_logging(self):
+        config = self.get_default_logging_config()
+        nested_update(config, self.logging_config or {})
+        dictConfig(config)
+
+    @default('log')
+    def _log_default(self):
+        """Start logging for this application."""
         log = logging.getLogger(self.__class__.__name__)
-        log.setLevel(self.log_level)
         log.propagate = False
         _log = log  # copied from Logger.hasHandlers() (new in Python 3.2)
         while _log:
@@ -250,17 +289,58 @@ def _log_default(self):
                 break
             else:
                 _log = _log.parent
-        if sys.executable and sys.executable.endswith("pythonw.exe"):
-            # this should really go to a file, but file-logging is only
-            # hooked up in parallel applications
-            _log_handler = logging.StreamHandler(open(os.devnull, "w"))
-        else:
-            _log_handler = logging.StreamHandler()
-        _log_formatter = self._log_formatter_cls(fmt=self.log_format, datefmt=self.log_datefmt)
-        _log_handler.setFormatter(_log_formatter)
-        log.addHandler(_log_handler)
         return log
 
+    logging_config = Dict(
+        help="""
+            Configure additional log handlers.
+
+            The default stderr logs handler is configured by the
+            log_level, log_datefmt and log_format settings.
+
+            This configuration can be used to configure additional handlers
+            (e.g. to output the log to a file) or for finer control over the
+            default handlers.
+
+            If provided this should be a logging configuration dictionary, for
+            more information see:
+            https://docs.python.org/3/library/logging.config.html#logging-config-dictschema
+
+            This dictionary is merged with the base logging configuration which
+            defines the following:
+
+            * A logging formatter intended for interactive use called
+              ``console``.
+            * A logging handler that writes to stderr called
+              ``console`` which uses the formatter ``console``.
+            * A logger with the name of this application set to ``DEBUG``
+              level.
+
+            This example adds a new handler that writes to a file:
+
+            .. code-block:: python
+
+               c.Application.logging_configuration = {
+                   'handlers': {
+                       'file': {
+                           'class': 'logging.FileHandler',
+                           'level': 'DEBUG',
+                           'filename': '<path/to/file>',
+                       }
+                   },
+                   'loggers': {
+                       '<application-name>': {
+                           'level': 'DEBUG',
+                           # NOTE: if you don't list the default "console"
+                           # handler here then it will be disabled
+                           'handlers': ['console', 'file'],
+                       },
+                   }
+               }
+
+        """,
+    ).tag(config=True)
+
     #: the alias map for configurables
     #: Keys might strings or tuples for additional options; single-letter alias accessed like `-v`.
     #: Values might be like "Class.trait" strings of two-tuples: (Class.trait, help-text).
@@ -860,10 +940,19 @@ def generate_config_file(self, classes=None):
             lines.append(cls.class_config_section(config_classes))
         return "\n".join(lines)
 
+    def close_handlers(self):
+        for handler in self.log.handlers:
+            with suppress(Exception):
+                handler.close()
+
     def exit(self, exit_status=0):
         self.log.debug("Exiting application: %s" % self.name)
+        self.close_handlers()
         sys.exit(exit_status)
 
+    def __del__(self):
+        self.close_handlers()
+
     @classmethod
     def launch_instance(cls, argv=None, **kwargs):
         """Launch a global instance of this Application

traitlets/config/configurable.py

@@ -469,6 +469,9 @@ def _get_log_handler(self):
         """Return the default Handler
 
         Returns None if none can be found
+
+        Deprecated, this now returns the first log handler which may or may
+        not be the default one.
         """
         logger = self.log
         if isinstance(logger, logging.LoggerAdapter):

traitlets/config/tests/test_application.py

@@ -121,9 +121,9 @@ def test_log(self):
         app = MyApp(log_level=logging.INFO)
         handler = logging.StreamHandler(stream)
         # trigger reconstruction of the log formatter
-        app.log.handlers = [handler]
         app.log_format = "%(message)s"
         app.log_datefmt = "%Y-%m-%d %H:%M"
+        app.log.handlers = [handler]
         app.log.info("hello")
         assert "hello" in stream.getvalue()
 
@@ -768,6 +768,42 @@ def initialize(self, *args, **kwargs):
     assert len(list(app.emit_alias_help())) > 0
 
 
-if __name__ == "__main__":
+def test_logging_config(tmp_path, capsys):
+    """We should be able to configure additional log handlers."""
+    log_file = tmp_path / 'log_file'
+    app = Application(
+        logging_config={
+            'version': 1,
+            'handlers': {
+                'file': {
+                    'class': 'logging.FileHandler',
+                    'level': 'DEBUG',
+                    'filename': str(log_file),
+                },
+            },
+            'loggers': {
+                'Application': {
+                    'level': 'DEBUG',
+                    'handlers': ['console', 'file'],
+                },
+            }
+        }
+    )
+    # the default "console" handler + our new "file" handler
+    assert len(app.log.handlers) == 2
+
+    # log a couple of messages
+    app.log.info('info')
+    app.log.warn('warn')
+
+    # test that log messages get written to the file
+    with open(log_file, 'r') as log_handle:
+        assert log_handle.read() == 'info\nwarn\n'
+
+    # test that log messages get written to stderr (default console handler)
+    assert capsys.readouterr().err == '[Application] WARNING | warn\n'
+
+
+if __name__ == '__main__':
     # for test_help_output:
     MyApp.launch_instance()

traitlets/config/tests/test_configurable.py

@@ -704,14 +704,13 @@ def test_warn_match(self):
         self.assertIn("Config option `totally_wrong` not recognized by `A`.", output)
         self.assertNotIn("Did you mean", output)
 
-    def test_logger_adapter(self):
-        logger = logging.getLogger("test_logger_adapter")
-        adapter = logging.LoggerAdapter(logger, {"key": "adapted"})
 
-        with self.assertLogs(logger, logging.INFO) as captured:
-            app = Application(log=adapter, log_level=logging.INFO)
-            app.log_format = "%(key)s %(message)s"
-            app.log.info("test message")
+def test_logger_adapter(caplog, capsys):
+    logger = logging.getLogger("Application")
+    adapter = logging.LoggerAdapter(logger, {"key": "adapted"})
 
-        output = "\n".join(captured.output)
-        assert "adapted test message" in output
+    app = Application(log=adapter, log_level=logging.INFO)
+    app.log_format = "%(key)s %(message)s"
+    app.log.info("test message")
+
+    assert 'adapted test message' in capsys.readouterr().err

traitlets/utils/nested_update.py

@@ -0,0 +1,38 @@
+# Copyright (c) IPython Development Team.
+# Distributed under the terms of the Modified BSD License.
+
+
+def nested_update(this, that):
+    """Merge two nested dictionaries.
+
+    Effectively a recursive ``dict.update``.
+
+    Examples
+    --------
+    Merge two flat dictionaries:
+    >>> nested_update(
+    ...     {'a': 1, 'b': 2},
+    ...     {'b': 3, 'c': 4}
+    ... )
+    {'a': 1, 'b': 3, 'c': 4}
+
+    Merge two nested dictionaries:
+    >>> nested_update(
+    ...     {'x': {'a': 1, 'b': 2}, 'y': 5, 'z': 6},
+    ...     {'x': {'b': 3, 'c': 4}, 'z': 7, '0': 8},
+    ... )
+    {'x': {'a': 1, 'b': 3, 'c': 4}, 'y': 5, 'z': 7, '0': 8}
+
+    """
+    for key, value in this.items():
+        if isinstance(value, dict):
+            if key in that and isinstance(that[key], dict):
+                nested_update(this[key], that[key])
+        elif key in that:
+            this[key] = that[key]
+
+    for key, value in that.items():
+        if key not in this:
+            this[key] = value
+
+    return this