fix(logfiles): share look-back context across log rotation

cardano_node_tests/utils/logfiles.py

@@ -146,6 +146,16 @@ def _retry_search[T](search_func: tp.Callable[[], T]) -> T:
     raise RuntimeError  # Unreachable, here for linters instead of return
 
 
+def _rotation_index(logfile: pl.Path) -> int:
+    """Return the rotation index of the log file (0 for the live log file).
+
+    A higher index means an older version of the log file (e.g. "node.stdout.2" was
+    rotated before "node.stdout.1").
+    """
+    suffix = logfile.suffix[1:]
+    return int(suffix) if suffix.isdigit() else 0
+
+
 def _get_rotated_logs(
     logfile: pl.Path, *, seek: int = 0, timestamp: float = 0.0, inode: int | None = None
 ) -> list[RotableLog]:
@@ -185,7 +195,12 @@ def _get_rotated_logs(
         for r in _logfile_records
         if r.timestamp > timestamp or r.logfile == logfile or r.inode == inode
     ]
-    logfile_records = sorted(_logfile_records, key=lambda r: r.timestamp)
+    # Sort by modification time. On filesystems with coarse timestamps the times can be
+    # equal, so use the rotation index (descending - a higher index is an older file) as
+    # a tiebreaker to keep the order deterministic.
+    logfile_records = sorted(
+        _logfile_records, key=lambda r: (r.timestamp, -_rotation_index(r.logfile))
+    )
 
     if not logfile_records:
         return []
@@ -490,12 +505,15 @@ def _compile_look_back_map_bytes(
 def _should_ignore_error(
     line_b: bytes, lookback: deque[bytes], pairs: list[tuple[re.Pattern[bytes], re.Pattern[bytes]]]
 ) -> bool:
-    """Return True if line matches an 'error' key and a preceding regex is in the look-back."""
-    for err_pat_b, prev_pat_b in pairs:
-        if err_pat_b.search(line_b):
-            # Found a mapped error; require a preceding match in the buffer
-            return any(prev_pat_b.search(prev_b) for prev_b in lookback)
-    return False
+    """Return True if line matches an 'error' key and a preceding regex is in the look-back.
+
+    All pairs are checked - a line can match the 'error' key of multiple pairs, and it is
+    enough when any of them has its preceding message in the look-back buffer.
+    """
+    return any(
+        err_pat_b.search(line_b) and any(prev_pat_b.search(prev_b) for prev_b in lookback)
+        for err_pat_b, prev_pat_b in pairs
+    )
 
 
 def _validated_start(seek: int | None, size: int) -> int:
@@ -563,6 +581,13 @@ def _check_line(line_b: bytes, look_back: deque[bytes], path: pl.Path) -> None:
             line = line_b.decode(encoding, errors="surrogateescape")
             results.append((path, line))
 
+    # The look-back buffer is shared by all versions of the log file. The versions are
+    # sorted from oldest to newest, so lines at the end of a rotated log file are the
+    # look-back context for lines at the beginning of the next version of the log file.
+    # The buffer holds only lines read by this search - lines before the seek offset or
+    # in versions that were already fully searched are not part of the context.
+    look_back: deque[bytes] = deque(maxlen=look_back_lines)
+
     for rec in rotated_logs:
         path = rec.logfile
         size = path.stat().st_size
@@ -572,7 +597,6 @@ def _check_line(line_b: bytes, look_back: deque[bytes], path: pl.Path) -> None:
             _validate_inode(rec)
             _resume_at_line_boundary(fb=fb, pos=start, size=size)
 
-            look_back: deque[bytes] = deque(maxlen=look_back_lines)
             leftover = b""
 
             while True:

framework_tests/test_logfiles.py

@@ -4,6 +4,7 @@
 import os
 import pathlib as pl
 import re
+from collections import deque
 
 import pytest
 
@@ -958,3 +959,80 @@ def test_search_cluster_logs_first_search_expiry(cluster_env: cluster_nodes.Clus
 
     errors = logfiles.search_cluster_logs()
     assert [e[1] for e in errors] == ["ignored error two"]
+
+
+def test_look_back_across_rotation(tmp_path: pl.Path):
+    """Check that the look-back context spans log file rotation.
+
+    The preceding message that makes a mapped error ignored can be at the end of
+    a rotated log file, while the error is at the beginning of the next version of
+    the log file.
+    """
+    rotated = _write_log(state_dir=tmp_path, name="node1.stdout.1", content="foo\ntrigger msg\n")
+    logfile = _write_log(state_dir=tmp_path, name="node1.stdout", content="error mapped one\n")
+    live_mtime = logfile.stat().st_mtime
+    os.utime(rotated, (live_mtime - 10, live_mtime - 10))
+
+    errors = _search_cluster_like_ignores(logfile=logfile)
+    assert errors == []
+
+
+def test_look_back_window_across_rotation(tmp_path: pl.Path):
+    """Check that the look-back window size applies also across log file rotation.
+
+    A preceding message that is further back than the look-back window doesn't make
+    the mapped error ignored, even when the window spans a rotated log file.
+    """
+    filler = "filler\n" * 10
+    rotated = _write_log(
+        state_dir=tmp_path, name="node1.stdout.1", content=f"trigger msg\n{filler}"
+    )
+    logfile = _write_log(state_dir=tmp_path, name="node1.stdout", content="error mapped one\n")
+    live_mtime = logfile.stat().st_mtime
+    os.utime(rotated, (live_mtime - 10, live_mtime - 10))
+
+    errors = _search_cluster_like_ignores(logfile=logfile)
+    assert [e[1] for e in errors] == ["error mapped one"]
+
+
+@pytest.mark.parametrize(
+    ("lookback_lines", "expected"),
+    (
+        pytest.param(["trigger two"], True, id="second_pair_trigger"),
+        pytest.param(["trigger one"], True, id="first_pair_trigger"),
+        pytest.param(["other line"], False, id="no_trigger"),
+    ),
+)
+def test_should_ignore_error_multiple_pairs(lookback_lines: list[str], expected: bool):
+    """Check that all look-back pairs are consulted for a line.
+
+    A line can match the 'error' key of multiple pairs. It is ignored when any of the
+    matching pairs has its preceding message in the look-back buffer, not just the
+    first one.
+    """
+    pairs = logfiles._compile_look_back_map_bytes(
+        m={"error one": "trigger one", "error": "trigger two"}
+    )
+    lookback = deque(line.encode("utf-8") for line in lookback_lines)
+
+    assert (
+        logfiles._should_ignore_error(line_b=b"error one happened", lookback=lookback, pairs=pairs)
+        is expected
+    )
+
+
+def test_rotated_logs_mtime_tiebreak(tmp_path: pl.Path):
+    """Check that log file versions with equal modification times are ordered correctly.
+
+    On filesystems with coarse timestamps, the modification times of rotated log files
+    can be equal. The rotation index breaks the tie - a higher index is an older file.
+    """
+    older = _write_log(state_dir=tmp_path, name="node1.stdout.2", content="two\n")
+    newer = _write_log(state_dir=tmp_path, name="node1.stdout.1", content="one\n")
+    logfile = _write_log(state_dir=tmp_path, name="node1.stdout", content="live\n")
+    mtime = logfile.stat().st_mtime
+    for f in (older, newer, logfile):
+        os.utime(f, (mtime, mtime))
+
+    records = logfiles._get_rotated_logs(logfile=logfile, seek=0, timestamp=0.0, inode=None)
+    assert [r.logfile for r in records] == [older, newer, logfile]