Enable stderr logging if JUJU_DEBUG is set. #209

jameinel · 2020-04-02T08:38:20Z

When running under 'juju debug-hooks' JUJU_DEBUG is set, which we can
use to detect that we should also print to stderr, so that people
interactively running the charm can see what is going on. It also
changes the default log level to DEBUG (though juju-log is still at
INFO).

This should address #200.

I chose to include the log level, and went with right-aligned, and fixed width so the messages end up left aligned. I don't terribly care, if people prefer a different format, this is all stderr, so it didn't make sense to me to include timestamps, etc. I also considered including the logger name, and/or file/line. Since it is stderr, I didn't want to overwhelm the output, but I'm flexible.

When running under 'juju debug-hooks' JUJU_DEBUG is set, which we can use to detect that we should also print to stderr, so that people interactively running the charm can see what is going on. It also changes the default log level to DEBUG (though juju-log is still at INFO).

jameinel · 2020-04-02T09:00:11Z

I feel like it might be a little odd to have lines starting with whitespace in stderr, but I do really like aligned content, I personally find it a lot easier to read. We could left align and have

DEBUG   this is the message
WARNING  another message
CRITICAL the most important

Or we could just say that messages at a similar level will likely be emitted together (and so would naturally be aligned). The one caveat in my experience is INFO and DEBUG tend to alternate quite frequently.

facundobatista

Nice work! I added a couple of inline comments, some suggestions and a couple of change requests.

Thanks!!

ops/log.py

ops/main.py

facundobatista · 2020-04-03T13:22:17Z

test/test_log.py

@@ -80,6 +86,32 @@ def test_handler_filtering(self):
        logger.warning('bar')
        self.assertEqual(self.backend.calls(), [('WARNING', 'bar')])

+    def test_debug_logging(self):
+        buffer = io.StringIO()
+        ops.log.setup_root_logging(self.backend, debug=True, debug_stream=buffer)


Check test_infra.py, l.43, for an easy way to test if something went to stdout/stderr.

As a general guideline I'm much more in favor of code and tests that do dependency injection rather than patching a global object. (You can never run the latter in parallel, and if you ever make a mistake cleaning up you break other tests that are hard to debug.)
I can happily pass sys.stderr from where this is called if you feel it should be exercised live.

we could actually do it differently where we set debug_stream only when debug is true, and then take out the extra argument. So something like:

debug_stream = None if 'JUJU_DEBUG' in os.environ: debug_stream = sys.stderr ops.log.setup_root_logging(self.backend, debug_stream=debug_stream)

That makes it an active parameter, and makes it easier to test.

This makes it easier to test, and contains the same amount of logic.

facundobatista · 2020-04-06T19:11:46Z

I feel like the previous version of the branch was more clear: if the envvar is set, the logging setup is indicated to go to debug mode, which means two decisions that belongs to the logging setup:

logger in debug level
also a handler to stderr

Now it feels mixed, it looks like which stream is decided outside the logging setup, and that stream is indicated to the logging setup, which when present, not only builds a handler for it (it's fine there) but also changes the level of the logger.

Note that the logger can NOT have always the level in DEBUG, as this is what controls the developer; by default it's in INFO, they can switch it if want to produce a more verbose logging.

Remember that the default output for the charm needs to be INFO level, and the juju handler will be in DEBUG, see this related issue (you may include a fix for it here, or not, but it needs to be considered for the final behaviour as a whole).

niemeyer

Just some trivials.. LGTM when you and @facundobatista are happy.

niemeyer · 2020-04-08T08:21:32Z

ops/log.py

+    """Setup python logging to forward messages to juju-log.
+
+    :param model_backend: a ModelBackend to use for juju_log.
+    :param debug_stream: (optional) If set, debug messages will also be sent to this stream.


The "(optional)" and "If set," are redundant.

Is "(optional)" a standard/agreed way to specify that? If so, sounds good, otherwise we should either try to agree on that or drop it and allow the sentence to describe it.

Since you raise the question, Sphinx seems to say that you should put , optional into the type:
https://sphinx-rtd-tutorial.readthedocs.io/en/latest/docstrings.html
And ', defaults to' into the string description.

niemeyer · 2020-04-08T08:24:18Z

ops/main.py

@@ -174,7 +174,10 @@ def main(charm_class):
        juju_event_name = '{}_action'.format(juju_event_name)

    model_backend = ops.model.ModelBackend()
-    setup_root_logging(model_backend)
+    debug_stream = None
+    if 'JUJU_DEBUG' in os.environ:


Should we check its value (can it be both 1 or 0)?

it is actually set to a path where the execution for the debug session exist ("/tmp/juju-debug-XXXX/"). So it isn't a simple boolean, it is just a variable I'm sure is only set during debug-hooks or debug-code.
I had been doing:
if os.getenv('JUJU_DEBUG'):

which would cater for JUJU_DEBUG='', though Juju itself would never set it to that.

The handler and where it goes is set by the logging infrastructure. In testing we just patch sys.stderr to read the output.

facundobatista

Great work, thanks!!!

Added a couple of small comments inside.

I'm approving the PR, but PLEASE check the comment in the test section.

Thanks!!!

facundobatista · 2020-04-13T11:40:11Z

ops/log.py

+    if debug:
+        level = logging.DEBUG
+    else:
+        level = logging.INFO


This is fine, but remember you can always write level = logging.DEBUG if debug else logging.INFO

I do realize that newer python has the Ternary operator, but I don't find that it is actually easier to read. The problem is that (foo if blah else bing) doesn't have great punctuation to clarify what the result is. I suppose the 2 possibilities are at the very beginning or the very end.

facundobatista · 2020-04-13T11:41:06Z

ops/main.py

@@ -174,7 +174,8 @@ def main(charm_class):
        juju_event_name = '{}_action'.format(juju_event_name)

    model_backend = ops.model.ModelBackend()
-    setup_root_logging(model_backend)
+    debug = ('JUJU_DEBUG' in os.environ)


This is fine if it's more clear to you, but parenthesis surrounding the expression are not really needed.

So it is, very much, for clarity rather than need.

foo = 'string' more stuff

looks like the result is a string to me.

facundobatista · 2020-04-13T11:43:24Z

test/test_log.py

+                r"\d\d\d\d-\d\d-\d\d \d\d:\d\d:\d\d,\d\d\d DEBUG    debug message\n")
+            logger.info('info message')
+            logger.warning('warning message')
+            logger.critical('critical message')


Any patching should be done around as less code as possible (similar to try/except code blocks).

So, the subsequent assertEqual and assertRegex should be de-indented.

The subsequent ones aren't in the with statement. And all the logging needs to happen inside the with statement.

That said, it doesn't mean a lot to assert the debug statement before doing the rest, so I moved all of the logging inside, and have only the final asserts.

Addresses canonical#200 When running under 'juju debug-hooks' JUJU_DEBUG is set, which we can use to detect that we should also print to stderr, so that people interactively running the charm can see what is going on. It also changes the default log level to DEBUG (though juju-log is still at currently at INFO).

facundobatista suggested changes Apr 3, 2020

View reviewed changes

jameinel added 2 commits April 5, 2020 15:59

Drop the debug flag in favor of just debug_stream.

d995303

This makes it easier to test, and contains the same amount of logic.

include asctime in the log messages

5f50b14

niemeyer approved these changes Apr 8, 2020

View reviewed changes

jameinel added 3 commits April 8, 2020 16:49

Use the type to indication optional parameters.

f8fbc54

Merge master into extra-logging

479c121

Switch back to 'debug=bool' for logging.

45d19ac

The handler and where it goes is set by the logging infrastructure. In testing we just patch sys.stderr to read the output.

facundobatista approved these changes Apr 13, 2020

View reviewed changes

Remove the asserts that are inside the patched section.

5c4911b

jameinel merged commit ac86de8 into canonical:master Apr 13, 2020

jameinel mentioned this pull request Apr 13, 2020

Install stderr log handler when running under debug-hooks #200

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Enable stderr logging if JUJU_DEBUG is set. #209

Enable stderr logging if JUJU_DEBUG is set. #209

jameinel commented Apr 2, 2020

jameinel commented Apr 2, 2020 •

edited

facundobatista left a comment

facundobatista Apr 3, 2020

jameinel Apr 4, 2020 •

edited

facundobatista commented Apr 6, 2020

niemeyer left a comment

niemeyer Apr 8, 2020

jameinel Apr 8, 2020

niemeyer Apr 8, 2020

jameinel Apr 8, 2020

facundobatista left a comment

facundobatista Apr 13, 2020

jameinel Apr 13, 2020

facundobatista Apr 13, 2020

jameinel Apr 13, 2020

facundobatista Apr 13, 2020

jameinel Apr 13, 2020

Enable stderr logging if JUJU_DEBUG is set. #209

Enable stderr logging if JUJU_DEBUG is set. #209

Conversation

jameinel commented Apr 2, 2020

jameinel commented Apr 2, 2020 • edited

facundobatista left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jameinel Apr 4, 2020 • edited

Choose a reason for hiding this comment

facundobatista commented Apr 6, 2020

niemeyer 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

facundobatista 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

jameinel commented Apr 2, 2020 •

edited

jameinel Apr 4, 2020 •

edited