fix(logfiles): handle CRLF chunk splits and glob metacharacters

cardano_node_tests/utils/logfiles.py

@@ -2,6 +2,7 @@
 import dataclasses
 import fnmatch
 import functools
+import glob
 import io
 import itertools
 import logging
@@ -194,8 +195,9 @@ def _get_rotated_logs(
     after the search start can get a modification time that is not newer than the recorded
     search start time.
     """
-    # Get logfile including rotated versions
-    logfiles = list(logfile.parent.glob(f"{logfile.name}*"))
+    # Get logfile including rotated versions. Escape the file name, so that glob
+    # metacharacters in it (e.g. "[") are matched literally.
+    logfiles = list(logfile.parent.glob(f"{glob.escape(logfile.name)}*"))
 
     # Get list of logfiles modified after `timestamp`, sorted by their last modification time
     # from oldest to newest. The live log file and the file matching `inode` are always
@@ -453,13 +455,20 @@ def _resume_at_line_boundary(fb: tp.BinaryIO, pos: int, size: int) -> None:
 
 
 def _split_complete_lines(buf: bytes) -> tuple[list[bytes], bytes]:
-    """Return (complete_lines_without_newline, leftover_tail). Handles LF/CRLF/CR."""
+    """Return (complete_lines_without_newline, leftover_tail).
+
+    Handles LF/CRLF/CR line endings. A trailing CR is deferred as an incomplete tail,
+    as it can be the first half of a CRLF pair split across chunk boundaries.
+    """
     parts = buf.splitlines(keepends=True)
     if not parts:
         return [], b""
-    # Determine if the last piece ends with a newline
+    # Determine if the last piece ends with a newline. A trailing "\r" can be the first
+    # half of a "\r\n" pair split across chunk boundaries, so treat the line as
+    # incomplete - the next chunk (or the end-of-file handling) completes it. Otherwise
+    # the second half of the pair would become a spurious empty line.
     last = parts[-1]
-    complete = parts if last.endswith((b"\n", b"\r")) else parts[:-1]
+    complete = parts if last.endswith(b"\n") else parts[:-1]
     leftover = b"" if complete is parts else last
 
     # Strip line endings
@@ -560,8 +569,9 @@ def _search_log_lines(  # noqa: C901
     - An unterminated final line of the live logfile is not searched. It is searched by
       a later search, once the line is complete or the file is rotated. When the line is
       never completed (e.g. the writer died mid-line and the file is never rotated), the
-      line is never searched. An unterminated final line of a rotated log file will never
-      be completed, so it is searched right away.
+      line is never searched. A final line terminated by a bare CR also counts as
+      unterminated. An unterminated final line of a rotated log file will never be
+      completed, so it is searched right away.
     """
     errs_b = _compile_bytes_from_pattern(pat=errors_re, encoding=encoding)
     if not errs_b:
@@ -637,9 +647,11 @@ def _check_line(line_b: bytes, look_back: deque[bytes], path: pl.Path) -> None:
                     _check_line(line_b=line_b, look_back=look_back, path=path)
 
             # An unterminated final line of a rotated log file will never be completed.
-            # Search it now, otherwise it would never be searched.
+            # Search it now, otherwise it would never be searched. A trailing CR is
+            # a line terminator here - at the end of a rotated file it can no longer be
+            # the first half of a CRLF pair.
             if leftover and path != logfile:
-                _check_line(line_b=leftover, look_back=look_back, path=path)
+                _check_line(line_b=leftover.rstrip(b"\r"), look_back=look_back, path=path)
 
             # Persist next offset for the "live" logfile at a line boundary
             if path == logfile:
@@ -796,11 +808,14 @@ def _search() -> list[str]:
                                 return lines_found
 
                 # An unterminated final line of a rotated log file is its final content,
-                # so search it as well. An unterminated final line of the live log file
-                # is skipped - it is searched once complete, and a truncated line must
-                # not be returned to callers that parse the line content.
-                if leftover and path != logfile and regex_b.search(leftover):
-                    lines_found.append(leftover.decode(encoding, errors="surrogateescape"))
+                # so search it as well (a trailing CR is a line terminator here). An
+                # unterminated final line of the live log file is skipped - it is
+                # searched once complete, and a truncated line must not be returned to
+                # callers that parse the line content.
+                if leftover and path != logfile and regex_b.search(leftover.rstrip(b"\r")):
+                    lines_found.append(
+                        leftover.rstrip(b"\r").decode(encoding, errors="surrogateescape")
+                    )
                     if only_first:
                         return lines_found
         return lines_found
@@ -927,8 +942,9 @@ def _search(
         regex_b = _compile_bytes_from_str(pat=regex)
 
         # Get list of candidate files by globbing keys of seek_offsets. Skip rotated file
-        # names here; `_get_rotated_logs` will include them appropriately.
-        pattern = f"{state_dir}/{files_glob}"
+        # names here; `_get_rotated_logs` will include them appropriately. Escape the
+        # state dir part, so that glob metacharacters in the path are matched literally.
+        pattern = f"{glob.escape(str(state_dir))}/{files_glob}"
         matching_files = [
             f
             for f in fnmatch.filter(seek_offsets, pattern)

framework_tests/test_logfiles.py

@@ -1086,3 +1086,81 @@ def test_get_ignored_error_regexes(
     for extra in extra_regexes:
         assert extra in regexes
     assert len(regexes) == len(logfiles.ERRORS_IGNORED) + len(extra_regexes)
+
+
+@pytest.mark.parametrize(
+    ("buf", "lines", "leftover"),
+    (
+        pytest.param(b"a\nb\n", [b"a", b"b"], b"", id="lf"),
+        pytest.param(b"a\r\nb\r\n", [b"a", b"b"], b"", id="crlf"),
+        pytest.param(b"a\rb\n", [b"a", b"b"], b"", id="cr_mid_buffer"),
+        pytest.param(b"a\r\nb", [b"a"], b"b", id="incomplete_tail"),
+        pytest.param(b"a\r", [], b"a\r", id="cr_at_chunk_boundary"),
+        pytest.param(b"abc", [], b"abc", id="no_line_end"),
+        pytest.param(b"", [], b"", id="empty"),
+    ),
+)
+def test_split_complete_lines(buf: bytes, lines: list[bytes], leftover: bytes):
+    r"""Check the splitting of a buffer into complete lines and an incomplete tail.
+
+    A trailing "\r" can be the first half of a "\r\n" pair split across chunk
+    boundaries, so the line is treated as incomplete. A "\r" in the middle of the
+    buffer is a line ending.
+    """
+    assert logfiles._split_complete_lines(buf=buf) == (lines, leftover)
+
+
+def test_search_log_lines_crlf_chunk_boundary(tmp_path: pl.Path, monkeypatch: pytest.MonkeyPatch):
+    r"""Check the search of a log file with CRLF line endings split across chunks.
+
+    With a two byte read buffer, the "\r\n" pairs get split across chunk boundaries.
+    The lines must be reassembled without spurious empty lines - with a look-back window
+    of two lines, spurious empty lines would evict the trigger message from the window
+    and the mapped error would be wrongly reported.
+    """
+    monkeypatch.setattr(logfiles, "BUFFER_SIZE", 2)
+    logfile = _write_log(
+        state_dir=tmp_path,
+        name="node1.stdout",
+        content="trigger msg\r\nfiller\r\nerror mapped one\r\n",
+    )
+
+    errors = logfiles._search_log_lines(
+        logfile=logfile,
+        rotated_logs=logfiles._get_rotated_logs(logfile=logfile, seek=0, timestamp=0.0, inode=None),
+        errors_re=re.compile("error"),
+        look_back_map={"error mapped": "trigger msg"},
+        look_back_lines=2,
+    )
+    assert errors == []
+
+
+def test_rotated_logs_glob_metacharacters(tmp_path: pl.Path):
+    """Check that glob metacharacters in a log file name are matched literally.
+
+    A log file named e.g. "node[1].stdout" must match itself (and its rotated
+    versions), not a file named "node1.stdout".
+    """
+    logfile = _write_log(state_dir=tmp_path, name="node[1].stdout", content="content\n")
+    rotated = _write_log(state_dir=tmp_path, name="node[1].stdout.1", content="old\n")
+    _write_log(state_dir=tmp_path, name="node1.stdout", content="other\n")
+    live_mtime = logfile.stat().st_mtime
+    os.utime(rotated, (live_mtime - 10, live_mtime - 10))
+
+    records = logfiles._get_rotated_logs(logfile=logfile, seek=0, timestamp=0.0, inode=None)
+    assert [r.logfile for r in records] == [rotated, logfile]
+
+
+def test_check_msgs_metacharacters_in_state_dir(tmp_path: pl.Path):
+    """Check that glob metacharacters in the state dir path are matched literally."""
+    state_dir = tmp_path / "state[1]"
+    state_dir.mkdir()
+    logfile = _write_log(state_dir=state_dir, name="node1.stdout", content="expected msg\n")
+
+    errors = logfiles.check_msgs_presence_in_logs(
+        regex_pairs=[("*.stdout", "expected msg")],
+        seek_offsets={str(logfile): (0, logfile.stat().st_ino)},
+        state_dir=state_dir,
+        timestamp=0.0,
+    )
+    assert errors == []