Handle the case where Purge is called while upload is in progress.

components/ukm/ukm_service.cc

 // Copyright 2017 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 "components/ukm/ukm_service.h"
 
 #include <memory>
 #include <string>
 #include <utility>
 
@@ skipping 254 matching lines @@
 }
 
 void UkmService::StartScheduledUpload() {
   DCHECK(thread_checker_.CalledOnValidThread());
   DCHECK(!log_upload_in_progress_);
   if (!persisted_logs_.has_unsent_logs()) {
     // No logs to send, so early out and schedule the next rotation.
     scheduler_->UploadFinished(true, /* has_unsent_logs */ false);
     return;
   }
   if (!persisted_logs_.has_staged_log())

[Alexei Svitkine (slow), 2017/03/07 22:02:10]

One other thing I noticed is this logic.

If StartScheduledUpload() is called while a log upload is in progress, the
second oncomplete might not have the staged log - since we don't queue them up
or anything.

Now, maybe it's impossible - but for example see this bug:
https://bugs.chromium.org/p/chromium/issues/detail?id=669542

where this was happening for variations service when the process was suspended
for a while.

If it is possible to happen, we should perhaps have logic here - e.g. to not do
the upload until the previous one finished.

[Steven Holte, 2017/03/07 22:26:18]

StartScheduledUpload should not be called while upload_in_progress is true since
we wait scheduler_->UploadFinished to re-arm the timer.

     persisted_logs_.StageNextLog();
   // TODO(holte): Handle data usage on cellular, etc.
   if (!log_uploader_) {
     log_uploader_ = client_->CreateUploader(
         GetServerUrl(), kMimeType, metrics::MetricsLogUploader::UKM,
         base::Bind(&UkmService::OnLogUploadComplete,
                    self_ptr_factory_.GetWeakPtr()));
   }
   log_upload_in_progress_ = true;
 
   const std::string hash =
       base::HexEncode(persisted_logs_.staged_log_hash().data(),
                       persisted_logs_.staged_log_hash().size());
   log_uploader_->UploadLog(persisted_logs_.staged_log(), hash);
 }
 
 void UkmService::OnLogUploadComplete(int response_code) {
   DCHECK(thread_checker_.CalledOnValidThread());
   DCHECK(log_upload_in_progress_);
   DVLOG(1) << "UkmService::OnLogUploadComplete";
   log_upload_in_progress_ = false;
 
   UMA_HISTOGRAM_SPARSE_SLOWLY("UKM.Upload.ResponseCode", response_code);
 
   bool upload_succeeded = response_code == 200;
+  if (persisted_logs_.has_staged_log()) {
+    // Provide boolean for error recovery (allow us to ignore response_code).
+    bool discard_log = false;
+    const size_t log_size_bytes = persisted_logs_.staged_log().length();
+    if (upload_succeeded) {
+      UMA_HISTOGRAM_COUNTS_10000("UKM.LogSize.OnSuccess",
+                                 log_size_bytes / 1024);
+    } else if (response_code == 400) {
+      // Bad syntax.  Retransmission won't work.
+      discard_log = true;
+    }
 
-  // Provide boolean for error recovery (allow us to ignore response_code).
-  bool discard_log = false;
-  const size_t log_size_bytes = persisted_logs_.staged_log().length();
-  if (upload_succeeded) {
-    UMA_HISTOGRAM_COUNTS_10000("UKM.LogSize.OnSuccess", log_size_bytes / 1024);
-  } else if (response_code == 400) {
-    // Bad syntax.  Retransmission won't work.
-    discard_log = true;
-  }
-
-  if (upload_succeeded || discard_log) {
-    persisted_logs_.DiscardStagedLog();

[Alexei Svitkine (slow), 2017/03/07 22:02:10]

You'll need to rebase on my change.

[Steven Holte, 2017/03/07 22:26:18]

Done.

-    // Store the updated list to disk now that the removed log is uploaded.
-    persisted_logs_.PersistUnsentLogs();
+    if (upload_succeeded || discard_log) {
+      persisted_logs_.DiscardStagedLog();
+      // Store the updated list to disk now that the removed log is uploaded.
+      persisted_logs_.PersistUnsentLogs();
+    }
+  } else {
+    // Staged log may have been deleted by Purge already.
+    UMA_HISTOGRAM_SPARSE_SLOWLY("UKM.Upload.Purged.ResponseCode",

[Alexei Svitkine (slow), 2017/03/07 22:02:10]

I don't understand why we should do a separate code path and separate histogram
when a log is purged.

If it's a valid thing to happen, why not just update my TODO comment to explain
the case and not do anything special?

[Steven Holte, 2017/03/07 22:26:18]

Was just adding this to record how often it actually happened.  Removed it for
now.

+                                response_code);
   }
 
   // Error 400 indicates a problem with the log, not with the server, so
   // don't consider that a sign that the server is in trouble.
   bool server_is_healthy = upload_succeeded || response_code == 400;
   scheduler_->UploadFinished(server_is_healthy,
                              persisted_logs_.has_unsent_logs());
 }
 
 void UkmService::RecordSource(std::unique_ptr<UkmSource> source) {
   if (!recording_enabled_) {
     RecordDroppedSource(DroppedSourceReason::RECORDING_DISABLED);
     return;
   }
   if (sources_.size() >= kMaxSources) {
     RecordDroppedSource(DroppedSourceReason::MAX_SOURCES_HIT);
     return;
   }
 
   sources_.push_back(std::move(source));
 }
 
 }  // namespace ukm