From 54ec17622350c16bab5ca41bd351c6e037c3089e Mon Sep 17 00:00:00 2001 From: Martin Kourim Date: Mon, 3 Aug 2026 12:50:33 +0200 Subject: [PATCH] fix(logfiles): share look-back context across log rotation The look-back buffer for ignoring mapped errors was reset for every version of a log file. A preceding message at the end of a rotated log file (e.g. "Switched to a fork") could not make a mapped error at the beginning of the next version of the log file ignored, and the error was reported as a false failure. Share the look-back buffer across all versions of the log file. The versions are searched from oldest to newest, so the buffer follows the chronological order of the log lines. Break ties in the modification time sorting with the rotation index, so the order is deterministic on filesystems with coarse timestamps. Also check all look-back map pairs for a line - a line can match the 'error' key of multiple pairs and it is enough when any of the matching pairs has its preceding message in the look-back buffer. --- cardano_node_tests/utils/logfiles.py | 40 +++++++++++--- framework_tests/test_logfiles.py | 78 ++++++++++++++++++++++++++++ 2 files changed, 110 insertions(+), 8 deletions(-) diff --git a/cardano_node_tests/utils/logfiles.py b/cardano_node_tests/utils/logfiles.py index dad4224de..96f994a63 100644 --- a/cardano_node_tests/utils/logfiles.py +++ b/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: diff --git a/framework_tests/test_logfiles.py b/framework_tests/test_logfiles.py index 8f5993dd2..62bea5270 100644 --- a/framework_tests/test_logfiles.py +++ b/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]