[Extensions Bindings] Add activity logging of custom handling

extensions/renderer/api_activity_logger.cc

Index: extensions/renderer/api_activity_logger.cc
diff --git a/extensions/renderer/api_activity_logger.cc b/extensions/renderer/api_activity_logger.cc
index baaca3f2302c070ba35a48944855d01474dbaf5b..6c8e97eec8137ec9b8a8fc2f1b5347b6c51144a5 100644
--- a/extensions/renderer/api_activity_logger.cc
+++ b/extensions/renderer/api_activity_logger.cc
@@ -2,6 +2,8 @@
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
+#include "extensions/renderer/api_activity_logger.h"
+
 #include <stddef.h>
 
 #include <string>
@@ -11,8 +13,8 @@
 #include "content/public/renderer/render_thread.h"
 #include "extensions/common/extension_messages.h"
 #include "extensions/renderer/activity_log_converter_strategy.h"
-#include "extensions/renderer/api_activity_logger.h"
 #include "extensions/renderer/dispatcher.h"
+#include "extensions/renderer/extensions_renderer_client.h"
 #include "extensions/renderer/script_context.h"
 
 namespace extensions {
@@ -20,28 +22,43 @@ namespace extensions {
 APIActivityLogger::APIActivityLogger(ScriptContext* context,
                                      Dispatcher* dispatcher)
     : ObjectBackedNativeHandler(context), dispatcher_(dispatcher) {
-  RouteFunction("LogEvent", base::Bind(&APIActivityLogger::LogEvent,
-                                       base::Unretained(this)));
-  RouteFunction("LogAPICall", base::Bind(&APIActivityLogger::LogAPICall,
-                                         base::Unretained(this)));
+  RouteFunction("LogEvent", base::Bind(&APIActivityLogger::LogForJS,
+                                       base::Unretained(this), EVENT));
+  RouteFunction("LogAPICall", base::Bind(&APIActivityLogger::LogForJS,
+                                         base::Unretained(this), APICALL));
 }
 
 APIActivityLogger::~APIActivityLogger() {}
 
 // static
 void APIActivityLogger::LogAPICall(
-    const v8::FunctionCallbackInfo<v8::Value>& args) {
-  LogInternal(APICALL, args);
-}
+    v8::Local<v8::Context> context,
+    const std::string& call_name,
+    const std::vector<v8::Local<v8::Value>>& arguments) {
+  const Dispatcher* dispatcher =
+      ExtensionsRendererClient::Get()->GetDispatcher();
+  if (!dispatcher ||  // dispatcher can be null in unittests.
+      !dispatcher->activity_logging_enabled()) {
+    return;
+  }
 
-// static
-void APIActivityLogger::LogEvent(
-    const v8::FunctionCallbackInfo<v8::Value>& args) {
-  LogInternal(EVENT, args);
+  ScriptContext* script_context =
+      ScriptContextSet::GetContextByV8Context(context);
+  auto value_args = base::MakeUnique<base::ListValue>();
+  std::unique_ptr<content::V8ValueConverter> converter =
+      content::V8ValueConverter::Create();
+  ActivityLogConverterStrategy strategy;
+  converter->SetFunctionAllowed(true);
+  converter->SetStrategy(&strategy);
+  value_args->Reserve(arguments.size());
+  for (const auto& arg : arguments)
+    value_args->Append(converter->FromV8Value(arg, context));

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

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.

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

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?

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

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.
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)
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.

+
+  LogInternal(APICALL, script_context->GetExtensionID(), call_name,
+              std::move(value_args), std::string());
 }
 
-// static
-void APIActivityLogger::LogInternal(
+void APIActivityLogger::LogForJS(
     const CallType call_type,
     const v8::FunctionCallbackInfo<v8::Value>& args) {
   CHECK_GT(args.Length(), 2);
@@ -52,38 +69,51 @@ void APIActivityLogger::LogInternal(
   if (!dispatcher_->activity_logging_enabled())
     return;
 
-  std::string ext_id = *v8::String::Utf8Value(args[0]);
-  ExtensionHostMsg_APIActionOrEvent_Params params;
-  params.api_call = *v8::String::Utf8Value(args[1]);
-  if (args.Length() == 4)  // Extras are optional.
-    params.extra = *v8::String::Utf8Value(args[3]);
-  else
-    params.extra = "";
+  v8::Isolate* isolate = args.GetIsolate();
+  v8::HandleScope handle_scope(isolate);
+  v8::Local<v8::Context> context = isolate->GetCurrentContext();
+
+  std::string extension_id = *v8::String::Utf8Value(args[0]);
+  std::string call_name = *v8::String::Utf8Value(args[1]);
+  std::string extra;
+  if (args.Length() == 4) {  // Extras are optional.
+    CHECK(args[3]->IsString());
+    extra = *v8::String::Utf8Value(args[3]);
+  }
 
-  // Get the array of api call arguments.
+  // Get the array of call arguments.
+  auto arguments = base::MakeUnique<base::ListValue>();
   v8::Local<v8::Array> arg_array = v8::Local<v8::Array>::Cast(args[2]);
   if (arg_array->Length() > 0) {
+    arguments->Reserve(arg_array->Length());
     std::unique_ptr<content::V8ValueConverter> converter =
         content::V8ValueConverter::Create();
     ActivityLogConverterStrategy strategy;
     converter->SetFunctionAllowed(true);
     converter->SetStrategy(&strategy);
-    std::unique_ptr<base::ListValue> arg_list(new base::ListValue());
-    for (size_t i = 0; i < arg_array->Length(); ++i) {
-      arg_list->Set(
-          i,
-          converter->FromV8Value(arg_array->Get(i),
-                                 args.GetIsolate()->GetCurrentContext()));
-    }
-    params.arguments.Swap(arg_list.get());
+    for (size_t i = 0; i < arg_array->Length(); ++i)
+      arguments->Append(converter->FromV8Value(arg_array->Get(i), context));
   }
 
+  LogInternal(call_type, extension_id, call_name, std::move(arguments), extra);
+}
+
+// static
+void APIActivityLogger::LogInternal(const CallType call_type,
+                                    const std::string& extension_id,
+                                    const std::string& call_name,
+                                    std::unique_ptr<base::ListValue> arguments,
+                                    const std::string& extra) {
+  ExtensionHostMsg_APIActionOrEvent_Params params;
+  params.api_call = call_name;
+  params.arguments.Swap(arguments.get());
+  params.extra = extra;
   if (call_type == APICALL) {
     content::RenderThread::Get()->Send(
-        new ExtensionHostMsg_AddAPIActionToActivityLog(ext_id, params));
+        new ExtensionHostMsg_AddAPIActionToActivityLog(extension_id, params));
   } else if (call_type == EVENT) {
     content::RenderThread::Get()->Send(
-        new ExtensionHostMsg_AddEventToActivityLog(ext_id, params));
+        new ExtensionHostMsg_AddEventToActivityLog(extension_id, params));
   }
 }