Set-up deferred logging with basicConfig

Fixes IAMconsortium#449.

See also discussion in the issue.

RELEASE_NOTES.md

@@ -2,6 +2,7 @@
 
 ## Individual updates
 
+- [#450](https://github.com/IAMconsortium/pyam/pull/450) Defer logging set-up to when the first logging message is generated
 - [#445](https://github.com/IAMconsortium/pyam/pull/445) Prevent conflicts between attributes and data/meta columns
 - [#444](https://github.com/IAMconsortium/pyam/pull/444) Use warnings module for deprecation warnings
 

pyam/__init__.py

@@ -10,26 +10,28 @@
 from pyam.iiasa import read_iiasa  # noqa: F401
 from pyam.datareader import read_worldbank  # noqa: F401
 
+from pyam.logging import defer_logging_config
+
 logger = logging.getLogger(__name__)
-logger.addHandler(logging.NullHandler())
 
-# in Jupyter notebooks: disable autoscroll and set logger to info
+# in Jupyter notebooks: disable autoscroll and set-up logging
 try:
-    get_ipython().run_cell_magic(u'javascript', u'',
-                                 u'IPython.OutputArea.prototype._should_scroll = function(lines) { return false; }')
-
-    logger.setLevel(logging.INFO)
-
-    stderr_info_handler = logging.StreamHandler()
-    formatter = logging.Formatter('%(name)s - %(levelname)s: %(message)s')
-    stderr_info_handler.setFormatter(formatter)
-    logger.addHandler(stderr_info_handler)
-
-    log_msg = (
-        "Running in a notebook, setting `{}` logging level to `logging.INFO` "
-        "and adding stderr handler".format(__name__)
-    )
-    logger.info(log_msg)
+    from ipykernel.zmqshell import ZMQInteractiveShell
+    from IPython import get_ipython
+
+    shell = get_ipython()
+    if isinstance(shell, ZMQInteractiveShell):
+        shell.run_cell_magic(
+            u'javascript', u'',
+            u'IPython.OutputArea.prototype._should_scroll = '
+            u'function(lines) { return false; }'
+        )
+
+        log_msg = "Running in a notebook, setting root logging level to INFO"
+        defer_logging_config(
+            logger, log_msg, level="INFO",
+            format="%(name)s - %(levelname)s: %(message)s",
+        )
 
 except Exception:
     pass

pyam/logging.py

@@ -21,3 +21,51 @@ def deprecation_warning(msg, type='This method'):
         DeprecationWarning,
         stacklevel=3
     )
+
+
+class ConfigPseudoHandler(logging.Handler):
+    """Pseudo logging handler to defer configuring logging until the first message
+
+    Registers itself as a handler for the provided logger and temporarily
+    sets the logger as sensitive to INFO messages. Upon receival of the first
+    message (of at least INFO level), it configures logging with the provided
+    `config_kwargs` and prints `log_msg`
+
+    Parameters
+    ----------
+    logger : logging.Logger
+        Logger to listen for the first message
+    log_msg : str, optional
+        Message to print once logging is configured, by default None
+    **config_kwargs
+        Arguments to pass on to logging.basicConfig
+    """
+    def __init__(self, logger, log_msg=None, **config_kwargs):
+        super().__init__()
+
+        self.logger = logger
+        self.log_msg = log_msg
+        self.config_kwargs = config_kwargs
+
+        self.logger.addHandler(self)
+
+        # temporarily set the logging level to a non-standard value,
+        # slightly below logging.INFO == 20 and use that as a sentinel
+        # to switch back to logging.NOTSET later
+        self.logger.setLevel(19)
+
+    def emit(self, record):
+        self.logger.removeHandler(self)
+
+        if self.logger.level == 19:
+            self.logger.setLevel(logging.NOTSET)
+
+        if not self.logger.root.hasHandlers():
+            logging.basicConfig(**self.config_kwargs)
+
+            if self.log_msg is not None:
+                self.logger.info(self.log_msg)
+
+
+# Give the Handler a function like alias
+defer_logging_config = ConfigPseudoHandler