1098592 - [mozlog] Stop using old mozlog API in other mozbase modules?

Status: RESOLVED INACTIVE

(Testing :: Mozbase, defect)

Description

[William Lachance (:wlach)]

Both mozversion and mozcrash instantiate an old (non structured) version of the logger if they are unable to get a "default logger" object:

http://mxr.mozilla.org/mozilla-central/source/testing/mozbase/mozcrash/mozcrash/mozcrash.py#40
http://mxr.mozilla.org/mozilla-central/source/testing/mozbase/mozversion/mozversion/mozversion.py#32
http://mxr.mozilla.org/mozilla-central/source/testing/mozbase/mozdevice/mozdevice/devicemanager.py#51

This is confusing for people looking for example code (see bug 1095026) and is probably generally a bad practice. Two options come to mind here (there may be others):

1. Demand that people set a default structured logger to use these modules.
2. Create a default structured logger that outputs to standard output.

I remember discussing this a while ago and we settled on the current solution as a compromise... but I'm not convinced it's what we should actually be doing. NEEDINFO'ing :jgraham since IIRC he had the most opinions about this at the time, but I'd welcome feedback from others as well.

Personally I think we might want to move towards (1). It might break a few existing consumers, but it would enforce good practices and hygiene in our test harnesses and tools, which I think would be a win long term.

Comment 1

[Andrew Halberstadt [:ahal]]

3. Fall back to logging instead of fall back to mozlog (which is basically just logging).

mozlog.structured was designed for test results, but it could be useful for other things as well. I'd be interested to know the reason why we don't want a default stdout logger being set automatically, seems like it would be convenient.

I think my order of preference is 2, 3, 1. Mozcrash and mozversion are simple modules and forcing consumers to know about structured logging seems like we're causing them trouble for no good reason (really, no one cares about the format of mozcrash/mozversion output).

Comment 2

[William Lachance (:wlach)]

(In reply to Andrew Halberstadt [:ahal] from comment #1)
> I think my order of preference is 2, 3, 1. Mozcrash and mozversion are
> simple modules and forcing consumers to know about structured logging seems
> like we're causing them trouble for no good reason (really, no one cares
> about the format of mozcrash/mozversion output).

It should be one line of python to set up basic structured logging. It's not a lot to ask. We could certainly provide a bit of a pointer in whatever except we throw to help point people to a resource on doing things properly.

I also disagree that no one cares about the output of these tools. I think generally it is very desirable to be able to finely control the amount and format of output that our tools produce, to ease debugging. For example, in mozregression I'd like to be able to just show critical messages that mozversion produces by default (e.g. ignoring anything at the debug or info level), but be able to turn up the logging level when I'm debugging a problem.

Comment 3

[James Graham [:jgraham]]

So I don't remember exactly what I previously thought.

I think the current solution was intended specifically to allow libraries to work with top-level code that wasn't yet ported to structured logging. If you just create a default structured logger then it could, I think, cause problems in some situations e.g. multithreaded applications where one thread is using the structured logger and one is using the unstructured logger. In this case you might end up with corrupt output on stdout.

Also, it's not exactly clear what a useful default formatter would be. Would it be designed to look as much as possible like normal logging? Would it be the raw output (like you get as the default when you use commandline.setup_logging)?

Having said that I'm very sympathetic to the idea that in python a function that returns None-or-logger is a usability hazard due to the lack of type checking.

Comment 4

[William Lachance (:wlach)]

(In reply to James Graham [:jgraham] from comment #3)
> So I don't remember exactly what I previously thought.
> 
> I think the current solution was intended specifically to allow libraries to
> work with top-level code that wasn't yet ported to structured logging. If
> you just create a default structured logger then it could, I think, cause
> problems in some situations e.g. multithreaded applications where one thread
> is using the structured logger and one is using the unstructured logger. In
> this case you might end up with corrupt output on stdout.

Yeah, I definitely don't think we should set a default global standard logger unless asked to do so, if that's what you mean.

> Also, it's not exactly clear what a useful default formatter would be. Would
> it be designed to look as much as possible like normal logging? Would it be
> the raw output (like you get as the default when you use
> commandline.setup_logging)?

After thinking about this a bit more, I think that probably is indeed what we should do (instead of my proposal to abort if no default logger is specified). Sometimes you just do want to instantiate a component quickly in the console or otherwise for testing purposes, and in those cases you just want it to dump to standard output and not do anything fancy.

Does that sound ok to everyone?

Comment 5

[William Lachance (:wlach)]

Attachment: Patch to update get_default_logger behaviour and consumers

Ok, I think we agreed on irc to change the behaviour of get_default_logger to output to create a logger outputting to standard output if one doesn't already exist, and update existing consumers accordingly. This patch does that.

Comment 6

[James Graham [:jgraham]]

Comment on attachment 8523144 [details] [diff] [review]
Patch to update get_default_logger behaviour and consumers

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

Could have a small change, but basically seems fine.

::: testing/mozbase/mozlog/mozlog/structured/structuredlog.py
@@ +70,5 @@
>      """
>      global _default_logger_name
>  
>      if not _default_logger_name:
> +        _default_logger_name = 'logger'

Can't we create the logger and then call set_default_logger here?

Comment 7

[Chris Manchester (limited bugmail, email directly)]

Comment on attachment 8523144 [details] [diff] [review]
Patch to update get_default_logger behaviour and consumers

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

This was asked and answered in https://bugzilla.mozilla.org/show_bug.cgi?id=1021943#c6 and below. Based on that response I've added code that uses get_default_logger to decide whether to call log_crashes or check_for_crashes in a number of cases.

::: testing/mozbase/mozlog/mozlog/structured/structuredlog.py
@@ +74,5 @@
> +        _default_logger_name = 'logger'
> +        from formatters import MachFormatter
> +        from handlers import StreamHandler
> +        logger = StructuredLogger(_default_logger_name, component=component)
> +        logger.add_handler(StreamHandler(sys.stdout, MachFormatter()))

Reftests use mozcrash for shutdown crashes, but don't otherwise use structured logging. Because of the line prefixing done in the MachFormatter, shutdown crashes will be green jobs

Comment 8

[William Lachance (:wlach)]

Attachment: Patch to reftest to fix stuff

Here's a patch to fix up reftest. Apparently it's insufficient but I don't know why. :) Hopefully :chmanchester does.

Comment 9

[Chris Manchester (limited bugmail, email directly)]

Comment on attachment 8523196 [details] [diff] [review]
Patch to reftest to fix stuff

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

I do think this will solve the problem of matching regex in the case of unstructured logging users assuming reftest are the only ones. It doesn't address the places we rely on the return value of None.  Those would need to be updated to reflect this change.

Comment 10

[James Graham [:jgraham]]

Comment on attachment 8523144 [details] [diff] [review]
Patch to update get_default_logger behaviour and consumers

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

Since chmanchester spotted a flaw I missed, I'm changing this to r- until we have a way to work with consumers that take different action depending on the logging type (e.g. mozcrash).

Comment 11

[William Lachance (:wlach)]

(In reply to Chris Manchester [:chmanchester] from comment #9)
> I do think this will solve the problem of matching regex in the case of
> unstructured logging users assuming reftest are the only ones. It doesn't
> address the places we rely on the return value of None.  Those would need to
> be updated to reflect this change.

Return value of None for get_default_logger? Who relies on those right now, except for other parts of mozbase (that we're changing)?

Comment 12

[Chris Manchester (limited bugmail, email directly)]

(In reply to William Lachance (:wlach) from comment #11)
> (In reply to Chris Manchester [:chmanchester] from comment #9)
> > I do think this will solve the problem of matching regex in the case of
> > unstructured logging users assuming reftest are the only ones. It doesn't
> > address the places we rely on the return value of None.  Those would need to
> > be updated to reflect this change.
> 
> Return value of None for get_default_logger? Who relies on those right now,
> except for other parts of mozbase (that we're changing)?

I only know about the ones I added, so a dxr search would possibly answer this better than I could. Again, the use case I added it for is mozcrash.

Comment 13

[William Lachance (:wlach)]

Not working on this at the moment, if someone wants to pick it up they should feel free.