assert_error_log.inc

# ==== Purpose ====
#
# Assert that the error log contains a given set of messages, and
# nothing else.  The messages are given as a sequence of regular
# expressions.  As a special case, if the list is set to NONE, the
# script asserts that no error was generated.  The script inspects
# only the tail of the error log generated from the last invocation of
# include/save_error_log_position.inc, or from the last invocation of
# this script; whatever happened most recently.
#
# ==== Suppressed messages are excluded from the check ====
#
# This script does not inspect messages that have been suppressed,
# either globally or by the test, i.e.:
#
# - Globally suppressed messages are listed in the
#   mtr.global_suppressions table, which is created and populated in
#   mtr_warnings.sql.
#
# - Per-test suppressed messages are listed in the
#   mtr.test_suppressions table, which is created in mtr_warnings.sql
#   and populated when the test either invokes mtr.add_suppression or
#   sources include/suppress_messages.inc.
#
# If you need to use this script with a message that has been
# suppressed globally, you need to ignore the global suppression: set
# $suppress_mode=IGNORE_GLOBAL_SUPPRESSION and source
# include/suppress_message.inc (see suppress_message.inc for details).
#
# ==== This script adds suppressions ====
#
# When this script finds an expected message in the log, it
# automatically adds a suppression for the message.  This prevents
# failure of the the check-testcase script that mtr runs after the
# test has finished.  In case the same message appears several times
# in the log, only the instances that were found by this script are
# suppressed, and others may be reported by the check-testcase script.
# (The suppression uses the full error log line, which includes a
# unique timestamp.)
#
# ==== Usage ====
#
# --source include/save_error_log_position.inc
# ... generate some errors...
# let $error_pattern = {
#     ERROR_1_REGEX
#     ERROR_2_REGEX
#     ...
#   | SHOW | NONE | SAVEPOS | DEBUG_STATUS };
# [--let $assert_dont_fail = 1]
# [--let $keep_old_error_log_position = 1]
# [--let $error_log_server_number = NUMBER]
# --source include/assert_error_log.inc
#
# Parameters:
#
#   $error_pattern
#
#     Normally this is a string containing a regular expression,
#     matching the expected error.
#
#     This can be a multi-line string: the first line matches the
#     first error, the second line matches the second error, and so
#     on.
#
#     It can also be NONE, indicating that the expectation is to
#     have no error in the log.
#
#     The special value SHOW is used by show_error_log.inc.  It should not
#     normally be used in any other context.
#
#     The special value SAVEPOS is used by
#     save_error_log_position.inc It should not normally be used in
#     any other context.
#
#     The special value DEBUG_STATUS can be used to show the internal
#     state of the error message assertion framework.
#
#   $keep_old_error_log_position
#
#     Normally, this script saves the current error log position after
#     reading the error log, so that the next invocation of
#     assert_error_log.inc starts after the current position.
#
#     To keep the old position, set this variable to 1.
#
#   $assert_dont_fail
#
#     If set to 1, failure to match the regular expression does not
#     make the test fail immediately. The output will fail with result
#     mismatch but the test can complete.  This can be used during
#     test development and debugging, but must not be used in tests
#     that are pushed to a main branch.
#
#   $error_log_server_number
#
#     By default, this script operates on the error log for the server
#     of the current connection.  To use this script from a connection
#     on a different server, set this to the number of the server
#     whose log should be inspected.
#
#   $ignore_global_suppressions
#
#     By default, this script takes into account both the global
#     suppressions defined in include/mtr_warnings.sql, and any
#     per-test suppressions that the test may have added through
#     mtr.add_suppression or include/suppress_message.inc.  This
#     option removes the check for global suppressions, allowing you
#     to check for those errors. Notes:
#     - Enabling this parameter may remove too many suppressions. If
#       that is the case, you can ignore individual global
#       suppressions using include/suppress_messages.inc with
#       $suppress_mode=IGNORE_GLOBAL_SUPPRESSIONS.
#     - Enabling this parameter will not ignore per-suppressions added
#       by mtr.add_suppression or include/suppress_message.inc.  If
#       you need that, just remove the per-test suppression from the
#       test.

# Get server number
--let $_ael_server_number = $error_log_server_number
if (!$_ael_server_number) {
  --let $_ael_server_number = `SELECT @@global.server_id`
}

--let $include_filename = assert_error_log.inc [server: $_ael_server_number, pattern: $error_pattern]
--source include/begin_include_file.inc

--source include/rpl/disable_binlog.inc

if (!$rpl_debug) {
  --disable_query_log
}

if ($error_pattern != DEBUG_STATUS) {
  # Get error log filename
  --let $_ael_error_log_filename_save = $error_log_filename
  if (!$error_log_filename) {
    if ($error_log_server_number) {
      --let $error_log_filename = $MYSQLTEST_VARDIR/log/mysqld.$_ael_server_number.err
    }
    if (!$error_log_server_number) {
      --let $error_log_filename = `SELECT IF(@@global.log_error = 'stderr', CONCAT('$MYSQLTEST_VARDIR/log/mysqld.', $_ael_server_number, '.err'), @@global.log_error)`
    }
  }

  # Get line count to skip
  if (!$_ael_positions) {
    --let $_ael_positions = {"1":-1,"2":-1,"3":-1,"4":-1,"5":-1,"6":-1,"7":-1,"8":-1,"9":-1,"10":-1}
  }
  --let $json_object = $_ael_positions
  --let $json_key = $_ael_server_number
  --source include/json_lookup.inc
  --let $ignore_line_count = $json_value
  if ($ignore_line_count == -1) {
    if ($error_pattern != SAVEPOS) {
      if ($error_pattern != SHOW) {
        --die !!!ERROR IN TEST: use save_error_log_position.inc before the first call to assert_error_log.inc. The error log may contain errors from earlier test runs.
      }
    }
    --let $ignore_line_count = 0
  }

  # Load error log from file into temporary table
  --source include/load_error_log.inc

  if ($rpl_debug) {
    SELECT * FROM mtr.error_log;
  }

  # Compute number of errors.
  --let $_ael_error_count = `SELECT COUNT(*) FROM mtr.error_log`
  if ($rpl_debug) {
    --echo # ignored $ignore_line_count lines from the error log
    --echo # found $_ael_error_count new lines after that position
  }

  # Update position
  --expr $_ael_new_offset = $ignore_line_count + $_ael_error_count
  if (!$keep_old_error_log_position) {
    --let $_ael_positions = `SELECT JSON_SET('$json_object', '$."$_ael_server_number"', $_ael_new_offset)`

    if ($rpl_debug) {
      --echo _ael_positions=<$_ael_positions>
    }
  }

  if ($error_pattern != SAVEPOS) {

    # For check-warnings, mtr pre-filters the log, including only Note and
    # Warning (and some other patterns related to Valgrind and stack traces,
    # but those are not relevant in this case).
    UPDATE mtr.error_log SET suspicious = 0 WHERE line NOT REGEXP '\\[(Error|Warning)\\]';

    if (!$ignore_global_suppressions) {
      CALL mtr.filter_global_suppressed_warnings();
    }
    CALL mtr.filter_test_suppressed_warnings();

    # Move filtered-in rows to a a new table in order to recompute the
    # autoincrement column so that it becomes consecutive and can be
    # joined with the pattern table.
    CREATE TEMPORARY TABLE mtr.filtered_error_log (id INT PRIMARY KEY AUTO_INCREMENT, message TEXT);
    INSERT INTO mtr.filtered_error_log(message) SELECT line FROM mtr.error_log WHERE suspicious = 1 ORDER BY id;
    if ($rpl_debug) {
      SELECT * FROM mtr.filtered_error_log;
    }

    --let $_ael_included_error_count = `SELECT COUNT(*) FROM mtr.filtered_error_log`

    if ($error_pattern != SHOW) {
      # Load expected error patterns from $error_pattern into temporary table.
      CREATE TEMPORARY TABLE mtr.error_patterns (id INT PRIMARY KEY AUTO_INCREMENT, pattern TEXT);
      if ($error_pattern != NONE) {
        # tmp_error_patterns contains all rows of $error_pattern, including comments and empty lines.
        CREATE TEMPORARY TABLE mtr.tmp_error_patterns (id INT PRIMARY KEY AUTO_INCREMENT, pattern TEXT);
        # Convert a multi-line string into a multi-row INSERT, by replacing
        # newlines by:
        #  '),('
        # Apply QUOTE before the newline-to-multirow conversion, so that
        # quotes within each message remain escaped but quotes that surround
        # each row remain unescaped.
        --let $_ael_pattern_escaped = escape(\',$error_pattern)
        --let $_ael_pattern_list = `SELECT REPLACE(QUOTE('$_ael_pattern_escaped'), '\n', "'),('")`
        eval INSERT INTO mtr.tmp_error_patterns(pattern) VALUES($_ael_pattern_list);
        # Filter out empty lines and comments
        INSERT INTO mtr.error_patterns(pattern) SELECT pattern FROM mtr.tmp_error_patterns WHERE pattern NOT REGEXP '^ *(#.*)?$' ORDER BY id;
        DROP TEMPORARY TABLE mtr.tmp_error_patterns;
      }
      --let $_ael_pattern_count = `SELECT COUNT(*) FROM mtr.error_patterns`

      # Check if the number of errors is as expected
      if ($_ael_included_error_count != $_ael_pattern_count) {
        --expr $_ael_excluded_error_count = $_ael_error_count - $_ael_included_error_count
        --echo Expected $_ael_pattern_count errors in the error log, but got $_ael_included_error_count.
        --echo We excluded the first $ignore_line_count lines. From the remaining $_ael_error_count lines (up to line $_ael_new_offset), we excluded $_ael_excluded_error_count lines that matched a suppression pattern.
        --let $_ael_failure = 1
      }

      # Check if the error texts match the patterns
      if ($_ael_included_error_count == $_ael_pattern_count) {
        --let $_ael_find_mismatch = FROM mtr.filtered_error_log e, mtr.error_patterns p WHERE e.id = p.id AND NOT e.message REGEXP p.pattern
        --let $_ael_mismatch_count = `SELECT COUNT(*) $_ael_find_mismatch`
        if ($_ael_mismatch_count) {
          --echo There were $_ael_mismatch_count error log lines which did not match the expected pattern:
          --let $_ael_offset = 0
          while ($_ael_offset < $_ael_mismatch_count) {
            --let $_ael_error = `SELECT e.message $_ael_find_mismatch LIMIT $_ael_offset, 1`
            --let $_ael_pattern = `SELECT p.pattern $_ael_find_mismatch LIMIT $_ael_offset, 1`
            --inc $_ael_offset
            --echo Mismatch $_ael_offset: error: <$_ael_error>
            --echo Mismatch $_ael_offset: pattern: <$_ael_pattern>
          }
          --let $_ael_failure = 1
        }
      }

      # Report error
      if ($_ael_failure) {
        --echo Error patterns:
        SELECT * FROM mtr.error_patterns;
        --echo Errors found in log on server $_ael_server_number:
        SELECT * FROM mtr.filtered_error_log;
        if (!$assert_dont_fail) {
          --die Errors did not match the expected list of patterns.
        }
      }

      # Note: suppression of asserted messages is based on string equality,
      # not regex search, in order to catch cases where the error is generated
      # without being checked.
      --disable_warnings
      INSERT IGNORE INTO mtr.asserted_test_suppressions SELECT message FROM mtr.filtered_error_log;
      if ($rpl_debug) {
        SELECT * FROM mtr.asserted_test_suppressions;
      }
      --enable_warnings
      DROP TEMPORARY TABLE mtr.error_patterns;
    }
    if ($error_pattern == SHOW) {
      if (!$assert_error_log_printed_do_not_check_in_this_line) {
        --let $assert_error_log_printed_do_not_check_in_this_line = 1
        --echo DO_NOT_CHECK_IN_THIS_LINE: include/show_error_log.inc should only be used for debugging. Never check in a test that calls it on success.
      }
      --echo # There were $_ael_included_error_count new errors on server $_ael_server_number:
      if ($_ael_included_error_count) {
        SELECT * FROM mtr.filtered_error_log;
      }
    }

    DROP TEMPORARY TABLE mtr.filtered_error_log;
  }

  DROP TEMPORARY TABLE mtr.error_log;
}

if ($error_pattern == DEBUG_STATUS) {
  --enable_query_log
  --echo # Static suppression patterns defined in mtr_warnings.sql
  SELECT * FROM mtr.global_suppressions;
  --echo
  --echo # Suppression patterns added by the test case, using
  --echo # mtr.add_suppression or include/suppress_messages.inc.
  SELECT * FROM mtr.test_suppressions;
  --echo
  --echo # Messages that were matched by an expected pattern in a previous
  --echo # invocation of assert_error_log.inc. These are excluded from the
  --echo # check that runs after the test has finished.
  SELECT * FROM mtr.asserted_test_suppressions;
  --echo
  --echo # Patterns added by the test case to make exceptions from
  --echo # mtr.global_suppressions, using include/suppress_messages.inc with
  --echo # suppress_mode=IGNORE_GLOBAL_SUPPRESSIONS.  This may be added
  --echo # by tests that need to assert the existence of a message that is
  --echo # included in mtr.global_suppressions.
  SELECT * FROM mtr.test_ignored_global_suppressions;
}

--let $error_log_filename = $_ael_error_log_filename_save
--source include/rpl/restore_binlog.inc

--let $include_filename = assert_error_log.inc
--source include/end_include_file.inc