[Summary view]

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