[Summary view]

Differences Between: [Versions 39 and 310] [Versions 39 and 311] [Versions 39 and 400] [Versions 39 and 401] [Versions 39 and 402] [Versions 39 and 403]

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