Closed Bug 1444431 Opened 5 years ago Closed 5 years ago

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


(Testing :: geckodriver, defect, P3)

Version 3


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

Tracking Status
firefox-esr52 --- unaffected
firefox59 --- unaffected
firefox60 --- fixed
firefox61 --- fixed


(Reporter: whimboo, Assigned: ato)



(Keywords: regression)


(1 file)

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:

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:

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  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:

(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 `` does not start with a crate name whose messages you want to log:
Thanks for digging into this mbrubeck!  This sounds easy enough to fix.
Assignee: nobody → ato
Attachment #8957903 - Flags: review?(hskupin) → review?(james)
Comment on attachment 8957903 [details]
Bug 1444431 - Filter logs from familiar logging targets.

::: testing/geckodriver/src/
(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|

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
Filter logs from familiar logging targets. r=jgraham
FWIW, that's roughly the same thing that env_logger does:

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
Closed: 5 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.