Closed Bug 1384956 Opened 3 years ago Closed 2 years ago

listener.js logs DEBUG level even if not specified

Categories

(Testing :: Marionette, defect, P3)

Version 3
defect

Tracking

(firefox-esr52 unaffected, firefox55 wontfix, firefox56 wontfix, firefox57 wontfix, firefox58 fixed, firefox59 fixed)

RESOLVED FIXED
mozilla59
Tracking Status
firefox-esr52 --- unaffected
firefox55 --- wontfix
firefox56 --- wontfix
firefox57 --- wontfix
firefox58 --- fixed
firefox59 --- fixed

People

(Reporter: ato, Assigned: ato)

References

(Depends on 1 open bug)

Details

(Keywords: regression)

Attachments

(1 file)

The following workaround in testing/marionette/listener.js causes
all log entries at all levels to be dumped to stdout, irregardless
of the set log level when Marionette initialises:

> var logger = Log.repository.getLogger("Marionette");
> // Append only once to avoid duplicated output after listener.js gets reloaded
> if (logger.ownAppenders.length == 0) {
>   logger.addAppender(new Log.DumpAppender());
> }

This was added in
https://bugzilla.mozilla.org/show_bug.cgi?id=1357407.
https://bugzilla.mozilla.org/show_bug.cgi?id=1357407 seems to
indicate the logger isn’t set up correctly after a remoteness
change, causing calls to the logger to go missing.  Was a bug ever
filed on Log.jsm?
Flags: needinfo?(hskupin)
jgraham: This bug is what is causing the excessive output from
Firefox in WPT tests.
Andreas, which log entries do you mean? Our own ones from Marionette or everything? When I run marionette without `-v` I can clearly see that we also log DEBUG statements. But all other log output from Firefox is around for a long time, and should not have been regressed by this change.
Flags: needinfo?(hskupin)
(In reply to Henrik Skupin (:whimboo) from comment #3)

> [W]hich log entries do you mean? Our own ones from Marionette
> or everything? When I run marionette without `-v` I can clearly
> see that we also log DEBUG statements. But all other log output
> from Firefox is around for a long time, and should not have been
> regressed by this change.

I mean log entries to the Marionette repository.

In the following paste, I do not expect to see the last line
“Register listener.js”:

> % ./mach marionette test --gecko-log -
>  0:00.00 LOG: MainThread INFO Using workspace for temporary data: "/home/ato/src/gecko"
>  0:00.00 LOG: MainThread mozversion INFO application_buildid: 20170808154717
>  0:00.00 LOG: MainThread mozversion INFO application_display_name: Nightly
>  0:00.00 LOG: MainThread mozversion INFO application_id: {ec8030f7-c20a-464f-9b0e-13a3a9e97384}
>  0:00.00 LOG: MainThread mozversion INFO application_name: Firefox
>  0:00.00 LOG: MainThread mozversion INFO application_remotingname: firefox
>  0:00.00 LOG: MainThread mozversion INFO application_vendor: Mozilla
>  0:00.00 LOG: MainThread mozversion INFO application_version: 57.0a1
>  0:00.00 LOG: MainThread mozversion INFO platform_buildid: 20170808154717
>  0:00.00 LOG: MainThread mozversion INFO platform_version: 57.0a1
>  0:00.01 LOG: MainThread INFO Application command: /home/ato/src/gecko/obj-x86_64-pc-linux-gnu/dist/bin/firefox -no-remote -marionette -profile /tmp/tmpOYgpDl.mozrunner
> 1502203811130	Marionette	INFO	Enabled via --marionette
> 
> (firefox:27777): GConf-WARNING **: Client failed to connect to the D-BUS daemon:
> /usr/bin/dbus-launch terminated abnormally without any error message
> 
> (firefox:27777): GConf-WARNING **: Client failed to connect to the D-BUS daemon:
> /usr/bin/dbus-launch terminated abnormally without any error message
> 
> (firefox:27777): GConf-WARNING **: Client failed to connect to the D-BUS daemon:
> /usr/bin/dbus-launch terminated abnormally without any error message
> 1502203813055	Marionette	INFO	Listening on port 2828
>  0:02.73 LOG: MainThread INFO Profile path is /tmp/tmpOYgpDl.mozrunner
>  0:02.73 LOG: MainThread INFO Starting fixture servers
> 1502203813172	Marionette	DEBUG	Register listener.js for window 2147483649
Ok, so my assumption from comment 3. Thanks for the feedback. Marking as regression for now, but not sure when I will find the time to work on this bug. If it's getting more annoying we might prioritize it higher.
Blocks: 1357407
Keywords: regression
Priority: -- → P3
Oh, maybe this is related to all the other DEBUG output from Firefox which we also get.
Summary: listener.js logs everything, irregardless of set log level → listener.js logs DEBUG level even if not specified
Duplicate of this bug: 1275270
No longer blocks: 1399441
Speaking to mossop last week, it appears the problem is that Log.jsm
isn’t e10s compatible.  Marionette uses Log.jsm in a content frame
script that is injected via loadFrameScript.

When Log.repository.getLogger("Marionette") is called and the
process is remote, it doesn’t inherit the logger configuration for
the "Marionette" repository we set up earlier in the main process.
This explains why the problem only exhibits following a remoteness
change to the <xul:browser>.
Summary: listener.js logs DEBUG level even if not specified → Log.jsm not e10s compatible
Summary: Log.jsm not e10s compatible → listener.js logs DEBUG level even if not specified
Depends on: 1411513
We can work around this by getting the current log level from the
main process.
Assignee: nobody → ato
Status: NEW → ASSIGNED
No longer depends on: 1411513
(In reply to Andreas Tolfsen ‹:ato› from comment #9)
> We can work around this by getting the current log level from the
> main process.

Sounds like a good idea. But lets leave bug 1411513 as dependency on this bug, so that we are getting notified once it got fixed, and we can remove the workaround.
Depends on: 1411513
Comment on attachment 8927612 [details]
Bug 1384956 - Get log level from main process when script is reloaded.

https://reviewboard.mozilla.org/r/198904/#review204048
Attachment #8927612 - Flags: review?(hskupin) → review+
(In reply to Henrik Skupin (:whimboo) from comment #11)
> (In reply to Andreas Tolfsen ‹:ato› from comment #9)
> > We can work around this by getting the current log level from the
> > main process.
> 
> Sounds like a good idea. But lets leave bug 1411513 as dependency on this
> bug, so that we are getting notified once it got fixed, and we can remove
> the workaround.

Sure, and thanks for the quick turnaround!
Pushed by atolfsen@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/9bbdf1312345
Get log level from main process when script is reloaded. r=whimboo
https://hg.mozilla.org/mozilla-central/rev/9bbdf1312345
Status: ASSIGNED → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla59
Andreas, I would say that we should also get this fixed for 58 too if it works.

I just had a look and I can still see debug output for wdspec tests. So is this not fixed yet?

https://treeherder.mozilla.org/logviewer.html#?job_id=144954307&repo=autoland&lineNumber=5073
Flags: needinfo?(ato)
(In reply to Henrik Skupin (:whimboo) from comment #16)

> Andreas, I would say that we should also get this fixed for 58 too
> if it works.

Yes, I’d say this is a good patch to uplift.

> I just had a look and I can still see debug output for wdspec
> tests. So is this not fixed yet?
>
> https://treeherder.mozilla.org/logviewer.html#?job_id=144954307&repo=autoland&lineNumber=5073

I am not sure yet, but I suspect this is a case of geckodriver
picking up the system installation of Firefox instead of the
Firefox-under-test that AutomatedTester reported yesterday.  We
discovered that because some New Session capabilities merging code
that has been fixed in WPT upstream hadn’t yet made it to m-c, the
system Firefox would occasionally be picked up.
Flags: needinfo?(ato)
(In reply to Andreas Tolfsen ‹:ato› from comment #17)
> I am not sure yet, but I suspect this is a case of geckodriver
> picking up the system installation of Firefox instead of the
> Firefox-under-test that AutomatedTester reported yesterday.

Andreas, once we know that this is the case can you make sure to flag this patch for uplift? Thanks.
Flags: needinfo?(ato)
setting 58 to fix-optional to get this off my list, I guess this can be uplifted as test-only when the time comes.
This looks actually fine now. So lets get this test harness patch uplifted to mozilla-beta. Thanks.
Flags: needinfo?(ato)
Whiteboard: [checkin-needed-beta]
Whiteboard: [checkin-needed-beta]
You need to log in before you can comment on or make changes to this bug.