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.
+  content::BrowserThread::ID dispatch_thread;
   if (BrowserThread::IsMessageLoopValid(BrowserThread::DB)) {
-    dispatch_thread_ = BrowserThread::DB;
+    dispatch_thread = BrowserThread::DB;
   } else {
     LOG(ERROR) << "BrowserThread::DB does not exist, running on UI thread!";
-    dispatch_thread_ = BrowserThread::UI;
+    dispatch_thread = BrowserThread::UI;
   }
 
-  // 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);
+  // TODO(dbabic) In the next iteration, we should support multiple policies,
+  // which are then polled by the ActivityLog object
+  if (IsLogEnabled()) {
+    switch (policy_type_) {

[felt, 2013/05/24 18:43:38]

Where is policy_type_ set?

[dbabic, 2013/05/28 21:11:49]

There's a static constructor at the end of this file.  Since ActivityLog is a
singleton, that should be fine.

[felt, 2013/05/29 03:41:15]

Ah, didn't see it. Cool.

On 2013/05/28 21:11:49, dbabic wrote:

+      case ActivityLogPolicy::POLICY_FULLSTREAM:
+        policy_ = new FullStreamUIPolicy(profile, dispatch_thread);
+        break;
+      case ActivityLogPolicy::POLICY_NOARGS:
+        policy_ = new StreamWithoutArgsUIPolicy(profile, dispatch_thread);
+        break;
+    }
+  }
 }
 
 ActivityLog::~ActivityLog() {
-  ScheduleAndForget(&ActivityDatabase::Close);
-}
-
-void ActivityLog::SetArgumentLoggingForTesting(bool log_arguments) {
-  testing_mode_ = log_arguments;
+  delete policy_;
 }
 
 // static
 ActivityLog* ActivityLog::GetInstance(Profile* profile) {
   return ActivityLogFactory::GetForProfile(profile);
 }
 
 void ActivityLog::AddObserver(const Extension* extension,
                               ActivityLog::Observer* observer) {
   if (!IsLogEnabled()) return;
   if (observers_.count(extension) == 0)
     observers_[extension] = new ObserverListThreadSafe<Observer>;
   observers_[extension]->AddObserver(observer);
 }
 
 void ActivityLog::RemoveObserver(const Extension* extension,
                                  ActivityLog::Observer* observer) {
   if (observers_.count(extension) == 1)
     observers_[extension]->RemoveObserver(observer);
 }
 
 void ActivityLog::LogAPIActionInternal(const Extension* extension,
                                        const std::string& api_call,
                                        ListValue* args,
                                        const std::string& extra,
                                        const APIAction::Type type) {
+  if (!extension)

[felt, 2013/05/24 18:43:38]

Note that these checks help with but still don't solve the TOCTOU problem. Can
you add a TODO here so I can add a real fix in another version? (In the future:
I'll get rid of the dependency on having the extension object, and just take the
extension ID as a parameter.)

[dbabic, 2013/05/28 21:11:49]

Sorry, I didn't understand why this doesn't fix the problem.  Are you saying
that the extension object can get deallocated in between the check (line 171)
and use (say, line 187)?  Taking extension ID would be a great fix.

I'll add a comment anyways.  Done.

[felt, 2013/05/29 03:41:15]

Yup, if the extension is uninstalled, the extension object might disappear, and
that can happen at any time. Another CL I have out will fix this (the only
reason we have the extension object instead of ID is because Eric Dingle relies
on the extension object for the UI that I'm about to deprecate).

On 2013/05/28 21:11:49, dbabic wrote:

+    return;
+
   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.");
+      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) {
         iter->second->Notify(&Observer::OnExtensionActivity,
                              extension,
                              ActivityLog::ACTIVITY_EVENT_DISPATCH,
                              MakeCallSignature(api_call, args));
       }
     }
     if (log_activity_to_stdout_)
       LOG(INFO) << action->PrintForDebug();
   } else {
     LOG(ERROR) << "Unknown API call! " << api_call;
   }
 }
 
 // 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())
-    args->Clear();
+  if (!IsLogEnabled() || !extension)
+    return;
+
   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())
-    args->Clear();
+  if (!IsLogEnabled() || !extension)
+    return;
+
   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_ &&
-      arg_whitelist_api_.find(blocked_call) == arg_whitelist_api_.end())
-    args->Clear();
+  if (!IsLogEnabled() || !extension)
+    return;
+
+  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));
+    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.
   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) {
+

[felt, 2013/05/24 18:43:38]

Delete the extra vertical spaces at the beginning of methods (both here and
elsewhere)

[dbabic, 2013/05/28 21:11:49]

Done.

+  if (!extension)
+    return;
+
+  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);
+    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,
                            action->PrintForDebug());
     } else {
       iter->second->Notify(&Observer::OnExtensionActivity,
                            extension,
                            ActivityLog::ACTIVITY_CONTENT_SCRIPT,
                            MakeCallSignature(api_call, args));
     }
   }
   if (log_activity_to_stdout_)
     LOG(INFO) << action->PrintForDebug();
 }
 
 void ActivityLog::LogDOMAction(const Extension* extension,
                                const GURL& url,
                                const string16& url_title,
                                const std::string& api_call,
                                const ListValue* args,
                                const std::string& extra) {
-  if (!IsLogEnabled()) return;
+  if (!IsLogEnabled() || !extension)
+    return;
+
   DOMAction::DOMActionType action = DOMAction::MODIFIED;
   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,
                                       const GURL& url,
                                       const std::string& api_call,
                                       scoped_ptr<DictionaryValue> details,
                                       const std::string& extra) {
   string16 null_title;
-  if (!IsLogEnabled()) return;
+  if (!IsLogEnabled() || !extension)
+    return;
 
-  // Strip details of the web request modifications (for privacy reasons),
-  // unless testing is enabled.
-  if (!testing_mode_) {
-    DictionaryValue::Iterator details_iterator(*details);
-    while (!details_iterator.IsAtEnd()) {
-      details->SetBoolean(details_iterator.key(), true);
-      details_iterator.Advance();
-    }
+  std::string details_string;
+  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);
+    policy_->ProcessAction(
+        ActivityLogPolicy::ACTION_WEB_REQUEST,
+        *extension,
+        api_call,
+        &url,
+        NULL,
+        details.get());
   }
-  std::string details_string;
+
   JSONStringValueSerializer serializer(&details_string);
   serializer.SerializeAndOmitBinaryValues(*details);
 
+  // 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 "";
   }
 }
 
+ActivityLogPolicy::PolicyType ActivityLog::policy_type_(
+    ActivityLogPolicy::POLICY_NOARGS);
+
 }  // namespace extensions