Introduce an artificial 2 second delay after network IP address changes before re-running proxy auto-config.

During this time network requests will be stalled.

This is to work around a problem where DNS gives transient failures shortly after IP address changes.

BUG=50779
TEST=On a linux laptop switch between wireless networks while using auto-detect. When you switch to a network that contains the host 'wpad' verify that when InitProxyResolver runs it does not get a DNS error resolving 'wpad'. (Use about:net-internals to view this information).

Review URL: http://codereview.chromium.org/3151040

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@57471 0039d316-1c4b-4281-b951-d872f2087c98

7 files changed, 213 insertions, 13 deletions

diff --git a/net/base/net_log_event_type_list.h b/net/base/net_log_event_type_list.h
index c2c754f..5c495f0 100644
--- a/net/base/net_log_event_type_list.h
+++ b/net/base/net_log_event_type_list.h
@@ -108,6 +108,11 @@ EVENT_TYPE(HOST_RESOLVER_IMPL_JOB)
 // The start/end of auto-detect + custom PAC URL configuration.
 EVENT_TYPE(INIT_PROXY_RESOLVER)
 
+// The start/end of when proxy autoconfig was artificially paused following
+// a network change event. (We wait some amount of time after being told of
+// network changes to avoid hitting spurious errors during auto-detect).
+EVENT_TYPE(INIT_PROXY_RESOLVER_WAIT)
+
 // The start/end of download of a PAC script. This could be the well-known
 // WPAD URL (if testing auto-detect), or a custom PAC URL.
 //
diff --git a/net/proxy/init_proxy_resolver.cc b/net/proxy/init_proxy_resolver.cc
index 04f828b..9cffa67 100644
--- a/net/proxy/init_proxy_resolver.cc
+++ b/net/proxy/init_proxy_resolver.cc
@@ -36,6 +36,7 @@ InitProxyResolver::~InitProxyResolver() {
 }
 
 int InitProxyResolver::Init(const ProxyConfig& config,
+                            const base::TimeDelta wait_delay,
                             CompletionCallback* callback) {
   DCHECK_EQ(STATE_NONE, next_state_);
   DCHECK(callback);
@@ -43,10 +44,15 @@ int InitProxyResolver::Init(const ProxyConfig& config,
 
   net_log_.BeginEvent(NetLog::TYPE_INIT_PROXY_RESOLVER, NULL);
 
+  // Save the |wait_delay| as a non-negative value.
+  wait_delay_ = wait_delay;
+  if (wait_delay_ < base::TimeDelta())
+    wait_delay_ = base::TimeDelta();
+
   pac_urls_ = BuildPacUrlsFallbackList(config);
   DCHECK(!pac_urls_.empty());
 
-  next_state_ = GetStartState();
+  next_state_ = STATE_WAIT;
 
   int rv = DoLoop(OK);
   if (rv == ERR_IO_PENDING)
@@ -86,6 +92,13 @@ int InitProxyResolver::DoLoop(int result) {
     State state = next_state_;
     next_state_ = STATE_NONE;
     switch (state) {
+      case STATE_WAIT:
+        DCHECK_EQ(OK, rv);
+        rv = DoWait();
+        break;
+      case STATE_WAIT_COMPLETE:
+        rv = DoWaitComplete(rv);
+        break;
       case STATE_FETCH_PAC_SCRIPT:
         DCHECK_EQ(OK, rv);
         rv = DoFetchPacScript();
@@ -115,6 +128,27 @@ void InitProxyResolver::DoCallback(int result) {
   user_callback_->Run(result);
 }
 
+int InitProxyResolver::DoWait() {
+  next_state_ = STATE_WAIT_COMPLETE;
+
+  // If no waiting is required, continue on to the next state.
+  if (wait_delay_.ToInternalValue() == 0)
+    return OK;
+
+  // Otherwise wait the specified amount of time.
+  wait_timer_.Start(wait_delay_, this, &InitProxyResolver::OnWaitTimerFired);
+  net_log_.BeginEvent(NetLog::TYPE_INIT_PROXY_RESOLVER_WAIT, NULL);
+  return ERR_IO_PENDING;
+}
+
+int InitProxyResolver::DoWaitComplete(int result) {
+  DCHECK_EQ(OK, result);
+  if (wait_delay_.ToInternalValue() != 0)
+    net_log_.EndEvent(NetLog::TYPE_INIT_PROXY_RESOLVER_WAIT, NULL);
+  next_state_ = GetStartState();
+  return OK;
+}
+
 int InitProxyResolver::DoFetchPacScript() {
   DCHECK(resolver_->expects_pac_bytes());
 
@@ -217,6 +251,10 @@ const InitProxyResolver::PacURL& InitProxyResolver::current_pac_url() const {
   return pac_urls_[current_pac_url_index_];
 }
 
+void InitProxyResolver::OnWaitTimerFired() {
+  OnIOCompletion(OK);
+}
+
 void InitProxyResolver::DidCompleteInit() {
   net_log_.EndEvent(NetLog::TYPE_INIT_PROXY_RESOLVER, NULL);
 }
@@ -227,6 +265,9 @@ void InitProxyResolver::Cancel() {
   net_log_.AddEvent(NetLog::TYPE_CANCELLED, NULL);
 
   switch (next_state_) {
+    case STATE_WAIT_COMPLETE:
+      wait_timer_.Stop();
+      break;
     case STATE_FETCH_PAC_SCRIPT_COMPLETE:
       proxy_script_fetcher_->Cancel();
       break;
diff --git a/net/proxy/init_proxy_resolver.h b/net/proxy/init_proxy_resolver.h
index 6c417d5..1bdb4e8 100644
--- a/net/proxy/init_proxy_resolver.h
+++ b/net/proxy/init_proxy_resolver.h
@@ -9,6 +9,8 @@
 #include <vector>
 
 #include "base/string16.h"
+#include "base/time.h"
+#include "base/timer.h"
 #include "googleurl/src/gurl.h"
 #include "net/base/completion_callback.h"
 #include "net/base/net_log.h"
@@ -47,12 +49,17 @@ class InitProxyResolver {
   ~InitProxyResolver();
 
   // Apply the PAC settings of |config| to |resolver_|.
+  // If |wait_delay| is positive, the initialization will pause for this
+  // amount of time before getting started.
   int Init(const ProxyConfig& config,
+           const base::TimeDelta wait_delay,
            CompletionCallback* callback);
 
  private:
   enum State {
     STATE_NONE,
+    STATE_WAIT,
+    STATE_WAIT_COMPLETE,
     STATE_FETCH_PAC_SCRIPT,
     STATE_FETCH_PAC_SCRIPT_COMPLETE,
     STATE_SET_PAC_SCRIPT,
@@ -75,6 +82,9 @@ class InitProxyResolver {
   int DoLoop(int result);
   void DoCallback(int result);
 
+  int DoWait();
+  int DoWaitComplete(int result);
+
   int DoFetchPacScript();
   int DoFetchPacScriptComplete(int result);
 
@@ -94,6 +104,7 @@ class InitProxyResolver {
   // Returns the current PAC URL we are fetching/testing.
   const PacURL& current_pac_url() const;
 
+  void OnWaitTimerFired();
   void DidCompleteInit();
   void Cancel();
 
@@ -113,6 +124,9 @@ class InitProxyResolver {
 
   BoundNetLog net_log_;
 
+  base::TimeDelta wait_delay_;
+  base::OneShotTimer<InitProxyResolver> wait_timer_;
+
   DISALLOW_COPY_AND_ASSIGN(InitProxyResolver);
 };
 
diff --git a/net/proxy/init_proxy_resolver_unittest.cc b/net/proxy/init_proxy_resolver_unittest.cc
index 458cc53..11d7c5f 100644
--- a/net/proxy/init_proxy_resolver_unittest.cc
+++ b/net/proxy/init_proxy_resolver_unittest.cc
@@ -177,7 +177,7 @@ TEST(InitProxyResolverTest, CustomPacSucceeds) {
   TestCompletionCallback callback;
   CapturingNetLog log(CapturingNetLog::kUnbounded);
   InitProxyResolver init(&resolver, &fetcher, &log);
-  EXPECT_EQ(OK, init.Init(config, &callback));
+  EXPECT_EQ(OK, init.Init(config, base::TimeDelta(), &callback));
   EXPECT_EQ(rule.text(), resolver.script_data()->utf16());
 
   // Check the NetLog was filled correctly.
@@ -210,7 +210,8 @@ TEST(InitProxyResolverTest, CustomPacFails1) {
   TestCompletionCallback callback;
   CapturingNetLog log(CapturingNetLog::kUnbounded);
   InitProxyResolver init(&resolver, &fetcher, &log);
-  EXPECT_EQ(kFailedDownloading, init.Init(config, &callback));
+  EXPECT_EQ(kFailedDownloading,
+            init.Init(config, base::TimeDelta(), &callback));
   EXPECT_EQ(NULL, resolver.script_data());
 
   // Check the NetLog was filled correctly.
@@ -238,7 +239,7 @@ TEST(InitProxyResolverTest, CustomPacFails2) {
 
   TestCompletionCallback callback;
   InitProxyResolver init(&resolver, &fetcher, NULL);
-  EXPECT_EQ(kFailedParsing, init.Init(config, &callback));
+  EXPECT_EQ(kFailedParsing, init.Init(config, base::TimeDelta(), &callback));
   EXPECT_EQ(NULL, resolver.script_data());
 }
 
@@ -252,7 +253,7 @@ TEST(InitProxyResolverTest, HasNullProxyScriptFetcher) {
 
   TestCompletionCallback callback;
   InitProxyResolver init(&resolver, NULL, NULL);
-  EXPECT_EQ(ERR_UNEXPECTED, init.Init(config, &callback));
+  EXPECT_EQ(ERR_UNEXPECTED, init.Init(config, base::TimeDelta(), &callback));
   EXPECT_EQ(NULL, resolver.script_data());
 }
 
@@ -269,7 +270,7 @@ TEST(InitProxyResolverTest, AutodetectSuccess) {
 
   TestCompletionCallback callback;
   InitProxyResolver init(&resolver, &fetcher, NULL);
-  EXPECT_EQ(OK, init.Init(config, &callback));
+  EXPECT_EQ(OK, init.Init(config, base::TimeDelta(), &callback));
   EXPECT_EQ(rule.text(), resolver.script_data()->utf16());
 }
 
@@ -288,7 +289,7 @@ TEST(InitProxyResolverTest, AutodetectFailCustomSuccess1) {
 
   TestCompletionCallback callback;
   InitProxyResolver init(&resolver, &fetcher, NULL);
-  EXPECT_EQ(OK, init.Init(config, &callback));
+  EXPECT_EQ(OK, init.Init(config, base::TimeDelta(), &callback));
   EXPECT_EQ(rule.text(), resolver.script_data()->utf16());
 }
 
@@ -308,7 +309,7 @@ TEST(InitProxyResolverTest, AutodetectFailCustomSuccess2) {
   TestCompletionCallback callback;
   CapturingNetLog log(CapturingNetLog::kUnbounded);
   InitProxyResolver init(&resolver, &fetcher, &log);
-  EXPECT_EQ(OK, init.Init(config, &callback));
+  EXPECT_EQ(OK, init.Init(config, base::TimeDelta(), &callback));
   EXPECT_EQ(rule.text(), resolver.script_data()->utf16());
 
   // Check the NetLog was filled correctly.
@@ -356,7 +357,8 @@ TEST(InitProxyResolverTest, AutodetectFailCustomFails1) {
 
   TestCompletionCallback callback;
   InitProxyResolver init(&resolver, &fetcher, NULL);
-  EXPECT_EQ(kFailedDownloading, init.Init(config, &callback));
+  EXPECT_EQ(kFailedDownloading,
+            init.Init(config, base::TimeDelta(), &callback));
   EXPECT_EQ(NULL, resolver.script_data());
 }
 
@@ -375,7 +377,7 @@ TEST(InitProxyResolverTest, AutodetectFailCustomFails2) {
 
   TestCompletionCallback callback;
   InitProxyResolver init(&resolver, &fetcher, NULL);
-  EXPECT_EQ(kFailedParsing, init.Init(config, &callback));
+  EXPECT_EQ(kFailedParsing, init.Init(config, base::TimeDelta(), &callback));
   EXPECT_EQ(NULL, resolver.script_data());
 }
 
@@ -396,9 +398,80 @@ TEST(InitProxyResolverTest, AutodetectFailCustomSuccess2_NoFetch) {
 
   TestCompletionCallback callback;
   InitProxyResolver init(&resolver, &fetcher, NULL);
-  EXPECT_EQ(OK, init.Init(config, &callback));
+  EXPECT_EQ(OK, init.Init(config, base::TimeDelta(), &callback));
   EXPECT_EQ(rule.url, resolver.script_data()->url());
 }
 
+// This is a copy-paste of CustomPacFails1, with the exception that we give it
+// a 1 millisecond delay. This means it will now complete asynchronously.
+// Moreover, we test the NetLog to make sure it logged the pause.
+TEST(InitProxyResolverTest, CustomPacFails1_WithPositiveDelay) {
+  Rules rules;
+  RuleBasedProxyResolver resolver(&rules, true /*expects_pac_bytes*/);
+  RuleBasedProxyScriptFetcher fetcher(&rules);
+
+  ProxyConfig config;
+  config.set_pac_url(GURL("http://custom/proxy.pac"));
+
+  rules.AddFailDownloadRule("http://custom/proxy.pac");
+
+  TestCompletionCallback callback;
+  CapturingNetLog log(CapturingNetLog::kUnbounded);
+  InitProxyResolver init(&resolver, &fetcher, &log);
+  EXPECT_EQ(ERR_IO_PENDING,
+            init.Init(config, base::TimeDelta::FromMilliseconds(1),
+                      &callback));
+
+  EXPECT_EQ(kFailedDownloading, callback.WaitForResult());
+  EXPECT_EQ(NULL, resolver.script_data());
+
+  // Check the NetLog was filled correctly.
+  EXPECT_EQ(6u, log.entries().size());
+  EXPECT_TRUE(LogContainsBeginEvent(
+      log.entries(), 0, NetLog::TYPE_INIT_PROXY_RESOLVER));
+  EXPECT_TRUE(LogContainsBeginEvent(
+      log.entries(), 1, NetLog::TYPE_INIT_PROXY_RESOLVER_WAIT));
+  EXPECT_TRUE(LogContainsEndEvent(
+      log.entries(), 2, NetLog::TYPE_INIT_PROXY_RESOLVER_WAIT));
+  EXPECT_TRUE(LogContainsBeginEvent(
+      log.entries(), 3, NetLog::TYPE_INIT_PROXY_RESOLVER_FETCH_PAC_SCRIPT));
+  EXPECT_TRUE(LogContainsEndEvent(
+      log.entries(), 4, NetLog::TYPE_INIT_PROXY_RESOLVER_FETCH_PAC_SCRIPT));
+  EXPECT_TRUE(LogContainsEndEvent(
+      log.entries(), 5, NetLog::TYPE_INIT_PROXY_RESOLVER));
+}
+
+// This is a copy-paste of CustomPacFails1, with the exception that we give it
+// a -5 second delay instead of a 0 ms delay. This change should have no effect
+// so the rest of the test is unchanged.
+TEST(InitProxyResolverTest, CustomPacFails1_WithNegativeDelay) {
+  Rules rules;
+  RuleBasedProxyResolver resolver(&rules, true /*expects_pac_bytes*/);
+  RuleBasedProxyScriptFetcher fetcher(&rules);
+
+  ProxyConfig config;
+  config.set_pac_url(GURL("http://custom/proxy.pac"));
+
+  rules.AddFailDownloadRule("http://custom/proxy.pac");
+
+  TestCompletionCallback callback;
+  CapturingNetLog log(CapturingNetLog::kUnbounded);
+  InitProxyResolver init(&resolver, &fetcher, &log);
+  EXPECT_EQ(kFailedDownloading,
+            init.Init(config, base::TimeDelta::FromSeconds(-5), &callback));
+  EXPECT_EQ(NULL, resolver.script_data());
+
+  // Check the NetLog was filled correctly.
+  EXPECT_EQ(4u, log.entries().size());
+  EXPECT_TRUE(LogContainsBeginEvent(
+      log.entries(), 0, NetLog::TYPE_INIT_PROXY_RESOLVER));
+  EXPECT_TRUE(LogContainsBeginEvent(
+      log.entries(), 1, NetLog::TYPE_INIT_PROXY_RESOLVER_FETCH_PAC_SCRIPT));
+  EXPECT_TRUE(LogContainsEndEvent(
+      log.entries(), 2, NetLog::TYPE_INIT_PROXY_RESOLVER_FETCH_PAC_SCRIPT));
+  EXPECT_TRUE(LogContainsEndEvent(
+      log.entries(), 3, NetLog::TYPE_INIT_PROXY_RESOLVER));
+}
+
 }  // namespace
 }  // namespace net
diff --git a/net/proxy/proxy_service.cc b/net/proxy/proxy_service.cc
index 54fe171..e3fc422 100644
--- a/net/proxy/proxy_service.cc
+++ b/net/proxy/proxy_service.cc
@@ -46,6 +46,45 @@ namespace {
 const size_t kMaxNumNetLogEntries = 100;
 const size_t kDefaultNumPacThreads = 4;
 
+// When the IP address changes we don't immediately re-run proxy auto-config.
+// Instead, we  wait for |kNumMillisToStallAfterNetworkChanges| before
+// attempting to re-valuate proxy auto-config.
+//
+// During this time window, any resolve requests sent to the ProxyService will
+// be queued. Once we have waited the required amount of them, the proxy
+// auto-config step will be run, and the queued requests resumed.
+//
+// The reason we play this game is that our signal for detecting network
+// changes (NetworkChangeNotifier) may fire *before* the system's networking
+// dependencies are fully configured. This is a problem since it means if
+// we were to run proxy auto-config right away, it could fail due to spurious
+// DNS failures. (see http://crbug.com/50779 for more details.)
+//
+// By adding the wait window, we give things a chance to get properly set up.
+// Now by the time we run the proxy-autoconfig there is a lower chance of
+// getting transient DNS / connect failures.
+//
+// Admitedly this is a hack. Ideally we would have NetworkChangeNotifier
+// deliver a reliable signal indicating that the network has changed AND is
+// ready for action... But until then, we can reduce the likelihood of users
+// getting wedged because of proxy detection failures on network switch.
+//
+// The obvious downside to this strategy is it introduces an additional
+// latency when switching networks. This delay shouldn't be too disruptive
+// assuming network switches are infrequent and user initiated. However if
+// NetworkChangeNotifier delivers network changes more frequently this could
+// cause jankiness. (NetworkChangeNotifier broadcasts a change event when ANY
+// interface goes up/down. So in theory if the non-primary interface were
+// hopping on and off wireless networks our constant delayed reconfiguration
+// could add noticeable jank.)
+//
+// The specific hard-coded wait time below is arbitrary.
+// Basically I ran some experiments switching between wireless networks on
+// a Linux Ubuntu (Lucid) laptop, and experimentally found this timeout fixes
+// things. It is entirely possible that the value is insuficient for other
+// setups.
+const int64 kNumMillisToStallAfterNetworkChanges = 2000;
+
 // Config getter that always returns direct settings.
 class ProxyConfigServiceDirect : public ProxyConfigService {
  public:
@@ -334,7 +373,10 @@ ProxyService::ProxyService(ProxyConfigService* config_service,
       ALLOW_THIS_IN_INITIALIZER_LIST(init_proxy_resolver_callback_(
           this, &ProxyService::OnInitProxyResolverComplete)),
       current_state_(STATE_NONE) ,
-      net_log_(net_log) {
+      net_log_(net_log),
+      stall_proxy_auto_config_delay_(
+          base::TimeDelta::FromMilliseconds(
+              kNumMillisToStallAfterNetworkChanges)) {
   NetworkChangeNotifier::AddObserver(this);
   ResetConfigService(config_service);
 }
@@ -755,14 +797,22 @@ void ProxyService::OnProxyConfigChanged(const ProxyConfig& config) {
       new InitProxyResolver(resolver_.get(), proxy_script_fetcher_.get(),
                             net_log_));
 
+  // If we changed networks recently, we should delay running proxy auto-config.
+  base::TimeDelta wait_delay =
+      stall_proxy_autoconfig_until_ - base::TimeTicks::Now();
+
   int rv = init_proxy_resolver_->Init(
-      config_, &init_proxy_resolver_callback_);
+      config_, wait_delay, &init_proxy_resolver_callback_);
 
   if (rv != ERR_IO_PENDING)
     OnInitProxyResolverComplete(rv);
 }
 
 void ProxyService::OnIPAddressChanged() {
+  // See the comment block by |kNumMillisToStallAfterNetworkChanges| for info.
+  stall_proxy_autoconfig_until_ =
+      base::TimeTicks::Now() + stall_proxy_auto_config_delay_;
+
   State previous_state = ResetProxyConfig();
   if (previous_state != STATE_NONE)
     ApplyProxyConfigIfAvailable();
diff --git a/net/proxy/proxy_service.h b/net/proxy/proxy_service.h
index 8f30327..3b61fbb 100644
--- a/net/proxy/proxy_service.h
+++ b/net/proxy/proxy_service.h
@@ -193,6 +193,12 @@ class ProxyService : public base::RefCountedThreadSafe<ProxyService>,
   static ProxyConfigService* CreateSystemProxyConfigService(
       MessageLoop* io_loop, MessageLoop* file_loop);
 
+#if UNIT_TEST
+  void set_stall_proxy_auto_config_delay(base::TimeDelta delay) {
+    stall_proxy_auto_config_delay_ = delay;
+  }
+#endif
+
  private:
   friend class base::RefCountedThreadSafe<ProxyService>;
   FRIEND_TEST_ALL_PREFIXES(ProxyServiceTest, UpdateConfigAfterFailedAutodetect);
@@ -302,6 +308,13 @@ class ProxyService : public base::RefCountedThreadSafe<ProxyService>,
   // sent to.
   NetLog* net_log_;
 
+  // The earliest time at which we should run any proxy auto-config. (Used to
+  // stall re-configuration following an IP address change).
+  base::TimeTicks stall_proxy_autoconfig_until_;
+
+  // The amount of time to stall requests following IP address changes.
+  base::TimeDelta stall_proxy_auto_config_delay_;
+
   DISALLOW_COPY_AND_ASSIGN(ProxyService);
 };
 
diff --git a/net/proxy/proxy_service_unittest.cc b/net/proxy/proxy_service_unittest.cc
index 70f1551..420d831 100644
--- a/net/proxy/proxy_service_unittest.cc
+++ b/net/proxy/proxy_service_unittest.cc
@@ -1590,6 +1590,10 @@ TEST(ProxyServiceTest, NetworkChangeTriggersPacRefetch) {
   MockProxyScriptFetcher* fetcher = new MockProxyScriptFetcher;
   service->SetProxyScriptFetcher(fetcher);
 
+  // Disable the "wait after IP address changes" hack, so this unit-test can
+  // complete quickly.
+  service->set_stall_proxy_auto_config_delay(base::TimeDelta());
+
   // Start 1 request.
 
   ProxyInfo info1;