yawan-workbench/server/app/system_log.py

"""Safe persisted system log writer. Never accepts request bodies or credentials."""
import re
import json
import atexit
import logging
import queue
import threading
import time
from sqlmodel import Session
from .models import SystemLog

_SECRET = re.compile(r"(?i)(bearer\s+|(?:api[_-]?key|token|secret|password|authorization)\s*[:=]\s*)[^\s,;]+")
_BEARER = re.compile(r"(?i)(authorization\s*:\s*|bearer\s+)[^\s,;]+")
_SENSITIVE_KEYS = re.compile(r"(?i)^(?:body|input|data|token|access_token|refresh_token|password|passwd|secret|api[_-]?key|authorization|cookie|headers?)$")

# Ordinary informational logs are useful for diagnosis but should not make
# every request wait on SQLite's single-writer lock.  The queue contains only
# plain values plus the SQLAlchemy engine; sessions/connections never cross
# the worker boundary.  Critical records continue to use ``write`` directly.
_MAX_QUEUE = 1000
_BATCH_SIZE = 100
_FLUSH_INTERVAL = 1.0
_ORDINARY_LEVELS = frozenset({"DEBUG", "INFO", "WARNING", "WARN"})
_STOP = object()
_queue: queue.Queue = queue.Queue(maxsize=_MAX_QUEUE)
_worker: threading.Thread | None = None
_worker_lock = threading.Lock()
_stats_lock = threading.Lock()
_stats = {"queued": 0, "written": 0, "dropped": 0, "failed_batches": 0, "last_error": "", "queue_size": 0}
_logger = logging.getLogger(__name__)

def redact(value: object, limit: int = 1000) -> str:
    text = str(value or "")
    text = _BEARER.sub(lambda m: m.group(1) + "[REDACTED]", text)
    text = _SECRET.sub(lambda m: m.group(1) + "[REDACTED]", text)
    text = re.sub(r"(?i)\b(sk-[A-Za-z0-9_-]+|ghp_[A-Za-z0-9_]+)\b", "[REDACTED]", text)
    # Catch explicitly secret-looking fixture/error values even when detached from a key.
    text = re.sub(r"(?i)\bsecret[-_][A-Za-z0-9_-]+\b", "[REDACTED]", text)
    return text[:limit]

def safe_detail(detail: object, limit: int = 600) -> str:
    """Return useful exception detail without persisting request payloads/secrets.

    Validation errors often contain an ``input`` field with the complete request body;
    only location/message/type metadata is retained. HTTPException strings are still
    preserved (and passed through the normal secret redactor).
    """
    def clean(value: object, key: str = ""):
        if key and _SENSITIVE_KEYS.match(key):
            return "[已省略]"
        if isinstance(value, dict):
            allowed = {"loc", "msg", "type", "code", "detail", "reason", "message", "ctx"}
            return {str(k): clean(v, str(k)) for k, v in value.items() if str(k) in allowed}
        if isinstance(value, (list, tuple)):
            return [clean(v, key) for v in list(value)[:12]]
        return value
    try:
        value = clean(detail)
        text = json.dumps(value, ensure_ascii=False, separators=(",", ":"), default=str) if isinstance(value, (dict, list)) else str(value or "")
    except Exception:
        text = str(detail or "")
    return redact(text, limit=limit)


def _stat(name: str, amount: int = 1, *, error: str = "") -> None:
    with _stats_lock:
        _stats[name] = int(_stats.get(name, 0)) + amount
        _stats["queue_size"] = _queue.qsize()
        if error:
            _stats["last_error"] = redact(error, 240)


def stats() -> dict[str, object]:
    """Return inexpensive, process-local buffer counters for the ops panel."""
    with _stats_lock:
        result = dict(_stats)
    result["queue_size"] = _queue.qsize()
    result["queue_capacity"] = _MAX_QUEUE
    return result


def _ensure_worker() -> None:
    global _worker
    with _worker_lock:
        if _worker and _worker.is_alive():
            return
        _worker = threading.Thread(target=_run_worker, name="system-log-writer", daemon=True)
        _worker.start()


def _flush(items: list[dict]) -> None:
    if not items:
        return
    # Group by engine identity. A worker must create its own Session for each
    # group; sharing a request Session or DBAPI connection is unsafe.
    groups: dict[object, list[dict]] = {}
    for item in items:
        groups.setdefault(item["bind"], []).append(item)
    written = 0
    for bind, group in groups.items():
        try:
            with Session(bind=bind) as session:
                session.add_all([SystemLog(level=i["level"], source=i["source"],
                                           message=i["message"], trace_id=i["trace_id"],
                                           status=i["status"]) for i in group])
                session.commit()
            written += len(group)
        except Exception as exc:  # ordinary logs may be lost; never kill API worker
            _stat("failed_batches", error=f"{type(exc).__name__}: {exc}")
            _logger.warning("system log batch flush failed: %s", exc)
    if written:
        _stat("written", written)


def _run_worker() -> None:
    pending: list[dict] = []
    deadline = time.monotonic() + _FLUSH_INTERVAL

    def flush_pending() -> None:
        if not pending:
            return
        batch = list(pending)
        pending.clear()
        _flush(batch)
        # Mark queue work complete only after its own writer transaction has
        # finished (or failed), so flush() is a meaningful graceful wait.
        for _ in batch:
            _queue.task_done()

    while True:
        timeout = max(0.0, deadline - time.monotonic())
        try:
            item = _queue.get(timeout=timeout)
        except queue.Empty:
            item = None
        if item is _STOP:
            flush_pending()
            _queue.task_done()
            return
        if item is not None:
            pending.append(item)
        if len(pending) >= _BATCH_SIZE or time.monotonic() >= deadline:
            flush_pending()
            deadline = time.monotonic() + _FLUSH_INTERVAL


def emit(session: Session, *, level="INFO", source="app", message="", trace_id="", status="ok") -> bool:
    """Queue a non-critical log for batched persistence.

    Returns ``True`` when accepted by the bounded queue. ERROR/critical logs
    must use :func:`write`, which remains synchronous and returns a refreshed
    ``SystemLog`` row with its database id.
    """
    normalized = str(level).upper()[:16]
    if normalized not in _ORDINARY_LEVELS:
        write(session, level=normalized, source=source, message=message,
              trace_id=trace_id, status=status)
        return True
    bind = session.get_bind()
    item = {"bind": bind, "level": normalized, "source": str(source)[:64],
            "message": redact(message), "trace_id": redact(trace_id, 128),
            "status": str(status)[:32]}
    try:
        _queue.put_nowait(item)
    except queue.Full:
        _stat("dropped")
        return False
    _stat("queued")
    _ensure_worker()
    return True


def flush(timeout: float = 5.0) -> bool:
    """Wait for currently queued ordinary records to be handed to SQLite."""
    end = time.monotonic() + max(0.0, timeout)
    while _queue.unfinished_tasks and time.monotonic() < end:
        time.sleep(0.01)
    return _queue.unfinished_tasks == 0


def shutdown(timeout: float = 5.0) -> None:
    """Gracefully flush ordinary logs during process shutdown."""
    worker = _worker
    if not worker or not worker.is_alive():
        return
    try:
        _queue.put_nowait(_STOP)
    except queue.Full:
        flush(timeout)
        return
    worker.join(max(0.0, timeout))


atexit.register(shutdown)

def write(session: Session, *, level="ERROR", source="app", message="", trace_id="", status="error") -> SystemLog:
    row = SystemLog(level=str(level).upper()[:16], source=str(source)[:64], message=redact(message),
                    trace_id=redact(trace_id, 128), status=str(status)[:32])
    session.add(row); session.commit(); session.refresh(row)
    return row

def write_exception(session: Session, *, source: str, exc: BaseException, trace_id="", status="error") -> SystemLog:
    return write(session, level="ERROR", source=source, message=f"{type(exc).__name__}: {exc}", trace_id=trace_id, status=status)