Closed Bug 1382968 Opened 7 years ago Closed 7 years ago

console calls shouldn't be piped to the parent until it is any useful

Categories

(DevTools :: Console, defect)

Product:
DevTools
Component:
Console
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(Performance Impact:high, firefox57 fixed)

Status:
RESOLVED FIXED
Milestone:
Firefox 57
Project Flags:
Performance Impact high
Tracking Flags:
Tracking Status
firefox57 --- fixed

People

(Reporter: ochameau, Assigned: ochameau)

References

Details

Attachments

(4 files)

Bug 1382968 - Only try to forward console messages from content processes to parent when browser console/toolbox are opened.
59 bytes, text/x-review-board-request
jryans
: review+
Details
Bug 1382968 - Move console actor helper modules to a dedicated folder.
59 bytes, text/x-review-board-request
jryans
: review+
Details
Bug 1382968 - Flag Browser Console target as being chrome and related to a TabActor.
59 bytes, text/x-review-board-request
jryans
: review+
Details
Bug 1382968 - Make WebExtension debugging test better test console behavior.
59 bytes, text/x-review-board-request
rpl
: review+
Details 
While looking at a recent regression, bug 1380449, I realized that the "processsingleton" code was piping absolutely all console calls from content to parent, without any conditions, so, always.

Here is the code:
http://searchfox.org/mozilla-central/source/toolkit/components/processsingleton/MainProcessSingleton.js#21-24
http://searchfox.org/mozilla-central/source/toolkit/components/processsingleton/ContentProcessSingleton.js#50-107

It basically pipes all "console-api-log-event" from content to parent.

If I understand all the console codebase correctly, this is only useful for the "Browser Console" and the "Browser Toolbox". That allows seeing calls to console made by websites and see everything. This was the original behavior of the browser console before e10s appeared and we kept that behavior.

If you ignore this bug, the typical behavior of devtools codebase is to listen to console-api-log-event *ONLY* if a console is opened. So for the regular webconsole, we do not listen, nor do anything until a console is opened against a tab. Then when you do open one, we listen and start slowing things down.

I believe we should:
1/ Move most of this processsingleton component to /devtools as it really relates to devtools more than any standard platform feature.
2/ Run this component *only* when we open either the browser console/toolbox!
3/ And ideally turn it off if we close the browser console/toolbox
I don't get why/how DAMP missed regression reported in bug 1380449,
but with this patch I see a 4x win. Test case goes from 4s to 1s:
  for(var i = 0; i < 10000; i++) {
    console.log('log test', {}, [], window, document, document.documentElement);
  }

The performance win is when you run this code in a tab and do not open any tool.
I'm kind of on the fence about this. There have been some times when we've lost ordinary error reporting when the console wasn't opened, and it's always caused complaints. But I guess I can live with it, if it's really necessary.

Can we at least try to make sure we get errors reported with console.error, though, especially if they're native exceptions or error objects?
(In reply to Kris Maglione [:kmag] from comment #3)
> I'm kind of on the fence about this. There have been some times when we've
> lost ordinary error reporting when the console wasn't opened, and it's
> always caused complaints. But I guess I can live with it, if it's really
> necessary.
> 
> Can we at least try to make sure we get errors reported with console.error,
> though, especially if they're native exceptions or error objects?

If a page logs a message and then the toolbox gets opened later, it needs to be there. I'm not sure if the proposal here changes that behavior, but I'd be against it if so.

Note that this case runs through getCachedMessages in the devtools actor (https://dxr.mozilla.org/mozilla-central/source/devtools/server/actors/utils/webconsole-listeners.js#329), which is distinct from the "console-api-log-event" message, which indeed is only observed once the toolbox is opened on a page (or when the Browser Console / Browser Toolbox is opened).
Yes.

First, console-api-log-event is only for catching console log calls, it isn't used for js/css errors.
Second, it is only for catching console log calls "live".
It won't change anything regarding things happening before the tools open.

I imagine you faced issues around either:
* nsIConsoleAPIStorage.getEvents or ConsoleAPIListener.getCachedMessages
https://dxr.mozilla.org/mozilla-central/source/dom/console/nsIConsoleAPIStorage.idl
https://dxr.mozilla.org/mozilla-central/source/devtools/server/actors/utils/webconsole-listeners.js#329
 For missing console log calls
* nsIConsoleService.getMessageArray or ConsoleServiceListener.getCachedMessages
https://dxr.mozilla.org/mozilla-central/source/xpcom/base/nsIConsoleService.idl
https://dxr.mozilla.org/mozilla-central/source/devtools/server/actors/utils/webconsole-listeners.js#130
 For missing error reports

Note that under memory pressure, these components are going to flush their cached messages.
Also, they store only a limited number of messages, nsIConsoleAPIStorage has a one storage per window limited to 1000 items. This one should be fine. But nsIConsoleService is only 250 for the whole process...
https://dxr.mozilla.org/mozilla-central/source/dom/console/ConsoleAPIStorage.js#17
https://dxr.mozilla.org/mozilla-central/source/xpcom/base/nsConsoleService.cpp#73
That may just be that...

Please, report any STR if you see something being lost.
Comment on attachment 8888711 [details]
Bug 1382968 - Only try to forward console messages from content processes to parent when browser console/toolbox are opened.

Brian, Any idea why DAMP doesn't catch this significant (4X!) win??

https://treeherder.mozilla.org/perf.html#/comparesubtest?originalProject=try&originalRevision=5b8b01b46bae6796ff6644437493d08bcb8f27c4&newProject=try&newRevision=26e91109a66b474c6c4359029cd062bba06cbd62&originalSignature=edaec66500db21d37602c99daa61ac983f21a6ac&newSignature=edaec66500db21d37602c99daa61ac983f21a6ac&framework=1

This DAMP test should be highlighting this:
http://searchfox.org/mozilla-central/source/testing/talos/talos/tests/devtools/addon/content/damp.js#192-200

I'm running it locally with:
   ./mach talos-test --activeTests damp
Do you know if we can restrict it to only run this console log tests?
I would like to ensure covering this kind of regression in the future.
Attachment #8888711 - Flags: review?(bgrinstead)
(In reply to Alexandre Poirot [:ochameau] from comment #6)
> Comment on attachment 8888711 [details]
> Bug 1382968 - Only try to forward console messages from content processes to
> parent when browser console/toolbox are opened. ?
> 
> Brian, Any idea why DAMP doesn't catch this significant (4X!) win??
> 
> https://treeherder.mozilla.org/perf.html#/
> comparesubtest?originalProject=try&originalRevision=5b8b01b46bae6796ff6644437
> 493d08bcb8f27c4&newProject=try&newRevision=26e91109a66b474c6c4359029cd062bba0
> 6cbd62&originalSignature=edaec66500db21d37602c99daa61ac983f21a6ac&newSignatur
> e=edaec66500db21d37602c99daa61ac983f21a6ac&framework=1
> 
> This DAMP test should be highlighting this:
> http://searchfox.org/mozilla-central/source/testing/talos/talos/tests/
> devtools/addon/content/damp.js#192-200
> 
> I'm running it locally with:
>    ./mach talos-test --activeTests damp
> Do you know if we can restrict it to only run this console log tests?
> I would like to ensure covering this kind of regression in the future.

I don't know why it isn't catching it, perhaps we are starting the timer too late. I'm guessing we need to start timing before sending the frame script that does the logs, like here: https://dxr.mozilla.org/mozilla-central/source/testing/talos/talos/tests/devtools/addon/content/damp.js?offset=800#150.

To restrict to console tests locally you can comment out all but these two in the subtests object: https://dxr.mozilla.org/mozilla-central/source/testing/talos/talos/tests/devtools/addon/content/damp.html#20-21.
Comment on attachment 8888711 [details]
Bug 1382968 - Only try to forward console messages from content processes to parent when browser console/toolbox are opened.

https://reviewboard.mozilla.org/r/159738/#review167010

I don't think I'm the best reviewer for this. Maybe billm or baku?
Attachment #8888711 - Flags: review?(bgrinstead)
Attachment #8888711 - Flags: review?(wmccloskey)
Comment on attachment 8888711 [details]
Bug 1382968 - Only try to forward console messages from content processes to parent when browser console/toolbox are opened.

https://reviewboard.mozilla.org/r/159738/#review167484

I can't claim to be any sort of expert here. But it seems like the right fix would be to:
1. Only forward console-api-log-event when the console is open.
2. Somehow make it possible for the parent process to read the child process's cached ConsoleAPIStorage messages.

It seems like the patch here does #1 but not #2. I think we should do both. If you do that, then feel free to get someone else to review.
Attachment #8888711 - Flags: review?(wmccloskey) → review-
I think these is some misunderstanding here as you may not know the devtools codebase. I'm not modifying the existing listening code. The browser console will listen from the parent process, where it lives. Both browser console and its console actor live in the parent process.
The browser console will instantiate a console actor, like the regular Web console.
So that it is going to listen for console-api-log-event from here:
http://searchfox.org/mozilla-central/source/devtools/server/actors/utils/webconsole-listeners.js#236
Attachment #8888711 - Flags: review- → review?(amarchesini)
Oh, I see. So the webconsole-listener.js code only runs when the console is open?

I still think we should do #2 so that people can see old console messages from content scripts. But I guess that's never been possible.
Comment on attachment 8888711 [details]
Bug 1382968 - Only try to forward console messages from content processes to parent when browser console/toolbox are opened.

https://reviewboard.mozilla.org/r/159738/#review167668

I think you need a devtool peer for this patch. I'm not confident enough to view it.
Attachment #8888711 - Flags: review?(amarchesini)
(In reply to Bill McCloskey (:billm) from comment #11)
> Oh, I see. So the webconsole-listener.js code only runs when the console is
> open?
> 
> I still think we should do #2 so that people can see old console messages
> from content scripts. But I guess that's never been possible.

The console actor (again used in both Browser and Web consoles), also pull messages logged before the console opened by using ConsoleAPIStorage from here:
http://searchfox.org/mozilla-central/source/devtools/server/actors/utils/webconsole-listeners.js#329-343
http://searchfox.org/mozilla-central/source/dom/console/ConsoleAPIStorage.js

I think the fact that noone is confident reviewing this patch highlights how unsupported/unknown this codepath was,
which led to the precise issue I'm trying to get rid here.
Comment on attachment 8888711 [details]
Bug 1382968 - Only try to forward console messages from content processes to parent when browser console/toolbox are opened.

Ryan, Tom, you are my two last chances. After that I'll consider landing that with r=me...
Attachment #8888711 - Flags: review?(ttromey)
Attachment #8888711 - Flags: review?(jryans)
If we proceed with this patch, processsingleton will only be used for Telemetry, it may be interesting to followup on that to load it from somewhere else? Or keep it to load more things from it, like what we did for Telemetry in bug 1355611.
Comment on attachment 8888711 [details]
Bug 1382968 - Only try to forward console messages from content processes to parent when browser console/toolbox are opened.

https://reviewboard.mozilla.org/r/159738/#review167926

Thanks for doing this.

This seems like a good idea to me.  My only question is whether there are tests covering the important scenario, which I think is when the page logs things before the console is opened.  I didn't look through the existing console tests to see if there is one, but if there is, then I think that's sufficient.

I'd suggest waiting for :jryans to review as well.

::: devtools/client/framework/devtools-browser.js:801
(Diff revision 1)
> +
> +  stopForwardingContentProcessMessage() {
> +    if (this.logConsoleMessage) {
> +      Services.ppmm.broadcastAsyncMessage("DevTools:StopForwardingContentProcessMessage");
> +      Services.ppmm.removeMessageListener("Console:Log", this.logConsoleMessage);
> +      Services.ppmm.removeDelayedProcessScript("resource://devtools/client/framework/content-process-forward.js");

I mildly prefer the DRY style of using constants for names like this, to avoid the possibility of future typos.  However I think it's a minor thing, and other code nearby seems to use literals, so up to you if you want to change it.
Attachment #8888711 - Flags: review?(ttromey) → review+
Comment on attachment 8888711 [details]
Bug 1382968 - Only try to forward console messages from content processes to parent when browser console/toolbox are opened.

https://reviewboard.mozilla.org/r/159738/#review167932

The overall concept seems reasonable to me, but I think the design is slightly odd.  Shouldn't this be something that's managed server side by the console actor?  It seems unusual for the client to be triggering code that shuttles debuggee data around like this.

Can we move content-process-forward.js to the server, and then have the console actor do the steps you currently have in devtools-browser.js?
Attachment #8888711 - Flags: review?(jryans) → review-
(In reply to Alexandre Poirot [:ochameau] from comment #13)
> (In reply to Bill McCloskey (:billm) from comment #11)
> > Oh, I see. So the webconsole-listener.js code only runs when the console is
> > open?
> > 
> > I still think we should do #2 so that people can see old console messages
> > from content scripts. But I guess that's never been possible.
> 
> The console actor (again used in both Browser and Web consoles), also pull
> messages logged before the console opened by using ConsoleAPIStorage from
> here:
> http://searchfox.org/mozilla-central/source/devtools/server/actors/utils/
> webconsole-listeners.js#329-343
> http://searchfox.org/mozilla-central/source/dom/console/ConsoleAPIStorage.js

That's true, but this code doesn't pull message from the child process's ConsoleAPIStorage. And ConsoleAPIStorage doesn't listen for the observer notifications. It just gets them directly from the platform console implementation. So any console.log calls from frame scripts in the content process will be lost if the console isn't open. This is not a regression from your patch. But it's something we should fix eventually.
Thanks for your reviews Tom et Ryan!

(In reply to Bill McCloskey (:billm) from comment #18)
>
> That's true, but this code doesn't pull message from the child process's
> ConsoleAPIStorage. And ConsoleAPIStorage doesn't listen for the observer
> notifications. It just gets them directly from the platform console
> implementation. So any console.log calls from frame scripts in the content
> process will be lost if the console isn't open. This is not a regression
> from your patch. But it's something we should fix eventually.

Ok, I see now. I would like to know more about the usage of the browser console.
For me, and I think it may be the same for other DevTools contributors,
it was mostely focused on debugging the chrome and so the parent process.
I didn't really knew about the code I'm patching here.

In order to debug add-ons, luca worked on the Addon toolboxes, that you can access via about:debugging.
These ones should catch all the messages correctly, but this is specific to a given add-on.

The browser console looks like a handy way to see everything in the same place.
Is that why you are expecting to see everything appear in it?
Then, yes, we have to review it, as, obviously, watching for everything, is going to slow down Firefox!
I'm wondering if we should have it configurable to make it less slow if you only care about the parent process.
I haven't added tests as the feature modified by this patch is already covered by this one:
http://searchfox.org/mozilla-central/source/devtools/client/webconsole/test/browser_console_clear_method.js#13-20
(but that's not the only test checking for the browser console behavior)

(In reply to Tom Tromey :tromey from comment #16)
> Comment on attachment 8888711 [details]
> Bug 1382968 - Only try to forward console messages from content processes to
> parent when browser console/toolbox are opened.
> 
> https://reviewboard.mozilla.org/r/159738/#review167926
> 
> Thanks for doing this.
> 
> This seems like a good idea to me.  My only question is whether there are
> tests covering the important scenario, which I think is when the page logs
> things before the console is opened.  I didn't look through the existing
> console tests to see if there is one, but if there is, then I think that's
> sufficient.

I can't introduce such test as it is currently broken and this patch doesn't change anything regarding console API call happening before the opening.
(You can easily reproduce that by loading:
 data:text/html,<script>console.log("foo");</script>
 and opening the browser console before/after this document load)

But fixing that sounds like a good followup, which, after trying to fill it, appear to already exists, bug 1241289.
Comment on attachment 8892515 [details]
Bug 1382968 - Move console actor helper modules to a dedicated folder.

We start to have too many random files in this utils folder,
so I decided to group all the console ones in its dedicated folder.

I hesitated to also drop the "webconsole-" in file names, what do you think?
Comment on attachment 8892516 [details]
Bug 1382968 - Flag Browser Console target as being chrome and related to a TabActor.

In the main patch, I need to identify from the client codebase if we are opening the console in the Browser Console or the Browser Toolbox.
I haven't found any way to identify the browser toolbox,
so I came up with this patch.

I need such check from devtools/client/webconsole/webconsole-connection-proxy.js
Comment on attachment 8892515 [details]
Bug 1382968 - Move console actor helper modules to a dedicated folder.

https://reviewboard.mozilla.org/r/163482/#review169014

::: devtools/server/actors/webconsole/moz.build:8
(Diff revision 1)
> -    'map-uri-to-addon-id.js',
> -    'shapes-geometry-utils.js',
> -    'stack.js',
> -    'TabSources.js',
> -    'walker-search.js',
>      'webconsole-listeners.js',

I'd say yes, remove the `webconsole-` prefix.  It's redundant now that you have the directory.
Attachment #8892515 - Flags: review?(jryans) → review+
Comment on attachment 8888711 [details]
Bug 1382968 - Only try to forward console messages from content processes to parent when browser console/toolbox are opened.

https://reviewboard.mozilla.org/r/159738/#review169032

Great, this design makes more sense to me. :)

I am a bit unsure about the target type, so let's try to work out those details first.

::: devtools/client/webconsole/webconsole-connection-proxy.js:181
(Diff revision 2)
>     * @private
>     */
>    _attachConsole: function () {
>      let listeners = ["PageError", "ConsoleAPI", "NetworkActivity",
>                       "FileActivity"];
> +    if (this.webConsoleFrame.isBrowserConsole ||

Hmm, don't you want this in most places where `target.chrome == true`?

(Why does the browser console set[1] `chrome: false`?  Even the comment doesn't explain it to me...  Maybe it predates the `isTabActor` flag.  Can we change it to `chrome: true, isTabActor: false`?)

It looks like the other `chrome: true` cases are the browser content toolbox and add-on toolboxes.  What's the expected behavior for those?

[1]: http://searchfox.org/mozilla-central/rev/bbc1c59e460a27b20929b56489e2e55438de81fa/devtools/client/webconsole/hudservice.js#194
Attachment #8888711 - Flags: review?(jryans) → review-
Comment on attachment 8892516 [details]
Bug 1382968 - Flag Browser Console target as being chrome and related to a TabActor.

https://reviewboard.mozilla.org/r/163484/#review169034

I'd like to work out whether we really need this first, see comments on the later patch.
Attachment #8892516 - Flags: review?(jryans)
(In reply to J. Ryan Stinnett [:jryans] (use ni?) from comment #27)
> Comment on attachment 8888711 [details]
> Bug 1382968 - Only try to forward console messages from content processes to
> parent when browser console/toolbox are opened.
> 
> https://reviewboard.mozilla.org/r/159738/#review169032
> 
> Great, this design makes more sense to me. :)
> 
> I am a bit unsure about the target type, so let's try to work out those
> details first.
> 
> ::: devtools/client/webconsole/webconsole-connection-proxy.js:181
> (Diff revision 2)
> >     * @private
> >     */
> >    _attachConsole: function () {
> >      let listeners = ["PageError", "ConsoleAPI", "NetworkActivity",
> >                       "FileActivity"];
> > +    if (this.webConsoleFrame.isBrowserConsole ||
> 
> Hmm, don't you want this in most places where `target.chrome == true`?

I don't think that's what we want.
We only want the Browser console and toolbox.

For the Browser content toolbox, we don't need the piping as the console actor is hooked into the content process and catch everything we want. There is no need to pipe any message to the parent. There isn't even any console actor in parent to listen for any piped message.

It is more complex for the Add-on toolboxes as we have two different setup:
* OOP WebExtension, which may become the only one default in FF57?
  This usecase should be like Browser content toolbox, the console actor is going to live in extension process and should catch everything we want. But there may be some edge cases with content script, which, I imagine would need some new specific piping.
* In parent process add-on, web-extension or bootstrapped
  It may help debugging content script debugging to keep the piping, but tbh, I don't know how that work today.
  This is the only usecase that may benefit from message piping as its console actor lives in the parent process.

Luca, could you confirm what happens regarding content scripts in the Add-on toolboxes?

> (Why does the browser console set[1] `chrome: false`?  Even the comment
> doesn't explain it to me...  Maybe it predates the `isTabActor` flag.  Can
> we change it to `chrome: true, isTabActor: false`?)

By default isTabActor will be considered to be true:
http://searchfox.org/mozilla-central/source/devtools/client/framework/target.js#137-142
And we want to keep it to match HUDService comment, we want to call attachTab and not attachConsole.
Here is the change that happened during isTabActor introduction:
http://searchfox.org/mozilla-central/diff/9ddabe806107298baf0fd3c066483f617b4be334/browser/devtools/framework/target.js#451-459
So yes, before this patch we had to set chrome to false to get the right behavior,
I think we can now use in HUDService: { chrome: true, isTabActor: true }

It looks like it shouldn't change anything in Browser console behavor, as target.chrome is only used in toolbox, definitions and inspector:
http://searchfox.org/mozilla-central/search?q=target.chrome&case=false&regexp=false&path=

Should I provide a patch to toggle chrome anyway, even if that doesn't help the message piping story?
Flags: needinfo?(lgreco)
(In reply to Alexandre Poirot [:ochameau] from comment #29)
> Luca, could you confirm what happens regarding content scripts in the Add-on
> toolboxes?

Yes, In the Add-on toolboxes we are not assuming that any content scripts log messages could be piped to it
(the content scripts logs are currently logged in the webconsole from the related tab,
basically the content scripts are accessing the console object of the target window and their console messages are collected by the tab toolbox's webconsole from the same source of the other console messages coming from that window,
in other words: it would be great to unify all the extension logging into one place at some point, but it is not what it is currently happening).
Flags: needinfo?(lgreco)
(In reply to Alexandre Poirot [:ochameau] from comment #29)
> So yes, before this patch we had to set chrome to false to get the right
> behavior,
> I think we can now use in HUDService: { chrome: true, isTabActor: true }
> 
> It looks like it shouldn't change anything in Browser console behavor, as
> target.chrome is only used in toolbox, definitions and inspector:
> http://searchfox.org/mozilla-central/search?q=target.
> chrome&case=false&regexp=false&path=
> 
> Should I provide a patch to toggle chrome anyway, even if that doesn't help
> the message piping story?

Yes, please add this as a separate patch, just for some future sanity.  This bug or another bug, whichever you like.  (I agree you would in fact want `isTabActor: true`.)
Once we change browser console to set chrome: true, it sounds you could use "target.chrome && !target.isAddon`, is that right?
Flags: needinfo?(poirot.alex)
(In reply to J. Ryan Stinnett [:jryans] (use ni?) from comment #32)
> Once we change browser console to set chrome: true, it sounds you could use
> "target.chrome && !target.isAddon`, is that right?

Yes, it looks correct with such check.

I just pushed a new patch queue, with the browser console target change, which replaces my previous patch with target.isBrowserToolbox.
Flags: needinfo?(poirot.alex)
Comment on attachment 8892516 [details]
Bug 1382968 - Flag Browser Console target as being chrome and related to a TabActor.

https://reviewboard.mozilla.org/r/163484/#review170826

Thanks for this, one less confusing kind of target! :)
Attachment #8892516 - Flags: review?(jryans) → review+
Comment on attachment 8888711 [details]
Bug 1382968 - Only try to forward console messages from content processes to parent when browser console/toolbox are opened.

https://reviewboard.mozilla.org/r/159738/#review170828

Looks good, thanks for reworking the design! :)
Attachment #8888711 - Flags: review?(jryans) → review+
Quick word about the actual perf improvement here:

Profile with this patch:
  https://perf-html.io/public/eaae4a6404ee702c548aaefd0fc84a26e938d80f/calltree/?hiddenThreads=&thread=2&threadOrder=0-2-1

Profile without it:
  https://perf-html.io/public/ca94419056aacad1eeba4c2dbd2c025b8734ac60/calltree/?hiddenThreads=&thread=2&threadOrder=0-2-1

Made while opening this document:
  data:text/html,<script>for(let i=0;i<10000; i++) console.log("foo", document, document.documentElement, 1);</script>

If you look at nsHtml5TreeOpExecutor::RunFlushLoop (which contains all the console api calls),
we go from 4517ms to 1453ms, which confirms the 4x win reported earlier.

It is interesting to see that if you filter with "processsingleton" in the profile without this patch,
this removed code was only being reported as lasting about 1s, whereas we win about 3s at the end.

After this patch is landed, now most of the time is spent in ConsoleAPIStorage.recordEvent (634ms):
  http://searchfox.org/mozilla-central/source/dom/console/ConsoleAPIStorage.js#124
And it is surprising but most of it seems to be coming from a call to Cu.cloneInto (428ms):
  http://searchfox.org/mozilla-central/source/dom/console/ConsoleAPIStorage.js#132-135
I get down to 227ms (compared to 634) if I comment this cloneInto line:
  https://perfht.ml/2wpanmB
Pushed by apoirot@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/869a9b46b5cc
Move console actor helper modules to a dedicated folder. r=jryans
https://hg.mozilla.org/integration/autoland/rev/5a2260bc98ca
Flag Browser Console target as being chrome and related to a TabActor. r=jryans
https://hg.mozilla.org/integration/autoland/rev/e25b4bd21ac8
Only try to forward console messages from content processes to parent when browser console/toolbox are opened. r=jryans,tromey
Oh that wasn't an easy one to see coming...

extensions.webextensions.remote is true on Windows only.
It makes the WebExtension run in another process and console-api-log-event is no longer fired in the parent process.

https://hg.mozilla.org/integration/autoland/diff/e25b4bd21ac8/devtools/server/actors/webconsole/listeners.js#l1.55
The forward code living in the parent process here, not longer spawn a console-api-log-event,
but instead directly call WebConsoleActor.onConsoleAPICall and this test no longer receive its observer event...

This check against console-api-log-event is pretty weak, it doesn't check if the console in the browser toolbox display anything, it just checks some internal in between platform and actors.
Flags: needinfo?(poirot.alex)
See Also: → 1252012
Just as a note, it's possible pulsebot will comment in here saying the original patches have been landed on mozilla-central, but that's only because I accidentally didn't include the backout commit in my merge from autoland to m-c. I corrected that immediately, but pulsebot might get confused and say otherwise. The updated patches should merge over later today/tonight and show things correctly.
Backout by kwierso@gmail.com:
https://hg.mozilla.org/mozilla-central/rev/be392d463805
Backed out 3 changesets for breaking browser_addons_debug_webextension.js a=backout
Comment on attachment 8895061 [details]
Bug 1382968 - Make WebExtension debugging test better test console behavior.

Luca, Listening for console-api-log-event was quite weak.
This is isn't really ensuring that the message is displayed in the console.
It only asserts that some event fires at the platform level, which doesn't test for example, the message filtering.
That without saying that it is incompatible with this patch...

So, in browser_addons_debug_webextension.js I made it so that it checks, within the toolbox process that the webconsole UI actually displays the message.

In browser_addons_debug_webextension_popup.js, I just forced to use non-OOP add-on, but it would be great to also tweak this test somehow.

I quick summary of what changed in this patch to make that fail:
* console-api-log-event is only fired by ConsoleAPIStorage.js, i.e. the platform code:
  http://searchfox.org/mozilla-central/source/dom/console/ConsoleAPIStorage.js#144
* it is no longer fired when we try to forward messages between content and parent process. We still do forward messages, but now, only when it is strictly needed/useful. See ContentProcessListener in the patch. And also, instead of dispatching a console-api-log-event, we no directly call the right WebConsoleActor method:
  https://hg.mozilla.org/integration/autoland/rev/e25b4bd21ac8#l4.55

Also, it may help to describe the complex setup around these tests.
We have 3 processes:
* the mochitest, living in the parent process
* the add-on process, living in a content process
* the browser toolbox living in a distinct process

The tricky thing is that we have no direct communication channel between the toolbox and parent processes.
We used to rely on this codepath:
 1) call console.log(foo) in the add-on process
 2) processsingleton code used to forward that to the parent process and fire a "console-api-log-event" observer service notification
 3) mochitest used to listen for this event

In order to fix browser_addons_debug_webextension_popup.js properly, we would have to find another way to communicate, but that isn't trivial. I haven't found any simple solution yet.
backed out also from m-c
https://hg.mozilla.org/mozilla-central/rev/309b1b63eb48
Comment on attachment 8895061 [details]
Bug 1382968 - Make WebExtension debugging test better test console behavior.

https://reviewboard.mozilla.org/r/166190/#review171670

Thanks Alex, the `browser_addons_debug_webextension` test looks also better now.

The fix on that test looks great to me (I only added two comments about optional nits about it),
and so that part is definitely r+.

About the popup tests, I have added a detailed comment about the strategy that we can use to
make it able to work with the oop extensions mode enabled.

We only need to decide if we want to apply this changes now or in a followup
(I can also send to you, or attach to this issue, the patch with the all the changes that I've applied locally,
if it can help us to decide if we want to apply them as part of this issue).

::: devtools/client/aboutdebugging/test/browser_addons_debug_webextension.js:32
(Diff revision 1)
>    // which lives in another process. So do not try to use any scope variable!
>    let env = Cc["@mozilla.org/process/environment;1"]
>                .getService(Ci.nsIEnvironment);
>    let testScript = function () {
>      /* eslint-disable no-undef */
> +    function findMessages(hud, text, selector = ".message") {

Nit, it could be nice to add an empty line between these helper function definitions to make them more visible.

::: devtools/client/aboutdebugging/test/browser_addons_debug_webextension.js:54
(Diff revision 1)
>      toolbox.selectTool("webconsole")
> -      .then(console => {
> -        let { jsterm } = console.hud;
> -        return jsterm.execute("myWebExtensionAddonFunction()");
> +      .then(async console => {
> +        let { hud } = console;
> +        let { jsterm } = hud;
> +        let onMessage = waitFor(() => {
> +          return findMessage(hud, "Background page function called");

Nit, we could change this line into:
```
  return findMessages(hud, "Background page function called").length > 0;
```

and get rid of the findMessage function.

::: devtools/client/aboutdebugging/test/browser_addons_debug_webextension.js:60
(Diff revision 1)
> +        });
> +        await jsterm.execute("myWebExtensionAddonFunction()");
> +        await onMessage;
> +        await toolbox.destroy();
>        })
> -      .then(() => toolbox.destroy());
> +      .catch(e => dump("Exception from browser toolbox process: " + e + "\n"));

ah, good "catch"! :-)

the test for the popup is dumping any exception happening in this king of "browser toolbox process test script" promise chain, but it was missing here and it can leads to silent error.

::: devtools/client/aboutdebugging/test/browser_addons_debug_webextension_popup.js:40
(Diff revision 1)
>    id = id.toLowerCase();
>    return id.replace(/[^a-z0-9_-]/g, "_");
>  }
>  
>  add_task(function* testWebExtensionsToolboxSwitchToPopup() {
> +  yield pushPref("extensions.webextensions.remote", false);

This test uses the "console messages" trick to orchestrate the test steps happening in the 2 different processes (main process and browser toolbox process), now that the webextensions are running in the extension process by default on windows, this trick doesn't work anymore and we need another strategy to signal the main process when something has happened in the browser toolbox process or in the extension process.

I have an idea about the strategy that we can use, I did some test locally and it seems a good strategy (and one that is going to work also in the long run):

The WebExtensions add-ons have a "browser.test" API namespace, we often use this API in the webextension tests exactly for this purpose: coordinate the test steps happening in the main and in the extension process.

To be able to use it in this test (without rewriting too much of it), we just need to retrieve the `extension` instance (e.g. using a listener subscribed to the webextensions `Management` object) and subscribe a listener to the `"test-message"` event, e.g. this is how I have redifined the two promise used in this test using this strategy:

```
  let onReadyForOpenPopup;
  let onPopupCustomMessage;

  Management.on("startup", function listener(event, extension) {
    if (extension.name != ADDON_NAME) {
      return;
    }

    Management.off("startup", listener);

    function waitForExtensionTestMessage(expectedMessage) {
      return new Promise(done => {
        extension.on("test-message", function testLogListener(evt, ...args) {
          const [message, ] = args;

          if (message !== expectedMessage) {
            return;
          }

          extension.off("test-message", testLogListener);
          done(args);
        });
      });
    }

    // Wait for the test script running in the browser toolbox process
    // to be ready for selecting the popup page in the frame list selector.
    onReadyForOpenPopup = waitForExtensionTestMessage("readyForOpenPopup");

    // Wait for a notification sent by a script evaluated the test addon via
    // the web console.
    onPopupCustomMessage = waitForExtensionTestMessage("popupPageFunctionCalled");
  });

```

and then I changed the background and popup scripts accordingly:

```
// in the background page:

function myWebExtensionShowPopup() {
  browser.test.sendMessage("readyForOpenPopup");
}

// in the popup page:

function myWebExtensionPopupAddonFunction() {
  browser.test.sendMessage("Popup page function called", 
                           browser.runtime.getManifest());
}

```

to be fair the test script could also use an "async/await" cure :-)
I did it locally and it is much more readable (and also shorter).
Attachment #8895061 - Flags: review?(lgreco) → review+
(In reply to Luca Greco [:rpl] from comment #54)
> Comment on attachment 8895061 [details]
> The fix on that test looks great to me (I only added two comments about
> optional nits about it),
> and so that part is definitely r+.

Addressed the nits and removed changes made to browser_addons_debug_webextension_popup.js in favor of bug 1388737.

Try looks green, on linux and windows:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=f55c29cc1fe9fb29dca19ec7cb67321a081990c5
Pushed by apoirot@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/cfc57926a26a
Move console actor helper modules to a dedicated folder. r=jryans
https://hg.mozilla.org/integration/autoland/rev/d0b89a730143
Flag Browser Console target as being chrome and related to a TabActor. r=jryans
https://hg.mozilla.org/integration/autoland/rev/5380b3782099
Only try to forward console messages from content processes to parent when browser console/toolbox are opened. r=jryans,tromey
https://hg.mozilla.org/integration/autoland/rev/ab16c50f1c29
Make WebExtension debugging test better test console behavior. r=rpl
Product: Firefox → DevTools
Performance Impact: --- → P1
Whiteboard: [qf:p1]
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: