sync: Attempt to fix sync scheduler test flakiness

sync/engine/sync_scheduler_unittest.cc

 // Copyright (c) 2012 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 "base/bind.h"
 #include "base/callback.h"
 #include "base/compiler_specific.h"
 #include "base/memory/weak_ptr.h"
 #include "base/message_loop/message_loop.h"
 #include "base/test/test_timeouts.h"
@@ skipping 76 matching lines @@
 }
 
 ModelSafeRoutingInfo TypesToRoutingInfo(ModelTypeSet types) {
   ModelSafeRoutingInfo routes;
   for (ModelTypeSet::Iterator iter = types.First(); iter.Good(); iter.Inc()) {
     routes[iter.Get()] = GROUP_PASSIVE;
   }
   return routes;
 }
 
-// Convenient to use in tests wishing to analyze SyncShare calls over time.
+
 static const size_t kMinNumSamples = 5;
+
+// Test harness for the SyncScheduler.  Test the delays and backoff timers used
+// in response to various events.
+//
+// These tests execute in real time with real timers.  We try to keep the
+// delays short, but there is a limit to how short we can make them.  The
+// timers on some platforms (ie. Windows) have a timer resolution greater than
+// 1ms.  Using 1ms delays may result in test flakiness.
+//
+// See crbug.com/402212 for more info.
 class SyncSchedulerTest : public testing::Test {
  public:
   SyncSchedulerTest() : syncer_(NULL), delay_(NULL), weak_ptr_factory_(this) {}
 
   class MockDelayProvider : public BackoffDelayProvider {
    public:
     MockDelayProvider() : BackoffDelayProvider(
         TimeDelta::FromSeconds(kInitialBackoffRetrySeconds),
         TimeDelta::FromSeconds(kInitialBackoffImmediateRetrySeconds)) {
     }
@@ skipping 227 matching lines @@
   scheduler()->ScheduleConfiguration(params);
   PumpLoop();
   ASSERT_EQ(1, ready_counter.times_called());
   ASSERT_EQ(0, retry_counter.times_called());
 }
 
 // Simulate a failure and make sure the config request is retried.
 TEST_F(SyncSchedulerTest, ConfigWithBackingOff) {
   UseMockDelayProvider();
   EXPECT_CALL(*delay(), GetDelay(_))
-      .WillRepeatedly(Return(TimeDelta::FromMilliseconds(1)));
+      .WillRepeatedly(Return(TimeDelta::FromMilliseconds(20)));
   SyncShareTimes times;
   const ModelTypeSet model_types(BOOKMARKS);
 
   StartSyncScheduler(SyncScheduler::CONFIGURATION_MODE);
 
   EXPECT_CALL(*syncer(), ConfigureSyncShare(_,_,_))
       .WillOnce(DoAll(Invoke(sessions::test_util::SimulateConfigureFailed),
                       RecordSyncShare(&times)))
       .WillOnce(DoAll(Invoke(sessions::test_util::SimulateConfigureFailed),
                       RecordSyncShare(&times)));
@@ skipping 25 matching lines @@
   RunLoop();
 
   ASSERT_EQ(1, ready_counter.times_called());
 }
 
 // Simuilate SyncSchedulerImpl::Stop being called in the middle of Configure.
 // This can happen if server returns NOT_MY_BIRTHDAY.
 TEST_F(SyncSchedulerTest, ConfigWithStop) {
   UseMockDelayProvider();
   EXPECT_CALL(*delay(), GetDelay(_))
-      .WillRepeatedly(Return(TimeDelta::FromMilliseconds(1)));
+      .WillRepeatedly(Return(TimeDelta::FromMilliseconds(20)));
   SyncShareTimes times;
   const ModelTypeSet model_types(BOOKMARKS);
 
   StartSyncScheduler(SyncScheduler::CONFIGURATION_MODE);
 
   // Make ConfigureSyncShare call scheduler->Stop(). It is not supposed to call
   // retry_task or dereference configuration params.
   EXPECT_CALL(*syncer(), ConfigureSyncShare(_,_,_))
       .WillOnce(DoAll(Invoke(sessions::test_util::SimulateConfigureFailed),
                       StopScheduler(scheduler()),
@@ skipping 242 matching lines @@
   scheduler()->ScheduleLocalNudge(zero(), model_types, FROM_HERE);
   RunLoop();
 
   EXPECT_EQ(delay2, scheduler()->GetSessionsCommitDelay());
   StopSyncScheduler();
 }
 
 // Test that no syncing occurs when throttled.
 TEST_F(SyncSchedulerTest, ThrottlingDoesThrottle) {
   const ModelTypeSet types(BOOKMARKS);
-  TimeDelta poll(TimeDelta::FromMilliseconds(5));
+  TimeDelta poll(TimeDelta::FromMilliseconds(20));
   TimeDelta throttle(TimeDelta::FromMinutes(10));
   scheduler()->OnReceivedLongPollIntervalUpdate(poll);
 
   EXPECT_CALL(*syncer(), ConfigureSyncShare(_,_,_))
       .WillOnce(DoAll(
           WithArg<2>(sessions::test_util::SimulateThrottled(throttle)),
           Return(true)))
       .WillRepeatedly(AddFailureAndQuitLoopNow());
 
   StartSyncScheduler(SyncScheduler::NORMAL_MODE);
@@ skipping 243 matching lines @@
 
   RunLoop();
   Mock::VerifyAndClearExpectations(syncer());
 }
 
 class BackoffTriggersSyncSchedulerTest : public SyncSchedulerTest {
   virtual void SetUp() {
     SyncSchedulerTest::SetUp();
     UseMockDelayProvider();
     EXPECT_CALL(*delay(), GetDelay(_))
-        .WillRepeatedly(Return(TimeDelta::FromMilliseconds(1)));
+        .WillRepeatedly(Return(TimeDelta::FromMilliseconds(10)));
   }
 
   virtual void TearDown() {
     StopSyncScheduler();
     SyncSchedulerTest::TearDown();
   }
 };
 
 // Have the sycner fail during commit.  Expect that the scheduler enters
 // backoff.
@@ skipping 64 matching lines @@
       base::Bind(&CallbackCounter::Callback, base::Unretained(&retry_counter)));
   scheduler()->ScheduleConfiguration(params);
   RunLoop();
 
   EXPECT_TRUE(scheduler()->IsBackingOff());
 }
 
 // Test that no polls or extraneous nudges occur when in backoff.
 TEST_F(SyncSchedulerTest, BackoffDropsJobs) {
   SyncShareTimes times;
-  TimeDelta poll(TimeDelta::FromMilliseconds(5));
+  TimeDelta poll(TimeDelta::FromMilliseconds(10));
   const ModelTypeSet types(BOOKMARKS);
   scheduler()->OnReceivedLongPollIntervalUpdate(poll);
   UseMockDelayProvider();
 
   EXPECT_CALL(*syncer(), NormalSyncShare(_,_,_))
       .WillOnce(DoAll(Invoke(sessions::test_util::SimulateCommitFailed),
                       RecordSyncShareMultiple(&times, 1U)));
   EXPECT_CALL(*delay(), GetDelay(_)).
       WillRepeatedly(Return(TimeDelta::FromDays(1)));
 
   StartSyncScheduler(SyncScheduler::NORMAL_MODE);
 
   // This nudge should fail and put us into backoff.  Thanks to our mock
   // GetDelay() setup above, this will be a long backoff.
   scheduler()->ScheduleLocalNudge(zero(), types, FROM_HERE);
   RunLoop();
 
   // From this point forward, no SyncShare functions should be invoked.
   Mock::VerifyAndClearExpectations(syncer());
 
   // Wait a while (10x poll interval) so a few poll jobs will be attempted.
   PumpLoopFor(poll * 10);
 
   // Try (and fail) to schedule a nudge.
   scheduler()->ScheduleLocalNudge(
-      base::TimeDelta::FromMilliseconds(1),
+      base::TimeDelta::FromMilliseconds(10),
       types,
       FROM_HERE);
 
   Mock::VerifyAndClearExpectations(syncer());
   Mock::VerifyAndClearExpectations(delay());
 
   EXPECT_CALL(*delay(), GetDelay(_)).Times(0);
 
   StartSyncScheduler(SyncScheduler::CONFIGURATION_MODE);
 
@@ skipping 15 matching lines @@
 // Test that backoff is shaping traffic properly with consecutive errors.
 TEST_F(SyncSchedulerTest, BackoffElevation) {
   SyncShareTimes times;
   UseMockDelayProvider();
 
   EXPECT_CALL(*syncer(), NormalSyncShare(_,_,_)).Times(kMinNumSamples)
       .WillRepeatedly(DoAll(Invoke(sessions::test_util::SimulateCommitFailed),
           RecordSyncShareMultiple(&times, kMinNumSamples)));
 
   const TimeDelta first = TimeDelta::FromSeconds(kInitialBackoffRetrySeconds);
-  const TimeDelta second = TimeDelta::FromMilliseconds(2);
-  const TimeDelta third = TimeDelta::FromMilliseconds(3);
-  const TimeDelta fourth = TimeDelta::FromMilliseconds(4);
-  const TimeDelta fifth = TimeDelta::FromMilliseconds(5);
+  const TimeDelta second = TimeDelta::FromMilliseconds(20);
+  const TimeDelta third = TimeDelta::FromMilliseconds(30);
+  const TimeDelta fourth = TimeDelta::FromMilliseconds(40);
+  const TimeDelta fifth = TimeDelta::FromMilliseconds(50);
   const TimeDelta sixth = TimeDelta::FromDays(1);
 
   EXPECT_CALL(*delay(), GetDelay(first)).WillOnce(Return(second))
           .RetiresOnSaturation();
   EXPECT_CALL(*delay(), GetDelay(second)).WillOnce(Return(third))
           .RetiresOnSaturation();
   EXPECT_CALL(*delay(), GetDelay(third)).WillOnce(Return(fourth))
           .RetiresOnSaturation();
   EXPECT_CALL(*delay(), GetDelay(fourth)).WillOnce(Return(fifth))
           .RetiresOnSaturation();
@@ skipping 12 matching lines @@
   EXPECT_GE(times[4] - times[3], fifth);
 }
 
 // Test that things go back to normal once a retry makes forward progress.
 TEST_F(SyncSchedulerTest, BackoffRelief) {
   SyncShareTimes times;
   const TimeDelta poll(TimeDelta::FromMilliseconds(10));
   scheduler()->OnReceivedLongPollIntervalUpdate(poll);
   UseMockDelayProvider();
 
-  const TimeDelta backoff = TimeDelta::FromMilliseconds(5);
+  const TimeDelta backoff = TimeDelta::FromMilliseconds(10);
   EXPECT_CALL(*delay(), GetDelay(_)).WillOnce(Return(backoff));
 
   // Optimal start for the post-backoff poll party.
   TimeTicks optimal_start = TimeTicks::Now();
   StartSyncScheduler(SyncScheduler::NORMAL_MODE);
 
   // Kick off the test with a failed nudge.
   EXPECT_CALL(*syncer(), NormalSyncShare(_,_,_))
       .WillOnce(DoAll(Invoke(sessions::test_util::SimulateCommitFailed),
                       RecordSyncShare(&times)));
@@ skipping 29 matching lines @@
     EXPECT_GE(times[i], optimal_job_time);
   }
 
   StopSyncScheduler();
 }
 
 // Test that poll failures are ignored.  They should have no effect on
 // subsequent poll attempts, nor should they trigger a backoff/retry.
 TEST_F(SyncSchedulerTest, TransientPollFailure) {
   SyncShareTimes times;
-  const TimeDelta poll_interval(TimeDelta::FromMilliseconds(1));
+  const TimeDelta poll_interval(TimeDelta::FromMilliseconds(10));
   scheduler()->OnReceivedLongPollIntervalUpdate(poll_interval);
   UseMockDelayProvider(); // Will cause test failure if backoff is initiated.
 
   EXPECT_CALL(*syncer(), PollSyncShare(_,_))
       .WillOnce(DoAll(Invoke(sessions::test_util::SimulatePollFailed),
                       RecordSyncShare(&times)))
       .WillOnce(DoAll(Invoke(sessions::test_util::SimulatePollSuccess),
                       RecordSyncShare(&times)));
 
   StartSyncScheduler(SyncScheduler::NORMAL_MODE);
@@ skipping 141 matching lines @@
   // poll once more
   EXPECT_CALL(*syncer(), PollSyncShare(_,_))
       .WillOnce(DoAll(Invoke(sessions::test_util::SimulatePollSuccess),
                       RecordSyncShare(&times)));
   scheduler()->OnCredentialsUpdated();
   connection()->SetServerStatus(HttpResponse::SERVER_CONNECTION_OK);
   RunLoop();
   StopSyncScheduler();
 }
 
-#if defined(OS_WIN)
-// Times out: http://crbug.com/402212
-#define MAYBE_SuccessfulRetry DISABLED_SuccessfulRetry
-#else
-#define MAYBE_SuccessfulRetry SuccessfulRetry
-#endif
-TEST_F(SyncSchedulerTest, MAYBE_SuccessfulRetry) {
+TEST_F(SyncSchedulerTest, SuccessfulRetry) {
   StartSyncScheduler(SyncScheduler::NORMAL_MODE);
 
   SyncShareTimes times;
-  base::TimeDelta delay = base::TimeDelta::FromMilliseconds(1);
+  base::TimeDelta delay = base::TimeDelta::FromMilliseconds(10);
   scheduler()->OnReceivedGuRetryDelay(delay);
   EXPECT_EQ(delay, GetRetryTimerDelay());
 
   EXPECT_CALL(*syncer(), NormalSyncShare(_,_,_))
       .WillOnce(
           DoAll(Invoke(sessions::test_util::SimulateNormalSuccess),
                 RecordSyncShare(&times)));
 
   // Run to wait for retrying.
   RunLoop();
 
   StopSyncScheduler();
 }
 
-#if defined(OS_WIN)
-// Times out: http://crbug.com/402212
-#define MAYBE_FailedRetry DISABLED_FailedRetry
-#else
-#define MAYBE_FailedRetry FailedRetry
-#endif
-TEST_F(SyncSchedulerTest, MAYBE_FailedRetry) {
+TEST_F(SyncSchedulerTest, FailedRetry) {
   UseMockDelayProvider();
   EXPECT_CALL(*delay(), GetDelay(_))
-      .WillRepeatedly(Return(TimeDelta::FromMilliseconds(1)));
+      .WillRepeatedly(Return(TimeDelta::FromMilliseconds(10)));
 
   StartSyncScheduler(SyncScheduler::NORMAL_MODE);
 
-  base::TimeDelta delay = base::TimeDelta::FromMilliseconds(1);
+  base::TimeDelta delay = base::TimeDelta::FromMilliseconds(10);
   scheduler()->OnReceivedGuRetryDelay(delay);
 
   EXPECT_CALL(*syncer(), NormalSyncShare(_,_,_))
       .WillOnce(
           DoAll(Invoke(sessions::test_util::SimulateDownloadUpdatesFailed),
                 QuitLoopNowAction()));
 
   // Run to wait for retrying.
   RunLoop();
 
   EXPECT_TRUE(scheduler()->IsBackingOff());
   EXPECT_CALL(*syncer(), NormalSyncShare(_,_,_))
       .WillOnce(
           DoAll(Invoke(sessions::test_util::SimulateNormalSuccess),
                 QuitLoopNowAction()));
 
   // Run to wait for second retrying.
   RunLoop();
 
   StopSyncScheduler();
 }
 
 ACTION_P2(VerifyRetryTimerDelay, scheduler_test, expected_delay) {
   EXPECT_EQ(expected_delay, scheduler_test->GetRetryTimerDelay());
 }
 
-#if defined(OS_WIN)
-// Times out: http://crbug.com/402212
-#define MAYBE_ReceiveNewRetryDelay DISABLED_ReceiveNewRetryDelay
-#else
-#define MAYBE_ReceiveNewRetryDelay ReceiveNewRetryDelay
-#endif
-TEST_F(SyncSchedulerTest, MAYBE_ReceiveNewRetryDelay) {
+TEST_F(SyncSchedulerTest, ReceiveNewRetryDelay) {
   StartSyncScheduler(SyncScheduler::NORMAL_MODE);
 
   SyncShareTimes times;
   base::TimeDelta delay1 = base::TimeDelta::FromMilliseconds(100);
   base::TimeDelta delay2 = base::TimeDelta::FromMilliseconds(200);
 
   scheduler()->ScheduleLocalRefreshRequest(zero(), ModelTypeSet(BOOKMARKS),
                                            FROM_HERE);
   scheduler()->OnReceivedGuRetryDelay(delay1);
   EXPECT_EQ(delay1, GetRetryTimerDelay());
@@ skipping 12 matching lines @@
       .WillOnce(DoAll(Invoke(sessions::test_util::SimulateNormalSuccess),
                       RecordSyncShare(&times)));
 
   // Run to wait for retrying.
   RunLoop();
 
   StopSyncScheduler();
 }
 
 }  // namespace syncer