1444431 - Excessive Debug/Trace logging of hyper with -vv log level

Status: RESOLVED FIXED

(Testing :: geckodriver, defect, P3)

Description

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

I thought that we restrict debug and trace logs only to geckodriver/webdriver/mozrunner/mozprofile and Firefox/Marionette, but as I can see in the wdspec tests we get a massive amount of hyper debug/trace lines logged:

https://treeherder.mozilla.org/logviewer.html#?job_id=166971005&repo=autoland&lineNumber=281432

Did something change lately for our logging? Maybe it should block the 0.20 release?

[task 2018-03-09T13:08:00.385Z] 13:08:00     INFO - PID 5876 | 1520600877459	hyper::header	TRACE	Headers.set( "Connection", Connection([Close]) )
[task 2018-03-09T13:08:00.386Z] 13:08:00     INFO - PID 5876 | 1520600877459	hyper::http::h1	TRACE	Sized read, remaining=29
[task 2018-03-09T13:08:00.386Z] 13:08:00     INFO - PID 5876 | 1520600877459	hyper::http::h1	TRACE	Sized read: 29
[task 2018-03-09T13:08:00.387Z] 13:08:00     INFO - PID 5876 | 1520600877459	hyper::http::h1	TRACE	Sized read, remaining=0

Comment 1

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

Looks like it started with the following changeset on mozilla-central:
https://hg.mozilla.org/mozilla-central/pushloghtml?changeset=f1965cf7425fe422c9e9c78018f11b97e0a0f229

Even when I build geckodriver locally from the latest m-c changeset, I cannot reproduce it with -vv. Why does it only happen in CI?

Comment 2

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

The reason for that is the upgrade of the log crate from version 0.3.8 to 0.3.9 on bug 1443257.

I wonder if some API has been changed for log even it is a minor version bump. Matt, could you have a look?

Comment 3

[Matt Brubeck (:mbrubeck)]

I'll investigate this, and in the meantime feel free to back out bug 1443257 if this is blocking things.

Comment 4

[Andreas Tolfsen ❲:ato❳]

I would’ve expected this to have changed with
https://bugzilla.mozilla.org/show_bug.cgi?id=1436830.  We used to
have some pretty stupid filtering mechanisms for only looking at
log entries matching certain strings.

Comment 5

[Matt Brubeck (:mbrubeck)]

`geckodriver` uses `log 0.4`, but it depends on a version of `hyper` that uses `log 0.3`.

Previously this meant that geckodriver's `Logger` could only see messages from crates using log 0.4, and had no access to messages from `hyper` or other crates using log 0.3.  However, log 0.3.9 added interoperability so that programs built with a mix of log 0.3 and log 0.4 can again display messages from all crates:

https://github.com/rust-lang-nursery/log/pull/217

(This would also have happened if geckodriver updated to a newer version of hyper.)

You can filter out these messages by returning `false` here when `meta.target()` does not start with a crate name whose messages you want to log:

https://searchfox.org/mozilla-central/rev/40b1baaab5aba21223590ae1029e916dfd5ff7cd/testing/geckodriver/src/logging.rs#1361

Comment 6

[Andreas Tolfsen ❲:ato❳]

Thanks for digging into this mbrubeck!  This sounds easy enough to fix.

Comment 7

[Andreas Tolfsen ❲:ato❳]

Attachment: Bug 1444431 - Filter logs from familiar logging targets.

geckodriver uses log 0.4, but it depends on a version of hyper that
uses log 0.3.

Previously this meant that geckodriver's logger could only see
messages from crates using log 0.4, and had no access to messages
from hyper or other crates using log 0.3.  However, log 0.3.9 added
interoperability so that programs built with a mix of log 0.3 and
log 0.4 can again display messages from all crates.

This patches geckodriver::logging to contain a whitelist of logged
targets we care about.  Currently this list includes geckodriver,
mozprofile, mozrunner, mozversion, and webdriver.  This will revert
us to the behaviour prior to upgrading hyper to use log 0.3.9,
and would be similar to the old implementation we had for filtering
logs we had when geckodriver used slog.

Thanks-to: Matt Brubeck <[e-mail]>

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

Comment 8

[James Graham [:jgraham]]

Comment on attachment 8957903 [details]
Bug 1444431 - Filter logs from familiar logging targets.

https://reviewboard.mozilla.org/r/226866/#review232756

::: testing/geckodriver/src/logging.rs:142
(Diff revision 1)
>  
>  struct Logger;
>  
>  impl log::Log for Logger {
>      fn enabled(&self, meta: &log::Metadata) -> bool {
> -        meta.level() <= log::max_level()
> +        LOGGED_TARGETS.iter().any(|&x| meta.target().starts_with(x))

I assume that this isn't an unacceptable performance burden because of the small size of the set? Did we measure anything here?

Comment 9

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/f20cbd6c20fd
Filter logs from familiar logging targets. r=jgraham

Comment 10

[(not currently active) Ted Mielczarek]

FWIW, that's roughly the same thing that env_logger does:
https://github.com/sebasmagri/env_logger/blob/4d7926c515a8620e7fa0e91a07047023170c1064/src/filter/mod.rs#L341

It would probably be nicer if the log crate's interface provided the crate name as a separate String so you could use a set instead of having to do a string prefix match, but that's a more invasive change.

Comment 11

[Eliza Balazs [:ebalazs_]]

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

Comment 12

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

The landed fix has never been requested for uplift to beta. We need it to stop the failures from bug 1444831.

Comment 13

[Cosmin Sabou [:CosminS]]

Revision from mozilla beta: https://hg.mozilla.org/releases/mozilla-beta/rev/f66887206a10ef7d176226b693be208952bc3868

Comment 14

[Ryan VanderMeulen [:RyanVM]]

Uplift of the actual fix for this bug:
https://hg.mozilla.org/releases/mozilla-beta/rev/ca36ebc45fd4