956738 - Add structuredlogging to mozlog

Status: RESOLVED FIXED

(Testing :: Mozbase, defect)

Description

[James Graham [:jgraham]]

The structured logging format developed in bug 916260 should become part of mozlog. The code needs to be factored out of the patch in bug 945222.

Comment 1

[James Graham [:jgraham]]

Attachment: Work in progress

Attached a patch in a state where it is useful for people to look at. This adds structured logging to mozlog, formatters for producing raw JSON, unittest style (not quite right yet), xUnit style (has some issues with name vs classname) and marionette HTML report style (no stylesheets) output. To try it out apply the marionette patch in bug 956739 and run |mach marionette-tests| (--help to get the logging options).

Comment 2

[:Ms2ger (he/him; ⌚ UTC+1/+2)]

Comment on attachment 8361095 [details] [diff] [review]
Work in progress

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

MPL headers everywhere!

::: testing/mozbase/mozlog/mozlog/structured/formatters/pyxml.py
@@ +1,5 @@
> +"""
> +module for generating and serializing xml and html structures
> +by using simple python objects.
> +
> +(c) holger krekel, holger at merlinux eu. 2009

Looks fishy

Comment 3

[James Graham [:jgraham]]

(In reply to :Ms2ger from comment #2)
> Comment on attachment 8361095 [details] [diff] [review]
> Work in progress
> 
> Review of attachment 8361095 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> MPL headers everywhere!

I know, I know :p

> ::: testing/mozbase/mozlog/mozlog/structured/formatters/pyxml.py
> @@ +1,5 @@
> > +"""
> > +module for generating and serializing xml and html structures
> > +by using simple python objects.
> > +
> > +(c) holger krekel, holger at merlinux eu. 2009
> 
> Looks fishy

Yeah so that's already in the tree for marionette. It seems nicer to me to not have that in-tree, which should be possible given that mach understands virtualenv. I can probably make it install that module iff you pass in a --format-html= flag (non-mach users are of course responsible for their own environment containing all the packages they need).

Comment 4

[James Graham [:jgraham]]

Attachment: Work in progress

Updated patch with license headers and support for mach-like logging.

Comment 5

[James Graham [:jgraham]]

I need a better filename than "logging" since that clashes with the stdlib. mozlog uses "logger", but that's a nice variable name. Anyone got a favourite colour for this particular bikeshed?

Comment 6

[(not currently active) Ted Mielczarek]

Just call it structuredlogging or structured and deal with the redundancy.

Comment 7

[Andrew Halberstadt [:ahal]]

Comment on attachment 8362612 [details] [diff] [review]
Work in progress

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

This is really cool!

I'm a little too out of it to grasp the big picture from a splinter review, but from what I can tell you seem to be on the right track. Sorry for not having much feedback on the actual API, I think I'd need to see some examples of how this would be used before I can comment on that.

::: testing/mozbase/mozlog/mozlog/structured/__init__.py
@@ +2,5 @@
> +# License, v. 2.0. If a copy of the MPL was not distributed with this
> +# file, You can obtain one at http://mozilla.org/MPL/2.0/.
> +
> +import commandline
> +import logger

I hadn't really thought of creating a separate structured submodule, I thought everything would log structured and we would provide a plain-text formatter. Your way could make the transition faster though.

::: testing/mozbase/mozlog/mozlog/structured/commandline.py
@@ +4,5 @@
> +
> +import argparse
> +import sys
> +
> +import logging

re: namespace collision. Pretty much what ted said. As long as it isn't this as it isn't this :)

@@ +32,5 @@
> +        group.add_argument("--log-" + name, type=log_file,
> +                           help=help_str)
> +
> +
> +def setup_logging(name, args, defaults):

Not really clear how this is supposed to be used, still WIP?

::: testing/mozbase/mozlog/mozlog/structured/formatters/__init__.py
@@ +5,5 @@
> +import json
> +from unittest import UnittestFormatter
> +from xunit import XUnitFormatter
> +from html import HTMLFormatter
> +from machformatter import MachFormatter, MachTerminalFormatter

nit: shouldn't this just be mach.py? None of the others have formatter appended to their file names.

::: testing/mozbase/mozlog/mozlog/structured/formatters/html.py
@@ +19,5 @@
> +def do_defered_imports():
> +    global html
> +    global raw
> +
> +    from pyxml import html, raw

Deferring this will solve problems in automation, but since we can't add it to setup.py, we might get some confused consumers wondering why --log-html isn't working. Maybe pyxml is check-in to tree worthy.

::: testing/mozbase/moztest/moztest/__init__.py
@@ +1,1 @@
> +import adapters

nit: license

::: testing/mozbase/moztest/moztest/adapters/unit.py
@@ +20,5 @@
> +            if info is not None:
> +                debug_info.update(info)
> +        return debug_info
> +
> +    def startTestRun(self):

nit: use underscores instead of camelcase throughout this file

Comment 8

[James Graham [:jgraham]]

Attachment: bug956738.diff

Comment 9

[James Graham [:jgraham]]

Attachment: bug956739.diff

Comment 10

[James Graham [:jgraham]]

(In reply to Andrew Halberstadt [:ahal] from comment #7)

> This is really cool!
> 
> I'm a little too out of it to grasp the big picture from a splinter review,
> but from what I can tell you seem to be on the right track. Sorry for not
> having much feedback on the actual API, I think I'd need to see some
> examples of how this would be used before I can comment on that.

So, if you need to try it out bug 956739 has a patch that converts Marionette to use structured logging. I'm not sure how much of an insight that gives into the internal API however since it just uses the adapter here.
 
> ::: testing/mozbase/mozlog/mozlog/structured/__init__.py
> @@ +2,5 @@
> > +# License, v. 2.0. If a copy of the MPL was not distributed with this
> > +# file, You can obtain one at http://mozilla.org/MPL/2.0/.
> > +
> > +import commandline
> > +import logger
> 
> I hadn't really thought of creating a separate structured submodule, I
> thought everything would log structured and we would provide a plain-text
> formatter. Your way could make the transition faster though.

I feel like I might be boiling enough ocean already; making this opt-in at first seems much easier and allows more breaking changes.

> ::: testing/mozbase/mozlog/mozlog/structured/commandline.py
> @@ +4,5 @@
> > +
> > +import argparse
> > +import sys
> > +
> > +import logging
> 
> re: namespace collision. Pretty much what ted said. As long as it isn't this
> as it isn't this :)

Changed to structuredlog.

> @@ +32,5 @@
> > +        group.add_argument("--log-" + name, type=log_file,
> > +                           help=help_str)
> > +
> > +
> > +def setup_logging(name, args, defaults):
> 
> Not really clear how this is supposed to be used, still WIP?

The idea is that you call this with the name of your testsuite, the arguments object you got from argparse and some defaults if no arguments were supplied, and it will set up the formatters for you. Needs some documentation, obviously.

> ::: testing/mozbase/mozlog/mozlog/structured/formatters/__init__.py
> @@ +5,5 @@
> > +import json
> > +from unittest import UnittestFormatter
> > +from xunit import XUnitFormatter
> > +from html import HTMLFormatter
> > +from machformatter import MachFormatter, MachTerminalFormatter
> 
> nit: shouldn't this just be mach.py? None of the others have formatter
> appended to their file names.

Possibly the others should have formatter in their names :) This was to avoid a clash with the mach module that you can import when running under mach. I don't think it's super-important, but a little less ambiguity is good.
 
> ::: testing/mozbase/mozlog/mozlog/structured/formatters/html.py
> @@ +19,5 @@
> > +def do_defered_imports():
> > +    global html
> > +    global raw
> > +
> > +    from pyxml import html, raw
> 
> Deferring this will solve problems in automation, but since we can't add it
> to setup.py, we might get some confused consumers wondering why --log-html
> isn't working. Maybe pyxml is check-in to tree worthy.

Yeah, maybe. I was thinking of solving it for the mach case at least by installing pyxml into the virtualenv iff the --log-html option is enabled.

> ::: testing/mozbase/moztest/moztest/adapters/unit.py
> @@ +20,5 @@
> > +            if info is not None:
> > +                debug_info.update(info)
> > +        return debug_info
> > +
> > +    def startTestRun(self):
> 
> nit: use underscores instead of camelcase throughout this file

This has to match the API of the python unittest module, which uses camel case.

Comment 11

[James Graham [:jgraham]]

Attachment: bug956738.diff

Requesting review to get the ball rolling. I will add some tests, but I think what's there already is in a state where doing review is sensible.

Comment 12

[James Graham [:jgraham]]

Attachment: bug956738.diff

Add some testcases, fix some bugs, add some more documentation.

Comment 13

[Andrew Halberstadt [:ahal]]

Comment on attachment 8368530 [details] [diff] [review]
bug956738.diff

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

r+ with review comments addressed. Also, how will this play with chmanchester's structured logging stuff he implemented in logger.py etc..? I'm assuming this will replace it rather than integrate with it?

::: testing/mozbase/mozlog/mozlog/structured/commandline.py
@@ +30,5 @@
> +    Add logging options to an argparse ArgumentParser.
> +
> +    Each formatter has a corresponding option of the form --log-{name}
> +    where {name} is the name of the formatter. The option takes a value
> +    which is either a filename or "-" to insdicate stdout.

typo: indicate

@@ +45,5 @@
> +        group.add_argument("--log-" + name, type=log_file,
> +                           help=help_str)
> +
> +
> +def setup_logging(name, args, defaults):

nit: name collides with the three for loops below, maybe this should be 'suite' or something?

::: testing/mozbase/mozlog/mozlog/structured/formatters/html.py
@@ +42,5 @@
> +            html.meta(charset="utf-8"),
> +            html.title(data["source"]),
> +            html.style(
> +#                raw(pkg_resources.resource_string(
> +#                    __name__, os.path.sep.join(['resources', 'htmlreport', 'style.css'])))

Why are these commented out?

@@ +129,5 @@
> +            self.head,
> +            html.body(
> +                html.script(
> +                    #raw(pkg_resources.resource_string(
> +                    #__name__, os.path.sep.join(['resources', 'htmlreport', 'jquery.js']))),

Likewise

@@ +133,5 @@
> +                    #__name__, os.path.sep.join(['resources', 'htmlreport', 'jquery.js']))),
> +                    ),
> +                html.script(
> +                    #raw(pkg_resources.resource_string(
> +                    #__name__, os.path.sep.join(['resources', 'htmlreport', 'main.js']))),

Likewise

::: testing/mozbase/mozlog/mozlog/structured/formatters/machformatter.py
@@ +10,5 @@
> +def get_test_id(data):
> +    test_id = data["test"]
> +    if isinstance(test_id, list):
> +        test_id = tuple(test_id)
> +    return test_id

Why is this a module level function?

::: testing/mozbase/mozlog/mozlog/structured/reader.py
@@ +8,5 @@
> +
> +    :param log_f: file-like object containing the log enteries, one per line"""
> +    for line in log_f:
> +        try:
> +            yield json.loads(line)

Need to import json

@@ +10,5 @@
> +    for line in log_f:
> +        try:
> +            yield json.loads(line)
> +        except ValueError:
> +            print line

Not yield?

::: testing/mozbase/mozlog/mozlog/structured/structuredlog.py
@@ +69,5 @@
> +
> +        :param name: The name of the logger.
> +        """
> +        self.name = name
> +        self._level = log_levels["DEBUG"]

I thought we weren't going to bother with log levels or something. Anyway, if we're doing this, don't we need some sort of set_level function?

@@ +84,5 @@
> +    @property
> +    def handlers(self):
> +        """Get a list of handlers that will be called when a
> +        message is logged from this logger"""
> +        return self._handlers[self.name]

Why is handlers a dict instead of a list? Isn't a StructuredLogger instance only ever associated with a single name?

@@ +123,5 @@
> +        :param test: Identifier of the test that will run.
> +        """
> +        self._log_data("test_start", {"test": test})
> +
> +    def test_status(self, test, subtest, status, expected="PASS", message=None):

The module docstring says this is called test_result. Not sure which one you meant it to be called, I'm fine with either.

@@ +159,5 @@
> +        :param message: String containing a message associated with the result.
> +        :param extra: suite-specific data associated with the test result.
> +        """
> +        if status.upper() not in ["PASS", "FAIL", "OK", "ERROR", "TIMEOUT",
> +                                  "CRASH", "ASSERT", "SKIP"]:

What's the difference between PASS and OK? I think if we have the opportunity to enforce a particular standard on our harnesses we should do it.

@@ +179,5 @@
> +        :param process: A unique identifier for the process producing the output
> +                        (typically the pid)
> +        :param data: The output to log
> +        :param command: A string representing the full command line used to start
> +                        the process.

I wonder if eventually we could accept a reference to a mozprocess object here and extract the pid and command ourselves. This is good for now though.

@@ +234,5 @@
> +
> +_wrapper_cls = None
> +
> +
> +def std_logging_adapter(logger):

Maybe this should go under 'adapters'?

@@ +244,5 @@
> +    """
> +    global _wrapper_cls
> +    import logging
> +
> +    if _wrapper_cls is not None:

nit: can just be if _wrapper_cls

::: testing/mozbase/mozlog/tests/test_structured.py
@@ +3,5 @@
> +import time
> +import unittest
> +import StringIO
> +
> +sys.path.insert(0, "../")

I don't think this is necessary. All the other unittests require mozbase be installed on the system anyway.

Comment 14

[James Graham [:jgraham]]

(In reply to Andrew Halberstadt [:ahal] from comment #13)

> @@ +10,5 @@
> > +    for line in log_f:
> > +        try:
> > +            yield json.loads(line)
> > +        except ValueError:
> > +            print line
> 
> Not yield?

In general it should be an error is a line doesn't decode as JSON. If we wanted to apply this to files where that wasn't the case, e.g. mixed structured/unstructured logs then returning the value along with an indicator of whether the line was structured or unstructured might be OK. As it is, I think the right approach might be to optionally propagate the error upwards.
 
> ::: testing/mozbase/mozlog/mozlog/structured/structuredlog.py
> @@ +69,5 @@
> > +
> > +        :param name: The name of the logger.
> > +        """
> > +        self.name = name
> > +        self._level = log_levels["DEBUG"]
> 
> I thought we weren't going to bother with log levels or something. Anyway,
> if we're doing this, don't we need some sort of set_level function?

I'm not especially attached to log levels. But maybe it makes sense to have a generic filter than cen be used to remove some messages before they reach the handler? Otherwise we could find that we are overrun by information (wpt on cedar is already complaining that the logs are too big).
 
> @@ +84,5 @@
> > +    @property
> > +    def handlers(self):
> > +        """Get a list of handlers that will be called when a
> > +        message is logged from this logger"""
> > +        return self._handlers[self.name]
> 
> Why is handlers a dict instead of a list? Isn't a StructuredLogger instance
> only ever associated with a single name?

No. The design at the moment is that you can create StructuredLoggers like normal objects, but those with the same name share the same handlers. This is an alternative to the whole getLogger(name) thing and trying to share the same logger object that I think makes the end-user code slightly more natural. Of course you can still run into problems if you try and attach the "same" handler to the logger multiple times, or rather different handler instances that do the same kind of thing, but I don't really see how to avoid that.

> @@ +159,5 @@
> > +        :param message: String containing a message associated with the result.
> > +        :param extra: suite-specific data associated with the test result.
> > +        """
> > +        if status.upper() not in ["PASS", "FAIL", "OK", "ERROR", "TIMEOUT",
> > +                                  "CRASH", "ASSERT", "SKIP"]:
> 
> What's the difference between PASS and OK? I think if we have the
> opportunity to enforce a particular standard on our harnesses we should do
> it.

The difference between "PASS" and "OK" is related to tests that have subtests vs those that don't. Where tests don't have subtests, we produce 0 test_status messages and a single test_end message with the result of the test (PASS, FAIL, etc.). Where a test type can have subtests we produce one test_status per subtest that completed and a test_end where the status tells us whether the overall tests ran to completion. In this latter case the possible statuses are OK, ERROR, TIMEOUT, CRASH, but not PASS or FAIL.

> @@ +179,5 @@
> > +        :param process: A unique identifier for the process producing the output
> > +                        (typically the pid)
> > +        :param data: The output to log
> > +        :param command: A string representing the full command line used to start
> > +                        the process.
> 
> I wonder if eventually we could accept a reference to a mozprocess object
> here and extract the pid and command ourselves. This is good for now though.

Sounds like a great idea.
 
> @@ +244,5 @@
> > +    """
> > +    global _wrapper_cls
> > +    import logging
> > +
> > +    if _wrapper_cls is not None:
> 
> nit: can just be if _wrapper_cls

FWIW I prefer explicit comparisons to None because I'm comparing to a specific sentinal, not comparing for general falsiness.

> ::: testing/mozbase/mozlog/tests/test_structured.py
> @@ +3,5 @@
> > +import time
> > +import unittest
> > +import StringIO
> > +
> > +sys.path.insert(0, "../")
> 
> I don't think this is necessary. All the other unittests require mozbase be
> installed on the system anyway.

I haven't worked out how you run the mozbase unittests though, so I currently need this to test it ;)

Comment 15

[James Graham [:jgraham]]

Attachment: bug956738.diff

Updated for review comments. Moved js and css files to be included inline in generated report file and removed jquery dependency for greater portability.

Comment 16

[James Graham [:jgraham]]

(In reply to Andrew Halberstadt [:ahal] from comment #13)

> @@ +234,5 @@
> > +
> > +_wrapper_cls = None
> > +
> > +
> > +def std_logging_adapter(logger):
> 
> Maybe this should go under 'adapters'?

I didn't change this because putting something purely about logging in moztest seems very odd.

Comment 17

[Andrew Halberstadt [:ahal]]

Comment on attachment 8370051 [details] [diff] [review]
bug956738.diff

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

Ah, I didn't notice adapters.py was part of moztest.

Looks good, ship it!

Comment 18

[Andrew Halberstadt [:ahal]]

Landed on github:
https://github.com/mozilla/mozbase/commit/bd9f199ea4b682e3636e877f6eac6797c588b7da