Send extension console messages to the right WebFrame.

Send extension console messages to the right WebFrame.

The extensions::console::ByContextFinder's conditions are tightened so
that the correct RenderView is found for a given v8::Context.
This fixes the problem where console messages may be sent to an
incorrect document (e.g. background page instead of the options page).

BUG=427922
Committed: https://crrev.com/15c088458a1e6bf4f315f7b61f1b153a5ca1d60d
Cr-Commit-Position: refs/heads/master@{#303824}

[msimonides, 2014-10-28 15:11:47]

msimonides@opera.com changed reviewers:
+ kalman@chromium.org

[not at google - send to devlin, 2014-10-28 16:00:41]

Nice catch.

https://codereview.chromium.org/678393002/diff/1/extensions/renderer/resource...
File extensions/renderer/resources/uncaught_exception_handler.js (right):

https://codereview.chromium.org/678393002/diff/1/extensions/renderer/resource...
extensions/renderer/resources/uncaught_exception_handler.js:8:
window.console.error(message);
The use of console rather than window.console here is deliberate. We've seen
extensions overriding window.console and breaking us.

These messages are supposed to be going via blink -
https://code.google.com/p/chromium/codesearch#chromium/src/extensions/rendere...
- so something must have gone wrong in that process.

[msimonides, 2014-10-29 08:44:42]

On 2014/10/28 16:00:41, kalman wrote:

> These messages are supposed to be going via blink -
>
https://code.google.com/p/chromium/codesearch#chromium/src/extensions/rendere...
> - so something must have gone wrong in that process.

That's right. After some debugging I see that the exception handler from
uncaught_exception_handler.js runs in a different blink::ExecutionContext than
the extension code and it is associated with a different blink::Page object
which has it's own InspectorController. So the messages are handled and stored
in Blink but with a different InspectorController than the one used to inspect
the extension page. So the messages end up... somewhere :)
I assume that running uncaught_exception_handler.js in a separate context is for
isolating the "built-in" JS code from the actual extension code.

I'm not sure where to go from here. If it were possible to get the WebView for
the extension code in extensions::console::AddMessage -
https://code.google.com/p/chromium/codesearch#chromium/src/extensions/rendere...
- the messages would probably end up in the DevTools for the extension page.
Or maybe it would be better for the pages to share their InspectorControllers at
the Blink level? (if that's even possible, I'm just throwing ideas here :)

[not at google - send to devlin, 2014-10-29 18:18:01]

On 2014/10/29 08:44:42, msimonides wrote:
> On 2014/10/28 16:00:41, kalman wrote:
> 
> > These messages are supposed to be going via blink -
> >
>
https://code.google.com/p/chromium/codesearch#chromium/src/extensions/rendere...
> > - so something must have gone wrong in that process.
> 
> That's right. After some debugging I see that the exception handler from
> uncaught_exception_handler.js runs in a different blink::ExecutionContext than
> the extension code and it is associated with a different blink::Page object
> which has it's own InspectorController. So the messages are handled and stored
> in Blink but with a different InspectorController than the one used to inspect
> the extension page. So the messages end up... somewhere :)
> I assume that running uncaught_exception_handler.js in a separate context is
for
> isolating the "built-in" JS code from the actual extension code.

uncaught_exception_handler should be running in the extension's context, not in
a separate context. Maybe something is going wrong in console.cc with figuring
out the RenderView to log to? You say that these InspectorControllers are now
attached to ExecutionContexts not RenderViews? If an ExecutionContext is
associated with a v8::Context then that might be what console.cc should be
doing. Instead of finding the RenderView associated with the v8::Context,
directly access this ExecutionContext->InspectorController.

> 
> I'm not sure where to go from here. If it were possible to get the WebView for
> the extension code in extensions::console::AddMessage -
>
https://code.google.com/p/chromium/codesearch#chromium/src/extensions/rendere...
> - the messages would probably end up in the DevTools for the extension page.
> Or maybe it would be better for the pages to share their InspectorControllers
at
> the Blink level? (if that's even possible, I'm just throwing ideas here :)

[msimonides, 2014-10-30 14:49:38]

On 2014/10/29 18:18:01, kalman wrote:
> On 2014/10/29 08:44:42, msimonides wrote:
> > On 2014/10/28 16:00:41, kalman wrote:
> > 
> > > These messages are supposed to be going via blink -
> > >
> >
>
https://code.google.com/p/chromium/codesearch#chromium/src/extensions/rendere...
> > > - so something must have gone wrong in that process.
> > 
> > That's right. After some debugging I see that the exception handler from
> > uncaught_exception_handler.js runs in a different blink::ExecutionContext
than
> > the extension code and it is associated with a different blink::Page object
> > which has it's own InspectorController. So the messages are handled and
stored
> > in Blink but with a different InspectorController than the one used to
inspect
> > the extension page. So the messages end up... somewhere :)
> > I assume that running uncaught_exception_handler.js in a separate context is
> for
> > isolating the "built-in" JS code from the actual extension code.
> 
> uncaught_exception_handler should be running in the extension's context, not
in
> a separate context. Maybe something is going wrong in console.cc with figuring
> out the RenderView to log to?

Precisely. Turns out the logs would go to the _generated_background_page.html
(it actually depends in the order in which console::ByContextFinder Visit()s the
RenderViews).
I will send a new patchset to this review with something that works for me but
I'm not sure is a correct solution - will test with iframes tomorrow.

[not at google - send to devlin, 2014-10-30 14:53:40]

> 
> Precisely. Turns out the logs would go to the _generated_background_page.html
> (it actually depends in the order in which console::ByContextFinder Visit()s
the
> RenderViews).
> I will send a new patchset to this review with something that works for me but
> I'm not sure is a correct solution - will test with iframes tomorrow.

Ok, thanks. I wonder if it's just a matter of changing the logic of

ScriptContext -> v8::Context -> RenderView -> console.

to

ScriptCOntext -> v8::Context -> ExecutionContext -> console.

presuming there's some way of getting an ExecutionContext from a v8::Context.

[msimonides, 2014-10-31 09:33:55]

On 2014/10/30 14:53:40, kalman wrote:

> Ok, thanks. I wonder if it's just a matter of changing the logic of
> 
> ScriptContext -> v8::Context -> RenderView -> console.
> 
> to
> 
> ScriptCOntext -> v8::Context -> ExecutionContext -> console.
> 
> presuming there's some way of getting an ExecutionContext from a v8::Context.

The only thing I could find was WebLocalFrame::frameForContext (patchset
uploaded). I see this method used in several places in extensions code but I'm
not 100% this will work in all cases (i.e. can extensions run in frames other
than WebLocalFrame?)

[not at google - send to devlin, 2014-10-31 16:41:34]

On 2014/10/31 09:33:55, msimonides wrote:
> On 2014/10/30 14:53:40, kalman wrote:
> 
> > Ok, thanks. I wonder if it's just a matter of changing the logic of
> > 
> > ScriptContext -> v8::Context -> RenderView -> console.
> > 
> > to
> > 
> > ScriptCOntext -> v8::Context -> ExecutionContext -> console.
> > 
> > presuming there's some way of getting an ExecutionContext from a
v8::Context.
> 
> The only thing I could find was WebLocalFrame::frameForContext (patchset
> uploaded). I see this method used in several places in extensions code but I'm
> not 100% this will work in all cases (i.e. can extensions run in frames other
> than WebLocalFrame?)

hm, ok, well if you're converting to a Web[Local]Frame then you're again losing
the actual script context that this originated from. Maybe that's correct, I
have no idea why this stuff broke.

[msimonides, 2014-10-31 17:02:18]

On 2014/10/31 16:41:34, kalman wrote:
> On 2014/10/31 09:33:55, msimonides wrote:
> > On 2014/10/30 14:53:40, kalman wrote:
> > 
> > > Ok, thanks. I wonder if it's just a matter of changing the logic of
> > > 
> > > ScriptContext -> v8::Context -> RenderView -> console.
> > > 
> > > to
> > > 
> > > ScriptCOntext -> v8::Context -> ExecutionContext -> console.
> > > 
> > > presuming there's some way of getting an ExecutionContext from a
> v8::Context.
> > 
> > The only thing I could find was WebLocalFrame::frameForContext (patchset
> > uploaded). I see this method used in several places in extensions code but
I'm
> > not 100% this will work in all cases (i.e. can extensions run in frames
other
> > than WebLocalFrame?)
> 
> hm, ok, well if you're converting to a Web[Local]Frame then you're again
losing
> the actual script context that this originated from. Maybe that's correct, I
> have no idea why this stuff broke.

Are you sure this ever worked correctly? If there's just a single extension
document (the background script) then the errors from callbacks would go to the
correct RenderView. But when there's more than one the ByContextFinder found the
first one associated with the extension (in my case it seems to be the
background script, I don't know how random this is).
With either of my fixes (patchset 2 or 3) the correct WebFrame is used to
deliver the console message... that is as long as the v8::Context is run inside
a WebLocalFrame and not a web worker or something else. 

Unfortunately I don't know the Blink code, the fix is based on what I have
learned analyzing and debugging this particular case. If you have doubts on how
to approach this then maybe we can loop someone else in? Maybe there is a way to
go from v8::Context to blink::ExecutionContext that I have overlooked?

[not at google - send to devlin, 2014-10-31 17:09:47]

kalman@chromium.org changed reviewers:
+ adamk@chromium.org

[not at google - send to devlin, 2014-10-31 17:09:47]

> Are you sure this ever worked correctly? If there's just a single extension
> document (the background script) then the errors from callbacks would go to
the
> correct RenderView. But when there's more than one the ByContextFinder found
the
> first one associated with the extension (in my case it seems to be the
> background script, I don't know how random this is).
> With either of my fixes (patchset 2 or 3) the correct WebFrame is used to
> deliver the console message... that is as long as the v8::Context is run
inside
> a WebLocalFrame and not a web worker or something else. 

I'm not 100% sure, but that's just because my memory isn't perfect. I'm fairly
sure it did though. In the background page there should only be a single
extension context, unless you're hosting an iframe in there or something.

> 
> Unfortunately I don't know the Blink code, the fix is based on what I have
> learned analyzing and debugging this particular case. If you have doubts on
how
> to approach this then maybe we can loop someone else in? Maybe there is a way
to
> go from v8::Context to blink::ExecutionContext that I have overlooked?

Adam?

[adamk, 2014-11-04 23:57:13]

On 2014/10/31 at 17:09:47, kalman wrote:
> > Are you sure this ever worked correctly? If there's just a single extension
> > document (the background script) then the errors from callbacks would go to
the
> > correct RenderView. But when there's more than one the ByContextFinder found
the
> > first one associated with the extension (in my case it seems to be the
> > background script, I don't know how random this is).
> > With either of my fixes (patchset 2 or 3) the correct WebFrame is used to
> > deliver the console message... that is as long as the v8::Context is run
inside
> > a WebLocalFrame and not a web worker or something else. 
> 
> I'm not 100% sure, but that's just because my memory isn't perfect. I'm fairly
sure it did though. In the background page there should only be a single
extension context, unless you're hosting an iframe in there or something.
> 
> > 
> > Unfortunately I don't know the Blink code, the fix is based on what I have
> > learned analyzing and debugging this particular case. If you have doubts on
how
> > to approach this then maybe we can loop someone else in? Maybe there is a
way to
> > go from v8::Context to blink::ExecutionContext that I have overlooked?
> 
> Adam?

I feel like I dropped into the middle of a conversation here. I've skimmed the
thread but I'm still not sure what's being asked. In Blink, we do have a way to
convert from v8::Context to blink::ExecutionContext:

https://code.google.com/p/chromium/codesearch#chromium/src/third_party/WebKit...

[msimonides, 2014-11-05 15:02:18]

On 2014/11/04 23:57:13, adamk wrote:
> 
> I feel like I dropped into the middle of a conversation here. I've skimmed the
> thread but I'm still not sure what's being asked. In Blink, we do have a way
to
> convert from v8::Context to blink::ExecutionContext:
> 
>
https://code.google.com/p/chromium/codesearch#chromium/src/third_party/WebKit...

@kalman: so there is a way to convert to blink::ExecutionContext. In order to
use it we would have to expose blink::ExecutionContext (or a wrapper for it) and
a conversion function to Chromium code. Or we'd have to expose a function like
"logToV8Context" that would log to the associated blink::ExecutionContext (I
assume that Chromium can only include files from third_party/WebKit/Public/).

BTW: I've added a browser test for this issue.

[not at google - send to devlin, 2014-11-05 18:23:35]

Yeah maybe addMessageToConsole should take a v8::Context as an argument? A bit
awkward to be mapping to v8::Context -> WebFrame -> v8::Context again, maybe
there's a better way to structure things.

[msimonides, 2014-11-06 07:55:45]

On 2014/11/05 18:23:35, kalman wrote:
> Yeah maybe addMessageToConsole should take a v8::Context as an argument? A bit
> awkward to be mapping to v8::Context -> WebFrame -> v8::Context again, maybe
> there's a better way to structure things.

Umm, but the mapping that we do is v8::Context -> blink::WebLocalFrame ->
blink::Document (which is a blink::ExecutionContext).
The mapping that may be missing from this fix is v8::Context -> ... ->
blink::WorkerGlobalScope (the other subclass of blink::ExecutionContext).

[not at google - send to devlin, 2014-11-06 16:57:49]

On 2014/11/06 07:55:45, msimonides wrote:
> On 2014/11/05 18:23:35, kalman wrote:
> > Yeah maybe addMessageToConsole should take a v8::Context as an argument? A
bit
> > awkward to be mapping to v8::Context -> WebFrame -> v8::Context again, maybe
> > there's a better way to structure things.
> 
> Umm, but the mapping that we do is v8::Context -> blink::WebLocalFrame ->
> blink::Document (which is a blink::ExecutionContext).
> The mapping that may be missing from this fix is v8::Context -> ... ->
> blink::WorkerGlobalScope (the other subclass of blink::ExecutionContext).

Ok - forget everything I've been saying here. I think that ByContextFinder is
just wrong, it goes from ExtensionHelper (per frame) -> ExtensionDispatcher (per
process) then concludes that if that context is known by the Dispatcher, that's
where to log to. Which is wrong.

A quick fix I think would be to add an extra condition in the loop - that the
ScriptContext it gets also matches the RenderView, see
https://code.google.com/p/chromium/codesearch#chromium/src/extensions/rendere...

[msimonides, 2014-11-07 07:45:05]

On 2014/11/06 16:57:49, kalman wrote:

> Ok - forget everything I've been saying here. I think that ByContextFinder is
> just wrong, it goes from ExtensionHelper (per frame) -> ExtensionDispatcher
(per
> process) then concludes that if that context is known by the Dispatcher,
that's
> where to log to. Which is wrong.
> 
> A quick fix I think would be to add an extra condition in the loop - that the
> ScriptContext it gets also matches the RenderView, see
>
https://code.google.com/p/chromium/codesearch#chromium/src/extensions/rendere...

Ok, so more or less back to patcheset 2 :)

[not at google - send to devlin, 2014-11-07 16:24:03]

Alright, patchset 2 lgtm :)

https://codereview.chromium.org/678393002/diff/20001/extensions/renderer/cons...
File extensions/renderer/console.cc (right):

https://codereview.chromium.org/678393002/diff/20001/extensions/renderer/cons...
extensions/renderer/console.cc:47: script_context->web_frame()->view()) ==
render_view) {
You should just be able to do "script_context->GetRenderView() == render_view".

[msimonides, 2014-11-07 17:46:15]

On 2014/11/07 16:24:03, kalman wrote:
> Alright, patchset 2 lgtm :)
> 
>
https://codereview.chromium.org/678393002/diff/20001/extensions/renderer/cons...
> File extensions/renderer/console.cc (right):
> 
>
https://codereview.chromium.org/678393002/diff/20001/extensions/renderer/cons...
> extensions/renderer/console.cc:47: script_context->web_frame()->view()) ==
> render_view) {
> You should just be able to do "script_context->GetRenderView() ==
render_view".

Sorry for not being explicit: I have uploaded patchset 5 which does just that.
And has the browsertest.

[not at google - send to devlin, 2014-11-11 00:50:26]

lgtm

https://codereview.chromium.org/678393002/diff/80001/chrome/test/data/extensi...
File chrome/test/data/extensions/api_test/uncaught_exception_logging/test.js
(right):

https://codereview.chromium.org/678393002/diff/80001/chrome/test/data/extensi...
chrome/test/data/extensions/api_test/uncaught_exception_logging/test.js:3:
chrome.debugger.onEvent.addListener(function(debuggee, method, params) {
Also nice to remove the event listener when the test is over.

https://codereview.chromium.org/678393002/diff/80001/chrome/test/data/extensi...
chrome/test/data/extensions/api_test/uncaught_exception_logging/test.js:10:
chrome.tabs.sendMessage(tab.id, { "action": "start_test" });
Should this sendMessage only happen if the chrome.debugger.sendCommand function
succeeded? Seems a little bit racy otherwise?

https://codereview.chromium.org/678393002/diff/80001/chrome/test/data/extensi...
chrome/test/data/extensions/api_test/uncaught_exception_logging/test.js:19:
function ExceptionInExtensionPage() {
More consistent if these are testExceptionInExtensionPage() ... etc (i.e. start
with "test"). 

(Besides which JS function names are supposed to start with a lower case
letter.)

https://codereview.chromium.org/678393002/diff/80001/chrome/test/data/extensi...
chrome/test/data/extensions/api_test/uncaught_exception_logging/test.js:21:
{url: chrome.runtime.getURL("extension_page.html")},
Be consistent with " vs ' (I prefer ').

https://codereview.chromium.org/678393002/diff/80001/chrome/test/data/extensi...
chrome/test/data/extensions/api_test/uncaught_exception_logging/test.js:31:
(createTestFunction('Exception thrown in injected script.'))(tab);
I don't think you need the outer parens here.

https://codereview.chromium.org/678393002/diff/80001/chrome/test/data/extensi...
chrome/test/data/extensions/api_test/uncaught_exception_logging/test.js:35:
chrome.test.log('getConfig');
No logging.

https://codereview.chromium.org/678393002/diff/80001/extensions/renderer/cons...
File extensions/renderer/console_apitest.cc (right):

https://codereview.chromium.org/678393002/diff/80001/extensions/renderer/cons...
extensions/renderer/console_apitest.cc:15: }  // anonymous namespace
just "namespace"

[msimonides, 2014-11-12 07:41:01]

https://codereview.chromium.org/678393002/diff/80001/chrome/test/data/extensi...
File chrome/test/data/extensions/api_test/uncaught_exception_logging/test.js
(right):

https://codereview.chromium.org/678393002/diff/80001/chrome/test/data/extensi...
chrome/test/data/extensions/api_test/uncaught_exception_logging/test.js:3:
chrome.debugger.onEvent.addListener(function(debuggee, method, params) {
On 2014/11/11 00:50:25, kalman wrote:
> Also nice to remove the event listener when the test is over.

Done.

https://codereview.chromium.org/678393002/diff/80001/chrome/test/data/extensi...
chrome/test/data/extensions/api_test/uncaught_exception_logging/test.js:10:
chrome.tabs.sendMessage(tab.id, { "action": "start_test" });
On 2014/11/11 00:50:25, kalman wrote:
> Should this sendMessage only happen if the chrome.debugger.sendCommand
function
> succeeded? Seems a little bit racy otherwise?

There is no race between sendMessage and debugger.sendCommand. Enabling the
console automatically sends all the past messages.
Actually I will remove the sendMessage and the other pages can just throw their
exceptions right away - this will be more straightforward.

https://codereview.chromium.org/678393002/diff/80001/chrome/test/data/extensi...
chrome/test/data/extensions/api_test/uncaught_exception_logging/test.js:19:
function ExceptionInExtensionPage() {
On 2014/11/11 00:50:25, kalman wrote:
> More consistent if these are testExceptionInExtensionPage() ... etc (i.e.
start
> with "test"). 
> 
> (Besides which JS function names are supposed to start with a lower case
> letter.)

Done.

https://codereview.chromium.org/678393002/diff/80001/chrome/test/data/extensi...
chrome/test/data/extensions/api_test/uncaught_exception_logging/test.js:21:
{url: chrome.runtime.getURL("extension_page.html")},
On 2014/11/11 00:50:25, kalman wrote:
> Be consistent with " vs ' (I prefer ').

Done.

https://codereview.chromium.org/678393002/diff/80001/chrome/test/data/extensi...
chrome/test/data/extensions/api_test/uncaught_exception_logging/test.js:31:
(createTestFunction('Exception thrown in injected script.'))(tab);
On 2014/11/11 00:50:25, kalman wrote:
> I don't think you need the outer parens here.

Done.

https://codereview.chromium.org/678393002/diff/80001/chrome/test/data/extensi...
chrome/test/data/extensions/api_test/uncaught_exception_logging/test.js:35:
chrome.test.log('getConfig');
On 2014/11/11 00:50:25, kalman wrote:
> No logging.

Done.

https://codereview.chromium.org/678393002/diff/80001/extensions/renderer/cons...
File extensions/renderer/console_apitest.cc (right):

https://codereview.chromium.org/678393002/diff/80001/extensions/renderer/cons...
extensions/renderer/console_apitest.cc:15: }  // anonymous namespace
On 2014/11/11 00:50:25, kalman wrote:
> just "namespace"

Done.

[msimonides, 2014-11-12 07:50:19]

The CQ bit was checked by msimonides@opera.com

[commit-bot: I haz the power, 2014-11-12 07:50:46]

CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/678393002/100001

[commit-bot: I haz the power, 2014-11-12 07:53:48]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2014-11-12 07:53:49]

Try jobs failed on following builders:
  mac_gpu on tryserver.chromium.gpu
(http://build.chromium.org/p/tryserver.chromium.gpu/builders/mac_gpu/builds/80400)
  win_gpu on tryserver.chromium.gpu
(http://build.chromium.org/p/tryserver.chromium.gpu/builders/win_gpu/builds/85315)
  android_arm64_dbg_recipe on tryserver.chromium.linux
(http://build.chromium.org/p/tryserver.chromium.linux/builders/android_arm64_d...)
  win8_chromium_rel on tryserver.chromium.win
(http://build.chromium.org/p/tryserver.chromium.win/builders/win8_chromium_rel...)

[msimonides, 2014-11-12 12:01:43]

The CQ bit was checked by msimonides@opera.com

[commit-bot: I haz the power, 2014-11-12 12:02:11]

CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/678393002/120001

[commit-bot: I haz the power, 2014-11-12 12:05:22]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2014-11-12 12:05:23]

Try jobs failed on following builders:
  chromium_presubmit on tryserver.chromium.linux
(http://build.chromium.org/p/tryserver.chromium.linux/builders/chromium_presub...)

[msimonides, 2014-11-12 12:09:08]

The CQ bit was checked by msimonides@opera.com

[commit-bot: I haz the power, 2014-11-12 12:09:15]

CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/678393002/140001

[commit-bot: I haz the power, 2014-11-12 13:15:18]

Committed patchset #8 (id:140001)

[commit-bot: I haz the power, 2014-11-12 13:15:56]

Patchset 8 (id:??) landed as
https://crrev.com/15c088458a1e6bf4f315f7b61f1b153a5ca1d60d
Cr-Commit-Position: refs/heads/master@{#303824}

[msimonides, 2014-11-14 08:38:20]

Patchset #9 (id:160001) has been deleted