Add logging and retry code to RLZ in chromeos.

NOPRESUBMIT=true
This CL was blocked by the presubmit check "net::URLFetcher".
This CL does not add, remove, nor change existing URLFetcher usage.
It adds usage of an existing URLFetcher::RESPONSE_CODE_INVALID constant.
This is deemed reasonable small enough change to bypass the presubmit.

Bug: 820783
Change-Id: I274aeeadc518b9b6ec2af4f2cd97ed0fbddbecb3
Reviewed-on: https://chromium-review.googlesource.com/980714
Commit-Queue: Roger Tawa <rogerta@chromium.org>
Reviewed-by: Wenzhao (Colin) Zang <wzang@chromium.org>
Cr-Commit-Position: refs/heads/master@{#546968}

components/rlz/rlz_tracker.cc

@@ -23,6 +23,10 @@
 #include "build/build_config.h"
 #include "components/rlz/rlz_tracker_delegate.h"
 
+#if defined(OS_CHROMEOS)
+#include "base/syslog_logging.h"
+#endif
+
 namespace rlz {
 namespace {
 
@@ -247,6 +251,15 @@ bool RLZTracker::Init(bool first_run,
   }
   delegate_->GetReactivationBrand(&reactivation_brand_);
 
+#if defined(OS_CHROMEOS)
+  // If the brand is organic, RLZ is essentially disabled.  Write a log to the
+  // console for administrators and QA.
+  if (delegate_->IsBrandOrganic(brand_) &&
+      delegate_->IsBrandOrganic(reactivation_brand_)) {
+    SYSLOG(INFO) << "RLZ is disabled";
+  }
+#endif
+
   // Could be null; don't run if so.  RLZ will try again next restart.
   net::URLRequestContextGetter* context_getter = delegate_->GetRequestContext();
   if (context_getter) {

rlz/lib/financial_ping.cc

@@ -334,9 +334,10 @@ void PingRlzServer(std::string url,
 }
 #endif
 
-bool FinancialPing::PingServer(const char* request, std::string* response) {
+FinancialPing::PingResponse FinancialPing::PingServer(const char* request,
+                                                      std::string* response) {
   if (!response)
-    return false;
+    return PING_FAILURE;
 
   response->clear();
 
@@ -346,14 +347,14 @@ bool FinancialPing::PingServer(const char* request, std::string* response) {
                                              INTERNET_OPEN_TYPE_PRECONFIG,
                                              NULL, NULL, 0);
   if (!inet_handle)
-    return false;
+    return PING_FAILURE;
 
   // Open network connection.
   InternetHandle connection_handle = InternetConnectA(inet_handle,
       kFinancialServer, kFinancialPort, "", "", INTERNET_SERVICE_HTTP,
       INTERNET_FLAG_NO_CACHE_WRITE, 0);
   if (!connection_handle)
-    return false;
+    return PING_FAILURE;
 
   // Prepare the HTTP request.
   const DWORD kFlags = INTERNET_FLAG_NO_CACHE_WRITE | INTERNET_FLAG_NO_COOKIES |
@@ -362,14 +363,14 @@ bool FinancialPing::PingServer(const char* request, std::string* response) {
       HttpOpenRequestA(connection_handle, "GET", request, NULL, NULL,
                        kFinancialPingResponseObjects, kFlags, NULL);
   if (!http_handle)
-    return false;
+    return PING_FAILURE;
 
   // Timeouts are probably:
   // INTERNET_OPTION_SEND_TIMEOUT, INTERNET_OPTION_RECEIVE_TIMEOUT
 
   // Send the HTTP request. Note: Fails if user is working in off-line mode.
   if (!HttpSendRequest(http_handle, NULL, 0, NULL, 0))
-    return false;
+    return PING_FAILURE;
 
   // Check the response status.
   DWORD status;
@@ -377,12 +378,12 @@ bool FinancialPing::PingServer(const char* request, std::string* response) {
   if (!HttpQueryInfo(http_handle, HTTP_QUERY_STATUS_CODE |
                      HTTP_QUERY_FLAG_NUMBER, &status, &status_size, NULL) ||
       200 != status)
-    return false;
+    return PING_FAILURE;
 
   // Get the response text.
   std::unique_ptr<char[]> buffer(new char[kMaxPingResponseLength]);
   if (buffer.get() == NULL)
-    return false;
+    return PING_FAILURE;
 
   DWORD bytes_read = 0;
   while (InternetReadFile(http_handle, buffer.get(), kMaxPingResponseLength,
@@ -391,7 +392,7 @@ bool FinancialPing::PingServer(const char* request, std::string* response) {
     bytes_read = 0;
   };
 
-  return true;
+  return PING_SUCCESSFUL;
 #else
   std::string url =
       base::StringPrintf("https://%s%s", kFinancialServer, request);
@@ -423,11 +424,17 @@ bool FinancialPing::PingServer(const char* request, std::string* response) {
 
   base::subtle::Release_Store(&g_cancelShutdownCheck, 1);
 
-  if (!is_signaled || event->GetResponseCode() != 200)
-    return false;
+  if (!is_signaled)
+    return PING_FAILURE;
+
+  if (event->GetResponseCode() == net::URLFetcher::RESPONSE_CODE_INVALID) {
+    return PING_SHUTDOWN;
+  } else if (event->GetResponseCode() != 200) {
+    return PING_FAILURE;
+  }
 
   *response = event->TakeResponse();
-  return true;
+  return PING_SUCCESSFUL;
 #endif
 }
 

rlz/lib/financial_ping.h

@@ -20,6 +20,13 @@ namespace rlz_lib {
 
 class FinancialPing {
  public:
+  // Return values of the PingServer() method.
+  enum PingResponse {
+    PING_SUCCESSFUL,  // Ping sent and response processed successfully.
+    PING_FAILURE,     // Ping not sent.
+    PING_SHUTDOWN     // Ping not sent because chrome is shutting down.
+  };
+
   // Form the HTTP request to send to the PSO server.
   // Will look something like:
   // /pso/ping?as=swg&brand=GGLD&id=124&hl=en&
@@ -47,7 +54,7 @@ class FinancialPing {
   static bool ClearLastPingTime(Product product);
 
   // Ping the financial server with request. Writes to RlzValueStore.
-  static bool PingServer(const char* request, std::string* response);
+  static PingResponse PingServer(const char* request, std::string* response);
 
   // Returns the time relative to a fixed point in the past in multiples of
   // 100 ns stepts. The point in the past is arbitrary but can't change, as the

rlz/lib/rlz_lib.cc

@@ -13,7 +13,9 @@
 #include "base/strings/string_util.h"
 #include "base/strings/stringprintf.h"
 #include "base/syslog_logging.h"
+#include "base/time/time.h"
 #include "build/build_config.h"
+#include "net/base/backoff_entry.h"
 #include "rlz/lib/assert.h"
 #include "rlz/lib/financial_ping.h"
 #include "rlz/lib/lib_values.h"
@@ -407,7 +409,11 @@ bool SendFinancialPing(Product product,
                        const char* product_lang,
                        bool exclude_machine_id,
                        const bool skip_time_check) {
-  // Create the financial ping request.
+  // Create the financial ping request.  To support ChromeOS retries, the
+  // same request needs to be sent out each time in order to preserve the
+  // machine id.  Not doing so could cause the RLZ server to over count
+  // ChromeOS machines under some network error conditions (for example,
+  // the request is properly received but the response it not).
   std::string request;
   if (!FinancialPing::FormRequest(product, access_points, product_signature,
                                   product_brand, product_id, product_lang,
@@ -418,29 +424,65 @@ bool SendFinancialPing(Product product,
   if (!FinancialPing::IsPingTime(product, skip_time_check))
     return false;
 
-#if defined(OS_CHROMEOS)
-  // Write to syslog that an RLZ ping is being attempted.  This is purposefully
-  // done via syslog so that admin and/or end users can monitor RLZ activity
-  // from this machine.  If RLZ is turned off in crosh, these messages will
-  // be absent.
-  SYSLOG(INFO) << "Attempting to send RLZ ping brand=" << product_brand;
-#endif
-
   // Send out the ping, update the last ping time irrespective of success.
   FinancialPing::UpdateLastPingTime(product);
   std::string response;
-  if (!FinancialPing::PingServer(request.c_str(), &response)) {
+
 #if defined(OS_CHROMEOS)
-    SYSLOG(INFO) << "Failed sending RLZ ping";
-#endif
+
+  const net::BackoffEntry::Policy policy = {
+      0,  // Number of initial errors to ignore.
+      base::TimeDelta::FromSeconds(5).InMilliseconds(),  // Initial delay.
+      2,    // Factor to increase delay.
+      0.1,  // Delay fuzzing.
+      base::TimeDelta::FromMinutes(5).InMilliseconds(),  // Maximum delay.
+      -1,  // Time to keep entries.  -1 == never discard.
+  };
+  net::BackoffEntry backoff(&policy);
+
+  const int kMaxRetryCount = 3;
+  FinancialPing::PingResponse res = FinancialPing::PING_FAILURE;
+  while (backoff.failure_count() < kMaxRetryCount) {
+    // Write to syslog that an RLZ ping is being attempted.  This is
+    // purposefully done via syslog so that admin and/or end users can monitor
+    // RLZ activity from this machine.  If RLZ is turned off in crosh, these
+    // messages will be absent.
+    SYSLOG(INFO) << "Attempting to send RLZ ping brand=" << product_brand;
+
+    res = FinancialPing::PingServer(request.c_str(), &response);
+    if (res != FinancialPing::PING_FAILURE)
+      break;
+
+    backoff.InformOfRequest(false);
+    if (backoff.ShouldRejectRequest()) {
+      SYSLOG(INFO) << "Failed sending RLZ ping - retrying in "
+                   << backoff.GetTimeUntilRelease().InSeconds() << " seconds";
+    }
+
+    base::PlatformThread::Sleep(backoff.GetTimeUntilRelease());
+  }
+
+  if (res != FinancialPing::PING_SUCCESSFUL) {
+    if (res == FinancialPing::PING_FAILURE) {
+      SYSLOG(INFO) << "Failed sending RLZ ping after " << kMaxRetryCount
+                   << " tries";
+    } else {  // res == FinancialPing::PING_SHUTDOWN
+      SYSLOG(INFO) << "Failed sending RLZ ping due to chrome shutdown";
+    }
     return false;
   }
 
-#if defined(OS_CHROMEOS)
   SYSLOG(INFO) << "Succeeded in sending RLZ ping";
+
+#else
+
+  FinancialPing::PingResponse res =
+      FinancialPing::PingServer(request.c_str(), &response);
+  if (res != FinancialPing::PING_SUCCESSFUL)
+    return false;
+
 #endif
 
-  // Parse the ping response - update RLZs, clear events.
   return ParsePingResponse(product, response.c_str());
 }
 

rlz/lib/rlz_lib_test.cc

@@ -20,16 +20,19 @@
 #include "base/logging.h"
 #include "base/message_loop/message_loop.h"
 #include "base/posix/eintr_wrapper.h"
-#include "base/single_thread_task_runner.h"
+#include "base/strings/stringprintf.h"
 #include "base/test/scoped_task_environment.h"
 #include "build/build_config.h"
+#include "net/url_request/test_url_fetcher_factory.h"
 #include "rlz/lib/financial_ping.h"
+#include "rlz/lib/lib_values.h"
 #include "rlz/lib/net_response_check.h"
 #include "rlz/lib/rlz_lib.h"
 #include "rlz/lib/rlz_value_store.h"
 #include "rlz/test/rlz_test_helpers.h"
 #include "testing/gmock/include/gmock/gmock.h"
 #include "testing/gtest/include/gtest/gtest.h"
+#include "url/gurl.h"
 
 #if defined(OS_WIN)
 #include <Windows.h>
@@ -42,7 +45,6 @@
 #include "net/url_request/url_request_test_util.h"
 #endif
 
-
 class MachineDealCodeHelper
 #if defined(OS_WIN)
     : public rlz_lib::MachineDealCode
@@ -64,6 +66,37 @@ class MachineDealCodeHelper
 
 class RlzLibTest : public RlzLibTestBase {
  protected:
+  void FakeGoodPingResponse(rlz_lib::Product product,
+                            const rlz_lib::AccessPoint* access_points,
+                            const char* product_signature,
+                            const char* product_brand,
+                            const char* product_id,
+                            const char* product_lang,
+                            bool exclude_machine_id,
+                            net::FakeURLFetcherFactory* factory) {
+    const char kGoodPingResponses[] =
+        "version: 3.0.914.7250\r\n"
+        "url: "
+        "http://www.corp.google.com/~av/45/opt/SearchWithGoogleUpdate.exe\r\n"
+        "launch-action: custom-action\r\n"
+        "launch-target: SearchWithGoogleUpdate.exe\r\n"
+        "signature: c08a3f4438e1442c4fe5678ee147cf6c5516e5d62bb64e\r\n"
+        "rlz: 1R1_____en__252\r\n"
+        "rlzXX: 1R1_____en__250\r\n"
+        "rlzT4  1T4_____en__251\r\n"
+        "rlzT4: 1T4_____en__252\r\n"
+        "rlz\r\n"
+        "crc32: D6FD55A3";
+    std::string request;
+    EXPECT_TRUE(rlz_lib::FinancialPing::FormRequest(
+        product, access_points, product_signature, product_brand, product_id,
+        product_lang, exclude_machine_id, &request));
+    GURL url = GURL(base::StringPrintf(
+        "https://%s%s", rlz_lib::kFinancialServer, request.c_str()));
+    factory->SetFakeResponse(url, kGoodPingResponses, net::HTTP_OK,
+                             net::URLRequestStatus::SUCCESS);
+  }
+
   base::test::ScopedTaskEnvironment scoped_task_environment_;
 };
 
@@ -455,9 +488,9 @@ class URLRequestRAII {
 };
 
 TEST_F(RlzLibTest, SendFinancialPing) {
-  // We don't really check a value or result in this test. All this does is
-  // attempt to ping the financial server, which you can verify in Fiddler.
-  // TODO: Make this a measurable test.
+  // rlz_lib::SendFinancialPing fails when this is set.
+  if (!rlz_lib::SupplementaryBranding::GetBrand().empty())
+    return;
 
 #if defined(RLZ_NETWORK_IMPLEMENTATION_CHROME_NET)
 #if defined(OS_MACOSX)
@@ -495,10 +528,18 @@ TEST_F(RlzLibTest, SendFinancialPing) {
     {rlz_lib::IETB_SEARCH_BOX, rlz_lib::NO_ACCESS_POINT,
      rlz_lib::NO_ACCESS_POINT};
 
-  std::string request;
-  rlz_lib::SendFinancialPing(rlz_lib::TOOLBAR_NOTIFIER, points,
-      "swg", "GGLA", "SwgProductId1234", "en-UK", false,
-      /*skip_time_check=*/true);
+  // Excluding machine id from requests so that a stable URL is used and
+  // this test can use FakeURLFetcherFactory.
+  net::FakeURLFetcherFactory factory(nullptr);
+  FakeGoodPingResponse(rlz_lib::TOOLBAR_NOTIFIER, points, "swg", "GGLA",
+                       "SwgProductId1234", "en-UK",
+                       /* exclude_machine_id */ true, &factory);
+
+  EXPECT_TRUE(rlz_lib::SendFinancialPing(rlz_lib::TOOLBAR_NOTIFIER, points,
+                                         "swg", "GGLA", "SwgProductId1234",
+                                         "en-UK",
+                                         /* exclude_machine_id */ true,
+                                         /* skip_time_check */true));
 }
 
 #if defined(RLZ_NETWORK_IMPLEMENTATION_CHROME_NET)