Save extension activity log to a file.

chrome/browser/extensions/activity_log.cc

 // Copyright (c) 2011 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 "chrome/browser/extensions/activity_log.h"
 
+#include <set>
 #include "base/command_line.h"
+#include "base/json/json_string_value_serializer.h"
 #include "base/logging.h"
 #include "base/string_util.h"
+#include "base/threading/thread_checker.h"
+#include "chrome/browser/extensions/blocked_actions.h"
 #include "chrome/browser/extensions/extension_service.h"
 #include "chrome/browser/extensions/extension_system.h"
+#include "chrome/browser/extensions/manager_actions.h"
 #include "chrome/browser/profiles/profile.h"
+#include "chrome/browser/profiles/profile_dependency_manager.h"
+#include "chrome/browser/profiles/profile_keyed_service_factory.h"
+#include "chrome/common/chrome_constants.h"
 #include "chrome/common/chrome_switches.h"
 #include "chrome/common/extensions/extension.h"
 #include "content/public/browser/web_contents.h"
 #include "googleurl/src/gurl.h"
+#include "sql/error_delegate_util.h"
+#include "third_party/re2/re2/re2.h"
+
+namespace {
+
+static const char* kActivityThreadName = "Chrome_ActivityLogThread";

[Eric Dingle, 2012/12/13 20:37:34]

No need for static keyword in this context.

[felt, 2012/12/15 02:51:52]

Done.

+
+// Concatenate an API call with its arguments.
+std::string MakeCallSignature(const std::string& name, const ListValue& args) {
+  std::string call_signature = name + "(";
+  ListValue::const_iterator it = args.begin();
+  for (; it != args.end(); ++it) {
+    std::string arg;
+    JSONStringValueSerializer serializer(&arg);
+    if (serializer.SerializeAndOmitBinaryValues(**it)) {
+      if (it != args.begin())
+        call_signature += ", ";
+      call_signature += arg;
+    }
+  }
+  call_signature += ")";
+  return call_signature;
+}
+
+}  // namespace
 
 namespace extensions {
 
-ActivityLog::ActivityLog() {
+namespace {
+
+// Each profile has different extensions, so we keep a different database for
+// each profile.
+class ActivityLogFactory : public ProfileKeyedServiceFactory {

[Eric Dingle, 2012/12/13 20:37:34]

All classes should have at least one constructor and a destructor.

[felt, 2012/12/15 02:51:52]

Done.

+ public:
+  static ActivityLog* GetForProfile(Profile* profile) {
+    return static_cast<ActivityLog*>(
+        GetInstance()->GetServiceForProfile(profile, true));
+  }
+
+  static ActivityLogFactory* GetInstance();
+
+ private:
+  friend struct DefaultSingletonTraits<ActivityLogFactory>;
+
+  ActivityLogFactory()
+      : ProfileKeyedServiceFactory("ActivityLog",
+                                   ProfileDependencyManager::GetInstance()) { }
+
+  virtual ProfileKeyedService* BuildServiceInstanceFor(
+      Profile* profile) const OVERRIDE {
+    return new ActivityLog(profile);
+  }
+
+  virtual bool ServiceRedirectedInIncognito() const OVERRIDE {
+    return true;
+  }
+};
+
+ActivityLogFactory* ActivityLogFactory::GetInstance() {
+  return Singleton<ActivityLogFactory>::get();
+}
+
+// This handles errors from the database.
+class KillActivityDatabaseErrorDelegate : public sql::ErrorDelegate {
+ public:
+  explicit KillActivityDatabaseErrorDelegate(ActivityLog* backend)
+      : backend_(backend),
+        scheduled_death_(false) { }
+
+  virtual int OnError(int error,
+                      sql::Connection* connection,
+                      sql::Statement* stmt) OVERRIDE {
+    if (!scheduled_death_ && sql::IsErrorCatastrophic(error)) {
+      scheduled_death_ = true;
+      backend_->KillActivityLogDatabase();
+    }
+    return error;
+  }
+
+  bool scheduled_death() const {
+    return scheduled_death_;
+  }
+
+ private:
+  ActivityLog* backend_;
+  bool scheduled_death_;
+
+  DISALLOW_COPY_AND_ASSIGN(KillActivityDatabaseErrorDelegate);
+};
+
+}  // namespace
+
+// Use GetInstance instead of directly creating an ActivityLog.
+ActivityLog::ActivityLog(Profile* profile)
+    : thread_(new base::Thread(kActivityThreadName)) {

[Eric Dingle, 2012/12/13 20:37:34]

I'm not saying that this is wrong, but you should look into reusing the IO
thread of IO operations.

[felt, 2012/12/17 22:45:09]

Now using the DB thread.

+

[Eric Dingle, 2012/12/13 20:37:34]

Remove extra blank line.

[felt, 2012/12/15 02:51:52]

Done.

+  log_activity_to_stdout_ = CommandLine::ForCurrentProcess()->
+      HasSwitch(switches::kEnableExtensionActivityLogging);
+
+  // If the database cannot be initialized, we keep chugging along and still
+  // log actions for displaying in the UI.
+  db_ = new ActivityDatabase();

[Eric Dingle, 2012/12/13 20:37:34]

Would suggest using db_.reset(new ActivityDatabase()) for readability.

[felt, 2012/12/15 02:51:52]

The docs in base/memory/ref_counted.h say to use a = new Y(); for scoped_refptrs
(different from scoped_ptrs).

+  KillActivityDatabaseErrorDelegate* error_delegate =
+      new KillActivityDatabaseErrorDelegate(this);
+  FilePath base_dir = profile->GetPath();
+  FilePath database_name = base_dir.Append(chrome::kActivityLogFilename);
+  sql::InitStatus status = db_->Init(database_name, error_delegate);
+  if (status == sql::INIT_OK) {
+    thread_->Start();
+  } else {
+    LOG(ERROR) << "Couldn't initialize the activity log database.";
+    if (error_delegate->scheduled_death()) {
+      KillActivityLogDatabase();
+    }
+  }
+}
+
+// If you call this constructor, none of the actions will be recorded in the
+// database, but they will still be displayed in the UI.  You should use
+// GetInstance instead of directly creating an ActivityLog.
+ActivityLog::ActivityLog()
+    : thread_(NULL) {
   log_activity_to_stdout_ = CommandLine::ForCurrentProcess()->
       HasSwitch(switches::kEnableExtensionActivityLogging);
 }
 
 ActivityLog::~ActivityLog() {
+  if (thread_) {
+    // Delete and defensively NULL the thread.
+    base::Thread* thread = thread_;
+    thread_ = NULL;
+    delete thread;
+  }
 }
 
 // static
-ActivityLog* ActivityLog::GetInstance() {
-  return Singleton<ActivityLog>::get();
+ActivityLog* ActivityLog::GetInstance(Profile* profile) {
+  return ActivityLogFactory::GetForProfile(profile);
 }
 
 void ActivityLog::AddObserver(const Extension* extension,
                               ActivityLog::Observer* observer) {
   base::AutoLock scoped_lock(lock_);
 
   if (observers_.count(extension) == 0) {
     observers_[extension] = new ObserverListThreadSafe<Observer>;
   }
 
   observers_[extension]->AddObserver(observer);
 }
 
 void ActivityLog::RemoveObserver(const Extension* extension,
                                  ActivityLog::Observer* observer) {
   base::AutoLock scoped_lock(lock_);
 
   if (observers_.count(extension) == 1) {
     observers_[extension]->RemoveObserver(observer);
   }
 }
 
-// Extension*
 bool ActivityLog::HasObservers(const Extension* extension) const {
   base::AutoLock scoped_lock(lock_);
 
   // We also return true if extension activity logging is enabled since in that
   // case this class is observing all extensions.
   return observers_.count(extension) > 0 || log_activity_to_stdout_;
 }
 
-void ActivityLog::Log(const Extension* extension,
-                      Activity activity,
-                      const std::string& message) const {
-  std::vector<std::string> messages(1, message);
-  Log(extension, activity, messages);
-}
+void ActivityLog::LogManagerAction(const Extension* extension,
+                                   const std::string& name,
+                                   const ListValue& args) {
+  base::AutoLock scoped_lock(lock_);
+  std::string verb;

[Eric Dingle, 2012/12/13 20:37:34]

std::string manager, verb;

[felt, 2012/12/15 02:51:52]

Done.

+  std::string manager;
+  bool matches = RE2::FullMatch(name, "(.*?)\\.(.*)", &manager, &verb);
+  if (matches) {
+    std::string call_signature = MakeCallSignature(name, args);
+    scoped_refptr<ManagerAction> action = new ManagerAction(
+        extension->id(),
+        ManagerAction::StringAsActionType(verb),
+        ManagerAction::StringAsTargetType(manager),
+        call_signature,
+        base::Time::Now());
+    ScheduleAndForget(&ActivityDatabase::RecordManagerAction, action);
 
-void ActivityLog::Log(const Extension* extension,
-                      Activity activity,
-                      const std::vector<std::string>& messages) const {
-  base::AutoLock scoped_lock(lock_);
-
-  ObserverMap::const_iterator iter = observers_.find(extension);
-  if (iter != observers_.end()) {
-    iter->second->Notify(&Observer::OnExtensionActivity, extension, activity,
-                         messages);
-  }
-
-  if (log_activity_to_stdout_) {
-    LOG(INFO) << extension->id() << ":" << ActivityToString(activity) << ":" <<
-        JoinString(messages, ' ');
+    // Display the action.
+    ObserverMap::const_iterator iter = observers_.find(extension);
+    if (iter != observers_.end()) {
+      iter->second->Notify(&Observer::OnExtensionActivity,
+                           extension,
+                           ActivityLog::ACTIVITY_EXTENSION_API_CALL,
+                           std::vector<std::string>(1, call_signature));
+    }
+    if (log_activity_to_stdout_) {
+      LOG(INFO) << action->PrettyPrintForDebug();
+    }
+  } else {
+    LOG(ERROR) << "Unknown API call! " << name;
   }
 }
 
+void ActivityLog::LogBlockedAction(const Extension* extension,

[Eric Dingle, 2012/12/13 20:37:34]

You don't notify the observers on blocked calls?

[felt, 2012/12/15 02:51:52]

Whoops.  Done.

+                                   const std::string& blocked_name,
+                                   const ListValue& args,
+                                   const char* reason) {
+  base::AutoLock scoped_lock(lock_);
+  std::string blocked_call = MakeCallSignature(blocked_name, args);
+  scoped_refptr<BlockedAction> action = new BlockedAction(extension->id(),
+                                                          blocked_call,
+                                                          std::string(reason),
+                                                          base::Time::Now());
+  ScheduleAndForget(&ActivityDatabase::RecordBlockedAction, action);
+  if (log_activity_to_stdout_) {
+    LOG(INFO) << action->PrettyPrintForDebug();
+  }
+}
+
+void ActivityLog::LogUrlAction(const Extension* extension,
+                               const GURL& url,
+                               const string16& url_title,
+                               std::string& message,
+                               const UrlAction::UrlActionType verb) {
+  base::AutoLock scoped_lock(lock_);
+  scoped_refptr<UrlAction> action = new UrlAction(
+    extension->id(),
+    verb,
+    url,
+    url_title,
+    message,
+    base::Time::Now());
+  ScheduleAndForget(&ActivityDatabase::RecordUrlAction, action);
+
+  // Display the action.
+  ObserverMap::const_iterator iter = observers_.find(extension);
+  if (iter != observers_.end()) {
+    iter->second->Notify(&Observer::OnExtensionActivity,
+                         extension,
+                         ActivityLog::ACTIVITY_CONTENT_SCRIPT,

[Eric Dingle, 2012/12/13 20:37:34]

I assume that you'll notify for a different kind of activity for dom
manipulations or network requests?

[felt, 2012/12/15 02:51:52]

Yes, I'm going to change how this works as part of the new UI.  I'll be using
the enum values inside of the UrlAction to format the message to display.

+                         std::vector<std::string>(1,
+                             action->PrettyPrintForDebug()));
+  }
+  if (log_activity_to_stdout_) {
+    LOG(INFO) << action->PrettyPrintForDebug();
+  }
+}
+
 void ActivityLog::OnScriptsExecuted(
     const content::WebContents* web_contents,
     const ExecutingScriptsMap& extension_ids,
     int32 on_page_id,
     const GURL& on_url) {
   Profile* profile =
       Profile::FromBrowserContext(web_contents->GetBrowserContext());
   const ExtensionService* extension_service =
       ExtensionSystem::Get(profile)->extension_service();
   const ExtensionSet* extensions = extension_service->extensions();
 
   for (ExecutingScriptsMap::const_iterator it = extension_ids.begin();
        it != extension_ids.end(); ++it) {
     const Extension* extension = extensions->GetByID(it->first);
     if (!extension || !HasObservers(extension))
       continue;
 
-    for (std::set<std::string>::const_iterator it2 = it->second.begin();
-         it2 != it->second.end(); ++it2) {
-      std::vector<std::string> messages;
-      messages.push_back(on_url.spec());
-      messages.push_back(*it2);
-      Log(extension, ActivityLog::ACTIVITY_CONTENT_SCRIPT, messages);
+    // If OnScriptsExecuted is fired because of tabs.executeScript, the list
+    // of content scripts will be empty.  We don't want to log it because
+    // the call to tabs.executeScript will have already been logged anyway.
+    if (!it->second.empty()) {
+      std::string ext_scripts_str = "";
+      for (std::set<std::string>::const_iterator it2 = it->second.begin();
+           it2 != it->second.end(); ++it2) {
+        ext_scripts_str += *it2;
+        ext_scripts_str += " ";
+      }
+      LogUrlAction(extension,
+                   on_url,
+                   web_contents->GetTitle(),
+                   ext_scripts_str,
+                   UrlAction::INSERTED);
     }
   }
 }
 
+void ActivityLog::KillActivityLogDatabase() {
+  if (db_.get()) {
+    ScheduleAndForget(&ActivityDatabase::KillDatabase);
+  }
+}
+
 // static
 const char* ActivityLog::ActivityToString(Activity activity) {
   switch (activity) {
     case ActivityLog::ACTIVITY_EXTENSION_API_CALL:
       return "api_call";
     case ActivityLog::ACTIVITY_EXTENSION_API_BLOCK:
       return "api_block";
     case ActivityLog::ACTIVITY_CONTENT_SCRIPT:
       return "content_script";
     default:
       NOTREACHED();
       return "";
   }
 }
 
 }  // namespace extensions