lib/tests/task_logging_test.php

   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 task logging system.
  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 require_once(__DIR__ . '/fixtures/task_fixtures.php');
  28
  29
  30 /**
  31  * This file contains the unit tests for the task logging system.
  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 core_task_logmanager extends advanced_testcase {
  37
  38     /**
  39      * @var \moodle_database The original database prior to mocking
  40      */
  41     protected $DB;
  42
  43     /**
  44      * Relevant tearDown for logging tests.
  45      */
  46     public function tearDown() {
  47         global $DB;
  48
  49         // Ensure that any logging is always ended.
  50         \core\task\logmanager::finalise_log();
  51
  52         if (null !== $this->DB) {
  53             $DB = $this->DB;
  54             $this->DB = null;
  55         }
  56     }
  57
  58     /**
  59      * When the logmode is set to none, logging should not start.
  60      */
  61     public function test_logmode_none() {
  62         global $CFG;
  63         $this->resetAfterTest();
  64
  65         $CFG->task_logmode = \core\task\logmanager::MODE_NONE;
  66
  67         $initialbufferstate = ob_get_status();
  68
  69         $task = $this->get_test_adhoc_task();
  70         \core\task\logmanager::start_logging($task);
  71
  72         // There will be no additional output buffer.
  73         $this->assertEquals($initialbufferstate, ob_get_status());
  74     }
  75
  76     /**
  77      * When the logmode is set to all that log capture is started.
  78      */
  79     public function test_start_logmode_all() {
  80         global $CFG;
  81         $this->resetAfterTest();
  82
  83         $CFG->task_logmode = \core\task\logmanager::MODE_ALL;
  84
  85         $initialbufferstate = ob_get_status();
  86
  87         $task = $this->get_test_adhoc_task();
  88         \core\task\logmanager::start_logging($task);
  89
  90         // Fetch the new output buffer state.
  91         $state = ob_get_status();
  92
  93         // There will be no additional output buffer.
  94         $this->assertNotEquals($initialbufferstate, $state);
  95     }
  96
  97     /**
  98      * When the logmode is set to fail that log capture is started.
  99      */
 100     public function test_start_logmode_fail() {
 101         global $CFG;
 102         $this->resetAfterTest();
 103
 104         $CFG->task_logmode = \core\task\logmanager::MODE_FAILONLY;
 105
 106         $initialbufferstate = ob_get_status();
 107
 108         $task = $this->get_test_adhoc_task();
 109         \core\task\logmanager::start_logging($task);
 110
 111         // Fetch the new output buffer state.
 112         $state = ob_get_status();
 113
 114         // There will be no additional output buffer.
 115         $this->assertNotEquals($initialbufferstate, $state);
 116     }
 117
 118     /**
 119      * When the logmode is set to fail, passing adhoc tests should not be logged.
 120      */
 121     public function test_logmode_fail_with_passing_adhoc_task() {
 122         global $CFG;
 123         $this->resetAfterTest();
 124
 125         $CFG->task_logmode = \core\task\logmanager::MODE_FAILONLY;
 126
 127         $logger = $this->get_mocked_logger();
 128
 129         $initialbufferstate = ob_get_status();
 130
 131         $task = $this->get_test_adhoc_task();
 132         \core\task\logmanager::start_logging($task);
 133
 134         \core\task\manager::adhoc_task_complete($task);
 135
 136         $this->assertEmpty($logger::$storelogfortask);
 137     }
 138
 139     /**
 140      * When the logmode is set to fail, passing scheduled tests should not be logged.
 141      */
 142     public function test_logmode_fail_with_passing_scheduled_task() {
 143         global $CFG;
 144         $this->resetAfterTest();
 145
 146         $CFG->task_logmode = \core\task\logmanager::MODE_FAILONLY;
 147
 148         $logger = $this->get_mocked_logger();
 149
 150         $initialbufferstate = ob_get_status();
 151
 152         $task = $this->get_test_scheduled_task();
 153         \core\task\logmanager::start_logging($task);
 154
 155         \core\task\manager::scheduled_task_complete($task);
 156
 157         $this->assertEmpty($logger::$storelogfortask);
 158     }
 159
 160     /**
 161      * When the logmode is set to fail, failing adhoc tests should be logged.
 162      */
 163     public function test_logmode_fail_with_failing_adhoc_task() {
 164         global $CFG;
 165
 166         $this->resetAfterTest();
 167
 168         // Mock the database. Marking jobs as failed updates a DB record which doesn't exist.
 169         $this->mock_database();
 170
 171         $task = $this->get_test_adhoc_task();
 172
 173         $CFG->task_logmode = \core\task\logmanager::MODE_FAILONLY;
 174
 175         $logger = $this->get_mocked_logger();
 176
 177         \core\task\logmanager::start_logging($task);
 178         \core\task\manager::adhoc_task_failed($task);
 179
 180         $this->assertCount(1, $logger::$storelogfortask);
 181         $this->assertEquals($task, $logger::$storelogfortask[0][0]);
 182         $this->assertTrue($logger::$storelogfortask[0][2]);
 183     }
 184
 185     /**
 186      * When the logmode is set to fail, failing scheduled tests should be logged.
 187      */
 188     public function test_logmode_fail_with_failing_scheduled_task() {
 189         global $CFG;
 190
 191         $this->resetAfterTest();
 192
 193         // Mock the database. Marking jobs as failed updates a DB record which doesn't exist.
 194         $this->mock_database();
 195
 196         $task = $this->get_test_scheduled_task();
 197
 198         $CFG->task_logmode = \core\task\logmanager::MODE_FAILONLY;
 199
 200         $logger = $this->get_mocked_logger();
 201
 202         \core\task\logmanager::start_logging($task);
 203         \core\task\manager::scheduled_task_failed($task);
 204
 205         $this->assertCount(1, $logger::$storelogfortask);
 206         $this->assertEquals($task, $logger::$storelogfortask[0][0]);
 207         $this->assertTrue($logger::$storelogfortask[0][2]);
 208     }
 209
 210     /**
 211      * When the logmode is set to fail, failing adhoc tests should be logged.
 212      */
 213     public function test_logmode_any_with_failing_adhoc_task() {
 214         global $CFG;
 215
 216         $this->resetAfterTest();
 217
 218         // Mock the database. Marking jobs as failed updates a DB record which doesn't exist.
 219         $this->mock_database();
 220
 221         $task = $this->get_test_adhoc_task();
 222
 223         $CFG->task_logmode = \core\task\logmanager::MODE_FAILONLY;
 224
 225         $logger = $this->get_mocked_logger();
 226
 227         \core\task\logmanager::start_logging($task);
 228         \core\task\manager::adhoc_task_failed($task);
 229
 230         $this->assertCount(1, $logger::$storelogfortask);
 231         $this->assertEquals($task, $logger::$storelogfortask[0][0]);
 232         $this->assertTrue($logger::$storelogfortask[0][2]);
 233     }
 234
 235     /**
 236      * When the logmode is set to fail, failing scheduled tests should be logged.
 237      */
 238     public function test_logmode_any_with_failing_scheduled_task() {
 239         global $CFG;
 240
 241         $this->resetAfterTest();
 242
 243         // Mock the database. Marking jobs as failed updates a DB record which doesn't exist.
 244         $this->mock_database();
 245
 246         $task = $this->get_test_scheduled_task();
 247
 248         $CFG->task_logmode = \core\task\logmanager::MODE_FAILONLY;
 249
 250         $logger = $this->get_mocked_logger();
 251
 252         \core\task\logmanager::start_logging($task);
 253         \core\task\manager::scheduled_task_failed($task);
 254
 255         $this->assertCount(1, $logger::$storelogfortask);
 256         $this->assertEquals($task, $logger::$storelogfortask[0][0]);
 257         $this->assertTrue($logger::$storelogfortask[0][2]);
 258     }
 259
 260     /**
 261      * When the logmode is set to fail, passing adhoc tests should be logged.
 262      */
 263     public function test_logmode_any_with_passing_adhoc_task() {
 264         global $CFG;
 265
 266         $this->resetAfterTest();
 267
 268         $this->mock_database();
 269
 270         $task = $this->get_test_adhoc_task();
 271
 272         $CFG->task_logmode = \core\task\logmanager::MODE_ALL;
 273
 274         $logger = $this->get_mocked_logger();
 275
 276         \core\task\logmanager::start_logging($task);
 277         \core\task\manager::adhoc_task_complete($task);
 278
 279         $this->assertCount(1, $logger::$storelogfortask);
 280         $this->assertEquals($task, $logger::$storelogfortask[0][0]);
 281         $this->assertFalse($logger::$storelogfortask[0][2]);
 282     }
 283
 284     /**
 285      * When the logmode is set to fail, passing scheduled tests should be logged.
 286      */
 287     public function test_logmode_any_with_passing_scheduled_task() {
 288         global $CFG;
 289
 290         $this->resetAfterTest();
 291
 292         $this->mock_database();
 293
 294         $task = $this->get_test_scheduled_task();
 295
 296         $CFG->task_logmode = \core\task\logmanager::MODE_ALL;
 297
 298         $logger = $this->get_mocked_logger();
 299
 300         \core\task\logmanager::start_logging($task);
 301         \core\task\manager::scheduled_task_complete($task);
 302
 303         $this->assertCount(1, $logger::$storelogfortask);
 304         $this->assertEquals($task, $logger::$storelogfortask[0][0]);
 305         $this->assertFalse($logger::$storelogfortask[0][2]);
 306     }
 307
 308     /**
 309      * Ensure that start_logging cannot be called in a nested fashion.
 310      */
 311     public function test_prevent_nested_logging() {
 312         $this->resetAfterTest();
 313
 314         $task = $this->get_test_adhoc_task();
 315         \core\task\logmanager::start_logging($task);
 316
 317         $this->expectException(\coding_exception::class);
 318         \core\task\logmanager::start_logging($task);
 319     }
 320
 321     /**
 322      * Ensure that logging can be called after a previous log has finished.
 323      */
 324     public function test_repeated_usages() {
 325         $this->resetAfterTest();
 326
 327         $logger = $this->get_mocked_logger();
 328
 329         $task = $this->get_test_adhoc_task();
 330         \core\task\logmanager::start_logging($task);
 331         \core\task\logmanager::finalise_log();
 332
 333         \core\task\logmanager::start_logging($task);
 334         \core\task\logmanager::finalise_log();
 335
 336         $this->assertCount(2, $logger::$storelogfortask);
 337         $this->assertEquals($task, $logger::$storelogfortask[0][0]);
 338         $this->assertFalse($logger::$storelogfortask[0][2]);
 339         $this->assertEquals($task, $logger::$storelogfortask[1][0]);
 340         $this->assertFalse($logger::$storelogfortask[1][2]);
 341     }
 342
 343     /**
 344      * Enusre that when finalise_log is called when logging is not active, nothing happens.
 345      */
 346     public function test_finalise_log_no_logging() {
 347         $initialbufferstate = ob_get_status();
 348
 349         \core\task\logmanager::finalise_log();
 350
 351         // There will be no additional output buffer.
 352         $this->assertEquals($initialbufferstate, ob_get_status());
 353     }
 354
 355     /**
 356      * When log capture is enabled, calls to the flush function should cause log output to be both returned and captured.
 357      */
 358     public function test_flush_on_own_buffer() {
 359         $this->resetAfterTest();
 360
 361         $logger = $this->get_mocked_logger();
 362
 363         $testoutput = "I am the output under test.\n";
 364
 365         $task = $this->get_test_adhoc_task();
 366         \core\task\logmanager::start_logging($task);
 367
 368         echo $testoutput;
 369
 370         $this->expectOutputString($testoutput);
 371         \core\task\logmanager::flush();
 372
 373         // Finalise the log.
 374         \core\task\logmanager::finalise_log();
 375
 376         $this->assertCount(1, $logger::$storelogfortask);
 377         $this->assertEquals($testoutput, file_get_contents($logger::$storelogfortask[0][1]));
 378     }
 379
 380     /**
 381      * When log capture is enabled, calls to the flush function should not affect any subsequent ob_start.
 382      */
 383     public function test_flush_does_not_flush_inner_buffers() {
 384         $this->resetAfterTest();
 385
 386         $logger = $this->get_mocked_logger();
 387
 388         $testoutput = "I am the output under test.\n";
 389
 390         $task = $this->get_test_adhoc_task();
 391         \core\task\logmanager::start_logging($task);
 392
 393         ob_start();
 394         echo $testoutput;
 395         ob_end_clean();
 396
 397         \core\task\logmanager::flush();
 398
 399         // Finalise the log.
 400         \core\task\logmanager::finalise_log();
 401
 402         $this->assertCount(1, $logger::$storelogfortask);
 403
 404         // The task logger should not have captured the content of the inner buffer.
 405         $this->assertEquals('', file_get_contents($logger::$storelogfortask[0][1]));
 406     }
 407
 408     /**
 409      * When log capture is enabled, calls to the flush function should not affect any subsequent ob_start.
 410      */
 411     public function test_inner_flushed_buffers_are_logged() {
 412         $this->resetAfterTest();
 413
 414         $logger = $this->get_mocked_logger();
 415
 416         $testoutput = "I am the output under test.\n";
 417
 418         $task = $this->get_test_adhoc_task();
 419         \core\task\logmanager::start_logging($task);
 420
 421         // We are going to flush the inner buffer. That means that we should expect the output immediately.
 422         $this->expectOutputString($testoutput);
 423
 424         ob_start();
 425         echo $testoutput;
 426         ob_end_flush();
 427
 428         // Finalise the log.
 429         \core\task\logmanager::finalise_log();
 430
 431         $this->assertCount(1, $logger::$storelogfortask);
 432
 433         // The task logger should not have captured the content of the inner buffer.
 434         $this->assertEquals($testoutput, file_get_contents($logger::$storelogfortask[0][1]));
 435     }
 436
 437     /**
 438      * Get an example adhoc task to use for testing.
 439      *
 440      * @return  \core\task\adhoc_task
 441      */
 442     protected function get_test_adhoc_task() : \core\task\adhoc_task {
 443         $task = $this->getMockForAbstractClass(\core\task\adhoc_task::class);
 444
 445         // Mock a lock on the task.
 446         $lock = $this->getMockBuilder(\core\lock\lock::class)
 447             ->disableOriginalConstructor()
 448             ->getMock();
 449         $task->set_lock($lock);
 450
 451         return $task;
 452     }
 453
 454     /**
 455      * Get an example scheduled task to use for testing.
 456      *
 457      * @return  \core\task\scheduled_task
 458      */
 459     protected function get_test_scheduled_task() : \core\task\scheduled_task {
 460         $task = $this->getMockForAbstractClass(\core\task\scheduled_task::class);
 461
 462         // Mock a lock on the task.
 463         $lock = $this->getMockBuilder(\core\lock\lock::class)
 464             ->disableOriginalConstructor()
 465             ->getMock();
 466         $task->set_lock($lock);
 467
 468         return $task;
 469     }
 470
 471     /**
 472      * Create and configure a mocked task logger.
 473      *
 474      * @return  \core\task\task_logger
 475      */
 476     protected function get_mocked_logger() {
 477         global $CFG;
 478
 479         // We will modify config for the alternate logging class therefore we mnust reset after the test.
 480         $this->resetAfterTest();
 481
 482         // Note PHPUnit does not support mocking static functions.
 483         $CFG->task_log_class = \task_logging_test_mocked_logger::class;
 484         \task_logging_test_mocked_logger::test_reset();
 485
 486         return $CFG->task_log_class;
 487     }
 488
 489     /**
 490      * Mock the database.
 491      */
 492     protected function mock_database() {
 493         global $DB;
 494
 495         // Store the old Database for restoration in reset.
 496         $this->DB = $DB;
 497
 498         $DB = $this->getMockBuilder(\moodle_database::class)
 499             ->getMock();
 500
 501         $DB->method('get_record')
 502             ->willReturn((object) []);
 503     }
 504 }
 505
 506 /**
 507  * Mocked logger.
 508  *
 509  * @copyright 2018 Andrew Nicols <andrew@nicols.co.uk>
 510  * @license   http://www.gnu.org/copyleft/gpl.html GNU GPL v3 or later
 511  */
 512 class task_logging_test_mocked_logger implements \core\task\task_logger {
 513
 514     /**
 515      * @var bool Whether this is configured.
 516      */
 517     public static $isconfigured = true;
 518
 519     /**
 520      * @var array Arguments that store_log_for_task was called with.
 521      */
 522     public static $storelogfortask = [];
 523
 524     /**
 525      * @var bool Whether this logger has a report.
 526      */
 527     public static $haslogreport = true;
 528
 529     /**
 530      * Reset the test class.
 531      */
 532     public static function test_reset() {
 533         self::$isconfigured = true;
 534         self::$storelogfortask = [];
 535         self::$haslogreport = true;
 536     }
 537
 538     /**
 539      * Whether the task is configured and ready to log.
 540      *
 541      * @return  bool
 542      */
 543     public static function is_configured() : bool {
 544         return self::$isconfigured;
 545     }
 546
 547     /**
 548      * Store the log for the specified task.
 549      *
 550      * @param   \core\task\task_base   $task The task that the log belongs to.
 551      * @param   string      $logpath The path to the log on disk
 552      * @param   bool        $failed Whether the task failed
 553      * @param   int         $dbreads The number of DB reads
 554      * @param   int         $dbwrites The number of DB writes
 555      * @param   float       $timestart The start time of the task
 556      * @param   float       $timeend The end time of the task
 557      */
 558     public static function store_log_for_task(\core\task\task_base $task, string $logpath, bool $failed,
 559             int $dbreads, int $dbwrites, float $timestart, float $timeend) {
 560         self::$storelogfortask[] = func_get_args();
 561     }
 562
 563     /**
 564      * Whether this task logger has a report available.
 565      *
 566      * @return  bool
 567      */
 568     public static function has_log_report() : bool {
 569         return self::$haslogreport;
 570     }
 571
 572     /**
 573      * Get any URL available for viewing relevant task log reports.
 574      *
 575      * @param   string      $classname The task class to fetch for
 576      * @return  \moodle_url
 577      */
 578     public static function get_url_for_task_class(string $classname) : \moodle_url {
 579         return new \moodle_url('');
 580     }
 581
 582 }