MDL-49399 task: Add task logging API
authorAndrew Nicols <andrew@nicols.co.uk>
Tue, 4 Dec 2018 02:39:56 +0000 (10:39 +0800)
committerAndrew Nicols <andrew@nicols.co.uk>
Wed, 16 Jan 2019 04:14:25 +0000 (12:14 +0800)
17 files changed:
admin/settings/server.php
admin/tool/task/cli/schedule_task.php
config-dist.php
lang/en/admin.php
lib/classes/task/database_logger.php [new file with mode: 0644]
lib/classes/task/logmanager.php [new file with mode: 0644]
lib/classes/task/manager.php
lib/classes/task/task_log_cleanup_task.php [new file with mode: 0644]
lib/classes/task/task_logger.php [new file with mode: 0644]
lib/cronlib.php
lib/db/install.xml
lib/db/tasks.php
lib/db/upgrade.php
lib/moodlelib.php
lib/tests/task_database_logger_test.php [new file with mode: 0644]
lib/tests/task_logging_test.php [new file with mode: 0644]
version.php

index f4c24c0..73efce1 100644 (file)
@@ -4,7 +4,6 @@
 
 if ($hassiteconfig) { // speedup for non-admins, add all caps used on this page
 
-
 // "systempaths" settingpage
 $temp = new admin_settingpage('systempaths', new lang_string('systempaths','admin'));
 $temp->add(new admin_setting_configexecutable('pathtophp', new lang_string('pathtophp', 'admin'),
@@ -212,6 +211,45 @@ $temp->add(new admin_setting_configtext('curltimeoutkbitrate', new lang_string('
 $ADMIN->add('server', $temp);
 
 
+$ADMIN->add('server', new admin_category('taskconfig', new lang_string('taskadmintitle', 'admin')));
+$temp = new admin_settingpage('tasklogging', new lang_string('tasklogging','admin'));
+$temp->add(
+    new admin_setting_configselect(
+        'task_logmode',
+        new lang_string('task_logmode', 'admin'),
+        new lang_string('task_logmode_desc', 'admin'),
+        \core\task\logmanager::MODE_ALL,
+        [
+            \core\task\logmanager::MODE_ALL => new lang_string('task_logmode_all', 'admin'),
+            \core\task\logmanager::MODE_FAILONLY => new lang_string('task_logmode_failonly', 'admin'),
+            \core\task\logmanager::MODE_NONE => new lang_string('task_logmode_none', 'admin'),
+        ]
+    )
+);
+
+if (\core\task\logmanager::uses_standard_settings()) {
+    $temp->add(
+        new admin_setting_configduration(
+            'task_logretention',
+            new \lang_string('task_logretention', 'admin'),
+            new \lang_string('task_logretention_desc', 'admin'),
+            28 * DAYSECS
+        )
+    );
+
+    $temp->add(
+        new admin_setting_configtext(
+            'task_logretainruns',
+            new \lang_string('task_logretainruns', 'admin'),
+            new \lang_string('task_logretainruns_desc', 'admin'),
+            20,
+            PARAM_INT
+        )
+    );
+
+}
+$ADMIN->add('taskconfig', $temp);
+
 // E-mail settings.
 $ADMIN->add('server', new admin_category('email', new lang_string('categoryemail', 'admin')));
 
index 0de826c..cf03700 100644 (file)
@@ -129,6 +129,7 @@ if ($execute = $options['execute']) {
     $predbqueries = $DB->perf_get_queries();
     $pretime = microtime(true);
 
+    \core\task\logmanager::start_logging($task);
     $fullname = $task->get_name() . ' (' . get_class($task) . ')';
     mtrace('Execute scheduled task: ' . $fullname);
     // NOTE: it would be tricky to move this code to \core\task\manager class,
index 18cbe31..29f9b79 100644 (file)
@@ -545,6 +545,15 @@ $CFG->admin = 'admin';
 // on a shared file system that supports locking.
 //      $CFG->lock_file_root = $CFG->dataroot . '/lock';
 //
+//
+// Alternative task logging.
+// Since Moodle 3.7 the output of al scheduled and adhoc tasks is stored in the database and it is possible to use an
+// alternative task logging mechanism.
+// To set the alternative task logging mechanism in config.php you can use the following settings, providing the
+// alternative class name that will be auto-loaded.
+//
+//      $CFG->task_log_class = '\\local_mytasklogger\\logger';
+//
 // Moodle 2.9 allows administrators to customise the list of supported file types.
 // To add a new filetype or override the definition of an existing one, set the
 // customfiletypes variable like this:
index c2aad42..86f77cd 100644 (file)
@@ -1164,6 +1164,16 @@ $string['tablesnosave'] = 'Changes in tables above are saved automatically.';
 $string['tabselectedtofront'] = 'On tables with tabs, should the row with the currently selected tab be placed at the front';
 $string['tabselectedtofronttext'] = 'Bring selected tab row to front';
 $string['testsiteupgradewarning'] = 'You are currently using the {$a} test site, to upgrade it properly use the command line interface tool';
+$string['task_logmode'] = 'When to log';
+$string['task_logmode_desc'] = 'You can choose when you wish task logging to take place. By default logs are always captured. You can disable logging entirely, or change to only log tasks which fail.';
+$string['task_logmode_none'] = 'Do not log anything';
+$string['task_logmode_all'] = 'Store the log output of all jobs';
+$string['task_logmode_failonly'] = 'Only store logs for jobs which fail';
+$string['task_logretention'] = 'Retention period';
+$string['task_logretention_desc'] = 'The maximum period that logs should be kept for. This setting interacts with the \'Retain runs\' setting: whichever is reached first will apply';
+$string['task_logretainruns'] = 'Retain runs';
+$string['task_logretainruns_desc'] = 'The number of runs of each task to retain. This setting interacts with the \'Retention period\' setting: whichever is reached first will apply.';
+$string['taskadmintitle'] = 'Tasks';
 $string['taskanalyticscleanup'] = 'Analytics cleanup';
 $string['taskautomatedbackup'] = 'Automated backups';
 $string['taskbackupcleanup'] = 'Clean backup tables and logs';
@@ -1176,6 +1186,7 @@ $string['taskcheckforupdates'] = 'Check for updates';
 $string['taskcompletionregular'] = 'Calculate regular completion data';
 $string['taskcompletiondaily'] = 'Completion mark as started';
 $string['taskcontextcleanup'] = 'Cleanup contexts';
+$string['tasklogging'] = 'Task log configuration';
 $string['taskcreatecontexts'] = 'Create missing contexts';
 $string['taskdeletecachetext'] = 'Delete old text cache records';
 $string['taskdeleteincompleteusers'] = 'Delete incomplete users';
@@ -1186,6 +1197,8 @@ $string['taskglobalsearchindex'] = 'Global search indexing';
 $string['taskglobalsearchoptimize'] = 'Global search index optimization';
 $string['taskgradecron'] = 'Background processing for gradebook';
 $string['tasklegacycron'] = 'Legacy cron processing for plugins';
+$string['tasklogcleanup'] = 'Cleanup of task logs';
+$string['tasklogs'] = 'Task logs';
 $string['taskmessagingcleanup'] = 'Background processing for messaging';
 $string['taskpasswordresetcleanup'] = 'Cleanup password reset attempts';
 $string['taskplagiarismcron'] = 'Background processing for legacy cron in plagiarism plugins';
diff --git a/lib/classes/task/database_logger.php b/lib/classes/task/database_logger.php
new file mode 100644 (file)
index 0000000..253e0d2
--- /dev/null
@@ -0,0 +1,144 @@
+<?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/>.
+
+/**
+ * Database logger for task logging.
+ *
+ * @package    core
+ * @copyright  2018 Andrew Nicols <andrew@nicols.co.uk>
+ * @license    http://www.gnu.org/copyleft/gpl.html GNU GPL v3 or later
+ */
+namespace core\task;
+
+defined('MOODLE_INTERNAL') || die();
+
+/**
+ * Database logger for task logging.
+ *
+ * @copyright  2018 Andrew Nicols <andrew@nicols.co.uk>
+ * @license    http://www.gnu.org/copyleft/gpl.html GNU GPL v3 or later
+ */
+class database_logger implements task_logger {
+
+    /** @var int Type constant for a scheduled task */
+    const TYPE_SCHEDULED = 0;
+
+    /** @var int Type constant for an adhoc task */
+    const TYPE_ADHOC = 1;
+
+    /**
+     * Whether the task is configured and ready to log.
+     *
+     * @return  bool
+     */
+    public static function is_configured() : bool {
+        return true;
+    }
+
+    /**
+     * Store the log for the specified task.
+     *
+     * @param   task_base   $task The task that the log belongs to.
+     * @param   string      $logpath The path to the log on disk
+     * @param   bool        $failed Whether the task failed
+     * @param   int         $dbreads The number of DB reads
+     * @param   int         $dbwrites The number of DB writes
+     * @param   float       $timestart The start time of the task
+     * @param   float       $timeend The end time of the task
+     */
+    public static function store_log_for_task(task_base $task, string $logpath, bool $failed,
+            int $dbreads, int $dbwrites, float $timestart, float $timeend) {
+        global $DB;
+
+        // Write this log to the database.
+        $logdata = (object) [
+            'type' => is_a($task, scheduled_task::class) ? self::TYPE_SCHEDULED : self::TYPE_ADHOC,
+            'component' => $task->get_component(),
+            'classname' => get_class($task),
+            'userid' => 0,
+            'timestart' => $timestart,
+            'timeend' => $timeend,
+            'dbreads' => $dbreads,
+            'dbwrites' => $dbwrites,
+            'result' => (int) $failed,
+            'output' => file_get_contents($logpath),
+        ];
+
+        if (is_a($task, adhoc_task::class) && $userid = $task->get_userid()) {
+            $logdata->userid = $userid;
+        }
+
+        $logdata->id = $DB->insert_record('task_log', $logdata);
+    }
+
+    /**
+     * Cleanup old task logs.
+     */
+    public static function cleanup() {
+        global $CFG, $DB;
+
+        // Delete logs older than the retention period.
+        $params = [
+            'retentionperiod' => time() - $CFG->task_logretention,
+        ];
+        $logids = $DB->get_fieldset_select('task_log', 'id', 'timestart < :retentionperiod', $params);
+        self::delete_task_logs($logids);
+
+        // Delete logs to retain a minimum number of logs.
+        $sql = "SELECT classname FROM {task_log} GROUP BY classname HAVING COUNT(classname) > :retaincount";
+        $params = [
+            'retaincount' => $CFG->task_logretainruns,
+        ];
+        $classes = $DB->get_fieldset_sql($sql, $params);
+
+        foreach ($classes as $classname) {
+            $params = [
+                'classname' => $classname,
+            ];
+
+            $retaincount = (int) $CFG->task_logretainruns;
+            $keeplogs = $DB->get_fieldset_sql(
+                    "SELECT id FROM {task_log} WHERE classname = :classname ORDER BY timestart DESC LIMIT {$retaincount}",
+                    $params
+                );
+
+            $notinsql = "";
+            if ($keeplogs) {
+                list($notinsql, $params) = $DB->get_in_or_equal($keeplogs, SQL_PARAMS_NAMED, 'p', false);
+                $params['classname'] = $classname;
+                $notinsql = " AND id {$notinsql}";
+            }
+
+            $logids = $DB->get_fieldset_select('task_log', 'id', "classname = :classname {$notinsql}", $params);
+            self::delete_task_logs($logids);
+        }
+    }
+
+    /**
+     * Delete task logs for the specified logs.
+     *
+     * @param   array   $logids
+     */
+    public static function delete_task_logs(array $logids) {
+        global $DB;
+
+        if (empty($logids)) {
+            return;
+        }
+
+        $DB->delete_records_list('task_log', 'id', $logids);
+    }
+}
diff --git a/lib/classes/task/logmanager.php b/lib/classes/task/logmanager.php
new file mode 100644 (file)
index 0000000..6e2e682
--- /dev/null
@@ -0,0 +1,334 @@
+<?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/>.
+
+/**
+ * Task log manager.
+ *
+ * @package    core
+ * @category   task
+ * @copyright  2018 Andrew Nicols <andrew@nicols.co.uk>
+ * @license    http://www.gnu.org/copyleft/gpl.html GNU GPL v3 or later
+ */
+namespace core\task;
+
+defined('MOODLE_INTERNAL') || die();
+
+/**
+ * Task log manager.
+ *
+ * @copyright  2018 Andrew Nicols <andrew@nicols.co.uk>
+ * @license    http://www.gnu.org/copyleft/gpl.html GNU GPL v3 or later
+ */
+class logmanager {
+
+    /** @var int Do not log anything */
+    const MODE_NONE = 0;
+
+    /** @var int Log all tasks */
+    const MODE_ALL = 1;
+
+    /** @var int Only log fails */
+    const MODE_FAILONLY = 2;
+
+    /** @var int The default chunksize to use in ob_start */
+    const CHUNKSIZE = 1;
+
+    /**
+     * @var \core\task\task_base The task being logged.
+     */
+    protected static $task = null;
+
+    /**
+     * @var \stdClass Metadata about the current log
+     */
+    protected static $taskloginfo = null;
+
+    /**
+     * @var \resource The current filehandle used for logging
+     */
+    protected static $fh = null;
+
+    /**
+     * @var string The path to the log file
+     */
+    protected static $logpath = null;
+
+    /**
+     * @var bool Whether the task logger has been registered with the shutdown handler
+     */
+    protected static $tasklogregistered = false;
+
+    /**
+     * @var int The level of output buffering in place before starting.
+     */
+    protected static $oblevel = null;
+
+    /**
+     * Create a new task logger for the specified task, and prepare for logging.
+     *
+     * @param   \core\task\task_base    $task The task being run
+     */
+    public static function start_logging(task_base $task) {
+        global $DB;
+
+        if (!self::should_log()) {
+            return;
+        }
+
+        // We register a shutdown handler to ensure that logs causing any failures are correctly disposed of.
+        // Note: This must happen before the per-request directory is requested because the shutdown handler may delete
+        // the logfile.
+        if (!self::$tasklogregistered) {
+            \core_shutdown_manager::register_function(function() {
+                // These will only actually do anything if capturing is current active when the thread ended, which
+                // constitutes a failure.
+                \core\task\logmanager::finalise_log(true);
+            });
+
+            self::$tasklogregistered = true;
+        }
+
+        if (self::is_current_output_buffer()) {
+            // We cannot capture when we are already capturing.
+            throw new \coding_exception('Logging is already in progress for task "' . get_class(self::$task) . '". ' .
+                'Nested logging is not supported.');
+        }
+
+        // Store the initial data about the task and current state.
+        self::$task = $task;
+        self::$taskloginfo = (object) [
+            'dbread'    => $DB->perf_get_reads(),
+            'dbwrite'   => $DB->perf_get_writes(),
+            'timestart' => microtime(true),
+        ];
+
+        // For simplicity's sake we always store logs on disk and flush at the end.
+        self::$logpath = make_request_directory() . DIRECTORY_SEPARATOR . "task.log";
+        self::$fh = fopen(self::$logpath, 'w+');
+
+        // Note the level of the current output buffer.
+        // Note: You cannot use ob_get_level() as it will return `1` when the default output buffer is enabled.
+        if ($obstatus = ob_get_status()) {
+            self::$oblevel = $obstatus['level'];
+        } else {
+            self::$oblevel = null;
+        }
+
+        // Start capturing output.
+        ob_start([\core\task\logmanager::class, 'add_line'], self::CHUNKSIZE);
+    }
+
+    /**
+     * Whether logging is possible and should be happening.
+     *
+     * @return  bool
+     */
+    protected static function should_log() : bool {
+        global $CFG;
+
+        // Respect the config setting.
+        if (isset($CFG->task_logmode) && empty($CFG->task_logmode)) {
+            return false;
+        }
+
+        return !empty(self::get_logger_classname());
+    }
+
+    /**
+     * Return the name of the logging class to use.
+     *
+     * @return  string
+     */
+    public static function get_logger_classname() : string {
+        global $CFG;
+
+        if (!empty($CFG->task_log_class)) {
+            // Configuration is present to use an alternative task logging class.
+            return $CFG->task_log_class;
+        }
+
+        // Fall back on the default database logger.
+        return database_logger::class;
+    }
+
+    /**
+     * Whether this task logger has a report available.
+     *
+     * @return  bool
+     */
+    public static function has_log_report() : bool {
+        $loggerclass = self::get_logger_classname();
+
+        return $loggerclass::has_log_report();
+    }
+
+    /**
+     * Whether to use the standard settings fore
+     */
+    public static function uses_standard_settings() : bool {
+        $classname = self::get_logger_classname();
+        if (!class_exists($classname)) {
+            return false;
+        }
+
+        if (is_a($classname, database_logger::class, true)) {
+            return true;
+        }
+
+        return false;
+    }
+
+    /**
+     * Get any URL available for viewing relevant task log reports.
+     *
+     * @param   string      $classname The task class to fetch for
+     * @return  \moodle_url
+     */
+    public static function get_url_for_task_class(string $classname) : \moodle_url {
+        $loggerclass = self::get_logger_classname();
+
+        return $loggerclass::get_url_for_task_class($classname);
+    }
+
+    /**
+     * Whether we are the current log collector.
+     *
+     * @return  bool
+     */
+    protected static function is_current_output_buffer() : bool {
+        if (empty(self::$taskloginfo)) {
+            return false;
+        }
+
+        if ($ob = ob_get_status()) {
+            return 'core\\task\\logmanager::add_line' == $ob['name'];
+        }
+
+        return false;
+    }
+
+    /**
+     * Whether we are capturing at all.
+     *
+     * @return  bool
+     */
+    protected static function is_capturing() : bool {
+        $buffers = ob_get_status(true);
+        foreach ($buffers as $ob) {
+            if ('core\\task\\logmanager::add_line' == $ob['name']) {
+                return true;
+            }
+        }
+
+        return false;
+    }
+
+    /**
+     * Finish writing for the current task.
+     *
+     * @param   bool    $failed
+     */
+    public static function finalise_log(bool $failed = false) {
+        global $CFG, $DB, $PERF;
+
+        if (!self::should_log()) {
+            return;
+        }
+
+        if (!self::is_capturing()) {
+            // Not capturing anything.
+            return;
+        }
+
+        // Ensure that all logs are closed.
+        $buffers = ob_get_status(true);
+        foreach (array_reverse($buffers) as $ob) {
+            if (null !== self::$oblevel) {
+                if ($ob['level'] <= self::$oblevel) {
+                    // Only close as far as the initial output buffer level.
+                    break;
+                }
+            }
+
+            // End and flush this buffer.
+            ob_end_flush();
+
+            if ('core\\task\\logmanager::add_line' == $ob['name']) {
+                break;
+            }
+        }
+        self::$oblevel = null;
+
+        // Flush any remaining buffer.
+        self::flush();
+
+        // Close and unset the FH.
+        fclose(self::$fh);
+        self::$fh = null;
+
+        if ($failed || empty($CFG->task_logmode) || self::MODE_ALL == $CFG->task_logmode) {
+            // Finalise the log.
+            $loggerclass = self::get_logger_classname();
+            $loggerclass::store_log_for_task(
+                self::$task,
+                self::$logpath,
+                $failed,
+                $DB->perf_get_reads() - self::$taskloginfo->dbread,
+                $DB->perf_get_writes() - self::$taskloginfo->dbwrite - $PERF->logwrites,
+                self::$taskloginfo->timestart,
+                microtime(true)
+            );
+        }
+
+        // Tidy up.
+        self::$logpath = null;
+        self::$taskloginfo = null;
+    }
+
+    /**
+     * Flush the current output buffer.
+     *
+     * This function will ensure that we are the current output buffer handler.
+     */
+    public static function flush() {
+        // We only call ob_flush if the current output buffer belongs to us.
+        if (self::is_current_output_buffer()) {
+            ob_flush();
+        }
+    }
+
+    /**
+     * Add a log record to the task log.
+     *
+     * @param   string  $log
+     * @return  string
+     */
+    public static function add_line(string $log) : string {
+        if (empty(self::$taskloginfo)) {
+            return $log;
+        }
+
+        if (empty(self::$fh)) {
+            return $log;
+        }
+
+        if (self::is_current_output_buffer()) {
+            fwrite(self::$fh, $log);
+        }
+
+        return $log;
+    }
+}
index fe4124a..6e8f467 100644 (file)
@@ -590,6 +590,9 @@ class manager {
             $task->get_cron_lock()->release();
         }
         $task->get_lock()->release();
+
+        // Finalise the log output.
+        \core\task\logmanager::finalise_log(true);
     }
 
     /**
@@ -600,6 +603,9 @@ class manager {
     public static function adhoc_task_complete(adhoc_task $task) {
         global $DB;
 
+        // Finalise the log output.
+        \core\task\logmanager::finalise_log();
+
         // Delete the adhoc task record - it is finished.
         $DB->delete_records('task_adhoc', array('id' => $task->get_id()));
 
@@ -643,6 +649,9 @@ class manager {
             $task->get_cron_lock()->release();
         }
         $task->get_lock()->release();
+
+        // Finalise the log output.
+        \core\task\logmanager::finalise_log(true);
     }
 
     /**
@@ -670,6 +679,9 @@ class manager {
     public static function scheduled_task_complete(scheduled_task $task) {
         global $DB;
 
+        // Finalise the log output.
+        \core\task\logmanager::finalise_log();
+
         $classname = self::get_canonical_class_name($task);
         $record = $DB->get_record('task_scheduled', array('classname' => $classname));
         if ($record) {
diff --git a/lib/classes/task/task_log_cleanup_task.php b/lib/classes/task/task_log_cleanup_task.php
new file mode 100644 (file)
index 0000000..188171a
--- /dev/null
@@ -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/>.
+
+/**
+ * Task to cleanup task logs.
+ *
+ * @package    core
+ * @copyright  2018 Andrew Nicols <andrew@nicols.co.uk>
+ * @license    http://www.gnu.org/copyleft/gpl.html GNU GPL v3 or later
+ */
+namespace core\task;
+
+defined('MOODLE_INTERNAL') || die();
+
+/**
+ * A task to cleanup log entries for tasks.
+ *
+ * @copyright  2018 Andrew Nicols <andrew@nicols.co.uk>
+ * @license    http://www.gnu.org/copyleft/gpl.html GNU GPL v3 or later
+ */
+class task_log_cleanup_task extends scheduled_task {
+
+    /**
+     * Get a descriptive name for this task (shown to admins).
+     *
+     * @return string
+     */
+    public function get_name() {
+        return get_string('tasklogcleanup', 'admin');
+    }
+
+    /**
+     * Perform the cleanup task.
+     */
+    public function execute() {
+        if (\core\task\database_logger::class == \core\task\logmanager::get_logger_classname()) {
+            \core\task\database_logger::cleanup();
+        }
+    }
+}
diff --git a/lib/classes/task/task_logger.php b/lib/classes/task/task_logger.php
new file mode 100644 (file)
index 0000000..c7b322a
--- /dev/null
@@ -0,0 +1,57 @@
+<?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/>.
+
+/**
+ * Interface for task logging.
+ *
+ * @package    core
+ * @category   task
+ * @copyright  2018 Andrew Nicols <andrew@nicols.co.uk>
+ * @license    http://www.gnu.org/copyleft/gpl.html GNU GPL v3 or later
+ */
+namespace core\task;
+
+defined('MOODLE_INTERNAL') || die();
+
+/**
+ * Interface for task logging.
+ *
+ * @copyright  2018 Andrew Nicols <andrew@nicols.co.uk>
+ * @license    http://www.gnu.org/copyleft/gpl.html GNU GPL v3 or later
+ */
+interface task_logger {
+    /**
+     * Whether the task is configured and ready to log.
+     *
+     * @return  bool
+     */
+    public static function is_configured() : bool;
+
+    /**
+     * Store the log for the specified task.
+     *
+     * @param   task_base   $task The task that the log belongs to.
+     * @param   string      $logpath The path to the log on disk
+     * @param   bool        $failed Whether the task failed
+     * @param   int         $dbreads The number of DB reads
+     * @param   int         $dbwrites The number of DB writes
+     * @param   float       $timestart The start time of the task
+     * @param   float       $timeend The end time of the task
+     */
+    public static function store_log_for_task(task_base $task, string $logpath, bool $failed,
+            int $dbreads, int $dbwrites, float $timestart, float $timeend);
+
+}
index 589af74..b11be3f 100644 (file)
@@ -93,6 +93,8 @@ function cron_run() {
 function cron_run_inner_scheduled_task(\core\task\task_base $task) {
     global $CFG, $DB;
 
+    \core\task\logmanager::start_logging($task);
+
     $fullname = $task->get_name() . ' (' . get_class($task) . ')';
     mtrace('Execute scheduled task: ' . $fullname);
     cron_trace_time_and_memory();
@@ -144,6 +146,9 @@ function cron_run_inner_scheduled_task(\core\task\task_base $task) {
  */
 function cron_run_inner_adhoc_task(\core\task\adhoc_task $task) {
     global $DB, $CFG;
+
+    \core\task\logmanager::start_logging($task);
+
     mtrace("Execute adhoc task: " . get_class($task));
     cron_trace_time_and_memory();
     $predbqueries = null;
index 2c57cda..7de20fc 100644 (file)
@@ -1,5 +1,5 @@
 <?xml version="1.0" encoding="UTF-8" ?>
-<XMLDB PATH="lib/db" VERSION="20181205" COMMENT="XMLDB file for core Moodle tables"
+<XMLDB PATH="lib/db" VERSION="20181210" COMMENT="XMLDB file for core Moodle tables"
     xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
     xsi:noNamespaceSchemaLocation="../../lib/xmldb/xmldb.xsd"
 >
         <FIELD NAME="dbreads" TYPE="int" LENGTH="10" NOTNULL="true" SEQUENCE="false" COMMENT="The number of DB reads performed during the task."/>
         <FIELD NAME="dbwrites" TYPE="int" LENGTH="10" NOTNULL="true" SEQUENCE="false" COMMENT="The number of DB writes performed during the task."/>
         <FIELD NAME="result" TYPE="int" LENGTH="2" NOTNULL="true" SEQUENCE="false" COMMENT="Whether the task was successful or not. 0 = pass; 1 = fail."/>
+        <FIELD NAME="output" TYPE="text" NOTNULL="true" SEQUENCE="false"/>
       </FIELDS>
       <KEYS>
         <KEY NAME="primary" TYPE="primary" FIELDS="id"/>
index 38e8d85..93ffff0 100644 (file)
@@ -356,4 +356,13 @@ $tasks = array(
         'dayofweek' => '*',
         'month' => '*'
     ),
+    array(
+        'classname' => 'core\task\task_log_cleanup_task',
+        'blocking' => 0,
+        'minute' => 'R',
+        'hour' => 'R',
+        'day' => '*',
+        'dayofweek' => '*',
+        'month' => '*'
+    ),
 );
index 80dc8ec..bf81f99 100644 (file)
@@ -2548,5 +2548,19 @@ function xmldb_main_upgrade($oldversion) {
         upgrade_main_savepoint(true, 2019011500.00);
     }
 
+    if ($oldversion < 2019011501.00) {
+        // Define field output to be added to task_log.
+        $table = new xmldb_table('task_log');
+        $field = new xmldb_field('output', XMLDB_TYPE_TEXT, null, null, XMLDB_NOTNULL, null, null, 'result');
+
+        // Conditionally launch add field output.
+        if (!$dbman->field_exists($table, $field)) {
+            $dbman->add_field($table, $field);
+        }
+
+        // Main savepoint reached.
+        upgrade_main_savepoint(true, 2019011501.00);
+    }
+
     return true;
 }
index 4cfc923..d3b85d2 100644 (file)
@@ -8953,10 +8953,15 @@ function mtrace($string, $eol="\n", $sleep=0) {
         return;
     } else if (defined('STDOUT') && !PHPUNIT_TEST && !defined('BEHAT_TEST')) {
         fwrite(STDOUT, $string.$eol);
+
+        // We must explicitly call the add_line function here.
+        // Uses of fwrite to STDOUT are not picked up by ob_start.
+        \core\task\logmanager::add_line("{$string}{$eol}");
     } else {
         echo $string . $eol;
     }
 
+    // Flush again.
     flush();
 
     // Delay to keep message on user's screen in case of subsequent redirect.
diff --git a/lib/tests/task_database_logger_test.php b/lib/tests/task_database_logger_test.php
new file mode 100644 (file)
index 0000000..d2c43b2
--- /dev/null
@@ -0,0 +1,505 @@
+<?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/>.
+
+/**
+ * This file contains the unit tests for the database task logger.
+ *
+ * @package   core
+ * @category  phpunit
+ * @copyright 2018 Andrew Nicols <andrew@nicols.co.uk>
+ * @license   http://www.gnu.org/copyleft/gpl.html GNU GPL v3 or later
+ */
+
+defined('MOODLE_INTERNAL') || die();
+
+use \core\task\database_logger;
+
+/**
+ * This file contains the unit tests for the database task logger.
+ *
+ * @copyright 2018 Andrew Nicols <andrew@nicols.co.uk>
+ * @license   http://www.gnu.org/copyleft/gpl.html GNU GPL v3 or later
+ */
+class task_database_logger_testcase extends advanced_testcase {
+
+    /**
+     * @var \moodle_database The original database prior to mocking
+     */
+    protected $DB;
+
+    /**
+     * Setup to backup the database before mocking.
+     */
+    public function setUp() {
+        global $DB;
+
+        $this->DB = $DB;
+    }
+
+    /**
+     * Tear down to unmock the database where it was mocked.
+     */
+    public function tearDown() {
+        global $DB;
+
+        $DB = $this->DB;
+        $this->DB = null;
+    }
+
+    /**
+     * Ensure that store_log_for_task works with a passing scheduled task.
+     */
+    public function test_store_log_for_task_scheduled() {
+        global $DB;
+
+        $this->resetAfterTest();
+
+        $endtime = microtime(true);
+        $starttime = $endtime - 4;
+
+        $logdir = make_request_directory();
+        $logpath = "{$logdir}/log.txt";
+        file_put_contents($logpath, 'Example content');
+
+        $task = new \core\task\cache_cron_task();
+        database_logger::store_log_for_task($task, $logpath, false, 1, 2, $starttime, $endtime);
+
+        $logs = $DB->get_records('task_log');
+        $this->assertCount(1, $logs);
+
+        $log = reset($logs);
+        $this->assertEquals(file_get_contents($logpath), $log->output);
+        $this->assertEquals(0, $log->result);
+        $this->assertEquals(database_logger::TYPE_SCHEDULED, $log->type);
+        $this->assertEquals('core\task\cache_cron_task', $log->classname);
+        $this->assertEquals(0, $log->userid);
+    }
+
+    /**
+     * Ensure that store_log_for_task works with a passing adhoc task.
+     */
+    public function test_store_log_for_task_adhoc() {
+        global $DB;
+
+        $this->resetAfterTest();
+
+        $endtime = microtime(true);
+        $starttime = $endtime - 4;
+
+        $logdir = make_request_directory();
+        $logpath = "{$logdir}/log.txt";
+        file_put_contents($logpath, 'Example content');
+
+        $task = $this->getMockBuilder(\core\task\adhoc_task::class)
+            ->setMethods(['get_component', 'execute'])
+            ->getMock();
+
+        $task->method('get_component')->willReturn('core_test');
+
+        database_logger::store_log_for_task($task, $logpath, false, 1, 2, $starttime, $endtime);
+
+        $logs = $DB->get_records('task_log');
+        $this->assertCount(1, $logs);
+
+        $log = reset($logs);
+        $this->assertEquals(file_get_contents($logpath), $log->output);
+        $this->assertEquals(0, $log->result);
+        $this->assertEquals(database_logger::TYPE_ADHOC, $log->type);
+    }
+
+    /**
+     * Ensure that store_log_for_task works with a failing scheduled task.
+     */
+    public function test_store_log_for_task_failed_scheduled() {
+        global $DB;
+
+        $this->resetAfterTest();
+
+        $endtime = microtime(true);
+        $starttime = $endtime - 4;
+
+        $logdir = make_request_directory();
+        $logpath = "{$logdir}/log.txt";
+        file_put_contents($logpath, 'Example content');
+
+        $task = new \core\task\cache_cron_task();
+        database_logger::store_log_for_task($task, $logpath, true, 1, 2, $starttime, $endtime);
+
+        $logs = $DB->get_records('task_log');
+        $this->assertCount(1, $logs);
+
+        $log = reset($logs);
+        $this->assertEquals(file_get_contents($logpath), $log->output);
+        $this->assertEquals(1, $log->result);
+        $this->assertEquals(database_logger::TYPE_SCHEDULED, $log->type);
+        $this->assertEquals('core\task\cache_cron_task', $log->classname);
+        $this->assertEquals(0, $log->userid);
+    }
+
+    /**
+     * Ensure that store_log_for_task works with a failing adhoc task.
+     */
+    public function test_store_log_for_task_failed_adhoc() {
+        global $DB;
+
+        $this->resetAfterTest();
+
+        $endtime = microtime(true);
+        $starttime = $endtime - 4;
+
+        $logdir = make_request_directory();
+        $logpath = "{$logdir}/log.txt";
+        file_put_contents($logpath, 'Example content');
+
+        $task = $this->getMockBuilder(\core\task\adhoc_task::class)
+            ->setMethods(['get_component', 'execute'])
+            ->getMock();
+
+        $task->method('get_component')->willReturn('core_test');
+
+        database_logger::store_log_for_task($task, $logpath, true, 1, 2, $starttime, $endtime);
+
+        $logs = $DB->get_records('task_log');
+        $this->assertCount(1, $logs);
+
+        $log = reset($logs);
+        $this->assertEquals(file_get_contents($logpath), $log->output);
+        $this->assertEquals(1, $log->result);
+        $this->assertEquals(database_logger::TYPE_ADHOC, $log->type);
+        $this->assertEquals(0, $log->userid);
+    }
+    /**
+     * Ensure that store_log_for_task works with a passing adhoc task run as a specific user.
+     */
+    public function test_store_log_for_task_adhoc_userid() {
+        global $DB;
+
+        $this->resetAfterTest();
+
+        $endtime = microtime(true);
+        $starttime = $endtime - 4;
+
+        $logdir = make_request_directory();
+        $logpath = "{$logdir}/log.txt";
+        file_put_contents($logpath, 'Example content');
+
+        $task = $this->getMockBuilder(\core\task\adhoc_task::class)
+            ->setMethods(['get_component', 'execute', 'get_userid'])
+            ->getMock();
+
+        $task->method('get_component')->willReturn('core_test');
+        $task->method('get_userid')->willReturn(99);
+
+        database_logger::store_log_for_task($task, $logpath, false, 1, 2, $starttime, $endtime);
+
+        $logs = $DB->get_records('task_log');
+        $this->assertCount(1, $logs);
+
+        $log = reset($logs);
+        $this->assertEquals(file_get_contents($logpath), $log->output);
+        $this->assertEquals(0, $log->result);
+        $this->assertEquals(database_logger::TYPE_ADHOC, $log->type);
+        $this->assertEquals(99, $log->userid);
+    }
+
+    /**
+     * Ensure that the delete_task_logs function performs necessary deletion tasks.
+     *
+     * @dataProvider    delete_task_logs_provider
+     * @param   mixed   $ids
+     */
+    public function test_delete_task_logs($ids) {
+        $DB = $this->mock_database();
+        $DB->expects($this->once())
+            ->method('delete_records_list')
+            ->with(
+                $this->equalTo('task_log'),
+                $this->equalTo('id'),
+                $this->callback(function($deletedids) use ($ids) {
+                    sort($ids);
+                    $idvalues = array_values($deletedids);
+                    sort($idvalues);
+
+                    return $ids == $idvalues;
+                })
+            );
+
+        database_logger::delete_task_logs($ids);
+    }
+
+    /**
+     * Data provider for delete_task_logs tests.
+     *
+     * @return  array
+     */
+    public function delete_task_logs_provider() : array {
+        return [
+            [
+                [0],
+                [1],
+                [1, 2, 3, 4, 5],
+            ],
+        ];
+    }
+
+    /**
+     * Ensure that the retention period applies correctly.
+     */
+    public function test_cleanup_retention() {
+        global $DB;
+
+        $this->resetAfterTest();
+
+        // Set a high value for task_logretainruns so that it does no interfere.
+        set_config('task_logretainruns', 1000);
+
+        // Create sample log data - 1 run per hour for 3 days - round down to the start of the hour to avoid time race conditions.
+        $date = new DateTime();
+        $date->setTime($date->format('G'), 0);
+        $baselogtime = $date->getTimestamp();
+
+        for ($i = 0; $i < 3 * 24; $i++) {
+            $task = new \core\task\cache_cron_task();
+            $logpath = __FILE__;
+            database_logger::store_log_for_task($task, $logpath, false, 1, 2, $date->getTimestamp(), $date->getTimestamp() + MINSECS);
+
+            $date->sub(new \DateInterval('PT1H'));
+        }
+
+        // Initially there should be 72 runs.
+        $this->assertCount(72, $DB->get_records('task_log'));
+
+        // Note: We set the retention time to a period like DAYSECS minus an adjustment.
+        // The adjustment is to account for the time taken during setup.
+
+        // With a retention period of 2 * DAYSECS, there should only be 47-48 left.
+        set_config('task_logretention', (2 * DAYSECS) - (time() - $baselogtime));
+        \core\task\database_logger::cleanup();
+        $this->assertGreaterThanOrEqual(47, $DB->count_records('task_log'));
+        $this->assertLessThanOrEqual(48, $DB->count_records('task_log'));
+
+        // The oldest should be no more than 48 hours old.
+        $oldest = $DB->get_records('task_log', [], 'timestart DESC', 'timestart', 0, 1);
+        $oldest = reset($oldest);
+        $this->assertGreaterThan(time() - (48 * DAYSECS), $oldest->timestart);
+
+        // With a retention period of DAYSECS, there should only be 23 left.
+        set_config('task_logretention', DAYSECS - (time() - $baselogtime));
+        \core\task\database_logger::cleanup();
+        $this->assertGreaterThanOrEqual(23, $DB->count_records('task_log'));
+        $this->assertLessThanOrEqual(24, $DB->count_records('task_log'));
+
+        // The oldest should be no more than 24 hours old.
+        $oldest = $DB->get_records('task_log', [], 'timestart DESC', 'timestart', 0, 1);
+        $oldest = reset($oldest);
+        $this->assertGreaterThan(time() - (24 * DAYSECS), $oldest->timestart);
+
+        // With a retention period of 0.5 DAYSECS, there should only be 11 left.
+        set_config('task_logretention', (DAYSECS / 2) - (time() - $baselogtime));
+        \core\task\database_logger::cleanup();
+        $this->assertGreaterThanOrEqual(11, $DB->count_records('task_log'));
+        $this->assertLessThanOrEqual(12, $DB->count_records('task_log'));
+
+        // The oldest should be no more than 12 hours old.
+        $oldest = $DB->get_records('task_log', [], 'timestart DESC', 'timestart', 0, 1);
+        $oldest = reset($oldest);
+        $this->assertGreaterThan(time() - (12 * DAYSECS), $oldest->timestart);
+    }
+
+    /**
+     * Ensure that the run-count retention applies.
+     */
+    public function test_cleanup_retainruns() {
+        global $DB;
+
+        $this->resetAfterTest();
+
+        // Set a high value for task_logretention so that it does not interfere.
+        set_config('task_logretention', YEARSECS);
+
+        // Create sample log data - 2 tasks, once per hour for 3 days.
+        $date = new DateTime();
+        $date->setTime($date->format('G'), 0);
+        $firstdate = $date->getTimestamp();
+
+        for ($i = 0; $i < 3 * 24; $i++) {
+            $task = new \core\task\cache_cron_task();
+            $logpath = __FILE__;
+            database_logger::store_log_for_task($task, $logpath, false, 1, 2, $date->getTimestamp(), $date->getTimestamp() + MINSECS);
+
+            $task = new \core\task\badges_cron_task();
+            $logpath = __FILE__;
+            database_logger::store_log_for_task($task, $logpath, false, 1, 2, $date->getTimestamp(), $date->getTimestamp() + MINSECS);
+
+            $date->sub(new \DateInterval('PT1H'));
+        }
+        $lastdate = $date->getTimestamp();
+
+        // Initially there should be 144 runs - 72 for each task.
+        $this->assertEquals(144, $DB->count_records('task_log'));
+        $this->assertEquals(72, $DB->count_records('task_log', ['classname' => \core\task\cache_cron_task::class]));
+        $this->assertEquals(72, $DB->count_records('task_log', ['classname' => \core\task\badges_cron_task::class]));
+
+        // Grab the records for comparison.
+        $cachecronrecords = array_values($DB->get_records('task_log', ['classname' => \core\task\cache_cron_task::class], 'timestart DESC'));
+        $badgescronrecords = array_values($DB->get_records('task_log', ['classname' => \core\task\badges_cron_task::class], 'timestart DESC'));
+
+        // Configured to retain 144 should have no effect.
+        set_config('task_logretainruns', 144);
+        \core\task\database_logger::cleanup();
+        $this->assertEquals(144, $DB->count_records('task_log'));
+        $this->assertEquals(72, $DB->count_records('task_log', ['classname' => \core\task\cache_cron_task::class]));
+        $this->assertEquals(72, $DB->count_records('task_log', ['classname' => \core\task\badges_cron_task::class]));
+
+        // The list of records should be identical.
+        $this->assertEquals($cachecronrecords, array_values($DB->get_records('task_log', ['classname' => \core\task\cache_cron_task::class], 'timestart DESC')));
+        $this->assertEquals($badgescronrecords, array_values($DB->get_records('task_log', ['classname' => \core\task\badges_cron_task::class], 'timestart DESC')));
+
+        // Configured to retain 72 should have no effect either.
+        set_config('task_logretainruns', 72);
+        \core\task\database_logger::cleanup();
+        $this->assertEquals(144, $DB->count_records('task_log'));
+        $this->assertEquals(72, $DB->count_records('task_log', ['classname' => \core\task\cache_cron_task::class]));
+        $this->assertEquals(72, $DB->count_records('task_log', ['classname' => \core\task\badges_cron_task::class]));
+
+        // The list of records should now only contain the first 72 of each.
+        $this->assertEquals(
+            array_slice($cachecronrecords, 0, 72),
+            array_values($DB->get_records('task_log', ['classname' => \core\task\cache_cron_task::class], 'timestart DESC'))
+        );
+        $this->assertEquals(
+            array_slice($badgescronrecords, 0, 72),
+            array_values($DB->get_records('task_log', ['classname' => \core\task\badges_cron_task::class], 'timestart DESC'))
+        );
+
+        // Configured to only retain 24 should bring that down to a total of 48, or 24 each.
+        set_config('task_logretainruns', 24);
+        \core\task\database_logger::cleanup();
+        $this->assertEquals(48, $DB->count_records('task_log'));
+        $this->assertEquals(24, $DB->count_records('task_log', ['classname' => \core\task\cache_cron_task::class]));
+        $this->assertEquals(24, $DB->count_records('task_log', ['classname' => \core\task\badges_cron_task::class]));
+
+        // The list of records should now only contain the first 24 of each.
+        $this->assertEquals(
+            array_slice($cachecronrecords, 0, 24),
+            array_values($DB->get_records('task_log', ['classname' => \core\task\cache_cron_task::class], 'timestart DESC'))
+        );
+        $this->assertEquals(
+            array_slice($badgescronrecords, 0, 24),
+            array_values($DB->get_records('task_log', ['classname' => \core\task\badges_cron_task::class], 'timestart DESC'))
+        );
+
+        // Configured to only retain 5 should bring that down to a total of 10, or 5 each.
+        set_config('task_logretainruns', 5);
+        \core\task\database_logger::cleanup();
+        $this->assertEquals(10, $DB->count_records('task_log'));
+        $this->assertEquals(5, $DB->count_records('task_log', ['classname' => \core\task\cache_cron_task::class]));
+        $this->assertEquals(5, $DB->count_records('task_log', ['classname' => \core\task\badges_cron_task::class]));
+
+        // The list of records should now only contain the first 5 of each.
+        $this->assertEquals(
+            array_slice($cachecronrecords, 0, 5),
+            array_values($DB->get_records('task_log', ['classname' => \core\task\cache_cron_task::class], 'timestart DESC'))
+        );
+        $this->assertEquals(
+            array_slice($badgescronrecords, 0, 5),
+            array_values($DB->get_records('task_log', ['classname' => \core\task\badges_cron_task::class], 'timestart DESC'))
+        );
+
+        // Configured to only retain 0 should bring that down to none.
+        set_config('task_logretainruns', 0);
+        \core\task\database_logger::cleanup();
+        $this->assertEquals(0, $DB->count_records('task_log'));
+    }
+
+    /**
+     * Ensure that the retention period applies correctly when combined with the run count retention.
+     */
+    public function test_cleanup_combined() {
+        global $DB;
+
+        $this->resetAfterTest();
+
+        // Create sample log data - 2 tasks, once per hour for 3 days.
+        $date = new DateTime();
+        $date->setTime($date->format('G'), 0);
+        $baselogtime = $date->getTimestamp();
+
+        for ($i = 0; $i < 3 * 24; $i++) {
+            $task = new \core\task\cache_cron_task();
+            $logpath = __FILE__;
+            database_logger::store_log_for_task($task, $logpath, false, 1, 2, $date->getTimestamp(), $date->getTimestamp() + MINSECS);
+
+            $task = new \core\task\badges_cron_task();
+            $logpath = __FILE__;
+            database_logger::store_log_for_task($task, $logpath, false, 1, 2, $date->getTimestamp(), $date->getTimestamp() + MINSECS);
+
+            $date->sub(new \DateInterval('PT1H'));
+        }
+
+        // Initially there should be 144 runs - 72 for each task.
+        $this->assertEquals(144, $DB->count_records('task_log'));
+        $this->assertEquals(72, $DB->count_records('task_log', ['classname' => \core\task\cache_cron_task::class]));
+        $this->assertEquals(72, $DB->count_records('task_log', ['classname' => \core\task\badges_cron_task::class]));
+
+        // Note: We set the retention time to a period like DAYSECS minus an adjustment.
+        // The adjustment is to account for the time taken during setup.
+
+        // With a retention period of 2 * DAYSECS, there should only be 94-96 left.
+        // The run count is a higher number so it will have no effect.
+        set_config('task_logretention', (2 * DAYSECS) - (time() - $baselogtime));
+        set_config('task_logretainruns', 50);
+        \core\task\database_logger::cleanup();
+        $this->assertGreaterThanOrEqual(94, $DB->count_records('task_log'));
+        $this->assertLessThanOrEqual(96, $DB->count_records('task_log'));
+        $this->assertGreaterThanOrEqual(47, $DB->count_records('task_log', ['classname' => \core\task\cache_cron_task::class]));
+        $this->assertLessThanOrEqual(48, $DB->count_records('task_log', ['classname' => \core\task\cache_cron_task::class]));
+        $this->assertGreaterThanOrEqual(47, $DB->count_records('task_log', ['classname' => \core\task\badges_cron_task::class]));
+        $this->assertLessThanOrEqual(48, $DB->count_records('task_log', ['classname' => \core\task\badges_cron_task::class]));
+
+        // We should retain the most recent 48 so the oldest will be no more than 48 hours old.
+        $oldest = $DB->get_records('task_log', [], 'timestart DESC', 'timestart', 0, 1);
+        $oldest = reset($oldest);
+        $this->assertGreaterThan(time() - (48 * DAYSECS), $oldest->timestart);
+
+        // Reducing the retain runs count to 10 should reduce the total logs to 20, overriding the time constraint.
+        set_config('task_logretainruns', 10);
+        \core\task\database_logger::cleanup();
+        $this->assertEquals(20, $DB->count_records('task_log'));
+        $this->assertEquals(10, $DB->count_records('task_log', ['classname' => \core\task\cache_cron_task::class]));
+        $this->assertEquals(10, $DB->count_records('task_log', ['classname' => \core\task\badges_cron_task::class]));
+
+        // We should retain the most recent 10 so the oldeste will be no more than 10 hours old.
+        $oldest = $DB->get_records('task_log', [], 'timestart DESC', 'timestart', 0, 1);
+        $oldest = reset($oldest);
+        $this->assertGreaterThan(time() - (10 * DAYSECS), $oldest->timestart);
+    }
+
+    /**
+     * Mock the database.
+     */
+    protected function mock_database() {
+        global $DB;
+
+        $DB = $this->getMockBuilder(\moodle_database::class)
+            ->getMock();
+
+        $DB->method('get_record')
+            ->willReturn((object) []);
+
+        return $DB;
+    }
+}
diff --git a/lib/tests/task_logging_test.php b/lib/tests/task_logging_test.php
new file mode 100644 (file)
index 0000000..aaed98c
--- /dev/null
@@ -0,0 +1,558 @@
+<?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/>.
+
+/**
+ * This file contains the unit tests for the task logging system.
+ *
+ * @package   core
+ * @category  phpunit
+ * @copyright 2018 Andrew Nicols <andrew@nicols.co.uk>
+ * @license   http://www.gnu.org/copyleft/gpl.html GNU GPL v3 or later
+ */
+
+defined('MOODLE_INTERNAL') || die();
+require_once(__DIR__ . '/fixtures/task_fixtures.php');
+
+
+/**
+ * This file contains the unit tests for the task logging system.
+ *
+ * @copyright 2018 Andrew Nicols <andrew@nicols.co.uk>
+ * @license   http://www.gnu.org/copyleft/gpl.html GNU GPL v3 or later
+ */
+class core_task_logmanager extends advanced_testcase {
+
+    /**
+     * @var \moodle_database The original database prior to mocking
+     */
+    protected $DB;
+
+    /**
+     * Relevant tearDown for logging tests.
+     */
+    public function tearDown() {
+        global $DB;
+
+        // Ensure that any logging is always ended.
+        \core\task\logmanager::finalise_log();
+
+        if (null !== $this->DB) {
+            $DB = $this->DB;
+            $this->DB = null;
+        }
+    }
+
+    /**
+     * When the logmode is set to none, logging should not start.
+     */
+    public function test_logmode_none() {
+        global $CFG;
+        $this->resetAfterTest();
+
+        $CFG->task_logmode = \core\task\logmanager::MODE_NONE;
+
+        $initialbufferstate = ob_get_status();
+
+        $task = $this->get_test_adhoc_task();
+        \core\task\logmanager::start_logging($task);
+
+        // There will be no additional output buffer.
+        $this->assertEquals($initialbufferstate, ob_get_status());
+    }
+
+    /**
+     * When the logmode is set to all that log capture is started.
+     */
+    public function test_start_logmode_all() {
+        global $CFG;
+        $this->resetAfterTest();
+
+        $CFG->task_logmode = \core\task\logmanager::MODE_ALL;
+
+        $initialbufferstate = ob_get_status();
+
+        $task = $this->get_test_adhoc_task();
+        \core\task\logmanager::start_logging($task);
+
+        // Fetch the new output buffer state.
+        $state = ob_get_status();
+
+        // There will be no additional output buffer.
+        $this->assertNotEquals($initialbufferstate, $state);
+    }
+
+    /**
+     * When the logmode is set to fail that log capture is started.
+     */
+    public function test_start_logmode_fail() {
+        global $CFG;
+        $this->resetAfterTest();
+
+        $CFG->task_logmode = \core\task\logmanager::MODE_FAILONLY;
+
+        $initialbufferstate = ob_get_status();
+
+        $task = $this->get_test_adhoc_task();
+        \core\task\logmanager::start_logging($task);
+
+        // Fetch the new output buffer state.
+        $state = ob_get_status();
+
+        // There will be no additional output buffer.
+        $this->assertNotEquals($initialbufferstate, $state);
+    }
+
+    /**
+     * When the logmode is set to fail, passing adhoc tests should not be logged.
+     */
+    public function test_logmode_fail_with_passing_adhoc_task() {
+        global $CFG;
+        $this->resetAfterTest();
+
+        $CFG->task_logmode = \core\task\logmanager::MODE_FAILONLY;
+
+        $logger = $this->get_mocked_logger();
+
+        $initialbufferstate = ob_get_status();
+
+        $task = $this->get_test_adhoc_task();
+        \core\task\logmanager::start_logging($task);
+
+        \core\task\manager::adhoc_task_complete($task);
+
+        $this->assertEmpty($logger::$storelogfortask);
+    }
+
+    /**
+     * When the logmode is set to fail, passing scheduled tests should not be logged.
+     */
+    public function test_logmode_fail_with_passing_scheduled_task() {
+        global $CFG;
+        $this->resetAfterTest();
+
+        $CFG->task_logmode = \core\task\logmanager::MODE_FAILONLY;
+
+        $logger = $this->get_mocked_logger();
+
+        $initialbufferstate = ob_get_status();
+
+        $task = $this->get_test_scheduled_task();
+        \core\task\logmanager::start_logging($task);
+
+        \core\task\manager::scheduled_task_complete($task);
+
+        $this->assertEmpty($logger::$storelogfortask);
+    }
+
+    /**
+     * When the logmode is set to fail, failing adhoc tests should be logged.
+     */
+    public function test_logmode_fail_with_failing_adhoc_task() {
+        global $CFG;
+
+        $this->resetAfterTest();
+
+        // Mock the database. Marking jobs as failed updates a DB record which doesn't exist.
+        $this->mock_database();
+
+        $task = $this->get_test_adhoc_task();
+
+        $CFG->task_logmode = \core\task\logmanager::MODE_FAILONLY;
+
+        $logger = $this->get_mocked_logger();
+
+        \core\task\logmanager::start_logging($task);
+        \core\task\manager::adhoc_task_failed($task);
+
+        $this->assertCount(1, $logger::$storelogfortask);
+        $this->assertEquals($task, $logger::$storelogfortask[0][0]);
+        $this->assertTrue($logger::$storelogfortask[0][2]);
+    }
+
+    /**
+     * When the logmode is set to fail, failing scheduled tests should be logged.
+     */
+    public function test_logmode_fail_with_failing_scheduled_task() {
+        global $CFG;
+
+        $this->resetAfterTest();
+
+        // Mock the database. Marking jobs as failed updates a DB record which doesn't exist.
+        $this->mock_database();
+
+        $task = $this->get_test_scheduled_task();
+
+        $CFG->task_logmode = \core\task\logmanager::MODE_FAILONLY;
+
+        $logger = $this->get_mocked_logger();
+
+        \core\task\logmanager::start_logging($task);
+        \core\task\manager::scheduled_task_failed($task);
+
+        $this->assertCount(1, $logger::$storelogfortask);
+        $this->assertEquals($task, $logger::$storelogfortask[0][0]);
+        $this->assertTrue($logger::$storelogfortask[0][2]);
+    }
+
+    /**
+     * When the logmode is set to fail, failing adhoc tests should be logged.
+     */
+    public function test_logmode_any_with_failing_adhoc_task() {
+        global $CFG;
+
+        $this->resetAfterTest();
+
+        // Mock the database. Marking jobs as failed updates a DB record which doesn't exist.
+        $this->mock_database();
+
+        $task = $this->get_test_adhoc_task();
+
+        $CFG->task_logmode = \core\task\logmanager::MODE_FAILONLY;
+
+        $logger = $this->get_mocked_logger();
+
+        \core\task\logmanager::start_logging($task);
+        \core\task\manager::adhoc_task_failed($task);
+
+        $this->assertCount(1, $logger::$storelogfortask);
+        $this->assertEquals($task, $logger::$storelogfortask[0][0]);
+        $this->assertTrue($logger::$storelogfortask[0][2]);
+    }
+
+    /**
+     * When the logmode is set to fail, failing scheduled tests should be logged.
+     */
+    public function test_logmode_any_with_failing_scheduled_task() {
+        global $CFG;
+
+        $this->resetAfterTest();
+
+        // Mock the database. Marking jobs as failed updates a DB record which doesn't exist.
+        $this->mock_database();
+
+        $task = $this->get_test_scheduled_task();
+
+        $CFG->task_logmode = \core\task\logmanager::MODE_FAILONLY;
+
+        $logger = $this->get_mocked_logger();
+
+        \core\task\logmanager::start_logging($task);
+        \core\task\manager::scheduled_task_failed($task);
+
+        $this->assertCount(1, $logger::$storelogfortask);
+        $this->assertEquals($task, $logger::$storelogfortask[0][0]);
+        $this->assertTrue($logger::$storelogfortask[0][2]);
+    }
+
+    /**
+     * When the logmode is set to fail, passing adhoc tests should be logged.
+     */
+    public function test_logmode_any_with_passing_adhoc_task() {
+        global $CFG;
+
+        $this->resetAfterTest();
+
+        $this->mock_database();
+
+        $task = $this->get_test_adhoc_task();
+
+        $CFG->task_logmode = \core\task\logmanager::MODE_ALL;
+
+        $logger = $this->get_mocked_logger();
+
+        \core\task\logmanager::start_logging($task);
+        \core\task\manager::adhoc_task_complete($task);
+
+        $this->assertCount(1, $logger::$storelogfortask);
+        $this->assertEquals($task, $logger::$storelogfortask[0][0]);
+        $this->assertFalse($logger::$storelogfortask[0][2]);
+    }
+
+    /**
+     * When the logmode is set to fail, passing scheduled tests should be logged.
+     */
+    public function test_logmode_any_with_passing_scheduled_task() {
+        global $CFG;
+
+        $this->resetAfterTest();
+
+        $this->mock_database();
+
+        $task = $this->get_test_scheduled_task();
+
+        $CFG->task_logmode = \core\task\logmanager::MODE_ALL;
+
+        $logger = $this->get_mocked_logger();
+
+        \core\task\logmanager::start_logging($task);
+        \core\task\manager::scheduled_task_complete($task);
+
+        $this->assertCount(1, $logger::$storelogfortask);
+        $this->assertEquals($task, $logger::$storelogfortask[0][0]);
+        $this->assertFalse($logger::$storelogfortask[0][2]);
+    }
+
+    /**
+     * Ensure that start_logging cannot be called in a nested fashion.
+     */
+    public function test_prevent_nested_logging() {
+        $this->resetAfterTest();
+
+        $task = $this->get_test_adhoc_task();
+        \core\task\logmanager::start_logging($task);
+
+        $this->expectException(\coding_exception::class);
+        \core\task\logmanager::start_logging($task);
+    }
+
+    /**
+     * Ensure that logging can be called after a previous log has finished.
+     */
+    public function test_repeated_usages() {
+        $this->resetAfterTest();
+
+        $logger = $this->get_mocked_logger();
+
+        $task = $this->get_test_adhoc_task();
+        \core\task\logmanager::start_logging($task);
+        \core\task\logmanager::finalise_log();
+
+        \core\task\logmanager::start_logging($task);
+        \core\task\logmanager::finalise_log();
+
+        $this->assertCount(2, $logger::$storelogfortask);
+        $this->assertEquals($task, $logger::$storelogfortask[0][0]);
+        $this->assertFalse($logger::$storelogfortask[0][2]);
+        $this->assertEquals($task, $logger::$storelogfortask[1][0]);
+        $this->assertFalse($logger::$storelogfortask[1][2]);
+    }
+
+    /**
+     * Enusre that when finalise_log is called when logging is not active, nothing happens.
+     */
+    public function test_finalise_log_no_logging() {
+        $initialbufferstate = ob_get_status();
+
+        \core\task\logmanager::finalise_log();
+
+        // There will be no additional output buffer.
+        $this->assertEquals($initialbufferstate, ob_get_status());
+    }
+
+    /**
+     * When log capture is enabled, calls to the flush function should cause log output to be both returned and captured.
+     */
+    public function test_flush_on_own_buffer() {
+        $this->resetAfterTest();
+
+        $logger = $this->get_mocked_logger();
+
+        $testoutput = "I am the output under test.\n";
+
+        $task = $this->get_test_adhoc_task();
+        \core\task\logmanager::start_logging($task);
+
+        echo $testoutput;
+
+        $this->expectOutputString($testoutput);
+        \core\task\logmanager::flush();
+
+        // Finalise the log.
+        \core\task\logmanager::finalise_log();
+
+        $this->assertCount(1, $logger::$storelogfortask);
+        $this->assertEquals($testoutput, file_get_contents($logger::$storelogfortask[0][1]));
+    }
+
+    /**
+     * When log capture is enabled, calls to the flush function should not affect any subsequent ob_start.
+     */
+    public function test_flush_does_not_flush_inner_buffers() {
+        $this->resetAfterTest();
+
+        $logger = $this->get_mocked_logger();
+
+        $testoutput = "I am the output under test.\n";
+
+        $task = $this->get_test_adhoc_task();
+        \core\task\logmanager::start_logging($task);
+
+        ob_start();
+        echo $testoutput;
+        ob_end_clean();
+
+        \core\task\logmanager::flush();
+
+        // Finalise the log.
+        \core\task\logmanager::finalise_log();
+
+        $this->assertCount(1, $logger::$storelogfortask);
+
+        // The task logger should not have captured the content of the inner buffer.
+        $this->assertEquals('', file_get_contents($logger::$storelogfortask[0][1]));
+    }
+
+    /**
+     * When log capture is enabled, calls to the flush function should not affect any subsequent ob_start.
+     */
+    public function test_inner_flushed_buffers_are_logged() {
+        $this->resetAfterTest();
+
+        $logger = $this->get_mocked_logger();
+
+        $testoutput = "I am the output under test.\n";
+
+        $task = $this->get_test_adhoc_task();
+        \core\task\logmanager::start_logging($task);
+
+        // We are going to flush the inner buffer. That means that we should expect the output immediately.
+        $this->expectOutputString($testoutput);
+
+        ob_start();
+        echo $testoutput;
+        ob_end_flush();
+
+        // Finalise the log.
+        \core\task\logmanager::finalise_log();
+
+        $this->assertCount(1, $logger::$storelogfortask);
+
+        // The task logger should not have captured the content of the inner buffer.
+        $this->assertEquals($testoutput, file_get_contents($logger::$storelogfortask[0][1]));
+    }
+
+    /**
+     * Get an example adhoc task to use for testing.
+     *
+     * @return  \core\task\adhoc_task
+     */
+    protected function get_test_adhoc_task() : \core\task\adhoc_task {
+        $task = $this->getMockForAbstractClass(\core\task\adhoc_task::class);
+
+        // Mock a lock on the task.
+        $lock = $this->getMockBuilder(\core\lock\lock::class)
+            ->disableOriginalConstructor()
+            ->getMock();
+        $task->set_lock($lock);
+
+        return $task;
+    }
+
+    /**
+     * Get an example scheduled task to use for testing.
+     *
+     * @return  \core\task\scheduled_task
+     */
+    protected function get_test_scheduled_task() : \core\task\scheduled_task {
+        $task = $this->getMockForAbstractClass(\core\task\scheduled_task::class);
+
+        // Mock a lock on the task.
+        $lock = $this->getMockBuilder(\core\lock\lock::class)
+            ->disableOriginalConstructor()
+            ->getMock();
+        $task->set_lock($lock);
+
+        return $task;
+    }
+
+    /**
+     * Create and configure a mocked task logger.
+     *
+     * @return  \core\task\task_logger
+     */
+    protected function get_mocked_logger() {
+        global $CFG;
+
+        // We will modify config for the alternate logging class therefore we mnust reset after the test.
+        $this->resetAfterTest();
+
+        // Note PHPUnit does not support mocking static functions.
+        $CFG->task_log_class = \task_logging_test_mocked_logger::class;
+        \task_logging_test_mocked_logger::test_reset();
+
+        return $CFG->task_log_class;
+    }
+
+    /**
+     * Mock the database.
+     */
+    protected function mock_database() {
+        global $DB;
+
+        // Store the old Database for restoration in reset.
+        $this->DB = $DB;
+
+        $DB = $this->getMockBuilder(\moodle_database::class)
+            ->getMock();
+
+        $DB->method('get_record')
+            ->willReturn((object) []);
+    }
+}
+
+/**
+ * Mocked logger.
+ *
+ * @copyright 2018 Andrew Nicols <andrew@nicols.co.uk>
+ * @license   http://www.gnu.org/copyleft/gpl.html GNU GPL v3 or later
+ */
+class task_logging_test_mocked_logger implements \core\task\task_logger {
+
+    /**
+     * @var bool Whether this is configured.
+     */
+    public static $isconfigured = true;
+
+    /**
+     * @var array Arguments that store_log_for_task was called with.
+     */
+    public static $storelogfortask = [];
+
+    /**
+     * Reset the test class.
+     */
+    public static function test_reset() {
+        self::$isconfigured = true;
+        self::$storelogfortask = [];
+        self::$haslogreport = true;
+    }
+
+    /**
+     * Whether the task is configured and ready to log.
+     *
+     * @return  bool
+     */
+    public static function is_configured() : bool {
+        return self::$isconfigured;
+    }
+
+    /**
+     * Store the log for the specified task.
+     *
+     * @param   \core\task\task_base   $task The task that the log belongs to.
+     * @param   string      $logpath The path to the log on disk
+     * @param   bool        $failed Whether the task failed
+     * @param   int         $dbreads The number of DB reads
+     * @param   int         $dbwrites The number of DB writes
+     * @param   float       $timestart The start time of the task
+     * @param   float       $timeend The end time of the task
+     */
+    public static function store_log_for_task(\core\task\task_base $task, string $logpath, bool $failed,
+            int $dbreads, int $dbwrites, float $timestart, float $timeend) {
+        self::$storelogfortask[] = func_get_args();
+    }
+
+}
index be82e4b..84b00cb 100644 (file)
@@ -29,7 +29,7 @@
 
 defined('MOODLE_INTERNAL') || die();
 
-$version  = 2019011500.00;              // YYYYMMDD      = weekly release date of this DEV branch.
+$version  = 2019011501.00;              // YYYYMMDD      = weekly release date of this DEV branch.
                                         //         RR    = release increments - 00 in DEV branches.
                                         //           .XX = incremental changes.