Henrik Skupin [:whimboo][⌚️UTC+1] Assignee
	Description • 6 years ago

When trace logs are enabled the following lines are visible in the logs for each and every command. Here an example:

> 28:34.87 pid:5174 1523449559945	Marionette	TRACE	0 <- [1,90,null,{}]
> 28:34.87 pid:5174 1523449559945	geckodriver::marionette	TRACE	<- [1,90,null,{}]
> 28:34.87 pid:5174 1523449559945	webdriver::server	DEBUG	<- 200 OK {"value": {}}

I don't see the reason to log `geckodriver::marionette` because it is basccially duplicates what `Marionette` has already been logged. Only the additional `webdriver::server` output is helpful.

	Andreas Tolfsen ❲:ato❳
	Comment 1 • 6 years ago

It’s useful because it tells you the path a request takes before
it fails.  A response from Marionette goes to geckodriver’s Marionette
protocol implementino, then to the HTTP handler in the webdriver
crate that returns a 200 HTTP response.

Because the webdriver::server log entry in the above quote is the
most important, it is logged at DEBUG level, whereas the two other
less significant lines are logged at TRACE.  This means it is
sufficient to just use -v or --log-level debug to get a good overview
of what the WebDriver server is doing.

	Henrik Skupin [:whimboo][⌚️UTC+1] Assignee
	Comment 2 • 6 years ago

Sure about debug level, and the path it takes from Marionette to geckodriver. But I wonder what benefits it has to log the same thing twice. It's cluttering the logs a lot, and also takes some extra ms to find the right information while investigating problems. Also note that its length is not limited, so that for screenshots we log all the base64 data. I'm fine with that for `webdriver:server` because it allows me to see the screenshot taken in case of failures; we don't store those yet anywhere.

	Andreas Tolfsen ❲:ato❳
	Comment 3 • 6 years ago

(In reply to Henrik Skupin (:whimboo) from comment #2)

> Sure about debug level, and the path it takes from Marionette to
> geckodriver. But I wonder what benefits it has to log the same
> thing twice.  It's cluttering the logs a lot, and also takes
> some extra ms to find the right information while investigating
> problems.

So we are talking about three different modules doing three
different tasks here:

  (1) The Marionette server (Marionette)
  (2) The WebDriver-to-Marionette protocol adapter (geckodriver::marionette)
  (3) The WebDriver HTTP server (webdriver::server)

If we drop logging from the second one, we need to be aware that we
lose one level of granularity when checking if something went wrong.
If for example there’s a conversion or deserialisation problem in
the WebDriver-to/from-Marionette conversion the current log makes
it clear exactly how far a message got before an error occurred.
When an error from geckodriver::marionette is returned, the log
from webdriver::server wouldn’t distinguish between whether this
originated from the conversion, from the webdriver crate, or from
the server.

In any case, this needn’t be a blocker, but I just want to
highlight that whilst it may look better in the happy-path scenario
it can also make conversion errors harder to reason about.  They
arguably happen less often than server problems, so maybe this is a
worthwhile trade-off.

> Also note that its length is not limited, so that for
> screenshots we log all the base64 data. I'm fine with that for
> `webdriver:server` because it allows me to see the screenshot
> taken in case of failures; we don't store those yet anywhere.

This is orthogonal to its usefulness though.

There’s probably a point to be made that the log entries should be
limited like we do in the server, but this is a separate issue.

	Henrik Skupin [:whimboo][⌚️UTC+1] Assignee
	Comment 4 • 6 years ago

(In reply to Andreas Tolfsen ‹:ato› from comment #3)
> If we drop logging from the second one, we need to be aware that we
> lose one level of granularity when checking if something went wrong.
> If for example there’s a conversion or deserialisation problem in
> the WebDriver-to/from-Marionette conversion the current log makes
> it clear exactly how far a message got before an error occurred.

I would like to see how this looks like under such a failure condition. Would it be enough to just reply something different from Marionette, which then causes a failure in deserialisation in the webdriver crate?

	Andreas Tolfsen ❲:ato❳
	Comment 5 • 6 years ago

(In reply to Henrik Skupin (:whimboo) from comment #4)

> (In reply to Andreas Tolfsen ‹:ato› from comment #3)
> 
> > If we drop logging from the second one, we need to be aware that
> > we lose one level of granularity when checking if something went
> > wrong.  If for example there’s a conversion or deserialisation
> > problem in the WebDriver-to/from-Marionette conversion the
> > current log makes it clear exactly how far a message got before
> > an error occurred.
> 
> I would like to see how this looks like under such a failure
> condition.  Would it be enough to just reply something different
> from Marionette, which then causes a failure in deserialisation in
> the webdriver crate?

Yes.  Something that triggers an error in the deserialisation from
Marionette.

	Henrik Skupin [:whimboo][⌚️UTC+1] Assignee
	Comment 6 • 6 years ago

Ok, so I modified `findElement` to just return a number. Here how the log looks like:

> 1523622449925	Marionette	TRACE	0 <- [1,2,null,{"value":3}]
> 1523622449926	geckodriver::marionette	TRACE	<- [1,2,null,{"value":3}]
> 1523622449926	webdriver::server	DEBUG	<- 500 Internal Server Error {"value":{"error":"unknown error","message":"Failed to convert data to an object","stacktrace":""}}

So if the `value` key is present the failure happens in `webdriver::server`, and seeing the debug logging there it makes it clear for me. The code in `marionette.rs` just passes it through.

If the `value` key is not present, and we really fail in marionette.rs, the output looks like:

> 1523623156800	geckodriver::marionette	TRACE	<- [1,3,null,{"valu":3}]
> 1523623156800	webdriver::server	DEBUG	<- 500 Internal Server Error {"value":{"error":"unknown error","message":"Failed to find value field","stacktrace":""}}

With a possible patch applied to remove the logging from `geckodriver:marionette` we would have:

> 1523622449925	Marionette	TRACE	0 <- [1,2,null,{"value":3}]
> 1523622449926	webdriver::server	DEBUG	<- 500 Internal Server Error {"value":{"error":"unknown error","message":"Failed to convert data to an object","stacktrace":""}}

and

> 1523623156800	geckodriver::marionette	TRACE	<- [1,3,null,{"valu":3}]
> 1523623156800	webdriver::server	DEBUG	<- 500 Internal Server Error {"value":{"error":"unknown error","message":"Failed to find value field","stacktrace":""}}

So as long as the failure message from webdriver is clear enough, I don't see a loss here. IMHO it should be fine to remove.

Andreas, what's your take?

	Andreas Tolfsen ❲:ato❳
	Comment 7 • 6 years ago

It took me some time to understand what you were trying to say, but
that seems acceptable to me too.

	Andreas Tolfsen ❲:ato❳
	Comment 9 • 6 years ago
mozreview-review

Comment on attachment 8974296 [details]
Bug 1453307 - Remove geckodriver::marionette trace logging.

https://reviewboard.mozilla.org/r/242604/#review248518

::: testing/geckodriver/src/marionette.rs:1510
(Diff revision 1)
>          let data = String::from_utf8(payload).unwrap();
> -        trace!("<- {}", data);
>  
>          Ok(data)

Maybe just collapse the return value of String::from_utf8 into Ok(…)
instead of the unused variable assignment?

	Henrik Skupin [:whimboo][⌚️UTC+1] Assignee
	Comment 10 • 6 years ago
mozreview-review-reply

Comment on attachment 8974296 [details]
Bug 1453307 - Remove geckodriver::marionette trace logging.

https://reviewboard.mozilla.org/r/242604/#review248518

> Maybe just collapse the return value of String::from_utf8 into Ok(…)
> instead of the unused variable assignment?

`from_utf8()` returns a `std::result::Result<std::string::String, std::string::FromUtf8Error>`. So there is no need to put it into `Ok()` but at the same time doesn't work because we cannot convert from `std::string::FromUtf8Error` to `std::io::Error`. If you are ok with changing the line to just `Ok(String::from_utf8(payload).unwrap())` I could do it. Otherwise it looks to become more complex, and I feel the correct error handling should be done in a different bug.

	Andreas Tolfsen ❲:ato❳
	Comment 11 • 6 years ago

Right, if you want to go all the line and avoid .unwrap() you would
need to implement the From trait for that error.

	Henrik Skupin [:whimboo][⌚️UTC+1] Assignee
	Comment 12 • 6 years ago

(In reply to Andreas Tolfsen 「:ato」 from comment #11)
> Right, if you want to go all the line and avoid .unwrap() you would
> need to implement the From trait for that error.

I think that this is at best left for its own bug. So I will keep the comment from James in place.

	Pulsebot
	Comment 14 • 6 years ago

Pushed by hskupin@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/fdc0719e9607
Remove geckodriver::marionette trace logging. r=ato

	Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)
	Comment 15 • 6 years ago
bugherder

https://hg.mozilla.org/mozilla-central/rev/fdc0719e9607