diff --git a/doc/newsfragments/3025_new.logmatcher_debug_logging.rst b/doc/newsfragments/3025_new.logmatcher_debug_logging.rst new file mode 100644 index 000000000..de6038878 --- /dev/null +++ b/doc/newsfragments/3025_new.logmatcher_debug_logging.rst @@ -0,0 +1 @@ +Add more logging to :py:meth:`~testplan.common.utils.match.LogMatcher.match`, :py:meth:`~testplan.common.utils.match.LogMatcher.not_match` and :py:meth:`~testplan.common.utils.match.LogMatcher.match_all` for debugging purpose. \ No newline at end of file diff --git a/examples/Assertions/Basic/test_plan_logfile.py b/examples/Assertions/Basic/test_plan_logfile.py index 05c330de3..e3468db2f 100755 --- a/examples/Assertions/Basic/test_plan_logfile.py +++ b/examples/Assertions/Basic/test_plan_logfile.py @@ -35,6 +35,8 @@ def logpath(self): def starting(self): super().starting() self._log = open(self.logpath, "wb+") + self._log.write(b"pretending setup line\n") + self._log.flush() self._sig = threading.Event() self._thr = threading.Thread(target=self._start_loop) self._thr.start() @@ -93,9 +95,9 @@ def match_logfile(self, env, result): def match_logfile_xfail(self, env, result): lm = LogMatcher(env.server.logpath, binary=True) with result.logfile.expect( - lm, r"pong", description="first assertion", timeout=0.2 + lm, r"pong", description="first assertion", timeout=1 ): - env.client.send(b"ping") + env.client.send(b"ping\n") @test_plan( diff --git a/testplan/common/utils/match.py b/testplan/common/utils/match.py index 2eab48751..28a32c879 100644 --- a/testplan/common/utils/match.py +++ b/testplan/common/utils/match.py @@ -6,11 +6,9 @@ import time import warnings from contextlib import closing -from itertools import repeat from typing import ( AnyStr, Dict, - Iterator, List, Match, Optional, @@ -41,6 +39,14 @@ Regex: TypeAlias = Union[str, bytes, Pattern] +def _format_logline(s): + if not s: + return "\n" + if len(s) <= 100: + return s + return f"{s[:100]} ... ({len(s) - 100} chars omitted)" + + def match_regexps_in_file( logpath: os.PathLike, log_extracts: List[Pattern] ) -> Tuple[bool, Dict[str, str], List[Pattern]]: @@ -109,11 +115,11 @@ def __enter__(self): def __exit__(self, exc_type, exc_value, traceback): if exc_type is not None: return False - s_pos = self.log_matcher.position m = self.log_matcher.match( self.regex, self.timeout, raise_on_timeout=False ) - e_pos = self.log_matcher.position + s_pos = self.log_matcher._debug_info_s[0] + e_pos = self.log_matcher._debug_info_e[0] if m is not None: self.match_results.append((m, self.regex, s_pos, e_pos)) else: @@ -142,6 +148,9 @@ def __init__( self.position: Optional[LogPosition] = None self.log_stream: FileLogStream = self._create_log_stream() + self._debug_info_s = () + self._debug_info_e = () + # deprecation helpers self.had_transformed = False @@ -241,41 +250,44 @@ def mark(self, name: str): """ self.marks[name] = self.position - def match( + def _match( self, - regex: Regex, - timeout: float = LOG_MATCHER_DEFAULT_TIMEOUT, - raise_on_timeout: bool = True, + regex: Pattern[AnyStr], + timeout: float, ) -> Optional[Match]: """ - Matches each line in the log file from the current line number to the - end of the file. If a match is found the line number is stored and the - match is returned. By default an exception is raised if no match is - found. + Base block for ``match``, ``not_match`` & ``match_all``, + as well as certain ``LogfileNamespace`` assertions. - :param regex: Regex string or compiled regular expression - (``re.compile``) + :param regex: Checked regular expression :param timeout: Timeout in seconds to wait for matching process, 0 means matching till EOF and not waiting for new lines, any value greater than 0 means doing matching up to such seconds, defaults to 5 seconds - :param raise_on_timeout: To raise TimeoutException or not :return: The regex match or None if no match is found """ match = None start_time = time.time() end_time = start_time + timeout - regex = self._prepare_regexp(regex) with closing(self.log_stream) as log: log.seek(self.position) + non_eof = "" while True: - if timeout > 0 and time.time() > end_time: - break line = log.readline() + if self._debug_info_s is None: + self._debug_info_s = ( + str(self.position) + if self.position is not None + else "", + start_time, + _format_logline(line), + ) + if line: + non_eof = line match = regex.match(line) if match: break @@ -284,20 +296,62 @@ def match( else: break + if timeout > 0 and time.time() > end_time: + break + self.position = self.log_stream.position + if self._debug_info_e is None: + self._debug_info_e = ( + str(self.position), + time.time(), + _format_logline(non_eof), + ) - if match is not None: + return match + + def match( + self, + regex: Regex, + timeout: float = LOG_MATCHER_DEFAULT_TIMEOUT, + raise_on_timeout: bool = True, + ) -> Optional[Match]: + """ + Matches each line in the log file from the current line number to the + end of the file. If a match is found the line number is stored and the + match is returned. By default an exception is raised if no match is + found. + + :param regex: Regex string or compiled regular expression + (``re.compile``) + :param timeout: Timeout in seconds to wait for matching process, + 0 means matching till EOF and not waiting for new lines, any + value greater than 0 means doing matching up to such seconds, + defaults to 5 seconds + :param raise_on_timeout: To raise TimeoutException or not + :return: The regex match or None if no match is found + """ + self._debug_info_s = None + self._debug_info_e = None + regex = self._prepare_regexp(regex) + + m = self._match(regex, timeout=timeout) + + if m is None: self.logger.debug( - "Match[%s] found in %.2fs", + "%s: no expected match[%s] found,\nsearch starting from %s (around %s), " + "where first line seen as:\n%s" + "and ending at %s (around %s), where last line seen as:\n%s", + self, regex.pattern, - time.time() - start_time, - ) - elif timeout and raise_on_timeout: - raise timing.TimeoutException( - "No match[{}] found in {}s".format(regex.pattern, timeout) + *self._debug_info_s, + *self._debug_info_e, ) + if timeout and raise_on_timeout: + raise timing.TimeoutException( + "No match[%s] found in %.2fs.", regex.pattern, timeout + ) - return match + return m def not_match( self, @@ -316,9 +370,22 @@ def not_match( 0 means should not wait and return whatever matched on initial scan, defaults to 5 seconds """ + self._debug_info_s = None + self._debug_info_e = None + regex = self._prepare_regexp(regex) + + m = self._match(regex, timeout) - match = self.match(regex, timeout, raise_on_timeout=False) - if match is not None: + if m is not None: + self.logger.debug( + "%s: unexpected match[%s] found,\nsearch starting from %s (around %s), " + "where first line seen as:\n%s" + "and ending at %s (around %s), where last line seen as:\n%s", + self, + regex.pattern, + *self._debug_info_s, + *self._debug_info_e, + ) raise Exception( f"Unexpected match[{regex.pattern}] found in {timeout}s" ) @@ -343,15 +410,37 @@ def match_all( matches = [] end_time = time.time() + timeout - try: - while timeout >= 0: - matches.append( - self.match(regex, timeout, raise_on_timeout=True) + self._debug_info_s = None + regex = self._prepare_regexp(regex) + + while True: + if timeout == 0: + t = 0 + else: + t = end_time - time.time() + if t <= 0: + break + self._debug_info_e = None + m = self._match(regex, t) + if m is not None: + matches.append(m) + else: + break + + if not matches: + self.logger.debug( + "%s: no expected match[%s] found,\nsearch starting from %s (around %s), " + "where first line seen as:\n%s" + "and ending at %s (around %s), where last line seen as:\n%s", + self, + regex.pattern, + *self._debug_info_s, + *self._debug_info_e, + ) + if timeout and raise_on_timeout: + raise timing.TimeoutException( + "No match[%s] found in %.2fs.", regex.pattern, timeout ) - timeout = end_time - time.time() - except timing.TimeoutException: - if not matches and raise_on_timeout: - raise return matches diff --git a/testplan/testing/multitest/entries/assertions.py b/testplan/testing/multitest/entries/assertions.py index 96655155f..6f097d4f3 100644 --- a/testplan/testing/multitest/entries/assertions.py +++ b/testplan/testing/multitest/entries/assertions.py @@ -1486,7 +1486,7 @@ class LogfileMatch(Assertion): """ @dataclass - class Result: + class ResultRep: matched: Optional[str] pattern: str start_pos: str @@ -1519,14 +1519,12 @@ def _truncate_str(s): @classmethod def _handle_quadruple(cls, tup): m, r, s, e = tup - if s is None: - s = "" r = re.compile(r).pattern - return cls.Result( + return cls.ResultRep( cls._truncate_str(m.group()) if m is not None else None, cls._truncate_str(r), - str(s), - str(e), + s, + e, ) def evaluate(self): diff --git a/testplan/testing/result.py b/testplan/testing/result.py index 6d61a6cec..e4d6bf1ab 100644 --- a/testplan/testing/result.py +++ b/testplan/testing/result.py @@ -1450,9 +1450,9 @@ def match( """ results = [] failure = None - s_pos = log_matcher.position m = log_matcher.match(regex, timeout, raise_on_timeout=False) - e_pos = log_matcher.position + s_pos = log_matcher._debug_info_s[0] + e_pos = log_matcher._debug_info_e[0] if m is not None: results.append((m, regex, s_pos, e_pos)) else: diff --git a/testplan/web_ui/testing/src/AssertionPane/AssertionTypes/LogfileMatchAssertion.js b/testplan/web_ui/testing/src/AssertionPane/AssertionTypes/LogfileMatchAssertion.js index 2ccdb7f2d..5c56c1257 100644 --- a/testplan/web_ui/testing/src/AssertionPane/AssertionTypes/LogfileMatchAssertion.js +++ b/testplan/web_ui/testing/src/AssertionPane/AssertionTypes/LogfileMatchAssertion.js @@ -36,7 +36,7 @@ const LogfileMatchAssertion = ({ assertion }) => { const { timeout, results, failure } = assertion; const timeoutMsg = - (assertion.passed ? "Passed" : "Failed") + ` in ${timeout} seconds.`; + (assertion.passed ? "Passed" : "Failed") + (timeout === 0 ? " when scanning till ." : ` in ${timeout} seconds.`); const entries = [...results, ...failure].map((entry, index) => { const { matched, pattern, start_pos: startPos, end_pos: endPos } = entry; return ( diff --git a/tests/unit/testplan/common/utils/test_match.py b/tests/unit/testplan/common/utils/test_match.py index 3f9626fad..bdb27392c 100644 --- a/tests/unit/testplan/common/utils/test_match.py +++ b/tests/unit/testplan/common/utils/test_match.py @@ -104,6 +104,8 @@ def test_match_found(self, basic_logfile): matcher = LogMatcher(log_path=basic_logfile) regex_exp = re.compile(r"second") match = matcher.match(regex=regex_exp) + assert len(matcher._debug_info_s) == 3 + assert len(matcher._debug_info_e) == 3 assert match is not None assert match.group(0) == "second" @@ -125,6 +127,8 @@ def test_match_only_searches_after_position(self, basic_logfile): matcher = LogMatcher(log_path=basic_logfile) second_string = re.compile(r"second") match = matcher.match(regex=second_string) + assert len(matcher._debug_info_s) == 3 + assert len(matcher._debug_info_e) == 3 # It should find this string. assert match is not None @@ -152,6 +156,8 @@ def test_match_not_found(self, basic_logfile): matcher = LogMatcher(log_path=basic_logfile) with pytest.raises(timing.TimeoutException): matcher.match(regex=r"bob", timeout=LOG_MATCHER_TIMEOUT) + assert len(matcher._debug_info_s) == 3 + assert len(matcher._debug_info_e) == 3 def test_binary_match_not_found(self, basic_logfile): """Does the LogMatcher raise an exception when no match is found.""" @@ -165,13 +171,19 @@ def test_not_match(self, basic_logfile): matcher.not_match( regex=re.compile(r"bob"), timeout=LOG_MATCHER_TIMEOUT ) + assert len(matcher._debug_info_s) == 3 + assert len(matcher._debug_info_e) == 3 matcher.seek() - with pytest.raises(Exception): + with pytest.raises(Exception, match=r"^Unexpected match.*"): matcher.not_match( regex=re.compile(r"third"), timeout=LOG_MATCHER_TIMEOUT ) - with pytest.raises(Exception): + assert len(matcher._debug_info_s) == 3 + assert len(matcher._debug_info_e) == 3 + with pytest.raises(Exception, match=r"^Unexpected match.*"): matcher.not_match(regex=re.compile(r"fourth"), timeout=0) + assert len(matcher._debug_info_s) == 3 + assert len(matcher._debug_info_e) == 3 def test_match_all(self, basic_logfile): """Can the LogMatcher find all the correct lines in the log file.""" @@ -179,6 +191,8 @@ def test_match_all(self, basic_logfile): matches = matcher.match_all( regex=re.compile(r".+ir.+"), timeout=LOG_MATCHER_TIMEOUT ) + assert len(matcher._debug_info_s) == 3 + assert len(matcher._debug_info_e) == 3 assert len(matches) == 2 assert matches[0].group(0) == "first" assert matches[1].group(0) == "third" @@ -186,6 +200,8 @@ def test_match_all(self, basic_logfile): matches = matcher.match_all( regex=re.compile(r".+th.*"), timeout=LOG_MATCHER_TIMEOUT ) + assert len(matcher._debug_info_s) == 3 + assert len(matcher._debug_info_e) == 3 assert len(matches) == 2 assert matches[0].group(0) == "fourth" assert matches[1].group(0) == "fifth" @@ -203,6 +219,13 @@ def test_match_all_not_found(self, basic_logfile): with pytest.raises(timing.TimeoutException): matcher.match_all(regex=r".+th.+", timeout=LOG_MATCHER_TIMEOUT) + def test_match_all_large(self, large_logfile): + matcher = LogMatcher(log_path=large_logfile) + matcher.match_all(r"blah", timeout=0.5) + assert len(matcher._debug_info_s) == 3 + assert len(matcher._debug_info_e) == 3 + assert matcher._debug_info_e[2] == "blah\n" + def test_match_between(self, basic_logfile): """ Does the LogMatcher match between the given marks. diff --git a/tests/unit/testplan/testing/multitest/test_result.py b/tests/unit/testplan/testing/multitest/test_result.py index f241ab385..04fe18112 100644 --- a/tests/unit/testplan/testing/multitest/test_result.py +++ b/tests/unit/testplan/testing/multitest/test_result.py @@ -889,6 +889,23 @@ def test_subset_of_tags_with_include_tags_true(self, fix_ns): class TestLogfileNamespace: """Unit testcases for the result.LogfileNamespace class.""" + def test_match(self, logfile_ns, logfile_w_matcher): + f, lm = logfile_w_matcher + f.logline("chai") + f.flush() + + logfile_ns.match(lm, r"chai", timeout=0) + assert len(logfile_ns.result.entries) == 1 + assert logfile_ns.result.entries[0] + e = logfile_ns.result.entries[0] + assert len(e.results) == 1 + assert e.results[0].pattern == "chai" == e.results[0].matched + assert e.results[0].start_pos == "" + if os.name == "posix": + assert e.results[0].end_pos == "".format( + len("chai\n") + ) + def test_seek_eof_match(self, logfile_ns, logfile_w_matcher): f, lm = logfile_w_matcher f.logline("coffee") @@ -907,16 +924,19 @@ def test_seek_eof_match(self, logfile_ns, logfile_w_matcher): for d in drinks: f.logline(d) f.flush() - logfile_ns.match( - lm, - r"vodka", - timeout=0.1, - ) + logfile_ns.match(lm, r"vodka", timeout=0.1) assert len(logfile_ns.result.entries) == 2 assert logfile_ns.result.entries[1] e = logfile_ns.result.entries[1] assert len(e.results) == 1 + assert all( + map( + lambda x: x.start_pos.startswith("