Improve performance of proxy resolver by tracing DNS dependencies.

net/proxy/proxy_resolver_v8_tracing_unittest.cc

+// Copyright (c) 2013 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 "net/proxy/proxy_resolver_v8_tracing.h"
+
+#include "base/file_util.h"
+#include "base/json/json_writer.h"
+#include "base/message_loop.h"
+#include "base/path_service.h"
+#include "base/stl_util.h"
+#include "base/string_util.h"
+#include "base/stringprintf.h"
+#include "base/synchronization/waitable_event.h"
+#include "base/threading/platform_thread.h"
+#include "base/utf_string_conversions.h"
+#include "base/values.h"
+#include "googleurl/src/gurl.h"
+#include "net/base/mock_host_resolver.h"
+#include "net/base/net_errors.h"
+#include "net/base/net_log.h"
+#include "net/base/net_log_unittest.h"
+#include "net/base/test_completion_callback.h"
+#include "net/proxy/proxy_info.h"
+#include "net/proxy/proxy_resolver_error_observer.h"
+#include "testing/gtest/include/gtest/gtest.h"
+
+namespace net {
+
+namespace {
+
+scoped_refptr<ProxyResolverScriptData> LoadData(const char* filename) {
+  FilePath path;
+  PathService::Get(base::DIR_SOURCE_ROOT, &path);
+  path = path.AppendASCII("net");
+  path = path.AppendASCII("data");
+  path = path.AppendASCII("proxy_resolver_v8_tracing_unittest");
+  path = path.AppendASCII(filename);
+
+  // Try to read the file from disk.
+  std::string file_contents;
+  bool ok = file_util::ReadFileToString(path, &file_contents);
+
+  // If we can't load the file from disk, something is misconfigured.
+  if (!ok)
+    LOG(ERROR) << "Failed to read file: " << path.value();
+  EXPECT_TRUE(ok);

[mmenke, 2013/01/18 19:59:40]

Can't you just do:

EXPECT_TRUE(ok) << "Failed to read file: " << path.value();

[eroman, 2013/01/23 03:26:02]

Done.

+
+  // Load the PAC script into the ProxyResolver.
+  return ProxyResolverScriptData::FromUTF8(file_contents);
+}
+
+std::string GetParamsJson(const CapturingNetLog::CapturedEntry& entry) {
+  if (!entry.params)
+    return std::string();
+  std::string json;
+  base::JSONWriter::Write(entry.params.get(), &json);
+  return json;
+}
+
+void InitResolver(ProxyResolverV8Tracing* resolver, const char* filename) {
+  TestCompletionCallback callback;
+  int rv =
+      resolver->SetPacScript(LoadData(filename), callback.callback());
+  EXPECT_EQ(ERR_IO_PENDING, rv);
+  EXPECT_EQ(OK, callback.WaitForResult());
+}
+
+class MockErrorObserver : public ProxyResolverErrorObserver {
+ public:
+  virtual void OnPACScriptError(int line_number,
+                                const string16& error) OVERRIDE {
+    output += StringPrintf("Error: line %d: %s\n", line_number,
+                           UTF16ToASCII(error).c_str());
+  }
+  std::string output;
+};
+
+TEST(ProxyResolverV8TracingTest, Simple) {
+  CapturingNetLog log;
+  CapturingBoundNetLog req_log;
+  MockHostResolver host_resolver;
+  MockErrorObserver* error_observer = new MockErrorObserver;
+  ProxyResolverV8Tracing resolver(&host_resolver, error_observer, &log);
+
+  InitResolver(&resolver, "simple.js");
+
+  TestCompletionCallback callback;
+  ProxyInfo proxy_info;
+
+  int rv = resolver.GetProxyForURL(
+      GURL("http://foo/"), &proxy_info, callback.callback(),
+      NULL, req_log.bound());
+
+  EXPECT_EQ(ERR_IO_PENDING, rv);
+  EXPECT_EQ(OK, callback.WaitForResult());
+
+  EXPECT_EQ("foo:99",
+            proxy_info.proxy_server().ToURI());
+
+  EXPECT_EQ(0u, host_resolver.num_resolve());
+  EXPECT_EQ(0u, host_resolver.num_resolve_from_cache());
+
+  // There were no errors.
+  EXPECT_EQ("", error_observer->output);
+
+  // Check the NetLogs -- nothing was logged.
+  EXPECT_EQ(0u, log.GetSize());
+  EXPECT_EQ(0u, req_log.GetSize());
+}
+
+TEST(ProxyResolverV8TracingTest, JavascriptError) {
+  CapturingNetLog log;
+  CapturingBoundNetLog req_log;
+  MockHostResolver host_resolver;
+  MockErrorObserver* error_observer = new MockErrorObserver;
+  ProxyResolverV8Tracing resolver(&host_resolver, error_observer, &log);
+
+  InitResolver(&resolver, "error.js");
+
+  TestCompletionCallback callback;
+  ProxyInfo proxy_info;
+
+  int rv = resolver.GetProxyForURL(
+      GURL("http://foo/"), &proxy_info, callback.callback(), NULL,
+      req_log.bound());
+
+  EXPECT_EQ(ERR_IO_PENDING, rv);
+  EXPECT_EQ(ERR_PAC_SCRIPT_FAILED, callback.WaitForResult());
+
+  EXPECT_EQ(0u, host_resolver.num_resolve());
+  EXPECT_EQ(0u, host_resolver.num_resolve_from_cache());
+
+  EXPECT_EQ("Error: line 3: Uncaught TypeError: Cannot call method 'split' "
+            "of null\n", error_observer->output);
+
+  // Check the NetLogs -- there was 1 javascript error, and it was output to
+  // both the global log, and per-request log.
+  CapturingNetLog::CapturedEntryList entries_list[2];
+  log.GetEntries(&entries_list[0]);
+  req_log.GetEntries(&entries_list[1]);
+
+  for (size_t list_i = 0; list_i < arraysize(entries_list); list_i++) {
+    const CapturingNetLog::CapturedEntryList& entries = entries_list[list_i];
+    EXPECT_EQ(1u, entries.size());
+    EXPECT_TRUE(
+        LogContainsEvent(entries, 0, NetLog::TYPE_PAC_JAVASCRIPT_ERROR,
+                         NetLog::PHASE_NONE));
+    EXPECT_EQ("{\"line_number\":3,\"message\":\"Uncaught TypeError: Cannot "
+              "call method 'split' of null\"}", GetParamsJson(entries[0]));
+  }
+}
+
+TEST(ProxyResolverV8TracingTest, TooManyAlerts) {
+  CapturingNetLog log;
+  CapturingBoundNetLog req_log;
+  MockHostResolver host_resolver;
+  MockErrorObserver* error_observer = new MockErrorObserver;
+  ProxyResolverV8Tracing resolver(&host_resolver, error_observer, &log);
+
+  InitResolver(&resolver, "too_many_alerts.js");
+
+  TestCompletionCallback callback;
+  ProxyInfo proxy_info;
+
+  int rv = resolver.GetProxyForURL(
+      GURL("http://foo/"),
+      &proxy_info,
+      callback.callback(),
+      NULL,
+      req_log.bound());
+
+  EXPECT_EQ(ERR_IO_PENDING, rv);
+  EXPECT_EQ(OK, callback.WaitForResult());
+
+  EXPECT_EQ("foo:99",
+            proxy_info.proxy_server().ToURI());
+
+  EXPECT_EQ(1u, host_resolver.num_resolve());
+  EXPECT_EQ(1u, host_resolver.num_resolve_from_cache());
+
+  // No errors.
+  EXPECT_EQ("", error_observer->output);
+
+  // Check the NetLogs -- the script generated 50 alerts, which were mirrored
+  // to both the global and per-request logs.
+  CapturingNetLog::CapturedEntryList entries_list[2];
+  log.GetEntries(&entries_list[0]);
+  req_log.GetEntries(&entries_list[1]);
+
+  for (size_t list_i = 0; list_i < arraysize(entries_list); list_i++) {
+    const CapturingNetLog::CapturedEntryList& entries = entries_list[list_i];
+    EXPECT_EQ(50u, entries.size());
+    for (size_t i = 0; i < 50u; ++i) {
+      EXPECT_TRUE(
+          LogContainsEvent(entries, i, NetLog::TYPE_PAC_JAVASCRIPT_ALERT,
+                           NetLog::PHASE_NONE));
+    }
+  }
+}
+
+// This test runs a PAC script that issues a sequence of DNS resolves. The test
+// verifies the final result, and that the underlying DNS resolver received
+// the correct set of queries.
+TEST(ProxyResolverV8TracingTest, Dns) {
+  CapturingNetLog log;
+  CapturingBoundNetLog req_log;
+  MockHostResolver host_resolver;
+  MockErrorObserver* error_observer = new MockErrorObserver;
+  ProxyResolverV8Tracing resolver(&host_resolver, error_observer, &log);
+
+  host_resolver.rules()->AddRule("host1", "166.155.144.11");
+  host_resolver.rules()->AddSimulatedFailure("host2");
+  host_resolver.rules()->AddRule("host3", "166.155.144.33");
+  host_resolver.rules()->AddRule("host4", "166.155.144.44");
+  host_resolver.rules()->AddRule("host5", "166.155.144.55");
+  host_resolver.rules()->AddRule("*", "122.133.144.155");
+
+  InitResolver(&resolver, "dns.js");
+
+  TestCompletionCallback callback;
+  ProxyInfo proxy_info;
+
+  int rv = resolver.GetProxyForURL(
+      GURL("http://foo/"),
+      &proxy_info,
+      callback.callback(),
+      NULL,
+      req_log.bound());
+
+  EXPECT_EQ(ERR_IO_PENDING, rv);
+  EXPECT_EQ(OK, callback.WaitForResult());
+
+  // The test does 11 DNS resolution, however only 5 of them are unique.
+  EXPECT_EQ(5u, host_resolver.num_resolve());
+  EXPECT_EQ(5u, host_resolver.num_resolve_from_cache());
+
+  const char* kExpectedResult =
+    "122.133.144.155-"  // myIpAddress()
+    "null-"  // dnsResolve('')
+    "166.155.144.11-"  // dnsResolve('host1')
+    "null-"  // dnsResolve('host2')
+    "166.155.144.33-"  // dnsResolve('host3')
+    "122.133.144.155-"  // myIpAddress()
+    "166.155.144.33-"  // dnsResolve('host3')
+    "166.155.144.11-"  // dnsResolve('host1')
+    "122.133.144.155-"  // myIpAddress()
+    "null-"  // dnsResolve('host2')
+    "166.155.144.44"  // dnsResolve('host4')
+    ":99";
+
+  EXPECT_EQ(kExpectedResult, proxy_info.proxy_server().ToURI());
+
+  // No errors.
+  EXPECT_EQ("", error_observer->output);
+
+  // Check the NetLogs -- the script generated 1 alert, mirrored to both
+  // the per-request and global logs.
+  CapturingNetLog::CapturedEntryList entries_list[2];
+  log.GetEntries(&entries_list[0]);
+  req_log.GetEntries(&entries_list[1]);
+
+  for (size_t list_i = 0; list_i < arraysize(entries_list); list_i++) {
+    const CapturingNetLog::CapturedEntryList& entries = entries_list[list_i];
+    EXPECT_EQ(1u, entries.size());
+    EXPECT_TRUE(
+        LogContainsEvent(entries, 0, NetLog::TYPE_PAC_JAVASCRIPT_ALERT,
+                         NetLog::PHASE_NONE));
+    EXPECT_EQ("{\"message\":\"iteration: 5\"}", GetParamsJson(entries[0]));
+  }
+}
+
+// This test runs a weird PAC script that was designed to defeat the DNS tracing
+// optimization. The proxy resolver should detect the inconsistency and
+// fall-back to synchronous mode execution.
+TEST(ProxyResolverV8TracingTest, FallBackToSynchronous1) {
+  CapturingNetLog log;
+  CapturingBoundNetLog req_log;
+  MockHostResolver host_resolver;
+  MockErrorObserver* error_observer = new MockErrorObserver;
+  ProxyResolverV8Tracing resolver(&host_resolver, error_observer, &log);
+
+  host_resolver.rules()->AddRule("host1", "166.155.144.11");
+  host_resolver.rules()->AddRule("crazy4", "133.199.111.4");
+  host_resolver.rules()->AddRule("*", "122.133.144.155");
+
+  InitResolver(&resolver, "global_sideffects1.js");
+
+  TestCompletionCallback callback;
+  ProxyInfo proxy_info;
+
+  int rv = resolver.GetProxyForURL(GURL("http://foo/"), &proxy_info,
+                                   callback.callback(), NULL, req_log.bound());
+  EXPECT_EQ(ERR_IO_PENDING, rv);
+  EXPECT_EQ(OK, callback.WaitForResult());
+
+  // The script itself only does 2 DNS resolves, however it constructs the
+  // hostname using a global counter which changes on each invocation.
+  EXPECT_EQ(3u, host_resolver.num_resolve());
+  EXPECT_EQ(2u, host_resolver.num_resolve_from_cache());
+
+  EXPECT_EQ("166.155.144.11-133.199.111.4:100",
+            proxy_info.proxy_server().ToURI());
+
+  // No errors.
+  EXPECT_EQ("", error_observer->output);
+
+  // Check the NetLogs -- the script generated 1 alert, mirrored to both
+  // the per-request and global logs.
+  CapturingNetLog::CapturedEntryList entries_list[2];
+  log.GetEntries(&entries_list[0]);
+  req_log.GetEntries(&entries_list[1]);
+
+  for (size_t list_i = 0; list_i < arraysize(entries_list); list_i++) {
+    const CapturingNetLog::CapturedEntryList& entries = entries_list[list_i];
+    EXPECT_EQ(1u, entries.size());
+    EXPECT_TRUE(
+        LogContainsEvent(entries, 0, NetLog::TYPE_PAC_JAVASCRIPT_ALERT,
+                         NetLog::PHASE_NONE));
+    EXPECT_EQ("{\"message\":\"iteration: 4\"}", GetParamsJson(entries[0]));
+  }
+}
+
+// This test runs a weird PAC script that was designed to defeat the DNS tracing
+// optimization. The proxy resolver should detect the inconsistency and
+// fall-back to synchronous mode execution.
+TEST(ProxyResolverV8TracingTest, FallBackToSynchronous2) {
+  CapturingNetLog log;
+  CapturingBoundNetLog req_log;
+  MockHostResolver host_resolver;
+  MockErrorObserver* error_observer = new MockErrorObserver;
+  ProxyResolverV8Tracing resolver(&host_resolver, error_observer, &log);
+
+  host_resolver.rules()->AddRule("host1", "166.155.144.11");
+  host_resolver.rules()->AddRule("host2", "166.155.144.22");
+  host_resolver.rules()->AddRule("host3", "166.155.144.33");
+  host_resolver.rules()->AddRule("host4", "166.155.144.44");
+  host_resolver.rules()->AddRule("*", "122.133.144.155");
+
+  InitResolver(&resolver, "global_sideffects2.js");
+
+  TestCompletionCallback callback;
+  ProxyInfo proxy_info;
+
+  int rv = resolver.GetProxyForURL(GURL("http://foo/"), &proxy_info,
+                                   callback.callback(), NULL, req_log.bound());
+  EXPECT_EQ(ERR_IO_PENDING, rv);
+  EXPECT_EQ(OK, callback.WaitForResult());
+
+  EXPECT_EQ(3u, host_resolver.num_resolve());
+  EXPECT_EQ(2u, host_resolver.num_resolve_from_cache());
+
+  EXPECT_EQ("166.155.144.44:100",
+            proxy_info.proxy_server().ToURI());
+
+  // No errors.
+  EXPECT_EQ("", error_observer->output);
+
+  // Check the NetLogs -- nothing was logged.
+  EXPECT_EQ(0u, log.GetSize());
+  EXPECT_EQ(0u, req_log.GetSize());
+}
+
+// Tests a PAC script which does DNS resolves during initialization.
+TEST(ProxyResolverV8TracingTest, DnsDuringInit) {
+  CapturingNetLog log;
+  CapturingBoundNetLog req_log;
+  MockHostResolver host_resolver;
+  MockErrorObserver* error_observer = new MockErrorObserver;
+  ProxyResolverV8Tracing resolver(&host_resolver, error_observer, &log);
+
+  host_resolver.rules()->AddRule("host1", "91.13.12.1");
+  host_resolver.rules()->AddRule("host2", "91.13.12.2");
+
+  InitResolver(&resolver, "dns_during_init.js");
+
+  // Initialization did 2 dnsResolves.
+  EXPECT_EQ(2u, host_resolver.num_resolve());
+  EXPECT_EQ(0u, host_resolver.num_resolve_from_cache());
+
+  host_resolver.rules()->ClearRules();
+
+  host_resolver.rules()->AddRule("host1", "145.88.13.3");
+  host_resolver.rules()->AddRule("host2", "137.89.8.45");
+
+  TestCompletionCallback callback;
+  ProxyInfo proxy_info;
+
+  int rv = resolver.GetProxyForURL(GURL("http://foo/"), &proxy_info,
+                                   callback.callback(), NULL, req_log.bound());
+  EXPECT_EQ(ERR_IO_PENDING, rv);
+  EXPECT_EQ(OK, callback.WaitForResult());
+
+  // Fetched host1 and host2 again, since the ones done during initialization
+  // should not have been cached.
+  EXPECT_EQ(4u, host_resolver.num_resolve());
+
+  EXPECT_EQ("91.13.12.1-91.13.12.2-145.88.13.3-137.89.8.45:99",
+            proxy_info.proxy_server().ToURI());
+
+  // Check the NetLogs -- the script generated 2 alerts during initialization.
+  EXPECT_EQ(0u, req_log.GetSize());
+  CapturingNetLog::CapturedEntryList entries;
+  log.GetEntries(&entries);
+
+  ASSERT_EQ(2u, entries.size());
+  EXPECT_TRUE(
+      LogContainsEvent(entries, 0, NetLog::TYPE_PAC_JAVASCRIPT_ALERT,
+                       NetLog::PHASE_NONE));
+  EXPECT_TRUE(
+      LogContainsEvent(entries, 1, NetLog::TYPE_PAC_JAVASCRIPT_ALERT,
+                       NetLog::PHASE_NONE));
+
+  EXPECT_EQ("{\"message\":\"Watsup\"}", GetParamsJson(entries[0]));
+  EXPECT_EQ("{\"message\":\"Watsup2\"}", GetParamsJson(entries[1]));
+}
+
+void CrashCallback(int) {
+  // Be extra sure that if the callback ever gets invoked, the test will fail.
+  CHECK(false);
+}
+
+// Start some requests, cancel them all, and then destroy the resolver.
+// Note the execution order for this test can vary. Since multiple
+// threads are involved, the cancellation may be received a different
+// times.
+TEST(ProxyResolverV8TracingTest, CancelAll) {
+  MockHostResolver host_resolver;
+  MockErrorObserver* error_observer = new MockErrorObserver;
+  ProxyResolverV8Tracing resolver(&host_resolver, error_observer, NULL);
+
+  host_resolver.rules()->AddSimulatedFailure("*");
+
+  InitResolver(&resolver, "dns.js");
+
+  const size_t kNumRequests = 5;
+  ProxyInfo proxy_info[kNumRequests];
+  ProxyResolver::RequestHandle request[kNumRequests];
+
+  for (size_t i = 0; i < kNumRequests; ++i) {
+    int rv = resolver.GetProxyForURL(
+        GURL("http://foo/"), &proxy_info[i],
+        base::Bind(&CrashCallback), &request[i], BoundNetLog());
+    EXPECT_EQ(ERR_IO_PENDING, rv);
+  }
+
+  for (size_t i = 0; i < kNumRequests; ++i) {
+    resolver.CancelRequest(request[i]);
+  }
+}
+
+// Note the execution order for this test can vary. Since multiple
+// threads are involved, the cancellation may be received a different
+// times.
+TEST(ProxyResolverV8TracingTest, CancelSome) {
+  MockHostResolver host_resolver;
+  MockErrorObserver* error_observer = new MockErrorObserver;
+  ProxyResolverV8Tracing resolver(&host_resolver, error_observer, NULL);
+
+  host_resolver.rules()->AddSimulatedFailure("*");
+
+  InitResolver(&resolver, "dns.js");
+
+  ProxyInfo proxy_info1;
+  ProxyInfo proxy_info2;
+  ProxyResolver::RequestHandle request1;
+  ProxyResolver::RequestHandle request2;
+  TestCompletionCallback callback;
+
+  int rv = resolver.GetProxyForURL(
+      GURL("http://foo/"), &proxy_info1,
+      base::Bind(&CrashCallback), &request1, BoundNetLog());
+
+  rv = resolver.GetProxyForURL(
+      GURL("http://foo/"), &proxy_info2,
+      callback.callback(), &request2, BoundNetLog());
+  EXPECT_EQ(ERR_IO_PENDING, rv);
+
+  resolver.CancelRequest(request1);
+
+  EXPECT_EQ(OK, callback.WaitForResult());
+}
+
+// This implementation of HostResolver allows blocking until a resolve request
+// has been received. The resolve requests it receives will never be completed.
+class BlockableHostResolver : public HostResolver {
+ public:
+  BlockableHostResolver()
+      : was_request_cancelled_(false) {
+  }
+
+  virtual int Resolve(const RequestInfo& info,
+                      AddressList* addresses,
+                      const CompletionCallback& callback,
+                      RequestHandle* out_req,
+                      const BoundNetLog& net_log) OVERRIDE {
+    EXPECT_FALSE(callback.is_null());
+    EXPECT_TRUE(out_req);
+    *out_req = reinterpret_cast<RequestHandle*>(1);  // Magic value.
+
+    // Indicate to the caller that a request was received.
+    MessageLoop::current()->Quit();
+
+    // Return ERR_IO_PENDING as this request will NEVER be completed.
+    // Expectation is for the caller to later cancel the request.
+    return ERR_IO_PENDING;
+  }
+
+  virtual int ResolveFromCache(const RequestInfo& info,
+                               AddressList* addresses,
+                               const BoundNetLog& net_log) OVERRIDE {
+    return ERR_DNS_CACHE_MISS;
+  }
+
+  virtual void CancelRequest(RequestHandle req) OVERRIDE {
+    EXPECT_EQ(reinterpret_cast<RequestHandle*>(1), req);
+    was_request_cancelled_ = true;
+  }
+
+  // Waits until Resolve() has been called.
+  void WaitUntilRequestIsReceived() {
+    MessageLoop::current()->Run();
+  }
+
+  bool was_request_cancelled() const {
+    return was_request_cancelled_;
+  }
+
+ private:
+  bool was_request_cancelled_;
+};
+
+// This cancellation test exercises a more predictable cancellation codepath --
+// when the request has an outstanding DNS request in flight.
+TEST(ProxyResolverV8TracingTest, CancelWhileOutstandingNonBlockingDns) {
+  BlockableHostResolver host_resolver;
+  MockErrorObserver* error_observer = new MockErrorObserver;
+  ProxyResolverV8Tracing resolver(&host_resolver, error_observer, NULL);
+
+  InitResolver(&resolver, "dns.js");
+
+  ProxyInfo proxy_info;
+  ProxyResolver::RequestHandle request;
+
+  int rv = resolver.GetProxyForURL(
+      GURL("http://foo/"), &proxy_info,
+      base::Bind(&CrashCallback), &request, BoundNetLog());
+
+  EXPECT_EQ(ERR_IO_PENDING, rv);
+
+  host_resolver.WaitUntilRequestIsReceived();
+
+  resolver.CancelRequest(request);
+
+  EXPECT_TRUE(host_resolver.was_request_cancelled());
+
+  // After leaving this scope, the ProxyResolver is destroyed.
+  // This should not cause any problems, as the outstanding work
+  // should have been cancelled.
+}
+
+TEST(ProxyResolverV8TracingTest, CancelWhileOutstandingBlockingDns) {
+  BlockableHostResolver host_resolver;
+  MockErrorObserver* error_observer = new MockErrorObserver;
+
+  ProxyResolverV8Tracing resolver(&host_resolver, error_observer, NULL);
+
+  int rv =
+      resolver.SetPacScript(LoadData("dns_during_init.js"),
+      base::Bind(&CrashCallback));
+  EXPECT_EQ(ERR_IO_PENDING, rv);
+
+  host_resolver.WaitUntilRequestIsReceived();
+
+  resolver.CancelSetPacScript();
+  EXPECT_TRUE(host_resolver.was_request_cancelled());
+}
+
+}  // namespace
+
+}  // namespace net