Merge pull request #546 from lsst/tickets/DM-30977

DM-30977: Add python log handler to store LogRecord as they come in

doc/changes/DM-30977.feature.rst

@@ -0,0 +1,5 @@
+* Add class representing a collection of log records (``ButlerLogRecords``).
+* Allow this class to be stored and retrieved from a Butler datastore.
+* Add special log handler to allow JSON log records to be stored.
+* Add ``--log-file`` option to command lines to redirect log output to file.
+* Add ``--no-log-tty`` to disable log output to terminal.

python/lsst/daf/butler/cli/butler.py

@@ -29,7 +29,7 @@
 import yaml
 
 from .cliLog import CliLog
-from .opt import log_level_option, long_log_option
+from .opt import log_level_option, long_log_option, log_file_option, log_tty_option
 from .progress import ClickProgressHandler
 from lsst.utils import doImport
 
@@ -152,7 +152,9 @@ def _setupLogging(self, ctx):
 
         Subcommands may further configure the log settings."""
         if isinstance(ctx, click.Context):
-            CliLog.initLog(longlog=ctx.params.get(long_log_option.name(), False))
+            CliLog.initLog(longlog=ctx.params.get(long_log_option.name(), False),
+                           log_tty=ctx.params.get(log_tty_option.name(), True),
+                           log_file=ctx.params.get(log_file_option.name(), ()))
             if log_level_option.name() in ctx.params:
                 CliLog.setLogLevels(ctx.params[log_level_option.name()])
         else:
@@ -316,8 +318,10 @@ def _cmdNameToFuncName(cls, commandName):
 @click.command(cls=ButlerCLI, context_settings=dict(help_option_names=["-h", "--help"]))
 @log_level_option()
 @long_log_option()
+@log_file_option()
+@log_tty_option()
 @ClickProgressHandler.option
-def cli(log_level, long_log, progress):
+def cli(log_level, long_log, log_file, log_tty, progress):
     # log_level is handled by get_command and list_commands, and is called in
     # one of those functions before this is called. long_log is handled by
     # setup_logging.

python/lsst/daf/butler/cli/cliLog.py

@@ -27,8 +27,7 @@
 except ModuleNotFoundError:
     lsstLog = None
 
-from lsst.daf.butler import ButlerMDC
-from ..core.logging import MDCDict
+from ..core.logging import JsonLogFormatter, ButlerMDC
 
 
 class PrecisionLogFormatter(logging.Formatter):
@@ -80,8 +79,12 @@ class CliLog:
     _initialized = False
     _componentSettings = []
 
+    _fileHandlers = []
+    """Any FileHandler classes attached to the root logger by this class
+    that need to be closed on reset."""
+
     @classmethod
-    def initLog(cls, longlog):
+    def initLog(cls, longlog: bool, log_tty: bool = True, log_file=()):
         """Initialize logging. This should only be called once per program
         execution. After the first call this will log a warning and return.
 
@@ -92,6 +95,14 @@ def initLog(cls, longlog):
         ----------
         longlog : `bool`
             If True, make log messages appear in long format, by default False.
+        log_tty : `bool`
+            Control whether a default stream handler is enabled that logs
+            to the terminal.
+        log_file : `tuple` of `str`
+            Path to files to write log records. If path ends in ``.json`` the
+            records will be written in JSON format. Else they will be written
+            in text format. If empty no log file will be created. Records
+            will be appended to this file if it exists.
         """
         if cls._initialized:
             # Unit tests that execute more than one command do end up
@@ -115,7 +126,9 @@ def initLog(cls, longlog):
             # MDC is set via ButlerMDC, rather than in lsst.log.
             lsstLog.usePythonLogging()
 
-        if longlog:
+        if not log_tty:
+            logging.basicConfig(force=True, handlers=[logging.NullHandler()])
+        elif longlog:
 
             # Want to create our own Formatter so that we can get high
             # precision timestamps. This requires we attach our own
@@ -142,18 +155,24 @@ def initLog(cls, longlog):
         # to the records. By default this is only used for long-log
         # but always enable it for when someone adds a new handler
         # that needs it.
-        old_factory = logging.getLogRecordFactory()
-
-        def record_factory(*args, **kwargs):
-            record = old_factory(*args, **kwargs)
-            # Make sure we send a copy of the global dict in the record.
-            record.MDC = MDCDict(ButlerMDC._MDC)
-            return record
-
-        logging.setLogRecordFactory(record_factory)
+        ButlerMDC.add_mdc_log_record_factory()
+
+        # Set up the file logger
+        for file in log_file:
+            handler = logging.FileHandler(file)
+            if file.endswith(".json"):
+                formatter = JsonLogFormatter()
+            else:
+                if longlog:
+                    formatter = PrecisionLogFormatter(fmt=cls.pylog_longLogFmt, style="{")
+                else:
+                    formatter = logging.Formatter(fmt=cls.pylog_normalFmt, style="{")
+            handler.setFormatter(formatter)
+            logging.getLogger().addHandler(handler)
+            cls._fileHandlers.append(handler)
 
         # remember this call
-        cls.configState.append((cls.initLog, longlog))
+        cls.configState.append((cls.initLog, longlog, log_tty, log_file))
 
     @classmethod
     def resetLog(cls):
@@ -177,6 +196,16 @@ def resetLog(cls):
             logger = logging.getLogger(componentSetting.component)
             logger.setLevel(componentSetting.pythonLogLevel)
         cls._setLogLevel(None, "INFO")
+
+        ButlerMDC.restore_log_record_factory()
+
+        # Remove the FileHandler we may have attached.
+        root = logging.getLogger()
+        for handler in cls._fileHandlers:
+            handler.close()
+            root.removeHandler(handler)
+
+        cls._fileHandlers.clear()
         cls._initialized = False
         cls.configState = []
 

python/lsst/daf/butler/cli/opt/options.py

@@ -23,7 +23,7 @@
 import click
 from functools import partial
 
-from ..utils import MWOptionDecorator, split_commas, split_kv, unwrap, yaml_presets
+from ..utils import MWOptionDecorator, MWPath, split_commas, split_kv, unwrap, yaml_presets
 from lsst.daf.butler.registry import CollectionType
 
 
@@ -113,6 +113,19 @@ def makeCollectionTypes(context, param, value):
                                     help="Make log messages appear in long format.",
                                     is_flag=True)
 
+log_file_option = MWOptionDecorator("--log-file",
+                                    default=None,
+                                    multiple=True,
+                                    callback=split_commas,
+                                    type=MWPath(file_okay=True, dir_okay=False, writable=True),
+                                    help="File(s) to write log messages. If the path ends with '.json' then"
+                                    " JSON log records will be written, else formatted text log records"
+                                    " will be written. This file can exist and records will be appended.")
+
+log_tty_option = MWOptionDecorator("--log-tty/--no-log-tty",
+                                   default=True,
+                                   help="Log to terminal (default). If false logging to terminal is"
+                                   " disabled.")
 
 options_file_option = MWOptionDecorator("--options-file", "-@",
                                         expose_value=False,  # This option should not be forwarded

python/lsst/daf/butler/configs/datastores/formatters.yaml

@@ -73,3 +73,4 @@ AstropyTable: lsst.daf.butler.formatters.astropyTable.AstropyTableFormatter
 AstropyQTable: lsst.daf.butler.formatters.astropyTable.AstropyTableFormatter
 ExtendedPsf: lsst.obs.base.formatters.fitsGeneric.FitsGenericFormatter
 HealSparseMap: lsst.pipe.tasks.healSparseMapping.HealSparseMapFormatter
+ButlerLogRecords: lsst.daf.butler.formatters.logs.ButlerLogRecordsFormatter

python/lsst/daf/butler/configs/storageClasses.yaml

@@ -260,3 +260,5 @@ storageClasses:
     parameters:
       - pixels
       - degrade_nside
+  ButlerLogRecords:
+    pytype: lsst.daf.butler.ButlerLogRecords

python/lsst/daf/butler/core/__init__.py

@@ -30,4 +30,7 @@
 from .timespan import *
 from .progress import Progress
 from . import progress  # most symbols are only used by handler implementors
-from .logging import *
+# Only import the VERBOSE constant and ButlerLogRecords
+# VERBOSE is useful for log messages and ButlerLogRecords is the
+# fundamental type stored in datastores.
+from .logging import VERBOSE, ButlerLogRecords

python/lsst/daf/butler/core/datastore.py

@@ -488,7 +488,7 @@ def _prepIngest(self, *datasets: FileDataset, transfer: Optional[str] = None) ->
         instead of `_finishIngest`.
         """
         raise NotImplementedError(
-            "Datastore does not support direct file-based ingest."
+            f"Datastore {self} does not support direct file-based ingest."
         )
 
     def _finishIngest(self, prepData: IngestPrepData, *, transfer: Optional[str] = None) -> None:
@@ -518,7 +518,7 @@ def _finishIngest(self, prepData: IngestPrepData, *, transfer: Optional[str] = N
         directly.
         """
         raise NotImplementedError(
-            "Datastore does not support direct file-based ingest."
+            f"Datastore {self} does not support direct file-based ingest."
         )
 
     def ingest(self, *datasets: FileDataset, transfer: Optional[str] = None) -> None: