Log Upload Throttling on Chrome Process Restart

Currently the logs were being uploaded at each chrome process restart.
Upload at most K logs in any X hours window. This prevents log uploading at start of each chrome process. Local state of chrome process is maintained across reboots. Maintained a List of uploads made in the previous X hour window.
UpdateLocalStateForLogs() keeps the logs updated for previous X hour window and appends if any upload is made recently.

The unit test makes K+3 uploads consecutively, and checks if delay of first K uploads is 0 and for the remaining uploads it is approximately X.
Another unit test checks that immediate log upload is not throttled.
Initial Commit

Bug: 789481
Change-Id: I16cadf69e68d8982b5b2384aebbeb6cdad892d2e
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/1876092
Commit-Queue: Swapnil Gupta <swapnilgupta@google.com>
Reviewed-by: Sergey Poromov <poromov@chromium.org>
Reviewed-by: Ivan Šandrk <isandrk@chromium.org>
Cr-Commit-Position: refs/heads/master@{#713395}

chrome/browser/chromeos/BUILD.gn

@@ -1778,6 +1778,8 @@ source_set("chromeos") {
     "policy/policy_cert_service_factory.h",
     "policy/policy_oauth2_token_fetcher.cc",
     "policy/policy_oauth2_token_fetcher.h",
+    "policy/policy_pref_names.cc",
+    "policy/policy_pref_names.h",
     "policy/pre_signin_policy_fetcher.cc",
     "policy/pre_signin_policy_fetcher.h",
     "policy/remote_commands/affiliated_remote_commands_invalidator.cc",

chrome/browser/chromeos/policy/device_cloud_policy_manager_chromeos.cc

@@ -29,6 +29,7 @@
 #include "chrome/browser/chromeos/login/startup_utils.h"
 #include "chrome/browser/chromeos/policy/device_cloud_policy_store_chromeos.h"
 #include "chrome/browser/chromeos/policy/heartbeat_scheduler.h"
+#include "chrome/browser/chromeos/policy/policy_pref_names.h"
 #include "chrome/browser/chromeos/policy/remote_commands/device_commands_factory_chromeos.h"
 #include "chrome/browser/chromeos/policy/rsu/lookup_key_uploader.h"
 #include "chrome/browser/chromeos/policy/server_backed_state_keys_broker.h"
@@ -243,6 +244,7 @@ void DeviceCloudPolicyManagerChromeOS::RegisterPrefs(
   registry->RegisterDictionaryPref(prefs::kServerBackedDeviceState);
   registry->RegisterBooleanPref(prefs::kRemoveUsersRemoteCommand, false);
   registry->RegisterStringPref(prefs::kLastRsuDeviceIdUploaded, std::string());
+  registry->RegisterListPref(prefs::kStoreLogStatesAcrossReboots);
 }
 
 // static

chrome/browser/chromeos/policy/policy_pref_names.cc

+// Copyright 2019 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/chromeos/policy/policy_pref_names.h"
+
+namespace prefs {
+
+// Maintain a list of last upload times of system logs in double type; this is
+// for the purpose of throttling log uploads.
+const char kStoreLogStatesAcrossReboots[] =
+    "policy_store_log_states_across_reboots";
+
+}  // namespace prefs

chrome/browser/chromeos/policy/policy_pref_names.h

+// Copyright 2019 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.
+
+#ifndef CHROME_BROWSER_CHROMEOS_POLICY_POLICY_PREF_NAMES_H_
+#define CHROME_BROWSER_CHROMEOS_POLICY_POLICY_PREF_NAMES_H_
+
+namespace prefs {
+
+// Non-specific prefs.
+extern const char kStoreLogStatesAcrossReboots[];
+
+}  // namespace prefs
+
+#endif  // CHROME_BROWSER_CHROMEOS_POLICY_POLICY_PREF_NAMES_H_

chrome/browser/chromeos/policy/system_log_uploader.cc

@@ -4,8 +4,10 @@
 
 #include "chrome/browser/chromeos/policy/system_log_uploader.h"
 
+#include <algorithm>
 #include <map>
 #include <utility>
+#include <vector>
 
 #include "base/bind.h"
 #include "base/bind_helpers.h"
@@ -19,7 +21,9 @@
 #include "base/strings/stringprintf.h"
 #include "base/syslog_logging.h"
 #include "base/task/post_task.h"
+#include "base/values.h"
 #include "chrome/browser/browser_process.h"
+#include "chrome/browser/chromeos/policy/policy_pref_names.h"
 #include "chrome/browser/chromeos/policy/upload_job_impl.h"
 #include "chrome/browser/chromeos/settings/device_oauth2_token_service.h"
 #include "chrome/browser/chromeos/settings/device_oauth2_token_service_factory.h"
@@ -30,6 +34,7 @@
 #include "chrome/common/extensions/extension_constants.h"
 #include "components/feedback/anonymizer_tool.h"
 #include "components/policy/core/browser/browser_policy_connector.h"
+#include "components/prefs/pref_service.h"
 #include "components/user_manager/user_manager.h"
 #include "net/http/http_request_headers.h"
 #include "services/network/public/cpp/shared_url_loader_factory.h"
@@ -273,6 +278,13 @@ const int64_t SystemLogUploader::kDefaultUploadDelayMs =
 const int64_t SystemLogUploader::kErrorUploadDelayMs =
     120 * 1000;  // 120 seconds
 
+// Determines max number of logs to be uploaded in kLogThrottleWindowDuration.
+const int64_t SystemLogUploader::kLogThrottleCount = 100;
+
+// Determines the time window for which the upload times should be stored.
+const base::TimeDelta SystemLogUploader::kLogThrottleWindowDuration =
+    base::TimeDelta::FromHours(24);
+
 // String constant identifying the header field which stores the file type.
 const char* const SystemLogUploader::kFileTypeHeaderName = "File-Type";
 
@@ -500,6 +512,55 @@ void SystemLogUploader::OnSystemLogsLoaded(
   }
 }
 
+// Update the list of logs within kLogThrottleWindowDuration window and add the
+// latest log upload time if any.
+base::Time SystemLogUploader::UpdateLocalStateForLogs() {
+  const base::Time now = base::Time::NowFromSystemTime();
+  PrefService* local_state = g_browser_process->local_state();
+
+  const base::ListValue* prev_log_uploads =
+      local_state->GetList(prefs::kStoreLogStatesAcrossReboots);
+
+  std::vector<base::Time> updated_log_uploads;
+
+  for (const base::Value& item : *prev_log_uploads) {
+    // ListValue stores Value type and Value does not support base::Time,
+    // so we store double and convert to base::Time here.
+    const base::Time current_item_time =
+        base::Time::FromDoubleT(item.GetDouble());
+
+    // Logs are valid only if they occur in previous kLogThrottleWindowDuration
+    // time window.
+    if (now - current_item_time <= kLogThrottleWindowDuration)
+      updated_log_uploads.push_back(current_item_time);
+  }
+
+  if (!last_upload_attempt_.is_null() &&
+      (updated_log_uploads.empty() ||
+       last_upload_attempt_ > updated_log_uploads.back())) {
+    updated_log_uploads.push_back(last_upload_attempt_);
+  }
+
+  // This happens only in case of ScheduleNextSystemLogUploadImmediately. It is
+  // sufficient to delete only one entry as at most 1 entry is appended on the
+  // method call, hence the list size would exceed by at most 1.
+  if (updated_log_uploads.size() > kLogThrottleCount)
+    updated_log_uploads.erase(updated_log_uploads.begin());
+
+  // Create a list to be updated for the pref.
+  base::Value updated_prev_log_uploads(base::Value::Type::LIST);
+  for (auto it : updated_log_uploads) {
+    updated_prev_log_uploads.Append(it.ToDoubleT());
+  }
+  local_state->Set(prefs::kStoreLogStatesAcrossReboots,
+                   updated_prev_log_uploads);
+
+  // Write the changes to the disk to prevent loss of changes.
+  local_state->CommitPendingWrite();
+  // If there are no log entries till now, return zero value.
+  return updated_log_uploads.empty() ? base::Time() : updated_log_uploads[0];
+}
+
 void SystemLogUploader::ScheduleNextSystemLogUpload(base::TimeDelta frequency) {
   // Don't schedule a new system log upload if there's a log upload in progress
   // (it will be scheduled once the current one completes).
@@ -508,14 +569,25 @@ void SystemLogUploader::ScheduleNextSystemLogUpload(base::TimeDelta frequency) {
                  << "next one until this one finishes.";
     return;
   }
-
+  base::Time last_valid_log_upload = UpdateLocalStateForLogs();
   // Calculate when to fire off the next update.
   base::TimeDelta delay = std::max(
       (last_upload_attempt_ + frequency) - base::Time::NowFromSystemTime(),
       base::TimeDelta());
+
+  // To ensure at most kLogThrottleCount logs are uploaded in
+  // kLogThrottleWindowDuration time.
+  if (g_browser_process->local_state()
+              ->GetList(prefs::kStoreLogStatesAcrossReboots)
+              ->GetSize() >= kLogThrottleCount &&
+      !frequency.is_zero()) {
+    delay = std::max(delay, last_valid_log_upload + kLogThrottleWindowDuration -
+                                base::Time::NowFromSystemTime());
+  }
+
   SYSLOG(INFO) << "Scheduling next system log upload " << delay << " from now.";
   // Ensure that we never have more than one pending delayed task
-  // (InvalidateWeakPtrs() will cancel any pending log uploads).
+  // (InvalidateWeakPtrs() will cancel any pending calls to log uploads).
   weak_factory_.InvalidateWeakPtrs();
   task_runner_->PostDelayedTask(
       FROM_HERE,

chrome/browser/chromeos/policy/system_log_uploader.h

@@ -48,6 +48,9 @@ class SystemLogUploader : public UploadJob::Delegate {
   static const int64_t kDefaultUploadDelayMs;
   static const int64_t kErrorUploadDelayMs;
 
+  static const int64_t kLogThrottleCount;
+  static const base::TimeDelta kLogThrottleWindowDuration;
+
   // Http header constants to upload non-zipped logs.
   static const char* const kNameFieldTemplate;
   static const char* const kFileTypeHeaderName;
@@ -119,6 +122,12 @@ class SystemLogUploader : public UploadJob::Delegate {
 
   void ScheduleNextSystemLogUploadImmediately();
 
+  // Removes the log upload times before the particular time window ( which were
+  // uploaded before kLogThrottleWindowDuration time from now), add the latest
+  // log upload time if any and return the oldest log upload time in the
+  // particular time window.
+  base::Time UpdateLocalStateForLogs();
+
   // UploadJob::Delegate:
   // Callbacks handle success and failure results of upload, destroy the
   // upload job.

chrome/browser/chromeos/policy/system_log_uploader_unittest.cc

@@ -12,8 +12,11 @@
 #include "base/test/test_simple_task_runner.h"
 #include "base/time/time.h"
 #include "chrome/browser/chromeos/settings/scoped_cros_settings_test_helper.h"
+#include "chrome/browser/prefs/browser_prefs.h"
 #include "chrome/common/chrome_features.h"
+#include "chrome/test/base/testing_browser_process.h"
 #include "components/feedback/anonymizer_tool.h"
+#include "components/prefs/testing_pref_service.h"
 #include "content/public/test/browser_task_environment.h"
 #include "content/public/test/test_utils.h"
 #include "net/http/http_request_headers.h"
@@ -27,6 +30,10 @@ namespace {
 constexpr char kPolicyDumpFileLocation[] = "/var/log/policy_dump.json";
 constexpr char kPolicyDump[] = "{}";
 
+// A small time interval to check log throttling.
+constexpr base::TimeDelta kLogThrottleDeltaTime =
+    base::TimeDelta::FromMilliseconds(100);
+
 // The list of tested system log file names.
 const char* const kTestSystemLogFileNames[] = {"name1.txt", "name32.txt"};
 
@@ -220,18 +227,21 @@ class MockSystemLogDelegate : public SystemLogUploader::Delegate {
 
 class SystemLogUploaderTest : public testing::TestWithParam<bool> {
  public:
+  TestingPrefServiceSimple local_state_;
   SystemLogUploaderTest()
       : task_runner_(new base::TestSimpleTaskRunner()),
         is_zipped_upload_(GetParam()) {
     feature_list.InitWithFeatureState(features::kUploadZippedSystemLogs,
                                       is_zipped_upload_);
   }
-
   void SetUp() override {
+    RegisterLocalState(local_state_.registry());
+    TestingBrowserProcess::GetGlobal()->SetLocalState(&local_state_);
     settings_helper_.ReplaceDeviceSettingsProviderWithStub();
   }
 
   void TearDown() override {
+    TestingBrowserProcess::GetGlobal()->SetLocalState(nullptr);
     settings_helper_.RestoreRealDeviceSettingsProvider();
     content::RunAllTasksUntilIdle();
   }
@@ -285,6 +295,62 @@ class SystemLogUploaderTest : public testing::TestWithParam<bool> {
   base::HistogramTester histogram_tester_;
 };
 
+// Verify log throttling. Try successive kLogThrottleCount log uploads by
+// creating a new task. First kLogThrottleCount logs should have 0 delay.
+// Successive logs should have approx. kLogThrottleWindowDuration delay.
+TEST_P(SystemLogUploaderTest, LogThrottleTest) {
+  for (int upload_num = 0;
+       upload_num < SystemLogUploader::kLogThrottleCount + 3; upload_num++) {
+    EXPECT_FALSE(task_runner_->HasPendingTask());
+    auto syslog_delegate = std::make_unique<MockSystemLogDelegate>(
+        false, SystemLogUploader::SystemLogs(), is_zipped_upload_);
+
+    syslog_delegate->set_upload_allowed(true);
+    settings_helper_.SetBoolean(chromeos::kSystemLogUploadEnabled, true);
+
+    SystemLogUploader uploader(std::move(syslog_delegate), task_runner_);
+
+    EXPECT_EQ(1U, task_runner_->NumPendingTasks());
+
+    if (upload_num < SystemLogUploader::kLogThrottleCount) {
+      EXPECT_EQ(task_runner_->NextPendingTaskDelay(),
+                base::TimeDelta::FromMilliseconds(0));
+    } else {
+      // The delay would be in a small delta range of
+      // kLogThrottleWindowDuration.
+      EXPECT_GE(task_runner_->NextPendingTaskDelay(),
+                SystemLogUploader::kLogThrottleWindowDuration -
+                    kLogThrottleDeltaTime);
+      EXPECT_LE(task_runner_->NextPendingTaskDelay(),
+                SystemLogUploader::kLogThrottleWindowDuration +
+                    kLogThrottleDeltaTime);
+    }
+
+    task_runner_->RunPendingTasks();
+    task_runner_->ClearPendingTasks();
+  }
+}
+
+// Verify that we never throttle immediate log upload.
+TEST_P(SystemLogUploaderTest, ImmediateLogUpload) {
+  EXPECT_FALSE(task_runner_->HasPendingTask());
+  auto syslog_delegate = std::make_unique<MockSystemLogDelegate>(
+      false, SystemLogUploader::SystemLogs(), is_zipped_upload_);
+
+  syslog_delegate->set_upload_allowed(true);
+  settings_helper_.SetBoolean(chromeos::kSystemLogUploadEnabled, true);
+
+  SystemLogUploader uploader(std::move(syslog_delegate), task_runner_);
+  for (int upload_num = 0;
+       upload_num < SystemLogUploader::kLogThrottleCount + 3; upload_num++) {
+    uploader.ScheduleNextSystemLogUploadImmediately();
+    EXPECT_EQ(task_runner_->NextPendingTaskDelay(),
+              base::TimeDelta::FromMilliseconds(0));
+    task_runner_->RunPendingTasks();
+    task_runner_->ClearPendingTasks();
+  }
+}
+
 // Check disabled system log uploads by default.
 TEST_P(SystemLogUploaderTest, Basic) {
   EXPECT_FALSE(task_runner_->HasPendingTask());
@@ -321,7 +387,7 @@ TEST_P(SystemLogUploaderTest, SuccessTest) {
   ExpectSuccessHistogram(/*amount=*/1);
 }
 
-// Three failed responses recieved.
+// Three failed responses received.
 TEST_P(SystemLogUploaderTest, ThreeFailureTest) {
   EXPECT_FALSE(task_runner_->HasPendingTask());