components/metrics/unsent_log_store.cc

   1 // Copyright 2014 The Chromium Authors
   2 // Use of this source code is governed by a BSD-style license that can be
   3 // found in the LICENSE file.
   4
   5 #include "components/metrics/unsent_log_store.h"
   6
   7 #include <cmath>
   8 #include <memory>
   9 #include <string>
  10 #include <utility>
  11
  12 #include "base/base64.h"
  13 #include "base/hash/sha1.h"
  14 #include "base/metrics/histogram_macros.h"
  15 #include "base/strings/string_number_conversions.h"
  16 #include "base/strings/string_util.h"
  17 #include "base/timer/elapsed_timer.h"
  18 #include "components/metrics/unsent_log_store_metrics.h"
  19 #include "components/prefs/pref_service.h"
  20 #include "components/prefs/scoped_user_pref_update.h"
  21 #include "crypto/hmac.h"
  22 #include "third_party/zlib/google/compression_utils.h"
  23
  24 namespace metrics {
  25
  26 namespace {
  27
  28 const char kLogHashKey[] = "hash";
  29 const char kLogSignatureKey[] = "signature";
  30 const char kLogTimestampKey[] = "timestamp";
  31 const char kLogDataKey[] = "data";
  32 const char kLogUnsentCountKey[] = "unsent_samples_count";
  33 const char kLogSentCountKey[] = "sent_samples_count";
  34 const char kLogPersistedSizeInKbKey[] = "unsent_persisted_size_in_kb";
  35 const char kLogUserIdKey[] = "user_id";
  36
  37 std::string EncodeToBase64(const std::string& to_convert) {
  38   DCHECK(to_convert.data());
  39   std::string base64_result;
  40   base::Base64Encode(to_convert, &base64_result);
  41   return base64_result;
  42 }
  43
  44 std::string DecodeFromBase64(const std::string& to_convert) {
  45   std::string result;
  46   base::Base64Decode(to_convert, &result);
  47   return result;
  48 }
  49
  50 // Used to write unsent logs to prefs.
  51 class LogsPrefWriter {
  52  public:
  53   // Create a writer that will write unsent logs to |list_value|. |list_value|
  54   // should be a base::Value::List representing a pref. Clears the contents of
  55   // |list_value|.
  56   explicit LogsPrefWriter(base::Value::List* list_value)
  57       : list_value_(list_value) {
  58     DCHECK(list_value);
  59     list_value->clear();
  60   }
  61
  62   LogsPrefWriter(const LogsPrefWriter&) = delete;
  63   LogsPrefWriter& operator=(const LogsPrefWriter&) = delete;
  64
  65   ~LogsPrefWriter() { DCHECK(finished_); }
  66
  67   // Persists |log| by appending it to |list_value_|.
  68   void WriteLogEntry(UnsentLogStore::LogInfo* log) {
  69     DCHECK(!finished_);
  70
  71     base::Value::Dict dict_value;
  72     dict_value.Set(kLogHashKey, EncodeToBase64(log->hash));
  73     dict_value.Set(kLogSignatureKey, EncodeToBase64(log->signature));
  74     dict_value.Set(kLogDataKey, EncodeToBase64(log->compressed_log_data));
  75     dict_value.Set(kLogTimestampKey, log->timestamp);
  76
  77     auto user_id = log->log_metadata.user_id;
  78     if (user_id.has_value()) {
  79       dict_value.Set(kLogUserIdKey,
  80                      EncodeToBase64(base::NumberToString(user_id.value())));
  81     }
  82     list_value_->Append(std::move(dict_value));
  83
  84     auto samples_count = log->log_metadata.samples_count;
  85     if (samples_count.has_value()) {
  86       unsent_samples_count_ += samples_count.value();
  87     }
  88     unsent_persisted_size_ += log->compressed_log_data.length();
  89     ++unsent_logs_count_;
  90   }
  91
  92   // Indicates to this writer that it is finished, and that it should not write
  93   // any more logs. This also reverses |list_value_| in order to maintain the
  94   // original order of the logs that were written.
  95   void Finish() {
  96     DCHECK(!finished_);
  97     finished_ = true;
  98     std::reverse(list_value_->begin(), list_value_->end());
  99   }
 100
 101   base::HistogramBase::Count unsent_samples_count() const {
 102     return unsent_samples_count_;
 103   }
 104
 105   size_t unsent_persisted_size() const { return unsent_persisted_size_; }
 106
 107   size_t unsent_logs_count() const { return unsent_logs_count_; }
 108
 109  private:
 110   // The list where the logs will be written to. This should represent a pref.
 111   raw_ptr<base::Value::List> list_value_;
 112
 113   // Whether or not this writer has finished writing to pref.
 114   bool finished_ = false;
 115
 116   // The total number of histogram samples written so far.
 117   base::HistogramBase::Count unsent_samples_count_ = 0;
 118
 119   // The total size of logs written so far.
 120   size_t unsent_persisted_size_ = 0;
 121
 122   // The total number of logs written so far.
 123   size_t unsent_logs_count_ = 0;
 124 };
 125
 126 bool GetString(const base::Value::Dict& dict,
 127                base::StringPiece key,
 128                std::string& out) {
 129   const std::string* value = dict.FindString(key);
 130   if (!value)
 131     return false;
 132   out = *value;
 133   return true;
 134 }
 135
 136 }  // namespace
 137
 138 UnsentLogStore::LogInfo::LogInfo() = default;
 139 UnsentLogStore::LogInfo::~LogInfo() = default;
 140
 141 void UnsentLogStore::LogInfo::Init(const std::string& log_data,
 142                                    const std::string& log_timestamp,
 143                                    const std::string& signing_key,
 144                                    const LogMetadata& optional_log_metadata) {
 145   DCHECK(!log_data.empty());
 146
 147   if (!compression::GzipCompress(log_data, &compressed_log_data)) {
 148     NOTREACHED();
 149     return;
 150   }
 151
 152   hash = base::SHA1HashString(log_data);
 153
 154   if (!ComputeHMACForLog(log_data, signing_key, &signature)) {
 155     NOTREACHED() << "HMAC signing failed";
 156   }
 157
 158   timestamp = log_timestamp;
 159   this->log_metadata = optional_log_metadata;
 160 }
 161
 162 void UnsentLogStore::LogInfo::Init(const std::string& log_data,
 163                                    const std::string& signing_key,
 164                                    const LogMetadata& optional_log_metadata) {
 165   Init(log_data, base::NumberToString(base::Time::Now().ToTimeT()), signing_key,
 166        optional_log_metadata);
 167 }
 168
 169 UnsentLogStore::UnsentLogStore(std::unique_ptr<UnsentLogStoreMetrics> metrics,
 170                                PrefService* local_state,
 171                                const char* log_data_pref_name,
 172                                const char* metadata_pref_name,
 173                                UnsentLogStoreLimits log_store_limits,
 174                                const std::string& signing_key,
 175                                MetricsLogsEventManager* logs_event_manager)
 176     : metrics_(std::move(metrics)),
 177       local_state_(local_state),
 178       log_data_pref_name_(log_data_pref_name),
 179       metadata_pref_name_(metadata_pref_name),
 180       log_store_limits_(log_store_limits),
 181       signing_key_(signing_key),
 182       logs_event_manager_(logs_event_manager),
 183       staged_log_index_(-1) {
 184   DCHECK(local_state_);
 185   // One of the limit arguments must be non-zero.
 186   DCHECK(log_store_limits_.min_log_count > 0 ||
 187          log_store_limits_.min_queue_size_bytes > 0);
 188 }
 189
 190 UnsentLogStore::~UnsentLogStore() = default;
 191
 192 bool UnsentLogStore::has_unsent_logs() const {
 193   return !!size();
 194 }
 195
 196 // True if a log has been staged.
 197 bool UnsentLogStore::has_staged_log() const {
 198   return staged_log_index_ != -1;
 199 }
 200
 201 // Returns the compressed data of the element in the front of the list.
 202 const std::string& UnsentLogStore::staged_log() const {
 203   DCHECK(has_staged_log());
 204   return list_[staged_log_index_]->compressed_log_data;
 205 }
 206
 207 // Returns the hash of element in the front of the list.
 208 const std::string& UnsentLogStore::staged_log_hash() const {
 209   DCHECK(has_staged_log());
 210   return list_[staged_log_index_]->hash;
 211 }
 212
 213 // Returns the signature of element in the front of the list.
 214 const std::string& UnsentLogStore::staged_log_signature() const {
 215   DCHECK(has_staged_log());
 216   return list_[staged_log_index_]->signature;
 217 }
 218
 219 // Returns the timestamp of the element in the front of the list.
 220 const std::string& UnsentLogStore::staged_log_timestamp() const {
 221   DCHECK(has_staged_log());
 222   return list_[staged_log_index_]->timestamp;
 223 }
 224
 225 // Returns the user id of the current staged log.
 226 absl::optional<uint64_t> UnsentLogStore::staged_log_user_id() const {
 227   DCHECK(has_staged_log());
 228   return list_[staged_log_index_]->log_metadata.user_id;
 229 }
 230
 231 // static
 232 bool UnsentLogStore::ComputeHMACForLog(const std::string& log_data,
 233                                        const std::string& signing_key,
 234                                        std::string* signature) {
 235   crypto::HMAC hmac(crypto::HMAC::SHA256);
 236   const size_t digest_length = hmac.DigestLength();
 237   unsigned char* hmac_data = reinterpret_cast<unsigned char*>(
 238       base::WriteInto(signature, digest_length + 1));
 239   return hmac.Init(signing_key) &&
 240          hmac.Sign(log_data, hmac_data, digest_length);
 241 }
 242
 243 void UnsentLogStore::StageNextLog() {
 244   // CHECK, rather than DCHECK, because swap()ing with an empty list causes
 245   // hard-to-identify crashes much later.
 246   CHECK(!list_.empty());
 247   DCHECK(!has_staged_log());
 248   staged_log_index_ = list_.size() - 1;
 249   NotifyLogEvent(MetricsLogsEventManager::LogEvent::kLogStaged,
 250                  list_[staged_log_index_]->hash);
 251   DCHECK(has_staged_log());
 252 }
 253
 254 void UnsentLogStore::DiscardStagedLog(base::StringPiece reason) {
 255   DCHECK(has_staged_log());
 256   DCHECK_LT(static_cast<size_t>(staged_log_index_), list_.size());
 257   NotifyLogEvent(MetricsLogsEventManager::LogEvent::kLogDiscarded,
 258                  list_[staged_log_index_]->hash, reason);
 259   list_.erase(list_.begin() + staged_log_index_);
 260   staged_log_index_ = -1;
 261 }
 262
 263 void UnsentLogStore::MarkStagedLogAsSent() {
 264   DCHECK(has_staged_log());
 265   DCHECK_LT(static_cast<size_t>(staged_log_index_), list_.size());
 266   auto samples_count = list_[staged_log_index_]->log_metadata.samples_count;
 267   if (samples_count.has_value())
 268     total_samples_sent_ += samples_count.value();
 269   NotifyLogEvent(MetricsLogsEventManager::LogEvent::kLogUploaded,
 270                  list_[staged_log_index_]->hash);
 271 }
 272
 273 void UnsentLogStore::TrimAndPersistUnsentLogs(bool overwrite_in_memory_store) {
 274   ScopedListPrefUpdate update(local_state_, log_data_pref_name_);
 275   LogsPrefWriter writer(&update.Get());
 276
 277   std::vector<std::unique_ptr<LogInfo>> trimmed_list;
 278   size_t bytes_used = 0;
 279
 280   // The distance of the staged log from the end of the list of logs, which is
 281   // usually 0 (end of list). This is used in case there is currently a staged
 282   // log, which may or may not get trimmed. We want to keep track of the new
 283   // position of the staged log after trimming so that we can update
 284   // |staged_log_index_|.
 285   absl::optional<size_t> staged_index_distance;
 286
 287   // Reverse order, so newest ones are prioritized.
 288   for (int i = list_.size() - 1; i >= 0; --i) {
 289     size_t log_size = list_[i]->compressed_log_data.length();
 290     // Hit the caps, we can stop moving the logs.
 291     if (bytes_used >= log_store_limits_.min_queue_size_bytes &&
 292         writer.unsent_logs_count() >= log_store_limits_.min_log_count) {
 293       // The rest of the logs (including the current one) are trimmed.
 294       if (overwrite_in_memory_store) {
 295         NotifyLogsEvent(base::span<std::unique_ptr<LogInfo>>(
 296                             list_.begin(), list_.begin() + i + 1),
 297                         MetricsLogsEventManager::LogEvent::kLogTrimmed);
 298       }
 299       break;
 300     }
 301     // Omit overly large individual logs if the value is non-zero.
 302     if (log_store_limits_.max_log_size_bytes != 0 &&
 303         log_size > log_store_limits_.max_log_size_bytes) {
 304       metrics_->RecordDroppedLogSize(log_size);
 305       if (overwrite_in_memory_store) {
 306         NotifyLogEvent(MetricsLogsEventManager::LogEvent::kLogTrimmed,
 307                        list_[i]->hash, "Log size too large.");
 308       }
 309       continue;
 310     }
 311
 312     bytes_used += log_size;
 313
 314     if (staged_log_index_ == i) {
 315       staged_index_distance = writer.unsent_logs_count();
 316     }
 317
 318     // Append log to prefs.
 319     writer.WriteLogEntry(list_[i].get());
 320     if (overwrite_in_memory_store)
 321       trimmed_list.emplace_back(std::move(list_[i]));
 322   }
 323
 324   writer.Finish();
 325
 326   if (overwrite_in_memory_store) {
 327     // We went in reverse order, but appended entries. So reverse list to
 328     // correct.
 329     std::reverse(trimmed_list.begin(), trimmed_list.end());
 330
 331     size_t dropped_logs_count = list_.size() - trimmed_list.size();
 332     if (dropped_logs_count > 0)
 333       metrics_->RecordDroppedLogsNum(dropped_logs_count);
 334
 335     // Put the trimmed list in the correct place.
 336     list_.swap(trimmed_list);
 337
 338     // We may need to adjust the staged index since the number of logs may be
 339     // reduced.
 340     if (staged_index_distance.has_value()) {
 341       staged_log_index_ = list_.size() - 1 - staged_index_distance.value();
 342     } else {
 343       // Set |staged_log_index_| to -1. It might already be -1. E.g., at the
 344       // time we are trimming logs, there was no staged log. However, it is also
 345       // possible that we trimmed away the staged log, so we need to update the
 346       // index to -1.
 347       staged_log_index_ = -1;
 348     }
 349   }
 350
 351   WriteToMetricsPref(writer.unsent_samples_count(), total_samples_sent_,
 352                      writer.unsent_persisted_size());
 353 }
 354
 355 void UnsentLogStore::LoadPersistedUnsentLogs() {
 356   ReadLogsFromPrefList(local_state_->GetList(log_data_pref_name_));
 357   RecordMetaDataMetrics();
 358 }
 359
 360 void UnsentLogStore::StoreLog(const std::string& log_data,
 361                               const LogMetadata& log_metadata,
 362                               MetricsLogsEventManager::CreateReason reason) {
 363   std::unique_ptr<LogInfo> info = std::make_unique<LogInfo>();
 364   info->Init(log_data, signing_key_, log_metadata);
 365   StoreLogInfo(std::move(info), log_data.size(), reason);
 366 }
 367
 368 void UnsentLogStore::StoreLogInfo(
 369     std::unique_ptr<LogInfo> log_info,
 370     size_t uncompressed_log_size,
 371     MetricsLogsEventManager::CreateReason reason) {
 372   DCHECK(log_info);
 373   metrics_->RecordCompressionRatio(log_info->compressed_log_data.size(),
 374                                    uncompressed_log_size);
 375   NotifyLogCreated(*log_info, reason);
 376   list_.emplace_back(std::move(log_info));
 377 }
 378
 379 const std::string& UnsentLogStore::GetLogAtIndex(size_t index) {
 380   DCHECK_GE(index, 0U);
 381   DCHECK_LT(index, list_.size());
 382   return list_[index]->compressed_log_data;
 383 }
 384
 385 std::string UnsentLogStore::ReplaceLogAtIndex(size_t index,
 386                                               const std::string& new_log_data,
 387                                               const LogMetadata& log_metadata) {
 388   DCHECK_GE(index, 0U);
 389   DCHECK_LT(index, list_.size());
 390
 391   // Avoid copying of long strings.
 392   std::string old_log_data;
 393   old_log_data.swap(list_[index]->compressed_log_data);
 394   std::string old_timestamp;
 395   old_timestamp.swap(list_[index]->timestamp);
 396   std::string old_hash;
 397   old_hash.swap(list_[index]->hash);
 398
 399   std::unique_ptr<LogInfo> info = std::make_unique<LogInfo>();
 400   info->Init(new_log_data, old_timestamp, signing_key_, log_metadata);
 401   // Note that both the compression ratio of the new log and the log that is
 402   // being replaced are recorded.
 403   metrics_->RecordCompressionRatio(info->compressed_log_data.size(),
 404                                    new_log_data.size());
 405
 406   // TODO(crbug/1363747): Pass a message to make it clear that the new log is
 407   // replacing the old log.
 408   NotifyLogEvent(MetricsLogsEventManager::LogEvent::kLogDiscarded, old_hash);
 409   NotifyLogCreated(*info, MetricsLogsEventManager::CreateReason::kUnknown);
 410   list_[index] = std::move(info);
 411   return old_log_data;
 412 }
 413
 414 void UnsentLogStore::Purge() {
 415   NotifyLogsEvent(list_, MetricsLogsEventManager::LogEvent::kLogDiscarded,
 416                   "Purged.");
 417
 418   if (has_staged_log()) {
 419     DiscardStagedLog();
 420   }
 421   list_.clear();
 422   local_state_->ClearPref(log_data_pref_name_);
 423   // The |total_samples_sent_| isn't cleared intentionally because it is still
 424   // meaningful.
 425   if (metadata_pref_name_)
 426     local_state_->ClearPref(metadata_pref_name_);
 427 }
 428
 429 void UnsentLogStore::SetLogsEventManager(
 430     MetricsLogsEventManager* logs_event_manager) {
 431   logs_event_manager_ = logs_event_manager;
 432 }
 433
 434 void UnsentLogStore::ReadLogsFromPrefList(const base::Value::List& list_value) {
 435   // The below DCHECK ensures that a log from prefs is not loaded multiple
 436   // times, which is important for the semantics of the NotifyLogsCreated() call
 437   // below.
 438   DCHECK(list_.empty());
 439
 440   if (list_value.empty()) {
 441     metrics_->RecordLogReadStatus(UnsentLogStoreMetrics::LIST_EMPTY);
 442     return;
 443   }
 444
 445   const size_t log_count = list_value.size();
 446
 447   list_.resize(log_count);
 448
 449   for (size_t i = 0; i < log_count; ++i) {
 450     const base::Value::Dict* dict = list_value[i].GetIfDict();
 451     std::unique_ptr<LogInfo> info = std::make_unique<LogInfo>();
 452     if (!dict || !GetString(*dict, kLogDataKey, info->compressed_log_data) ||
 453         !GetString(*dict, kLogHashKey, info->hash) ||
 454         !GetString(*dict, kLogTimestampKey, info->timestamp) ||
 455         !GetString(*dict, kLogSignatureKey, info->signature)) {
 456       // Something is wrong, so we don't try to get any persisted logs.
 457       list_.clear();
 458       metrics_->RecordLogReadStatus(
 459           UnsentLogStoreMetrics::LOG_STRING_CORRUPTION);
 460       return;
 461     }
 462
 463     info->compressed_log_data = DecodeFromBase64(info->compressed_log_data);
 464     info->hash = DecodeFromBase64(info->hash);
 465     info->signature = DecodeFromBase64(info->signature);
 466     // timestamp doesn't need to be decoded.
 467
 468     // Extract user id of the log if it exists.
 469     const std::string* user_id_str = dict->FindString(kLogUserIdKey);
 470     if (user_id_str) {
 471       uint64_t user_id;
 472
 473       // Only initialize the metadata if conversion was successful.
 474       if (base::StringToUint64(DecodeFromBase64(*user_id_str), &user_id))
 475         info->log_metadata.user_id = user_id;
 476     }
 477
 478     list_[i] = std::move(info);
 479   }
 480
 481   // Only notify log observers after loading all logs from pref instead of
 482   // notifying as logs are loaded. This is because we may return early and end
 483   // up not loading any logs.
 484   NotifyLogsCreated(
 485       list_, MetricsLogsEventManager::CreateReason::kLoadFromPreviousSession);
 486
 487   metrics_->RecordLogReadStatus(UnsentLogStoreMetrics::RECALL_SUCCESS);
 488 }
 489
 490 void UnsentLogStore::WriteToMetricsPref(
 491     base::HistogramBase::Count unsent_samples_count,
 492     base::HistogramBase::Count sent_samples_count,
 493     size_t unsent_persisted_size) const {
 494   if (metadata_pref_name_ == nullptr)
 495     return;
 496
 497   ScopedDictPrefUpdate update(local_state_, metadata_pref_name_);
 498   base::Value::Dict& pref_data = update.Get();
 499   pref_data.Set(kLogUnsentCountKey, unsent_samples_count);
 500   pref_data.Set(kLogSentCountKey, sent_samples_count);
 501   // Round up to kb.
 502   pref_data.Set(kLogPersistedSizeInKbKey,
 503                 static_cast<int>(std::ceil(unsent_persisted_size / 1024.0)));
 504 }
 505
 506 void UnsentLogStore::RecordMetaDataMetrics() {
 507   if (metadata_pref_name_ == nullptr)
 508     return;
 509
 510   const base::Value::Dict& value = local_state_->GetDict(metadata_pref_name_);
 511
 512   auto unsent_samples_count = value.FindInt(kLogUnsentCountKey);
 513   auto sent_samples_count = value.FindInt(kLogSentCountKey);
 514   auto unsent_persisted_size_in_kb = value.FindInt(kLogPersistedSizeInKbKey);
 515
 516   if (unsent_samples_count && sent_samples_count &&
 517       unsent_persisted_size_in_kb) {
 518     metrics_->RecordLastUnsentLogMetadataMetrics(
 519         unsent_samples_count.value(), sent_samples_count.value(),
 520         unsent_persisted_size_in_kb.value());
 521   }
 522 }
 523
 524 void UnsentLogStore::NotifyLogCreated(
 525     const LogInfo& info,
 526     MetricsLogsEventManager::CreateReason reason) {
 527   if (!logs_event_manager_)
 528     return;
 529   logs_event_manager_->NotifyLogCreated(info.hash, info.compressed_log_data,
 530                                         info.timestamp, reason);
 531 }
 532
 533 void UnsentLogStore::NotifyLogsCreated(
 534     base::span<std::unique_ptr<LogInfo>> logs,
 535     MetricsLogsEventManager::CreateReason reason) {
 536   if (!logs_event_manager_)
 537     return;
 538   for (const std::unique_ptr<LogInfo>& info : logs) {
 539     logs_event_manager_->NotifyLogCreated(info->hash, info->compressed_log_data,
 540                                           info->timestamp, reason);
 541   }
 542 }
 543
 544 void UnsentLogStore::NotifyLogEvent(MetricsLogsEventManager::LogEvent event,
 545                                     base::StringPiece log_hash,
 546                                     base::StringPiece message) {
 547   if (!logs_event_manager_)
 548     return;
 549   logs_event_manager_->NotifyLogEvent(event, log_hash, message);
 550 }
 551
 552 void UnsentLogStore::NotifyLogsEvent(base::span<std::unique_ptr<LogInfo>> logs,
 553                                      MetricsLogsEventManager::LogEvent event,
 554                                      base::StringPiece message) {
 555   if (!logs_event_manager_)
 556     return;
 557   for (const std::unique_ptr<LogInfo>& info : logs) {
 558     logs_event_manager_->NotifyLogEvent(event, info->hash, message);
 559   }
 560 }
 561
 562 }  // namespace metrics