[Summary view]

Differences Between: [Versions 39 and 310]

   1  <?php
   2  // This file is part of Moodle - http://moodle.org/
   3  //
   4  // Moodle is free software: you can redistribute it and/or modify
   5  // it under the terms of the GNU General Public License as published by
   6  // the Free Software Foundation, either version 3 of the License, or
   7  // (at your option) any later version.
   8  //
   9  // Moodle is distributed in the hope that it will be useful,
  10  // but WITHOUT ANY WARRANTY; without even the implied warranty of
  11  // MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
  12  // GNU General Public License for more details.
  13  //
  14  // You should have received a copy of the GNU General Public License
  15  // along with Moodle.  If not, see <http://www.gnu.org/licenses/>.
  16  
  17  /**
  18   * This file contains the unit tests for the database task logger.
  19   *
  20   * @package   core
  21   * @category  phpunit
  22   * @copyright 2018 Andrew Nicols <andrew@nicols.co.uk>
  23   * @license   http://www.gnu.org/copyleft/gpl.html GNU GPL v3 or later
  24   */
  25  
  26  defined('MOODLE_INTERNAL') || die();
  27  
  28  use \core\task\database_logger;
  29  
  30  /**
  31   * This file contains the unit tests for the database task logger.
  32   *
  33   * @copyright 2018 Andrew Nicols <andrew@nicols.co.uk>
  34   * @license   http://www.gnu.org/copyleft/gpl.html GNU GPL v3 or later
  35   */
  36  class task_database_logger_testcase extends advanced_testcase {
  37  
  38      /**
  39       * @var \moodle_database The original database prior to mocking
  40       */
  41      protected $DB;
  42  
  43      /**
  44       * Setup to backup the database before mocking.
  45       */
  46      public function setUp() {
  47          global $DB;
  48  
  49          $this->DB = $DB;
  50      }
  51  
  52      /**
  53       * Tear down to unmock the database where it was mocked.
  54       */
  55      public function tearDown() {
  56          global $DB;
  57  
  58          $DB = $this->DB;
  59          $this->DB = null;
  60      }
  61  
  62      /**
  63       * Ensure that store_log_for_task works with a passing scheduled task.
  64       */
  65      public function test_store_log_for_task_scheduled() {
  66          global $DB;
  67  
  68          $this->resetAfterTest();
  69  
  70          $endtime = microtime(true);
  71          $starttime = $endtime - 4;
  72  
  73          $logdir = make_request_directory();
  74          $logpath = "{$logdir}/log.txt";
  75          file_put_contents($logpath, 'Example content');
  76  
  77          $task = new \core\task\cache_cron_task();
  78          database_logger::store_log_for_task($task, $logpath, false, 1, 2, $starttime, $endtime);
  79  
  80          $logs = $DB->get_records('task_log');
  81          $this->assertCount(1, $logs);
  82  
  83          $log = reset($logs);
  84          $this->assertEquals(file_get_contents($logpath), $log->output);
  85          $this->assertEquals(0, $log->result);
  86          $this->assertEquals(database_logger::TYPE_SCHEDULED, $log->type);
  87          $this->assertEquals('core\task\cache_cron_task', $log->classname);
  88          $this->assertEquals(0, $log->userid);
  89      }
  90  
  91      /**
  92       * Ensure that store_log_for_task works with a passing adhoc task.
  93       */
  94      public function test_store_log_for_task_adhoc() {
  95          global $DB;
  96  
  97          $this->resetAfterTest();
  98  
  99          $endtime = microtime(true);
 100          $starttime = $endtime - 4;
 101  
 102          $logdir = make_request_directory();
 103          $logpath = "{$logdir}/log.txt";
 104          file_put_contents($logpath, 'Example content');
 105  
 106          $task = $this->getMockBuilder(\core\task\adhoc_task::class)
 107              ->setMethods(['get_component', 'execute'])
 108              ->getMock();
 109  
 110          $task->method('get_component')->willReturn('core_test');
 111  
 112          database_logger::store_log_for_task($task, $logpath, false, 1, 2, $starttime, $endtime);
 113  
 114          $logs = $DB->get_records('task_log');
 115          $this->assertCount(1, $logs);
 116  
 117          $log = reset($logs);
 118          $this->assertEquals(file_get_contents($logpath), $log->output);
 119          $this->assertEquals(0, $log->result);
 120          $this->assertEquals(database_logger::TYPE_ADHOC, $log->type);
 121      }
 122  
 123      /**
 124       * Ensure that store_log_for_task works with a failing scheduled task.
 125       */
 126      public function test_store_log_for_task_failed_scheduled() {
 127          global $DB;
 128  
 129          $this->resetAfterTest();
 130  
 131          $endtime = microtime(true);
 132          $starttime = $endtime - 4;
 133  
 134          $logdir = make_request_directory();
 135          $logpath = "{$logdir}/log.txt";
 136          file_put_contents($logpath, 'Example content');
 137  
 138          $task = new \core\task\cache_cron_task();
 139          database_logger::store_log_for_task($task, $logpath, true, 1, 2, $starttime, $endtime);
 140  
 141          $logs = $DB->get_records('task_log');
 142          $this->assertCount(1, $logs);
 143  
 144          $log = reset($logs);
 145          $this->assertEquals(file_get_contents($logpath), $log->output);
 146          $this->assertEquals(1, $log->result);
 147          $this->assertEquals(database_logger::TYPE_SCHEDULED, $log->type);
 148          $this->assertEquals('core\task\cache_cron_task', $log->classname);
 149          $this->assertEquals(0, $log->userid);
 150      }
 151  
 152      /**
 153       * Ensure that store_log_for_task works with a failing adhoc task.
 154       */
 155      public function test_store_log_for_task_failed_adhoc() {
 156          global $DB;
 157  
 158          $this->resetAfterTest();
 159  
 160          $endtime = microtime(true);
 161          $starttime = $endtime - 4;
 162  
 163          $logdir = make_request_directory();
 164          $logpath = "{$logdir}/log.txt";
 165          file_put_contents($logpath, 'Example content');
 166  
 167          $task = $this->getMockBuilder(\core\task\adhoc_task::class)
 168              ->setMethods(['get_component', 'execute'])
 169              ->getMock();
 170  
 171          $task->method('get_component')->willReturn('core_test');
 172  
 173          database_logger::store_log_for_task($task, $logpath, true, 1, 2, $starttime, $endtime);
 174  
 175          $logs = $DB->get_records('task_log');
 176          $this->assertCount(1, $logs);
 177  
 178          $log = reset($logs);
 179          $this->assertEquals(file_get_contents($logpath), $log->output);
 180          $this->assertEquals(1, $log->result);
 181          $this->assertEquals(database_logger::TYPE_ADHOC, $log->type);
 182          $this->assertEquals(0, $log->userid);
 183      }
 184      /**
 185       * Ensure that store_log_for_task works with a passing adhoc task run as a specific user.
 186       */
 187      public function test_store_log_for_task_adhoc_userid() {
 188          global $DB;
 189  
 190          $this->resetAfterTest();
 191  
 192          $endtime = microtime(true);
 193          $starttime = $endtime - 4;
 194  
 195          $logdir = make_request_directory();
 196          $logpath = "{$logdir}/log.txt";
 197          file_put_contents($logpath, 'Example content');
 198  
 199          $task = $this->getMockBuilder(\core\task\adhoc_task::class)
 200              ->setMethods(['get_component', 'execute', 'get_userid'])
 201              ->getMock();
 202  
 203          $task->method('get_component')->willReturn('core_test');
 204          $task->method('get_userid')->willReturn(99);
 205  
 206          database_logger::store_log_for_task($task, $logpath, false, 1, 2, $starttime, $endtime);
 207  
 208          $logs = $DB->get_records('task_log');
 209          $this->assertCount(1, $logs);
 210  
 211          $log = reset($logs);
 212          $this->assertEquals(file_get_contents($logpath), $log->output);
 213          $this->assertEquals(0, $log->result);
 214          $this->assertEquals(database_logger::TYPE_ADHOC, $log->type);
 215          $this->assertEquals(99, $log->userid);
 216      }
 217  
 218      /**
 219       * Ensure that the delete_task_logs function performs necessary deletion tasks.
 220       *
 221       * @dataProvider    delete_task_logs_provider
 222       * @param   mixed   $ids
 223       */
 224      public function test_delete_task_logs($ids) {
 225          $DB = $this->mock_database();
 226          $DB->expects($this->once())
 227              ->method('delete_records_list')
 228              ->with(
 229                  $this->equalTo('task_log'),
 230                  $this->equalTo('id'),
 231                  $this->callback(function($deletedids) use ($ids) {
 232                      sort($ids);
 233                      $idvalues = array_values($deletedids);
 234                      sort($idvalues);
 235  
 236                      return $ids == $idvalues;
 237                  })
 238              );
 239  
 240          database_logger::delete_task_logs($ids);
 241      }
 242  
 243      /**
 244       * Data provider for delete_task_logs tests.
 245       *
 246       * @return  array
 247       */
 248      public function delete_task_logs_provider() : array {
 249          return [
 250              [
 251                  [0],
 252                  [1],
 253                  [1, 2, 3, 4, 5],
 254              ],
 255          ];
 256      }
 257  
 258      /**
 259       * Ensure that the retention period applies correctly.
 260       */
 261      public function test_cleanup_retention() {
 262          global $DB;
 263  
 264          $this->resetAfterTest();
 265  
 266          // Set a high value for task_logretainruns so that it does no interfere.
 267          set_config('task_logretainruns', 1000);
 268  
 269          // Create sample log data - 1 run per hour for 3 days - round down to the start of the hour to avoid time race conditions.
 270          $date = new DateTime();
 271          $date->setTime($date->format('G'), 0);
 272          $baselogtime = $date->getTimestamp();
 273  
 274          for ($i = 0; $i < 3 * 24; $i++) {
 275              $task = new \core\task\cache_cron_task();
 276              $logpath = __FILE__;
 277              database_logger::store_log_for_task($task, $logpath, false, 1, 2, $date->getTimestamp(), $date->getTimestamp() + MINSECS);
 278  
 279              $date->sub(new \DateInterval('PT1H'));
 280          }
 281  
 282          // Initially there should be 72 runs.
 283          $this->assertCount(72, $DB->get_records('task_log'));
 284  
 285          // Note: We set the retention time to a period like DAYSECS minus an adjustment.
 286          // The adjustment is to account for the time taken during setup.
 287  
 288          // With a retention period of 2 * DAYSECS, there should only be 47-48 left.
 289          set_config('task_logretention', (2 * DAYSECS) - (time() - $baselogtime));
 290          \core\task\database_logger::cleanup();
 291          $this->assertGreaterThanOrEqual(47, $DB->count_records('task_log'));
 292          $this->assertLessThanOrEqual(48, $DB->count_records('task_log'));
 293  
 294          // The oldest should be no more than 48 hours old.
 295          $oldest = $DB->get_records('task_log', [], 'timestart DESC', 'timestart', 0, 1);
 296          $oldest = reset($oldest);
 297          $this->assertGreaterThan(time() - (48 * DAYSECS), $oldest->timestart);
 298  
 299          // With a retention period of DAYSECS, there should only be 23 left.
 300          set_config('task_logretention', DAYSECS - (time() - $baselogtime));
 301          \core\task\database_logger::cleanup();
 302          $this->assertGreaterThanOrEqual(23, $DB->count_records('task_log'));
 303          $this->assertLessThanOrEqual(24, $DB->count_records('task_log'));
 304  
 305          // The oldest should be no more than 24 hours old.
 306          $oldest = $DB->get_records('task_log', [], 'timestart DESC', 'timestart', 0, 1);
 307          $oldest = reset($oldest);
 308          $this->assertGreaterThan(time() - (24 * DAYSECS), $oldest->timestart);
 309  
 310          // With a retention period of 0.5 DAYSECS, there should only be 11 left.
 311          set_config('task_logretention', (DAYSECS / 2) - (time() - $baselogtime));
 312          \core\task\database_logger::cleanup();
 313          $this->assertGreaterThanOrEqual(11, $DB->count_records('task_log'));
 314          $this->assertLessThanOrEqual(12, $DB->count_records('task_log'));
 315  
 316          // The oldest should be no more than 12 hours old.
 317          $oldest = $DB->get_records('task_log', [], 'timestart DESC', 'timestart', 0, 1);
 318          $oldest = reset($oldest);
 319          $this->assertGreaterThan(time() - (12 * DAYSECS), $oldest->timestart);
 320      }
 321  
 322      /**
 323       * Ensure that the run-count retention applies.
 324       */
 325      public function test_cleanup_retainruns() {
 326          global $DB;
 327  
 328          $this->resetAfterTest();
 329  
 330          // Set a high value for task_logretention so that it does not interfere.
 331          set_config('task_logretention', YEARSECS);
 332  
 333          // Create sample log data - 2 tasks, once per hour for 3 days.
 334          $date = new DateTime();
 335          $date->setTime($date->format('G'), 0);
 336          $firstdate = $date->getTimestamp();
 337  
 338          for ($i = 0; $i < 3 * 24; $i++) {
 339              $task = new \core\task\cache_cron_task();
 340              $logpath = __FILE__;
 341              database_logger::store_log_for_task($task, $logpath, false, 1, 2, $date->getTimestamp(), $date->getTimestamp() + MINSECS);
 342  
 343              $task = new \core\task\badges_cron_task();
 344              $logpath = __FILE__;
 345              database_logger::store_log_for_task($task, $logpath, false, 1, 2, $date->getTimestamp(), $date->getTimestamp() + MINSECS);
 346  
 347              $date->sub(new \DateInterval('PT1H'));
 348          }
 349          $lastdate = $date->getTimestamp();
 350  
 351          // Initially there should be 144 runs - 72 for each task.
 352          $this->assertEquals(144, $DB->count_records('task_log'));
 353          $this->assertEquals(72, $DB->count_records('task_log', ['classname' => \core\task\cache_cron_task::class]));
 354          $this->assertEquals(72, $DB->count_records('task_log', ['classname' => \core\task\badges_cron_task::class]));
 355  
 356          // Grab the records for comparison.
 357          $cachecronrecords = array_values($DB->get_records('task_log', ['classname' => \core\task\cache_cron_task::class], 'timestart DESC'));
 358          $badgescronrecords = array_values($DB->get_records('task_log', ['classname' => \core\task\badges_cron_task::class], 'timestart DESC'));
 359  
 360          // Configured to retain 144 should have no effect.
 361          set_config('task_logretainruns', 144);
 362          \core\task\database_logger::cleanup();
 363          $this->assertEquals(144, $DB->count_records('task_log'));
 364          $this->assertEquals(72, $DB->count_records('task_log', ['classname' => \core\task\cache_cron_task::class]));
 365          $this->assertEquals(72, $DB->count_records('task_log', ['classname' => \core\task\badges_cron_task::class]));
 366  
 367          // The list of records should be identical.
 368          $this->assertEquals($cachecronrecords, array_values($DB->get_records('task_log', ['classname' => \core\task\cache_cron_task::class], 'timestart DESC')));
 369          $this->assertEquals($badgescronrecords, array_values($DB->get_records('task_log', ['classname' => \core\task\badges_cron_task::class], 'timestart DESC')));
 370  
 371          // Configured to retain 72 should have no effect either.
 372          set_config('task_logretainruns', 72);
 373          \core\task\database_logger::cleanup();
 374          $this->assertEquals(144, $DB->count_records('task_log'));
 375          $this->assertEquals(72, $DB->count_records('task_log', ['classname' => \core\task\cache_cron_task::class]));
 376          $this->assertEquals(72, $DB->count_records('task_log', ['classname' => \core\task\badges_cron_task::class]));
 377  
 378          // The list of records should now only contain the first 72 of each.
 379          $this->assertEquals(
 380              array_slice($cachecronrecords, 0, 72),
 381              array_values($DB->get_records('task_log', ['classname' => \core\task\cache_cron_task::class], 'timestart DESC'))
 382          );
 383          $this->assertEquals(
 384              array_slice($badgescronrecords, 0, 72),
 385              array_values($DB->get_records('task_log', ['classname' => \core\task\badges_cron_task::class], 'timestart DESC'))
 386          );
 387  
 388          // Configured to only retain 24 should bring that down to a total of 48, or 24 each.
 389          set_config('task_logretainruns', 24);
 390          \core\task\database_logger::cleanup();
 391          $this->assertEquals(48, $DB->count_records('task_log'));
 392          $this->assertEquals(24, $DB->count_records('task_log', ['classname' => \core\task\cache_cron_task::class]));
 393          $this->assertEquals(24, $DB->count_records('task_log', ['classname' => \core\task\badges_cron_task::class]));
 394  
 395          // The list of records should now only contain the first 24 of each.
 396          $this->assertEquals(
 397              array_slice($cachecronrecords, 0, 24),
 398              array_values($DB->get_records('task_log', ['classname' => \core\task\cache_cron_task::class], 'timestart DESC'))
 399          );
 400          $this->assertEquals(
 401              array_slice($badgescronrecords, 0, 24),
 402              array_values($DB->get_records('task_log', ['classname' => \core\task\badges_cron_task::class], 'timestart DESC'))
 403          );
 404  
 405          // Configured to only retain 5 should bring that down to a total of 10, or 5 each.
 406          set_config('task_logretainruns', 5);
 407          \core\task\database_logger::cleanup();
 408          $this->assertEquals(10, $DB->count_records('task_log'));
 409          $this->assertEquals(5, $DB->count_records('task_log', ['classname' => \core\task\cache_cron_task::class]));
 410          $this->assertEquals(5, $DB->count_records('task_log', ['classname' => \core\task\badges_cron_task::class]));
 411  
 412          // The list of records should now only contain the first 5 of each.
 413          $this->assertEquals(
 414              array_slice($cachecronrecords, 0, 5),
 415              array_values($DB->get_records('task_log', ['classname' => \core\task\cache_cron_task::class], 'timestart DESC'))
 416          );
 417          $this->assertEquals(
 418              array_slice($badgescronrecords, 0, 5),
 419              array_values($DB->get_records('task_log', ['classname' => \core\task\badges_cron_task::class], 'timestart DESC'))
 420          );
 421  
 422          // Configured to only retain 0 should bring that down to none.
 423          set_config('task_logretainruns', 0);
 424          \core\task\database_logger::cleanup();
 425          $this->assertEquals(0, $DB->count_records('task_log'));
 426      }
 427  
 428      /**
 429       * Ensure that the retention period applies correctly when combined with the run count retention.
 430       */
 431      public function test_cleanup_combined() {
 432          global $DB;
 433  
 434          $this->resetAfterTest();
 435  
 436          // Calculate date to be used for logs, starting from current time rounded down to nearest hour.
 437          $date = new DateTime();
 438          $date->setTime($date->format('G'), 0);
 439          $baselogtime = $date->getTimestamp();
 440  
 441          // Create sample log data - 2 tasks, once per hour for 3 days.
 442          for ($i = 0; $i < 3 * 24; $i++) {
 443              $task = new \core\task\cache_cron_task();
 444              $logpath = __FILE__;
 445              database_logger::store_log_for_task($task, $logpath, false, 1, 2, $date->getTimestamp(), $date->getTimestamp() + MINSECS);
 446  
 447              $task = new \core\task\badges_cron_task();
 448              $logpath = __FILE__;
 449              database_logger::store_log_for_task($task, $logpath, false, 1, 2, $date->getTimestamp(), $date->getTimestamp() + MINSECS);
 450  
 451              $date->sub(new \DateInterval('PT1H'));
 452          }
 453  
 454          // Initially there should be 144 runs - 72 for each task.
 455          $this->assertEquals(144, $DB->count_records('task_log'));
 456          $this->assertEquals(72, $DB->count_records('task_log', ['classname' => \core\task\cache_cron_task::class]));
 457          $this->assertEquals(72, $DB->count_records('task_log', ['classname' => \core\task\badges_cron_task::class]));
 458  
 459          // Note: We set the retention time to a period like DAYSECS minus an adjustment.
 460          // The adjustment is to account for the difference between current time and baselogtime.
 461  
 462          // With a retention period of 2 * DAYSECS, there should only be 96 left.
 463          // The run count is a higher number so it will have no effect.
 464          set_config('task_logretention', time() - ($baselogtime - (2 * DAYSECS)) - 1);
 465          set_config('task_logretainruns', 50);
 466          \core\task\database_logger::cleanup();
 467  
 468          $this->assertEquals(96, $DB->count_records('task_log'));
 469          $this->assertEquals(48, $DB->count_records('task_log', ['classname' => \core\task\cache_cron_task::class]));
 470          $this->assertEquals(48, $DB->count_records('task_log', ['classname' => \core\task\badges_cron_task::class]));
 471  
 472          // We should retain the most recent 48 of each task, so the oldest will be 47 hours old.
 473          $oldest = $DB->get_records('task_log', [], 'timestart ASC', 'timestart', 0, 1);
 474          $oldest = reset($oldest);
 475          $this->assertEquals($baselogtime - (47 * HOURSECS), $oldest->timestart);
 476  
 477          // Reducing the retain runs count to 10 should reduce the total logs to 20, overriding the time constraint.
 478          set_config('task_logretainruns', 10);
 479          \core\task\database_logger::cleanup();
 480  
 481          $this->assertEquals(20, $DB->count_records('task_log'));
 482          $this->assertEquals(10, $DB->count_records('task_log', ['classname' => \core\task\cache_cron_task::class]));
 483          $this->assertEquals(10, $DB->count_records('task_log', ['classname' => \core\task\badges_cron_task::class]));
 484  
 485          // We should retain the most recent 10 of each task, so the oldest will be 9 hours old.
 486          $oldest = $DB->get_records('task_log', [], 'timestart ASC', 'timestart', 0, 1);
 487          $oldest = reset($oldest);
 488          $this->assertEquals($baselogtime - (9 * HOURSECS), $oldest->timestart);
 489      }
 490  
 491      /**
 492       * Mock the database.
 493       */
 494      protected function mock_database() {
 495          global $DB;
 496  
 497          $DB = $this->getMockBuilder(\moodle_database::class)
 498              ->getMock();
 499  
 500          $DB->method('get_record')
 501              ->willReturn((object) []);
 502  
 503          return $DB;
 504      }
 505  }