diff --git a/admin/settings/server.php b/admin/settings/server.php index f4c24c0f3f0..73efce12e45 100644 --- a/admin/settings/server.php +++ b/admin/settings/server.php @@ -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'))); diff --git a/admin/tool/task/cli/schedule_task.php b/admin/tool/task/cli/schedule_task.php index 0de826c1655..cf03700bd4f 100644 --- a/admin/tool/task/cli/schedule_task.php +++ b/admin/tool/task/cli/schedule_task.php @@ -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, diff --git a/config-dist.php b/config-dist.php index 18cbe311524..29f9b799d76 100644 --- a/config-dist.php +++ b/config-dist.php @@ -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: diff --git a/lang/en/admin.php b/lang/en/admin.php index c2aad42f376..86f77cd08a2 100644 --- a/lang/en/admin.php +++ b/lang/en/admin.php @@ -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 index 00000000000..253e0d2645f --- /dev/null +++ b/lib/classes/task/database_logger.php @@ -0,0 +1,144 @@ +. + +/** + * Database logger for task logging. + * + * @package core + * @copyright 2018 Andrew Nicols + * @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 + * @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 index 00000000000..6e2e6820abd --- /dev/null +++ b/lib/classes/task/logmanager.php @@ -0,0 +1,334 @@ +. + +/** + * Task log manager. + * + * @package core + * @category task + * @copyright 2018 Andrew Nicols + * @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 + * @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; + } +} diff --git a/lib/classes/task/manager.php b/lib/classes/task/manager.php index fe4124a39e5..6e8f467178c 100644 --- a/lib/classes/task/manager.php +++ b/lib/classes/task/manager.php @@ -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 index 00000000000..188171a5efb --- /dev/null +++ b/lib/classes/task/task_log_cleanup_task.php @@ -0,0 +1,53 @@ +. + +/** + * Task to cleanup task logs. + * + * @package core + * @copyright 2018 Andrew Nicols + * @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 + * @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 index 00000000000..c7b322ac21c --- /dev/null +++ b/lib/classes/task/task_logger.php @@ -0,0 +1,57 @@ +. + +/** + * Interface for task logging. + * + * @package core + * @category task + * @copyright 2018 Andrew Nicols + * @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 + * @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); + +} diff --git a/lib/cronlib.php b/lib/cronlib.php index 589af74503f..b11be3f45ba 100644 --- a/lib/cronlib.php +++ b/lib/cronlib.php @@ -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; diff --git a/lib/db/install.xml b/lib/db/install.xml index 2c57cdaa3da..7de20fcf304 100644 --- a/lib/db/install.xml +++ b/lib/db/install.xml @@ -1,5 +1,5 @@ - @@ -3317,6 +3317,7 @@ + diff --git a/lib/db/tasks.php b/lib/db/tasks.php index 38e8d85c4a7..93ffff03005 100644 --- a/lib/db/tasks.php +++ b/lib/db/tasks.php @@ -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' => '*' + ), ); diff --git a/lib/db/upgrade.php b/lib/db/upgrade.php index 80dc8ec4c38..bf81f99238a 100644 --- a/lib/db/upgrade.php +++ b/lib/db/upgrade.php @@ -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; } diff --git a/lib/moodlelib.php b/lib/moodlelib.php index 4cfc923df44..d3b85d2aac3 100644 --- a/lib/moodlelib.php +++ b/lib/moodlelib.php @@ -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 index 00000000000..d2c43b241a4 --- /dev/null +++ b/lib/tests/task_database_logger_test.php @@ -0,0 +1,505 @@ +. + +/** + * This file contains the unit tests for the database task logger. + * + * @package core + * @category phpunit + * @copyright 2018 Andrew Nicols + * @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 + * @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 index 00000000000..aaed98c5de4 --- /dev/null +++ b/lib/tests/task_logging_test.php @@ -0,0 +1,558 @@ +. + +/** + * This file contains the unit tests for the task logging system. + * + * @package core + * @category phpunit + * @copyright 2018 Andrew Nicols + * @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 + * @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 + * @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(); + } + +} diff --git a/version.php b/version.php index be82e4bb506..84b00cb36d2 100644 --- a/version.php +++ b/version.php @@ -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.