fix(backtest): bound every log tail to the final 256 KB

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 `<date>.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:])
 

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, "")