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

RESOLVED FIXED in Firefox 60

Status

defect
P3
normal
RESOLVED FIXED
2 years ago
Last year

People

(Reporter: whimboo, Assigned: ato)

Tracking

({regression})

Version 3
mozilla61
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox-esr52 unaffected, firefox59 unaffected, firefox60 fixed, firefox61 fixed)

Details

Attachments

(1 attachment)

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
Flags: needinfo?(james)
Flags: needinfo?(ato)
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?
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?
Flags: needinfo?(mbrubeck)
Flags: needinfo?(james)
Flags: needinfo?(ato)
Keywords: regression
I'll investigate this, and in the meantime feel free to back out bug 1443257 if this is blocking things.
Flags: needinfo?(mbrubeck)
Blocks: 1441204
No longer blocks: 1401129
Priority: -- → P3
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.
`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
Thanks for digging into this mbrubeck!  This sounds easy enough to fix.
Assignee: nobody → ato
Status: NEW → ASSIGNED
Attachment #8957903 - Flags: review?(hskupin) → review?(james)
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?
Attachment #8957903 - Flags: review?(james) → review+
Pushed by atolfsen@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/f20cbd6c20fd
Filter logs from familiar logging targets. r=jgraham
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.
Blocks: 1444922
https://hg.mozilla.org/mozilla-central/rev/f20cbd6c20fd
Status: ASSIGNED → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla61
No longer blocks: 1441204
The landed fix has never been requested for uplift to beta. We need it to stop the failures from bug 1444831.
Whiteboard: [checkin-needed-beta]
Whiteboard: [checkin-needed-beta]
You need to log in before you can comment on or make changes to this bug.