New architecture of the activity logging: Policies for summarization (and compression)

chrome/browser/extensions/activity_log/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 <set>
 #include <vector>
 #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/activity_log/activity_log.h"
 #include "chrome/browser/extensions/activity_log/api_actions.h"
 #include "chrome/browser/extensions/activity_log/blocked_actions.h"
+#include "chrome/browser/extensions/activity_log/stream_noargs_ui_policy.h"
 #include "chrome/browser/extensions/extension_service.h"
 #include "chrome/browser/extensions/extension_system.h"
 #include "chrome/browser/profiles/incognito_helpers.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"
@@ skipping 56 matching lines @@
 // static
 bool ActivityLog::IsLogEnabled() {
   return LogIsEnabled::GetInstance()->enabled();
 }
 
 // static
 void ActivityLog::RecomputeLoggingIsEnabled() {
   return LogIsEnabled::GetInstance()->ComputeIsEnabled();
 }
 
-// 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)) {
-      ScheduleDeath();
-    }
-    return error;
-  }
-
-  // Schedules death if an error wasn't already reported.
-  void ScheduleDeath() {
-    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(
     content::BrowserContext* profile) const {
   return new ActivityLog(static_cast<Profile*>(profile));
 }
 
 content::BrowserContext* ActivityLogFactory::GetBrowserContextToUse(
     content::BrowserContext* context) const {
   return chrome::GetBrowserContextRedirectedInIncognito(context);
 }
 
 // ActivityLog
 
 // Use GetInstance instead of directly creating an ActivityLog.
-ActivityLog::ActivityLog(Profile* profile) : profile_(profile) {
+ActivityLog::ActivityLog(Profile* profile) : policy_(NULL), profile_(profile) {
   // enable-extension-activity-logging and enable-extension-activity-ui
   log_activity_to_stdout_ = CommandLine::ForCurrentProcess()->HasSwitch(
       switches::kEnableExtensionActivityLogging);
   log_activity_to_ui_ = CommandLine::ForCurrentProcess()->HasSwitch(
       switches::kEnableExtensionActivityUI);
 
   // enable-extension-activity-log-testing
   // This controls whether arguments are collected.
   testing_mode_ = CommandLine::ForCurrentProcess()->HasSwitch(
       switches::kEnableExtensionActivityLogTesting);
   if (!testing_mode_) {
     for (int i = 0; i < APIAction::kSizeAlwaysLog; i++) {
       arg_whitelist_api_.insert(std::string(APIAction::kAlwaysLog[i]));
     }
   }
 
-  // We normally dispatch DB requests to the DB thread, but the thread might
-  // not exist if we are under test conditions. Substitute the UI thread for
-  // this case.
-  if (BrowserThread::IsMessageLoopValid(BrowserThread::DB)) {
-    dispatch_thread_ = BrowserThread::DB;
-  } else {
-    LOG(ERROR) << "BrowserThread::DB does not exist, running on UI thread!";
-    dispatch_thread_ = BrowserThread::UI;
+  // TODO(dbabic) In the next iteration, we should support multiple policies,
+  // which are then polled by the ActivityLog object
+  if (IsLogEnabled()){
+    if (testing_mode_) {
+      policy_ = new FullStreamUIPolicy(profile);
+    } else {
+      policy_ = new StreamWithoutArgsUIPolicy(profile);
+    }
   }
-
-  // If the database cannot be initialized for some reason, we keep
-  // chugging along but nothing will get recorded. If the UI is
-  // available, things will still get sent to the UI even if nothing
-  // is being written to the database.
-  db_ = new ActivityDatabase();
-  if (!IsLogEnabled()) return;
-  base::FilePath base_dir = profile->GetPath();
-  base::FilePath database_name = base_dir.Append(
-      chrome::kExtensionActivityLogFilename);
-  KillActivityDatabaseErrorDelegate* error_delegate =
-      new KillActivityDatabaseErrorDelegate(this);
-  db_->SetErrorDelegate(error_delegate);
-  ScheduleAndForget(&ActivityDatabase::Init, database_name);
 }
 
 ActivityLog::~ActivityLog() {
-  ScheduleAndForget(&ActivityDatabase::Close);
+  delete policy_;
 }
 
 void ActivityLog::SetArgumentLoggingForTesting(bool log_arguments) {
   testing_mode_ = log_arguments;
 }
 
 // static
 ActivityLog* ActivityLog::GetInstance(Profile* profile) {
   return ActivityLogFactory::GetForProfile(profile);
 }
@@ skipping 16 matching lines @@
                                        const std::string& api_call,
                                        ListValue* args,
                                        const std::string& extra,
                                        const APIAction::Type type) {
   std::string verb, manager;
   bool matches = RE2::FullMatch(api_call, "(.*?)\\.(.*)", &manager, &verb);
   if (matches) {
     if (!args->empty() && manager == "tabs") {
       APIAction::LookupTabId(api_call, args, profile_);
     }
+
+    if (policy_) {
+      DCHECK((type == APIAction::CALL || type == APIAction::EVENT_CALLBACK) &&
+          "Unexpected APIAction call type.");
+      CHECK(extension && "Must pass a valid extension ptr.");
+      policy_->ProcessAction(
+          type == APIAction::CALL ? ActivityLogPolicy::ACTION_API :
+              ActivityLogPolicy::ACTION_EVENT,
+          *extension,
+          api_call,
+          NULL,
+          args,
+          NULL);
+    }
+
+    // TODO(felt) Logging should be done more efficiently, so that it
+    // doesn't require construction of the action object.
     scoped_refptr<APIAction> action = new APIAction(
         extension->id(),
         base::Time::Now(),
         type,
         api_call,
         MakeArgList(args),
         extra);
-    ScheduleAndForget(&ActivityDatabase::RecordAction, action);
 
     // Display the action.
     ObserverMap::const_iterator iter = observers_.find(extension);
     if (iter != observers_.end()) {
       if (type == APIAction::CALL) {
         iter->second->Notify(&Observer::OnExtensionActivity,
                              extension,
                              ActivityLog::ACTIVITY_EXTENSION_API_CALL,
                              MakeCallSignature(api_call, args));
       } else if (type == APIAction::EVENT_CALLBACK) {
@@ skipping 10 matching lines @@
   }
 }
 
 // A wrapper around LogAPIActionInternal, but we know it's an API call.
 void ActivityLog::LogAPIAction(const Extension* extension,
                                const std::string& api_call,
                                ListValue* args,
                                const std::string& extra) {
   if (!IsLogEnabled()) return;
   if (!testing_mode_ &&
-      arg_whitelist_api_.find(api_call) == arg_whitelist_api_.end())
+      arg_whitelist_api_.find(api_call) == arg_whitelist_api_.end()) {
     args->Clear();
+  }
   LogAPIActionInternal(extension,
                        api_call,
                        args,
                        extra,
                        APIAction::CALL);
 }
 
 // A wrapper around LogAPIActionInternal, but we know it's actually an event
 // being fired and triggering extension code. Having the two separate methods
 // (LogAPIAction vs LogEventAction) lets us hide how we actually choose to
 // handle them. Right now they're being handled almost the same.
 void ActivityLog::LogEventAction(const Extension* extension,
                                  const std::string& api_call,
                                  ListValue* args,
                                  const std::string& extra) {
   if (!IsLogEnabled()) return;
   if (!testing_mode_ &&
-      arg_whitelist_api_.find(api_call) == arg_whitelist_api_.end())
+      arg_whitelist_api_.find(api_call) == arg_whitelist_api_.end()) {
     args->Clear();
+  }
   LogAPIActionInternal(extension,
                        api_call,
                        args,
                        extra,
                        APIAction::EVENT_CALLBACK);
 }
 
 void ActivityLog::LogBlockedAction(const Extension* extension,
                                    const std::string& blocked_call,
                                    ListValue* args,
                                    BlockedAction::Reason reason,
                                    const std::string& extra) {
   if (!IsLogEnabled()) return;
   if (!testing_mode_ &&

[felt, 2013/05/22 19:55:46]

Shouldn't this be moved into one of the policies?

[dbabic, 2013/05/23 01:35:04]

Sure, if that's your preference.  If you expect that the whitelist might change
in the future, and vary from policy to policy, then that would certainly make
sense.

[felt, 2013/05/23 04:20:01]

Yes, I expect this to change. Please move it into the policy that redacts args.

On 2013/05/23 01:35:04, dbabic wrote:

[dbabic, 2013/05/24 00:35:07]

Done.

-      arg_whitelist_api_.find(blocked_call) == arg_whitelist_api_.end())
+      arg_whitelist_api_.find(blocked_call) == arg_whitelist_api_.end()) {
     args->Clear();
+  }
+
+  if (policy_) {
+    scoped_ptr<base::DictionaryValue> details(new DictionaryValue());
+    std::string key;
+    policy_->GetKey(ActivityLogPolicy::PARAM_KEY_REASON, key);
+    details->SetInteger(key, static_cast<int>(reason));
+    CHECK(extension && "Must pass a valid extension ptr.");

[felt, 2013/05/22 19:55:46]

In general, you probably want DCHECK here. 

Regarding this specific problem: note that a currently unsolved problem (that
luckily only occurs very infrequently) is that sometimes extensions are
uninstalled while we're in the middle of logging an activity. Coming up with a
way to handle that is on my TODO list, but keep in mind that at present this
CHECK/DCHECK may actually fire.

[dbabic, 2013/05/23 01:35:04]

Infrequent or not, the old ActivityLog code will crash if that happens.  I will
add an explicit check at the beginning of all Log* member functions.

[felt, 2013/05/23 04:20:01]

Yup, just letting you know it's a known bug. Please still either use DCHECK as
per the style guide *or* add a quick fix (have it simply return if it's null).

On 2013/05/23 01:35:04, dbabic wrote:

[dbabic, 2013/05/24 00:35:07]

Done.

+    policy_->ProcessAction(
+        ActivityLogPolicy::ACTION_BLOCKED,
+        *extension,
+        blocked_call,
+        NULL,
+        args,
+        details.get());
+  }
+
+  // TODO(felt) Logging should be done more efficiently, so that it
+  // doesn't require construction of the action object.

[felt, 2013/05/22 19:55:46]

Regardless, the following code will all be deleted when I implement the API and
get rid of the old UI in a subsequent CL.

[dbabic, 2013/05/23 01:35:04]

Ok.

   scoped_refptr<BlockedAction> action = new BlockedAction(extension->id(),
                                                           base::Time::Now(),
                                                           blocked_call,
                                                           MakeArgList(args),
                                                           reason,
                                                           extra);
-  ScheduleAndForget(&ActivityDatabase::RecordAction, action);
   // Display the action.
   ObserverMap::const_iterator iter = observers_.find(extension);
   if (iter != observers_.end()) {
     std::string blocked_str = MakeCallSignature(blocked_call, args);
     iter->second->Notify(&Observer::OnExtensionActivity,
                          extension,
                          ActivityLog::ACTIVITY_EXTENSION_API_BLOCK,
                          blocked_str);
   }
   if (log_activity_to_stdout_)
     LOG(INFO) << action->PrintForDebug();
 }
 
 void ActivityLog::LogDOMActionInternal(const Extension* extension,
                                        const GURL& url,
                                        const string16& url_title,
                                        const std::string& api_call,
                                        const ListValue* args,
                                        const std::string& extra,
                                        DOMAction::DOMActionType verb) {
+
+  if (policy_) {
+    scoped_ptr<base::DictionaryValue> details(new DictionaryValue());
+    std::string key;
+    policy_->GetKey(ActivityLogPolicy::PARAM_KEY_DOM_ACTION, key);
+    details->SetInteger(key, static_cast<int>(verb));
+    policy_->GetKey(ActivityLogPolicy::PARAM_KEY_URL_TITLE, key);
+    details->SetString(key, url_title);
+    CHECK(extension && "Must pass a valid extension ptr.");
+    policy_->ProcessAction(
+        ActivityLogPolicy::ACTION_DOM,
+        *extension,
+        api_call,
+        &url,
+        args,
+        details.get());
+  }
+
+
+  // TODO(felt) Logging should be done more efficiently, so that it
+  // doesn't require construction of the action object.
   scoped_refptr<DOMAction> action = new DOMAction(
       extension->id(),
       base::Time::Now(),
       verb,
       url,
       url_title,
       api_call,
       MakeArgList(args),
       extra);
-  ScheduleAndForget(&ActivityDatabase::RecordAction, action);
 
   // Display the action.
   ObserverMap::const_iterator iter = observers_.find(extension);
   if (iter != observers_.end()) {
     // TODO(felt): This is a kludge, planning to update this when new
     // UI is in place.
     if (verb == DOMAction::INSERTED) {
       iter->second->Notify(&Observer::OnExtensionActivity,
                            extension,
                            ActivityLog::ACTIVITY_CONTENT_SCRIPT,
@@ skipping 20 matching lines @@
   if (extra == "Getter") {
     action = DOMAction::GETTER;
   } else if (extra == "Setter") {
     action = DOMAction::SETTER;
   } else if (api_call == "XMLHttpRequest.open") {
     // Has to come before the Method check because XHR is also a Method.
     action = DOMAction::XHR;
   } else if (extra == "Method") {
     action = DOMAction::METHOD;
   }
+
   LogDOMActionInternal(extension,
                        url,
                        url_title,
                        api_call,
                        args,
                        extra,
                        action);
 }
 
 void ActivityLog::LogWebRequestAction(const Extension* extension,
@@ skipping 10 matching lines @@
     DictionaryValue::Iterator details_iterator(*details);
     while (!details_iterator.IsAtEnd()) {
       details->SetBoolean(details_iterator.key(), true);
       details_iterator.Advance();
     }
   }
   std::string details_string;
   JSONStringValueSerializer serializer(&details_string);
   serializer.SerializeAndOmitBinaryValues(*details);
 
+  if (policy_) {
+    scoped_ptr<base::DictionaryValue> details(new DictionaryValue());
+    std::string key;
+    policy_->GetKey(ActivityLogPolicy::PARAM_KEY_DETAILS_STRING, key);
+    details->SetString(key, details_string);
+    CHECK(extension && "Must pass a valid extension ptr.");
+    policy_->ProcessAction(
+        ActivityLogPolicy::ACTION_WEB_REQUEST,
+        *extension,
+        api_call,
+        &url,
+        NULL,
+        details.get());
+  }
+
+  // TODO(felt) Logging should be done more efficiently, so that it
+  // doesn't require construction of the action object.
   scoped_refptr<DOMAction> action = new DOMAction(
       extension->id(),
       base::Time::Now(),
       DOMAction::WEBREQUEST,
       url,
       null_title,
       api_call,
       details_string,
       extra);
-  ScheduleAndForget(&ActivityDatabase::RecordAction, 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,
                          action->PrintForDebug());
   }
   if (log_activity_to_stdout_)
     LOG(INFO) << action->PrintForDebug();
 }
 
 void ActivityLog::GetActions(
     const std::string& extension_id,
     const int day,
     const base::Callback
         <void(scoped_ptr<std::vector<scoped_refptr<Action> > >)>& callback) {
-  BrowserThread::PostTaskAndReplyWithResult(
-      dispatch_thread_,
-      FROM_HERE,
-      base::Bind(&ActivityDatabase::GetActions,
-                 base::Unretained(db_),
-                 extension_id,
-                 day),
-      callback);
+  if (policy_) {
+    policy_->ReadData(extension_id, day, callback);
+  }
 }
 
 void ActivityLog::OnScriptsExecuted(
     const content::WebContents* web_contents,
     const ExecutingScriptsMap& extension_ids,
     int32 on_page_id,
     const GURL& on_url) {
   if (!IsLogEnabled()) return;
   Profile* profile =
       Profile::FromBrowserContext(web_contents->GetBrowserContext());
@@ skipping 18 matching lines @@
         ext_scripts_str += *it2;
         ext_scripts_str += " ";
       }
       scoped_ptr<ListValue> script_names(new ListValue());
       script_names->Set(0, new StringValue(ext_scripts_str));
       LogDOMActionInternal(extension,
                            on_url,
                            web_contents->GetTitle(),
                            std::string(),  // no api call here
                            script_names.get(),
-                           std::string(),  // no extras either
-                           DOMAction::INSERTED);
+                           std::string(),
+                           DOMAction::INSERTED);  // no extras either
     }
   }
 }
 
-void ActivityLog::KillActivityLogDatabase() {
-  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";
     case ActivityLog::ACTIVITY_EVENT_DISPATCH:
       return "event_dispatch";
     default:
       NOTREACHED();
       return "";
   }
 }
 
 }  // namespace extensions