Adding NetLog support to SafeBrowsingPingManager.

This includes defining a new NetLog event (SAFE_BROWSING_PING), which begins
when a ping is queued up, and ends when the result callback is fired. Covers
both the SafeBrowsingHit and ThreatDetails pings.

BUG=648323

Review-Url: https://codereview.chromium.org/2361963002
Cr-Commit-Position: refs/heads/master@{#422849}

chrome/browser/safe_browsing/ping_manager.cc

@@ -6,10 +6,12 @@
 
 #include <utility>
 
+#include "base/base64.h"
 #include "base/logging.h"
 #include "base/memory/ptr_util.h"
 #include "base/strings/string_util.h"
 #include "base/strings/stringprintf.h"
+#include "base/values.h"
 #include "chrome/browser/safe_browsing/permission_reporter.h"
 #include "components/certificate_reporting/error_reporter.h"
 #include "components/data_use_measurement/core/data_use_user_data.h"
@@ -17,9 +19,11 @@
 #include "google_apis/google_api_keys.h"
 #include "net/base/escape.h"
 #include "net/base/load_flags.h"
+#include "net/log/net_log_source_type.h"
 #include "net/ssl/ssl_info.h"
 #include "net/url_request/report_sender.h"
 #include "net/url_request/url_fetcher.h"
+#include "net/url_request/url_request_context.h"
 #include "net/url_request/url_request_context_getter.h"
 #include "net/url_request/url_request_status.h"
 #include "url/gurl.h"
@@ -33,6 +37,36 @@ namespace {
 const char kExtendedReportingUploadUrlInsecure[] =
     "http://safebrowsing.googleusercontent.com/safebrowsing/clientreport/"
     "chrome-certs";
+
+// Returns a dictionary with "url"=|url-spec| and "data"=|payload| for
+// netlogging the start phase of a ping.
+std::unique_ptr<base::Value> NetLogPingStartCallback(
+    const net::NetLogWithSource& net_log,
+    const GURL& url,
+    const std::string& payload,
+    net::NetLogCaptureMode) {
+  std::unique_ptr<base::DictionaryValue> event_params(
+      new base::DictionaryValue());
+  event_params->SetString("url", url.spec());
+  event_params->SetString("payload", payload);
+  net_log.source().AddToEventParameters(event_params.get());
+  return std::move(event_params);
+}
+
+// Returns a dictionary with "url"=|url-spec|, "status"=|status| and
+// "error"=|error| for netlogging the end phase of a ping.
+std::unique_ptr<base::Value> NetLogPingEndCallback(
+    const net::NetLogWithSource& net_log,
+    const net::URLRequestStatus& status,
+    net::NetLogCaptureMode) {
+  std::unique_ptr<base::DictionaryValue> event_params(
+      new base::DictionaryValue());
+  event_params->SetInteger("status", status.status());
+  event_params->SetInteger("error", status.error());
+  net_log.source().AddToEventParameters(event_params.get());
+  return std::move(event_params);
+}
+
 }  // namespace
 
 namespace safe_browsing {
@@ -68,6 +102,10 @@ SafeBrowsingPingManager::SafeBrowsingPingManager(
 
     permission_reporter_.reset(
         new PermissionReporter(request_context_getter->GetURLRequestContext()));
+
+    net_log_ = net::NetLogWithSource::Make(
+        request_context_getter->GetURLRequestContext()->net_log(),
+        net::NetLogSourceType::SAFE_BROWSING);
   }
 
   version_ = SafeBrowsingProtocolManagerHelper::Version();
@@ -81,6 +119,9 @@ SafeBrowsingPingManager::~SafeBrowsingPingManager() {
 // All SafeBrowsing request responses are handled here.
 void SafeBrowsingPingManager::OnURLFetchComplete(
     const net::URLFetcher* source) {
+  net_log_.EndEvent(
+      net::NetLogEventType::SAFE_BROWSING_PING,
+      base::Bind(&NetLogPingEndCallback, net_log_, source->GetStatus()));
   auto it =
       std::find_if(safebrowsing_reports_.begin(), safebrowsing_reports_.end(),
                    [source](const std::unique_ptr<net::URLFetcher>& ptr) {
@@ -103,10 +144,19 @@ void SafeBrowsingPingManager::ReportSafeBrowsingHit(
       report, data_use_measurement::DataUseUserData::SAFE_BROWSING);
   report_ptr->SetLoadFlags(net::LOAD_DISABLE_CACHE);
   report_ptr->SetRequestContext(request_context_getter_.get());
-  if (!hit_report.post_data.empty())
+  std::string post_data_base64;
+  if (!hit_report.post_data.empty()) {
     report_ptr->SetUploadData("text/plain", hit_report.post_data);
-  safebrowsing_reports_.insert(std::move(report_ptr));
+    base::Base64Encode(hit_report.post_data, &post_data_base64);
+  }
+
+  net_log_.BeginEvent(
+      net::NetLogEventType::SAFE_BROWSING_PING,
+      base::Bind(&NetLogPingStartCallback, net_log_,
+                 report_ptr->GetOriginalURL(), post_data_base64));
+
   report->Start();
+  safebrowsing_reports_.insert(std::move(report_ptr));
 }
 
 // Sends threat details for users who opt-in.
@@ -121,6 +171,14 @@ void SafeBrowsingPingManager::ReportThreatDetails(const std::string& report) {
   fetcher->SetUploadData("application/octet-stream", report);
   // Don't try too hard to send reports on failures.
   fetcher->SetAutomaticallyRetryOn5xx(false);
+
+  std::string report_base64;
+  base::Base64Encode(report, &report_base64);
+  net_log_.BeginEvent(
+      net::NetLogEventType::SAFE_BROWSING_PING,
+      base::Bind(&NetLogPingStartCallback, net_log_, fetcher->GetOriginalURL(),
+                 report_base64));
+
   fetcher->Start();
   safebrowsing_reports_.insert(std::move(fetcher));
 }

chrome/browser/safe_browsing/ping_manager.h

@@ -19,6 +19,7 @@
 #include "components/safe_browsing_db/hit_report.h"
 #include "components/safe_browsing_db/util.h"
 #include "content/public/browser/permission_type.h"
+#include "net/log/net_log_with_source.h"
 #include "net/url_request/url_fetcher_delegate.h"
 #include "url/gurl.h"
 
@@ -69,9 +70,14 @@ class SafeBrowsingPingManager : public net::URLFetcherDelegate {
 
  private:
   friend class PermissionReporterBrowserTest;
+  friend class SafeBrowsingPingManagerTest;
   FRIEND_TEST_ALL_PREFIXES(SafeBrowsingPingManagerTest,
                            TestSafeBrowsingHitUrl);
   FRIEND_TEST_ALL_PREFIXES(SafeBrowsingPingManagerTest, TestThreatDetailsUrl);
+  FRIEND_TEST_ALL_PREFIXES(SafeBrowsingPingManagerTest,
+                           TestReportThreatDetails);
+  FRIEND_TEST_ALL_PREFIXES(SafeBrowsingPingManagerTest,
+                           TestReportSafeBrowsingHit);
 
   typedef std::set<std::unique_ptr<net::URLFetcher>> Reports;
 
@@ -111,6 +117,8 @@ class SafeBrowsingPingManager : public net::URLFetcherDelegate {
   // Sends reports of permission actions.
   std::unique_ptr<PermissionReporter> permission_reporter_;
 
+  net::NetLogWithSource net_log_;
+
   DISALLOW_COPY_AND_ASSIGN(SafeBrowsingPingManager);
 };
 

chrome/browser/safe_browsing/ping_manager_unittest.cc

@@ -3,12 +3,19 @@
 // found in the LICENSE file.
 //
 
+#include "base/base64.h"
 #include "base/logging.h"
 #include "base/strings/stringprintf.h"
 #include "base/time/time.h"
+#include "base/values.h"
 #include "chrome/browser/safe_browsing/ping_manager.h"
 #include "google_apis/google_api_keys.h"
 #include "net/base/escape.h"
+#include "net/log/net_log.h"
+#include "net/log/net_log_source_type.h"
+#include "net/log/test_net_log.h"
+#include "net/log/test_net_log_entry.h"
+#include "net/url_request/test_url_fetcher_factory.h"
 #include "testing/gtest/include/gtest/gtest.h"
 
 using base::Time;
@@ -23,9 +30,14 @@ static const char kAppVer[] = "1.0";
 namespace safe_browsing {
 
 class SafeBrowsingPingManagerTest : public testing::Test {
- protected:
-  std::string key_param_;
+ public:
+  SafeBrowsingPingManagerTest()
+      : net_log_(new net::TestNetLog()) {
+    net_log_with_source_ = net::NetLogWithSource::Make(
+        net_log_.get(), net::NetLogSourceType::SAFE_BROWSING);
+  }
 
+ protected:
   void SetUp() override {
     std::string key = google_apis::GetAPIKey();
     if (!key.empty()) {
@@ -33,16 +45,27 @@ class SafeBrowsingPingManagerTest : public testing::Test {
           "&key=%s",
           net::EscapeQueryParamValue(key, true).c_str());
     }
+
+    SafeBrowsingProtocolConfig config;
+    config.client_name = kClient;
+    config.url_prefix = kUrlPrefix;
+    ping_manager_.reset(new SafeBrowsingPingManager(NULL, config));
+    ping_manager_->version_ = kAppVer;
+    ping_manager_->net_log_ = net_log_with_source_;
   }
+
+  SafeBrowsingPingManager* ping_manager()  {
+    return ping_manager_.get();
+  }
+
+  std::string key_param_;
+  std::unique_ptr<net::TestNetLog> net_log_;
+  net::NetLogWithSource net_log_with_source_;
+  net::TestURLFetcherFactory fetcher_factory_;
+  std::unique_ptr<SafeBrowsingPingManager> ping_manager_;
 };
 
 TEST_F(SafeBrowsingPingManagerTest, TestSafeBrowsingHitUrl) {
-  SafeBrowsingProtocolConfig config;
-  config.client_name = kClient;
-  config.url_prefix = kUrlPrefix;
-  SafeBrowsingPingManager pm(NULL, config);
-  pm.version_ = kAppVer;
-
   HitReport base_hp;
   base_hp.malicious_url = GURL("http://malicious.url.com");
   base_hp.page_url = GURL("http://page.url.com");
@@ -63,7 +86,7 @@ TEST_F(SafeBrowsingPingManagerTest, TestSafeBrowsingHitUrl) {
             "&ext=1&evts=malblhit&evtd=http%3A%2F%2Fmalicious.url.com%2F&"
             "evtr=http%3A%2F%2Fpage.url.com%2F&evhr=http%3A%2F%2Freferrer."
             "url.com%2F&evtb=1&src=l3&m=1",
-        pm.SafeBrowsingHitUrl(hp).spec());
+        ping_manager()->SafeBrowsingHitUrl(hp).spec());
   }
 
   {
@@ -81,7 +104,7 @@ TEST_F(SafeBrowsingPingManagerTest, TestSafeBrowsingHitUrl) {
             "evtd=http%3A%2F%2Fmalicious.url.com%2F&"
             "evtr=http%3A%2F%2Fpage.url.com%2F&evhr=http%3A%2F%2Freferrer."
             "url.com%2F&evtb=0&src=ds&m=1",
-        pm.SafeBrowsingHitUrl(hp).spec());
+        ping_manager()->SafeBrowsingHitUrl(hp).spec());
   }
 
   {
@@ -99,7 +122,7 @@ TEST_F(SafeBrowsingPingManagerTest, TestSafeBrowsingHitUrl) {
             "evtd=http%3A%2F%2Fmalicious.url.com%2F&"
             "evtr=http%3A%2F%2Fpage.url.com%2F&evhr=http%3A%2F%2Freferrer."
             "url.com%2F&evtb=0&src=rem&m=1",
-        pm.SafeBrowsingHitUrl(hp).spec());
+        ping_manager()->SafeBrowsingHitUrl(hp).spec());
   }
 
   {
@@ -117,7 +140,7 @@ TEST_F(SafeBrowsingPingManagerTest, TestSafeBrowsingHitUrl) {
             "evtd=http%3A%2F%2Fmalicious.url.com%2F&"
             "evtr=http%3A%2F%2Fpage.url.com%2F&evhr=http%3A%2F%2Freferrer."
             "url.com%2F&evtb=0&src=l4&m=0",
-        pm.SafeBrowsingHitUrl(hp).spec());
+        ping_manager()->SafeBrowsingHitUrl(hp).spec());
   }
 
   {
@@ -135,7 +158,7 @@ TEST_F(SafeBrowsingPingManagerTest, TestSafeBrowsingHitUrl) {
             "evtd=http%3A%2F%2Fmalicious.url.com%2F&"
             "evtr=http%3A%2F%2Fpage.url.com%2F&evhr=http%3A%2F%2Freferrer."
             "url.com%2F&evtb=1&src=l4&m=0",
-        pm.SafeBrowsingHitUrl(hp).spec());
+        ping_manager()->SafeBrowsingHitUrl(hp).spec());
   }
 
   // Same as above, but add population_id
@@ -155,20 +178,136 @@ TEST_F(SafeBrowsingPingManagerTest, TestSafeBrowsingHitUrl) {
             "evtd=http%3A%2F%2Fmalicious.url.com%2F&"
             "evtr=http%3A%2F%2Fpage.url.com%2F&evhr=http%3A%2F%2Freferrer."
             "url.com%2F&evtb=1&src=l4&m=0&up=foo+bar",
-        pm.SafeBrowsingHitUrl(hp).spec());
+        ping_manager()->SafeBrowsingHitUrl(hp).spec());
   }
 }
 
 TEST_F(SafeBrowsingPingManagerTest, TestThreatDetailsUrl) {
-  SafeBrowsingProtocolConfig config;
-  config.client_name = kClient;
-  config.url_prefix = kUrlPrefix;
-  SafeBrowsingPingManager pm(NULL, config);
-
-  pm.version_ = kAppVer;
   EXPECT_EQ("https://prefix.com/foo/clientreport/malware?"
             "client=unittest&appver=1.0&pver=1.0" + key_param_,
-            pm.ThreatDetailsUrl().spec());
+            ping_manager()->ThreatDetailsUrl().spec());
+}
+
+TEST_F(SafeBrowsingPingManagerTest, TestReportThreatDetails) {
+  const std::string kThreatDetailsReportString = "Threat Details Report String";
+  std::string encoded_threat_report = "";
+  base::Base64Encode(kThreatDetailsReportString, &encoded_threat_report);
+  std::string expected_threat_details_url = ping_manager()->ThreatDetailsUrl()
+      .spec();
+  const int kRequestErrorCode = -123;
+
+  // Start the report.
+  ping_manager()->ReportThreatDetails(kThreatDetailsReportString);
+
+  net::TestURLFetcher* fetcher = fetcher_factory_.GetFetcherByID(0);
+  DCHECK(fetcher);
+  // Set some error response data on the fetcher to make things interesting.
+  fetcher->set_status(
+      net::URLRequestStatus(net::URLRequestStatus::FAILED, kRequestErrorCode));
+  // Tell the test fetcher to invoke the fetch callback.
+  fetcher->delegate()->OnURLFetchComplete(fetcher);
+
+  // We expect two net log entries: one when the ping starts, one when it ends.
+  net::TestNetLogEntry::List entries;
+  net_log_->GetEntries(&entries);
+  ASSERT_EQ(2u, entries.size());
+
+  // Check for expected log entries for the begin phase.
+  const net::TestNetLogEntry& start_entry = entries[0];
+  ASSERT_EQ(3u, start_entry.params->size());
+
+  std::string string_value;
+  EXPECT_TRUE(start_entry.GetStringValue("url", &string_value));
+  EXPECT_EQ(expected_threat_details_url, string_value);
+
+  EXPECT_TRUE(start_entry.GetStringValue("payload", &string_value));
+  EXPECT_EQ(encoded_threat_report, string_value);
+
+  // We don't really care what the source_dependency value is, just making sure
+  // it's there.
+  EXPECT_TRUE(start_entry.params->HasKey("source_dependency"));
+
+  // Check for expected log entries for the end phase.
+  const net::TestNetLogEntry& end_entry = entries[1];
+  ASSERT_EQ(3u, end_entry.params->size());
+
+  int int_value;
+  EXPECT_TRUE(end_entry.GetIntegerValue("status", &int_value));
+  EXPECT_EQ(net::URLRequestStatus::FAILED, int_value);
+
+  EXPECT_TRUE(end_entry.GetIntegerValue("error", &int_value));
+  EXPECT_EQ(kRequestErrorCode, int_value);
+
+  // We don't really care what the source_dependency value is, just making sure
+  // it's there.
+  EXPECT_TRUE(end_entry.params->HasKey("source_dependency"));
+}
+
+TEST_F(SafeBrowsingPingManagerTest, TestReportSafeBrowsingHit) {
+  const std::string kHitReportPostData = "Hit Report POST Data";
+  std::string encoded_post_data = "";
+  base::Base64Encode(kHitReportPostData, &encoded_post_data);
+
+  HitReport hp;
+  hp.malicious_url = GURL("http://malicious.url.com");
+  hp.page_url = GURL("http://page.url.com");
+  hp.referrer_url = GURL("http://referrer.url.com");
+  hp.threat_type = SB_THREAT_TYPE_CLIENT_SIDE_MALWARE_URL;
+  hp.threat_source = ThreatSource::LOCAL_PVER4;
+  hp.is_extended_reporting = false;
+  hp.is_metrics_reporting_active = false;
+  hp.is_subresource = true;
+  hp.population_id = "foo bar";
+  hp.post_data = kHitReportPostData;
+  std::string expected_hit_report_url = ping_manager()->SafeBrowsingHitUrl(hp)
+      .spec();
+  const int kRequestErrorCode = -321;
+
+  // Start the report.
+  ping_manager()->ReportSafeBrowsingHit(hp);
+
+  net::TestURLFetcher* fetcher = fetcher_factory_.GetFetcherByID(0);
+  DCHECK(fetcher);
+  // Set some error response data on the fetcher to make things interesting.
+  fetcher->set_status(
+      net::URLRequestStatus(net::URLRequestStatus::FAILED, kRequestErrorCode));
+  // Tell the test fetcher to invoke the fetch callback.
+  fetcher->delegate()->OnURLFetchComplete(fetcher);
+
+  // We expect two net log entries: one when the ping starts, one when it ends.
+  net::TestNetLogEntry::List entries;
+  net_log_->GetEntries(&entries);
+  ASSERT_EQ(2u, entries.size());
+
+  // Check for expected log entries for the begin phase.
+  const net::TestNetLogEntry& start_entry = entries[0];
+  ASSERT_EQ(3u, start_entry.params->size());
+
+  std::string string_value;
+  EXPECT_TRUE(start_entry.GetStringValue("url", &string_value));
+  EXPECT_EQ(expected_hit_report_url, string_value);
+
+  EXPECT_TRUE(start_entry.GetStringValue("payload", &string_value));
+  EXPECT_EQ(encoded_post_data, string_value);
+
+  // We don't really care what the source_dependency value is, just making sure
+  // it's there.
+  EXPECT_TRUE(start_entry.params->HasKey("source_dependency"));
+
+  // Check for expected log entries for the end phase.
+  const net::TestNetLogEntry& end_entry = entries[1];
+  ASSERT_EQ(3u, end_entry.params->size());
+
+  int int_value;
+  EXPECT_TRUE(end_entry.GetIntegerValue("status", &int_value));
+  EXPECT_EQ(net::URLRequestStatus::FAILED, int_value);
+
+  EXPECT_TRUE(end_entry.GetIntegerValue("error", &int_value));
+  EXPECT_EQ(kRequestErrorCode, int_value);
+
+  // We don't really care what the source_dependency value is, just making sure
+  // it's there.
+  EXPECT_TRUE(end_entry.params->HasKey("source_dependency"));
 }
 
 }  // namespace safe_browsing

net/log/net_log_event_type_list.h

@@ -3020,6 +3020,21 @@ EVENT_TYPE(SAFE_BROWSING_CHECKING_URL)
 //  }
 EVENT_TYPE(SAFE_BROWSING_DEFERRED)
 
+// The start/end of a Safe Browsing ping being sent.
+//
+// The BEGIN phase contains the following parameters:
+//  {
+//    "url": <The URL the ping is going to, which identifies the type of ping
+//            that is being sent (eg: ThreatReport, SafeBrowsingHit)>
+//    "data": <The base64 encoding of the payload sent with the ping>
+//
+// The END phase contains the following parameters:
+//  {
+//    "status": <The integer status of the report transmission. Corresponds to
+//               URLRequestStatus::Status>
+//    "error": <The error code returned by the server, 0 indicating success>
+EVENT_TYPE(SAFE_BROWSING_PING)
+
 // Marks start of UploadDataStream that is logged on initialization.
 // The END phase contains the following parameters:
 // {