Feature/more debug logging to LogMatcher (#1110)

* add debug logging, some refactor

* bugfix

* add newsfrag

Author: zhenyu-ms

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.

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(

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 "<EOF>\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 "<BOF>",
+                        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
 

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 = "<BOF>"
         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):

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:

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 <EOF>." : ` in ${timeout} seconds.`);
   const entries = [...results, ...failure].map((entry, index) => {
     const { matched, pattern, start_pos: startPos, end_pos: endPos } = entry;
     return (