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 == []