Add --log-file option to command line tooling

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
 from .progress import ClickProgressHandler
 from lsst.utils import doImport
 
@@ -152,7 +152,8 @@ 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_file=ctx.params.get(log_file_option.name(), None))
             if log_level_option.name() in ctx.params:
                 CliLog.setLogLevels(ctx.params[log_level_option.name()])
         else:
@@ -316,8 +317,9 @@ 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()
 @ClickProgressHandler.option
-def cli(log_level, long_log, progress):
+def cli(log_level, long_log, log_file, 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

@@ -28,7 +28,7 @@
     lsstLog = None
 
 from lsst.daf.butler import ButlerMDC
-from ..core.logging import MDCDict
+from ..core.logging import MDCDict, JsonFormatter
 
 
 class PrecisionLogFormatter(logging.Formatter):
@@ -80,8 +80,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, log_file=None):
         """Initialize logging. This should only be called once per program
         execution. After the first call this will log a warning and return.
 
@@ -92,6 +96,11 @@ def initLog(cls, longlog):
         ----------
         longlog : `bool`
             If True, make log messages appear in long format, by default False.
+        log_file : `str`
+            Path to file to write log records. If ends in ``.json`` the
+            records will be written in JSON format. Else they will be written
+            in text format. If `None` 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
@@ -152,8 +161,22 @@ def record_factory(*args, **kwargs):
 
         logging.setLogRecordFactory(record_factory)
 
+        # Set up the file logger
+        if log_file:
+            handler = logging.FileHandler(log_file, delay=True)
+            if log_file.endswith(".json"):
+                formatter = JsonFormatter()
+            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_file))
 
     @classmethod
     def resetLog(cls):
@@ -177,6 +200,14 @@ def resetLog(cls):
             logger = logging.getLogger(componentSetting.component)
             logger.setLevel(componentSetting.pythonLogLevel)
         cls._setLogLevel(None, "INFO")
+
+        # 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,12 @@ def makeCollectionTypes(context, param, value):
                                     help="Make log messages appear in long format.",
                                     is_flag=True)
 
+log_file_option = MWOptionDecorator("--log-file",
+                                    default=None,
+                                    type=MWPath(file_okay=True, dir_okay=False, writable=True),
+                                    help="File to write log messages. If .json JSON log records will be"
+                                    " written. Else formatted text log records will be written."
+                                    " This file can exist and records will be appended.")
 
 options_file_option = MWOptionDecorator("--options-file", "-@",
                                         expose_value=False,  # This option should not be forwarded

python/lsst/daf/butler/tests/cliLogTestBase.py

@@ -32,10 +32,12 @@
 import re
 import subprocess
 import unittest
+import tempfile
 
 from lsst.daf.butler.cli.butler import cli as butlerCli
 from lsst.daf.butler.cli.cliLog import CliLog
 from lsst.daf.butler.cli.utils import clickResultMsg, command_test_env, LogCliRunner
+from lsst.daf.butler import ButlerLogRecords
 try:
     import lsst.log as lsstLog
 except ModuleNotFoundError:
@@ -196,6 +198,37 @@ def testLongLog(self):
                     self.assertTrue(startedWithModule,
                                     msg=f"did not find lines starting with module in: \n{output.getvalue()}")
 
+    def testFileLogging(self):
+        """Test --file-log option."""
+        with self.runner.isolated_filesystem():
+            for i, suffix in enumerate([".json", ".log"]):
+                # Get a temporary file name and immediately close it
+                fd = tempfile.NamedTemporaryFile(suffix=suffix)
+                filename = fd.name
+                fd.close()
+
+                args = ("--log-level", "DEBUG", "--log-file", filename, "create", f"here{i}")
+
+                result = self.runner.invoke(butlerCli, args)
+                self.assertEqual(result.exit_code, 0, clickResultMsg(result))
+
+                # Record to test. Test one in the middle that we know is
+                # a DEBUG message. The first message might come from
+                # python itself since warnings are redirected to log
+                # messages.
+                num = 4
+
+                if suffix == ".json":
+                    records = ButlerLogRecords.from_file(filename)
+                    self.assertEqual(records[num].levelname, "DEBUG", str(records[num]))
+                else:
+                    with open(filename) as fd:
+                        records = fd.readlines()
+                    self.assertIn("DEBUG", records[num], str(records[num]))
+                    self.assertNotIn("{", records[num], str(records[num]))
+
+                self.assertGreater(len(records), 5)
+
 
 if __name__ == "__main__":
     unittest.main()