From 6d8a679e2cb79807972027f4039642806a7615c6 Mon Sep 17 00:00:00 2001 From: Marinski Date: Sat, 29 Aug 2026 14:24:43 +0300 Subject: [PATCH] fix(backtest): bound every log tail to the final 256 KB MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The live /tail endpoint read entire log files into memory on every poll: _tail_dir_log and get_tail's run.log block called a whole-file reader, then decoded and split the result. A Strategy Tester log grows to gigabytes WHILE the run that is being polled writes it, so each poll allocated the file plus a decoded copy plus a line list — 45-65 s per call measured against a 1.9 GB log, with the GIL held through the decode. Every thread in the process stalled behind it: /ping took 25-50 s, the container healthcheck flapped, clients timed out, and a healthy terminal was indistinguishable from a wedged one. (_tail_terminal_log, the failure-path tail, had the same unbounded read.) _read_tail_text seeks to the final 256 KB, aligned to a 2-byte boundary so UTF-16 code units stay intact, sniffs UTF-16 from a BOM or a NUL second byte, and drops the truncated first line of a mid-file window. Both tail helpers and the run.log block now use it; whole-file reads remain only where the whole file is genuinely needed (INI parse, report parse). _tail_dir_log also inherits the two picker rules _tail_terminal_log already had and it predated: newest by mtime, never metaeditor.log — the alphabetical pick returned a stale compile log ('m' > '2') instead of the run being polled. --- mt5api/backtest/handler.py | 92 ++++++++++++++++++++++---- tests/test_backtest_log_tail.py | 111 ++++++++++++++++++++++++++++++++ 2 files changed, 190 insertions(+), 13 deletions(-) diff --git a/mt5api/backtest/handler.py b/mt5api/backtest/handler.py index 895ed5b..8f3eef1 100644 --- a/mt5api/backtest/handler.py +++ b/mt5api/backtest/handler.py @@ -254,6 +254,52 @@ def _tail(text, limit=DIAGNOSTIC_TAIL_CHARS): return text if len(text) <= limit else text[-limit:] +#: How much of a log file a tail is allowed to touch. A terminal writing a +#: multi-year backtest grows its Tester log to gigabytes WHILE the run is +#: polled, so tailing must stay O(tail), never O(file) — a whole-file read of +#: one of those seizes the process for a minute per call (whole-file bytes + +#: a decoded str copy + a splitlines() list, all while holding the GIL), which +#: starves every other request including /ping and the container healthcheck. +TAIL_MAX_BYTES = 256 * 1024 + + +def _read_tail_text(path, max_bytes=TAIL_MAX_BYTES): + """Decode at most the final ``max_bytes`` of ``path``. + + Encoding is sniffed from the file's first two bytes: a BOM means + UTF-16-LE (how MT5 writes its logs), and so does a NUL second byte — + UTF-16-LE of any ASCII-leading text, which covers BOM-less UTF-16 logs. + Anything else decodes as UTF-8 (run.log). The read then seeks to the + final window, aligned to a 2-byte boundary so UTF-16 code units stay + intact. When the window starts mid-file, everything up to the first + newline is dropped — a truncated first line reads as garbage, and a tail + endpoint never needs it. + """ + try: + with open(path, "rb") as handle: + head = handle.read(2) + utf16 = head == b"\xff\xfe" or (len(head) == 2 and head[1] == 0) + size = handle.seek(0, os.SEEK_END) + offset = max(0, size - max_bytes) + if utf16 and offset % 2: + offset -= 1 + handle.seek(offset) + raw = handle.read() + except OSError: + return "" + + if utf16: + text = raw.decode("utf-16-le", errors="replace") + else: + text = raw.decode("utf-8", errors="replace") + + if offset > 0: + first_break = text.find("\n") + if first_break != -1: + text = text[first_break + 1:] + return text + + def _tail_terminal_log(lines=20): """Tail of the terminal's most recently written run log. @@ -286,12 +332,7 @@ def _tail_terminal_log(lines=20): except OSError: return "" - latest_path = newest.path - try: - with open(latest_path, "r", encoding="utf-16-le", errors="replace") as handle: - content = handle.read() - except OSError: - return "" + content = _read_tail_text(newest.path) tail_lines = [line.strip() for line in content.splitlines() if line.strip()] if not tail_lines: @@ -832,19 +873,42 @@ def get_log(job_id): def _tail_dir_log(log_dir, lines): - """Return (path_used, last N non-empty lines) from the newest .log in log_dir.""" + """Return (path_used, last N non-empty lines) from the newest .log in log_dir. + + Newest by MODIFICATION TIME, excluding `metaeditor.log` — the same two + rules `_tail_terminal_log` already applies, and for the same reason: the + logs are `.log` files plus a `metaeditor.log` that sorts after all + of them ("m" > "2") and never changes, so an alphabetical pick returned a + stale compile log instead of the run being polled. + + Bounded read (`_read_tail_text`): this runs on the live /tail endpoint, + which the backend polls once a minute for every running job, against a + Tester log that reaches gigabytes mid-run. The prior whole-file read took + 45-65 s per call on such a log, starving every thread in the process — + /ping and the container healthcheck included — which made a healthy + terminal look wedged from the outside. + """ if not os.path.isdir(log_dir): return None, "" try: - candidates = sorted(f for f in os.listdir(log_dir) if f.lower().endswith(".log")) + candidates = [ + entry + for entry in os.scandir(log_dir) + if entry.is_file() + and entry.name.lower().endswith(".log") + and entry.name.lower() != "metaeditor.log" + ] except OSError: return None, "" if not candidates: return None, "" - path = os.path.join(log_dir, candidates[-1]) - content = _read_text_best_effort(path) + try: + newest = max(candidates, key=lambda entry: entry.stat().st_mtime) + except OSError: + return None, "" + content = _read_tail_text(newest.path) tail_lines = [ln.strip() for ln in content.splitlines() if ln.strip()] - return path, "\n".join(tail_lines[-lines:]) + return newest.path, "\n".join(tail_lines[-lines:]) def get_tail(job_id): @@ -865,11 +929,13 @@ def get_tail(job_id): if job is None: return jsonify({"error": f"Backtest job not found: {job_id}"}), 404 - # run.log — stdout/stderr of terminal64.exe (sparse but useful on errors) + # run.log — stdout/stderr of terminal64.exe. Usually sparse, but "usually" + # is not a bound: a chatty terminal can grow it without limit, and this + # endpoint is polled — same O(tail) rule as _tail_dir_log. run_log = "" log_path = job.get("logPath") if log_path: - content = _read_text_best_effort(log_path) + content = _read_tail_text(log_path) run_tail = [ln.strip() for ln in content.splitlines() if ln.strip()] run_log = "\n".join(run_tail[-50:]) diff --git a/tests/test_backtest_log_tail.py b/tests/test_backtest_log_tail.py index d6f3957..d1d9473 100644 --- a/tests/test_backtest_log_tail.py +++ b/tests/test_backtest_log_tail.py @@ -81,3 +81,114 @@ def test_tail_is_limited_to_the_requested_line_count(terminal_logs): _write_utf16(terminal_logs / "20260808.log", "".join(f"line {i}\n" for i in range(50))) tail = handler._tail_terminal_log(lines=5) assert tail.splitlines() == [f"line {i}" for i in range(45, 50)] + + +# ── Bounded reads (_read_tail_text) ───────────────────────────────────── +# +# Tailing must stay O(tail), never O(file): the live /tail endpoint is polled +# once a minute per running job against a Tester log that reaches gigabytes +# mid-run. A whole-file read of one of those took 45-65 s per call — decode +# and splitlines hold the GIL, so every thread in the process stalled, +# /ping and the container healthcheck included, and a healthy terminal +# looked wedged from the outside. + + +def test_read_tail_text_reads_only_the_final_window(tmp_path): + path = tmp_path / "big.log" + body = "".join(f"line {i:07d}\n" for i in range(200_000)) # ~2.6 MB utf-8 + path.write_text(body, encoding="utf-8") + + text = handler._read_tail_text(str(path), max_bytes=64 * 1024) + + lines = text.splitlines() + assert lines[-1] == "line 0199999" + assert len(text.encode("utf-8")) <= 64 * 1024 + # The window starts mid-file: the truncated first line must be dropped, + # so every surviving line is complete. + assert all(ln.startswith("line ") and len(ln) == 12 for ln in lines) + + +def test_read_tail_text_keeps_utf16_code_units_aligned(tmp_path): + path = tmp_path / "terminal.log" + body = "".join(f"запись {i:06d}\n" for i in range(50_000)) # force odd offsets + with open(path, "w", encoding="utf-16-le") as fh: + fh.write("") + fh.write(body) + + text = handler._read_tail_text(str(path), max_bytes=32 * 1024 + 1) + + lines = text.splitlines() + assert lines[-1] == "запись 049999" + # A misaligned seek shifts every code unit by one byte and turns the + # whole tail to mojibake — one intact line proves alignment held. + assert all(ln.startswith("запись ") for ln in lines) + + +def test_read_tail_text_small_file_is_returned_whole(tmp_path): + path = tmp_path / "run.log" + path.write_text("first\nsecond\n", encoding="utf-8") + assert handler._read_tail_text(str(path)) == "first\nsecond\n" + + +def test_read_tail_text_missing_file_is_empty(tmp_path): + assert handler._read_tail_text(str(tmp_path / "absent.log")) == "" + + +def test_tail_terminal_log_is_bounded(terminal_logs): + huge = "".join(f"entry {i:08d}\n" for i in range(300_000)) # ~9.7 MB utf-16 + _write_utf16(terminal_logs / "20260829.log", huge) + + tail = handler._tail_terminal_log(lines=5) + + assert tail.splitlines() == [f"entry {i:08d}" for i in range(299_995, 300_000)] + + +# ── _tail_dir_log (the live /tail endpoint's picker) ──────────────────── +# +# Same two rules as _tail_terminal_log — newest by mtime, never +# metaeditor.log — which this helper predated and never received. + + +def test_tail_dir_log_never_picks_metaeditor_log(tmp_path): + log_dir = tmp_path / "logs" + log_dir.mkdir() + _write_utf16(log_dir / "20260808.log", "Tester\tautomatic testing started\n") + _write_utf16(log_dir / "metaeditor.log", "compiling ancient stuff\n") + _age(log_dir / "20260808.log", 3600) + _age(log_dir / "metaeditor.log", 1) + + path, tail = handler._tail_dir_log(str(log_dir), 20) + + assert path.endswith("20260808.log") + assert "ancient" not in tail + + +def test_tail_dir_log_picks_newest_by_mtime_not_name(tmp_path): + log_dir = tmp_path / "logs" + log_dir.mkdir() + _write_utf16(log_dir / "20261231.log", "last year\n") + _write_utf16(log_dir / "20270101.log", "this year\n") + _age(log_dir / "20261231.log", 5) # older name, newer mtime + _age(log_dir / "20270101.log", 86400) + + path, tail = handler._tail_dir_log(str(log_dir), 20) + + assert path.endswith("20261231.log") + assert tail == "last year" + + +def test_tail_dir_log_is_bounded_on_a_large_log(tmp_path): + log_dir = tmp_path / "logs" + log_dir.mkdir() + huge = "".join(f"tick {i:08d}\n" for i in range(300_000)) + _write_utf16(log_dir / "20260829.log", huge) + + _, tail = handler._tail_dir_log(str(log_dir), 3) + + assert tail.splitlines() == [f"tick {i:08d}" for i in range(299_997, 300_000)] + + +def test_tail_dir_log_empty_dir(tmp_path): + log_dir = tmp_path / "logs" + log_dir.mkdir() + assert handler._tail_dir_log(str(log_dir), 20) == (None, "")