Merge branch 'tickets/DM-27351' into master

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

@@ -28,14 +28,12 @@
 import yaml
 
 from .cliLog import CliLog
-from .opt import log_level_option
+from .opt import log_level_option, long_log_option
 from lsst.utils import doImport
 
 
 log = logging.getLogger(__name__)
 
-LONG_LOG_FLAG = "--long-log"
-
 
 class LoaderCLI(click.MultiCommand, abc.ABC):
     """Extends `click.MultiCommand`, which dispatches to subcommands, to load
@@ -122,9 +120,17 @@ def _setupLogging(self, ctx):
         """Init the logging system and config it for the command.
 
         Subcommands may further configure the log settings."""
-        CliLog.initLog(longlog=LONG_LOG_FLAG in ctx.params)
-        if log_level_option.name() in ctx.params:
-            CliLog.setLogLevels(ctx.params[log_level_option.name()])
+        if isinstance(ctx, click.Context):
+            CliLog.initLog(longlog=ctx.params.get(long_log_option.name(), False))
+            if log_level_option.name() in ctx.params:
+                CliLog.setLogLevels(ctx.params[log_level_option.name()])
+        else:
+            # This works around a bug in sphinx-click, where it passes in the
+            # click.MultiCommand instead of the context.
+            # https://github.com/click-contrib/sphinx-click/issues/70
+            CliLog.initLog(longlog=False)
+            logging.debug("The passed-in context was not a click.Context, could not determine --long-log or "
+                          "--log-level values.")
 
     @classmethod
     def getPluginList(cls):
@@ -301,9 +307,11 @@ def _cmdNameToFuncName(cls, commandName):
 
 @click.command(cls=ButlerCLI, context_settings=dict(help_option_names=["-h", "--help"]))
 @log_level_option()
-def cli(log_level):
+@long_log_option()
+def cli(log_level, long_log):
     # log_level is handled by get_command and list_commands, and is called in
-    # one of those functions before this is called.
+    # one of those functions before this is called. long_log is handled by
+    # setup_logging.
     pass
 
 

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

@@ -39,17 +39,44 @@
 
 
 class CliLog:
-    """Interface for managing python logging and lsst.log. Handles
-    initialization so that lsst.log is a handler for python logging.
+    """Interface for managing python logging and ``lsst.log``.
 
-    Handles log uninitialization, which allows command line interface code that
-    initializes logging to run unit tests that execute in batches, without
-    affecting other unit tests. """
+    .. warning::
+
+       When ``lsst.log`` is importable it is the primary logger, and
+       ``lsst.log`` is set up to be a handler for python logging - so python
+       logging will be processed by ``lsst.log``.
+
+    This class defines log format strings for the log output and timestamp
+    formats, for both ``lsst.log`` and python logging. If lsst.log is
+    importable then the ``lsstLog_`` format strings will be used, otherwise
+    the ``pylog_`` format strings will be used.
+
+    This class can perform log uninitialization, which allows command line
+    interface code that initializes logging to run unit tests that execute in
+    batches, without affecting other unit tests. See ``resetLog``."""
 
     defaultLsstLogLevel = lsstLog.FATAL if lsstLog is not None else None
 
-    longLogFmt = "%-5p %d{yyyy-MM-ddTHH:mm:ss.SSSZ} %c (%X{LABEL})(%F:%L)- %m%n"
-    normalLogFmt = "%c %p: %m%n"
+    lsstLog_longLogFmt = "%-5p %d{yyyy-MM-ddTHH:mm:ss.SSSZ} %c (%X{LABEL})(%F:%L)- %m%n"
+    """The log format used when the lsst.log package is importable and the log
+    is initialized with longlog=True."""
+
+    lsstLog_normalLogFmt = "%c %p: %m%n"
+    """The log format used when the lsst.log package is importable and the log
+    is initialized with longlog=False."""
+
+    pylog_longLogFmt = "%(levelname)s %(asctime)s %(name)s %(filename)s:%(lineno)s - %(message)s"
+    """The log format used when the lsst.log package is not importable and the
+    log is initialized with longlog=True."""
+
+    pylog_longLogDateFmt = "%Y-%m-%dT%H:%M:%S%z"
+    """The log date format used when the lsst.log package is not importable and
+    the log is initialized with longlog=True."""
+
+    pylog_normalFmt = "%(name)s %(levelname)s: %(message)s"
+    """The log format used when the lsst.log package is not importable and the
+    log is initialized with longlog=False."""
 
     _initialized = False
     _lsstLogHandler = None
@@ -83,7 +110,8 @@ def initLog(cls, longlog):
             # LSST_LOG_CONFIG exists. The file it points to would already
             # configure lsst.log.
             if not os.path.isfile(os.environ.get("LSST_LOG_CONFIG", "")):
-                lsstLog.configure_prop(_LOG_PROP.format(cls.longLogFmt if longlog else cls.normalLogFmt))
+                lsstLog.configure_prop(_LOG_PROP.format(
+                    cls.lsstLog_longLogFmt if longlog else cls.lsstLog_normalLogFmt))
             cls._recordComponentSetting(None)
             pythonLogger = logging.getLogger()
             pythonLogger.setLevel(logging.INFO)
@@ -92,7 +120,12 @@ def initLog(cls, longlog):
             pythonLogger.addHandler(cls._lsstLogHandler)
         else:
             cls._recordComponentSetting(None)
-            logging.basicConfig(level=logging.INFO)
+            if longlog:
+                logging.basicConfig(level=logging.INFO,
+                                    format=cls.pylog_longLogFmt,
+                                    datefmt=cls.pylog_longLogDateFmt)
+            else:
+                logging.basicConfig(level=logging.INFO, format=cls.pylog_normalFmt)
 
         # also capture warnings and send them to logging
         logging.captureWarnings(True)

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

@@ -27,7 +27,10 @@
 import click
 from collections import namedtuple
 from functools import partial
+from io import StringIO
 import logging
+import re
+import subprocess
 import unittest
 
 from lsst.daf.butler.cli.butler import cli as butlerCli
@@ -168,6 +171,69 @@ def test_helpLogReset(self):
 
         self.runTest(partial(self.runner.invoke, butlerCli, ["command-log-settings-test", "--help"]))
 
+    def testLongLog(self):
+        """Verify the timestamp is in the log messages when the --long-log
+        flag is set."""
+
+        # When longlog=True, loglines start with the log level and a
+        # timestamp with the following format:
+        # "year-month-day T hour-minute-second.millisecond-zoneoffset"
+        # If lsst.log is importable then the timestamp will have
+        # milliseconds, as described above. If lsst.log is NOT
+        # importable then milliseconds (and the preceding ".") are
+        # omitted (the python `time` module does not support
+        # milliseconds in its format string). Examples of expected
+        # strings follow:
+        # lsst.log:   "DEBUG 2020-10-29T10:20:31.518-0700 ..."
+        # pure python "DEBUG 2020-10-28T10:20:31-0700 ...""
+        # The log level name can change, we verify there is an all
+        # caps word there but do not verify the word. We do not verify
+        # the rest of the log string, assume that if the timestamp is
+        # in the string that the rest of the string will appear as
+        # expected.
+        # N.B. this test is defined in daf_butler which does not depend
+        # on lsst.log. However, CliLog may be used in packages that do
+        # depend on lsst.log and so both forms of timestamps must be
+        # supported. These packages should have a test (the file is
+        # usually called test_cliLog.py) that subclasses CliLogTestBase
+        # and unittest.TestCase so that these tests are run in that
+        # package.
+        timestampRegex = re.compile(
+            r".*[A-Z]+ [0-9]{4}-[0-9]{2}-[0-9]{2}T[0-9]{2}:[0-9]{2}:[0-9]{2}(.[0-9]{3})?([-,+][0-9]{4}|Z) .*")
+
+        # When longlog=False, log lines start with the module name and
+        # log level, for example:
+        # lsst.daf.butler.core.config DEBUG: ...
+        modulesRegex = re.compile(
+            r".* ([a-z]+\.)+[a-z]+ [A-Z]+: .*")
+
+        with self.runner.isolated_filesystem():
+            for longlog in (True, False):
+                # The click test does not capture logging emitted from lsst.log
+                # so use subprocess to run the test instead.
+                if longlog:
+                    args = ("butler", "--log-level", "DEBUG", "--long-log", "create", "here")
+                else:
+                    args = ("butler", "--log-level", "DEBUG", "create", "here")
+                result = subprocess.run(args, capture_output=True)
+                # There are cases where the newlines are stripped from the log
+                # output (like in Jenkins), since we can't depend on newlines
+                # in log output they are removed here from test output.
+                output = StringIO((result.stderr.decode().replace("\n", " ")))
+                startedWithTimestamp = any([timestampRegex.match(line) for line in output.readlines()])
+                output.seek(0)
+                startedWithModule = any(modulesRegex.match(line) for line in output.readlines())
+                if longlog:
+                    self.assertTrue(startedWithTimestamp,
+                                    msg=f"did not find timestamp in: \n{output.getvalue()}")
+                    self.assertFalse(startedWithModule,
+                                     msg=f"found lines starting with module in: \n{output.getvalue()}")
+                else:
+                    self.assertFalse(startedWithTimestamp,
+                                     msg=f"found timestamp in: \n{output.getvalue()}")
+                    self.assertTrue(startedWithModule,
+                                    msg=f"did not find lines starting with module in: \n{output.getvalue()}")
+
 
 if __name__ == "__main__":
     unittest.main()