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/host_cache.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> LoadScriptData(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.
+  EXPECT_TRUE(ok) << "Failed to read file: " << path.value();
+
+  // Load the PAC script into the ProxyResolver.
+  return ProxyResolverScriptData::FromUTF8(file_contents);
+}
+
+std::string GetParamsJson(const CapturingNetLog::CapturedEntry& entry) {

[mmenke, 2013/01/29 20:19:08]

Worth making this a method of CapturingNetLog::CapturedEntry?

[eroman, 2013/01/29 22:51:23]

Done.

+  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(LoadScriptData(filename), callback.callback());
+  EXPECT_EQ(ERR_IO_PENDING, rv);
+  EXPECT_EQ(OK, callback.WaitForResult());
+}
+
+class MockErrorObserver : public ProxyResolverErrorObserver {
+ public:
+  MockErrorObserver() : event_(true, false) {}
+
+  virtual void OnPACScriptError(int line_number,
+                                const string16& error) OVERRIDE {
+    {
+      base::AutoLock l(lock_);
+      output += StringPrintf("Error: line %d: %s\n", line_number,
+                             UTF16ToASCII(error).c_str());
+    }
+    event_.Signal();
+  }
+
+  std::string GetOutput() {
+    base::AutoLock l(lock_);
+    return output;
+  }
+
+  void WaitForOutput() {
+    event_.Wait();
+  }
+
+ private:
+  base::Lock lock_;
+  std::string output;
+
+  base::WaitableEvent event_;
+};
+
+TEST(ProxyResolverV8TracingTest, Simple) {
+  CapturingNetLog log;
+  CapturingBoundNetLog request_log;
+  MockCachingHostResolver 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, request_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->GetOutput());
+
+  // Check the NetLogs -- nothing was logged.
+  EXPECT_EQ(0u, log.GetSize());
+  EXPECT_EQ(0u, request_log.GetSize());
+}
+
+TEST(ProxyResolverV8TracingTest, JavascriptError) {
+  CapturingNetLog log;
+  CapturingBoundNetLog request_log;
+  MockCachingHostResolver 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://throw-an-error/"), &proxy_info, callback.callback(), NULL,
+      request_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 5: Uncaught TypeError: Cannot call method 'split' "
+            "of null\n", error_observer->GetOutput());

[mmenke, 2013/01/29 20:19:08]

Should we be depending on the exact v8 error string in net/?

[eroman, 2013/01/29 22:51:23]

If it turns into a maintenance problem I can generalize the test, however I
don't anticipate these changing any time soon.

(The ProxyResolverV8 unittests already hardcode some error strings, and those
have not had to be changed in years.)

[mmenke, 2013/01/29 23:10:31]

SGTM.

+
+  // Check the NetLogs -- there was 1 alert and 1 javascript error, and they
+  // were output to both the global log, and per-request log.
+  CapturingNetLog::CapturedEntryList entries_list[2];
+  log.GetEntries(&entries_list[0]);
+  request_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(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_ERROR,
+                         NetLog::PHASE_NONE));
+
+    EXPECT_EQ("{\"message\":\"Prepare to DIE!\"}", GetParamsJson(entries[0]));
+    EXPECT_EQ("{\"line_number\":5,\"message\":\"Uncaught TypeError: Cannot "
+              "call method 'split' of null\"}", GetParamsJson(entries[1]));
+  }
+}
+
+TEST(ProxyResolverV8TracingTest, TooManyAlerts) {
+  CapturingNetLog log;
+  CapturingBoundNetLog request_log;
+  MockCachingHostResolver 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,
+      request_log.bound());
+
+  EXPECT_EQ(ERR_IO_PENDING, rv);
+  EXPECT_EQ(OK, callback.WaitForResult());
+
+  EXPECT_EQ("foo:3", proxy_info.proxy_server().ToURI());

[mmenke, 2013/01/29 20:19:08]

Think it's worth a comment that iteration 1 does a DNS lookup, 2 runs into the
issue with two many alerts, and the third blocking iteration is the one that
returns the results.

[eroman, 2013/01/29 22:51:23]

Done.

+
+  EXPECT_EQ(1u, host_resolver.num_resolve());
+  EXPECT_EQ(0u, host_resolver.num_resolve_from_cache());
+
+  // No errors.
+  EXPECT_EQ("", error_observer->GetOutput());
+
+  // 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]);
+  request_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 < entries.size(); ++i) {
+      EXPECT_TRUE(
+          LogContainsEvent(entries, i, NetLog::TYPE_PAC_JAVASCRIPT_ALERT,
+                           NetLog::PHASE_NONE));
+    }
+  }
+}
+
+// Verify that buffered alerts cannot grow unboundedly, even when the message is
+// empty string.
+TEST(ProxyResolverV8TracingTest, TooManyEmptyAlerts) {
+  CapturingNetLog log;
+  CapturingBoundNetLog request_log;
+  MockCachingHostResolver host_resolver;
+  MockErrorObserver* error_observer = new MockErrorObserver;
+  ProxyResolverV8Tracing resolver(&host_resolver, error_observer, &log);
+
+  InitResolver(&resolver, "too_many_empty_alerts.js");
+
+  TestCompletionCallback callback;
+  ProxyInfo proxy_info;
+
+  int rv = resolver.GetProxyForURL(
+      GURL("http://foo/"),
+      &proxy_info,
+      callback.callback(),
+      NULL,
+      request_log.bound());
+
+  EXPECT_EQ(ERR_IO_PENDING, rv);
+  EXPECT_EQ(OK, callback.WaitForResult());
+
+  EXPECT_EQ("foo:3", proxy_info.proxy_server().ToURI());
+
+  EXPECT_EQ(1u, host_resolver.num_resolve());
+  EXPECT_EQ(0u, host_resolver.num_resolve_from_cache());
+
+  // No errors.
+  EXPECT_EQ("", error_observer->GetOutput());
+
+  // 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]);
+  request_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(1000u, entries.size());
+    for (size_t i = 0; i < entries.size(); ++i) {
+      EXPECT_TRUE(

[mmenke, 2013/01/29 20:19:08]

I can just imagine this test spewing 2000 lines of garbage.

[eroman, 2013/01/29 22:51:23]

Lulz. Changed to ASSERT_TRUE() instead

+          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 request_log;
+  MockCachingHostResolver 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,
+      request_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(0u, 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->GetOutput());
+
+  // 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]);
+  request_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 PAC script that does "myIpAddress()" followed by
+// "dnsResolve()". This requires 2 restarts. However once the HostResolver's
+// cache is warmed, subsequent calls should take 0 restarts.
+TEST(ProxyResolverV8TracingTest, DnsChecksCache) {
+  CapturingNetLog log;
+  CapturingBoundNetLog request_log;
+  MockCachingHostResolver host_resolver;
+  MockErrorObserver* error_observer = new MockErrorObserver;
+  ProxyResolverV8Tracing resolver(&host_resolver, error_observer, &log);
+
+  host_resolver.rules()->AddRule("foopy", "166.155.144.11");
+  host_resolver.rules()->AddRule("*", "122.133.144.155");
+
+  InitResolver(&resolver, "simple_dns.js");
+
+  TestCompletionCallback callback1;
+  TestCompletionCallback callback2;
+  ProxyInfo proxy_info;
+
+  int rv = resolver.GetProxyForURL(
+      GURL("http://foopy/req1"),
+      &proxy_info,
+      callback1.callback(),
+      NULL,
+      request_log.bound());
+
+  EXPECT_EQ(ERR_IO_PENDING, rv);
+  EXPECT_EQ(OK, callback1.WaitForResult());
+
+  // The test does 2 DNS resolutions.
+  EXPECT_EQ(2u, host_resolver.num_resolve());
+  EXPECT_EQ(0u, host_resolver.num_resolve_from_cache());
+
+  // The first request took 2 restarts, hence on g_iteration=3.
+  EXPECT_EQ("166.155.144.11:3", proxy_info.proxy_server().ToURI());
+
+  rv = resolver.GetProxyForURL(
+      GURL("http://foopy/req2"),
+      &proxy_info,
+      callback2.callback(),
+      NULL,
+      request_log.bound());
+
+  EXPECT_EQ(ERR_IO_PENDING, rv);
+  EXPECT_EQ(OK, callback2.WaitForResult());
+
+  EXPECT_EQ(4u, host_resolver.num_resolve());
+  EXPECT_EQ(0u, host_resolver.num_resolve_from_cache());

[mmenke, 2013/01/29 20:19:08]

Think it's worth a note that this is only incremented on cache only resolutions.
 Alternatively, could just remove all the calls to num_resolve_from_cache in
this file.

[eroman, 2013/01/29 22:51:23]

Done.

+
+  // This time no restarts were required, so g_iteration incremented by 1.
+  EXPECT_EQ("166.155.144.11:4", proxy_info.proxy_server().ToURI());
+
+  // No errors.
+  EXPECT_EQ("", error_observer->GetOutput());
+
+  EXPECT_EQ(0u, log.GetSize());
+  EXPECT_EQ(0u, request_log.GetSize());
+}
+
+// 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 request_log;
+  MockCachingHostResolver 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,
+      request_log.bound());
+  EXPECT_EQ(ERR_IO_PENDING, rv);
+  EXPECT_EQ(OK, callback.WaitForResult());
+
+  // The script itself only does 2 DNS resolves per execution, however it
+  // constructs the hostname using a global counter which changes on each
+  // invocation.
+  EXPECT_EQ(3u, host_resolver.num_resolve());
+  EXPECT_EQ(0u, 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->GetOutput());
+
+  // 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]);
+  request_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 request_log;
+  MockCachingHostResolver 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,
+      request_log.bound());
+  EXPECT_EQ(ERR_IO_PENDING, rv);
+  EXPECT_EQ(OK, callback.WaitForResult());
+
+  EXPECT_EQ(3u, host_resolver.num_resolve());
+  EXPECT_EQ(0u, host_resolver.num_resolve_from_cache());
+
+  EXPECT_EQ("166.155.144.44:100", proxy_info.proxy_server().ToURI());
+
+  // No errors.
+  EXPECT_EQ("", error_observer->GetOutput());
+
+  // Check the NetLogs -- nothing was logged.
+  EXPECT_EQ(0u, log.GetSize());
+  EXPECT_EQ(0u, request_log.GetSize());
+}
+
+// This test runs a weird PAC script that yields a never ending sequence
+// of DNS resolves when restarting. Running it will hit the maximum
+// DNS resolves per request limit (20) after which every DNS resolve will
+// fail.
+TEST(ProxyResolverV8TracingTest, InfiniteDNSSequence) {

[mmenke, 2013/01/29 20:19:08]

Suggest modifying this to make sure the first 20 dnsResolves were correctly
accessed from the cache.  Just count the non-NULL results in the loop and use it
as the port or something.

Not something that I think is terribly likely to regress without setting off
other failures, but I'm paranoid.

[eroman, 2013/01/29 22:51:23]

Done. I admire your paranoia.

+  CapturingNetLog log;
+  CapturingBoundNetLog request_log;
+  MockCachingHostResolver host_resolver;
+  MockErrorObserver* error_observer = new MockErrorObserver;
+  ProxyResolverV8Tracing resolver(&host_resolver, error_observer, &log);
+
+  host_resolver.rules()->AddRule("host*", "166.155.144.11");
+  host_resolver.rules()->AddRule("*", "122.133.144.155");
+
+  InitResolver(&resolver, "global_sideffects3.js");
+
+  TestCompletionCallback callback;
+  ProxyInfo proxy_info;
+
+  int rv = resolver.GetProxyForURL(
+      GURL("http://foo/"), &proxy_info, callback.callback(), NULL,
+      request_log.bound());
+  EXPECT_EQ(ERR_IO_PENDING, rv);
+  EXPECT_EQ(OK, callback.WaitForResult());
+
+  EXPECT_EQ(20u, host_resolver.num_resolve());
+  EXPECT_EQ(0u, host_resolver.num_resolve_from_cache());
+
+  EXPECT_EQ("null21:97", proxy_info.proxy_server().ToURI());
+
+  // No errors.
+  EXPECT_EQ("", error_observer->GetOutput());
+
+  // Check the NetLogs -- 1 alert was logged.
+  EXPECT_EQ(1u, log.GetSize());
+  EXPECT_EQ(1u, request_log.GetSize());
+}
+
+// This test runs a weird PAC script that yields a never ending sequence
+// of DNS resolves when restarting. Running it will hit the maximum
+// DNS resolves per request limit (20) after which every DNS resolve will
+// fail.
+TEST(ProxyResolverV8TracingTest, InfiniteDNSSequence2) {
+  CapturingNetLog log;
+  CapturingBoundNetLog request_log;
+  MockCachingHostResolver host_resolver;
+  MockErrorObserver* error_observer = new MockErrorObserver;
+  ProxyResolverV8Tracing resolver(&host_resolver, error_observer, &log);
+
+  host_resolver.rules()->AddRule("host*", "166.155.144.11");
+  host_resolver.rules()->AddRule("*", "122.133.144.155");
+
+  InitResolver(&resolver, "global_sideffects4.js");
+
+  TestCompletionCallback callback;
+  ProxyInfo proxy_info;
+
+  int rv = resolver.GetProxyForURL(
+      GURL("http://foo/"), &proxy_info, callback.callback(), NULL,
+      request_log.bound());
+  EXPECT_EQ(ERR_IO_PENDING, rv);
+  EXPECT_EQ(OK, callback.WaitForResult());
+
+  EXPECT_EQ(20u, host_resolver.num_resolve());
+  EXPECT_EQ(0u, host_resolver.num_resolve_from_cache());
+
+  EXPECT_EQ("null21:34", proxy_info.proxy_server().ToURI());
+
+  // No errors.
+  EXPECT_EQ("", error_observer->GetOutput());
+
+  // Check the NetLogs -- 1 alert was logged.
+  EXPECT_EQ(1u, log.GetSize());
+  EXPECT_EQ(1u, request_log.GetSize());
+}
+
+// Tests a PAC script which does DNS resolves during initialization.
+TEST(ProxyResolverV8TracingTest, DnsDuringInit) {
+  CapturingNetLog log;
+  CapturingBoundNetLog request_log;
+  MockCachingHostResolver 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.GetHostCache()->clear();
+
+  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,
+      request_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, request_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) {
+  MockCachingHostResolver 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) {
+  MockCachingHostResolver 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());
+  EXPECT_EQ(ERR_IO_PENDING, rv);
+
+  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());
+}
+
+// Cancel a request after it has finished running on the worker thread, and has
+// posted a task the completion task back to origin thread.
+TEST(ProxyResolverV8TracingTest, CancelWhilePendingCompletionTask) {
+  MockCachingHostResolver host_resolver;
+  MockErrorObserver* error_observer = new MockErrorObserver;
+  ProxyResolverV8Tracing resolver(&host_resolver, error_observer, NULL);
+
+  host_resolver.rules()->AddSimulatedFailure("*");
+
+  InitResolver(&resolver, "error.js");
+
+  ProxyInfo proxy_info1;
+  ProxyInfo proxy_info2;
+  ProxyInfo proxy_info3;
+  ProxyResolver::RequestHandle request1;
+  ProxyResolver::RequestHandle request2;
+  ProxyResolver::RequestHandle request3;
+  TestCompletionCallback callback;
+
+  int rv = resolver.GetProxyForURL(
+      GURL("http://foo/"), &proxy_info1,
+      base::Bind(&CrashCallback), &request1, BoundNetLog());
+  EXPECT_EQ(ERR_IO_PENDING, rv);
+
+  rv = resolver.GetProxyForURL(
+      GURL("http://throw-an-error/"), &proxy_info2,
+      callback.callback(), &request2, BoundNetLog());
+  EXPECT_EQ(ERR_IO_PENDING, rv);
+
+  // Wait until the first request has finished running on the worker thread.
+  // (The second request will output an error).
+  error_observer->WaitForOutput();
+
+  // Cancel the first request, while it has a pending completion task on
+  // the origin thread.
+  resolver.CancelRequest(request1);
+
+  EXPECT_EQ(ERR_PAC_SCRIPT_FAILED, callback.WaitForResult());
+
+  // Start another request, to make sure it is able to complete.
+  rv = resolver.GetProxyForURL(
+      GURL("http://i-have-no-idea-what-im-doing/"), &proxy_info3,
+      callback.callback(), &request3, BoundNetLog());
+  EXPECT_EQ(ERR_IO_PENDING, rv);
+
+  EXPECT_EQ(OK, callback.WaitForResult());
+
+  EXPECT_EQ("i-approve-this-message:42",
+            proxy_info3.proxy_server().ToURI());
+}
+
+// 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() : num_cancelled_requests_(0) {}
+
+  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.
+
+    if (!action_.is_null())
+      action_.Run();
+
+    // Indicate to the caller that a request was received.
+    MessageLoop::current()->Quit();

[mmenke, 2013/01/29 20:19:08]

Call me paranoid, but can we either ASSERT / CHECK that we're in
WaitUntilREquestIsReceived here, or not quit if we aren't?

[eroman, 2013/01/29 22:51:23]

Done.

+
+    // 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 {
+    NOTREACHED();
+    return ERR_DNS_CACHE_MISS;
+  }
+
+  virtual void CancelRequest(RequestHandle req) OVERRIDE {
+    EXPECT_EQ(reinterpret_cast<RequestHandle*>(1), req);
+    num_cancelled_requests_++;
+  }
+
+  void SetAction(const base::Callback<void(void)>& action) {
+    action_ = action;
+  }
+
+  // Waits until Resolve() has been called.
+  void WaitUntilRequestIsReceived() {
+    MessageLoop::current()->Run();
+  }
+
+  int num_cancelled_requests() const {
+    return num_cancelled_requests_;
+  }
+
+ private:
+  int num_cancelled_requests_;
+  base::Callback<void(void)> action_;
+};
+
+// 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_info1;
+  ProxyInfo proxy_info2;
+  ProxyResolver::RequestHandle request1;
+  ProxyResolver::RequestHandle request2;
+
+  int rv = resolver.GetProxyForURL(
+      GURL("http://foo/req1"), &proxy_info1,
+      base::Bind(&CrashCallback), &request1, BoundNetLog());
+
+  EXPECT_EQ(ERR_IO_PENDING, rv);
+
+  host_resolver.WaitUntilRequestIsReceived();
+
+  rv = resolver.GetProxyForURL(
+      GURL("http://foo/req2"), &proxy_info2,
+      base::Bind(&CrashCallback), &request2, BoundNetLog());
+
+  EXPECT_EQ(ERR_IO_PENDING, rv);
+
+  host_resolver.WaitUntilRequestIsReceived();
+
+  resolver.CancelRequest(request1);
+  resolver.CancelRequest(request2);
+
+  EXPECT_EQ(2, host_resolver.num_cancelled_requests());
+
+  // After leaving this scope, the ProxyResolver is destroyed.
+  // This should not cause any problems, as the outstanding work
+  // should have been cancelled.
+}
+
+// In non-blocking mode, the worker thread actually does block for
+// a short time to see if the result is in the DNS cache. Test
+// cancellation while the worker thread is waiting on this event.
+TEST(ProxyResolverV8TracingTest, CancelWhileBlockedInNonBlockingDns) {
+  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.SetAction(base::Bind(&ProxyResolverV8Tracing::CancelRequest,
+                                     base::Unretained(&resolver), request));
+
+  host_resolver.WaitUntilRequestIsReceived();
+
+  // At this point the host resolver ran Resolve(), and should have cancelled
+  // the request.
+
+  EXPECT_EQ(1, host_resolver.num_cancelled_requests());
+}
+
+// Cancel the request while there is a pending DNS request, however before
+// the request is sent to the host resolver.
+TEST(ProxyResolverV8TracingTest, CancelWhileBlockedInNonBlockingDns2) {
+  MockCachingHostResolver 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);
+
+  // Wait a bit, so the DNS task has hopefully been posted. The test will
+  // work whatever the delay is here, but it is most useful if the delay
+  // is large enough to allow a task to be posted back.
+  base::PlatformThread::Sleep(base::TimeDelta::FromMilliseconds(10));
+  resolver.CancelRequest(request);
+
+  EXPECT_EQ(0u, host_resolver.num_resolve());
+}
+
+TEST(ProxyResolverV8TracingTest, CancelWhileOutstandingBlockingDns) {

[mmenke, 2013/01/29 20:19:08]

CancelSetPacWhile...?

All the others cancel a normal job.

[eroman, 2013/01/29 22:51:23]

Done.

+  BlockableHostResolver host_resolver;
+  MockErrorObserver* error_observer = new MockErrorObserver;
+
+  ProxyResolverV8Tracing resolver(&host_resolver, error_observer, NULL);
+
+  int rv =
+      resolver.SetPacScript(LoadScriptData("dns_during_init.js"),
+      base::Bind(&CrashCallback));
+  EXPECT_EQ(ERR_IO_PENDING, rv);
+
+  host_resolver.WaitUntilRequestIsReceived();
+
+  resolver.CancelSetPacScript();
+  EXPECT_EQ(1, host_resolver.num_cancelled_requests());
+}
+
+}  // namespace
+
+}  // namespace net