Reduce clock skew in flaky duration tests

There are three changes here that should help reduce the
amount of duration test failures caused by clock skew.

First, we reported some skew when the test expected playback
to start immediately after loading the license. However,
with round-off, this could easily be more than 1 second. So
this does not warrent even a warning.

Second, the fake and real clocks were only synced after
computing how long to sleep. This is fixed by moving
SleepUntil to the TestSleep class and having it sync before
computing the delta and after doing the sleep.

Third, I am guessing that some failures due to unexpected
lenience were caused by the rental or playback clock being
started at the end of signing the license or the end of the
first decrypt instead of the beginning. We work around this
by recording how long these operations take, and then adding
this extra time at the end of the check for FailDecrypt.

Bug: 275003529
Bug: 279249646
Bug: 207500749
Merged from https://widevine-internal-review.googlesource.com/176070

Change-Id: I6a973565edfbebca53ee7f239b4b93f8f73d1e0a

libwvdrmengine/cdm/core/test/duration_use_case_test.cpp

@@ -141,6 +141,14 @@ class CdmDurationTest : public WvCdmTestBaseWithEngine,
     // All times in the license are relative to the rental clock.
     start_of_rental_clock_ = wvutil::Clock().GetCurrentTime();
     license_holder_.FetchLicense();
+    // Record the time it took to fetch the license. This will be used as
+    // some extra fudge when looking for playback cutoff at the end of the
+    // rental window.
+    extra_fudge_time_ = CurrentRentalTime();
+    if (extra_fudge_time_ > kRoundTripTime) {
+      LOGE("FetchLicense took a long time: %" PRIu64 " seconds",
+           extra_fudge_time_);
+    }
   }
 
   void TearDown() override {
@@ -182,16 +190,8 @@ class CdmDurationTest : public WvCdmTestBaseWithEngine,
 
   // Sleep until the specified time on the rental clock.
   void SleepUntil(uint64_t desired_rental_time) {
-    const uint64_t rental_time = CurrentRentalTime();
-    if (desired_rental_time >= rental_time) {
-      const unsigned int sleep_time =
-          static_cast<unsigned int>(desired_rental_time - rental_time);
-      wvutil::TestSleep::Sleep(sleep_time);
-    } else {
-      LOGW("Test Clock skew sleeping from rental clock time %" PRIu64
-           " to %" PRIu64,
-           rental_time, desired_rental_time);
-    }
+    // We use rental clock in this file, but TestSleep uses the system clock.
+    wvutil::TestSleep::SleepUntil(desired_rental_time + start_of_rental_clock_);
     cdm_engine_.OnTimerEvent();
   }
 
@@ -232,7 +232,10 @@ class CdmDurationTest : public WvCdmTestBaseWithEngine,
   // a green check mark.  Both |start| and |stop| are all system times.
   void AllowPlayback(uint64_t start, uint64_t stop) {
     ASSERT_LT(start, stop);
-    SleepUntil(start);
+    // If now is before start, then sleep until start.
+    // If we are already after start, don't try to sleep or a warning will be
+    // logged. Instead, we'll just start playback as soon as we can.
+    if (start > CurrentRentalTime()) SleepUntil(start);
     Decrypt();
     const uint64_t mid = (start + stop) / 2;
     SleepUntil(mid);
@@ -278,11 +281,21 @@ class CdmDurationTest : public WvCdmTestBaseWithEngine,
   void AllowLenience() { allow_lenience_ = true; }
 
   void Decrypt() {
-    const uint64_t now = CurrentRentalTime();
+    const uint64_t start = CurrentRentalTime();
     EXPECT_EQ(NO_ERROR, license_holder_.Decrypt(kKeyId))
-        << "Failed to decrypt when rental clock = " << now
+        << "Failed to decrypt when rental clock = " << start
         << ", and playback clock = "
-        << ((now < start_of_playback_) ? 0 : (now - start_of_playback_));
+        << ((start < start_of_playback_) ? 0 : (start - start_of_playback_));
+    const uint64_t fudge = CurrentRentalTime() - start;
+    if (fudge > kFudge) {
+      LOGE("Decrypt took a long time: %" PRIu64 " seconds", fudge);
+    }
+    // We need extra_fudge_time_ to be at least as big as the first decrypt to
+    // allow extra fudge when looking for playback cutoff at the end of the
+    // playback window.
+    if (fudge > extra_fudge_time_) {
+      extra_fudge_time_ = fudge;
+    }
   }
 
   void FailDecrypt() {
@@ -311,10 +324,15 @@ class CdmDurationTest : public WvCdmTestBaseWithEngine,
         << now << ", and playback clock = "
         << (now < start_of_playback_ ? 0 : now - start_of_playback_);
     // However, for those cases decided above, we also allow success.
-    EXPECT_TRUE(allow_success)
+    if (allow_success) return;
+    // Try again after allowing for the extra fudge time. See comment at the
+    // definition of extra_fudge_time_ for an explanation.
+    wvutil::TestSleep::Sleep(static_cast<unsigned int>(extra_fudge_time_));
+    ASSERT_EQ(NEED_KEY, license_holder_.Decrypt(kKeyId))
         << "Device was unexpectedly lenient when rental clock = " << now
         << ", and playback clock = "
-        << (now < start_of_playback_ ? 0 : now - start_of_playback_);
+        << (now < start_of_playback_ ? 0 : now - start_of_playback_)
+        << ", extra fudge = " << extra_fudge_time_;
   }
 
   LicenseHolder license_holder_;
@@ -331,6 +349,16 @@ class CdmDurationTest : public WvCdmTestBaseWithEngine,
   // If this is set, then the next time we expect a playback to be terminated,
   // we will allow lenient failure.
   bool allow_lenience_;
+  // Extra fudge accounts for the amount of extra time it takes to perform an
+  // operation that starts a clock. In some test environments under high load,
+  // creating the license request might take a second or more. The rental clock
+  // starts at the time the license request is signed -- this extra fudge
+  // accounts for the question of whether we mean at the beginning or the end of
+  // the siging operation. Similarly the playback clock starts at the first
+  // decrypt. This value, extra_fudge_time_, is the maximum of the license
+  // request time and the first decrypt time, so it can be used for testing
+  // cutoff for either rental duration or playback duration.
+  uint64_t extra_fudge_time_ = 0;
 };
 
 /*****************************************************************************/

libwvdrmengine/cdm/util/test/test_sleep.cpp

@@ -14,6 +14,7 @@
 #endif
 
 #include <errno.h>
+#include <inttypes.h>
 #include <string.h>
 #include <unistd.h>
 
@@ -53,6 +54,18 @@ void TestSleep::Sleep(unsigned int seconds) {
   if (callback_ != nullptr) callback_->ElapseTime(milliseconds);
 }
 
+void TestSleep::SleepUntil(int64_t desired_time) {
+  SyncFakeClock();
+  const int64_t now = Clock().GetCurrentTime();
+  if (desired_time < now) {
+    LOGE("Test Clock skew sleeping from time %" PRId64 " to %" PRId64, now,
+         desired_time);
+    return;
+  }
+  const unsigned int sleep_time = static_cast<unsigned int>(desired_time - now);
+  TestSleep::Sleep(sleep_time);
+}
+
 void TestSleep::SyncFakeClock() {
   // Syncing can be done by sleeping 0 seconds.
   Sleep(0);

libwvdrmengine/cdm/util/test/test_sleep.h

@@ -13,7 +13,9 @@ namespace wvutil {
 
 class TestSleep {
  public:
-  // The callback is called when the clock should be advanced.
+  // The callback is called when the test clock should be advanced. If the
+  // system uses a real clock, it is used to sync the real and test
+  // clock. Otherwise it is used to simulate sleep in the test clock.
   class CallBack {
    public:
     virtual void ElapseTime(int64_t milliseconds) = 0;
@@ -27,6 +29,9 @@ class TestSleep {
   // callback exists, this calls the callback.
   static void Sleep(unsigned int seconds);
 
+  // Like sleep, above, except it sleeps until the specified time.
+  static void SleepUntil(int64_t desired_time);
+
   // If we are using a real clock and a fake clock, then the real clock advances
   // a little while we are doing work, but the fake one only advances when we
   // sleep. This function advances the fake clock to be in sync with the real