Add NetLog details for DHCP-based WPAD.

Adds NetLog instrumentation for how the network adapter list was read on Windows:
 * The enumerated network adapters
 * How long it took to schedule the task to worker thread
 * How long it took to schedule the reply task to origin thread
 * How long it took to query the adapters
 * Which "adapter fetcher" won the overall race for WPAD

Subsequent CLS will add more logging for the individual "adapter fetchers".

TBR=stevenjb@chromium.org

Bug: 770201
Change-Id: I9f704614e4a991e9a56879fc81637d41782dce1f
Reviewed-on: https://chromium-review.googlesource.com/876921
Commit-Queue: Eric Roman <eroman@chromium.org>
Reviewed-by: Eric Roman <eroman@chromium.org>
Reviewed-by: Steven Bennetts <stevenjb@chromium.org>
Reviewed-by: Matt Menke <mmenke@chromium.org>
Cr-Commit-Position: refs/heads/master@{#540693}

chromeos/network/dhcp_pac_file_fetcher_chromeos.cc

@@ -45,7 +45,8 @@ DhcpProxyScriptFetcherChromeos::~DhcpProxyScriptFetcherChromeos() = default;
 
 int DhcpProxyScriptFetcherChromeos::Fetch(
     base::string16* utf16_text,
-    const net::CompletionCallback& callback) {
+    const net::CompletionCallback& callback,
+    const net::NetLogWithSource& net_log) {
   if (!network_handler_task_runner_.get())
     return net::ERR_PAC_NOT_IN_DHCP;
   CHECK(!callback.is_null());

chromeos/network/dhcp_pac_file_fetcher_chromeos.h

@@ -20,6 +20,7 @@ class SingleThreadTaskRunner;
 
 namespace net {
 class URLRequestContext;
+class NetLogWithSource;
 class ProxyScriptFetcher;
 }
 
@@ -37,7 +38,8 @@ class CHROMEOS_EXPORT DhcpProxyScriptFetcherChromeos
 
   // net::DhcpProxyScriptFetcher
   int Fetch(base::string16* utf16_text,
-            const net::CompletionCallback& callback) override;
+            const net::CompletionCallback& callback,
+            const net::NetLogWithSource& net_log) override;
   void Cancel() override;
   void OnShutdown() override;
   const GURL& GetPacURL() const override;

net/log/net_log_event_type_list.h

@@ -3219,3 +3219,55 @@ EVENT_TYPE(HOST_CACHE_PREF_WRITE)
 // This event is created when the HostCachePersistenceManager starts the timer
 // for writing a cache change to prefs.
 EVENT_TYPE(HOST_CACHE_PERSISTENCE_START_TIMER)
+
+// -----------------------------------------------------------------------------
+// DHCP-based WPAD (Windows)
+// -----------------------------------------------------------------------------
+
+// The start/end of running DHCP based WPAD.
+//
+// The start event contains no parameters, whereas the END event describes
+// which of the "adapter fetchers" was used:
+//  {
+//    "fetcher_index": <Index of the fetcher that "won" the race, or -1 if no
+//                     fetcher won>,
+//    "net_error": <The network error code for the overall result of DHCP
+//                  based auto-discovery>,
+//  }
+EVENT_TYPE(WPAD_DHCP_WIN_FETCH)
+
+// The start/end of getting the list of network adapters.
+//
+// The END event describes all the adapters that were enumerated, as well
+// as how long it took to do the various thread-hops (from origin to worker
+// thread, and then worker thread back to origin thread):
+//  {
+//    "adapters": <List describing each adapter (its name, flags, and
+//                 status)>,
+//    "origin_to_worker_thread_hop_dt": <The time in milliseconds it took
+//                                       for the worker thread task to get
+//                                       scheduled>,
+//    "worker_to_origin_thread_hop_dt": <The time in milliseconds it took
+//                                       for the reply task from worker
+//                                       thread to get scheduled>,
+//    "worker_dt": <The time in milliseconds it took to enumerate network
+//                  adapters on the worker thread>,
+//    "error": <The result code returned by iphlpapi!GetAdaptersAddresses>
+//  }
+EVENT_TYPE(WPAD_DHCP_WIN_GET_ADAPTERS)
+
+// This event logs when one of the "adapter fetchers" completed. (Fetchers
+// may not complete in the order that they were started):
+//  {
+//    "fetcher_index": <Index of the fetcher that completed>,
+//    "net_error": <The network error code returned by the fetcher>,
+//  }
+EVENT_TYPE(WPAD_DHCP_WIN_ON_FETCHER_DONE)
+
+// This event is logged when a timer is started to timeout remaining
+// adapter fetchers. The event has no parameters.
+EVENT_TYPE(WPAD_DHCP_WIN_START_WAIT_TIMER)
+
+// This event is emitted if the wait timer for remaining fetchers fires. It
+// has no parameters.
+EVENT_TYPE(WPAD_DHCP_WIN_ON_WAIT_TIMER)

net/proxy_resolution/dhcp_pac_file_fetcher.cc

@@ -20,8 +20,9 @@ DoNothingDhcpProxyScriptFetcher::DoNothingDhcpProxyScriptFetcher() = default;
 
 DoNothingDhcpProxyScriptFetcher::~DoNothingDhcpProxyScriptFetcher() = default;
 
-int DoNothingDhcpProxyScriptFetcher::Fetch(
-    base::string16* utf16_text, const CompletionCallback& callback) {
+int DoNothingDhcpProxyScriptFetcher::Fetch(base::string16* utf16_text,
+                                           const CompletionCallback& callback,
+                                           const NetLogWithSource& net_log) {
   return ERR_NOT_IMPLEMENTED;
 }
 

net/proxy_resolution/dhcp_pac_file_fetcher.h

@@ -15,6 +15,8 @@
 
 namespace net {
 
+class NetLogWithSource;
+
 // Interface for classes that can fetch a proxy script as configured via DHCP.
 //
 // The Fetch method on this interface tries to retrieve the most appropriate
@@ -57,7 +59,8 @@ class NET_EXPORT_PRIVATE DhcpProxyScriptFetcher {
   //
   // Only one fetch is allowed to be outstanding at a time.
   virtual int Fetch(base::string16* utf16_text,
-                    const CompletionCallback& callback) = 0;
+                    const CompletionCallback& callback,
+                    const NetLogWithSource& net_log) = 0;
 
   // Aborts the in-progress fetch (if any).
   virtual void Cancel() = 0;
@@ -91,7 +94,8 @@ class NET_EXPORT_PRIVATE DoNothingDhcpProxyScriptFetcher
   ~DoNothingDhcpProxyScriptFetcher() override;
 
   int Fetch(base::string16* utf16_text,
-            const CompletionCallback& callback) override;
+            const CompletionCallback& callback,
+            const NetLogWithSource& net_log) override;
   void Cancel() override;
   void OnShutdown() override;
   const GURL& GetPacURL() const override;

net/proxy_resolution/dhcp_pac_file_fetcher_win.h

@@ -16,6 +16,7 @@
 #include "base/time/time.h"
 #include "base/timer/timer.h"
 #include "net/base/net_export.h"
+#include "net/log/net_log_with_source.h"
 #include "net/proxy_resolution/dhcp_pac_file_fetcher.h"
 
 namespace base {
@@ -24,6 +25,7 @@ class TaskRunner;
 
 namespace net {
 
+struct DhcpAdapterNamesLoggingInfo;
 class DhcpProxyScriptAdapterFetcher;
 class URLRequestContext;
 
@@ -40,16 +42,19 @@ class NET_EXPORT_PRIVATE DhcpProxyScriptFetcherWin
 
   // DhcpProxyScriptFetcher implementation.
   int Fetch(base::string16* utf16_text,
-            const CompletionCallback& callback) override;
+            const CompletionCallback& callback,
+            const NetLogWithSource& net_log) override;
   void Cancel() override;
   void OnShutdown() override;
   const GURL& GetPacURL() const override;
   std::string GetFetcherName() const override;
 
   // Sets |adapter_names| to contain the name of each network adapter on
-  // this machine that has DHCP enabled and is not a loop-back adapter. Returns
-  // false on error.
-  static bool GetCandidateAdapterNames(std::set<std::string>* adapter_names);
+  // this machine that has DHCP enabled and is not a loop-back adapter. May
+  // optionally update |info| (if non-null) with information for logging.
+  // Returns false on error.
+  static bool GetCandidateAdapterNames(std::set<std::string>* adapter_names,
+                                       DhcpAdapterNamesLoggingInfo* info);
 
  protected:
   int num_pending_fetchers() const;
@@ -73,19 +78,23 @@ class NET_EXPORT_PRIVATE DhcpProxyScriptFetcherWin
     // been run. Its lifetime is scoped by this object.
     const std::set<std::string>& adapter_names() const;
 
+    DhcpAdapterNamesLoggingInfo* logging_info() { return logging_info_.get(); }
+
    protected:
     // Virtual method introduced to allow unit testing.
     virtual bool ImplGetCandidateAdapterNames(
-        std::set<std::string>* adapter_names);
+        std::set<std::string>* adapter_names,
+        DhcpAdapterNamesLoggingInfo* info);
 
     friend class base::RefCountedThreadSafe<AdapterQuery>;
     virtual ~AdapterQuery();
 
    private:
-    // This is constructed on the originating thread, then used on the
+    // These are constructed on the originating thread, then used on the
     // worker thread, then used again on the originating thread only when
     // the task has completed on the worker thread. No locking required.
     std::set<std::string> adapter_names_;
+    std::unique_ptr<DhcpAdapterNamesLoggingInfo> logging_info_;
 
     DISALLOW_COPY_AND_ASSIGN(AdapterQuery);
   };
@@ -100,7 +109,7 @@ class NET_EXPORT_PRIVATE DhcpProxyScriptFetcherWin
   // Event/state transition handlers
   void CancelImpl();
   void OnGetCandidateAdapterNamesDone(scoped_refptr<AdapterQuery> query);
-  void OnFetcherDone(int result);
+  void OnFetcherDone(size_t fetcher_i, int result);
   void OnWaitTimer();
   void TransitionToDone();
 
@@ -139,9 +148,6 @@ class NET_EXPORT_PRIVATE DhcpProxyScriptFetcherWin
     STATE_DONE,
   };
 
-  // Current state of this state machine.
-  State state_;
-
   // Vector, in Windows' network adapter preference order, of
   // DhcpProxyScriptAdapterFetcher objects that are or were attempting
   // to fetch a PAC file based on DHCP configuration.
@@ -149,12 +155,20 @@ class NET_EXPORT_PRIVATE DhcpProxyScriptFetcherWin
       std::vector<std::unique_ptr<DhcpProxyScriptAdapterFetcher>>;
   FetcherVector fetchers_;
 
+  // Current state of this state machine.
+  State state_;
+
+  // The following members are associated with the latest call to Fetch().
+
   // Number of fetchers we are waiting for.
   int num_pending_fetchers_;
 
   // Lets our client know we're done. Not valid in states START or DONE.
   CompletionCallback callback_;
 
+  // The NetLog to use for the current Fetch().
+  NetLogWithSource net_log_;
+
   // Pointer to string we will write results to. Not valid in states
   // START and DONE.
   base::string16* destination_string_;
@@ -170,9 +184,6 @@ class NET_EXPORT_PRIVATE DhcpProxyScriptFetcherWin
   // NULL or the AdapterQuery currently in flight.
   scoped_refptr<AdapterQuery> last_query_;
 
-  // Time |Fetch()| was last called, 0 if never.
-  base::TimeTicks fetch_start_time_;
-
   // TaskRunner used for all DHCP lookup tasks.
   const scoped_refptr<base::TaskRunner> task_runner_;
 

net/proxy_resolution/dhcp_pac_file_fetcher_win_unittest.cc

@@ -36,11 +36,8 @@ TEST(DhcpProxyScriptFetcherWin, AdapterNamesAndPacURLFromDhcp) {
   // is no crash and no error returned, but does not assert on the number
   // of interfaces or the information returned via DHCP.
   std::set<std::string> adapter_names;
-  DhcpProxyScriptFetcherWin::GetCandidateAdapterNames(&adapter_names);
-  for (std::set<std::string>::const_iterator it = adapter_names.begin();
-       it != adapter_names.end();
-       ++it) {
-    const std::string& adapter_name = *it;
+  DhcpProxyScriptFetcherWin::GetCandidateAdapterNames(&adapter_names, nullptr);
+  for (const std::string& adapter_name : adapter_names) {
     DhcpProxyScriptAdapterFetcher::GetPacURLFromDhcp(adapter_name);
   }
 }
@@ -61,7 +58,8 @@ class RealFetchTester {
   void RunTest() {
     int result = fetcher_->Fetch(
         &pac_text_,
-        base::Bind(&RealFetchTester::OnCompletion, base::Unretained(this)));
+        base::Bind(&RealFetchTester::OnCompletion, base::Unretained(this)),
+        NetLogWithSource());
     if (result != ERR_IO_PENDING)
       finished_ = true;
   }
@@ -276,9 +274,10 @@ class MockDhcpProxyScriptFetcherWin : public DhcpProxyScriptFetcherWin {
     }
 
     bool ImplGetCandidateAdapterNames(
-        std::set<std::string>* adapter_names) override {
-      adapter_names->insert(
-          mock_adapter_names_.begin(), mock_adapter_names_.end());
+        std::set<std::string>* adapter_names,
+        DhcpAdapterNamesLoggingInfo* logging) override {
+      adapter_names->insert(mock_adapter_names_.begin(),
+                            mock_adapter_names_.end());
       return true;
     }
 
@@ -388,14 +387,16 @@ class FetcherClient {
   void RunTest() {
     int result = fetcher_.Fetch(
         &pac_text_,
-        base::Bind(&FetcherClient::OnCompletion, base::Unretained(this)));
+        base::Bind(&FetcherClient::OnCompletion, base::Unretained(this)),
+        NetLogWithSource());
     ASSERT_THAT(result, IsError(ERR_IO_PENDING));
   }
 
   int RunTestThatMayFailSync() {
     int result = fetcher_.Fetch(
         &pac_text_,
-        base::Bind(&FetcherClient::OnCompletion, base::Unretained(this)));
+        base::Bind(&FetcherClient::OnCompletion, base::Unretained(this)),
+        NetLogWithSource());
     if (result != ERR_IO_PENDING)
       result_ = result;
     return result;

net/proxy_resolution/pac_file_decider.cc

@@ -327,8 +327,9 @@ int ProxyScriptDecider::DoFetchPacScript() {
     }
 
     return dhcp_proxy_script_fetcher_->Fetch(
-        &pac_script_, base::Bind(&ProxyScriptDecider::OnIOCompletion,
-                                 base::Unretained(this)));
+        &pac_script_,
+        base::Bind(&ProxyScriptDecider::OnIOCompletion, base::Unretained(this)),
+        net_log_);
   }
 
   if (!proxy_script_fetcher_) {

net/proxy_resolution/pac_file_decider_unittest.cc

@@ -145,7 +145,8 @@ class MockDhcpProxyScriptFetcher : public DhcpProxyScriptFetcher {
   ~MockDhcpProxyScriptFetcher() override;
 
   int Fetch(base::string16* utf16_text,
-            const CompletionCallback& callback) override;
+            const CompletionCallback& callback,
+            const NetLogWithSource& net_log) override;
   void Cancel() override;
   void OnShutdown() override;
   const GURL& GetPacURL() const override;
@@ -166,7 +167,8 @@ MockDhcpProxyScriptFetcher::MockDhcpProxyScriptFetcher() = default;
 MockDhcpProxyScriptFetcher::~MockDhcpProxyScriptFetcher() = default;
 
 int MockDhcpProxyScriptFetcher::Fetch(base::string16* utf16_text,
-                                      const CompletionCallback& callback) {
+                                      const CompletionCallback& callback,
+                                      const NetLogWithSource& net_log) {
   utf16_text_ = utf16_text;
   callback_ = callback;
   return ERR_IO_PENDING;
@@ -673,7 +675,8 @@ class SynchronousSuccessDhcpFetcher : public DhcpProxyScriptFetcher {
       : gurl_("http://dhcppac/"), expected_text_(expected_text) {}
 
   int Fetch(base::string16* utf16_text,
-            const CompletionCallback& callback) override {
+            const CompletionCallback& callback,
+            const NetLogWithSource& net_log) override {
     *utf16_text = expected_text_;
     return OK;
   }
@@ -751,7 +754,8 @@ class AsyncFailDhcpFetcher
   ~AsyncFailDhcpFetcher() override = default;
 
   int Fetch(base::string16* utf16_text,
-            const CompletionCallback& callback) override {
+            const CompletionCallback& callback,
+            const NetLogWithSource& net_log) override {
     callback_ = callback;
     base::ThreadTaskRunnerHandle::Get()->PostTask(
         FROM_HERE,