[Extenisons Bindings] Don't throw unchecked errors; add console errors

Throwing an unchecked runtime.lastError results in an uncaught
exception, which can prevent future JS from properly running in
somewhat unpredictable ways. These errors should be logged as console
errors, rather than being thrown as exceptions.

Add tests to a) check errors being logged and b) check that chaining
API calls and callbacks works even when there are uncheked last errors.

BUG=653596

Review-Url: https://codereview.chromium.org/2819683002
Cr-Commit-Position: refs/heads/master@{#465740}

chrome/browser/extensions/native_bindings_apitest.cc

@@ -202,4 +202,47 @@ IN_PROC_BROWSER_TEST_F(NativeBindingsApiTest, ContextMenusTest) {
   EXPECT_TRUE(listener.WaitUntilSatisfied());
 }
 
+// Tests that unchecked errors don't impede future calls.
+IN_PROC_BROWSER_TEST_F(NativeBindingsApiTest, ErrorsInCallbackTest) {
+  host_resolver()->AddRule("*", "127.0.0.1");
+  embedded_test_server()->ServeFilesFromDirectory(test_data_dir_);
+  ASSERT_TRUE(StartEmbeddedTestServer());
+
+  TestExtensionDir test_dir;
+  test_dir.WriteManifest(
+      R"({
+           "name": "Errors In Callback",
+           "manifest_version": 2,
+           "version": "0.1",
+           "permissions": ["contextMenus"],
+           "background": {
+             "scripts": ["background.js"]
+           }
+         })");
+  test_dir.WriteFile(
+      FILE_PATH_LITERAL("background.js"),
+      R"(chrome.tabs.query({}, function(tabs) {
+           chrome.tabs.executeScript(tabs[0].id, {code: 'x'}, function() {
+             // There's an error here (we don't have permission to access the
+             // host), but we don't check it so that it gets surfaced as an
+             // unchecked runtime.lastError.
+             // We should still be able to invoke other APIs and get correct
+             // callbacks.
+             chrome.tabs.query({}, function(tabs) {
+               chrome.tabs.query({}, function(tabs) {
+                 chrome.test.sendMessage('callback');
+               });
+             });
+           });
+         });)");
+
+  ui_test_utils::NavigateToURL(
+      browser(), embedded_test_server()->GetURL(
+                     "example.com", "/native_bindings/simple.html"));
+
+  ExtensionTestMessageListener listener("callback", false);
+  ASSERT_TRUE(LoadExtension(test_dir.UnpackedPath()));
+  EXPECT_TRUE(listener.WaitUntilSatisfied());
+}
+
 }  // namespace extensions

extensions/renderer/api_binding_unittest.cc

@@ -144,7 +144,8 @@ class APIBindingUnittest : public APIBindingTest {
     request_handler_ = base::MakeUnique<APIRequestHandler>(
         base::Bind(&APIBindingUnittest::OnFunctionCall, base::Unretained(this)),
         base::Bind(&RunFunctionOnGlobalAndIgnoreResult),
-        APILastError(APILastError::GetParent()));
+        APILastError(APILastError::GetParent(),
+                     APILastError::AddConsoleError()));
   }
 
   void TearDown() override {

extensions/renderer/api_bindings_system_unittest.cc

@@ -118,7 +118,8 @@ void APIBindingsSystemTest::SetUp() {
       base::Bind(&APIBindingsSystemTest::OnEventListenersChanged,
                  base::Unretained(this)),
       APILastError(base::Bind(&APIBindingsSystemTest::GetLastErrorParent,
-                              base::Unretained(this))));
+                              base::Unretained(this)),
+                   APILastError::AddConsoleError()));
 }
 
 void APIBindingsSystemTest::TearDown() {

extensions/renderer/api_last_error.cc

@@ -53,8 +53,9 @@ gin::WrapperInfo LastErrorObject::kWrapperInfo = {gin::kEmbedderNativeGin};
 
 }  // namespace
 
-APILastError::APILastError(const GetParent& get_parent)
-    : get_parent_(get_parent) {}
+APILastError::APILastError(const GetParent& get_parent,
+                           const AddConsoleError& add_console_error)
+    : get_parent_(get_parent), add_console_error_(add_console_error) {}
 APILastError::APILastError(APILastError&& other) = default;
 APILastError::~APILastError() = default;
 
@@ -133,8 +134,8 @@ void APILastError::ClearError(v8::Local<v8::Context> context,
   }
 
   if (report_if_unchecked && !last_error->accessed()) {
-    isolate->ThrowException(
-        v8::Exception::Error(gin::StringToV8(isolate, last_error->error())));
+    add_console_error_.Run(
+        context, "Unchecked runtime.lastError: " + last_error->error());
   }
 
   // See comment in SetError().

extensions/renderer/api_last_error.h

@@ -21,8 +21,12 @@ class APILastError {
   // given context.
   using GetParent =
       base::Callback<v8::Local<v8::Object>(v8::Local<v8::Context>)>;
+  // Adds an error message to the context's console.
+  using AddConsoleError =
+      base::Callback<void(v8::Local<v8::Context>, const std::string& error)>;
 
-  explicit APILastError(const GetParent& get_parent);
+  APILastError(const GetParent& get_parent,
+               const AddConsoleError& add_console_error);
   APILastError(APILastError&& other);
   ~APILastError();
 
@@ -39,6 +43,8 @@ class APILastError {
  private:
   GetParent get_parent_;
 
+  AddConsoleError add_console_error_;
+
   DISALLOW_COPY_AND_ASSIGN(APILastError);
 };
 

extensions/renderer/api_last_error_unittest.cc

@@ -6,6 +6,7 @@
 
 #include "base/bind.h"
 #include "base/callback_helpers.h"
+#include "base/optional.h"
 #include "extensions/renderer/api_binding_test.h"
 #include "extensions/renderer/api_binding_test_util.h"
 #include "gin/converter.h"
@@ -15,6 +16,9 @@ namespace extensions {
 
 namespace {
 
+void DoNothingWithError(v8::Local<v8::Context> context,
+                        const std::string& error) {}
+
 std::string GetLastError(v8::Local<v8::Object> parent,
                          v8::Local<v8::Context> context) {
   v8::Local<v8::Value> last_error =
@@ -50,7 +54,8 @@ TEST_F(APILastErrorTest, TestLastError) {
   v8::Local<v8::Object> parent_object = v8::Object::New(isolate());
 
   ParentList parents = {{context, parent_object}};
-  APILastError last_error(base::Bind(&GetParent, parents));
+  APILastError last_error(base::Bind(&GetParent, parents),
+                          base::Bind(&DoNothingWithError));
 
   EXPECT_EQ("undefined", GetLastError(parent_object, context));
   // Check that the key isn't present on the object (as opposed to simply being
@@ -75,27 +80,36 @@ TEST_F(APILastErrorTest, ReportIfUnchecked) {
   v8::Local<v8::Context> context = MainContext();
   v8::Local<v8::Object> parent_object = v8::Object::New(isolate());
 
+  base::Optional<std::string> console_error;
+  auto log_error = [](base::Optional<std::string>* console_error,
+                      v8::Local<v8::Context> context,
+                      const std::string& error) { *console_error = error; };
+
   ParentList parents = {{context, parent_object}};
-  APILastError last_error(base::Bind(&GetParent, parents));
+  APILastError last_error(base::Bind(&GetParent, parents),
+                          base::Bind(log_error, &console_error));
 
   {
     v8::TryCatch try_catch(isolate());
     last_error.SetError(context, "foo");
     // GetLastError() will count as accessing the error property, so we
-    // shouldn't throw an exception.
+    // shouldn't log an error.
     EXPECT_EQ("\"foo\"", GetLastError(parent_object, context));
     last_error.ClearError(context, true);
+    EXPECT_FALSE(console_error);
     EXPECT_FALSE(try_catch.HasCaught());
   }
 
   {
     v8::TryCatch try_catch(isolate());
-    // This time, we should throw an exception.
+    // This time, we should log an error.
     last_error.SetError(context, "A last error");
     last_error.ClearError(context, true);
-    ASSERT_TRUE(try_catch.HasCaught());
-    EXPECT_EQ("Uncaught Error: A last error",
-              gin::V8ToString(try_catch.Message()->Get()));
+    ASSERT_TRUE(console_error);
+    EXPECT_EQ("Unchecked runtime.lastError: A last error", *console_error);
+    // We shouldn't have thrown an exception in order to prevent disrupting
+    // JS execution.
+    EXPECT_FALSE(try_catch.HasCaught());
   }
 }
 
@@ -107,7 +121,8 @@ TEST_F(APILastErrorTest, NonLastErrorObject) {
   v8::Local<v8::Object> parent_object = v8::Object::New(isolate());
 
   ParentList parents = {{context, parent_object}};
-  APILastError last_error(base::Bind(&GetParent, parents));
+  APILastError last_error(base::Bind(&GetParent, parents),
+                          base::Bind(&DoNothingWithError));
 
   auto checked_set = [context](v8::Local<v8::Object> object,
                                base::StringPiece key,
@@ -143,7 +158,8 @@ TEST_F(APILastErrorTest, MultipleContexts) {
   v8::Local<v8::Object> parent_a = v8::Object::New(isolate());
   v8::Local<v8::Object> parent_b = v8::Object::New(isolate());
   ParentList parents = {{context_a, parent_a}, {context_b, parent_b}};
-  APILastError last_error(base::Bind(&GetParent, parents));
+  APILastError last_error(base::Bind(&GetParent, parents),
+                          base::Bind(&DoNothingWithError));
 
   last_error.SetError(context_a, "Last error a");
   EXPECT_EQ("\"Last error a\"", GetLastError(parent_a, context_a));

extensions/renderer/api_request_handler_unittest.cc

@@ -67,7 +67,7 @@ TEST_F(APIRequestHandlerTest, AddRequestAndCompleteRequestTest) {
   APIRequestHandler request_handler(
       base::Bind(&DoNothingWithRequest),
       base::Bind(&APIRequestHandlerTest::RunJS, base::Unretained(this)),
-      APILastError(APILastError::GetParent()));
+      APILastError(APILastError::GetParent(), APILastError::AddConsoleError()));
 
   EXPECT_TRUE(request_handler.GetPendingRequestIdsForTesting().empty());
 
@@ -102,7 +102,7 @@ TEST_F(APIRequestHandlerTest, InvalidRequestsTest) {
   APIRequestHandler request_handler(
       base::Bind(&DoNothingWithRequest),
       base::Bind(&APIRequestHandlerTest::RunJS, base::Unretained(this)),
-      APILastError(APILastError::GetParent()));
+      APILastError(APILastError::GetParent(), APILastError::AddConsoleError()));
 
   v8::Local<v8::Function> function = FunctionFromString(context, kEchoArgs);
   ASSERT_FALSE(function.IsEmpty());
@@ -138,7 +138,7 @@ TEST_F(APIRequestHandlerTest, MultipleRequestsAndContexts) {
   APIRequestHandler request_handler(
       base::Bind(&DoNothingWithRequest),
       base::Bind(&APIRequestHandlerTest::RunJS, base::Unretained(this)),
-      APILastError(APILastError::GetParent()));
+      APILastError(APILastError::GetParent(), APILastError::AddConsoleError()));
 
   // By having both different arguments and different behaviors in the
   // callbacks, we can easily verify that the right function is called in the
@@ -190,7 +190,7 @@ TEST_F(APIRequestHandlerTest, CustomCallbackArguments) {
   APIRequestHandler request_handler(
       base::Bind(&DoNothingWithRequest),
       base::Bind(&APIRequestHandlerTest::RunJS, base::Unretained(this)),
-      APILastError(APILastError::GetParent()));
+      APILastError(APILastError::GetParent(), APILastError::AddConsoleError()));
 
   v8::Local<v8::Function> custom_callback =
       FunctionFromString(context, kEchoArgs);
@@ -237,7 +237,7 @@ TEST_F(APIRequestHandlerTest, CustomCallbackArgumentsWithEmptyCallback) {
   APIRequestHandler request_handler(
       base::Bind(&DoNothingWithRequest),
       base::Bind(&APIRequestHandlerTest::RunJS, base::Unretained(this)),
-      APILastError(APILastError::GetParent()));
+      APILastError(APILastError::GetParent(), APILastError::AddConsoleError()));
 
   v8::Local<v8::Function> custom_callback =
       FunctionFromString(context, kEchoArgs);
@@ -275,7 +275,7 @@ TEST_F(APIRequestHandlerTest, UserGestureTest) {
   APIRequestHandler request_handler(
       base::Bind(&DoNothingWithRequest),
       base::Bind(&APIRequestHandlerTest::RunJS, base::Unretained(this)),
-      APILastError(APILastError::GetParent()));
+      APILastError(APILastError::GetParent(), APILastError::AddConsoleError()));
 
   auto callback = [](base::Optional<bool>* ran_with_user_gesture) {
     *ran_with_user_gesture =
@@ -339,7 +339,7 @@ TEST_F(APIRequestHandlerTest, RequestThread) {
   APIRequestHandler request_handler(
       base::Bind(on_request, &thread),
       base::Bind(&APIRequestHandlerTest::RunJS, base::Unretained(this)),
-      APILastError(APILastError::GetParent()));
+      APILastError(APILastError::GetParent(), APILastError::AddConsoleError()));
 
   request_handler.StartRequest(
       context, kMethod, base::MakeUnique<base::ListValue>(),

extensions/renderer/console.cc

@@ -54,31 +54,39 @@ void BoundLogMethodCallback(const v8::FunctionCallbackInfo<v8::Value>& info) {
   ScriptContext* script_context =
       ScriptContextSet::GetContextByV8Context(context);
   // TODO(devlin): Consider (D)CHECK(script_context)
-  content::RenderFrame* render_frame =
-      script_context ? script_context->GetRenderFrame() : nullptr;
   const auto level = static_cast<content::ConsoleMessageLevel>(
       info.Data().As<v8::Int32>()->Value());
-  AddMessage(render_frame, level, message);
+  AddMessage(script_context, level, message);
 }
 
 gin::WrapperInfo kWrapperInfo = {gin::kEmbedderNativeGin};
 
 }  // namespace
 
-void Fatal(content::RenderFrame* render_frame, const std::string& message) {
-  AddMessage(render_frame, content::CONSOLE_MESSAGE_LEVEL_ERROR, message);
+void Fatal(ScriptContext* context, const std::string& message) {
+  AddMessage(context, content::CONSOLE_MESSAGE_LEVEL_ERROR, message);
   CheckWithMinidump(message);
 }
 
-void AddMessage(content::RenderFrame* render_frame,
+void AddMessage(ScriptContext* script_context,
                 content::ConsoleMessageLevel level,
                 const std::string& message) {
+  if (!script_context) {
+    LOG(WARNING) << "Could not log \"" << message
+                 << "\": no ScriptContext found";
+    return;
+  }
+  content::RenderFrame* render_frame = script_context->GetRenderFrame();
   if (!render_frame) {
+    // TODO(lazyboy/devlin): This can happen when this is the context for a
+    // service worker. blink::WebEmbeddedWorker has an AddMessageToConsole
+    // method that we could theoretically hook into.
     LOG(WARNING) << "Could not log \"" << message
                  << "\": no render frame found";
-  } else {
-    render_frame->AddMessageToConsole(level, message);
+    return;
   }
+
+  render_frame->AddMessageToConsole(level, message);
 }
 
 v8::Local<v8::Object> AsV8Object(v8::Isolate* isolate) {

extensions/renderer/console.h

@@ -10,23 +10,20 @@
 #include "content/public/common/console_message_level.h"
 #include "v8/include/v8.h"
 
-namespace content {
-class RenderFrame;
-}
-
 namespace extensions {
+class ScriptContext;
 
-// Utility for logging messages to RenderFrames.
+// Utility for logging console messages.
 namespace console {
 
-// Adds |message| to the console of |render_frame|. If |render_frame| is null,
-// LOG()s the message instead.
-void AddMessage(content::RenderFrame* render_frame,
+// Adds |message| to the console of of the |script_context|. If |script_context|
+// is null, LOG()s the message instead.
+void AddMessage(ScriptContext* script_context,
                 content::ConsoleMessageLevel level,
                 const std::string& message);
 
 // Logs an Error then crashes the current process.
-void Fatal(content::RenderFrame* render_frame, const std::string& message);
+void Fatal(ScriptContext* context, const std::string& message);
 
 // Returns a new v8::Object with each standard log method (Debug/Log/Warn/Error)
 // bound to respective debug/log/warn/error methods. This is a direct drop-in

extensions/renderer/declarative_event_unittest.cc

@@ -98,7 +98,8 @@ class DeclarativeEventTest : public APIBindingTest {
     request_handler_ = base::MakeUnique<APIRequestHandler>(
         base::Bind(&DeclarativeEventTest::OnRequest, base::Unretained(this)),
         base::Bind(&RunFunctionOnGlobalAndIgnoreResult),
-        APILastError(APILastError::GetParent()));
+        APILastError(APILastError::GetParent(),
+                     APILastError::AddConsoleError()));
   }
 
   void TearDown() override {

extensions/renderer/module_system.cc

@@ -61,20 +61,19 @@ void Fatal(ScriptContext* context, const std::string& message) {
 
   ExtensionsClient* client = ExtensionsClient::Get();
   if (client->ShouldSuppressFatalErrors()) {
-    console::AddMessage(context->GetRenderFrame(),
-                        content::CONSOLE_MESSAGE_LEVEL_ERROR, full_message);
+    console::AddMessage(context, content::CONSOLE_MESSAGE_LEVEL_ERROR,
+                        full_message);
     client->RecordDidSuppressFatalError();
   } else {
-    console::Fatal(context->GetRenderFrame(), full_message);
+    console::Fatal(context, full_message);
   }
 }
 
 void Warn(v8::Isolate* isolate, const std::string& message) {
   ScriptContext* script_context =
       ScriptContextSet::GetContextByV8Context(isolate->GetCurrentContext());
-  console::AddMessage(
-      script_context ? script_context->GetRenderFrame() : nullptr,
-      content::CONSOLE_MESSAGE_LEVEL_WARNING, message);
+  console::AddMessage(script_context, content::CONSOLE_MESSAGE_LEVEL_WARNING,
+                      message);
 }
 
 // Default exception handler which logs the exception.

extensions/renderer/native_extension_bindings_system.cc

@@ -6,6 +6,7 @@
 
 #include "base/command_line.h"
 #include "base/memory/ptr_util.h"
+#include "content/public/common/console_message_level.h"
 #include "content/public/common/content_switches.h"
 #include "extensions/common/constants.h"
 #include "extensions/common/event_filtering_info.h"
@@ -16,6 +17,7 @@
 #include "extensions/renderer/api_binding_hooks.h"
 #include "extensions/renderer/api_binding_js_util.h"
 #include "extensions/renderer/chrome_setting.h"
+#include "extensions/renderer/console.h"
 #include "extensions/renderer/module_system.h"
 #include "extensions/renderer/script_context.h"
 #include "extensions/renderer/script_context_set.h"
@@ -164,6 +166,14 @@ v8::Global<v8::Value> CallJsFunctionSync(v8::Local<v8::Function> function,
   return result;
 }
 
+void AddConsoleError(v8::Local<v8::Context> context, const std::string& error) {
+  ScriptContext* script_context =
+      ScriptContextSet::GetContextByV8Context(context);
+  CHECK(script_context);
+  console::AddMessage(script_context, content::CONSOLE_MESSAGE_LEVEL_ERROR,
+                      error);
+}
+
 // Returns the API schema indicated by |api_name|.
 const base::DictionaryValue& GetAPISchema(const std::string& api_name) {
   const base::DictionaryValue* schema =
@@ -335,7 +345,7 @@ NativeExtensionBindingsSystem::NativeExtensionBindingsSystem(
                      base::Unretained(this)),
           base::Bind(&NativeExtensionBindingsSystem::OnEventListenerChanged,
                      base::Unretained(this)),
-          APILastError(base::Bind(&GetRuntime))),
+          APILastError(base::Bind(&GetRuntime), base::Bind(&AddConsoleError))),
       weak_factory_(this) {
   api_system_.RegisterCustomType("storage.StorageArea",
                                  base::Bind(&StorageArea::CreateStorageArea));

extensions/renderer/object_backed_native_handler.cc

@@ -57,10 +57,8 @@ void ObjectBackedNativeHandler::Router(
       !feature_name_value->IsString()) {
     ScriptContext* script_context =
         ScriptContextSet::GetContextByV8Context(context);
-    console::AddMessage(
-        script_context ? script_context->GetRenderFrame() : nullptr,
-        content::CONSOLE_MESSAGE_LEVEL_ERROR,
-        "Extension view no longer exists");
+    console::AddMessage(script_context, content::CONSOLE_MESSAGE_LEVEL_ERROR,
+                        "Extension view no longer exists");
     return;
   }