Extensions: suspend extension's scripts when V8 is paused

extensions/renderer/script_injection_manager.cc

 // Copyright 2014 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "extensions/renderer/script_injection_manager.h"
 
 #include "base/auto_reset.h"
 #include "base/bind.h"
 #include "base/memory/weak_ptr.h"
 #include "base/values.h"
@@ skipping 224 matching lines @@
 void ScriptInjectionManager::RVOHelper::InvalidateFrame(
     blink::WebFrame* frame) {
   pending_idle_frames_.erase(frame);
   manager_->InvalidateForFrame(frame);
 }
 
 ScriptInjectionManager::ScriptInjectionManager(
     const ExtensionSet* extensions,
     UserScriptSetManager* user_script_set_manager)
     : extensions_(extensions),
-      injecting_scripts_(false),
       user_script_set_manager_(user_script_set_manager),
       user_script_set_manager_observer_(this) {
   user_script_set_manager_observer_.Add(user_script_set_manager_);
 }
 
 ScriptInjectionManager::~ScriptInjectionManager() {
 }
 
 void ScriptInjectionManager::OnRenderViewCreated(
     content::RenderView* render_view) {
   rvo_helpers_.push_back(new RVOHelper(render_view, this));
 }
 
+void ScriptInjectionManager::OnInjectionFinished(
+    ScriptInjection* injection,
+    scoped_refptr<ScriptsRunInfo> scripts_run_info) {
+  blink::WebFrame* frame = injection->web_frame();
+  UserScript::RunLocation run_location = injection->run_location();
+
+  ScopedVector<ScriptInjection>::iterator it;
+  for (it = running_injections_.begin(); it != running_injections_.end(); ++it){
+    running_injections_.erase(it);
+    break;
+  }
+
+  if (scripts_run_info && scripts_run_info->HasOneRef() && IsFrameValid(frame))

[Devlin, 2015/02/25 18:02:15]

ref counted lifetimes are already somewhat Evil.  Coupled with the fact that you
have multiple spots of logic where you need to know how many refs are left, this
seems like a very fragile solution to me.  What's more, there are two things
that a ScriptsRunInfo does:
1. Logs that content scripts are running for the activity log.
2. Logs how long injecting content scripts took.
For 1., we really shouldn't delay sending the message until the script finishes
- there's no need.
For 2., we should probably differentiate between synchronous and asynchronous
injection times. If a script injects an alert, then it could be several seconds
(or longer) before it's complete, which is normally a very, very bad metric.

I propose:
- Notify the activity log of injections synchronously directly after they start.
- Record some metrics - scriptcount, csscount, and existing time metrics -
synchronously directly after they start.
- Record a set of new time metrics (with, e.g., _Blocking appened to the metric
name) once they all finish, if any were blocking.

We should also not use a refcounted ScriptsRunInfo. Instead, have
ScriptInjectionManager own the scripts run infos for each frame/location, and
when an injection (asynchronously) finishes, check if there are any other
injections for that frame/location pair. If not, log the info.

[kozy, 2015/02/27 17:32:28]

I've removed ref counted Scripts Run Info and returned back old implementation.
If injection runs synchronously (when blink doesn't show modal dialog and V8
isn't paused at breakpoint) then ScripsRunInfo will log information about run in
old manner.
If injection runs asynchronously then ScriptsRunInfo will log information about
css and js count in old manner and time spent on the transfer of injection to
blink without script execution time.
This corresponds to the first two points of the your proposal.
Is it really necessary to log time of asynchronous injections? It seems like
rarely case and time of execution can be absolutely unpredictable and depends on
user actions.

[Devlin, 2015/02/27 18:25:32]

Fair enough.  More than anything else, I'd want to know how often exactly this
is happening (as you point out, it should be pretty rare).  Could we omit the
timing logs, but insert a metric for scripts that were delayed (akin to num
scripts injected)?

[kozy, 2015/02/28 15:23:21]

I've added _BlockedScriptCount metrics to ScriptsRunInfo and added these metrics
to histograms.xml with you and Kalman as owners.

+    scripts_run_info->LogRun(frame, run_location);
+}
+
 void ScriptInjectionManager::OnUserScriptsUpdated(
     const std::set<std::string>& changed_extensions,
     const std::vector<UserScript*>& scripts) {
   for (ScopedVector<ScriptInjection>::iterator iter =
            pending_injections_.begin();
        iter != pending_injections_.end();) {
     if (changed_extensions.count((*iter)->host_id().id()) > 0)
       iter = pending_injections_.erase(iter);
     else
       ++iter;
   }
-
-  // If we are currently injecting scripts, we need to make a note that these
-  // extensions were updated.
-  if (injecting_scripts_) {
-    invalidated_while_injecting_.insert(changed_extensions.begin(),
-                                        changed_extensions.end());
-  }
 }
 
 void ScriptInjectionManager::RemoveObserver(RVOHelper* helper) {
   for (ScopedVector<RVOHelper>::iterator iter = rvo_helpers_.begin();
        iter != rvo_helpers_.end();
        ++iter) {
     if (*iter == helper) {
       rvo_helpers_.erase(iter);
       break;
     }
@@ skipping 43 matching lines @@
     // Certain run location signals (like DidCreateDocumentElement) can happen
     // multiple times. Ignore the subsequent signals.
     return;
   }
 
   // Otherwise, all is right in the world, and we can get on with the
   // injections!
 
   frame_statuses_[frame] = run_location;
 
-  // If a content script injects blocking code (such as a javascript alert()),
-  // then there is a chance that we are running in a nested message loop, and
-  // shouldn't inject scripts right now (to avoid conflicts).
-  if (!injecting_scripts_) {
+  InjectScripts(frame, run_location);
+  // As above, we might have been blocked, but that means that, in the mean

[Devlin, 2015/02/25 18:02:15]

Isn't the point of this patch that executing scripts can no longer block and run
a nested loop?  How would this still be possible?

[kozy, 2015/02/27 17:32:28]

Done.

+  // time, it's possible the frame advanced. Inject any scripts for run
+  // locations that were registered, but never ran.
+  while ((iter = frame_statuses_.find(frame)) != frame_statuses_.end() &&
+         iter->second > run_location) {
+    run_location = NextRunLocation(run_location);
+    DCHECK_LE(run_location, UserScript::DOCUMENT_IDLE);
     InjectScripts(frame, run_location);
-    // As above, we might have been blocked, but that means that, in the mean
-    // time, it's possible the frame advanced. Inject any scripts for run
-    // locations that were registered, but never ran.
-    while ((iter = frame_statuses_.find(frame)) != frame_statuses_.end() &&
-           iter->second > run_location) {
-      run_location = NextRunLocation(run_location);
-      DCHECK_LE(run_location, UserScript::DOCUMENT_IDLE);
-      InjectScripts(frame, run_location);
-    }
   }
 }
 
 void ScriptInjectionManager::InjectScripts(
     blink::WebFrame* frame,
     UserScript::RunLocation run_location) {
-  DCHECK(!injecting_scripts_);
-  DCHECK(invalidated_while_injecting_.empty());
-  base::AutoReset<bool>(&injecting_scripts_, true);
-
   // Find any injections that want to run on the given frame.
   // We create a separate vector for these because there is a chance that
   // injected scripts can block, which can create a nested message loop. When
   // this happens, other signals (like IPCs) can cause |pending_injections_| to
   // be changed, so we don't want to risk that.
   ScopedVector<ScriptInjection> frame_injections;
   for (ScopedVector<ScriptInjection>::iterator iter =
            pending_injections_.begin();
        iter != pending_injections_.end();) {
     if ((*iter)->web_frame() == frame) {
       frame_injections.push_back(*iter);
       iter = pending_injections_.weak_erase(iter);
     } else {
       ++iter;
     }
   }
 
   // Add any injections for user scripts.
   int tab_id = ExtensionHelper::Get(content::RenderView::FromWebView(
                                         frame->top()->view()))->tab_id();
   user_script_set_manager_->GetAllInjections(
       &frame_injections, frame, tab_id, run_location);
 
-  ScriptsRunInfo scripts_run_info;
+  scoped_refptr<ScriptsRunInfo> scripts_run_info(new ScriptsRunInfo());
   for (ScopedVector<ScriptInjection>::iterator iter = frame_injections.begin();
        iter != frame_injections.end();) {
     // If a blocking script was injected, there is potentially a possibility
     // that the frame has been invalidated in the time since. Check.
     if (!IsFrameValid(frame))
       break;
 
     const std::string& extension_id = (*iter)->host_id().id();
     scoped_ptr<ExtensionInjectionHost> extension_injection_host =
         GetExtensionInjectionHost(extension_id, extensions_);
-    // Try to inject the script if the extension is not "dirty" (invalidated by
-    // an update). If the injection does not finish (i.e., it is waiting for
-    // permission), add it to the list of pending injections.
-    if (invalidated_while_injecting_.count(extension_id) == 0 &&
-        !(*iter)->TryToInject(run_location,
-                              extension_injection_host.get(),
-                              &scripts_run_info)) {
-      pending_injections_.insert(pending_injections_.begin(), *iter);
+    // Try to inject the script. If the injection does not finish
+    // (i.e., it is waiting for permission), add it to the list of pending
+    // injections.  If the injection does not finished, add it to the list of
+    // running injections.
+    ScriptInjection* injection = *iter;
+    injection->SetScriptInjectionManager(this);
+    if (!injection->TryToInject(run_location,
+                                extension_injection_host.get(),
+                                scripts_run_info)) {
+      pending_injections_.insert(pending_injections_.begin(), injection);
+      iter = frame_injections.weak_erase(iter);
+    } else if (!injection->is_complete()) {
+      running_injections_.insert(running_injections_.begin(), injection);
       iter = frame_injections.weak_erase(iter);
     } else {
       ++iter;
     }
   }
 
-  if (IsFrameValid(frame))
-    scripts_run_info.LogRun(frame, run_location);
-
-  invalidated_while_injecting_.clear();
+  frame_injections.clear();
+  // If injection executes synchronously in OnInjectionFinished handler we
+  // will have two refs to scripts run info and we need call here LogRun
+  if (scripts_run_info && scripts_run_info->HasOneRef() && IsFrameValid(frame))
+    scripts_run_info->LogRun(frame, run_location);
 }
 
 void ScriptInjectionManager::HandleExecuteCode(
     const ExtensionMsg_ExecuteCode_Params& params,
     content::RenderView* render_view) {
   // TODO(dcheng): Not sure how this can happen today. In an OOPI world, it
   // would indicate a logic error--the browser must direct this request to the
   // right renderer process to begin with.
   blink::WebLocalFrame* main_frame =
       render_view->GetWebView()->mainFrame()->toWebLocalFrame();
   if (!main_frame) {
     render_view->Send(
         new ExtensionHostMsg_ExecuteCodeFinished(render_view->GetRoutingID(),
                                                  params.request_id,
                                                  "No main frame",
                                                  GURL(std::string()),
                                                  base::ListValue()));
     return;
   }
 
   scoped_ptr<ScriptInjection> injection(new ScriptInjection(
       scoped_ptr<ScriptInjector>(
           new ProgrammaticScriptInjector(params, main_frame)),
       main_frame,
       HostID(HostID::EXTENSIONS, params.extension_id),
       static_cast<UserScript::RunLocation>(params.run_at),
       ExtensionHelper::Get(render_view)->tab_id()));
 
-  ScriptsRunInfo scripts_run_info;
+  scoped_refptr<ScriptsRunInfo> scripts_run_info(new ScriptsRunInfo());
   FrameStatusMap::const_iterator iter = frame_statuses_.find(main_frame);
 
+  blink::WebFrame* frame = injection->web_frame();
+  UserScript::RunLocation run_location = injection->run_location();
+
   scoped_ptr<ExtensionInjectionHost> extension_injection_host =
       GetExtensionInjectionHost(injection->host_id().id(), extensions_);
-
+  injection->SetScriptInjectionManager(this);
   if (!injection->TryToInject(
           iter == frame_statuses_.end() ? UserScript::UNDEFINED : iter->second,
           extension_injection_host.get(),
-          &scripts_run_info)) {
+          scripts_run_info)) {
     pending_injections_.push_back(injection.release());
+  } else if (!injection->is_complete()) {
+    running_injections_.push_back(injection.release());
+  } else {
+    injection = NULL;
   }
+
+  if (scripts_run_info && scripts_run_info->HasOneRef() && IsFrameValid(frame))
+    scripts_run_info->LogRun(frame, run_location);
 }
 
 void ScriptInjectionManager::HandleExecuteDeclarativeScript(
     blink::WebFrame* web_frame,
     int tab_id,
     const ExtensionId& extension_id,
     int script_id,
     const GURL& url) {
   scoped_ptr<ExtensionInjectionHost> extension_injection_host =
       GetExtensionInjectionHost(extension_id, extensions_);
   const Extension* extension = extensions_->GetByID(extension_id);
   // TODO(dcheng): This function signature should really be a WebLocalFrame,
   // rather than trying to coerce it here.
   scoped_ptr<ScriptInjection> injection =
       user_script_set_manager_->GetInjectionForDeclarativeScript(
           script_id,
           web_frame->toWebLocalFrame(),
           tab_id,
           url,
           extension);
   if (injection.get()) {
-    ScriptsRunInfo scripts_run_info;
+    scoped_refptr<ScriptsRunInfo> scripts_run_info(new ScriptsRunInfo());
+    injection->SetScriptInjectionManager(this);
+
+    blink::WebFrame* frame = injection->web_frame();
+    UserScript::RunLocation run_location = injection->run_location();
+
     // TODO(markdittmer): Use return value of TryToInject for error handling.
-    injection->TryToInject(UserScript::BROWSER_DRIVEN,
-                           extension_injection_host.get(),
-                           &scripts_run_info);
-    scripts_run_info.LogRun(web_frame, UserScript::BROWSER_DRIVEN);
+    if (injection->TryToInject(UserScript::BROWSER_DRIVEN,
+                              extension_injection_host.get(),
+                              scripts_run_info)) {
+      if (!injection->is_complete())
+        running_injections_.push_back(injection.release());
+    }
+    injection = NULL;
+    if (scripts_run_info && scripts_run_info->HasOneRef()
+        && IsFrameValid(frame))
+      scripts_run_info->LogRun(frame, run_location);
   }
 }
 
 void ScriptInjectionManager::HandlePermitScriptInjection(int64 request_id) {
   ScopedVector<ScriptInjection>::iterator iter =
       pending_injections_.begin();
   for (; iter != pending_injections_.end(); ++iter) {
     if ((*iter)->request_id() == request_id)
       break;
   }
   if (iter == pending_injections_.end())
     return;
 
   // At this point, because the request is present in pending_injections_, we
   // know that this is the same page that issued the request (otherwise,
   // RVOHelper's DidStartProvisionalLoad callback would have caused it to be
   // cleared out).
 
   scoped_ptr<ScriptInjection> injection(*iter);
   pending_injections_.weak_erase(iter);
 
-  ScriptsRunInfo scripts_run_info;
+  injection->SetScriptInjectionManager(this);
+
   scoped_ptr<ExtensionInjectionHost> extension_injection_host =
       GetExtensionInjectionHost(injection->host_id().id(), extensions_);
-  if (injection->OnPermissionGranted(extension_injection_host.get(),
-                                     &scripts_run_info)) {
-    scripts_run_info.LogRun(injection->web_frame(), UserScript::RUN_DEFERRED);
+  if (injection->OnPermissionGranted(extension_injection_host.get())) {
+    if (!injection->is_complete())
+      running_injections_.push_back(injection.Pass());
   }
 }
 
 }  // namespace extensions