Trim in-memory logs in unsent_log_store when attempting to persist.

This will actually trim large logs if they cannot be uploaded right away. I'm not sure this is behavior we want, although I presume logs large enough to hit our limits (looks like 100K currently from metrics_reporting_service.cc) are large enough it probably makes sense to trim. Curious if you think this is risky.

After writing this, i considered changing the API such that the trimming call and persisting are seperate. Not sure which is better, but trimming at the time of persisting seems like a reasonable place to do it, so left it this way as it is simpler.


Bug: 1098317

Change-Id: Ieb72890d45f8ec3735403f5aa5695e6044df0b5e
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2257503
Commit-Queue: Robert Kaplow <rkaplow@chromium.org>
Reviewed-by: Steven Holte <holte@chromium.org>
Cr-Commit-Position: refs/heads/master@{#789055}

components/metrics/log_store.h

@@ -46,8 +46,8 @@ class LogStore {
   // the staged log needs discarded.
   virtual void MarkStagedLogAsSent() = 0;
 
-  // Saves any unsent logs to persistent storage.
-  virtual void PersistUnsentLogs() const = 0;
+  // Trims saved logs and writes to persistent storage.
+  virtual void TrimAndPersistUnsentLogs() = 0;
 
   // Loads unsent logs from persistent storage.
   virtual void LoadPersistedUnsentLogs() = 0;

components/metrics/metrics_log_store.cc

@@ -138,13 +138,13 @@ void MetricsLogStore::MarkStagedLogAsSent() {
     ongoing_log_queue_.MarkStagedLogAsSent();
 }
 
-void MetricsLogStore::PersistUnsentLogs() const {
+void MetricsLogStore::TrimAndPersistUnsentLogs() {
   DCHECK(unsent_logs_loaded_);
   if (!unsent_logs_loaded_)
     return;
 
-  initial_log_queue_.PersistUnsentLogs();
-  ongoing_log_queue_.PersistUnsentLogs();
+  initial_log_queue_.TrimAndPersistUnsentLogs();
+  ongoing_log_queue_.TrimAndPersistUnsentLogs();
 }
 
 }  // namespace metrics

components/metrics/metrics_log_store.h

@@ -51,7 +51,7 @@ class MetricsLogStore : public LogStore {
   void StageNextLog() override;
   void DiscardStagedLog() override;
   void MarkStagedLogAsSent() override;
-  void PersistUnsentLogs() const override;
+  void TrimAndPersistUnsentLogs() override;
   void LoadPersistedUnsentLogs() override;
 
   // Inspection methods for tests.

components/metrics/metrics_log_store_unittest.cc

@@ -70,7 +70,7 @@ TEST_F(MetricsLogStoreTest, StoreAndLoad) {
     log_store.LoadPersistedUnsentLogs();
     EXPECT_FALSE(log_store.has_unsent_logs());
     log_store.StoreLog("a", MetricsLog::ONGOING_LOG, base::nullopt);
-    log_store.PersistUnsentLogs();
+    log_store.TrimAndPersistUnsentLogs();
     EXPECT_EQ(0U, TypeCount(MetricsLog::INITIAL_STABILITY_LOG));
     EXPECT_EQ(1U, TypeCount(MetricsLog::ONGOING_LOG));
   }
@@ -91,7 +91,7 @@ TEST_F(MetricsLogStoreTest, StoreAndLoad) {
     EXPECT_EQ(0U, TypeCount(MetricsLog::INITIAL_STABILITY_LOG));
     EXPECT_EQ(1U, TypeCount(MetricsLog::ONGOING_LOG));
 
-    log_store.PersistUnsentLogs();
+    log_store.TrimAndPersistUnsentLogs();
     EXPECT_EQ(1U, TypeCount(MetricsLog::INITIAL_STABILITY_LOG));
     EXPECT_EQ(2U, TypeCount(MetricsLog::ONGOING_LOG));
   }
@@ -106,7 +106,7 @@ TEST_F(MetricsLogStoreTest, StoreAndLoad) {
     log_store.DiscardStagedLog();
     // The initial log should be sent first; update the persisted storage to
     // verify.
-    log_store.PersistUnsentLogs();
+    log_store.TrimAndPersistUnsentLogs();
     EXPECT_EQ(0U, TypeCount(MetricsLog::INITIAL_STABILITY_LOG));
     EXPECT_EQ(2U, TypeCount(MetricsLog::ONGOING_LOG));
 
@@ -120,11 +120,11 @@ TEST_F(MetricsLogStoreTest, StoreAndLoad) {
     log_store.DiscardStagedLog();
     EXPECT_FALSE(log_store.has_unsent_logs());
 
-    // Nothing should have changed "on disk" since PersistUnsentLogs hasn't been
-    // called again.
+    // Nothing should have changed "on disk" since TrimAndPersistUnsentLogs
+    // hasn't been called again.
     EXPECT_EQ(2U, TypeCount(MetricsLog::ONGOING_LOG));
     // Persist, and make sure nothing is left.
-    log_store.PersistUnsentLogs();
+    log_store.TrimAndPersistUnsentLogs();
     EXPECT_EQ(0U, TypeCount(MetricsLog::INITIAL_STABILITY_LOG));
     EXPECT_EQ(0U, TypeCount(MetricsLog::ONGOING_LOG));
   }
@@ -136,7 +136,7 @@ TEST_F(MetricsLogStoreTest, StoreStagedOngoingLog) {
   log_store.LoadPersistedUnsentLogs();
   log_store.StoreLog("a", MetricsLog::ONGOING_LOG, base::nullopt);
   log_store.StageNextLog();
-  log_store.PersistUnsentLogs();
+  log_store.TrimAndPersistUnsentLogs();
 
   EXPECT_EQ(0U, TypeCount(MetricsLog::INITIAL_STABILITY_LOG));
   EXPECT_EQ(1U, TypeCount(MetricsLog::ONGOING_LOG));
@@ -148,7 +148,7 @@ TEST_F(MetricsLogStoreTest, StoreStagedInitialLog) {
   log_store.LoadPersistedUnsentLogs();
   log_store.StoreLog("b", MetricsLog::INITIAL_STABILITY_LOG, base::nullopt);
   log_store.StageNextLog();
-  log_store.PersistUnsentLogs();
+  log_store.TrimAndPersistUnsentLogs();
 
   EXPECT_EQ(1U, TypeCount(MetricsLog::INITIAL_STABILITY_LOG));
   EXPECT_EQ(0U, TypeCount(MetricsLog::ONGOING_LOG));
@@ -164,7 +164,7 @@ TEST_F(MetricsLogStoreTest, LargeLogDiscarding) {
   log_store.StoreLog("not_persisted", MetricsLog::ONGOING_LOG, base::nullopt);
 
   // Only the stability log should be written out, due to the threshold.
-  log_store.PersistUnsentLogs();
+  log_store.TrimAndPersistUnsentLogs();
   EXPECT_EQ(1U, TypeCount(MetricsLog::INITIAL_STABILITY_LOG));
   EXPECT_EQ(0U, TypeCount(MetricsLog::ONGOING_LOG));
 }

components/metrics/metrics_service.cc

@@ -662,7 +662,7 @@ void MetricsService::PushPendingLogsToPersistentStorage() {
     return;  // We didn't and still don't have time to get plugin list etc.
 
   CloseCurrentLog();
-  log_store()->PersistUnsentLogs();
+  log_store()->TrimAndPersistUnsentLogs();
 }
 
 //------------------------------------------------------------------------------
@@ -769,7 +769,7 @@ bool MetricsService::PrepareInitialStabilityLog(
 
   // Store unsent logs, including the stability log that was just saved, so
   // that they're not lost in case of a crash before upload time.
-  log_store()->PersistUnsentLogs();
+  log_store()->TrimAndPersistUnsentLogs();
 
   return true;
 }
@@ -799,7 +799,7 @@ void MetricsService::PrepareInitialMetricsLog() {
 
   // Store unsent logs, including the initial log that was just saved, so
   // that they're not lost in case of a crash before upload time.
-  log_store()->PersistUnsentLogs();
+  log_store()->TrimAndPersistUnsentLogs();
 
   state_ = SENDING_LOGS;
 }

components/metrics/reporting_service.cc

@@ -198,7 +198,7 @@ void ReportingService::OnLogUploadComplete(int response_code,
 
       log_store()->DiscardStagedLog();
       // Store the updated list to disk now that the removed log is uploaded.
-      log_store()->PersistUnsentLogs();
+      log_store()->TrimAndPersistUnsentLogs();
     }
   }
 

components/metrics/reporting_service_unittest.cc

@@ -57,7 +57,7 @@ class TestLogStore : public LogStore {
     staged_log_hash_.clear();
   }
   void MarkStagedLogAsSent() override {}
-  void PersistUnsentLogs() const override {}
+  void TrimAndPersistUnsentLogs() override {}
   void LoadPersistedUnsentLogs() override {}
 
  private:

components/metrics/unsent_log_store.cc

@@ -120,25 +120,25 @@ bool UnsentLogStore::has_staged_log() const {
 // Returns the compressed data of the element in the front of the list.
 const std::string& UnsentLogStore::staged_log() const {
   DCHECK(has_staged_log());
-  return list_[staged_log_index_].compressed_log_data;
+  return list_[staged_log_index_]->compressed_log_data;
 }
 
 // Returns the hash of element in the front of the list.
 const std::string& UnsentLogStore::staged_log_hash() const {
   DCHECK(has_staged_log());
-  return list_[staged_log_index_].hash;
+  return list_[staged_log_index_]->hash;
 }
 
 // Returns the signature of element in the front of the list.
 const std::string& UnsentLogStore::staged_log_signature() const {
   DCHECK(has_staged_log());
-  return list_[staged_log_index_].signature;
+  return list_[staged_log_index_]->signature;
 }
 
 // Returns the timestamp of the element in the front of the list.
 const std::string& UnsentLogStore::staged_log_timestamp() const {
   DCHECK(has_staged_log());
-  return list_[staged_log_index_].timestamp;
+  return list_[staged_log_index_]->timestamp;
 }
 
 void UnsentLogStore::StageNextLog() {
@@ -160,15 +160,16 @@ void UnsentLogStore::DiscardStagedLog() {
 void UnsentLogStore::MarkStagedLogAsSent() {
   DCHECK(has_staged_log());
   DCHECK_LT(static_cast<size_t>(staged_log_index_), list_.size());
-  if (list_[staged_log_index_].samples_count.has_value())
-    total_samples_sent_ += list_[staged_log_index_].samples_count.value();
+  if (list_[staged_log_index_]->samples_count.has_value())
+    total_samples_sent_ += list_[staged_log_index_]->samples_count.value();
 }
 
-void UnsentLogStore::PersistUnsentLogs() const {
+void UnsentLogStore::TrimAndPersistUnsentLogs() {
   ListPrefUpdate update(local_state_, log_data_pref_name_);
   // TODO(crbug.com/859477): Verify that the preference has been properly
   // registered.
   CHECK(update.Get());
+  TrimLogs();
   WriteLogsToPrefList(update.Get());
 }
 
@@ -180,16 +181,17 @@ void UnsentLogStore::LoadPersistedUnsentLogs() {
 void UnsentLogStore::StoreLog(
     const std::string& log_data,
     base::Optional<base::HistogramBase::Count> samples_count) {
-  list_.emplace_back();
-  list_.back().Init(metrics_.get(), log_data,
-                    base::NumberToString(base::Time::Now().ToTimeT()),
-                    signing_key_, samples_count);
+  LogInfo info;
+  info.Init(metrics_.get(), log_data,
+            base::NumberToString(base::Time::Now().ToTimeT()), signing_key_,
+            samples_count);
+  list_.emplace_back(std::make_unique<LogInfo>(info));
 }
 
 const std::string& UnsentLogStore::GetLogAtIndex(size_t index) {
   DCHECK_GE(index, 0U);
   DCHECK_LT(index, list_.size());
-  return list_[index].compressed_log_data;
+  return list_[index]->compressed_log_data;
 }
 
 std::string UnsentLogStore::ReplaceLogAtIndex(
@@ -201,13 +203,17 @@ std::string UnsentLogStore::ReplaceLogAtIndex(
 
   // Avoid copying of long strings.
   std::string old_log_data;
-  old_log_data.swap(list_[index].compressed_log_data);
+  old_log_data.swap(list_[index]->compressed_log_data);
   std::string old_timestamp;
-  old_timestamp.swap(list_[index].timestamp);
+  old_timestamp.swap(list_[index]->timestamp);
 
-  list_[index] = LogInfo();
-  list_[index].Init(metrics_.get(), new_log_data, old_timestamp, signing_key_,
-                    samples_count);
+  // TODO(rkaplow): Would be a bit simpler if we had a method that would
+  // just return a pointer to the logInfo so we could combine the next 3 lines.
+  LogInfo info;
+  info.Init(metrics_.get(), new_log_data, old_timestamp, signing_key_,
+            samples_count);
+
+  list_[index] = std::make_unique<LogInfo>(info);
   return old_log_data;
 }
 
@@ -236,80 +242,100 @@ void UnsentLogStore::ReadLogsFromPrefList(const base::ListValue& list_value) {
 
   for (size_t i = 0; i < log_count; ++i) {
     const base::DictionaryValue* dict;
+    LogInfo info;
     if (!list_value.GetDictionary(i, &dict) ||
-        !dict->GetString(kLogDataKey, &list_[i].compressed_log_data) ||
-        !dict->GetString(kLogHashKey, &list_[i].hash) ||
-        !dict->GetString(kLogSignatureKey, &list_[i].signature)) {
+        !dict->GetString(kLogDataKey, &info.compressed_log_data) ||
+        !dict->GetString(kLogHashKey, &info.hash) ||
+        !dict->GetString(kLogTimestampKey, &info.timestamp) ||
+        !dict->GetString(kLogSignatureKey, &info.signature)) {
+      // Something is wrong, so we don't try to get any persisted logs.
       list_.clear();
       metrics_->RecordLogReadStatus(
           UnsentLogStoreMetrics::LOG_STRING_CORRUPTION);
       return;
     }
 
-    list_[i].compressed_log_data =
-        DecodeFromBase64(list_[i].compressed_log_data);
-    list_[i].hash = DecodeFromBase64(list_[i].hash);
-    list_[i].signature = DecodeFromBase64(list_[i].signature);
+    info.compressed_log_data = DecodeFromBase64(info.compressed_log_data);
+    info.hash = DecodeFromBase64(info.hash);
+    info.signature = DecodeFromBase64(info.signature);
+    // timestamp doesn't need to be decoded.
 
-    // Ignoring the success of this step as timestamp might not be there for
-    // older logs.
-    // NOTE: Should be added to the check with other fields once migration is
-    // over.
-    dict->GetString(kLogTimestampKey, &list_[i].timestamp);
+    list_[i] = std::make_unique<LogInfo>(info);
   }
 
   metrics_->RecordLogReadStatus(UnsentLogStoreMetrics::RECALL_SUCCESS);
 }
 
-void UnsentLogStore::WriteLogsToPrefList(base::ListValue* list_value) const {
-  list_value->Clear();
-
-  // Keep the most recent logs which are smaller than |max_log_size_|.
-  // We keep at least |min_log_bytes_| and |min_log_count_| of logs before
-  // discarding older logs.
-  size_t start = list_.size();
-  size_t saved_log_count = 0;
+void UnsentLogStore::TrimLogs() {
+  std::vector<std::unique_ptr<LogInfo>> trimmed_list;
   size_t bytes_used = 0;
-  for (; start > 0; --start) {
-    size_t log_size = list_[start - 1].compressed_log_data.length();
-    if (bytes_used >= min_log_bytes_ &&
-        saved_log_count >= min_log_count_) {
+
+  // The distance of the staged log from the end of the list of logs. Usually
+  // this is 0 (end of list). We mark so we can correct adjust the
+  // staged_log_index after log trimming.
+  size_t staged_index_distance = 0;
+
+  // Reverse order, so newest ones are prioritized.
+  for (int i = list_.size() - 1; i >= 0; --i) {
+    size_t log_size = list_[i]->compressed_log_data.length();
+    // Hit the caps, we can stop moving the logs.
+    if (bytes_used >= min_log_bytes_ && trimmed_list.size() >= min_log_count_) {
       break;
     }
-    // Oversized logs won't be persisted, so don't count them.
-    if (log_size > max_log_size_)
+    // Omit overly large individual logs.
+    if (log_size > max_log_size_) {
+      metrics_->RecordDroppedLogSize(log_size);
       continue;
+    }
+
     bytes_used += log_size;
-    ++saved_log_count;
+
+    if (staged_log_index_ == i) {
+      staged_index_distance = trimmed_list.size();
+    }
+
+    trimmed_list.emplace_back(std::move(list_[i]));
+  }
+
+  // We went in reverse order, but appended entries. So reverse list to correct.
+  std::reverse(trimmed_list.begin(), trimmed_list.end());
+
+  size_t dropped_logs_count = list_.size() - trimmed_list.size();
+  if (dropped_logs_count > 0)
+    metrics_->RecordDroppedLogsNum(dropped_logs_count);
+
+  // Put the trimmed list in the correct place.
+  list_.swap(trimmed_list);
+
+  // We may need to adjust the staged index since the number of logs may be
+  // reduced. However, we want to make sure not to change the index if there is
+  // no log staged.
+  if (staged_log_index_ != -1) {
+    staged_log_index_ = list_.size() - 1 - staged_index_distance;
   }
-  int dropped_logs_num = start - 1;
+}
+
+void UnsentLogStore::WriteLogsToPrefList(base::ListValue* list_value) const {
+  list_value->Clear();
+
   base::HistogramBase::Count unsent_samples_count = 0;
   size_t unsent_persisted_size = 0;
 
-  for (size_t i = start; i < list_.size(); ++i) {
-    size_t log_size = list_[i].compressed_log_data.length();
-    if (log_size > max_log_size_) {
-      metrics_->RecordDroppedLogSize(log_size);
-      dropped_logs_num++;
-      continue;
-    }
+  for (auto& log : list_) {
     std::unique_ptr<base::DictionaryValue> dict_value(
         new base::DictionaryValue);
-    dict_value->SetString(kLogHashKey, EncodeToBase64(list_[i].hash));
-    dict_value->SetString(kLogSignatureKey, EncodeToBase64(list_[i].signature));
+    dict_value->SetString(kLogHashKey, EncodeToBase64(log->hash));
+    dict_value->SetString(kLogSignatureKey, EncodeToBase64(log->signature));
     dict_value->SetString(kLogDataKey,
-                          EncodeToBase64(list_[i].compressed_log_data));
-    dict_value->SetString(kLogTimestampKey, list_[i].timestamp);
+                          EncodeToBase64(log->compressed_log_data));
+    dict_value->SetString(kLogTimestampKey, log->timestamp);
     list_value->Append(std::move(dict_value));
 
-    if (list_[i].samples_count.has_value()) {
-      unsent_samples_count += list_[i].samples_count.value();
+    if (log->samples_count.has_value()) {
+      unsent_samples_count += log->samples_count.value();
     }
-    unsent_persisted_size += log_size;
+    unsent_persisted_size += log->compressed_log_data.length();
   }
-  if (dropped_logs_num > 0)
-    metrics_->RecordDroppedLogsNum(dropped_logs_num);
-
   WriteToMetricsPref(unsent_samples_count, total_samples_sent_,
                      unsent_persisted_size);
 }