[#165] Add cachecheck logging

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,34 +102,88 @@ 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');
     }
 
     /**
      * Sets a timestamp in config from web or cron
      * @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);
+            }
         }
     }
 }

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);
+        }
+    }
 }
+

lang/en/tool_heartbeat.php

@@ -87,6 +87,12 @@
 $string['tasklatencyok'] = 'Task latency OK.';
 $string['checkfailingtaskcheck'] = 'Failing tasks';
 
+$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 <code>cache_ping</code> 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 <code>cachecheck</code> check is executed) a <code>cache_check</code> event will be triggered';
+
 /*
  * Privacy provider (GDPR)
  */

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
+        ));
     }
 }

version.php

@@ -24,8 +24,8 @@
 
 defined('MOODLE_INTERNAL') || die();
 
-$plugin->version   = 2023110700;
-$plugin->release   = 2023110700; // Match release exactly to version.
+$plugin->version   = 2023112000;
+$plugin->release   = 2023112000; // Match release exactly to version.
 $plugin->requires  = 2020061500; // Support for 3.9 and above, due to the Check API.
 $plugin->supported = [39, 401];
 $plugin->component = 'tool_heartbeat';