dev/core#1781 - CRM_Utils_Time - Allow TIME_FUNC to better isolate timing bugs

Overview
--------

`CRM_Utils_Time` is a helper for (a) getting the time and (b) setting the time
to a mocked value (for testing purposes).

Timing bugs can manifest as flaky tests.

This provides a new option, `TIME_FUNC`, which may help isolate some timing
bugs (provided the test consistently uses `CRM_Utils_Time`).

Before
------

When using `CRM_Utils_Time::setTime()`, it simulates a change in the clock, and
the clock is allowed to proceed at a natural/real pace.

This policy aims to be representative of real-world execution (wherein the
clock also executes at a natural pace).  However, consider that the pace at
which the code executes depends on numerous factors (CPU speed, memory
managers, system-load, system-caches, the specific code/use-case, etc).  If
your use-case relies on multiple calls to `getTime()`, and if you run the
use-case in repeated trials, then you may find somewhat chaotic variations
in the exact values of `getTime()`.

Consequently, if there is a timing-sensitive bug, you may find that some trials
pass while others fail, and it is impossible to reproduce the natural
circumstance of the failure.

After
-----

By default, `CRM_Utils_Time` still performs simulations where the clock
proceeds a natural/real pace.

However, if you see flaky results and suspect a timing bug, you can re-run the
test suite with alternative time functions (`TIME_FUNC`):

```bash
TIME_FUNC=frozen      ## every call to getTime() yields the same, static value
TIME_FUNC=natural     ## every call to getTime() progresses in tandem with the real/natural clock
TIME_FUNC=linear:333  ## every call to getTime() progresses by 333ms
TIME_FUNC=prng:333    ## every call to getTime() progresses by a random interval, up to 333ms
```

Now "time" is not so natural or chaotic - it's more synthetic and
deterministic, which can help with debugging.

For example, consider `CRM_Core_BAO_ActionScheduleTest` and its functions
`testMembershipEndDateRepeat`, `testEventTypeEndDateRepeat`, and
`testRepetitionFrequencyUnit` -- which (anecdotally) appear to be flaky.  We
can run one of these tests with deterministic time functions:

```bash
for TIME_FUNC in frozen prng:333 prng:666 prng:1000 prng:1500 linear:333 linear:666 linear:1000 ; do
  export TIME_FUNC
  echo
  echo "Running with TIME_FUNC=$TIME_FUNC"
  env CIVICRM_UF=UnitTests phpunit6 tests/phpunit/CRM/Core/BAO/ActionScheduleTest.php --filter testRepetitionFrequencyUnit
done
```

We get different results depending on the `TIME_FUNC`. I've done multiple trials with each `TIME_FUNC`, and
results have been stable so far:

* PASSING: `frozen` `prng:333` `prng:666` `linear:333` `linear:666` `linear:1000` `linear:1500`
* FAILING: `prng:1000` `prng:1500`

This doesn't specifically tell you what the bug is.  It could be a real bug
in the main logic or less important bug in the test logic.  However, you can
now *reproduce it* (locally, in an IDE, etc) by setting `TIME_FUNC=prng:1500`.

diff --git a/CRM/Utils/Time.php b/CRM/Utils/Time.php
index dd4b4e2cca6100321cfc29eeb81d8eda11617a31..b700e572071092ee7c9f1462b914613b876c406f 100644 (file)
--- a/CRM/Utils/Time.php
+++ b/CRM/Utils/Time.php
@@ -21,10 +21,14 @@
 class CRM_Utils_Time {
 
   /**
-   * @var int
-   *   the seconds offset from the real world time
+   * A function which determines the current time.
+   * Only used during testing (with mocked time).
+   *
+   * The normal value, NULL, indicates the use of real time.
+   *
+   * @var callable|null
    */
-  static private $_delta = 0;
+  static private $callback = NULL;
 
   /**
    * Get the time.
@@ -45,7 +49,7 @@ class CRM_Utils_Time {
    *   seconds since epoch
    */
   public static function getTimeRaw() {
-    return time() + self::$_delta;
+    return self::$callback === NULL ? time() : call_user_func(self::$callback);
   }
 
   /**
@@ -56,10 +60,61 @@ class CRM_Utils_Time {
    * @param string $returnFormat
    *   Format in which date is to be retrieved.
    *
+   * Note: The progression of time will be influenced by TIME_FUNC, which may be:
+   *   - 'frozen' (time does not move)
+   *   - 'natural' (time moves naturally)
+   *   - 'linear:XXX' (time moves in increments of XXX milliseconds - with every lookup)
+   *   - 'prng:XXX' (time moves by random increments, between 0 and XXX milliseconds)
    * @return string
    */
   public static function setTime($newDateTime, $returnFormat = 'YmdHis') {
-    self::$_delta = strtotime($newDateTime) - time();
+    $mode = getenv('TIME_FUNC') ? getenv('TIME_FUNC') : 'natural';
+
+    list ($modeName, $modeNum) = explode(":", "$mode:");
+
+    switch ($modeName) {
+      case 'frozen':
+        // Every getTime() will produce the same value (ie $newDateTime).
+        $now = strtotime($newDateTime);
+        self::$callback = function () use ($now) {
+          return $now;
+        };
+        break;
+
+      case 'natural':
+        // Time changes to $newDateTime and then proceeds naturally.
+        $delta = strtotime($newDateTime) - time();
+        self::$callback = function () use ($delta) {
+          return time() + $delta;
+        };
+        break;
+
+      case 'linear':
+        // Time changes to $newDateTime and then proceeds in fixed increments ($modeNum milliseconds).
+        $incr = ($modeNum / 1000.0);
+        $now = (float) strtotime($newDateTime) - $incr;
+        self::$callback = function () use (&$now, $incr) {
+          $now += $incr;
+          return floor($now);
+        };
+        break;
+
+      case 'prng':
+        // Time changes to $newDateTime and then proceeds using deterministic pseudorandom increments (of up to $modeNum milliseconds).
+        $seed = md5($newDateTime . chr(0) . $mode, TRUE);
+        $now = (float) strtotime($newDateTime);
+        self::$callback = function () use (&$seed, &$now, $modeNum) {
+          $mod = gmp_strval(gmp_mod(gmp_import($seed), "$modeNum"));
+          $seed = md5($seed . $now, TRUE);
+          $now = $now + ($mod / 1000.0);
+          return floor($now);
+        };
+        break;
+
+      default:
+        throw new \RuntimeException("Unrecognized TIME_FUNC ($mode)");
+    }
+
     return self::getTime($returnFormat);
   }
 
@@ -67,7 +122,7 @@ class CRM_Utils_Time {
    * Remove any time overrides.
    */
   public static function resetTime() {
-    self::$_delta = 0;
+    self::$callback = NULL;
   }
 
   /**