133 lines
4.8 KiB
Python
133 lines
4.8 KiB
Python
"""Logging: eine Zeile je Ereignis, als JSON (Betrieb) oder Text (Entwicklung).
|
|
|
|
Jede Zeile trägt den Kontext, in dem sie entsteht: request_id, user_id, workspace_id,
|
|
run_id und worker_id. Gesetzt wird er über contextvars (Middleware im Web, Run im Worker),
|
|
damit Aufrufer nichts durchreichen müssen.
|
|
|
|
Nie geloggt werden Inhalte (Prompts, Antworten, Abfrageergebnisse) und Geheimnisse; als
|
|
zweite Sicherung maskiert ein Filter typische Muster (Bearer-Token, API-Keys, Passwörter).
|
|
"""
|
|
|
|
import json
|
|
import logging
|
|
import re
|
|
import sys
|
|
from collections.abc import Iterator, Mapping
|
|
from contextlib import contextmanager
|
|
from contextvars import ContextVar
|
|
from datetime import UTC, datetime
|
|
from types import MappingProxyType
|
|
from typing import Any
|
|
|
|
CONTEXT_FIELDS = ("request_id", "user_id", "workspace_id", "run_id", "worker_id")
|
|
# Unveränderlich: Änderungen setzen immer ein neues Dict, der Standard wird nie geteilt beschrieben
|
|
_context: ContextVar[Mapping[str, Any]] = ContextVar("aiw_log_context", default=MappingProxyType({}))
|
|
|
|
# Felder des LogRecord, die nicht als Zusatzangaben ausgegeben werden
|
|
_STANDARD = set(vars(logging.LogRecord("", 0, "", 0, "", None, None))) | {"message", "asctime", "taskName", "color_message"}
|
|
|
|
SECRETS = [
|
|
(re.compile(r"(?i)(bearer\s+)[A-Za-z0-9._~+/=-]{6,}"), r"\1***"),
|
|
(re.compile(r"\b(sk|pk|rk)-[A-Za-z0-9_-]{8,}"), r"\1-***"),
|
|
(re.compile(r"(?i)\b(password|passwort|secret|token|api_key|apikey)(\s*[=:]\s*)([^\s,;&\"']+)"), r"\1\2***"),
|
|
(re.compile(r"(?i)(://[^:/@\s]+:)[^@\s]+@"), r"\1***@"),
|
|
]
|
|
|
|
|
|
def redact(text: str) -> str:
|
|
for pattern, replacement in SECRETS:
|
|
text = pattern.sub(replacement, text)
|
|
return text
|
|
|
|
|
|
def bind(**values: Any) -> None:
|
|
"""Kontext für alle folgenden Zeilen dieses Requests bzw. Runs ergänzen."""
|
|
_context.set({**_context.get(), **{k: v for k, v in values.items() if v is not None}})
|
|
|
|
|
|
@contextmanager
|
|
def scope(**values: Any) -> Iterator[None]:
|
|
"""Kontext nur für einen Abschnitt, danach wieder der vorherige."""
|
|
token = _context.set({**_context.get(), **{k: v for k, v in values.items() if v is not None}})
|
|
try:
|
|
yield
|
|
finally:
|
|
_context.reset(token)
|
|
|
|
|
|
def current() -> dict[str, Any]:
|
|
return dict(_context.get())
|
|
|
|
|
|
def clear() -> None:
|
|
_context.set({})
|
|
|
|
|
|
class ContextFilter(logging.Filter):
|
|
def filter(self, record: logging.LogRecord) -> bool:
|
|
for key, value in _context.get().items():
|
|
if not hasattr(record, key):
|
|
setattr(record, key, value)
|
|
return True
|
|
|
|
|
|
_factory = logging.getLogRecordFactory()
|
|
|
|
|
|
def _record(*args: Any, **kwargs: Any) -> logging.LogRecord:
|
|
"""Kontext beim Erzeugen anhängen: dann tragen ihn alle Handler, auch fremde."""
|
|
record = _factory(*args, **kwargs)
|
|
record.__dict__.update(_context.get())
|
|
return record
|
|
|
|
|
|
if not getattr(_factory, "aiw", False):
|
|
_record.aiw = True # type: ignore[attr-defined]
|
|
logging.setLogRecordFactory(_record)
|
|
|
|
|
|
def extras(record: logging.LogRecord) -> dict[str, Any]:
|
|
return {k: v for k, v in vars(record).items() if k not in _STANDARD and not k.startswith("_")}
|
|
|
|
|
|
class JsonFormatter(logging.Formatter):
|
|
def format(self, record: logging.LogRecord) -> str:
|
|
entry: dict[str, Any] = {
|
|
"time": datetime.fromtimestamp(record.created, UTC).isoformat(timespec="milliseconds"),
|
|
"level": record.levelname.lower(),
|
|
"logger": record.name,
|
|
"message": redact(record.getMessage()),
|
|
}
|
|
for key, value in extras(record).items():
|
|
entry[key] = redact(value) if isinstance(value, str) else value
|
|
if record.exc_info:
|
|
entry["exception"] = redact(self.formatException(record.exc_info))
|
|
return json.dumps(entry, ensure_ascii=False, default=str)
|
|
|
|
|
|
class TextFormatter(logging.Formatter):
|
|
def __init__(self) -> None:
|
|
super().__init__("%(asctime)s %(levelname)s %(name)s: %(message)s")
|
|
|
|
def format(self, record: logging.LogRecord) -> str:
|
|
text = redact(super().format(record))
|
|
fields = extras(record)
|
|
if fields:
|
|
text += " " + " ".join(f"{k}={fields[k]}" for k in sorted(fields))
|
|
return text
|
|
|
|
|
|
def setup(level: str = "INFO", fmt: str = "text") -> None:
|
|
handler = logging.StreamHandler(sys.stdout)
|
|
handler.setFormatter(JsonFormatter() if fmt == "json" else TextFormatter())
|
|
handler.addFilter(ContextFilter())
|
|
root = logging.getLogger()
|
|
root.handlers[:] = [handler]
|
|
root.setLevel(level.upper())
|
|
# Eigene Zugriffszeile statt der von uvicorn; Fehler von uvicorn laufen über root
|
|
logging.getLogger("uvicorn.access").disabled = True
|
|
for name in ("uvicorn", "uvicorn.error"):
|
|
logging.getLogger(name).handlers[:] = []
|
|
logging.getLogger(name).propagate = True
|
|
# httpx loggt jede Anfrage mit voller URL auf INFO
|
|
logging.getLogger("httpx").setLevel(logging.WARNING)
|