[#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,84 @@ 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) || true) {
+            debugging("\nHEARTBEAT doing {$type} ping\n", DEBUG_DEVELOPER);
+            self::set_cache_ping_value($type, $time);
+
+            if (get_config('tool_heartbeat', 'shouldlogcacheping')) {
+                lib::record_cache_pinged($currentcache, $currentdb, $time, $type);
+            }
         }
     }
 }

classes/event/cache_check.php

@@ -0,0 +1,53 @@
+<?php
+// This file is part of Moodle - http://moodle.org/
+//
+// Moodle is free software: you can redistribute it and/or modify
+// it under the terms of the GNU General Public License as published by
+// the Free Software Foundation, either version 3 of the License, or
+// (at your option) any later version.
+//
+// Moodle is distributed in the hope that it will be useful,
+// but WITHOUT ANY WARRANTY; without even the implied warranty of
+// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+// GNU General Public License for more details.
+//
+// You should have received a copy of the GNU General Public License
+// along with Moodle.  If not, see <http://www.gnu.org/licenses/>.
+
+namespace tool_heartbeat\event;
+
+use context_system;
+
+/**
+ * Heartbeat cache checked event class
+ *
+ * @package tool_heartbeat
+ * @copyright Catalyst IT Australia
+ * @author Matthew Hilton <[email protected]>
+ * @license    http://www.gnu.org/copyleft/gpl.html GNU GPL v3 or later
+ */
+class cache_check extends \core\event\base {
+    /**
+     * Inialises event
+     */
+    protected function init() {
+        $this->data['crud'] = 'r';
+        $this->data['edulevel'] = self::LEVEL_OTHER;
+    }
+
+    /**
+     * Returns name
+     * @return string
+     */
+    public static function get_name() {
+        return get_string('event:cachecheck', 'tool_heartbeat');
+    }
+
+    /**
+     * Returns description
+     * @return string
+     */
+    public function get_description() {
+        return "The cache was checked: " . json_encode($this->data['other']);
+    }
+}

classes/event/cache_ping.php

@@ -0,0 +1,53 @@
+<?php
+// This file is part of Moodle - http://moodle.org/
+//
+// Moodle is free software: you can redistribute it and/or modify
+// it under the terms of the GNU General Public License as published by
+// the Free Software Foundation, either version 3 of the License, or
+// (at your option) any later version.
+//
+// Moodle is distributed in the hope that it will be useful,
+// but WITHOUT ANY WARRANTY; without even the implied warranty of
+// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+// GNU General Public License for more details.
+//
+// You should have received a copy of the GNU General Public License
+// along with Moodle.  If not, see <http://www.gnu.org/licenses/>.
+
+namespace tool_heartbeat\event;
+
+use context_system;
+
+/**
+ * Heartbeat cache pinged class
+ *
+ * @package tool_heartbeat
+ * @copyright Catalyst IT Australia
+ * @author Matthew Hilton <[email protected]>
+ * @license    http://www.gnu.org/copyleft/gpl.html GNU GPL v3 or later
+ */
+class cache_ping extends \core\event\base {
+    /**
+     * Inialises event
+     */
+    protected function init() {
+        $this->data['crud'] = 'u';
+        $this->data['edulevel'] = self::LEVEL_OTHER;
+    }
+
+    /**
+     * Returns name
+     * @return string
+     */
+    public static function get_name() {
+        return get_string('event:cacheping', 'tool_heartbeat');
+    }
+
+    /**
+     * Returns description
+     * @return string
+     */
+    public function get_description() {
+        return "The cache ping was updated: " . json_encode($this->data['other']);
+    }
+}

classes/lib.php

@@ -16,6 +16,12 @@
 
 namespace tool_heartbeat;
 
+use cache;
+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 +65,80 @@ 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 $new
+     * @param string $where cron or web
+     */
+    public static function record_cache_pinged(int $previousincache, int $previousindb, int $new, string $where) {
+        try {
+            $details = array_merge(
+                self::get_cache_log_details(),
+                [
+                    'previousvalueindb' => $previousindb,
+                    'previousvalueincache' => $previousincache,
+                    'newvalue' => $new,
+                    'where' => $where,
+                ]
+            );
+
+            $event = cache_ping::create([
+                'other' => $details,
+                'contextid' => context_system::instance()->id,
+            ]);
+            $event->trigger();
+        } 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 = array_merge(
+                self::get_cache_log_details(),
+                [
+                    'valueindb' => $valueindb,
+                    'valueincache' => $valueincache,
+                    'where' => $where,
+                ]
+            );
+
+            $event = cache_check::create([
+                'other' => $details,
+                'contextid' => context_system::instance()->id,
+            ]);
+            $event->trigger();
+        } catch (Throwable $e) {
+            debugging($e, DEBUG_DEVELOPER);
+        }
+    }
+
+    /**
+     * Gets useful information about caches that can be logged when doing cache check ping
+     * @return array
+     */
+    private static function get_cache_log_details() {
+        global $CFG;
+
+        $cache = cache::make('core', 'config');
+        $siteidentifier = !empty($CFG->siteidentifier) ? md5((string) $CFG->siteidentifier) : '';
+
+        return [
+            'config' => [
+                'siteidentifierhash' => $siteidentifier,
+                'cacheidentifier' => $cache->get_identifier(),
+                'session_redix_prefix' => $CFG->session_redis_prefix ?? null,
+            ],
+        ];
+    }
 }
+

lang/en/tool_heartbeat.php

@@ -85,6 +85,16 @@
 $string['checktasklatencycheck'] = 'Task latency check';
 $string['taskconfigbad'] = 'Bad configurations {$a}';
 $string['tasklatencyok'] = 'Task latency OK.';
+
+$string['event:cachecheck'] = 'Cache check event';
+$string['event:cacheping'] = 'Cache ping event';
+
+$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   = 2023102400;
-$plugin->release   = 2023102400; // Match release exactly to version.
+$plugin->version   = 2023102400.01;
+$plugin->release   = 2023102400.01; // Match release exactly to version.
 $plugin->requires  = 2012120311; // Deep support going back to 2.4.
 $plugin->supported = [24, 401];
 $plugin->component = 'tool_heartbeat';