Chris Manchester (limited bugmail, email directly) Assignee
	Description • 10 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.

	Chris Manchester (limited bugmail, email directly) Assignee
	Comment 1 • 10 years ago

Something like this. If this looks reasonable enough, I'll add a way to specify the option from the commandline.

	James Graham [:jgraham]
	Comment 2 • 10 years ago

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?

	Chris Manchester (limited bugmail, email directly) Assignee
	Comment 3 • 10 years ago

Maybe something like this would work, although this would now only be configurable from the command line.

	James Graham [:jgraham]
	Comment 4 • 10 years ago

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

	James Graham [:jgraham]
	Comment 5 • 10 years ago

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.

	Chris Manchester (limited bugmail, email directly) Assignee
	Comment 6 • 10 years ago

Updated with review comments and added a default filter of "info".

	James Graham [:jgraham]
	Comment 7 • 10 years ago

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?

	Chris Manchester (limited bugmail, email directly) Assignee
	Comment 8 • 10 years ago

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

	James Graham [:jgraham]
	Comment 9 • 10 years ago

Comment on attachment 8467836 [details] [diff] [review]
patch

Thanks! ci if try comes back green.

	Chris Manchester (limited bugmail, email directly) Assignee
	Comment 10 • 10 years ago

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

	Chris Manchester (limited bugmail, email directly) Assignee
	Comment 11 • 10 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

	Chris Manchester (limited bugmail, email directly) Assignee
	Comment 12 • 10 years ago

Trees reopened:

https://hg.mozilla.org/integration/mozilla-inbound/rev/dfece7923301

	Nigel Babu [:nigelb]
	Comment 13 • 10 years ago

https://hg.mozilla.org/mozilla-central/rev/dfece7923301