[Summary view]

Differences Between: [Versions 310 and 311] [Versions 310 and 400] [Versions 310 and 401] [Versions 310 and 402] [Versions 310 and 403] [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   * Standard log store tests.
  19   *
  20   * @package    logstore_standard
  21   * @copyright  2014 Petr Skoda {@link http://skodak.org/}
  22   * @license    http://www.gnu.org/copyleft/gpl.html GNU GPL v3 or later
  23   */
  24  
  25  defined('MOODLE_INTERNAL') || die();
  26  
  27  require_once (__DIR__ . '/fixtures/event.php');
  28  require_once (__DIR__ . '/fixtures/restore_hack.php');
  29  
  30  class logstore_standard_store_testcase extends advanced_testcase {
  31      /**
  32       * @var bool Determine if we disabled the GC, so it can be re-enabled in tearDown.
  33       */
  34      private $wedisabledgc = false;
  35  
  36      /**
  37       * Tests log writing.
  38       *
  39       * @param bool $jsonformat True to test with JSON format
  40       * @dataProvider test_log_writing_provider
  41       * @throws moodle_exception
  42       */
  43      public function test_log_writing(bool $jsonformat) {
  44          global $DB;
  45          $this->resetAfterTest();
  46          $this->preventResetByRollback(); // Logging waits till the transaction gets committed.
  47  
  48          // Apply JSON format system setting.
  49          set_config('jsonformat', $jsonformat ? 1 : 0, 'logstore_standard');
  50  
  51          $this->setAdminUser();
  52          $user1 = $this->getDataGenerator()->create_user();
  53          $user2 = $this->getDataGenerator()->create_user();
  54          $course1 = $this->getDataGenerator()->create_course();
  55          $module1 = $this->getDataGenerator()->create_module('resource', array('course' => $course1));
  56          $course2 = $this->getDataGenerator()->create_course();
  57          $module2 = $this->getDataGenerator()->create_module('resource', array('course' => $course2));
  58  
  59          // Test all plugins are disabled by this command.
  60          set_config('enabled_stores', '', 'tool_log');
  61          $manager = get_log_manager(true);
  62          $stores = $manager->get_readers();
  63          $this->assertCount(0, $stores);
  64  
  65          // Enable logging plugin.
  66          set_config('enabled_stores', 'logstore_standard', 'tool_log');
  67          set_config('buffersize', 0, 'logstore_standard');
  68          set_config('logguests', 1, 'logstore_standard');
  69          $manager = get_log_manager(true);
  70  
  71          $stores = $manager->get_readers();
  72          $this->assertCount(1, $stores);
  73          $this->assertEquals(array('logstore_standard'), array_keys($stores));
  74          /** @var \logstore_standard\log\store $store */
  75          $store = $stores['logstore_standard'];
  76          $this->assertInstanceOf('logstore_standard\log\store', $store);
  77          $this->assertInstanceOf('tool_log\log\writer', $store);
  78          $this->assertTrue($store->is_logging());
  79  
  80          $logs = $DB->get_records('logstore_standard_log', array(), 'id ASC');
  81          $this->assertCount(0, $logs);
  82  
  83          $this->setCurrentTimeStart();
  84  
  85          $this->setUser(0);
  86          $event1 = \logstore_standard\event\unittest_executed::create(
  87              array('context' => context_module::instance($module1->cmid), 'other' => array('sample' => 5, 'xx' => 10)));
  88          $event1->trigger();
  89  
  90          $logs = $DB->get_records('logstore_standard_log', array(), 'id ASC');
  91          $this->assertCount(1, $logs);
  92  
  93          $log1 = reset($logs);
  94          unset($log1->id);
  95          if ($jsonformat) {
  96              $log1->other = json_decode($log1->other, true);
  97          } else {
  98              $log1->other = unserialize($log1->other);
  99          }
 100          $log1 = (array)$log1;
 101          $data = $event1->get_data();
 102          $data['origin'] = 'cli';
 103          $data['ip'] = null;
 104          $data['realuserid'] = null;
 105          $this->assertEquals($data, $log1);
 106  
 107          $this->setAdminUser();
 108          \core\session\manager::loginas($user1->id, context_system::instance());
 109          $this->assertEquals(2, $DB->count_records('logstore_standard_log'));
 110  
 111          logstore_standard_restore::hack_executing(1);
 112          $event2 = \logstore_standard\event\unittest_executed::create(
 113              array('context' => context_module::instance($module2->cmid), 'other' => array('sample' => 6, 'xx' => 9)));
 114          $event2->trigger();
 115          logstore_standard_restore::hack_executing(0);
 116  
 117          \core\session\manager::init_empty_session();
 118          $this->assertFalse(\core\session\manager::is_loggedinas());
 119  
 120          $logs = $DB->get_records('logstore_standard_log', array(), 'id ASC');
 121          $this->assertCount(3, $logs);
 122          array_shift($logs);
 123          $log2 = array_shift($logs);
 124          $this->assertSame('\core\event\user_loggedinas', $log2->eventname);
 125          $this->assertSame('cli', $log2->origin);
 126  
 127          $log3 = array_shift($logs);
 128          unset($log3->id);
 129          if ($jsonformat) {
 130              $log3->other = json_decode($log3->other, true);
 131          } else {
 132              $log3->other = unserialize($log3->other);
 133          }
 134          $log3 = (array)$log3;
 135          $data = $event2->get_data();
 136          $data['origin'] = 'restore';
 137          $data['ip'] = null;
 138          $data['realuserid'] = 2;
 139          $this->assertEquals($data, $log3);
 140  
 141          // Test table exists.
 142          $tablename = $store->get_internal_log_table_name();
 143          $this->assertTrue($DB->get_manager()->table_exists($tablename));
 144  
 145          // Test reading.
 146          $this->assertSame(3, $store->get_events_select_count('', array()));
 147          $events = $store->get_events_select('', array(), 'timecreated ASC', 0, 0); // Is actually sorted by "timecreated ASC, id ASC".
 148          $this->assertCount(3, $events);
 149          $resev1 = array_shift($events);
 150          array_shift($events);
 151          $resev2 = array_shift($events);
 152          $this->assertEquals($event1->get_data(), $resev1->get_data());
 153          $this->assertEquals($event2->get_data(), $resev2->get_data());
 154  
 155          // Test buffering.
 156          set_config('buffersize', 3, 'logstore_standard');
 157          $manager = get_log_manager(true);
 158          $stores = $manager->get_readers();
 159          /** @var \logstore_standard\log\store $store */
 160          $store = $stores['logstore_standard'];
 161          $DB->delete_records('logstore_standard_log');
 162  
 163          \logstore_standard\event\unittest_executed::create(
 164              array('context' => context_module::instance($module1->cmid), 'other' => array('sample' => 5, 'xx' => 10)))->trigger();
 165          $this->assertEquals(0, $DB->count_records('logstore_standard_log'));
 166          \logstore_standard\event\unittest_executed::create(
 167              array('context' => context_module::instance($module1->cmid), 'other' => array('sample' => 5, 'xx' => 10)))->trigger();
 168          $this->assertEquals(0, $DB->count_records('logstore_standard_log'));
 169          $store->flush();
 170          $this->assertEquals(2, $DB->count_records('logstore_standard_log'));
 171          \logstore_standard\event\unittest_executed::create(
 172              array('context' => context_module::instance($module1->cmid), 'other' => array('sample' => 5, 'xx' => 10)))->trigger();
 173          $this->assertEquals(2, $DB->count_records('logstore_standard_log'));
 174          \logstore_standard\event\unittest_executed::create(
 175              array('context' => context_module::instance($module1->cmid), 'other' => array('sample' => 5, 'xx' => 10)))->trigger();
 176          $this->assertEquals(2, $DB->count_records('logstore_standard_log'));
 177          \logstore_standard\event\unittest_executed::create(
 178              array('context' => context_module::instance($module1->cmid), 'other' => array('sample' => 5, 'xx' => 10)))->trigger();
 179          $this->assertEquals(5, $DB->count_records('logstore_standard_log'));
 180          \logstore_standard\event\unittest_executed::create(
 181              array('context' => context_module::instance($module1->cmid), 'other' => array('sample' => 5, 'xx' => 10)))->trigger();
 182          $this->assertEquals(5, $DB->count_records('logstore_standard_log'));
 183          \logstore_standard\event\unittest_executed::create(
 184              array('context' => context_module::instance($module1->cmid), 'other' => array('sample' => 5, 'xx' => 10)))->trigger();
 185          $this->assertEquals(5, $DB->count_records('logstore_standard_log'));
 186          \logstore_standard\event\unittest_executed::create(
 187              array('context' => context_module::instance($module1->cmid), 'other' => array('sample' => 5, 'xx' => 10)))->trigger();
 188          $this->assertEquals(8, $DB->count_records('logstore_standard_log'));
 189  
 190          // Test guest logging setting.
 191          set_config('logguests', 0, 'logstore_standard');
 192          set_config('buffersize', 0, 'logstore_standard');
 193          get_log_manager(true);
 194          $DB->delete_records('logstore_standard_log');
 195          get_log_manager(true);
 196  
 197          $this->setUser(null);
 198          \logstore_standard\event\unittest_executed::create(
 199              array('context' => context_module::instance($module1->cmid), 'other' => array('sample' => 5, 'xx' => 10)))->trigger();
 200          $this->assertEquals(0, $DB->count_records('logstore_standard_log'));
 201  
 202          $this->setGuestUser();
 203          \logstore_standard\event\unittest_executed::create(
 204              array('context' => context_module::instance($module1->cmid), 'other' => array('sample' => 5, 'xx' => 10)))->trigger();
 205          $this->assertEquals(0, $DB->count_records('logstore_standard_log'));
 206  
 207          $this->setUser($user1);
 208          \logstore_standard\event\unittest_executed::create(
 209              array('context' => context_module::instance($module1->cmid), 'other' => array('sample' => 5, 'xx' => 10)))->trigger();
 210          $this->assertEquals(1, $DB->count_records('logstore_standard_log'));
 211  
 212          $this->setUser($user2);
 213          \logstore_standard\event\unittest_executed::create(
 214              array('context' => context_module::instance($module1->cmid), 'other' => array('sample' => 5, 'xx' => 10)))->trigger();
 215          $this->assertEquals(2, $DB->count_records('logstore_standard_log'));
 216  
 217          set_config('enabled_stores', '', 'tool_log');
 218          get_log_manager(true);
 219      }
 220  
 221      /**
 222       * Returns different JSON format settings so the test can be run with JSON format either on or
 223       * off.
 224       *
 225       * @return [bool] Array of true/false
 226       */
 227      public static function test_log_writing_provider(): array {
 228          return [
 229              [false],
 230              [true]
 231          ];
 232      }
 233  
 234      /**
 235       * Test logmanager::get_supported_reports returns all reports that require this store.
 236       */
 237      public function test_get_supported_reports() {
 238          $logmanager = get_log_manager();
 239          $allreports = \core_component::get_plugin_list('report');
 240  
 241          $supportedreports = array(
 242              'report_log' => '/report/log',
 243              'report_loglive' => '/report/loglive',
 244              'report_outline' => '/report/outline',
 245              'report_participation' => '/report/participation',
 246              'report_stats' => '/report/stats'
 247          );
 248  
 249          // Make sure all supported reports are installed.
 250          $expectedreports = array_keys(array_intersect_key($allreports, $supportedreports));
 251          $reports = $logmanager->get_supported_reports('logstore_standard');
 252          $reports = array_keys($reports);
 253          foreach ($expectedreports as $expectedreport) {
 254              $this->assertContains($expectedreport, $reports);
 255          }
 256      }
 257  
 258      /**
 259       * Verify that gc disabling works
 260       */
 261      public function test_gc_enabled_as_expected() {
 262          if (!gc_enabled()) {
 263              $this->markTestSkipped('Garbage collector (gc) is globally disabled.');
 264          }
 265  
 266          $this->disable_gc();
 267          $this->assertTrue($this->wedisabledgc);
 268          $this->assertFalse(gc_enabled());
 269      }
 270  
 271      /**
 272       * Test sql_reader::get_events_select_iterator.
 273       * @return void
 274       */
 275      public function test_events_traversable() {
 276          global $DB;
 277  
 278          $this->disable_gc();
 279  
 280          $this->resetAfterTest();
 281          $this->preventResetByRollback();
 282          $this->setAdminUser();
 283  
 284          set_config('enabled_stores', 'logstore_standard', 'tool_log');
 285  
 286          $manager = get_log_manager(true);
 287          $stores = $manager->get_readers();
 288          $store = $stores['logstore_standard'];
 289  
 290          $events = $store->get_events_select_iterator('', array(), '', 0, 0);
 291          $this->assertFalse($events->valid());
 292  
 293          // Here it should be already closed, but we should be allowed to
 294          // over-close it without exception.
 295          $events->close();
 296  
 297          $user = $this->getDataGenerator()->create_user();
 298          for ($i = 0; $i < 1000; $i++) {
 299              \core\event\user_created::create_from_userid($user->id)->trigger();
 300          }
 301          $store->flush();
 302  
 303          // Check some various sizes get the right number of elements.
 304          $this->assertEquals(1, iterator_count($store->get_events_select_iterator('', array(), '', 0, 1)));
 305          $this->assertEquals(2, iterator_count($store->get_events_select_iterator('', array(), '', 0, 2)));
 306  
 307          $iterator = $store->get_events_select_iterator('', array(), '', 0, 500);
 308          $this->assertInstanceOf('\core\event\base', $iterator->current());
 309          $this->assertEquals(500, iterator_count($iterator));
 310          $iterator->close();
 311  
 312          // Look for non-linear memory usage for the iterator version.
 313          $mem = memory_get_usage();
 314          $events = $store->get_events_select('', array(), '', 0, 0);
 315          $arraymemusage = memory_get_usage() - $mem;
 316  
 317          $mem = memory_get_usage();
 318          $eventsit = $store->get_events_select_iterator('', array(), '', 0, 0);
 319          $eventsit->close();
 320          $itmemusage = memory_get_usage() - $mem;
 321  
 322          $this->assertInstanceOf('\Traversable', $eventsit);
 323  
 324          $this->assertLessThan($arraymemusage / 10, $itmemusage);
 325          set_config('enabled_stores', '', 'tool_log');
 326          get_log_manager(true);
 327      }
 328  
 329      /**
 330       * Test that the standard log cleanup works correctly.
 331       */
 332      public function test_cleanup_task() {
 333          global $DB;
 334  
 335          $this->resetAfterTest();
 336  
 337          // Create some records spread over various days; test multiple iterations in cleanup.
 338          $ctx = context_course::instance(1);
 339          $record = (object) array(
 340              'edulevel' => 0,
 341              'contextid' => $ctx->id,
 342              'contextlevel' => $ctx->contextlevel,
 343              'contextinstanceid' => $ctx->instanceid,
 344              'userid' => 1,
 345              'timecreated' => time(),
 346          );
 347          $DB->insert_record('logstore_standard_log', $record);
 348          $record->timecreated -= 3600 * 24 * 30;
 349          $DB->insert_record('logstore_standard_log', $record);
 350          $record->timecreated -= 3600 * 24 * 30;
 351          $DB->insert_record('logstore_standard_log', $record);
 352          $record->timecreated -= 3600 * 24 * 30;
 353          $DB->insert_record('logstore_standard_log', $record);
 354          $this->assertEquals(4, $DB->count_records('logstore_standard_log'));
 355  
 356          // Remove all logs before "today".
 357          set_config('loglifetime', 1, 'logstore_standard');
 358  
 359          $this->expectOutputString(" Deleted old log records from standard store.\n");
 360          $clean = new \logstore_standard\task\cleanup_task();
 361          $clean->execute();
 362  
 363          $this->assertEquals(1, $DB->count_records('logstore_standard_log'));
 364      }
 365  
 366      /**
 367       * Tests the decode_other function can cope with both JSON and PHP serialized format.
 368       *
 369       * @param mixed $value Value to encode and decode
 370       * @dataProvider test_decode_other_provider
 371       */
 372      public function test_decode_other($value) {
 373          $this->assertEquals($value, \logstore_standard\log\store::decode_other(serialize($value)));
 374          $this->assertEquals($value, \logstore_standard\log\store::decode_other(json_encode($value)));
 375      }
 376  
 377      public function test_decode_other_with_wrongly_encoded_contents() {
 378          $this->assertSame(null, \logstore_standard\log\store::decode_other(null));
 379      }
 380  
 381      /**
 382       * List of possible values for 'other' field.
 383       *
 384       * I took these types from our logs based on the different first character of PHP serialized
 385       * data - my query found only these types. The normal case is an array.
 386       *
 387       * @return array Array of parameters
 388       */
 389      public function test_decode_other_provider(): array {
 390          return [
 391              [['info' => 'd2819896', 'logurl' => 'discuss.php?d=2819896']],
 392              [null],
 393              ['just a string'],
 394              [32768]
 395          ];
 396      }
 397  
 398      /**
 399       * Checks that backup and restore of log data works correctly.
 400       *
 401       * @param bool $jsonformat True to test with JSON format
 402       * @dataProvider test_log_writing_provider
 403       * @throws moodle_exception
 404       */
 405      public function test_backup_restore(bool $jsonformat) {
 406          global $DB;
 407          $this->resetAfterTest();
 408          $this->preventResetByRollback();
 409  
 410          // Enable logging plugin.
 411          set_config('enabled_stores', 'logstore_standard', 'tool_log');
 412          set_config('buffersize', 0, 'logstore_standard');
 413          $manager = get_log_manager(true);
 414  
 415          // User must be enrolled in course.
 416          $generator = $this->getDataGenerator();
 417          $course = $generator->create_course();
 418          $user = $generator->create_user();
 419          $this->getDataGenerator()->enrol_user($user->id, $course->id, 'student');
 420          $this->setUser($user);
 421  
 422          // Apply JSON format system setting.
 423          set_config('jsonformat', $jsonformat ? 1 : 0, 'logstore_standard');
 424  
 425          // Create some log data in a course - one with other data, one without.
 426          \logstore_standard\event\unittest_executed::create([
 427                  'context' => context_course::instance($course->id),
 428                  'other' => ['sample' => 5, 'xx' => 10]])->trigger();
 429          $this->waitForSecond();
 430          \logstore_standard\event\unittest_executed::create([
 431                  'context' => context_course::instance($course->id)])->trigger();
 432  
 433          $records = array_values($DB->get_records('logstore_standard_log',
 434                  ['courseid' => $course->id, 'target' => 'unittest'], 'timecreated'));
 435          $this->assertCount(2, $records);
 436  
 437          // Work out expected 'other' values based on JSON format.
 438          $expected0 = [
 439              false => 'a:2:{s:6:"sample";i:5;s:2:"xx";i:10;}',
 440              true => '{"sample":5,"xx":10}'
 441          ];
 442          $expected1 = [
 443              false => 'N;',
 444              true => 'null'
 445          ];
 446  
 447          // Backup the course twice, including log data.
 448          $this->setAdminUser();
 449          $backupid1 = $this->backup($course);
 450          $backupid2 = $this->backup($course);
 451  
 452          // Restore it with same jsonformat.
 453          $newcourseid = $this->restore($backupid1, $course, '_A');
 454  
 455          // Check entries are correctly encoded.
 456          $records = array_values($DB->get_records('logstore_standard_log',
 457                  ['courseid' => $newcourseid, 'target' => 'unittest'], 'timecreated'));
 458          $this->assertCount(2, $records);
 459          $this->assertEquals($expected0[$jsonformat], $records[0]->other);
 460          $this->assertEquals($expected1[$jsonformat], $records[1]->other);
 461  
 462          // Change JSON format to opposite value and restore again.
 463          set_config('jsonformat', $jsonformat ? 0 : 1, 'logstore_standard');
 464          $newcourseid = $this->restore($backupid2, $course, '_B');
 465  
 466          // Check entries are correctly encoded in other format.
 467          $records = array_values($DB->get_records('logstore_standard_log',
 468                  ['courseid' => $newcourseid, 'target' => 'unittest'], 'timecreated'));
 469          $this->assertEquals($expected0[!$jsonformat], $records[0]->other);
 470          $this->assertEquals($expected1[!$jsonformat], $records[1]->other);
 471      }
 472  
 473      /**
 474       * Backs a course up to temp directory.
 475       *
 476       * @param stdClass $course Course object to backup
 477       * @return string ID of backup
 478       */
 479      protected function backup($course): string {
 480          global $USER, $CFG;
 481          require_once($CFG->dirroot . '/backup/util/includes/backup_includes.php');
 482  
 483          // Turn off file logging, otherwise it can't delete the file (Windows).
 484          $CFG->backup_file_logger_level = backup::LOG_NONE;
 485  
 486          // Do backup with default settings. MODE_IMPORT means it will just
 487          // create the directory and not zip it.
 488          $bc = new backup_controller(backup::TYPE_1COURSE, $course->id,
 489                  backup::FORMAT_MOODLE, backup::INTERACTIVE_NO, backup::MODE_IMPORT,
 490                  $USER->id);
 491          $bc->get_plan()->get_setting('users')->set_status(backup_setting::NOT_LOCKED);
 492          $bc->get_plan()->get_setting('users')->set_value(true);
 493          $bc->get_plan()->get_setting('logs')->set_value(true);
 494          $backupid = $bc->get_backupid();
 495  
 496          $bc->execute_plan();
 497          $bc->destroy();
 498          return $backupid;
 499      }
 500  
 501      /**
 502       * Restores a course from temp directory.
 503       *
 504       * @param string $backupid Backup id
 505       * @param \stdClass $course Original course object
 506       * @param string $suffix Suffix to add after original course shortname and fullname
 507       * @return int New course id
 508       * @throws restore_controller_exception
 509       */
 510      protected function restore(string $backupid, $course, string $suffix): int {
 511          global $USER, $CFG;
 512          require_once($CFG->dirroot . '/backup/util/includes/restore_includes.php');
 513  
 514          // Do restore to new course with default settings.
 515          $newcourseid = restore_dbops::create_new_course(
 516                  $course->fullname . $suffix, $course->shortname . $suffix, $course->category);
 517          $rc = new restore_controller($backupid, $newcourseid,
 518                  backup::INTERACTIVE_NO, backup::MODE_GENERAL, $USER->id,
 519                  backup::TARGET_NEW_COURSE);
 520          $rc->get_plan()->get_setting('logs')->set_value(true);
 521          $rc->get_plan()->get_setting('users')->set_value(true);
 522  
 523          $this->assertTrue($rc->execute_precheck());
 524          $rc->execute_plan();
 525          $rc->destroy();
 526  
 527          return $newcourseid;
 528      }
 529  
 530      /**
 531       * Disable the garbage collector if it's enabled to ensure we don't adjust memory statistics.
 532       */
 533      private function disable_gc() {
 534          if (gc_enabled()) {
 535              $this->wedisabledgc = true;
 536              gc_disable();
 537          }
 538      }
 539  
 540      /**
 541       * Reset any garbage collector changes to the previous state at the end of the test.
 542       */
 543      public function tearDown(): void {
 544          if ($this->wedisabledgc) {
 545              gc_enable();
 546          }
 547          $this->wedisabledgc = false;
 548      }
 549  }