Closed Bug 1199902 Opened 9 years ago Closed 8 years ago

use mozlog proxy loggers

Categories

(Testing :: mozregression, defect)

defect
Not set
normal

Tracking

(firefox43 affected)

RESOLVED FIXED
Tracking Status
firefox43 --- affected

People

(Reporter: parkouss, Assigned: parkouss)

References

Details

Attachments

(1 file)

I think mozlog is not really adapted for mozregression. Some thoughts:

- We can't use at a module level something equivalent to:

> LOG = logging.getLogger()

  the equivalent mozlog get_default_logger just return None if we do that at the module level (when handlers are not yet initialized). This leads to boiler plate code, because we then have to pass log objects everywhere or call get_default_logger in each function/method.

- the output is not easy to configure. For example, I don't think we care about the thread name indication, at least without --debug, and that is not an easy change to do with mozlog.

- the output logging options when we type "mozregression --help" is not intuitive to me:

> Output Logging:
>   Each option represents a possible logging format and takes a filename to
>   write that format to, or '-' to write to stdout.
> 
>   --log-raw LOG_RAW     Raw structured log messages
>   --log-mach LOG_MACH   Human-readable output
>   --log-mach-buffer LOG_MACH_BUFFER
>                         If specified, enables message buffering at the given
>                         buffer size limit.
>   --log-mach-verbose    Enables verbose mode for the given formatter.
>   --log-mach-level LOG_MACH_LEVEL
>                         A least log level to subscribe to for the given
>                         formatter (debug, info, error, etc.)
>   --log-raw-level LOG_RAW_LEVEL
>                         A least log level to subscribe to for the given
>                         formatter (debug, info, error, etc.)

  We only really want a --log-level or something.

- I think the mozversion output is too verbose for mozregression, e.g.:

> 16:02.36 LOG: MainThread mozversion INFO application_buildid: 20150820111935
> 16:02.36 LOG: MainThread mozversion INFO application_changeset: 7eab671c99c59599331a9ba39ea5ec9e47cf6de0
> 16:02.36 LOG: MainThread mozversion INFO application_display_name: Nightly
> 16:02.36 LOG: MainThread mozversion INFO application_id: {ec8030f7-c20a-464f-9b0e-13a3a9e97384}
> 16:02.36 LOG: MainThread mozversion INFO application_name: Firefox
> 16:02.36 LOG: MainThread mozversion INFO application_remotingname: firefox
> 16:02.36 LOG: MainThread mozversion INFO application_repository: https://hg.mozilla.org/integration/mozilla-inbound
> 16:02.36 LOG: MainThread mozversion INFO application_vendor: Mozilla
> 16:02.36 LOG: MainThread mozversion INFO application_version: 43.0a1
> 16:02.36 LOG: MainThread mozversion INFO platform_buildid: 20150820111935
> 16:02.36 LOG: MainThread mozversion INFO platform_changeset: 7eab671c99c59599331a9ba39ea5ec9e47cf6de0
> 16:02.36 LOG: MainThread mozversion INFO platform_repository: https://hg.mozilla.org/integration/mozilla-inbound
> 16:02.36 LOG: MainThread mozversion INFO platform_version: 43.0a1

  I think it makes it harder to follow the regression process, some information is duplicated from other logs and we don't need that much information.


Using logging would allow us to be able to customize the output and write less code for logging statements. I think we should go for it.
Summary: should we switch from mozlog to lo logging ? → should we switch from mozlog to logging ?
Will, I know you want to keep mozlog, mainly because it is used in mozbase everywhere. Could you reconsider it, given the reasons in comment 0 ?
Flags: needinfo?(wlachance)
(In reply to Julien Pagès from comment #1)
> Will, I know you want to keep mozlog, mainly because it is used in mozbase
> everywhere. Could you reconsider it, given the reasons in comment 0 ?

I'm not really sure to be honest. I understand the issues you mention, but it feels to me like mozlog should work well for our use case, and it's a bit of an issue if it doesn't, since other things that use it are still user-facing to some extent (i.e. running the unit tests via mach) and the difficulty of using it is something that's going to come up again and again as we continue to use it in our test harnesses.

Personally, I'd lean towards fixing issues in mozlog itself.

CC'ing :jgraham to see if he has any comments.
Flags: needinfo?(wlachance)
So there are a few issues here:

1) mozlog is designed to make post-processing logs easier. If that isn't something you care about, then it's not such a big win for your use cases as for other use cases.

2) Having said that it appears that you are logging lots of structured information in an unstructured way. I feel like you would get a lot more out of mozlog if you figured out how to log the things you care about using the existing log actions, or added new log actions for those things.

3) I don't really feel like setting up the logger has been a big burden in code where I've used it. I don't know how the mozregression code is structured though.

4) There are some options available to limit the formatters presented as command line options, but it might make sense to extend the API to remove some options that are unlikely to be used in this use case.

5) Altering the formatting on a case-by-case basis is not currently well supported, but it's certainly something that we would take patches to improve.

I feel like fundamentally using mozlog — with more structured data than you have currently — is the right thing to do because it will better integrate with the ecosystem of tools we are developing that assume they are going to consume structured logs. When we run a test in mozregression having the test output be the same as that you would see on automation will be a clear win. Therefore my feeling is that you should improve mozlog rather than throw it out for some ergonomic rough edges.
Ok so, for

1) mozregression only use log to print things in a thread safe way, and making use of log levels to print out debug statements (or not). So no, no log processing at all in mozregression.

2) I don't think we have logging structured info. the only things we use that comes from mozlog are issued from mozversion, and this does not looks like structured: https://dxr.mozilla.org/mozilla-central/source/testing/mozbase/mozversion/mozversion/mozversion.py?offset=500#295. Futhermore, We need a fine grained control of what is printed here so we will probably filter/disable those in some way.

3) Well, we have for example https://github.com/mozilla/mozregression/blob/master/mozregression/main.py#L228. I don't like that we pass the logger. the alternative of course would be to use get_default_logger('something') inside that function. So at the end it could lead to one specific line in each function for log assignment. And variable assignment for each base class also. This can be discussed, but I like the logging global variable access (even though generally I don't like global stuff, this make sense and is easy for logging I think and it makes us write less code).

for 4) and 5), I can totally understand. But it is a lot more work to write patches and extend that api than it is to use logging. And I must say that doing this would looks to me like reinventing the wheel, because logging would just work here. So why bother writing the same thing with more bugs ?

Lastly, I don't agree with adding more structured things in mozregression, because as I said in 1) we only want to print out things. Well it would be good to have an ecosystem that looks the same, but for now there is no need I can see from consuming mozregression logs.
Ok well instead of moving to logging, we can do the following here:

 - implement a handler to filter messages from mozversion
 - implement a formatter to customize the output of mozregression
 - do not use the argparse integration, only implement our own --debug flag

Is that ok for you guys ? This way I can customize a bit the output, and we can still keep mozlog to maybe use the structured part in the future.
Flags: needinfo?(wlachance)
Flags: needinfo?(james)
I generally prefer it if you implement things that are reusable for other components that use mozlog, rather than doing special-case things. Also, with the mach command, it seems more reasonable to have a command line API and output style that looks like other mach commands. So I would prefer it if, at least, instead of implementing a new formatter you implemented customisations for the existing mach formatter to make it possible to hide fields that aren't relevant in certain contexts.
Flags: needinfo?(james)
I don't think I have any extra feedback here, what :jgraham said sounds reasonable.
Flags: needinfo?(wlachance)
See Also: → 1214386
So, after some discussions and more thinking, I changed my mind - It seems great to keep mozlog.

What was bothering me most was the ability to filter some logs, and the use of logger instances everywhere in function parameters (or calls to get_default_loggers multiple times).

Point 1 is easily fixed with component_filter, and the second point will be resolved with bug 1226554.

So, let's change this bug to use the new proxy loggers! We will address other things like formatters in time.
Depends on: 1226554
Summary: should we switch from mozlog to logging ? → use mozlog proxy loggers
Attachment #8704098 - Flags: review?(wlachance)
Assignee: nobody → j.parkouss
Status: NEW → ASSIGNED
Comment on attachment 8704098 [details] [review]
use mozlog proxy loggers

This is great! I can see the proxy logger stuff being useful in all sorts of places...
Attachment #8704098 - Flags: review?(wlachance) → review+
Landed in https://github.com/mozilla/mozregression/commit/6689f4026f8d81f4cc6e588895c1722d717571a9.

So let's address log output tweaks in another bug.
Status: ASSIGNED → RESOLVED
Closed: 8 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: