From ea9371f921e9be20f371330b5c72735a7267b868 Mon Sep 17 00:00:00 2001 From: Tim Otten Date: Wed, 27 May 2020 16:48:27 -0700 Subject: [PATCH] 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`. --- CRM/Utils/Time.php | 67 +++++++++++++++++++++++++++++++++++++++++----- 1 file changed, 61 insertions(+), 6 deletions(-) diff --git a/CRM/Utils/Time.php b/CRM/Utils/Time.php index dd4b4e2cca..b700e57207 100644 --- 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; } /** -- 2.25.1