[Extensions Bindings] Add activity logging of custom handling

[Extensions Bindings] Add activity logging of custom handling

If a method is handled by a custom hook, we won't notify the browser
(where we normally would with an API request), and so the activity log
won't be updated. Add support for activity logging with native binding.

If a request is handled by a custom hook and a request is not sent to
the browser, notify the activity logger (which will send the information
along to the browser process).  This matches the logic we currently have
in the JS bindings.

Add unit tests for the same.  In addition to the unit tests, this fixes
ActivityLogApiTest.TriggerEvent with native bindings enabled.

BUG=653596
Review-Url: https://codereview.chromium.org/2962093002
Cr-Commit-Position: refs/heads/master@{#485457}
Committed: https://chromium.googlesource.com/chromium/src/+/7ab1596cf4cde44bfc15f6ba2c74f694f130b608

[Devlin, 2017-06-29 17:15:30]

The CQ bit was checked by rdevlin.cronin@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2017-06-29 17:15:53]

Dry run: CQ is trying da patch.

Follow status at:
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2017-06-29 17:24:25]

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

[commit-bot: I haz the power, 2017-06-29 17:24:26]

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

[Devlin, 2017-06-29 20:50:33]

The CQ bit was checked by rdevlin.cronin@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2017-06-29 20:50:54]

Dry run: CQ is trying da patch.

Follow status at:
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2017-06-29 22:12:02]

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

[commit-bot: I haz the power, 2017-06-29 22:12:03]

Dry run: This issue passed the CQ dry run.

[Devlin, 2017-06-30 00:49:36]

Description was changed from

==========
activity logger
BUG=
==========

to

==========
[Extensions Bindings] Add activity logging of custom handling

If a method is handled by a custom hook, we won't notify the browser
(where we normally would with an API request), and so the activity log
won't be updated. Add support for activity logging with native binding.

If a request is handled by a custom hook and a request is not sent to
the browser, notify the activity logger (which will send the information
along to the browser process).  This matches the logic we currently have
in the JS bindings.

Add unit tests for the same.  In addition to the unit tests, this fixes
ActivityLogApiTest.TriggerEvent with native bindings enabled.

BUG=653596
==========

[Devlin, 2017-06-30 00:49:55]

rdevlin.cronin@chromium.org changed reviewers:
+ jbroman@chromium.org, lazyboy@chromium.org

[Devlin, 2017-06-30 00:50:12]

We're on the last bits, folks!  Just a few more failing tests.

[jbroman, 2017-06-30 19:05:48]

Some high-level thoughts.

https://codereview.chromium.org/2962093002/diff/40001/extensions/renderer/api...
File extensions/renderer/api_activity_logger.cc (right):

https://codereview.chromium.org/2962093002/diff/40001/extensions/renderer/api...
extensions/renderer/api_activity_logger.cc:55:
value_args->Append(converter->FromV8Value(arg, context));
How important is it that these are correct? It seems to me that since this is
separate from the Gets used to perform the logic, it would be possible for a
script to lie to the activity logger, by doing something like:

var i = 0;
chrome.api.doStuff({ get someArgument() { return f(i++); } });

where f is a function that sneakily chooses the values it wants to provide at
various times. If so, using post-conversion-from-V8 values would avoid this
issue.

https://codereview.chromium.org/2962093002/diff/40001/extensions/renderer/bin...
File extensions/renderer/bindings/api_binding_unittest.cc (right):

https://codereview.chromium.org/2962093002/diff/40001/extensions/renderer/bin...
extensions/renderer/bindings/api_binding_unittest.cc:1297: SetFunctions(
This seems to be missing any unit tests which have a non-empty parameter list.

[Devlin, 2017-07-06 15:15:23]

The CQ bit was checked by rdevlin.cronin@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2017-07-06 15:15:39]

Dry run: CQ is trying da patch.

Follow status at:
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[Devlin, 2017-07-06 17:09:53]

The CQ bit was checked by rdevlin.cronin@chromium.org to run a CQ dry run

[Devlin, 2017-07-06 17:09:57]

https://codereview.chromium.org/2962093002/diff/40001/extensions/renderer/api...
File extensions/renderer/api_activity_logger.cc (right):

https://codereview.chromium.org/2962093002/diff/40001/extensions/renderer/api...
extensions/renderer/api_activity_logger.cc:55:
value_args->Append(converter->FromV8Value(arg, context));
On 2017/06/30 19:05:48, jbroman wrote:
> How important is it that these are correct? It seems to me that since this is
> separate from the Gets used to perform the logic, it would be possible for a
> script to lie to the activity logger, by doing something like:
> 
> var i = 0;
> chrome.api.doStuff({ get someArgument() { return f(i++); } });
> 
> where f is a function that sneakily chooses the values it wants to provide at
> various times. If so, using post-conversion-from-V8 values would avoid this
> issue.

Nice catch.  This is a bit fun.

Having perfectly-correct arguments here is not an incredibly high priority,
because it's a pretty low-usage feature, and the majority of activity is
reported on the browser side after we pass the serialized arguments over - this
is only for the edge cases.  That said, it'd obviously be best to be correct,
all other things equal.  

The downside to using post-conversion-from-v8 values is that this is *only* sent
when an API is called that doesn't send a request to the browser (typically when
a custom binding has a handleRequest that synchronously in JS implements the
API).  In these cases, we never actually convert the arguments from V8.  Given
activity logging is a low-usage (default-disabled) feature, I'd prefer not to
slow down the average case by serializing in all cases.

There are ways around this - we could pass in a flag indicating whether or not
activity logging is enabled, and only in that case do the extra conversion. 
That could be reasonable, but is a bit more verbose, and I wasn't sure it was
worth it in v1.

It's also worth noting that the current behavior has the same flaw, where it
passes the arguments to the activity logger, which then converts them, so there
is the same chance for sneaky scripting.

-----

Taking a step back, I actually don't know that this concern is just related
here.  In fact, any hooks (in either JS or native bindings) that accept raw JS
arguments would be susceptible to this.  Unfortunately, the only fool-proof way
around this I can think of would be to do a deep copy of all arguments passed
in, in all cases.  That's not terrible sometimes, but to do it in every case
would very likely have non-trivial performance implications (particularly around
e.g. message passing, where we can pass very large strings or objects).

I think this probably warrants thinking a bit more about, and probably a longer
discussion.  For now, I'd like to punt that discussion, and this CL provides at
minimum parity with the current system (it's actually marginally better, because
at least we use the updated arguments).  What are your thoughts?

https://codereview.chromium.org/2962093002/diff/40001/extensions/renderer/bin...
File extensions/renderer/bindings/api_binding_unittest.cc (right):

https://codereview.chromium.org/2962093002/diff/40001/extensions/renderer/bin...
extensions/renderer/bindings/api_binding_unittest.cc:1297: SetFunctions(
On 2017/06/30 19:05:48, jbroman wrote:
> This seems to be missing any unit tests which have a non-empty parameter list.

Fair enough.  Added one with real parameters. :)

[commit-bot: I haz the power, 2017-07-06 17:10:08]

Dry run: CQ is trying da patch.

Follow status at:
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2017-07-06 18:33:46]

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

[commit-bot: I haz the power, 2017-07-06 18:33:47]

Dry run: This issue passed the CQ dry run.

[jbroman, 2017-07-06 20:48:45]

lgtm

https://codereview.chromium.org/2962093002/diff/40001/extensions/renderer/api...
File extensions/renderer/api_activity_logger.cc (right):

https://codereview.chromium.org/2962093002/diff/40001/extensions/renderer/api...
extensions/renderer/api_activity_logger.cc:55:
value_args->Append(converter->FromV8Value(arg, context));
On 2017/07/06 at 17:09:57, Devlin wrote:
> On 2017/06/30 19:05:48, jbroman wrote:
> > How important is it that these are correct? It seems to me that since this
is
> > separate from the Gets used to perform the logic, it would be possible for a
> > script to lie to the activity logger, by doing something like:
> > 
> > var i = 0;
> > chrome.api.doStuff({ get someArgument() { return f(i++); } });
> > 
> > where f is a function that sneakily chooses the values it wants to provide
at
> > various times. If so, using post-conversion-from-V8 values would avoid this
> > issue.
> 
> Nice catch.  This is a bit fun.
> 
> Having perfectly-correct arguments here is not an incredibly high priority,
because it's a pretty low-usage feature, and the majority of activity is
reported on the browser side after we pass the serialized arguments over - this
is only for the edge cases.  That said, it'd obviously be best to be correct,
all other things equal.  
> 
> The downside to using post-conversion-from-v8 values is that this is *only*
sent when an API is called that doesn't send a request to the browser (typically
when a custom binding has a handleRequest that synchronously in JS implements
the API).  In these cases, we never actually convert the arguments from V8. 
Given activity logging is a low-usage (default-disabled) feature, I'd prefer not
to slow down the average case by serializing in all cases.
> 
> There are ways around this - we could pass in a flag indicating whether or not
activity logging is enabled, and only in that case do the extra conversion. 
That could be reasonable, but is a bit more verbose, and I wasn't sure it was
worth it in v1.

Yeah, in my mind an ideal correct version looks something like (pseudo-code):

RealArgs real_args = InterpretV8Args(v8_args);
if (ActivityLogger::IsEnabled())
  ActivityLogger::Log(real_args.ForActivityLog());
APIImpl(real_args);

(As you note, the APIs implemented in the browser get roughly this logic
implicitly due to their request flow.)

But I get that you don't necessarily want to do that, especially in this CL.

> It's also worth noting that the current behavior has the same flaw, where it
passes the arguments to the activity logger, which then converts them, so there
is the same chance for sneaky scripting.
> 
> -----
> 
> Taking a step back, I actually don't know that this concern is just related
here.  In fact, any hooks (in either JS or native bindings) that accept raw JS
arguments would be susceptible to this.  Unfortunately, the only fool-proof way
around this I can think of would be to do a deep copy of all arguments passed
in, in all cases.  That's not terrible sometimes, but to do it in every case
would very likely have non-trivial performance implications (particularly around
e.g. message passing, where we can pass very large strings or objects).

Large objects, sure. I don't think large strings would have an extra copy
(because strings can't be hooked in the same ways, you can just hold a handle on
the same string).

Fundamentally this feature implies a deep copy already (for the IPC)

> I think this probably warrants thinking a bit more about, and probably a
longer discussion.  For now, I'd like to punt that discussion, and this CL
provides at minimum parity with the current system (it's actually marginally
better, because at least we use the updated arguments).  What are your thoughts?

Yeah, I'll leave the extensions system design decisions to you. If you'd rather
file a bug and think about this more later, that's fine with me.

https://codereview.chromium.org/2962093002/diff/80001/extensions/renderer/bin...
File extensions/renderer/bindings/api_binding_unittest.cc (right):

https://codereview.chromium.org/2962093002/diff/80001/extensions/renderer/bin...
extensions/renderer/bindings/api_binding_unittest.cc:1411: // The throwException
call will throw an exception; ignore it.
don't you still need to catch the exception?

https://codereview.chromium.org/2962093002/diff/80001/extensions/renderer/bin...
extensions/renderer/bindings/api_binding_unittest.cc:1469: ASSERT_EQ(2u,
request_arguments->size());
nit: Or this and the following two could be (using ::testing::ElementsAre from
gmock):

ASSERT_THAT(*request_arguments, ElementsAre("\"str\"", "42"));

(I personally prefer this to separate expectations on the size and elements, but
up to you.)

[lazyboy, 2017-07-07 23:54:58]

lgtm

https://codereview.chromium.org/2962093002/diff/80001/chrome/test/data/extens...
File chrome/test/data/extensions/api_test/activity_log_private/PRESUBMIT.py
(right):

https://codereview.chromium.org/2962093002/diff/80001/chrome/test/data/extens...
chrome/test/data/extensions/api_test/activity_log_private/PRESUBMIT.py:18:
'tools')
What is this change?

[Devlin, 2017-07-10 20:50:18]

The CQ bit was checked by rdevlin.cronin@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2017-07-10 20:50:40]

Dry run: CQ is trying da patch.

Follow status at:
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[Devlin, 2017-07-10 22:28:03]

https://codereview.chromium.org/2962093002/diff/80001/chrome/test/data/extens...
File chrome/test/data/extensions/api_test/activity_log_private/PRESUBMIT.py
(right):

https://codereview.chromium.org/2962093002/diff/80001/chrome/test/data/extens...
chrome/test/data/extensions/api_test/activity_log_private/PRESUBMIT.py:18:
'tools')
On 2017/07/07 23:54:58, lazyboy wrote:
> What is this change?

This activity log test folder has a presubmit intended to check js style, but
the js style script moved.  Apparently it's been awhile since we updated
anything in this directory. :)

https://codereview.chromium.org/2962093002/diff/80001/extensions/renderer/bin...
File extensions/renderer/bindings/api_binding_unittest.cc (right):

https://codereview.chromium.org/2962093002/diff/80001/extensions/renderer/bin...
extensions/renderer/bindings/api_binding_unittest.cc:1411: // The throwException
call will throw an exception; ignore it.
On 2017/07/06 20:48:45, jbroman wrote:
> don't you still need to catch the exception?

Hmm... probably should be.  Done.

https://codereview.chromium.org/2962093002/diff/80001/extensions/renderer/bin...
extensions/renderer/bindings/api_binding_unittest.cc:1469: ASSERT_EQ(2u,
request_arguments->size());
On 2017/07/06 20:48:45, jbroman wrote:
> nit: Or this and the following two could be (using ::testing::ElementsAre from
> gmock):
> 
> ASSERT_THAT(*request_arguments, ElementsAre("\"str\"", "42"));
> 
> (I personally prefer this to separate expectations on the size and elements,
but
> up to you.)

Sure, done.

[Devlin, 2017-07-10 22:28:09]

The CQ bit was unchecked by rdevlin.cronin@chromium.org

[Devlin, 2017-07-10 22:28:12]

The CQ bit was checked by rdevlin.cronin@chromium.org

[Devlin, 2017-07-10 22:28:14]

The patchset sent to the CQ was uploaded after l-g-t-m from
lazyboy@chromium.org, jbroman@chromium.org
Link to the patchset: https://codereview.chromium.org/2962093002/#ps120001
(title: "nit")

[commit-bot: I haz the power, 2017-07-10 22:28:41]

CQ is trying da patch.

Follow status at:
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2017-07-11 00:17:31]

CQ is committing da patch.

Bot data: {"patchset_id": 120001, "attempt_start_ts": 1499725692532430,
"parent_rev": "7e469cba37139f2f438acbeef855923d21c731c8", "commit_rev":
"7ab1596cf4cde44bfc15f6ba2c74f694f130b608"}

[commit-bot: I haz the power, 2017-07-11 00:17:53]

Description was changed from

==========
[Extensions Bindings] Add activity logging of custom handling

If a method is handled by a custom hook, we won't notify the browser
(where we normally would with an API request), and so the activity log
won't be updated. Add support for activity logging with native binding.

If a request is handled by a custom hook and a request is not sent to
the browser, notify the activity logger (which will send the information
along to the browser process).  This matches the logic we currently have
in the JS bindings.

Add unit tests for the same.  In addition to the unit tests, this fixes
ActivityLogApiTest.TriggerEvent with native bindings enabled.

BUG=653596
==========

to

==========
[Extensions Bindings] Add activity logging of custom handling

If a method is handled by a custom hook, we won't notify the browser
(where we normally would with an API request), and so the activity log
won't be updated. Add support for activity logging with native binding.

If a request is handled by a custom hook and a request is not sent to
the browser, notify the activity logger (which will send the information
along to the browser process).  This matches the logic we currently have
in the JS bindings.

Add unit tests for the same.  In addition to the unit tests, this fixes
ActivityLogApiTest.TriggerEvent with native bindings enabled.

BUG=653596

Review-Url: https://codereview.chromium.org/2962093002
Cr-Commit-Position: refs/heads/master@{#485457}
Committed:
https://chromium.googlesource.com/chromium/src/+/7ab1596cf4cde44bfc15f6ba2c74...
==========

[commit-bot: I haz the power, 2017-07-11 00:17:55]

Committed patchset #7 (id:120001) as
https://chromium.googlesource.com/chromium/src/+/7ab1596cf4cde44bfc15f6ba2c74...