Closed Bug 1098404 Opened 5 years ago Closed 5 years ago

Need a way to filter mozlog messages by component

Categories

(Testing :: Mozbase, defect)

defect
Not set

Tracking

(Not tracked)

RESOLVED FIXED
mozilla36

People

(Reporter: jgraham, Assigned: jgraham)

Details

Attachments

(6 files, 1 obsolete file)

Currently mozlog allows one set of handlers per logger name. A single logger name can have many sub components. There is no easy way to apply filters just to certain components without making every handler component-aware. This is a problem.

For a use case, consider the case where we import some tests that run server-side script. If the server logs errors in these scripts at ERROR level it will turn the mozharness job red, but actually nothing broke; it's just an upstream bug that shouldn't block our ability to import the tests. Therefore such messages should be viewed as WARNING-level when run in mozharness. This can be achieved by rewriting ERROR messages from the server component to be WARNING messages.
Attachment #8522332 - Flags: review?(cmanchester)
/r/593 - Bug 1098404 - Implement per-component filters for mozlog.

Pull down this commit:

hg pull review -r 9b37981368edb099ac555a2dacfafd486f8fcd2d
https://reviewboard.mozilla.org/r/591/#review243

::: testing/mozbase/mozlog/mozlog/structured/structuredlog.py
(Diff revision 1)
>      return set(convertor_registry.keys())

Needs some tests and stuff, but let's agree on a general approach first.
https://reviewboard.mozilla.org/r/591/#review251

::: testing/mozbase/mozlog/mozlog/structured/structuredlog.py
(Diff revision 1)
> +                    return

If we're going to implement this, I think it should only support one thing: subscribing and unsubscribing from components.

::: testing/mozbase/mozlog/mozlog/structured/structuredlog.py
(Diff revision 1)
>                  handler(data)

If you have a context where you absolutely have to re-interpret log messages and you want to do it in mozlog, it seems like you could take advantage of the fact that dictionaries are mutable and handlers are ordered to achieve the level demotion and achieve the desired result.

::: testing/mozbase/mozlog/mozlog/structured/handlers/__init__.py
(Diff revision 1)
> +            data["level"] = self.to_level

I don't think this should happen. If someone is reporting logs to our infrastructure, an error should be a red job. I don't know the context at all, but if we encourage the creation of situations where that isn't true adding a facility for it in mozlog it seems like it will just breed confusion.
Attachment #8522332 - Flags: review?(cmanchester)
https://reviewboard.mozilla.org/r/591/#review271

> I don't think this should happen. If someone is reporting logs to our infrastructure, an error should be a red job. I don't know the context at all, but if we encourage the creation of situations where that isn't true adding a facility for it in mozlog it seems like it will just breed confusion.

> If someone is reporting logs to our infrastructure, an error should be a red job.

That isn't really true. We already have examples in mozharness where something from upstream emits an "error" message and we don't want to actually mozharness red; there are regexps in (unstructured) mozharness to deal with those cases. In this case we have effectively an upstream library package that logs things that make sense as "errors" in the upstream context but aren't errors in the narrower mozharness sense of "things that went wrong and stopped the job completing / prevented the results being trustworthy". I think this is a use case we have to support somehow, either in mozlog or in mozharness.

In this case I could hack upstream to make less sense, or put this class in the test harness. But I don't think pretending this isn't a case we need to deal with is a viable solution. In some sense the *more* we centralise this the better e.g. putting it in mozharness. But this is a nice compromise because it means that you can postprocess the logs that were output and figure out what conclusion mozharness would have come to without having to know which components it was configured to ignore for the purposes of handling errors.

I'm happy to add a docstring indicating that there are only limited cases in which this approach makes sense.

> If you have a context where you absolutely have to re-interpret log messages and you want to do it in mozlog, it seems like you could take advantage of the fact that dictionaries are mutable and handlers are ordered to achieve the level demotion and achieve the desired result.

I don't understand exactly how you propose to make use of that. I mean I could wrap the handler in one that alters the messages only for a certian component, but this seems easier to understand.
Attachment #8522332 - Flags: review?(cmanchester)
/r/593 - Bug 1098404 - Implement per-component filters for mozlog.
/r/827 - fixup! Bug 1098404 - Remove LogLevelRewriter from the mozlog library

Pull down these commits:

hg pull review -r 0c1b6092f27685461996a16e576d9dea82e25984
/r/593 - Bug 1098404 - Implement per-component filters for mozlog.
/r/827 - fixup! Bug 1098404 - Remove LogLevelRewriter from the mozlog library

Pull down these commits:

hg pull review -r 0c1b6092f27685461996a16e576d9dea82e25984
/r/593 - Bug 1098404 - Implement per-component filters for mozlog.
/r/827 - fixup! Bug 1098404 - Remove LogLevelRewriter from the mozlog library
/r/837 - fixup! Add tests for component filters

Pull down these commits:

hg pull review -r 8344e0ec1ef769a5e09662e23775a4873172f8e3
https://reviewboard.mozilla.org/r/591/#review407

::: testing/mozbase/mozlog/mozlog/structured/structuredlog.py
(Diff revision 3)
> +                    return

This seems more like a handler than a filter.

::: testing/mozbase/mozlog/tests/test_structured.py
(Diff revision 3)
> +        component_logger.component_filter = handlers.LogLevelFilter(lambda x:x, "info")

Perhaps add a test that modifies the log message.

::: testing/mozbase/mozlog/mozlog/structured/structuredlog.py
(Diff revision 3)
> +    _component_states = {}

Should component states live in logger states? I wouldn't want to start filtering someone else's "server" component by accident.

::: testing/mozbase/mozlog/mozlog/structured/structuredlog.py
(Diff revision 3)
> +                self._component_states[component] = ComponentState()

This should be guarded against 'component is None'. Looks like all the top-level loggers share a component state with a key of None.

::: testing/mozbase/mozlog/mozlog/structured/structuredlog.py
(Diff revision 3)
> +        return self._component_states[self.component]

This extra level of indirection doesn't seem necessary (doesn't hurt anything, of course).

::: testing/mozbase/mozlog/mozlog/structured/structuredlog.py
(Diff revision 3)
>          self._state.handlers.append(handler)

Would it be about as good to have add_handler make a note of whether the handler is added to a component-specific logger, and later make sure to call a component specific handler first?

::: testing/mozbase/mozlog/tests/test_structured.py
(Diff revision 3)
> +        return not bool(self.items)

Doesn't "not" already coerce to a bool?
/r/593 - Bug 1098404 - Implement per-component filters for mozlog.
/r/827 - fixup! Bug 1098404 - Remove LogLevelRewriter from the mozlog library
/r/837 - fixup! Add tests for component filters
/r/881 - fixup! Make component state part of the logger state.
/r/883 - fixup! Add extra tests for filters that mutate the log message and filters on the default component.
/r/885 - fixup! Remove an unneeded bool()

Pull down these commits:

hg pull review -r 3334143dc0dee1e551c204c98fcd6a4b06930b2b
https://reviewboard.mozilla.org/r/591/#review435

> Would it be about as good to have add_handler make a note of whether the handler is added to a component-specific logger, and later make sure to call a component specific handler first?

Again, I don't think it makes sense unless we think that we should always special-case named components.

> This seems more like a handler than a filter.

I guess? It is intended to be compatible with the objects that you wrap aound handlers, but it isn't expected that it actually does any IO itself (that's hard to enforce of course). The name is intended to convey that distinction; although it would be possible to put e.g. a StreamHandler in as a log filter, because the API of both is just that of a function call, it isn't supposed to work.

Maybe in a followup we could create structuredlog.handlers.filters with these filters in, or something?

> This should be guarded against 'component is None'. Looks like all the top-level loggers share a component state with a key of None.

That would break things; if you did logger = StructuredLogger("name"); logger.component_filter = something then you'd get an error unless there is a ComponentState for the default component.

That could be special-cased of course, but I don't know why we would do that. It doesn't seem like it should be impossible to say "I want info-level logging at the top level and debug-level for a specific subcomponent".
https://reviewboard.mozilla.org/r/591/#review451

> That would break things; if you did logger = StructuredLogger("name"); logger.component_filter = something then you'd get an error unless there is a ComponentState for the default component.
> 
> That could be special-cased of course, but I don't know why we would do that. It doesn't seem like it should be impossible to say "I want info-level logging at the top level and debug-level for a specific subcomponent".

If someone adds a component filter to a logger that isn't associated with a component that should be an error. With this patch I could do logger = StructuredLogger("foo"); logger.component_filter = lambda _: None, at any point, and output would be supressed for every logger in the system.

> Again, I don't think it makes sense unless we think that we should always special-case named components.

Having handlers apply at a component level seems like an ok thing in general. Would save us from making the rather fine distinction between handlers and component filters. Component based loggers don't seem to add that much value vs. regular loggers (just seems like shorthand for sharing an initial set of handlers), I'm reluctant to associate novel concepts with them.
Attachment #8522332 - Flags: review?(cmanchester) → review+
https://reviewboard.mozilla.org/r/591/#review463

> Having handlers apply at a component level seems like an ok thing in general. Would save us from making the rather fine distinction between handlers and component filters. Component based loggers don't seem to add that much value vs. regular loggers (just seems like shorthand for sharing an initial set of handlers), I'm reluctant to associate novel concepts with them.

We talked about this on IRC and I concluded my proposal is pretty much equivalent.

> If someone adds a component filter to a logger that isn't associated with a component that should be an error. With this patch I could do logger = StructuredLogger("foo"); logger.component_filter = lambda _: None, at any point, and output would be supressed for every logger in the system.

We talked about this on IRC, this is only really a concern without the above issue resolved.
https://hg.mozilla.org/mozilla-central/rev/a3665a95a357
Assignee: nobody → james
Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla36
Attachment #8522332 - Attachment is obsolete: true
Attachment #8618625 - Flags: review+
Attachment #8618626 - Flags: review+
Attachment #8618627 - Flags: review+
Attachment #8618628 - Flags: review+
Attachment #8618629 - Flags: review+
Attachment #8618630 - Flags: review+
You need to log in before you can comment on or make changes to this bug.