Compressed activity log database storage

chrome/browser/extensions/activity_log/counting_policy.cc

+// Copyright 2013 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.
+
+// A policy for storing activity log data to a database that performs
+// aggregation to reduce the size of the database.  The database layout is
+// nearly the same as FullStreamUIPolicy, which stores a complete log, with a
+// few changes:
+//   - a "count" column is added to track how many log records were merged
+//     together into this row
+//   - the "time" column measures the most recent time that the current row was
+//     updated
+// When writing a record, if a row already exists where all other columns
+// (extension_id, action_type, api_name, args, urls, etc.) all match, and the
+// previous time falls within today (the current time), then the count field on
+// the old row is incremented.  Otherwise, a new row is written.
+//
+// For many text columns, repeated strings are compressed by moving string
+// storage to a separate table ("string_ids") and storing only an identifier in
+// the logging table.  For example, if the api_name_x column contained the
+// value 4 and the string_ids table contained a row with primary key 4 and
+// value 'tabs.query', then the api_name field should be taken to have the
+// value 'tabs.query'.  Each column ending with "_x" is compressed in this way.
+// All lookups are to the string_ids table, except for the page_url_x and
+// arg_url_x columns, which are converted via the url_ids table (this
+// separation of URL values is to help simplify history clearing).
+//
+// The activitylog_uncompressed view allows for simpler reading of the activity
+// log contents with identifiers already translated to string values.
+
+#include "chrome/browser/extensions/activity_log/counting_policy.h"
+
+#include <map>
+#include <string>
+#include <vector>
+
+#include "base/callback.h"
+#include "base/files/file_path.h"
+#include "base/json/json_reader.h"
+#include "base/json/json_string_value_serializer.h"
+#include "base/strings/string_util.h"
+#include "base/strings/stringprintf.h"
+#include "chrome/common/chrome_constants.h"
+
+using content::BrowserThread;
+
+namespace {
+
+// Delay between cleaning passes (to delete old action records) through the
+// database.
+const int kCleaningDelayInHours = 12;
+
+// We should log the arguments to these API calls.  Be careful when
+// constructing this whitelist to not keep arguments that might compromise
+// privacy by logging too much data to the activity log.
+//
+// TODO(mvrable): The contents of this whitelist should be reviewed and
+// expanded as needed.
+const char* kAlwaysLog[] = {"extension.connect", "extension.sendMessage",
+                            "tabs.executeScript", "tabs.insertCSS"};
+
+// Columns in the main database table.  See the file-level comment for a
+// discussion of how data is stored and the meanings of the _x columns.
+const char* kTableContentFields[] = {
+    "count", "extension_id_x", "time", "action_type", "api_name_x", "args_x",
+    "page_url_x", "page_title_x", "arg_url_x", "other_x"};
+const char* kTableFieldTypes[] = {
+    "INTEGER NOT NULL DEFAULT 1", "INTEGER NOT NULL", "INTEGER", "INTEGER",
+    "INTEGER", "INTEGER", "INTEGER", "INTEGER", "INTEGER",
+    "INTEGER"};
+
+// Miscellaneous SQL commands for initializing the database; these should be
+// idempotent.
+static const char kPolicyMiscSetup[] =
+    // The activitylog_uncompressed view performs string lookups for simpler
+    // access to the log data.
+    "DROP VIEW IF EXISTS activitylog_uncompressed;\n"
+    "CREATE VIEW activitylog_uncompressed AS\n"
+    "SELECT count,\n"
+    "    x1.value AS extension_id,\n"
+    "    time,\n"
+    "    action_type,\n"
+    "    x2.value AS api_name,\n"
+    "    x3.value AS args,\n"
+    "    x4.value AS page_url,\n"
+    "    x5.value AS page_title,\n"
+    "    x6.value AS arg_url,\n"
+    "    x7.value AS other\n"
+    "FROM activitylog_compressed\n"
+    "    LEFT JOIN string_ids AS x1 ON (x1.id = extension_id_x)\n"
+    "    LEFT JOIN string_ids AS x2 ON (x2.id = api_name_x)\n"
+    "    LEFT JOIN string_ids AS x3 ON (x3.id = args_x)\n"
+    "    LEFT JOIN url_ids    AS x4 ON (x4.id = page_url_x)\n"
+    "    LEFT JOIN string_ids AS x5 ON (x5.id = page_title_x)\n"
+    "    LEFT JOIN url_ids    AS x6 ON (x6.id = arg_url_x)\n"
+    "    LEFT JOIN string_ids AS x7 ON (x7.id = other_x);\n"
+    // An index on all fields except count and time: all the fields that aren't
+    // changed when incrementing a count.  This should accelerate finding the
+    // rows to update (at worst several rows will need to be checked to find
+    // the one in the right time range).
+    "CREATE INDEX IF NOT EXISTS activitylog_compressed_index\n"
+    "ON activitylog_compressed(extension_id_x, action_type, api_name_x,\n"
+    "    args_x, page_url_x, page_title_x, arg_url_x, other_x)";
+
+// SQL statements to clean old, unused entries out of the string and URL id
+// tables.
+static const char kStringTableCleanup[] =
+    "DELETE FROM string_ids WHERE id NOT IN\n"
+    "(SELECT extension_id_x FROM activitylog_compressed\n"
+    " UNION SELECT api_name_x FROM activitylog_compressed\n"
+    " UNION SELECT args_x FROM activitylog_compressed\n"
+    " UNION SELECT page_title_x FROM activitylog_compressed\n"
+    " UNION SELECT other_x FROM activitylog_compressed)";
+static const char kUrlTableCleanup[] =
+    "DELETE FROM url_ids WHERE id NOT IN\n"
+    "(SELECT page_url_x FROM activitylog_compressed\n"
+    " UNION SELECT arg_url_x FROM activitylog_compressed)";
+
+}  // namespace
+
+namespace extensions {
+
+// A specialized Action subclass which is used to represent an action read from
+// the database with a corresponding count.
+class CountedAction : public Action {
+ public:
+  CountedAction(const std::string& extension_id,
+                const base::Time& time,
+                const ActionType action_type,
+                const std::string& api_name)
+      : Action(extension_id, time, action_type, api_name) {}
+
+  // Number of merged records for this action.
+  int count() const { return count_; }
+  void set_count(int count) { count_ = count; }
+
+  virtual std::string PrintForDebug() const OVERRIDE;
+
+ protected:
+  virtual ~CountedAction() {}
+
+ private:
+  int count_;
+};
+
+std::string CountedAction::PrintForDebug() const {
+  return base::StringPrintf(
+      "%s COUNT=%d", Action::PrintForDebug().c_str(), count());
+}
+
+const char* CountingPolicy::kTableName = "activitylog_compressed";
+const char* CountingPolicy::kReadViewName = "activitylog_uncompressed";
+
+CountingPolicy::CountingPolicy(Profile* profile)
+    : ActivityLogDatabasePolicy(
+          profile,
+          base::FilePath(chrome::kExtensionActivityLogFilename)),
+      string_table_("string_ids"),
+      url_table_("url_ids"),
+      retention_time_(base::TimeDelta::FromHours(60)) {
+  for (size_t i = 0; i < arraysize(kAlwaysLog); i++) {
+    api_arg_whitelist_.insert(kAlwaysLog[i]);
+  }
+}
+
+CountingPolicy::~CountingPolicy() {}
+
+bool CountingPolicy::InitDatabase(sql::Connection* db) {
+  if (!Util::DropObsoleteTables(db))
+    return false;
+
+  if (!string_table_.Initialize(db))
+    return false;
+  if (!url_table_.Initialize(db))
+    return false;
+
+  // Create the unified activity log entry table.
+  if (!ActivityDatabase::InitializeTable(db,
+                                         kTableName,
+                                         kTableContentFields,
+                                         kTableFieldTypes,
+                                         arraysize(kTableContentFields)))
+    return false;
+
+  // Create a view for easily accessing the uncompressed form of the data, and
+  // any necessary indexes if needed.
+  return db->Execute(kPolicyMiscSetup);
+}
+
+void CountingPolicy::ProcessAction(scoped_refptr<Action> action) {
+  ScheduleAndForget(this, &CountingPolicy::QueueAction, action);
+}
+
+void CountingPolicy::QueueAction(scoped_refptr<Action> action) {
+  if (activity_database()->is_db_valid()) {
+    action = action->Clone();
+    Util::StripPrivacySensitiveFields(action);
+    Util::StripArguments(api_arg_whitelist_, action);
+    queued_actions_.push_back(action);
+    activity_database()->AdviseFlush(queued_actions_.size());
+  }
+}
+
+bool CountingPolicy::FlushDatabase(sql::Connection* db) {
+  // Columns that must match exactly for database rows to be coalesced.
+  static const char* matched_columns[] = {
+      "extension_id_x", "action_type", "api_name_x", "args_x", "page_url_x",
+      "page_title_x", "arg_url_x", "other_x"};
+  Action::ActionVector queue;
+  queue.swap(queued_actions_);
+
+  // Whether to clean old records out of the activity log database.  Do this
+  // much less frequently than database flushes since it is expensive, but
+  // always check on the first database flush (since there might be a large
+  // amount of data to clear).
+  bool clean_database = (last_database_cleaning_time_.is_null() ||
+                         Now() - last_database_cleaning_time_ >
+                             base::TimeDelta::FromHours(kCleaningDelayInHours));
+
+  if (queue.empty() && !clean_database)
+    return true;
+
+  sql::Transaction transaction(db);
+  if (!transaction.Begin())
+    return false;
+
+  std::string insert_str =
+      "INSERT INTO " + std::string(kTableName) + "(count, time";
+  std::string update_str =
+      "UPDATE " + std::string(kTableName) +
+      " SET count = count + 1, time = max(?, time)"
+      " WHERE time >= ? AND time < ?";
+
+  for (size_t i = 0; i < arraysize(matched_columns); i++) {
+    insert_str =
+        base::StringPrintf("%s, %s", insert_str.c_str(), matched_columns[i]);
+    update_str = base::StringPrintf(
+        "%s AND %s IS ?", update_str.c_str(), matched_columns[i]);
+  }
+  insert_str += ") VALUES (1, ?";
+  for (size_t i = 0; i < arraysize(matched_columns); i++) {
+    insert_str += ", ?";
+  }
+  insert_str += ")";
+
+  Action::ActionVector::size_type i;
+  for (i = 0; i != queue.size(); ++i) {
+    const Action& action = *queue[i];
+
+    base::Time day_start = action.time().LocalMidnight();
+    base::Time next_day = Util::AddDays(day_start, 1);
+
+    // The contents in values must match up with fields in matched_columns.  A
+    // value of -1 is used to encode a null database value.
+    int64 id;
+    std::vector<int64> matched_values;
+
+    if (!string_table_.StringToInt(db, action.extension_id(), &id))
+      return false;
+    matched_values.push_back(id);
+
+    matched_values.push_back(static_cast<int>(action.action_type()));
+
+    if (!string_table_.StringToInt(db, action.api_name(), &id))
+      return false;
+    matched_values.push_back(id);
+
+    if (action.args()) {
+      std::string args = Util::Serialize(action.args());
+      // TODO(mvrable): For now, truncate long argument lists.  This is a
+      // workaround for excessively-long values coming from DOM logging.  When
+      // the V8ValueConverter is fixed to return more reasonable values, we can
+      // drop the truncation.
+      if (args.length() > 10000) {
+        args = "[\"<too_large>\"]";
+      }
+      if (!string_table_.StringToInt(db, args, &id))
+        return false;
+      matched_values.push_back(id);
+    } else {
+      matched_values.push_back(-1);
+    }
+
+    std::string page_url_string = action.SerializePageUrl();
+    if (!page_url_string.empty()) {
+      if (!url_table_.StringToInt(db, page_url_string, &id))
+        return false;
+      matched_values.push_back(id);
+    } else {
+      matched_values.push_back(-1);
+    }
+
+    // TODO(mvrable): Create a title_table_?
+    if (!action.page_title().empty()) {
+      if (!string_table_.StringToInt(db, action.page_title(), &id))
+        return false;
+      matched_values.push_back(id);
+    } else {
+      matched_values.push_back(-1);
+    }
+
+    std::string arg_url_string = action.SerializeArgUrl();
+    if (!arg_url_string.empty()) {
+      if (!url_table_.StringToInt(db, arg_url_string, &id))
+        return false;
+      matched_values.push_back(id);
+    } else {
+      matched_values.push_back(-1);
+    }
+
+    if (action.other()) {
+      if (!string_table_.StringToInt(db, Util::Serialize(action.other()), &id))
+        return false;
+      matched_values.push_back(id);
+    } else {
+      matched_values.push_back(-1);
+    }
+
+    // Assume there is an existing row for this action, and try to update the
+    // count.
+    sql::Statement update_statement(db->GetCachedStatement(
+        sql::StatementID(SQL_FROM_HERE), update_str.c_str()));
+    update_statement.BindInt64(0, action.time().ToInternalValue());
+    update_statement.BindInt64(1, day_start.ToInternalValue());
+    update_statement.BindInt64(2, next_day.ToInternalValue());
+    for (size_t j = 0; j < matched_values.size(); j++) {
+      if (matched_values[j] == -1)
+        update_statement.BindNull(j + 3);
+      else
+        update_statement.BindInt64(j + 3, matched_values[j]);
+    }
+    if (!update_statement.Run())
+      return false;
+
+    // Check if the update succeeded (was the count of updated rows non-zero)?
+    // If it failed because no matching row existed, fall back to inserting a
+    // new record.
+    if (db->GetLastChangeCount() > 0) {
+      if (db->GetLastChangeCount() > 1) {
+        LOG(WARNING) << "Found and updated multiple rows in the activity log "
+                     << "database; counts may be off!";
+      }
+      continue;
+    }
+    sql::Statement insert_statement(db->GetCachedStatement(
+        sql::StatementID(SQL_FROM_HERE), insert_str.c_str()));
+    insert_statement.BindInt64(0, action.time().ToInternalValue());
+    for (size_t j = 0; j < matched_values.size(); j++) {
+      if (matched_values[j] == -1)
+        update_statement.BindNull(j + 1);
+      else
+        insert_statement.BindInt64(j + 1, matched_values[j]);
+    }
+    if (!insert_statement.Run())
+      return false;
+  }
+
+  if (clean_database) {
+    base::Time cutoff = (Now() - retention_time()).LocalMidnight();
+    if (!CleanOlderThan(db, cutoff))
+      return false;
+    last_database_cleaning_time_ = Now();
+  }
+
+  if (!transaction.Commit())
+    return false;
+
+  return true;
+}
+
+scoped_ptr<Action::ActionVector> CountingPolicy::DoReadData(
+    const std::string& extension_id,
+    const int days_ago) {
+  // Ensure data is flushed to the database first so that we query over all
+  // data.
+  activity_database()->AdviseFlush(ActivityDatabase::kFlushImmediately);
+
+  DCHECK_GE(days_ago, 0);
+  scoped_ptr<Action::ActionVector> actions(new Action::ActionVector());
+
+  sql::Connection* db = GetDatabaseConnection();
+  if (!db) {
+    return actions.Pass();
+  }
+
+  int64 early_bound;
+  int64 late_bound;
+  Util::ComputeDatabaseTimeBounds(Now(), days_ago, &early_bound, &late_bound);
+  std::string query_str = base::StringPrintf(
+      "SELECT time, action_type, api_name, args, page_url, page_title, "
+      "arg_url, other, count "
+      "FROM %s WHERE extension_id=? AND time>? AND time<=? "
+      "ORDER BY time DESC",
+      kReadViewName);
+  sql::Statement query(db->GetCachedStatement(SQL_FROM_HERE,
+                                              query_str.c_str()));
+  query.BindString(0, extension_id);
+  query.BindInt64(1, early_bound);
+  query.BindInt64(2, late_bound);
+
+  while (query.is_valid() && query.Step()) {
+    scoped_refptr<CountedAction> action =
+        new CountedAction(extension_id,
+                          base::Time::FromInternalValue(query.ColumnInt64(0)),
+                          static_cast<Action::ActionType>(query.ColumnInt(1)),
+                          query.ColumnString(2));
+
+    if (query.ColumnType(3) != sql::COLUMN_TYPE_NULL) {
+      scoped_ptr<Value> parsed_value(
+          base::JSONReader::Read(query.ColumnString(3)));
+      if (parsed_value && parsed_value->IsType(Value::TYPE_LIST)) {
+        action->set_args(
+            make_scoped_ptr(static_cast<ListValue*>(parsed_value.release())));
+      } else {
+        LOG(WARNING) << "Unable to parse args: '" << query.ColumnString(3)
+                     << "'";
+      }
+    }
+
+    action->ParsePageUrl(query.ColumnString(4));
+    action->set_page_title(query.ColumnString(5));
+    action->ParseArgUrl(query.ColumnString(6));
+
+    if (query.ColumnType(7) != sql::COLUMN_TYPE_NULL) {
+      scoped_ptr<Value> parsed_value(
+          base::JSONReader::Read(query.ColumnString(7)));
+      if (parsed_value && parsed_value->IsType(Value::TYPE_DICTIONARY)) {
+        action->set_other(make_scoped_ptr(
+            static_cast<DictionaryValue*>(parsed_value.release())));
+      } else {
+        LOG(WARNING) << "Unable to parse other: '" << query.ColumnString(7)
+                     << "'";
+      }
+    }
+
+    action->set_count(query.ColumnInt(8));
+
+    actions->push_back(action);
+  }
+
+  return actions.Pass();
+}
+
+void CountingPolicy::ReadData(
+    const std::string& extension_id,
+    const int day,
+    const base::Callback<void(scoped_ptr<Action::ActionVector>)>& callback) {
+  BrowserThread::PostTaskAndReplyWithResult(
+      BrowserThread::DB,
+      FROM_HERE,
+      base::Bind(&CountingPolicy::DoReadData,
+                 base::Unretained(this),
+                 extension_id,
+                 day),
+      callback);
+}
+
+void CountingPolicy::OnDatabaseFailure() {
+  queued_actions_.clear();
+}
+
+void CountingPolicy::OnDatabaseClose() {
+  delete this;
+}
+
+// Cleans old records from the activity log database.
+bool CountingPolicy::CleanOlderThan(sql::Connection* db,
+                                    const base::Time& cutoff) {
+  std::string clean_statement =
+      "DELETE FROM " + std::string(kTableName) + " WHERE time < ?";
+  sql::Statement cleaner(db->GetCachedStatement(sql::StatementID(SQL_FROM_HERE),
+                                                clean_statement.c_str()));
+  cleaner.BindInt64(0, cutoff.ToInternalValue());
+  if (!cleaner.Run())
+    return false;
+  return CleanStringTables(db);
+}
+
+// Cleans unused interned strings from the database.  This should be run after
+// deleting rows from the main log table to clean out stale values.
+bool CountingPolicy::CleanStringTables(sql::Connection* db) {
+  sql::Statement cleaner1(db->GetCachedStatement(
+      sql::StatementID(SQL_FROM_HERE), kStringTableCleanup));
+  if (!cleaner1.Run())
+    return false;
+  if (db->GetLastChangeCount() > 0)
+    string_table_.ClearCache();
+
+  sql::Statement cleaner2(db->GetCachedStatement(
+      sql::StatementID(SQL_FROM_HERE), kUrlTableCleanup));
+  if (!cleaner2.Run())
+    return false;
+  if (db->GetLastChangeCount() > 0)
+    url_table_.ClearCache();
+
+  return true;
+}
+
+void CountingPolicy::Close() {
+  // The policy object should have never been created if there's no DB thread.
+  DCHECK(BrowserThread::IsMessageLoopValid(BrowserThread::DB));
+  ScheduleAndForget(activity_database(), &ActivityDatabase::Close);
+}
+
+}  // namespace extensions