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