MDL-76649 quiz statistics task: output more useful trace info

At the moment, quiz_statistics\task\recalculate gives no useful
information about what it is doing, which makes it hard to investigate
if the task fails. This commit makes it more usefully verbose.

Also, following this change, one instance of this task will not
run for more than one hour at a time.

As part of this commit, I have added a new helper mtrace_exception.
to consistently log exceptions in scheduled tasks. It is sad to
add a new function to moodlelib.php, but that seemed the logical place.
Looking at other tasks, this method is badly needed. Many are just
logging the ->getMessage() which is normaly insufficient for proper
debugging. However, swiching all existing tasks to use the new function
will need to wait for a future MDL.

lib/moodlelib.php

@@ -9280,6 +9280,25 @@ function mtrace($string, $eol="\n", $sleep=0) {
     }
 }
 
+/**
+ * Helper to {@see mtrace()} an exception or throwable, including all relevant information.
+ *
+ * @param Throwable $e the error to ouptput.
+ */
+function mtrace_exception(Throwable $e): void {
+    $info = get_exception_info($e);
+
+    $message = $info->message;
+    if ($info->debuginfo) {
+        $message .= "\n\n" . $info->debuginfo;
+    }
+    if ($info->backtrace) {
+        $message .= "\n\n" . format_backtrace($info->backtrace, true);
+    }
+
+    mtrace($message);
+}
+
 /**
  * Replace 1 or more slashes or backslashes to 1 slash
  *

lib/setuplib.php

@@ -499,11 +499,12 @@ function print_error($errorcode, $module = 'error', $link = '', $a = null, $debu
 
 /**
  * Returns detailed information about specified exception.
- * @param exception $ex
- * @return object
+ *
+ * @param Throwable $ex any sort of exception or throwable.
+ * @return stdClass standardised info to display. Fields are clear if you look at the end of this function.
  */
-function get_exception_info($ex) {
-    global $CFG, $DB, $SESSION;
+function get_exception_info($ex): stdClass {
+    global $CFG;
 
     if ($ex instanceof moodle_exception) {
         $errorcode = $ex->errorcode;

lib/upgrade.txt

@@ -1,7 +1,12 @@
 This files describes API changes in core libraries and APIs,
 information provided here is intended especially for developers.
 
+=== 4.0.6 ===
+
+* There is a new helper function mtrace_exception to help with reporting exceptions you have caught in scheduled tasks.
+
 === 4.0.5 ===
+
 * For plugins that override secondary navigation, the namespace for the custom secondary navigation class has
   changed. It was (for example) mod_mymodule\local\views\secondary but is now
   mod_mymodule\navigation\views\secondary. The old location will continue to work, but will be deprecated in 4.1.

mod/quiz/report/statistics/classes/task/recalculate.php

@@ -36,21 +36,33 @@ require_once($CFG->dirroot . '/mod/quiz/report/statistics/report.php');
  * @license    http://www.gnu.org/copyleft/gpl.html GNU GPL v3 or later
  */
 class recalculate extends \core\task\scheduled_task {
+    /** @var int the maximum length of time one instance of this task will run. */
+    const TIME_LIMIT = 3600;
 
-    public function get_name() {
+    public function get_name(): string {
         return get_string('recalculatetask', 'quiz_statistics');
     }
 
-    public function execute() {
+    public function execute(): void {
         global $DB;
+        $stoptime = time() + self::TIME_LIMIT;
+        $dateformat = get_string('strftimedatetimeshortaccurate', 'core_langconfig');
+
         // TODO: MDL-75197, add quizid in quiz_statistics so that it is simpler to find quizzes for stats calculation.
         // Only calculate stats for quizzes which have recently finished attempt.
         $sql = "
-            SELECT qa.quiz, MAX(qa.timefinish) as timefinish
+            SELECT q.id AS quizid,
+                   q.name AS quizname,
+                   c.id AS courseid,
+                   c.shortname AS courseshortname,
+                   MAX(qa.timefinish) AS mostrecentattempttime,
+                   COUNT(1) AS numberofattempts
               FROM {quiz_attempts} qa
+              JOIN {quiz} q ON q.id = qa.quiz
+              JOIN {course} c ON c.id = q.course
              WHERE qa.preview = 0
                AND qa.state = :quizstatefinished
-          GROUP BY qa.quiz
+          GROUP BY q.id, q.name, c.id, c.shortname
         ";
 
         $params = [
@@ -59,30 +71,50 @@ class recalculate extends \core\task\scheduled_task {
 
         $latestattempts = $DB->get_records_sql($sql, $params);
 
+        $anyexception = null;
         foreach ($latestattempts as $attempt) {
-            $quizobj = quiz::create($attempt->quiz);
+            if (time() >= $stoptime) {
+                mtrace("This task has been running for more than " .
+                        format_time(self::TIME_LIMIT) . " so stopping this execution.");
+                break;
+            }
+
+            mtrace("  Examining quiz '$attempt->quizname' ($attempt->quizid) in course " .
+                    "$attempt->courseshortname ($attempt->courseid) with most recent attempt at " .
+                    userdate($attempt->mostrecentattempttime, $dateformat) . ".");
+            $quizobj = quiz::create($attempt->quizid);
             $quiz = $quizobj->get_quiz();
             // Hash code for question stats option in question bank.
             $qubaids = quiz_statistics_qubaids_condition($quiz->id, new \core\dml\sql_join(), $quiz->grademethod);
 
             // Check if there is any existing question stats, and it has been calculated after latest quiz attempt.
-            $records = $DB->get_records_select(
-                'quiz_statistics',
-                'hashcode = :hashcode AND timemodified > :timefinish',
-                [
-                    'hashcode' => $qubaids->get_hash_code(),
-                    'timefinish' => $attempt->timefinish
-                ]
-            );
+            $lateststatstime = $DB->get_field('quiz_statistics', 'COALESCE(MAX(timemodified), 0)',
+                    ['hashcode' => $qubaids->get_hash_code()]);
 
-            if (empty($records)) {
+            if ($lateststatstime >= $attempt->mostrecentattempttime) {
+                mtrace("    Statistics already calculated at " . userdate($lateststatstime, $dateformat) .
+                        " so nothing to do for this quiz.");
+                continue;
+            }
+
+            mtrace("    Calculating statistics for $attempt->numberofattempts attempts, starting at " .
+                    userdate(time(), $dateformat) . " ...");
+            try {
                 $report = new quiz_statistics_report();
-                // Clear old cache.
                 $report->clear_cached_data($qubaids);
-                // Calculate new stats.
                 $report->calculate_questions_stats_for_question_bank($quiz->id);
+                mtrace("    Calculations completed at " . userdate(time(), $dateformat) . ".");
+
+            } catch (\Throwable $e) {
+                // We don't want an exception from one quiz to stop processing of other quizzes.
+                mtrace_exception($e);
+                $anyexception = $e;
             }
         }
-        return true;
+
+        if ($anyexception) {
+            // If there was any error, ensure the task fails.
+            throw $anyexception;
+        }
     }
 }