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/profiles/profile.h"
+#include "chrome/browser/extensions/manager_actions.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 {
+
+// 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() {
+// 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;
+  }
+
+  // Schedules death if an error wasn't already reported.
+  void schedule_death() {

[Matt Perry, 2013/01/03 20:53:35]

ScheduleDeath

[felt, 2013/01/07 23:44:22]

Done.

+    if (!scheduled_death_) {
+      scheduled_death_ = true;
+      backend_->KillActivityLogDatabase();
+    }
+  }
+
+  bool scheduled_death() const {
+    return scheduled_death_;
+  }
+
+ private:
+  ActivityLog* backend_;
+  bool scheduled_death_;
+
+  DISALLOW_COPY_AND_ASSIGN(KillActivityDatabaseErrorDelegate);
+};
+
+// ActivityLogFactory
+
+ActivityLogFactory* ActivityLogFactory::GetInstance() {
+  return Singleton<ActivityLogFactory>::get();
+}
+
+ProfileKeyedService* ActivityLogFactory::BuildServiceInstanceFor(
+    Profile* profile) const {
+  return new ActivityLog(profile);
+}
+
+bool ActivityLogFactory::ServiceRedirectedInIncognito() const {
+  return true;
+}
+
+// ActivityLog
+
+// Use GetInstance instead of directly creating an ActivityLog.
+ActivityLog::ActivityLog(Profile* profile) {
   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();
+  KillActivityDatabaseErrorDelegate* error_delegate =
+      new KillActivityDatabaseErrorDelegate(this);
+  FilePath base_dir = profile->GetPath();
+  FilePath database_name = base_dir.Append(
+      chrome::kExtensionActivityLogFilename);
+  sql::InitStatus status = db_->Init(database_name, error_delegate);
+  if (status != sql::INIT_OK) {
+    LOG(ERROR) << "Couldn't initialize the activity log database.";
+    error_delegate->schedule_death();
+  }
 }
 
 ActivityLog::~ActivityLog() {
 }
 
 // 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::LogAPIAction(const Extension* extension,
+                               const std::string& name,
+                               const ListValue* args) {
+  base::AutoLock scoped_lock(lock_);
+  std::string verb, 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));

[Matt Perry, 2013/01/03 20:53:35]

Seems like we never Notify with multiple messages. Change OnExtensionActivity to
accept a single message.

[felt, 2013/01/07 23:44:22]

Done.

+    }
+    if (log_activity_to_stdout_) {
+      LOG(INFO) << action->PrettyPrintForDebug();
+    }
+  } else {
+    LOG(ERROR) << "Unknown API call! " << name;
   }
 }
 
+void ActivityLog::LogBlockedAction(const Extension* extension,
+                                   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);
+  // Display the action.
+  ObserverMap::const_iterator iter = observers_.find(extension);
+  if (iter != observers_.end()) {
+    iter->second->Notify(&Observer::OnExtensionActivity,
+                         extension,
+                         ActivityLog::ACTIVITY_EXTENSION_API_BLOCK,
+                         std::vector<std::string>(1, blocked_call));
+  }
+  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,
+                         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