dblog.test 20.5 KB
Newer Older
1 2
<?php

3 4 5 6 7
/**
 * @file
 * Tests for dblog.module.
 */

8
class DBLogTestCase extends DrupalWebTestCase {
9 10
  protected $profile = 'standard';

11 12 13
  protected $big_user;
  protected $any_user;

14
  public static function getInfo() {
15
    return array(
16 17 18
      'name' => 'DBLog functionality',
      'description' => 'Generate events and verify dblog entries; verify user access to log reports based on persmissions.',
      'group' => 'DBLog',
19 20 21 22 23 24 25
    );
  }

  /**
   * Enable modules and create users with specific permissions.
   */
  function setUp() {
26
    parent::setUp('dblog', 'poll');
27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45
    // Create users.
    $this->big_user = $this->drupalCreateUser(array('administer site configuration', 'access administration pages', 'access site reports', 'administer users'));
    $this->any_user = $this->drupalCreateUser(array());
  }

  /**
   * Login users, create dblog events, and test dblog functionality through the admin and user interfaces.
   */
  function testDBLog() {
    // Login the admin user.
    $this->drupalLogin($this->big_user);

    $row_limit = 100;
    $this->verifyRowLimit($row_limit);
    $this->verifyCron($row_limit);
    $this->verifyEvents();
    $this->verifyReports();

    // Login the regular user.
46
    $this->drupalLogin($this->any_user);
47 48 49 50 51 52 53 54 55 56 57 58
    $this->verifyReports(403);
  }

  /**
   * Verify setting of the dblog row limit.
   *
   * @param integer $count Log row limit.
   */
  private function verifyRowLimit($row_limit) {
    // Change the dblog row limit.
    $edit = array();
    $edit['dblog_row_limit'] = $row_limit;
59
    $this->drupalPost('admin/config/development/logging', $edit, t('Save configuration'));
60
    $this->assertResponse(200);
61

62 63
    // Check row limit variable.
    $current_limit = variable_get('dblog_row_limit', 1000);
64
    $this->assertTrue($current_limit == $row_limit, t('[Cache] Row limit variable of @count equals row limit of @limit', array('@count' => $current_limit, '@limit' => $row_limit)));
65
    // Verify dblog row limit equals specified row limit.
66
    $current_limit = unserialize(db_query("SELECT value FROM {variable} WHERE name = :dblog_limit", array(':dblog_limit' => 'dblog_row_limit'))->fetchField());
67
    $this->assertTrue($current_limit == $row_limit, t('[Variable table] Row limit variable of @count equals row limit of @limit', array('@count' => $current_limit, '@limit' => $row_limit)));
68 69 70 71 72 73 74 75 76 77 78
  }

  /**
   * Verify cron applies the dblog row limit.
   *
   * @param integer $count Log row limit.
   */
  private function verifyCron($row_limit) {
    // Generate additional log entries.
    $this->generateLogEntries($row_limit + 10);
    // Verify dblog row count exceeds row limit.
79
    $count = db_query('SELECT COUNT(wid) FROM {watchdog}')->fetchField();
80
    $this->assertTrue($count > $row_limit, t('Dblog row count of @count exceeds row limit of @limit', array('@count' => $count, '@limit' => $row_limit)));
81 82

    // Run cron job.
83
    $this->cronRun();
84
    // Verify dblog row count equals row limit plus one because cron adds a record after it runs.
85
    $count = db_query('SELECT COUNT(wid) FROM {watchdog}')->fetchField();
86
    $this->assertTrue($count == $row_limit + 1, t('Dblog row count of @count equals row limit of @limit plus one', array('@count' => $count, '@limit' => $row_limit)));
87 88 89 90 91
  }

  /**
   * Generate dblog entries.
   *
92 93 94 95 96 97
   * @param integer $count
   *   Number of log entries to generate.
   * @param $type
   *   The type of watchdog entry.
   * @param $severity
   *   The severity of the watchdog entry.
98
   */
99
  private function generateLogEntries($count, $type = 'custom', $severity = WATCHDOG_NOTICE) {
100 101 102 103
    global $base_root;

    // Prepare the fields to be logged
    $log = array(
104
      'type'        => $type,
105 106
      'message'     => 'Log entry added to test the dblog row limit.',
      'variables'   => array(),
107
      'severity'    => $severity,
108 109 110
      'link'        => NULL,
      'user'        => $this->big_user,
      'request_uri' => $base_root . request_uri(),
111
      'referer'     => $_SERVER['HTTP_REFERER'],
112
      'ip'          => ip_address(),
113
      'timestamp'   => REQUEST_TIME,
114
      );
115
    $message = 'Log entry added to test the dblog row limit. Entry #';
116
    for ($i = 0; $i < $count; $i++) {
117
      $log['message'] = $message . $i;
118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133
      dblog_watchdog($log);
    }
  }

  /**
   * Verify the logged in user has the desired access to the various dblog nodes.
   *
   * @param integer $response HTTP response code.
   */
  private function verifyReports($response = 200) {
    $quote = '&#039;';

    // View dblog help node.
    $this->drupalGet('admin/help/dblog');
    $this->assertResponse($response);
    if ($response == 200) {
134
      $this->assertText(t('Database Logging'), t('DBLog help was displayed'));
135 136 137 138 139 140
    }

    // View dblog report node.
    $this->drupalGet('admin/reports/dblog');
    $this->assertResponse($response);
    if ($response == 200) {
141
      $this->assertText(t('Recent log messages'), t('DBLog report was displayed'));
142 143 144 145 146 147
    }

    // View dblog page-not-found report node.
    $this->drupalGet('admin/reports/page-not-found');
    $this->assertResponse($response);
    if ($response == 200) {
148
      $this->assertText(t('Top ' . $quote . 'page not found' . $quote . ' errors'), t('DBLog page-not-found report was displayed'));
149 150 151 152 153 154
    }

    // View dblog access-denied report node.
    $this->drupalGet('admin/reports/access-denied');
    $this->assertResponse($response);
    if ($response == 200) {
155
      $this->assertText(t('Top ' . $quote . 'access denied' . $quote . ' errors'), t('DBLog access-denied report was displayed'));
156 157 158 159 160 161
    }

    // View dblog event node.
    $this->drupalGet('admin/reports/event/1');
    $this->assertResponse($response);
    if ($response == 200) {
162
      $this->assertText(t('Details'), t('DBLog event node was displayed'));
163 164 165 166 167 168 169 170 171 172 173 174 175
    }
  }

  /**
   * Verify events.
   */
  private function verifyEvents() {
    // Invoke events.
    $this->doUser();
    $this->doNode('article');
    $this->doNode('page');
    $this->doNode('poll');

176
    // When a user account is canceled, any content they created remains but the
177 178
    // uid = 0. Records in the watchdog table related to that user have the uid
    // set to zero.
179 180 181 182 183 184
  }

  /**
   * Generate and verify user events.
   *
   */
185
  private function doUser() {
186
    // Set user variables.
187
    $name = $this->randomName();
188 189 190 191
    $pass = user_password();
    // Add user using form to generate add user event (which is not triggered by drupalCreateUser).
    $edit = array();
    $edit['name'] = $name;
192
    $edit['mail'] = $name . '@example.com';
193 194 195
    $edit['pass[pass1]'] = $pass;
    $edit['pass[pass2]'] = $pass;
    $edit['status'] = 1;
196
    $this->drupalPost('admin/people/create', $edit, t('Create new account'));
197 198
    $this->assertResponse(200);
    // Retrieve user object.
199
    $user = user_load_by_name($name);
200
    $this->assertTrue($user != NULL, t('User @name was loaded', array('@name' => $name)));
201 202 203 204 205 206
    $user->pass_raw = $pass; // Needed by drupalLogin.
    // Login user.
    $this->drupalLogin($user);
    // Logout user.
    $this->drupalLogout();
    // Fetch row ids in watchdog that relate to the user.
207
    $result = db_query('SELECT wid FROM {watchdog} WHERE uid = :uid', array(':uid' => $user->uid));
208
    foreach ($result as $row) {
209
      $ids[] = $row->wid;
210 211
    }
    $count_before = (isset($ids)) ? count($ids) : 0;
212
    $this->assertTrue($count_before > 0, t('DBLog contains @count records for @name', array('@count' => $count_before, '@name' => $user->name)));
213 214 215

    // Login the admin user.
    $this->drupalLogin($this->big_user);
216
    // Delete user.
217 218 219
    // We need to POST here to invoke batch_process() in the internal browser.
    $this->drupalPost('user/' . $user->uid . '/cancel', array('user_cancel_method' => 'user_cancel_reassign'), t('Cancel account'));

220 221 222 223 224 225 226
    // View the dblog report.
    $this->drupalGet('admin/reports/dblog');
    $this->assertResponse(200);

    // Verify events were recorded.
    // Add user.
    // Default display includes name and email address; if too long then email is replaced by three periods.
227
    $this->assertLogMessage(t('New user: %name (%email).', array('%name' => $name, '%email' => $user->mail)), t('DBLog event was recorded: [add user]'));
228
    // Login user.
229
    $this->assertLogMessage(t('Session opened for %name.', array('%name' => $name)), t('DBLog event was recorded: [login user]'));
230
    // Logout user.
231
    $this->assertLogMessage(t('Session closed for %name.', array('%name' => $name)), t('DBLog event was recorded: [logout user]'));
232
    // Delete user.
233 234 235 236 237 238 239 240 241 242 243 244 245
    $message = t('Deleted user: %name %email.', array('%name' => $name, '%email' => '<' . $user->mail . '>'));
    $message_text = truncate_utf8(filter_xss($message, array()), 56, TRUE, TRUE);
    // Verify full message on details page.
    $link = FALSE;
    if ($links = $this->xpath('//a[text()="' . html_entity_decode($message_text) . '"]')) {
      // Found link with the message text.
      $links = array_shift($links);
      foreach ($links->attributes() as $attr => $value) {
        if ($attr == 'href') {
          // Extract link to details page.
          $link = drupal_substr($value, strpos($value, 'admin/reports/event/'));
          $this->drupalGet($link);
          // Check for full message text on the details page.
246
          $this->assertRaw($message, t('DBLog event details was found: [delete user]'));
247 248 249 250
          break;
        }
      }
    }
251
    $this->assertTrue($link, t('DBLog event was recorded: [delete user]'));
252 253 254 255 256 257 258 259
    // Visit random URL (to generate page not found event).
    $not_found_url = $this->randomName(60);
    $this->drupalGet($not_found_url);
    $this->assertResponse(404);
    // View dblog page-not-found report page.
    $this->drupalGet('admin/reports/page-not-found');
    $this->assertResponse(200);
    // Check that full-length url displayed.
260
    $this->assertText($not_found_url, t('DBLog event was recorded: [page not found]'));
261 262 263 264 265 266 267 268 269
  }

  /**
   * Generate and verify node events.
   *
   * @param string $type Content type.
   */
  private function doNode($type) {
    // Create user.
270
    $perm = array('create ' . $type . ' content', 'edit own ' . $type . ' content', 'delete own ' . $type . ' content');
271 272 273 274 275 276
    $user = $this->drupalCreateUser($perm);
    // Login user.
    $this->drupalLogin($user);

    // Create node using form to generate add content event (which is not triggered by drupalCreateNode).
    $edit = $this->getContent($type);
277
    $langcode = LANGUAGE_NOT_SPECIFIED;
278
    $title = $edit["title"];
279
    $this->drupalPost('node/add/' . $type, $edit, t('Save'));
280 281
    $this->assertResponse(200);
    // Retrieve node object.
282
    $node = $this->drupalGetNodeByTitle($title);
283
    $this->assertTrue($node != NULL, t('Node @title was loaded', array('@title' => $title)));
284 285
    // Edit node.
    $edit = $this->getContentUpdate($type);
286
    $this->drupalPost('node/' . $node->nid . '/edit', $edit, t('Save'));
287 288
    $this->assertResponse(200);
    // Delete node.
289
    $this->drupalPost('node/' . $node->nid . '/delete', array(), t('Delete'));
290 291
    $this->assertResponse(200);
    // View node (to generate page not found event).
292
    $this->drupalGet('node/' . $node->nid);
293 294 295 296 297 298 299 300 301 302 303 304 305
    $this->assertResponse(404);
    // View the dblog report (to generate access denied event).
    $this->drupalGet('admin/reports/dblog');
    $this->assertResponse(403);

    // Login the admin user.
    $this->drupalLogin($this->big_user);
    // View the dblog report.
    $this->drupalGet('admin/reports/dblog');
    $this->assertResponse(200);

    // Verify events were recorded.
    // Content added.
306
    $this->assertLogMessage(t('@type: added %title.', array('@type' => $type, '%title' => $title)), t('DBLog event was recorded: [content added]'));
307
    // Content updated.
308
    $this->assertLogMessage(t('@type: updated %title.', array('@type' => $type, '%title' => $title)), t('DBLog event was recorded: [content updated]'));
309
    // Content deleted.
310
    $this->assertLogMessage(t('@type: deleted %title.', array('@type' => $type, '%title' => $title)), t('DBLog event was recorded: [content deleted]'));
311 312 313 314 315

    // View dblog access-denied report node.
    $this->drupalGet('admin/reports/access-denied');
    $this->assertResponse(200);
    // Access denied.
316
    $this->assertText(t('admin/reports/dblog'), t('DBLog event was recorded: [access denied]'));
317 318 319 320 321

    // View dblog page-not-found report node.
    $this->drupalGet('admin/reports/page-not-found');
    $this->assertResponse(200);
    // Page not found.
322
    $this->assertText(t('node/@nid', array('@nid' => $node->nid)), t('DBLog event was recorded: [page not found]'));
323 324 325 326 327 328 329 330 331
  }

  /**
   * Create content based on content type.
   *
   * @param string $type Content type.
   * @return array Content.
   */
  private function getContent($type) {
332
    $langcode = LANGUAGE_NOT_SPECIFIED;
333 334 335
    switch ($type) {
      case 'poll':
        $content = array(
336
          "title" => $this->randomName(8),
337 338
          'choice[new:0][chtext]' => $this->randomName(32),
          'choice[new:1][chtext]' => $this->randomName(32),
339
        );
340
      break;
341 342 343

      default:
        $content = array(
344
          "title" => $this->randomName(8),
345
          "body[$langcode][0][value]" => $this->randomName(32),
346
        );
347
      break;
348 349 350 351 352 353 354 355 356 357 358 359 360 361
    }
    return $content;
  }

  /**
   * Create content update based on content type.
   *
   * @param string $type Content type.
   * @return array Content.
   */
  private function getContentUpdate($type) {
    switch ($type) {
      case 'poll':
        $content = array(
362 363
          'choice[chid:1][chtext]' => $this->randomName(32),
          'choice[chid:2][chtext]' => $this->randomName(32),
364
        );
365
      break;
366 367

      default:
368
        $langcode = LANGUAGE_NOT_SPECIFIED;
369
        $content = array(
370
          "body[$langcode][0][value]" => $this->randomName(32),
371
        );
372
      break;
373 374 375
    }
    return $content;
  }
376 377 378 379 380 381 382 383 384 385 386 387

  /**
   * Login an admin user, create dblog event, and test clearing dblog functionality through the admin interface.
   */
  protected function testDBLogAddAndClear() {
    global $base_root;
    // Get a count of how many watchdog entries there are.
    $count = db_query('SELECT COUNT(*) FROM {watchdog}')->fetchField();
    $log = array(
      'type'        => 'custom',
      'message'     => 'Log entry added to test the doClearTest clear down.',
      'variables'   => array(),
388
      'severity'    => WATCHDOG_NOTICE,
389 390 391 392 393 394 395 396 397 398
      'link'        => NULL,
      'user'        => $this->big_user,
      'request_uri' => $base_root . request_uri(),
      'referer'     => $_SERVER['HTTP_REFERER'],
      'ip'          => ip_address(),
      'timestamp'   => REQUEST_TIME,
    );
    // Add a watchdog entry.
    dblog_watchdog($log);
    // Make sure the table count has actually incremented.
399
    $this->assertEqual($count + 1, db_query('SELECT COUNT(*) FROM {watchdog}')->fetchField(), t('dblog_watchdog() added an entry to the dblog :count', array(':count' => $count)));
400 401 402 403 404 405
    // Login the admin user.
    $this->drupalLogin($this->big_user);
    // Now post to clear the db table.
    $this->drupalPost('admin/reports/dblog', array(), t('Clear log messages'));
    // Count rows in watchdog that previously related to the deleted user.
    $count = db_query('SELECT COUNT(*) FROM {watchdog}')->fetchField();
406
    $this->assertEqual($count, 0, t('DBLog contains :count records after a clear.', array(':count' => $count)));
407
  }
408 409 410 411 412 413 414 415 416 417 418 419 420 421 422

  /**
   * Test the dblog filter on admin/reports/dblog.
   */
  protected function testFilter() {
    $this->drupalLogin($this->big_user);

    // Clear log to ensure that only generated entries are found.
    db_delete('watchdog')->execute();

    // Generate watchdog entries.
    $type_names = array();
    $types = array();
    for ($i = 0; $i < 3; $i++) {
      $type_names[] = $type_name = $this->randomName();
423
      $severity = WATCHDOG_EMERGENCY;
424 425 426 427 428 429 430 431 432 433 434 435 436 437 438 439 440 441 442 443 444 445 446 447 448 449 450 451 452 453 454 455 456 457 458 459 460 461 462 463 464 465 466 467 468 469 470 471 472 473 474
      for ($j = 0; $j < 3; $j++) {
        $types[] = $type = array(
          'count' => mt_rand(1, 5),
          'type' => $type_name,
          'severity' => $severity++,
        );
        $this->generateLogEntries($type['count'], $type['type'], $type['severity']);
      }
    }

    // View the dblog.
    $this->drupalGet('admin/reports/dblog');

    // Confirm all the entries are displayed.
    $count = $this->getTypeCount($types);
    foreach ($types as $key => $type) {
      $this->assertEqual($count[$key], $type['count'], 'Count matched');
    }

    // Filter by each type and confirm that entries with various severities are
    // displayed.
    foreach ($type_names as $type_name) {
      $edit = array(
        'type[]' => array($type_name),
      );
      $this->drupalPost(NULL, $edit, t('Filter'));

      // Count the number of entries of this type.
      $type_count = 0;
      foreach ($types as $type) {
        if ($type['type'] == $type_name) {
          $type_count += $type['count'];
        }
      }

      $count = $this->getTypeCount($types);
      $this->assertEqual(array_sum($count), $type_count, 'Count matched');
    }

    // Set filter to match each of the three type attributes and confirm the
    // number of entries displayed.
    foreach ($types as $key => $type) {
      $edit = array(
        'type[]' => array($type['type']),
        'severity[]' => array($type['severity']),
      );
      $this->drupalPost(NULL, $edit, t('Filter'));

      $count = $this->getTypeCount($types);
      $this->assertEqual(array_sum($count), $type['count'], 'Count matched');
    }
475 476 477 478
    
    // Clear all logs and make sure the confirmation message is found.
    $this->drupalPost('admin/reports/dblog', array(), t('Clear log messages'));
    $this->assertText(t('Database log cleared.'), t('Confirmation message found'));
479 480 481 482 483 484 485 486 487 488 489 490 491 492 493 494 495 496 497 498 499 500 501 502 503 504 505 506 507 508 509 510 511 512 513 514 515 516 517 518 519 520 521 522 523 524 525 526 527 528 529 530 531 532 533 534 535
  }

  /**
   * Get the log entry information form the page.
   *
   * @return
   *   List of entries and their information.
   */
  protected function getLogEntries() {
    $entries = array();
    if ($table = $this->xpath('.//table[@id="admin-dblog"]')) {
      $table = array_shift($table);
      foreach ($table->tbody->tr as $row) {
        $entries[] = array(
          'severity' => $this->getSeverityConstant($row['class']),
          'type' => $this->asText($row->td[1]),
          'message' => $this->asText($row->td[3]),
          'user' => $this->asText($row->td[4]),
        );
      }
    }
    return $entries;
  }

  /**
   * Get the count of entries per type.
   *
   * @param $types
   *   The type information to compare against.
   * @return
   *   The count of each type keyed by the key of the $types array.
   */
  protected function getTypeCount(array $types) {
    $entries = $this->getLogEntries();
    $count = array_fill(0, count($types), 0);
    foreach ($entries as $entry) {
      foreach ($types as $key => $type) {
        if ($entry['type'] == $type['type'] && $entry['severity'] == $type['severity']) {
          $count[$key]++;
          break;
        }
      }
    }
    return $count;
  }

  /**
   * Get the watchdog severity constant corresponding to the CSS class.
   *
   * @param $class
   *   CSS class attribute.
   * @return
   *   The watchdog severity constant or NULL if not found.
   */
  protected function getSeverityConstant($class) {
    // Reversed array from dblog_overview().
    $map = array(
536 537 538 539 540 541 542 543
      'dblog-debug' => WATCHDOG_DEBUG,
      'dblog-info' => WATCHDOG_INFO,
      'dblog-notice' => WATCHDOG_NOTICE,
      'dblog-warning' => WATCHDOG_WARNING,
      'dblog-error' => WATCHDOG_ERROR,
      'dblog-critical' => WATCHDOG_CRITICAL,
      'dblog-alert' => WATCHDOG_ALERT,
      'dblog-emerg' => WATCHDOG_EMERGENCY,
544 545 546 547 548 549 550 551 552 553 554 555 556 557 558 559 560 561 562 563 564 565 566 567 568 569
    );

    // Find the class that contains the severity.
    $classes = explode(' ', $class);
    foreach ($classes as $class) {
      if (isset($map[$class])) {
        return $map[$class];
      }
    }
    return NULL;
  }

  /**
   * Extract the text contained by the element.
   *
   * @param $element
   *   Element to extract text from.
   * @return
   *   Extracted text.
   */
  protected function asText(SimpleXMLElement $element) {
    if (!is_object($element)) {
      return $this->fail('The element is not an element.');
    }
    return trim(html_entity_decode(strip_tags($element->asXML())));
  }
570 571 572 573

  /**
   * Assert messages appear on the log overview screen.
   *
574 575 576 577
   * This function should be used only for admin/reports/dblog page, because it
   * check for the message link text truncated to 56 characters. Other dblog
   * pages have no detail links so contains a full message text.
   *
578 579 580 581 582 583
   * @param $log_message
   *   The message to check.
   * @param $message
   *   The message to pass to simpletest.
   */
  protected function assertLogMessage($log_message, $message) {
584 585 586 587
    $message_text = truncate_utf8(filter_xss($log_message, array()), 56, TRUE, TRUE);
    // After filter_xss() HTML entities should be converted to their characters
    // because assertLink() uses this string in xpath() to query DOM.
    $this->assertLink(html_entity_decode($message_text), 0, $message);
588
  }
589
}
590