From bb08d1b46b24e09e5daa81a2ccd7555cbe4fe3c8 Mon Sep 17 00:00:00 2001 From: Martin Kourim Date: Mon, 3 Aug 2026 17:25:27 +0200 Subject: [PATCH] fix(logfiles): handle CRLF chunk splits and glob metacharacters A "\r\n" line ending split across read chunk boundaries produced a spurious empty line - the trailing "\r" ended a line and the "\n" from the next chunk became an empty line. The empty lines consumed look-back window slots, so a trigger message could be evicted early and a mapped error wrongly reported. Treat a trailing "\r" of a chunk as an incomplete line - the next chunk or the end-of-file handling completes it. Glob metacharacters in a log file name (e.g. "node[1].stdout") made the file invisible to its own rotation glob, so the file was silently not searched. Metacharacters in the state dir path similarly broke the expected messages check. Escape the literal parts of the patterns. --- cardano_node_tests/utils/logfiles.py | 48 +++++++++++------ framework_tests/test_logfiles.py | 78 ++++++++++++++++++++++++++++ 2 files changed, 110 insertions(+), 16 deletions(-) diff --git a/cardano_node_tests/utils/logfiles.py b/cardano_node_tests/utils/logfiles.py index 4723c5d5b..32d48a1f7 100644 --- a/cardano_node_tests/utils/logfiles.py +++ b/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) diff --git a/framework_tests/test_logfiles.py b/framework_tests/test_logfiles.py index 85a78a25e..5238a2b77 100644 --- a/framework_tests/test_logfiles.py +++ b/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 == []