[Metrics] Re-try failed protocol buffer uploads as well as failed XML uploads.

chrome/browser/metrics/metrics_service.cc

 // Copyright (c) 2012 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.
 
 //------------------------------------------------------------------------------
 // Description of the life cycle of a instance of MetricsService.
 //
 //  OVERVIEW
 //
 // A MetricsService instance is typically created at application startup.  It
@@ skipping 221 matching lines @@
 
 // If an upload fails, and the transmission was over this byte count, then we
 // will discard the log, and not try to retransmit it.  We also don't persist
 // the log to the prefs for transmission during the next chrome session if this
 // limit is exceeded.
 const size_t kUploadLogAvoidRetransmitSize = 50000;
 
 // Interval, in minutes, between state saves.
 const int kSaveStateIntervalMinutes = 5;
 
-// Used to indicate that the response code is currently not set at all --
-// RESPONSE_CODE_INVALID can sometimes be returned in response to a request if,
-// e.g., the server is down.
-const int kNoResponseCode = net::URLFetcher::RESPONSE_CODE_INVALID - 1;
-
 enum ResponseStatus {
   UNKNOWN_FAILURE,
   SUCCESS,
   BAD_REQUEST,  // Invalid syntax or log too large.
   NO_RESPONSE,
   NUM_RESPONSE_STATUSES
 };
 
 ResponseStatus ResponseCodeToStatus(int response_code) {
   switch (response_code) {
@@ skipping 753 matching lines @@
 }
 
 void MetricsService::PushPendingLogsToPersistentStorage() {
   if (state_ < INITIAL_LOG_READY)
     return;  // We didn't and still don't have time to get plugin list etc.
 
   if (log_manager_.has_staged_log()) {
     // We may race here, and send second copy of initial log later.
     if (state_ == INITIAL_LOG_READY)
       state_ = SENDING_OLD_LOGS;
-    MetricsLogManager::StoreType store_type = current_fetch_xml_.get() ?
-        MetricsLogManager::PROVISIONAL_STORE : MetricsLogManager::NORMAL_STORE;
+
+    MetricsLogManager::StoreType store_type;
+    if (current_fetch_xml_.get() || current_fetch_proto_.get())
+      store_type = MetricsLogManager::PROVISIONAL_STORE;
+    else
+      store_type = MetricsLogManager::NORMAL_STORE;
     log_manager_.StoreStagedLogAsUnsent(store_type);
   }
   DCHECK(!log_manager_.has_staged_log());
   StopRecording();
   StoreUnsentLogs();
 }
 
 //------------------------------------------------------------------------------
 // Transmission of logs methods
 
@@ skipping 85 matching lines @@
       !recording_active() || !reporting_active()) {
     scheduler_->Stop();
     scheduler_->UploadCancelled();
     return;
   }
 
   MakeStagedLog();
 
   // MakeStagedLog should have prepared log text; if it didn't, skip this
   // upload and hope things work out next time.
-  if (log_manager_.staged_log_text().empty()) {
+  if (!log_manager_.has_staged_log()) {
     scheduler_->UploadCancelled();
+    // TODO(jar): If compression failed, we should have created a tiny log and
+    // compressed that, so that we can signal that we're losing logs.
     return;
   }
 
   SendStagedLog();
 }
 
 void MetricsService::MakeStagedLog() {
   if (log_manager_.has_staged_log())
     return;
 
   switch (state_) {
     case INITIALIZED:
     case INIT_TASK_SCHEDULED:  // We should be further along by now.
-      DCHECK(false);
+      NOTREACHED();
       return;
 
     case INIT_TASK_DONE:
       // We need to wait for the initial log to be ready before sending
       // anything, because the server will tell us whether it wants to hear
       // from us.
       PrepareInitialLog();
       DCHECK_EQ(INIT_TASK_DONE, state_);
       log_manager_.LoadPersistedUnsentLogs();
       state_ = INITIAL_LOG_READY;
@@ skipping 47 matching lines @@
     return;  // We never Recalled the prior unsent logs.
 
   log_manager_.PersistUnsentLogs();
 }
 
 void MetricsService::SendStagedLog() {
   DCHECK(log_manager_.has_staged_log());
 
   PrepareFetchWithStagedLog();
 
-  if (!current_fetch_xml_.get()) {
-    DCHECK(!current_fetch_proto_.get());
-    // Compression failed, and log discarded :-/.
-    log_manager_.DiscardStagedLog();
-    scheduler_->UploadCancelled();

[stuartmorgan, 2012/06/08 08:26:42]

It's vital that UploadCancelled be called if something goes catastrophically
wrong and neither current_fetch_xml_ nor current_fetch_proto_ end up with any
content, otherwise the scheduler will never call back, so it seems like this
path needs to stay, just modified to check for both being empty.

[Ilya Sherman, 2012/06/08 22:20:26]

This check was logically redundant with the check on line 1126.  You're right,
though, that keeping the check here is probably appropriate; I've gone ahead and
removed the other one, keeping only this one.

-    // TODO(jar): If compression failed, we should have created a tiny log and
-    // compressed that, so that we can signal that we're losing logs.
-    return;
-  }
-  // Currently, the staged log for the protobuf version of the data is discarded
-  // after we create the URL request, so that there is no chance for
-  // re-transmission in case the corresponding XML request fails.  We will
-  // handle protobuf failures more carefully once that becomes the main
-  // pipeline, i.e. once we switch away from the XML pipeline.
-  DCHECK(current_fetch_proto_.get() || !log_manager_.has_staged_log_proto());
+  DCHECK(!waiting_for_asynchronous_reporting_step_);
+  waiting_for_asynchronous_reporting_step_ = true;
 
-  DCHECK(!waiting_for_asynchronous_reporting_step_);
-
-  waiting_for_asynchronous_reporting_step_ = true;
-  current_fetch_xml_->Start();
+  if (current_fetch_xml_.get())
+    current_fetch_xml_->Start();
   if (current_fetch_proto_.get())
     current_fetch_proto_->Start();
 
   HandleIdleSinceLastTransmission(true);
 }
 
 void MetricsService::PrepareFetchWithStagedLog() {
-  DCHECK(!log_manager_.staged_log_text().empty());
+  DCHECK(log_manager_.has_staged_log());
 
   // Prepare the XML version.
   DCHECK(!current_fetch_xml_.get());
-  current_fetch_xml_.reset(content::URLFetcher::Create(
-      GURL(server_url_xml_), net::URLFetcher::POST, this));
-  current_fetch_xml_->SetRequestContext(
-      g_browser_process->system_request_context());
-  current_fetch_xml_->SetUploadData(kMimeTypeXml,
-                                    log_manager_.staged_log_text().xml);
-  // We already drop cookies server-side, but we might as well strip them out
-  // client-side as well.
-  current_fetch_xml_->SetLoadFlags(net::LOAD_DO_NOT_SAVE_COOKIES |
-                                   net::LOAD_DO_NOT_SEND_COOKIES);
+  if (log_manager_.has_staged_log_xml()) {
+    current_fetch_xml_.reset(content::URLFetcher::Create(
+        GURL(server_url_xml_), net::URLFetcher::POST, this));
+    current_fetch_xml_->SetRequestContext(
+        g_browser_process->system_request_context());
+    current_fetch_xml_->SetUploadData(kMimeTypeXml,
+                                      log_manager_.staged_log_text().xml);
+    // We already drop cookies server-side, but we might as well strip them out
+    // client-side as well.
+    current_fetch_xml_->SetLoadFlags(net::LOAD_DO_NOT_SAVE_COOKIES |
+                                     net::LOAD_DO_NOT_SEND_COOKIES);
+  }
 
   // Prepare the protobuf version.
   DCHECK(!current_fetch_proto_.get());
   if (log_manager_.has_staged_log_proto()) {
     current_fetch_proto_.reset(content::URLFetcher::Create(
         GURL(server_url_proto_), net::URLFetcher::POST, this));
     current_fetch_proto_->SetRequestContext(
         g_browser_process->system_request_context());
     current_fetch_proto_->SetUploadData(kMimeTypeProto,
                                         log_manager_.staged_log_text().proto);
     // We already drop cookies server-side, but we might as well strip them out
     // client-side as well.
     current_fetch_proto_->SetLoadFlags(net::LOAD_DO_NOT_SAVE_COOKIES |
                                        net::LOAD_DO_NOT_SEND_COOKIES);
-
-    // Discard the protobuf version of the staged log, so that we will avoid
-    // re-uploading it even if we need to re-upload the XML version.
-    // TODO(isherman): Handle protobuf upload failures more gracefully once we
-    // transition away from the XML-based pipeline.
-    log_manager_.DiscardStagedLogProto();
   }
 }
 
 static const char* StatusToString(const net::URLRequestStatus& status) {
   switch (status.status()) {
     case net::URLRequestStatus::SUCCESS:
       return "SUCCESS";
 
     case net::URLRequestStatus::IO_PENDING:
       return "IO_PENDING";
 
     case net::URLRequestStatus::HANDLED_EXTERNALLY:
       return "HANDLED_EXTERNALLY";
 
     case net::URLRequestStatus::CANCELED:
       return "CANCELED";
 
     case net::URLRequestStatus::FAILED:
       return "FAILED";
 
     default:
       NOTREACHED();
       return "Unknown";
   }
 }
 
 // We need to wait for two responses: the response to the XML upload, and the
-// response to the protobuf upload.  For now, only the XML upload's response
-// affects decisions like whether to retry the upload, whether to abandon the
-// upload because it is too large, etc.  However, we still need to wait for the
-// protobuf upload, as we cannot reset |current_fetch_proto_| until we have
-// confirmation that the network request was sent; and the easiest way to do
-// that is to wait for the response.  In case the XML upload's response arrives
-// first, we cache that response until the protobuf upload's response also
-// arrives.
-//
-// Note that if the XML upload succeeds but the protobuf upload fails, we will
-// not retry the protobuf upload.  If the XML upload fails while the protobuf
-// upload succeeds, we will still avoid re-uploading the protobuf data because
-// we "zap" the data after the first upload attempt.  This means that we might
-// lose protobuf uploads when XML ones succeed; but we will never duplicate any
-// protobuf uploads.  Protobuf failures should be rare enough to where this
-// should be ok while we have the two pipelines running in parallel.
+// response to the protobuf upload.  In the case that exactly one of the uploads
+// fails and needs to be retried, we "zap" the other pipeline's staged log to
+// avoid incorrectly re-uploading it as well.
 void MetricsService::OnURLFetchComplete(const net::URLFetcher* source) {
   DCHECK(waiting_for_asynchronous_reporting_step_);
 
   // We're not allowed to re-use the existing |URLFetcher|s, so free them here.
   // Note however that |source| is aliased to one of these, so we should be
   // careful not to delete it too early.
   scoped_ptr<net::URLFetcher> s;
+  bool is_xml;
   if (source == current_fetch_xml_.get()) {
     s.reset(current_fetch_xml_.release());
-
-    // Cache the XML responses, in case we still need to wait for the protobuf
-    // response.
-    response_code_ = source->GetResponseCode();
-    response_status_ = StatusToString(source->GetStatus());
-    source->GetResponseAsString(&response_data_);
-
-    // Log a histogram to track response success vs. failure rates.
-    UMA_HISTOGRAM_ENUMERATION("UMA.UploadResponseStatus.XML",
-                              ResponseCodeToStatus(response_code_),
-                              NUM_RESPONSE_STATUSES);
+    is_xml = true;
   } else if (source == current_fetch_proto_.get()) {
     s.reset(current_fetch_proto_.release());
-
-    // Log a histogram to track response success vs. failure rates.
-    UMA_HISTOGRAM_ENUMERATION("UMA.UploadResponseStatus.Protobuf",
-                              ResponseCodeToStatus(source->GetResponseCode()),
-                              NUM_RESPONSE_STATUSES);
+    is_xml = false;
   } else {
     NOTREACHED();
     return;
   }
 
+  int response_code = source->GetResponseCode();
+
+  // Log a histogram to track response success vs. failure rates.
+  if (is_xml) {
+    UMA_HISTOGRAM_ENUMERATION("UMA.UploadResponseStatus.XML",
+                              ResponseCodeToStatus(response_code),
+                              NUM_RESPONSE_STATUSES);
+  } else {
+    UMA_HISTOGRAM_ENUMERATION("UMA.UploadResponseStatus.Protobuf",
+                              ResponseCodeToStatus(response_code),
+                              NUM_RESPONSE_STATUSES);
+  }
+
+  // If the upload was provisionally stored, drop it now that the upload is
+  // known to have gone through.
+  log_manager_.DiscardLastProvisionalStore();
+
+  // Confirm send so that we can move on.
+  VLOG(1) << "Metrics response code: " << response_code
+          << " status=" << StatusToString(source->GetStatus()) << " for "
+          << (is_xml ? "xml" : "protobuf") << " upload.";
+
+  bool upload_succeeded = response_code == 200;
+
+  // Provide boolean for error recovery (allow us to ignore response_code).
+  bool discard_log = false;
+  const size_t log_size = is_xml ?
+      log_manager_.staged_log_text().xml.length() :
+      log_manager_.staged_log_text().proto.length();
+  if (!upload_succeeded && log_size > kUploadLogAvoidRetransmitSize) {
+    UMA_HISTOGRAM_COUNTS("UMA.Large Rejected Log was Discarded",
+                         static_cast<int>(log_size));
+    discard_log = true;
+  } else if (response_code == 400) {
+    // Bad syntax.  Retransmission won't work.
+    discard_log = true;
+  }
+
+  if (!upload_succeeded && !discard_log) {
+    LogBadResponseCode(response_code, is_xml);
+  } else {  // Successful receipt (or we are discarding log).
+    std::string response_data;
+    source->GetResponseAsString(&response_data);
+    VLOG(1) << "Metrics response data: " << response_data;
+
+    if (is_xml)
+      log_manager_.DiscardStagedLogXml();
+    else
+      log_manager_.DiscardStagedLogProto();
+  }
+
   // If we're still waiting for one of the responses, keep waiting...
   if (current_fetch_xml_.get() || current_fetch_proto_.get())
     return;
 
-  // We should only be able to reach here once we've received responses to both
-  // the XML and the protobuf requests.  We should always have the response code
-  // available.
-  DCHECK_NE(response_code_, kNoResponseCode);
   waiting_for_asynchronous_reporting_step_ = false;
 
-  // If the upload was provisionally stored, drop it now that the upload is
-  // known to have gone through.
-  log_manager_.DiscardLastProvisionalStore();
-
-  // Confirm send so that we can move on.
-  VLOG(1) << "Metrics response code: " << response_code_
-          << " status=" << response_status_;
-
-  bool upload_succeeded = response_code_ == 200;
-
-  // Provide boolean for error recovery (allow us to ignore response_code).
-  bool discard_log = false;
-
-  if (!upload_succeeded &&
-      log_manager_.staged_log_text().xml.length() >
-          kUploadLogAvoidRetransmitSize) {
-    UMA_HISTOGRAM_COUNTS(
-        "UMA.Large Rejected Log was Discarded",
-        static_cast<int>(log_manager_.staged_log_text().xml.length()));
-    discard_log = true;
-  } else if (response_code_ == 400) {
-    // Bad syntax.  Retransmission won't work.
-    discard_log = true;
-  }
-
-  if (!upload_succeeded && !discard_log) {
-    VLOG(1) << "Metrics: transmission attempt returned a failure code: "
-            << response_code_ << ". Verify network connectivity";
-    LogBadResponseCode();
-  } else {  // Successful receipt (or we are discarding log).
-    VLOG(1) << "Metrics response data: " << response_data_;
+  if (!log_manager_.has_staged_log()) {
     switch (state_) {
       case INITIAL_LOG_READY:
         state_ = SENDING_OLD_LOGS;
         break;
 
       case SENDING_OLD_LOGS:
         // Store the updated list to disk now that the removed log is uploaded.
         StoreUnsentLogs();
         break;
 
       case SENDING_CURRENT_LOGS:
         break;
 
       default:
         NOTREACHED();
         break;
     }
 
-    log_manager_.DiscardStagedLog();
-
     if (log_manager_.has_unsent_logs())
       DCHECK_LT(state_, SENDING_CURRENT_LOGS);
   }
 
   // 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;
+  bool server_is_healthy = upload_succeeded || response_code == 400;
 
-  scheduler_->UploadFinished(server_is_healthy,
-                             log_manager_.has_unsent_logs());
+  // Note that we are essentially randomly choosing to report either the XML or
+  // the protobuf server's health status, but this is ok: In the case that the
+  // two statuses are not the same, one of the uploads succeeded but the other
+  // did not. In this case, we'll re-try only the upload that failed. This first
+  // re-try might ignore the server's unhealthiness; but the response to the
+  // re-tried upload will correctly propagate the server's health status for any
+  // subsequent re-tries. Hence, we'll at most delay slowing the upload rate by
+  // one re-try, which is fine.
+  scheduler_->UploadFinished(server_is_healthy, log_manager_.has_unsent_logs());
 
   // Collect network stats if UMA upload succeeded.
   IOThread* io_thread = g_browser_process->io_thread();
   if (server_is_healthy && io_thread) {
     chrome_browser_net::CollectNetworkStats(network_stats_server_, io_thread);
     chrome_browser_net::CollectPipeliningCapabilityStatsOnUIThread(
         http_pipelining_test_server_, io_thread);
   }
-
-  // Reset the cached response data.
-  response_code_ = kNoResponseCode;
-  response_data_ = std::string();
-  response_status_ = std::string();
 }
 
-void MetricsService::LogBadResponseCode() {
-  VLOG(1) << "Verify your metrics logs are formatted correctly.  Verify server "
-             "is active at " << server_url_xml_;
+void MetricsService::LogBadResponseCode(int response_code, bool is_xml) {
+  VLOG(1) << "Metrics: transmission attempt returned a failure code: "
+          << response_code << ". Verify network connectivity and that your "
+          << "metrics logs are formatted correctly. Verify server is active at "
+          << (is_xml ? server_url_xml_ : server_url_proto_) << ".";
+
   if (!log_manager_.has_staged_log()) {
-    VLOG(1) << "METRICS: Recorder shutdown during log transmission.";
+    // TODO(isherman): I don't think this code is reachable...
+    VLOG(1) << "Metrics: Recorder shutdown during log transmission.";
   } else {
-    VLOG(1) << "METRICS: transmission retry being scheduled for "
-            << log_manager_.staged_log_text().xml;
+    if (is_xml) {
+      VLOG(1) << "Metrics: transmission retry being scheduled for \n"
+              << log_manager_.staged_log_text().xml;
+    } else {
+      VLOG(1)
+          << "Metrics: transmission retry being scheduled for protobuf upload.";
+    }
   }
 }
 
 void MetricsService::LogWindowChange(
     int type,
     const content::NotificationSource& source,
     const content::NotificationDetails& details) {
   int controller_id = -1;
   uintptr_t window_or_tab = source.map_key();
   MetricsLog::WindowEventType window_type;
@@ skipping 371 matching lines @@
   if (local_state) {
     const PrefService::Preference* uma_pref =
         local_state->FindPreference(prefs::kMetricsReportingEnabled);
     if (uma_pref) {
       bool success = uma_pref->GetValue()->GetAsBoolean(&result);
       DCHECK(success);
     }
   }
   return result;
 }