[Summary view]

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

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