1021943 - mozlog.structured should have some additional features to help with general informational-level logging

Status: RESOLVED FIXED

(Testing :: Mozbase, defect)

Description

[William Lachance (:wlach)]

mozlog.structured works great right now for gathering together collections of test results, but it's a bit inconvenient for informational logging in other parts of the harness. For example, in mozdevice we want to log various things that we're doing when interacting with the device. There's many places we might want to do this, and it's a bit inconvenient to have to pass the main structured logger everywhere we want to do this. Following the same example, it would also be useful for informational purposes to be able to tag the "component" where these messages are coming from.

As discussed on irc, we could probably solve most of these problems by setting a "default" logger in the commandline processor and then making that accessible via a message called get_default_logger. For the case of tagging log messages with a component value, this can be easily done with an extension to the StructuredLog class.

Comment 1

[William Lachance (:wlach)]

Attachment: Initial try for a patch

Here's an initial attempt at a patch. I only made a preliminary attempt at documentation, I would add more before committing this. Here's an example using the new api's:

argparse
import sys

from mozlog.structured import structuredlog, commandline, get_default_logger

parser = argparse.ArgumentParser()
commandline.add_logging_group(parser)

args = parser.parse_args()
logger = commandline.setup_logging("structured-example", args, {"raw": sys.stdout})
logger2 = get_default_logger(component="t2")

logger.info("Running tests")
logger2.info("Doing stuff")

Output:

{"source": "structured-example", "thread": "MainThread", "time": 1402087571521, "action": "log", "message": "Running tests", "level": "INFO", "pid": 29152}
{"thread": "MainThread", "level": "INFO", "component": "t2", "pid": 29152, "source": "structured-example", "time": 1402087571521, "action": "log", "message": "Doing stuff"}

Comment 2

[James Graham [:jgraham]]

Comment on attachment 8436070 [details] [diff] [review]
Initial try for a patch

Review of attachment 8436070 [details] [diff] [review]:
-----------------------------------------------------------------

I think this looks fine. You might also want to update the formatter to use component.

Comment 3

[James Graham [:jgraham]]

Although thinking about it I wonder why we don't just store the logger name in _default_logger rather than a particular instance.

Comment 4

[Chris Manchester (limited bugmail, email directly)]

Comment on attachment 8436070 [details] [diff] [review]
Initial try for a patch

Review of attachment 8436070 [details] [diff] [review]:
-----------------------------------------------------------------

::: testing/mozbase/mozlog/mozlog/structured/structuredlog.py
@@ +61,5 @@
> +    name. Will return None if not yet set
> +
> +    :param component: The component name to tag log messages with
> +    """
> +    global _default_logger

I guess you only need the global statement when assigning to the variable, but I like this because it makes it more explicit.

@@ +116,5 @@
>      def _log_data(self, action, data=None):
>          if data is None:
>              data = {}
> +        if self.component:
> +            data['component'] = self.component

Some logging libraries have an idea of hierarchical names, which would make the "source" field in the example "structured-example.t2". This is nice because "source" and "component" seem to share a purpose in the sample output. But I suppose the point of this is that this callee doesn't know the caller logger's name, so this doesn't work for this case.

I agree we should consider storing just the name as a global.

Comment 5

[William Lachance (:wlach)]

Attachment: Updated patch

This patch has several differences from previous

1. Updated documentation bits
2. Now storing name internally instead of actual logger
3. Added some stuff to the formatters to include the subcomponent name

Comment 6

[Chris Manchester (limited bugmail, email directly)]

Comment on attachment 8437913 [details] [diff] [review]
Updated patch

Review of attachment 8437913 [details] [diff] [review]:
-----------------------------------------------------------------

I found an instance today where this would have been nice to have. I think this could reduce the boilerplate involved with converting to structured logging significantly.

::: testing/mozbase/mozlog/mozlog/structured/structuredlog.py
@@ +65,5 @@
> +    """
> +    global _default_logger_name
> +
> +    if not _default_logger_name:
> +        return None

Maybe throw an exception? Or supply one? "default" might make me think I get one for free.

Comment 7

[James Graham [:jgraham]]

Comment on attachment 8437913 [details] [diff] [review]
Updated patch

Review of attachment 8437913 [details] [diff] [review]:
-----------------------------------------------------------------

Looks like it will be fine once the code to set component is moved to the right place.

Please don't change the behaviour of get_default_logger; the return value of None is useful when a library is used in both structured and unstructured contexts.

::: testing/mozbase/mozlog/mozlog/structured/structuredlog.py
@@ +117,4 @@
>      def _log_data(self, action, data=None):
>          if data is None:
>              data = {}
> +        if self.component:

This should go in _make_log_data where all the other defaults are set.

Comment 8

[William Lachance (:wlach)]

Attachment: Updated patch with jgraham's suggested change, carrying forward r+

Comment 9

[James Graham [:jgraham]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/9a188d035eee

Comment 10

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/9a188d035eee