kis_trader/scripts/kis_error_watch_mm.py

#!/usr/bin/env python3
# -*- coding: utf-8 -*-
"""
kis_error_watch_mm.py — kis_trader_main journalctl 실시간(tail -f) 감시 → Mattermost

실매 봇과 분리된 프로세스. journald 만 보고 오류 시 MM 알림.
  - Traceback / FATAL / dead=[...] / 유닛 다운 등
  - 동일·유사 알림은 쿨다운으로 스팸 방지
  - 상태 JSON 즉시 저장(재시작 후에도 쿨다운 유지)

실행:
  nohup .venv/bin/python -u scripts/kis_error_watch_mm.py \\
    >> logs/kis_error_watch_mm.log 2>&1 &
  tail -f logs/kis_error_watch_mm.log

테스트:
  .venv/bin/python scripts/kis_error_watch_mm.py --test-mm

systemd (선택):
  sudo cp deploy/kis_error_watch_mm.service /etc/systemd/system/
  sudo systemctl daemon-reload && sudo systemctl enable --now kis_error_watch_mm
"""
from __future__ import annotations

import argparse
import hashlib
import logging
import os
import re
import signal
import subprocess
import sys
import time
from datetime import datetime
from pathlib import Path
from typing import List, Optional, Pattern, Tuple

ROOT = Path(__file__).resolve().parents[1]
sys.path.insert(0, str(ROOT))

from kis_trader.utils.env import (  # noqa: E402
    get_env_bool,
    get_env_float,
    get_env_from_db,
    get_env_int,
)
from kis_trader.utils.logger import atomic_load_json, atomic_save_json, msg_mm  # noqa: E402

LOG_PATH = ROOT / "logs" / "kis_error_watch_mm.log"
STATE_PATH = ROOT / "logs" / "kis_error_watch_mm_state.json"
LOG_PATH.parent.mkdir(parents=True, exist_ok=True)

logging.basicConfig(
    level=logging.INFO,
    format="[%(asctime)s] %(message)s",
    datefmt="%H:%M:%S",
    handlers=[logging.StreamHandler(sys.stdout)],
)
log = logging.getLogger("error_watch")

_STOP = False


def _on_signal(signum, _frame) -> None:
    global _STOP
    _STOP = True
    log.info("⏹ signal=%s → 종료 예약", signum)


def _cfg() -> dict:
    """DB/env 설정 — 하드코딩 수치 금지, get_env_* 만."""
    # Traceback·FATAL·비어있지 않은 dead=·유닛 크래시 시그니처
    default_match = (
        r"(?i)("
        r"Traceback \(most recent call last\)|"
        r"\bCRITICAL\b|\bFATAL\b|MemoryError|SIGBUS|Segmentation fault|"
        r"dead=\[[^\]]|"  # dead=[] 제외, dead=['Strat-... 매칭
        r"Main process exited|Failed with result|"
        r"can't open file|"
        r"강제\s*종료|Out of memory"
        r")"
    )
    default_ignore = (
        r"(?i)("
        r"numexpr\.utils|"
        r"\[MM 스킵\]|"
        r"MM 발송 실패|"
        r"heartbeat ws="
        r")"
    )
    return {
        "enabled": get_env_bool("ERROR_WATCH_ENABLED", True),
        "unit": str(
            get_env_from_db("ERROR_WATCH_UNIT", "kis_trader_main.service")
            or "kis_trader_main.service"
        ).strip(),
        "channel": str(
            get_env_from_db("ERROR_WATCH_MM_CHANNEL", "")
            or get_env_from_db("KIS_SYSTEM_MM_CHANNEL", "default")
            or "default"
        ).strip()
        or "default",
        "cooldown_sec": max(30, get_env_int("ERROR_WATCH_COOLDOWN_SEC", 180)),
        "context_lines": max(1, min(20, get_env_int("ERROR_WATCH_CONTEXT_LINES", 5))),
        "traceback_extra": max(0, min(40, get_env_int("ERROR_WATCH_TRACEBACK_EXTRA_LINES", 12))),
        "health_sec": max(15, get_env_int("ERROR_WATCH_HEALTH_CHECK_SEC", 60)),
        "match_re": str(
            get_env_from_db("ERROR_WATCH_MATCH_REGEX", default_match) or default_match
        ),
        "ignore_re": str(
            get_env_from_db("ERROR_WATCH_IGNORE_REGEX", default_ignore) or default_ignore
        ),
        "jitter": get_env_bool("ERROR_WATCH_MM_JITTER", False),
    }


def _compile_re(pat: str, name: str) -> Optional[Pattern[str]]:
    try:
        return re.compile(pat)
    except re.error as e:
        log.error("❌ regex 컴파일 실패 (%s): %s", name, e)
        return None


def _load_state() -> dict:
    st = atomic_load_json(STATE_PATH, default={})
    if not isinstance(st, dict):
        return {}
    return st


def _save_state(st: dict) -> None:
    atomic_save_json(STATE_PATH, st)


def _fp(text: str) -> str:
    # 시각·PID 제거 후 지문 → 같은 오류 반복 쿨다운
    norm = re.sub(r"\d{2}:\d{2}:\d{2}", "", text)
    norm = re.sub(r"python\[\d+\]", "python[PID]", norm)
    norm = re.sub(r"\s+", " ", norm).strip()[:800]
    return hashlib.sha1(norm.encode("utf-8", errors="ignore")).hexdigest()[:16]


def _can_alert(st: dict, fingerprint: str, cooldown_sec: int) -> bool:
    now = time.time()
    last_ts = float(st.get("last_alert_ts") or 0)
    last_fp = str(st.get("last_fingerprint") or "")
    if fingerprint == last_fp and (now - last_ts) < cooldown_sec:
        return False
    if (now - last_ts) < float(get_env_float("ERROR_WATCH_GLOBAL_MIN_GAP_SEC", 20.0)):
        # 서로 다른 오류라도 최소 간격
        if fingerprint != last_fp and (now - last_ts) < cooldown_sec * 0.15:
            return False
    return True


def _send_alert(title: str, lines: List[str], channel: str, jitter: bool, st: dict, fingerprint: str) -> bool:
    body_lines = [
        f"🚨 **[오류감시] {title}**",
        f"- 시각: {datetime.now().strftime('%Y-%m-%d %H:%M:%S')}",
        f"- 유닛: `{get_env_from_db('ERROR_WATCH_UNIT', 'kis_trader_main.service')}`",
        "```",
    ]
    clipped = "\n".join(lines)[:3500]
    body_lines.append(clipped)
    body_lines.append("```")
    body = "\n".join(body_lines)
    ok = msg_mm(body, channel_alias=channel, jitter=jitter)
    st["last_alert_ts"] = time.time()
    st["last_fingerprint"] = fingerprint
    st["last_title"] = title
    st["alert_count"] = int(st.get("alert_count") or 0) + 1
    _save_state(st)
    log.info("📤 MM %s title=%s fp=%s", "OK" if ok else "FAIL", title, fingerprint)
    return ok


def _unit_active(unit: str) -> Tuple[bool, str]:
    try:
        r = subprocess.run(
            ["systemctl", "is-active", unit],
            capture_output=True,
            text=True,
            timeout=5,
        )
        state = (r.stdout or "").strip() or (r.stderr or "").strip() or "unknown"
        return state == "active", state
    except Exception as e:
        return False, f"check_error:{e}"


def _follow_journal(unit: str) -> subprocess.Popen:
    # -n 0: 과거 덤프 없이 follow만 (기동 직후 과거 Traceback 폭주 방지)
    cmd = [
        "journalctl",
        "-u", unit,
        "-f",
        "-n", "0",
        "--output=short-iso",
        "--no-pager",
    ]
    log.info("📡 follow: %s", " ".join(cmd))
    return subprocess.Popen(
        cmd,
        stdout=subprocess.PIPE,
        stderr=subprocess.STDOUT,
        text=True,
        bufsize=1,
        errors="replace",
    )


def run_watch() -> int:
    cfg = _cfg()
    if not cfg["enabled"]:
        log.warning("ERROR_WATCH_ENABLED=false → 종료")
        return 0

    match_re = _compile_re(cfg["match_re"], "MATCH")
    ignore_re = _compile_re(cfg["ignore_re"], "IGNORE")
    if match_re is None:
        return 2

    unit = cfg["unit"]
    channel = cfg["channel"]
    st = _load_state()
    log.info(
        "✅ 감시 시작 unit=%s ch=%s cooldown=%ss health=%ss",
        unit, channel, cfg["cooldown_sec"], cfg["health_sec"],
    )

    # 기동 알림 (감시자 살아있음 확인)
    if get_env_bool("ERROR_WATCH_STARTUP_NOTIFY", True):
        active, state = _unit_active(unit)
        msg_mm(
            f"👁️ **[오류감시 기동]** `{unit}` → `{state}`"
            f"{' ✅' if active else ' ⚠️ 비활성'}",
            channel_alias=channel,
            jitter=False,
        )

    proc = _follow_journal(unit)
    buf: List[str] = []
    collecting_tb = False
    tb_left = 0
    last_health = time.time()
    was_active = True

    assert proc.stdout is not None

    while not _STOP:
        # health poll
        now = time.time()
        if now - last_health >= cfg["health_sec"]:
            last_health = now
            active, state = _unit_active(unit)
            if not active:
                fp = _fp(f"unit_down:{unit}:{state}")
                if _can_alert(st, fp, cfg["cooldown_sec"]):
                    _send_alert(
                        f"유닛 비활성 ({state})",
                        [f"systemctl is-active {unit} → {state}"],
                        channel,
                        cfg["jitter"],
                        st,
                        fp,
                    )
                was_active = False
            elif not was_active:
                # 복구 알림
                fp = _fp(f"unit_up:{unit}")
                if _can_alert(st, fp, max(30, cfg["cooldown_sec"] // 3)):
                    _send_alert(
                        "유닛 복구 (active)",
                        [f"systemctl is-active {unit} → active"],
                        channel,
                        cfg["jitter"],
                        st,
                        fp,
                    )
                was_active = True

            # journalctl 죽었으면 재기동
            if proc.poll() is not None:
                log.warning("⚠️ journalctl 종료 code=%s → 재기동", proc.returncode)
                proc = _follow_journal(unit)
                assert proc.stdout is not None

        # non-blocking-ish read with timeout via select
        import select

        ready, _, _ = select.select([proc.stdout], [], [], 1.0)
        if not ready:
            continue
        line = proc.stdout.readline()
        if line == "":
            # EOF — 재기동
            time.sleep(1.0)
            if proc.poll() is not None:
                proc = _follow_journal(unit)
                assert proc.stdout is not None
            continue

        line = line.rstrip("\n")
        if not line:
            continue

        # ignore
        if ignore_re is not None and ignore_re.search(line):
            continue

        # Traceback 블록 수집
        if "Traceback (most recent call last)" in line:
            collecting_tb = True
            tb_left = cfg["traceback_extra"]
            buf = [line]
            continue

        if collecting_tb:
            buf.append(line)
            tb_left -= 1
            # 들여쓴 프레임이 끝나고 일반 로그가 오면 종료
            if tb_left <= 0 or (
                len(buf) > 2
                and not line.startswith(" ")
                and not line.startswith("\t")
                and "File \"" not in line
                and not line.lstrip().startswith("File ")
                and "Error" not in line
                and "Exception" not in line
            ):
                collecting_tb = False
                block = buf[:]
                buf = []
                fp = _fp("\n".join(block))
                if _can_alert(st, fp, cfg["cooldown_sec"]):
                    _send_alert("Traceback", block, channel, cfg["jitter"], st, fp)
            continue

        if match_re.search(line):
            # 직전 컨텍스트는 journal에 없으므로 히트 라인 + 이후 N줄은 어려움 → 히트만
            ctx = [line]
            fp = _fp(line)
            if _can_alert(st, fp, cfg["cooldown_sec"]):
                title = "로그 오류 매칭"
                if "dead=[" in line:
                    title = "전략 dead 감지"
                elif "exited" in line.lower() or "Failed with result" in line:
                    title = "프로세스 종료"
                _send_alert(title, ctx, channel, cfg["jitter"], st, fp)

    try:
        proc.terminate()
    except Exception:
        pass
    log.info("👋 오류감시 종료")
    return 0


def run_test_mm() -> int:
    ch = str(
        get_env_from_db("ERROR_WATCH_MM_CHANNEL", "")
        or get_env_from_db("KIS_SYSTEM_MM_CHANNEL", "default")
        or "default"
    ).strip() or "default"
    ok = msg_mm(
        "🧪 **[오류감시 테스트]** kis_error_watch_mm.py --test-mm OK",
        channel_alias=ch,
        jitter=False,
    )
    print(f"test_mm channel={ch} ok={ok}")
    return 0 if ok else 1


def main() -> int:
    signal.signal(signal.SIGINT, _on_signal)
    signal.signal(signal.SIGTERM, _on_signal)
    ap = argparse.ArgumentParser(description="kis_trader journal 오류 → Mattermost")
    ap.add_argument("--test-mm", action="`  `", help="테스트 메시지 1회 발송 후 종료")
    args = ap.parse_args()
    if args.test_mm:
        return run_test_mm()
    return run_watch()


if __name__ == "__main__":
    raise SystemExit(main())