JP-4192: Work around default CRDS log configuration to allow stpipe capture (#312)

Author: melanieclarke

changes/312.feature.rst

@@ -0,0 +1 @@
+Add special handling for the CRDS logger to allow its messages to be captured by stpipe steps.

src/stpipe/crds_client.py

@@ -2,10 +2,6 @@
 This module defines functions that connect the core crds package
 to stpipe, tailoring it to provide results in the forms required
 by stpipe.
-
-WARNING:  stpipe and crds have circular dependencies.  Do not use crds imports
-directly in modules other than this crds_client so that dependency order and
-general integration can be managed here.
 """
 
 import re

src/stpipe/log.py

@@ -12,6 +12,7 @@
 
 from astropy.extern.configobj import validate
 from astropy.extern.configobj.configobj import ConfigObj
+from crds.core import log as crds_log
 
 from . import config_parser
 
@@ -102,6 +103,7 @@ def __init__(
             self.handlers.append(BreakHandler(self.break_level))
 
         self._previous_level = {}
+        self._previous_crds_console = False
 
     def get_handler(self, handler_str):
         """
@@ -131,6 +133,13 @@ def apply(self, log_names=None):
         If a logger has already been configured and not undone,
         it will be skipped.
 
+        Special handling is applied for the following log names:
+
+        - "py.warnings": If provided, Python warnings are captured and
+          logged (``logging.captureWarnings(True)``).
+        - "CRDS": If provided, the default stream handler for the CRDS
+          logger is removed if needed.
+
         Parameters
         ----------
         log_names : tuple of str, list of str, or None, optional
@@ -141,6 +150,10 @@ def apply(self, log_names=None):
             log_names = [STPIPE_ROOT_LOGGER]
         if "py.warnings" in log_names:
             logging.captureWarnings(True)
+        if "CRDS" in log_names:
+            self._previous_crds_console = crds_log.THE_LOGGER.console is not None
+            if self._previous_crds_console:
+                crds_log.remove_console_handler()
         for log_name in log_names:
             # Don't reapply configuration, to avoid overwriting the
             # previously recorded level.
@@ -160,6 +173,14 @@ def undo(self, log_names=None, close_handlers=True):
         """
         Removes the configuration from known loggers.
 
+        Special handling is applied for the following log names:
+
+        - "py.warnings": If provided, Python warnings are no longer captured
+          and logged (``logging.captureWarnings(False)``).
+        - "CRDS": If provided and if the default stream handler for the CRDS
+          logger was present when configuration was applied, it will be
+          restored.
+
         Parameters
         ----------
         log_names : list of str or None, optional
@@ -191,6 +212,9 @@ def undo(self, log_names=None, close_handlers=True):
             LogConfig.applied = None
         if "py.warnings" in log_names:
             logging.captureWarnings(False)
+        if "CRDS" in log_names and self._previous_crds_console:
+            self._previous_crds_console = False
+            crds_log.add_console_handler()
 
     @contextmanager
     def context(self, log_names=None):

tests/test_logger.py

@@ -3,6 +3,7 @@
 import warnings
 
 import pytest
+from crds.core import log as crds_log
 
 import stpipe.cmdline
 from stpipe import Step
@@ -49,7 +50,7 @@ def _clean_up_logging():
 
 
 class LoggingStep(Step):
-    """A Step that utilizes a local logger to log a warning."""
+    """A Step that uses a local and external logger to log messages."""
 
     spec = """
         str1 = string(default='default')
@@ -74,7 +75,7 @@ def get_stpipe_loggers():
 
 
 class LoggingPipeline(Pipeline):
-    """A Pipeline that utilizes a local logger to log a warning."""
+    """A Pipeline that uses a local and external logger to log messages."""
 
     spec = """
         str1 = string(default='default')
@@ -589,3 +590,56 @@ def get_stpipe_loggers():
     assert len(recwarn) == 1  # Unchanged from above assert
     assert MSG in caplog.text
     assert logging._warnings_showwarning is None
+
+
+@pytest.mark.parametrize("restore_console", [True, False])
+def test_crds_log(capsys, restore_console):
+    class CRDSLoggingStep(LoggingStep):
+        def process(self):
+            logger.info(STEP_INFO)
+            logger.warning(STEP_WARNING)
+            logger.debug(STEP_DEBUG)
+            crds_log.info(EXTERNAL_INFO)
+            crds_log.warning(EXTERNAL_WARNING)
+            crds_log.debug(EXTERNAL_DEBUG)
+
+        @staticmethod
+        def get_stpipe_loggers():
+            return ("stpipe", "CRDS")
+
+    crds_logger = logging.getLogger("CRDS")
+    if restore_console:
+        # Before the step call, the crds logger has a stream handler
+        assert len(crds_logger.handlers) == 1
+        assert isinstance(crds_logger.handlers[0], logging.StreamHandler)
+    else:
+        # remove any current console handler
+        crds_log.remove_console_handler()
+
+        # Before the step call, the crds logger has no handlers
+        assert len(crds_logger.handlers) == 0
+
+    # During the step call, the CRDS handler is removed if necessary and
+    # the stpipe handler is attached
+    CRDSLoggingStep.call()
+
+    # With default configuration, exactly one info and warning message is expected
+    # from each captured logger in the stderr stream
+    capt = capsys.readouterr()
+    for msg in ALL_MESSAGES:
+        assert capt.out == ""
+        if msg in [STEP_INFO, STEP_WARNING, EXTERNAL_INFO, EXTERNAL_WARNING]:
+            assert msg in capt.err
+            assert capt.err.count(msg) == 1
+        else:
+            assert capt.err.count(msg) == 0
+
+    # After the call is complete, the stpipe logger is removed and the CRDS
+    # stream logger is restored if it was previously present
+    if restore_console:
+        assert len(crds_logger.handlers) == 1
+        assert isinstance(crds_logger.handlers[0], logging.StreamHandler)
+    else:
+        assert len(crds_logger.handlers) == 0
+        # Clean up: restore a console logger
+        crds_log.add_console_handler()