Closed Bug 1021943 Opened 8 years ago Closed 7 years ago

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


(Testing :: Mozbase, defect)

Not set


(Not tracked)



(Reporter: wlach, Assigned: wlach)




(1 file, 2 obsolete files)

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.
Attached patch Initial try for a patch (obsolete) — Splinter Review
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:

import sys

from mozlog.structured import structuredlog, commandline, get_default_logger

parser = argparse.ArgumentParser()

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


{"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"}
Attachment #8436070 - Flags: feedback?(james)
Attachment #8436070 - Flags: feedback?(cmanchester)
Blocks: 1021880
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.
Attachment #8436070 - Flags: feedback?(james) → feedback+
Although thinking about it I wonder why we don't just store the logger name in _default_logger rather than a particular instance.
Comment on attachment 8436070 [details] [diff] [review]
Initial try for a patch

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

::: testing/mozbase/mozlog/mozlog/structured/
@@ +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.
Attachment #8436070 - Flags: feedback?(cmanchester) → feedback+
Attached patch Updated patch (obsolete) — Splinter Review
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
Attachment #8436070 - Attachment is obsolete: true
Attachment #8437913 - Flags: review?(james)
Attachment #8437913 - Flags: feedback?(cmanchester)
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/
@@ +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.
Attachment #8437913 - Flags: feedback?(cmanchester) → feedback+
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/
@@ +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.
Attachment #8437913 - Flags: review?(james) → review+
Closed: 7 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla33
You need to log in before you can comment on or make changes to this bug.