From fcf70630b63ec07ffbd5d99c78c269e9d3cf36ec Mon Sep 17 00:00:00 2001 From: Matthew Hilton Date: Fri, 17 Nov 2023 14:15:07 +1000 Subject: [PATCH] [#165] Add cachecheck logging --- classes/check/cachecheck.php | 79 ++++++++++++++++++++++++++++++------ classes/lib.php | 49 ++++++++++++++++++++++ lang/en/tool_heartbeat.php | 7 ++++ settings.php | 22 ++++++++++ version.php | 4 +- 5 files changed, 147 insertions(+), 14 deletions(-) diff --git a/classes/check/cachecheck.php b/classes/check/cachecheck.php index 01c07a2..527240d 100644 --- a/classes/check/cachecheck.php +++ b/classes/check/cachecheck.php @@ -17,6 +17,7 @@ namespace tool_heartbeat\check; use core\check\check; use core\check\result; +use tool_heartbeat\lib; /** * Cache check class @@ -101,20 +102,65 @@ private function build_result(array $results): array { * @param string $type type of check (e.g. web, cron) */ public function check($type) { - global $DB; - $return = []; - $key = "checkcache{$type}ping"; // Read from cache (e.g. get_config uses cache). - $return[$type . 'api'] = get_config('tool_heartbeat', $key); + $cachevalue = self::get_cache_ping_value($type); // Read directly from database. - $return[$type . 'db'] = $DB->get_field('config_plugins', 'value', [ + $dbvalue = self::get_db_ping_value($type); + + // Log that it was checked, so we can see historical values for debugging. + if (get_config('tool_heartbeat', 'shouldlogcachecheck')) { + lib::record_cache_checked($cachevalue, $dbvalue, $type); + } + + $return = [ + $type . 'api' => $cachevalue, + $type . 'db' => $dbvalue, + ]; + + return $return; + } + + /** + * Returns cache key + * @param string $type web or cron + * @return string + */ + private static function get_key(string $type) { + return "checkcache{$type}ping"; + } + + /** + * Returns the cached value from get_config + * @param string $type web or cron + * @return int value + */ + private static function get_cache_ping_value(string $type) { + return get_config('tool_heartbeat', self::get_key($type)); + } + + /** + * Returns the database stored ping value + * @param string $type web or cron + * @param int value + */ + private static function get_db_ping_value(string $type) { + global $DB; + return $DB->get_field('config_plugins', 'value', [ 'plugin' => 'tool_heartbeat', - 'name' => $key, + 'name' => self::get_key($type), ]); - return $return; + } + + /** + * Set the cache ping value + * @param string $type web or cron + * @param int $value new value to set + */ + private static function set_cache_ping_value(string $type, int $value) { + set_config(self::get_key($type), $value, 'tool_heartbeat'); } /** @@ -122,13 +168,22 @@ public function check($type) { * @param string $type type of check (e.g. web, cron) */ public static function ping($type) { - $key = "checkcache{$type}ping"; - $current = get_config('tool_heartbeat', $key); + $time = time(); + $currentcache = self::get_cache_ping_value($type); + $currentdb = self::get_db_ping_value($type); // Only update if the currently cached time is very old. - if ($current < (time() - DAYSECS)) { - debugging("\nHEARTBEAT doing {$type} ping {$current}\n", DEBUG_DEVELOPER); - set_config($key, time(), 'tool_heartbeat'); + if ($currentcache < ($time - DAYSECS)) { + debugging("\nHEARTBEAT doing {$type} ping\n", DEBUG_DEVELOPER); + self::set_cache_ping_value($type, $time); + + // Read back the cached value immediately after setting it. + // This should help detect any cache replication delays. + $readbackvalue = self::get_cache_ping_value($type); + + if (get_config('tool_heartbeat', 'shouldlogcacheping')) { + lib::record_cache_pinged($currentcache, $currentdb, $time, $readbackvalue, $type); + } } } } diff --git a/classes/lib.php b/classes/lib.php index dae7fe3..c004d9a 100644 --- a/classes/lib.php +++ b/classes/lib.php @@ -16,6 +16,11 @@ namespace tool_heartbeat; +use context_system; +use Throwable; +use tool_heartbeat\event\cache_check; +use tool_heartbeat\event\cache_ping; + /** * General functions for use with heartbeat. * @@ -59,4 +64,48 @@ public static function validate_ip_against_config() { send_unknown($msg); } } + + /** + * Records that the cache was pinged. This is useful for cache debugging. + * @param int $previousincache + * @param int $previousindb + * @param int $newvalueset the value that the cache was set to + * @param int $readbackvalue the value read back from the cache immediately after it was set. + * @param string $where cron or web + */ + public static function record_cache_pinged(int $previousincache, int $previousindb, int $newvalueset, int $readbackvalue, + string $where) { + try { + $details = [ + 'previousvalueindb' => $previousindb, + 'previousvalueincache' => $previousincache, + 'newvalueincache' => $newvalueset, + 'cachedvalueimmediatelyafterwrite' => $readbackvalue, + 'where' => $where, + ]; + error_log("Heartbeat cache was updated/pinged: " . json_encode($details)); + } catch (Throwable $e) { + debugging($e, DEBUG_DEVELOPER); + } + } + + /** + * Records that the cache was checked. This is used for debugging cache mismatches + * @param int $valueincache + * @param int $valueindb + * @param string $where web or cron + */ + public static function record_cache_checked(int $valueincache, int $valueindb, string $where) { + try { + $details = [ + 'valueindb' => $valueindb, + 'valueincache' => $valueincache, + 'where' => $where, + ]; + error_log("Heartbeat cache was checked: " . json_encode($details)); + } catch (Throwable $e) { + debugging($e, DEBUG_DEVELOPER); + } + } } + diff --git a/lang/en/tool_heartbeat.php b/lang/en/tool_heartbeat.php index 637a027..99958e1 100644 --- a/lang/en/tool_heartbeat.php +++ b/lang/en/tool_heartbeat.php @@ -85,6 +85,13 @@ $string['checktasklatencycheck'] = 'Task latency check'; $string['taskconfigbad'] = 'Bad configurations {$a}'; $string['tasklatencyok'] = 'Task latency OK.'; + +$string['settings:cachecheckheading'] = 'Cache consistency check'; +$string['settings:shouldlogcacheping:heading'] = 'Log cache ping'; +$string['settings:shouldlogcacheping:desc'] = 'If enabled, whenever the cache ping is updated (usually once every 24 hrs), a cache_ping event will be triggered'; +$string['settings:shouldlogcachecheck:heading'] = 'Log cache check'; +$string['settings:shouldlogcachecheck:desc'] = 'If enabled, whenever the cache ping is checked (whenever the cachecheck check is executed) a cache_check event will be triggered'; + /* * Privacy provider (GDPR) */ diff --git a/settings.php b/settings.php index 6439d16..7892ae1 100644 --- a/settings.php +++ b/settings.php @@ -95,5 +95,27 @@ $settings->add(new admin_setting_configtextarea('tool_heartbeat/tasklatencymonitoring', get_string('tasklatencymonitoring', 'tool_heartbeat'), get_string('tasklatencymonitoring_desc', 'tool_heartbeat', $example), '', PARAM_TEXT)); + + // Cache consistency check settings. + $settings->add(new admin_setting_heading('tool_heartbeat/cachechecksettings', + get_string('settings:cachecheckheading', 'tool_heartbeat'), + '' + )); + + $settings->add(new admin_setting_configcheckbox('tool_heartbeat/shouldlogcacheping', + get_string('settings:shouldlogcacheping:heading', 'tool_heartbeat'), + get_string('settings:shouldlogcacheping:desc', 'tool_heartbeat'), + // Since pinging only happens usually once every 24 hrs, we default this on as it is quite lightweight. + 1 + )); + + $settings->add(new admin_setting_configcheckbox('tool_heartbeat/shouldlogcachecheck', + get_string('settings:shouldlogcachecheck:heading', 'tool_heartbeat'), + get_string('settings:shouldlogcachecheck:desc', 'tool_heartbeat'), + // This happens every time the check api cachecheck is called, which is a lot more often than pinging. + // For e.g. with external monitoring, it could be once or more per minute. + // So its defaulted to off unless turned on for specific debugging. + 0 + )); } } diff --git a/version.php b/version.php index 41c4544..85209f4 100644 --- a/version.php +++ b/version.php @@ -24,8 +24,8 @@ defined('MOODLE_INTERNAL') || die(); -$plugin->version = 2023102400; -$plugin->release = 2023102400; // Match release exactly to version. +$plugin->version = 2023102401; +$plugin->release = 2023102401; // Match release exactly to version. $plugin->requires = 2012120311; // Deep support going back to 2.4. $plugin->supported = [24, 401]; $plugin->component = 'tool_heartbeat';