mozlog.structured should suppress debug output by default

RESOLVED FIXED in mozilla34

Status

Testing
Mozbase
RESOLVED FIXED
4 years ago
4 years ago

People

(Reporter: chmanchester, Assigned: chmanchester)

Tracking

unspecified
mozilla34
x86
Mac OS X
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(Not tracked)

Details

Attachments

(1 attachment, 4 obsolete attachments)

(Assignee)

Description

4 years ago
bug 1026710 added debug output to mozlog.structure's default logger. I just noticed a log on a recent try run with my patch for bug 1033126 that logs were truncated due to this.

The run:

https://tbpl.mozilla.org/?tree=Try&rev=47a5314dde6e

The log:

https://tbpl.mozilla.org/php/getParsedLog.php?id=44619430&tree=Try&full=1#error1

We discussed this a bit on IRC, but I think we can suppress this output by default in the formatter, add a "level" argument to setup_logging that will install a filter, or implement a facility for subscribing/unsubscribing from logs from various components.

The formatter seems like a reasonable way to go for now.
(Assignee)

Comment 1

4 years ago
Created attachment 8463608 [details] [diff] [review]
Add a filter to the tbplformatter to suppress debug output by default.

Something like this. If this looks reasonable enough, I'll add a way to specify the option from the commandline.
Attachment #8463608 - Flags: feedback?(james)
(Assignee)

Updated

4 years ago
Assignee: nobody → cmanchester
Status: NEW → ASSIGNED
Comment on attachment 8463608 [details] [diff] [review]
Add a filter to the tbplformatter to suppress debug output by default.

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

::: testing/mozbase/mozlog/mozlog/structured/formatters/tbplformatter.py
@@ +10,5 @@
>      This is intended to be used to preserve backward compatibility with existing tools
>      hand-parsing this format.
>      """
> +    def __init__(self, level="info"):
> +        self._log_filter = LogLevelFilter(self._log, level)

I guess…

As you can see from the gymnastics you had to do this isn't really how you're supposed to use a LogLevelFilter; they were intended to be attached to handlers rather than specific formatters and, in particular, are supposed to compose as functions rather than being hardcoded. As I pointed out the other day, that might not make the most sense and certainly won't be as easy to add command line arguments for.

But maybe we should work out some design that works better rather than hacking this on. In fact the design of LogLevelFilter does still work with tbplformatter, you'd just have to do 

formatter = LogLevelFilter(TBPLFormatter(), "info") or something.

But perhaps we don't care about that kind of composition and would prefer to just have kwargs for everything?
Attachment #8463608 - Flags: feedback?(james)
(Assignee)

Comment 3

4 years ago
Created attachment 8464241 [details] [diff] [review]
Add command line options for configuring log level of formatters in mozlog.structured.

Maybe something like this would work, although this would now only be configurable from the command line.
Attachment #8464241 - Flags: feedback?(james)
(Assignee)

Updated

4 years ago
Attachment #8463608 - Attachment is obsolete: true
Comment on attachment 8464241 [details] [diff] [review]
Add command line options for configuring log level of formatters in mozlog.structured.

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

I think this overall design is basically OK (once we get rid of mach_terminal). It is somewhat limited in that you can't do --log-tbpl=- --log-tbpl=logfile.log and have debug messages in the latter but not the former, but maybe if we want to solve that the right way is to tell people to save the raw messages and post-process them into the format they want.

It might also be good if the structlog command line utility was taught about this log level stuff, but that's not essential for this review.

(r- only because I want to see the next iteration; imagine a long rant here about how bugzilla makes me give pejorative feedback rather than tacitly assuming that we are going to work together and iterate the patch until it's ready to land).

::: testing/mozbase/mozlog/mozlog/structured/commandline.py
@@ +19,5 @@
>      'tbpl': (formatters.TbplFormatter, "TBPL style log format"),
>  }
>  
> +def level_filter_wrapper(formatter, level):
> +    return handlers.LogLevelFilter(formatter, level)

It seems like the problem this is solving is that LogLevelFilter can apply to handlers and formatters? Why not just move it and import it directly?

@@ +25,5 @@
> +fmt_options = {
> +    # <option name>: (<wrapper function>, description, <applicable formatters>)
> +    'level': (level_filter_wrapper,
> +              "A least log level to subscribe to for the given formatter (debug, info, error, etc.)",
> +              ["raw", "mach", "mach_terminal", "tbpl"]),

FYI: I'm planning to kill mach_terminal

@@ +62,5 @@
>                               help=help_str)
>  
> +        for optname, (cls, help_str, formatters) in fmt_options.iteritems():
> +            for fmt in formatters:
> +                group.add_option("--log-" + "-".join([fmt, optname]), action="store",

Might be clearer as "--log-%s-%s" % (fmt, optname)

@@ +76,5 @@
>                                 help=help_str)
>  
> +        for optname, (cls, help_str, formatters) in fmt_options.iteritems():
> +            for fmt in formatters:
> +                group.add_argument("--log-" + "-".join([fmt, optname]), action="store",

As above.

@@ +126,5 @@
>      found_stdout_logger = False
>      if not hasattr(args, 'iteritems'):
>          args = vars(args)
>      for name, values in args.iteritems():
> +        parts = name.split('_')

This breaks with mach_terminal, right?

@@ +129,5 @@
>      for name, values in args.iteritems():
> +        parts = name.split('_')
> +        if parts[0] == 'log' and values is not None:
> +            # Our args will be ['log', <formatter>] or ['log', <formatter>, <option>].
> +            if len(parts) < 2 or parts[1] not in log_formatters:

< 2 is just == 1 here, right?

@@ +134,5 @@
> +                continue
> +            if len(parts) == 3:
> +                _, formatter, opt = parts
> +                if formatter not in formatter_options:
> +                    formatter_options[formatter] = {opt: values}

Seems like formatter_options should be a defaultdict(dict)

@@ +137,5 @@
> +                if formatter not in formatter_options:
> +                    formatter_options[formatter] = {opt: values}
> +                else:
> +                    formatter_options[formatter][opt] = values
> +            else:

This could be more explicit about only working for len=2
Attachment #8464241 - Flags: feedback?(james) → feedback-
Comment on attachment 8464241 [details] [diff] [review]
Add command line options for configuring log level of formatters in mozlog.structured.

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

Oh, but feedback+. Apparently I can't read.
Attachment #8464241 - Flags: feedback- → feedback+
(Assignee)

Updated

4 years ago
Depends on: 1026181
Blocks: 1044136
(Assignee)

Comment 6

4 years ago
Created attachment 8467268 [details] [diff] [review]
Add command line options for configuring log level of formatters in mozlog.structured.

Updated with review comments and added a default filter of "info".
Attachment #8467268 - Flags: review?(james)
(Assignee)

Updated

4 years ago
Attachment #8464241 - Attachment is obsolete: true
Comment on attachment 8467268 [details] [diff] [review]
Add command line options for configuring log level of formatters in mozlog.structured.

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

Basically fine, but with some issues that need to be addressed.

::: testing/mozbase/mozlog/mozlog/structured/commandline.py
@@ +25,5 @@
> +fmt_options = {
> +    # <option name>: (<wrapper function>, description, <applicable formatters>)
> +    'level': (level_filter_wrapper,
> +              "A least log level to subscribe to for the given formatter (debug, info, error, etc.)",
> +              ["raw", "mach", "tbpl"]),

I don't think raw should support this.

@@ +76,5 @@
> +            for fmt in formatters:
> +                group.add_argument("--log-%s-%s" % (fmt, optname), action="store",
> +                                   type=str, help=help_str)
> +
> +def setup_handlers(logger, formatters, formatter_options):

I wonder if having formatter options for formatters that aren't enabled should be an error e.g.

unused_options = set(formatter_options.keys()) - set(formatters.keys())
if unused_options:
    # raise an error or something

@@ +86,5 @@
> +    :param formatters: A dict of {formatter, [streams]} to use in handlers.
> +    :param formatter_options: a dict of {formatter: {option: value}} to
> +                              to use when configuring formatters.
> +    """
> +    for (fmt, streams) in formatters.iteritems():

Unneeded parens.

@@ +89,5 @@
> +    """
> +    for (fmt, streams) in formatters.iteritems():
> +        formatter_cls = log_formatters[fmt][0]
> +        formatter = formatter_cls()
> +        for (option, value) in formatter_options[fmt].iteritems():

Unneeded parens

@@ +124,3 @@
>      logger = StructuredLogger(suite)
> +    # Keep track of any options passed for formatters.
> +    formatter_options = defaultdict(lambda: _option_defaults)

There is a subtle bug here; you always return the same dictionary. Instead you need to return _option_defaults.copy()

@@ +140,5 @@
>      for name, values in args.iteritems():
> +        parts = name.split('_')
> +        if len(parts) > 3:
> +            # In case a formatter name contains an underscore
> +            parts = parts[:2] + ['_'.join(parts[2:])]

Let's just forbid this?

::: testing/mozbase/mozlog/tests/test_structured.py
@@ +387,5 @@
> +            logger = commandline.setup_logging("test_fmtopts", args, {})
> +            logger.info("INFO message")
> +            logger.debug("DEBUG message")
> +            logger.error("ERROR message")
> +            with open(logfile.name) as f:

Are you sure this works on Windows? I think I saw a try run where this broke tests on windows; so please run on try to validate this.

Might just be easier to open as rw and rewind the file?

@@ +388,5 @@
> +            logger.info("INFO message")
> +            logger.debug("DEBUG message")
> +            logger.error("ERROR message")
> +            with open(logfile.name) as f:
> +                print "reading from %s" % logfile.name

Leftover debugging?
Attachment #8467268 - Flags: review?(james) → review-
(Assignee)

Comment 8

4 years ago
Created attachment 8467836 [details] [diff] [review]
patch

This is interdiff responding to review feedback.

Try here to confirm I'm no longer misusing NamedTemporaryFile in tests:

https://tbpl.mozilla.org/?tree=Try&rev=d332c45a37aa
Attachment #8467836 - Flags: review?(james)
Comment on attachment 8467836 [details] [diff] [review]
patch

Thanks! ci if try comes back green.
Attachment #8467836 - Flags: review?(james) → review+
(Assignee)

Comment 10

4 years ago
Created attachment 8468180 [details] [diff] [review]
Add command line options for configuring log level of formatters in mozlog.structured.

This is the final patch. I had to fix the tests again, but the last try run is looking ok.
(Assignee)

Updated

4 years ago
Attachment #8467268 - Attachment is obsolete: true
(Assignee)

Updated

4 years ago
Attachment #8467836 - Attachment is obsolete: true
(Assignee)

Updated

4 years ago
Attachment #8468180 - Flags: review+
(Assignee)

Comment 11

4 years ago
I tried to check this in, but inbound is closed. Here's the passing windows try run:

https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=72d8d3084271
https://hg.mozilla.org/mozilla-central/rev/dfece7923301
Status: ASSIGNED → RESOLVED
Last Resolved: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla34
You need to log in before you can comment on or make changes to this bug.