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]