1394381 - Add error logging to Marionette client

Status: RESOLVED INACTIVE

(Remote Protocol :: Marionette, enhancement, P3)

Description

[Henrik Skupin [:whimboo][⌚️UTC+1]]

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.

Comment 1

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Attachment: Bug 1394381 - Add logging output for Marionette connection attempts.

If Marionette client cannot connect to the server, the attempts
have to be logged to stderr. This allows us to inspect the reason
why a connection from the client could not be made, and that it
still tries to connect (see bug 1362293).

Review commit: https://reviewboard.mozilla.org/r/176756/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/176756/

Comment 2

[Maja Frydrychowicz :impossibus (was :maja_zf) (needinfo me)]

Comment on attachment 8904942 [details]
Bug 1394381 - Add logging output for Marionette connection attempts.

https://reviewboard.mozilla.org/r/176756/#review181838

Comment 3

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/1e12a866239c
Add logging output for Marionette connection attempts. r=maja_zf

Comment 4

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

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)

Comment 5

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

Only hits Windows.

Comment 6

[Pulsebot]

Backout by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/e37dfd5884b7
Backed out changeset 1e12a866239c for busting web-platform-tests. r=backout on a CLOSED TREE

Comment 7

[Henrik Skupin [:whimboo][⌚️UTC+1]]

For reference here all the results while the patch was on autoland:

https://treeherder.mozilla.org/#/jobs?repo=autoland&bugfiler&fromchange=1e12a866239c&tochange=e37dfd5884b7&filter-resultStatus=testfailed&filter-resultStatus=busted&filter-resultStatus=exception&filter-resultStatus=retry&filter-resultStatus=usercancel&filter-resultStatus=running&filter-resultStatus=pending&filter-resultStatus=runnable&selectedJob=128972463

James, can you explain why only on Windows we hit this problem with the structured log? Might that be a bug for that platform?

Comment 8

[James Graham [:jgraham]]

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).

Comment 9

[Henrik Skupin [:whimboo][⌚️UTC+1]]

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.

Comment 10

[Andrew Halberstadt [:ahal] (PTO Until Apr 3rd)]

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').

Comment 11

[Henrik Skupin [:whimboo][⌚️UTC+1]]

(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?

Comment 12

[Andrew Halberstadt [:ahal] (PTO Until Apr 3rd)]

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.

Comment 13

[Henrik Skupin [:whimboo][⌚️UTC+1]]

(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.

Comment 14

[Andrew Halberstadt [:ahal] (PTO Until Apr 3rd)]

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.

Comment 15

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Currently I'm not working on this bug.

Comment 16

[Henrik Skupin [:whimboo][⌚️UTC+1]]

We most likely won't ever get to this bug and meanwhile I don't see that it is that important.