Add error logging to Marionette client

NEW
Unassigned

Status

enhancement
P3
normal
2 years ago
10 months ago

People

(Reporter: whimboo, Unassigned)

Tracking

(Blocks 2 bugs)

57 Branch
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(Not tracked)

Details

Attachments

(1 attachment)

Similar to geckodriver it would be great to see some logging output for connection attempts from the Marionette client. It would help us to eg. get a better understanding for situations like reported on bug 1362293.
Assignee: nobody → hskupin
Status: NEW → ASSIGNED
Summary: Add info logging output to Marionette client's connection attempts → Add error logging output to Marionette client's connection attempts
Comment on attachment 8904942 [details]
Bug 1394381 - Add logging output for Marionette connection attempts.

https://reviewboard.mozilla.org/r/176756/#review181838
Attachment #8904942 - Flags: review?(mjzffr) → review+
Pushed by hskupin@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/1e12a866239c
Add logging output for Marionette connection attempts. r=maja_zf
Backed out for mass failing web-platform-tests:

A push with failures (the one which landed this was busted from a previous push): https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=adba302ab807e36ee451eb944496b83de55ca053&filter-resultStatus=testfailed&filter-resultStatus=busted&filter-resultStatus=exception&filter-resultStatus=retry&filter-resultStatus=usercancel&filter-resultStatus=runnable
Failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=128952059&repo=autoland

Several of these:

CRITICAL - Test harness output was not a valid structured log message: 
CRITICAL - Connection attempt to Marionette failed (timed out)
Flags: needinfo?(hskupin)
Backout by archaeopteryx@coole-files.de:
https://hg.mozilla.org/integration/autoland/rev/e37dfd5884b7
Backed out changeset 1e12a866239c for busting web-platform-tests. r=backout on a CLOSED TREE
I don't know why the connection is timing out, but printing directly to stderr is perhaps a problem. The wpt harness is supposed to capture output to stdio, but it's possible that's somehow broken on Windows. In any case, try using the logging package (or better still, mozlog).
Flags: needinfo?(james)
Priority: -- → P3
Summary: Add error logging output to Marionette client's connection attempts → Add error logging output to Marionette driver's connection attempts
Summary: Add error logging output to Marionette driver's connection attempts → Add error logging to Marionette client
As mentioned before there is no logger feature available yet in marionette_driver. To get started I wanted to use mozlog and structured logging, but have troubles in how to integrate it as best. Andrew, maybe you can give me a helping hand? TIA!

Here is what we have right now: Marionette unit tests are getting executed via marionette_harness, which itself uses structured logging, and makes use of the marionette_driver package to control Firefox. Beside that marionette_driver is also used by various other test harnesses like wpt-tests, mochitests, and reftests as helper to get extensions installed, or like in case of wptrunner to drive the tests.

What I want is that any logging in marionette_driver should inherit the settings from the consumer, including the log level, and formatter. The only exception would be the component, which should be `Marionette` for log entries. Further I don't want to have to pass a logger along for all the modules of marionette_driver, maybe a global mozlog instance can be used? It would also mean when should we log and under which circumstances we shouldn't. I think when the consumer hasn't setup any logging we should also refrain from doing so. Having to check if a logger exists each time in marionette_driver would be not ideal.

All the examples I found so far are for packages which are using an arg parser and setup logging via the command line. marionette_driver doesn't have a cli, and as such that doesn't fit.
Flags: needinfo?(ahalberstadt)
If you instantiate a new StructuredLogger instance with a name, it'll detect if an instance with the same name was previously instantiated and use the same state. Components are not part of this state, so sounds like it already does just what you need. E.g:

    from structuredlog import StructuredLogger
    log = StructuredLogger('<name>', component='marionette')

If only one logger has been instantiated previously, you could also use structuredlog.get_default_logger(component='marionette').
Flags: needinfo?(ahalberstadt)
(In reply to Andrew Halberstadt [:ahal] from comment #10)
> If you instantiate a new StructuredLogger instance with a name, it'll detect
> if an instance with the same name was previously instantiated and use the
> same state. Components are not part of this state, so sounds like it already
> does just what you need. E.g:
> 
>     from structuredlog import StructuredLogger
>     log = StructuredLogger('<name>', component='marionette')

So what I don't understand here is how structured logger will behave if I don't specify a name. Thing is that in marionette_driver we don't know which code is embedding it, and as such we also don't know which name has been chosen. 

> If only one logger has been instantiated previously, you could also use
> structuredlog.get_default_logger(component='marionette').

Would that inherit all the settings as made by the consumer when creating the default logger?

I assume now that I can put this globally in each of the modules of marionette_driver, and use the logging where it is needed. But what's under those conditions where no default logger is available? Then this method returns None, and I would need a fake logger which doesn't log anything?
Flags: needinfo?(ahalberstadt)
Yeah if you don't know the name you'll need to use get_default_logger. When you set a logger up via commandline.py, it should automatically call set_default_logger. And yes any state should be preserved, including handlers, running tests, suite start/end messages, and component states.
Flags: needinfo?(ahalberstadt)
(In reply to Andrew Halberstadt [:ahal] from comment #12)
> Yeah if you don't know the name you'll need to use get_default_logger. When

The problem is if the consumer is not doing it, the call to this method returns None. So no default logger is available. What would your proposal be in how marionette_driver should handle calls to eg. logger.info()? I think when a custom logger is setup, unwanted log output would appear. And not doing so, I would have to check everywhere if logger is not None.

> you set a logger up via commandline.py, it should automatically call
> set_default_logger. And yes any state should be preserved, including
> handlers, running tests, suite start/end messages, and component states.

Sounds good. Thanks.
Flags: needinfo?(ahalberstadt)
If you don't know the custom logger name and it wasn't set up as a default, I'd recommend just creating a new logger. But I guess if you *really* needed to StructuredLogger._logger_states.keys() contains all the names of previously instantiated loggers. Though that is definitely not an official API.
Flags: needinfo?(ahalberstadt)
Currently I'm not working on this bug.
Assignee: hskupin → nobody
Status: ASSIGNED → NEW
You need to log in before you can comment on or make changes to this bug.