DM-27351: --long-log does not work with butler command line command #408

n8pease · 2020-10-28T21:20:49Z

No description provided.

ktlim · 2020-10-28T21:36:50Z

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

-    normalLogFmt = "%c %p: %m%n"
+    lsstLog_longLogFmt = "%-5p %d{yyyy-MM-ddTHH:mm:ss.SSSZ} %c (%X{LABEL})(%F:%L)- %m%n"
+    lsstLog_normalLogFmt = "%c %p: %m%n"
+    pylog_longLogFmt = "%(asctime)s %(message)s"


You don't think it's a good idea to emulate the lsst.log format and include things like %(levelname) and %(name) or even %(filename) and %(lineno)?
asctime is in local time by default. We should either append timezone information (possibly by changing logging.Formatter.default_time_format) or use GMT/UTC consistently (possibly by changing logging.Formatter.converter). https://developer.lsst.io/stack/logging.html#logging

If you do use gmtime() to use GMT, you should make sure to include the "Z" timezone specifier in the format; it's more important that the timezone be clear than that any particular timezone be chosen.

this seems to work if it seems ok to you(?)

pylog_longLogFmt = "%(asctime)s %(message)s" ... logging.basicConfig(level=logging.INFO, format=cls.pylog_longLogFmt, datefmt="%Y-%m-%dT%H:%M:%S%z")

example output:

2020-10-28T22:07:49-0700 Opening YAML config file: resource://lsst.daf.butler/configs/registry.yaml 2020-10-28T22:07:49-0700 Opening YAML config file: resource://lsst.daf.butler/configs/storageClasses.yaml 2020-10-28T22:07:49-0700 Opening YAML config file: resource://lsst.daf.butler/configs/datastore.yaml

The only difference between this and the lsst.log output is that the time does not include milliseconds. As far as I can tell the time format string does not offer a milliseconds or microseconds option.

lsst.log example output

2020-10-28T22:05:43-0700 Opening YAML config file: resource://lsst.daf.butler/configs/registry.yaml 2020-10-28T22:05:43-0700 Opening YAML config file: resource://lsst.daf.butler/configs/storageClasses.yaml

That looks fine. My understanding is that the logging Formatter is what adds on milliseconds; we can probably do without it.

ktlim · 2020-10-28T21:39:24Z

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

@@ -92,7 +94,8 @@ def initLog(cls, longlog):
            pythonLogger.addHandler(cls._lsstLogHandler)
        else:
            cls._recordComponentSetting(None)
-            logging.basicConfig(level=logging.INFO)
+            logging.basicConfig(level=logging.INFO,
+                                **(dict(format=cls.pylog_longLogFmt if longlog else dict())))


The alternative with an if/else statement is only two lines longer and may be clearer.

@ktlim I'm not sure I really like any of the ways I've tried optionally passing a variable (or not). Can you show me the code you're thinking of?

Something simple like this:

if longlog: logging.basicConfig(level=logging.INFO, format=cls.pylog_longLogFmt) else: logging.basicConfig(level=logging.INFO)

timj · 2020-10-28T22:08:35Z

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

+        """Verify the timestamp is in the log messages when the --long-log
+        flag is set."""
+        with self.runner.isolated_filesystem():
+            # The click test does not capture logging emitted from lsst.log


Butler tests should never be issuing lsst.log log messages so lsstLog is only ever true if someone runs these tests after they've setup some other LSST package. Neither Jenkins nor GitHub Actions will ever have lsst.log available. I'm now a bit worried about these tests -- no code inside butler should ever be issuing an lsst.log log message so how do we ever see the change? Does python logging change in click subcommands based on lsst.log existing?

This test is run by test_cliClog.py in daf_butler as well as in test_cliLog.py in obs_base, so both variants are tested.

Can you help my future self by adding a comment here that says that this check is specifically because subclasses can enable lsst.log even if daf_butler does not use it?

timj

Looks fine. My main comment is my continual surprise that we always forward python logging to lsst.log but I can see that we have no choice.

timj · 2020-11-03T17:00:44Z

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

+            # 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 longlog or log"


maybe say long-log and log-level here to match the command line names?

timj · 2020-11-03T17:04:34Z

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

+        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


If the fix is as easy as you imply on that issue, please file a PR. You'll probably get more traction with a PR than an issue.

ok, I'll work on this.

timj · 2020-11-03T17:07:58Z

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

+    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


This is quite hard to understand without the hidden context below. Naively you would think that python logging should be configured regardless of lsst.log. Somehow we need to make it clearer that we actually bypass python logging if lsst.log is available -- not simply that we decide to use different log formats.

I will add to the class docstring about this.

timj · 2020-11-03T17:12:48Z

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

@@ -92,7 +110,12 @@ def initLog(cls, longlog):
            pythonLogger.addHandler(cls._lsstLogHandler)


This line is why you have so much trouble in your tests capturing log messages. We need to make it much more explicit in documentation (at least for this function) that this is going on. It is there but a sphinx warning might make it clearer. I keep forgetting we do this. The reason we can't go the other way round is that I have no way to forward the C++ log messages back to python.

timj · 2020-11-03T17:16:35Z

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

+                    args = ("butler", "--log-level", "DEBUG", "--long-log", "create", "here")
+                else:
+                    args = ("butler", "--log-level", "DEBUG", "create", "here")
+                result = subprocess.run(args, capture_output=True)


Does the normal click runner not work with lsst.log redirected to python logging? Maybe because one of the tests is using C++ logging? Or is it because click really is forking a subprocess and so logging can never be caught?

Click does not fork. It sets up its own isolation environment, see https://github.com/pallets/click/blob/master/src/click/testing.py#L172.
There's something about changing the logging configuration, or the way that we do it, that is incompatible with the way click does its isolation environment. I worked on it for a little while but didn't figure out much more than that, and using subprocess as a workaround for the log test seemed better than spending a ton of time on it. FWIW I've verified click.testing does capture python logging output if you don't mess with the log config.
If you want I can dig in more(?)

I mainly wanted to know if you had tried the suggested context manager that redirects lsst.log to python logging.

~~lsstLog.usePythongLogging() does allow click to capture the log output. Now, without using subprocesses I'm faced with the problem of re-initizliaing the logging system and new settings not taking.~~
I didn't have lsst.log importable. Still checking...

ok, more like I thought I remembered: logging even with usePythongLogging does not get captured by click.

surely python logging is always going to be captured by click? You mean the real problem is that click test runner drops log messages completely and doesn't capture them in any way? Okay, that is very funny.

When the default python log handler is used python logging gets captured by the click test runner. When we add the lsst.log.LogHandler to the python logger then no logging is captured by click, whether we call lsst.log.Log.usePythonLogging() or not. I can investigate it more if you want(?) but Fabio has poked me about getting this into the weekly so he can use it, so I'd like to do it on a different ticket. (let me know if you do want?)

Ok. Ignore this issue then. You have a solution and you understand what the problem is.

Also: Fix a bug found applying the long log option. Add a unit test.

There is a bug in sphinx-click that passes the MultiCommand into list_commands instead of the context. This works around that by not fetching log config out of the context if the context is not a click.Context instance.

Warn that lsst.log handles python logging when available. Describe when various formatter strings are chosen.

n8pease force-pushed the tickets/DM-27351 branch from 31e59e5 to acba8af Compare October 28, 2020 21:26

ktlim reviewed Oct 28, 2020

View reviewed changes

timj reviewed Oct 28, 2020

View reviewed changes

n8pease force-pushed the tickets/DM-27351 branch 6 times, most recently from 8c32999 to 31556ef Compare October 30, 2020 16:04

timj approved these changes Nov 3, 2020

View reviewed changes

n8pease force-pushed the tickets/DM-27351 branch 2 times, most recently from b99ceb9 to 2340b3a Compare November 4, 2020 20:44

n8pease added 6 commits November 4, 2020 14:02

add --long-log option to butler

d4fa8e8

Also: Fix a bug found applying the long log option. Add a unit test.

work around a bug in sphinx-click

5a86cce

There is a bug in sphinx-click that passes the MultiCommand into list_commands instead of the context. This works around that by not fetching log config out of the context if the context is not a click.Context instance.

don't depend on newlines in log output

5e0b8d5

allow the 'Z' UTC code

8236fed

make names match variable names

572f0b2

add CliLog documentation

f6ab362

Warn that lsst.log handles python logging when available. Describe when various formatter strings are chosen.

n8pease force-pushed the tickets/DM-27351 branch from 2340b3a to f6ab362 Compare November 4, 2020 22:02

n8pease merged commit 39b7668 into master Nov 4, 2020

timj deleted the tickets/DM-27351 branch February 16, 2024 17:17

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

DM-27351: --long-log does not work with butler command line command #408

DM-27351: --long-log does not work with butler command line command #408

n8pease commented Oct 28, 2020

ktlim Oct 28, 2020 •

edited

n8pease Oct 29, 2020

ktlim Oct 29, 2020

n8pease Oct 29, 2020

ktlim Oct 29, 2020

ktlim Oct 28, 2020

n8pease Oct 29, 2020

ktlim Oct 29, 2020 •

edited

timj Oct 28, 2020

n8pease Oct 29, 2020

timj Oct 29, 2020

timj left a comment

timj Nov 3, 2020

timj Nov 3, 2020

n8pease Nov 4, 2020

timj Nov 3, 2020

n8pease Nov 4, 2020

timj Nov 3, 2020

timj Nov 3, 2020

n8pease Nov 3, 2020 •

edited

timj Nov 3, 2020

n8pease Nov 4, 2020 •

edited

n8pease Nov 4, 2020

timj Nov 4, 2020

n8pease Nov 4, 2020

timj Nov 4, 2020

		@@ -92,7 +110,12 @@ def initLog(cls, longlog):
		pythonLogger.addHandler(cls._lsstLogHandler)

DM-27351: --long-log does not work with butler command line command #408

DM-27351: --long-log does not work with butler command line command #408

Conversation

n8pease commented Oct 28, 2020

ktlim Oct 28, 2020 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ktlim Oct 29, 2020 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

timj left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

n8pease Nov 3, 2020 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

n8pease Nov 4, 2020 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ktlim Oct 28, 2020 •

edited

ktlim Oct 29, 2020 •

edited

n8pease Nov 3, 2020 •

edited

n8pease Nov 4, 2020 •

edited