diff --git a/app/runtime/log.py b/app/runtime/log.py index 043098db6..1f370bf86 100644 --- a/app/runtime/log.py +++ b/app/runtime/log.py @@ -22,7 +22,7 @@ from datetime import datetime, timezone from logging.handlers import RotatingFileHandler from pathlib import Path from types import FrameType -from typing import Any, Callable, Dict, Iterator, NamedTuple, Optional, Protocol, Self, Tuple +from typing import Any, Callable, Dict, Iterator, NamedTuple, Optional, Protocol, Self, Tuple, cast import click from pydantic import BaseModel, ConfigDict, Field @@ -162,14 +162,22 @@ class LogEntry: message: str, file_path: Path, timestamp: datetime | None = None, + exc_info: Optional[Tuple[Any, Any, Any]] = None, ) -> None: """ - 记录日志级别、格式化文本和目标文件。 + 记录日志级别、格式化文本、目标文件和异常三元组。 + + :param level: 日志等级名称 + :param message: 已经格式化的日志正文 + :param file_path: 目标日志文件路径 + :param timestamp: 日志产生时间，缺省时取当前时间 + :param exc_info: 已规范化的异常三元组，供文件格式化器输出堆栈 """ self.level = level self.message = message self.file_path = file_path self.timestamp = timestamp or datetime.now() + self.exc_info = exc_info self.correlation_id = _get_log_correlation_id() @@ -178,13 +186,20 @@ class LogWriter(Protocol): 平台日志门面使用的文件写入端口。 """ - def write_log(self, level: str, message: str, file_path: Path) -> None: + def write_log( + self, + level: str, + message: str, + file_path: Path, + exc_info: Optional[Tuple[Any, Any, Any]] = None, + ) -> None: """ 将一条日志写入指定文件。 :param level: 日志等级名称 :param message: 已经格式化的日志正文 :param file_path: 目标日志文件路径 + :param exc_info: 已规范化的异常三元组，供文件格式化器输出堆栈 """ def shutdown(self) -> Optional[bool]: @@ -225,6 +240,26 @@ def _get_log_correlation_id() -> str: return _correlation_id_provider() or "-" +def _normalize_exc_info(exc_info: Any) -> Optional[Tuple[Any, Any, Any]]: + """ + 把日志入口接收的异常信息规范化为可跨线程携带的三元组。 + + 文件日志由独立写线程统一落盘，写入时已不在异常发生的调用栈中，因此必须在 + 调用方线程先把 ``exc_info=True`` 解析为当前异常、把异常实例展开为三元组， + 避免 ``sys.exc_info()`` 在写线程取到空值而再次丢失堆栈。 + + :param exc_info: 标准库日志语义下的异常信息，可为 True、异常实例或三元组 + :return: 可直接交给文件格式化器的异常三元组；输入为空时返回 None + """ + if not exc_info: + return None + if isinstance(exc_info, BaseException): + return type(exc_info), exc_info, exc_info.__traceback__ + if exc_info is True: + return sys.exc_info() + return cast(Tuple[Any, Any, Any], exc_info) + + # 插件实例日志等级允许的取值，与标准库 logging 的等级名保持一致。 LOG_LEVELS: Tuple[str, ...] = ("DEBUG", "INFO", "WARNING", "ERROR", "CRITICAL") @@ -589,11 +624,22 @@ class NonBlockingFileHandler: self._rotating_handlers[file_path] = handler return handler - def write_log(self, level: str, message: str, file_path: Path) -> None: + def write_log( + self, + level: str, + message: str, + file_path: Path, + exc_info: Optional[Tuple[Any, Any, Any]] = None, + ) -> None: """ 根据当前线程是否运行事件循环选择异步或同步文件写入。 + + :param level: 日志等级名称 + :param message: 已经格式化的日志正文 + :param file_path: 目标日志文件路径 + :param exc_info: 已规范化的异常三元组，供文件格式化器输出堆栈 """ - entry = LogEntry(level, message, file_path) + entry = LogEntry(level, message, file_path, exc_info=exc_info) if self._is_in_event_loop(): self._write_non_blocking(entry) return @@ -696,7 +742,7 @@ class NonBlockingFileHandler: lineno=0, msg=entry.message, args=(), - exc_info=None, + exc_info=entry.exc_info, ) created_at = entry.timestamp.timestamp() record.created = created_at @@ -898,7 +944,7 @@ class LoggerManager: _lock = threading.RLock() _writer: Optional[LogWriter] = None _log_path: Optional[Path] = None - _pending_file_logs: deque[tuple[str, str, Path]] = deque(maxlen=1000) + _pending_file_logs: deque[tuple[str, str, Path, Optional[Tuple[Any, Any, Any]]]] = deque(maxlen=1000) def get_logger(self, name: str) -> logging.Logger: """ @@ -1011,8 +1057,13 @@ class LoggerManager: cls._log_path = Path(log_path) pending = list(cls._pending_file_logs) cls._pending_file_logs.clear() - for level, message, logfile in pending: - writer.write_log(level, message, Path(log_path) / logfile) + for level, message, logfile, exc_info in pending: + writer.write_log( + level, + message, + Path(log_path) / logfile, + exc_info=exc_info, + ) def update_loggers(self) -> None: """ @@ -1031,17 +1082,28 @@ class LoggerManager: configured_logger.setLevel(_CONSOLE_PIPELINE_LEVEL) @classmethod - def _write_file_log(cls, level: str, message: str, logfile: Path) -> None: + def _write_file_log( + cls, + level: str, + message: str, + logfile: Path, + exc_info: Optional[Tuple[Any, Any, Any]] = None, + ) -> None: """ 写入文件，或在启动装配完成前暂存日志。 + + :param level: 日志等级名称 + :param message: 已经格式化的日志正文 + :param logfile: 目标日志文件路径 + :param exc_info: 已规范化的异常三元组，供文件格式化器输出堆栈 """ with cls._lock: writer = cls._writer log_path = cls._log_path if not writer or not log_path: - cls._pending_file_logs.append((level, message, logfile)) + cls._pending_file_logs.append((level, message, logfile, exc_info)) return - writer.write_log(level, message, log_path / logfile) + writer.write_log(level, message, log_path / logfile, exc_info=exc_info) def logger(self, method: str, msg: object, *args: Any, **kwargs: Any) -> None: """ @@ -1057,6 +1119,7 @@ class LoggerManager: 会认错来源。 消息可为文本、异常或其它可格式化对象；格式化留在日志分流内部，调用方无需预先转成字符串。 + 传入 ``exc_info`` 时会在调用方线程先规范化为异常三元组，使文件日志和控制台一样保留堆栈。 这里只是一道提前短路，省掉被丢弃日志的栈帧内省与格式化；控制台输出端 由 `_ContextLevelFilter` 用同一个判据再判一次，两处结论因而一致。 @@ -1076,12 +1139,18 @@ class LoggerManager: except (TypeError, ValueError): formatted_msg = f"{formatted_msg} {' '.join(str(arg) for arg in args)}" + file_exc_info = _normalize_exc_info(kwargs.get("exc_info")) + if scope: scoped_message = formatted_msg[:8192] if scope.accept(method_level, scoped_message): prefix = f"[来源={scope.source} 轮次={scope.operation_id}]" - self._write_file_log(method.upper(), f"{prefix} {scoped_message}", - Path(scope.category) / f"{scope.resource_id}.log") + self._write_file_log( + method.upper(), + f"{prefix} {scoped_message}", + Path(scope.category) / f"{scope.resource_id}.log", + exc_info=file_exc_info, + ) if not ordinary_enabled: return @@ -1090,7 +1159,7 @@ class LoggerManager: if plugin_name else self._default_log_file ) - self._write_file_log(method.upper(), formatted_msg, logfile) + self._write_file_log(method.upper(), formatted_msg, logfile, exc_info=file_exc_info) configured_logger = self._get_console_logger(logfile) log_method = getattr(configured_logger, method, configured_logger.info) @@ -1137,7 +1206,7 @@ class LoggerManager: 输出 ERROR 日志，控制台默认附带当前异常堆栈。 适用于异常处理分支；调用方可通过 exc_info 显式关闭堆栈或指定异常信息。 - 文件消息和资源日志仍由统一日志路由按 ERROR 等级输出。 + 文件消息和资源日志同样按 ERROR 等级输出，并保留调用方提供的异常堆栈。 """ kwargs.setdefault("exc_info", True) self.logger("error", msg, *args, **kwargs) diff --git a/docs/rules/06-code-styles.md b/docs/rules/06-code-styles.md index ea34b1a31..8f611e525 100644 --- a/docs/rules/06-code-styles.md +++ b/docs/rules/06-code-styles.md @@ -78,7 +78,7 @@ Within each group, sort alphabetically. Do not use wildcard imports (`from modul - In **endpoint layer**: use FastAPI's `HTTPException` or the project's standard response schemas for errors. - Application and adapter layers must not swallow operational failures silently. Log or re-raise them according to the owning contract. Foundation primitives do not log; they return their documented fallback value or raise, leaving operational reporting to the caller. - Do not use bare `except:` — always catch a specific exception type or at minimum `Exception`. -- `logger.exception(...)` records at ERROR level and includes the current traceback in console output by default. File and resource logs receive the formatted ERROR message through the usual routing. An explicit `exc_info` value follows standard-library logging semantics. +- `logger.exception(...)` records at ERROR level and includes the current traceback in console output by default. File and resource logs receive the formatted ERROR message through the usual routing and preserve the provided traceback. An explicit `exc_info` value follows standard-library logging semantics. ```python # 保留失败原因，便于定位外部调用问题 diff --git a/tests/test_log_exception.py b/tests/test_log_exception.py index cc950d1d9..97214a383 100644 --- a/tests/test_log_exception.py +++ b/tests/test_log_exception.py @@ -61,6 +61,37 @@ def test_exception_accepts_explicit_exception(captured_logs): assert caplog.records[-1].exc_info[1] is failure +def test_exception_file_log_carries_exc_info(captured_logs): + """ + 文件日志写入链路应携带规范化异常三元组，供格式化器输出堆栈。 + """ + caplog, writer = captured_logs + failure = RuntimeError("file traceback failure") + try: + raise failure + except RuntimeError: + logger.error("request failed", exc_info=True) + assert caplog.records[-1].exc_info[1] is failure + assert writer.call_args.kwargs["exc_info"][1] is failure + + +def test_file_record_formatter_includes_traceback(): + """ + 文件格式化器应把日志条目携带的异常三元组输出为可读堆栈。 + """ + failure = ValueError("formatted file failure") + entry = log_module.LogEntry( + "ERROR", + "API 请求发生未捕获异常: formatted file failure", + LoggerManager._default_log_file, + exc_info=(type(failure), failure, failure.__traceback__), + ) + record = log_module.NonBlockingFileHandler._to_record(entry) + formatter = logging.Formatter(log_module.LogSettings().LOG_FILE_FORMAT) + formatted = formatter.format(record) + assert "ValueError: formatted file failure" in formatted + + def test_exception_respects_current_log_threshold(captured_logs, monkeypatch): """ 高于 ERROR 的日志阈值继续拦截异常消息。 diff --git a/tests/test_log_plugin_routing.py b/tests/test_log_plugin_routing.py index 017ffec9a..d72398670 100644 --- a/tests/test_log_plugin_routing.py +++ b/tests/test_log_plugin_routing.py @@ -16,9 +16,20 @@ class CapturingLogWriter: def __init__(self) -> None: self.entries: list[tuple[str, str, Path]] = [] - def write_log(self, level: str, message: str, file_path: Path) -> None: + def write_log( + self, + level: str, + message: str, + file_path: Path, + exc_info: tuple | None = None, + ) -> None: """ 保存单条日志的级别、内容和目标路径。 + + :param level: 日志等级名称 + :param message: 已经格式化的日志正文 + :param file_path: 目标日志文件路径 + :param exc_info: 已规范化的异常三元组，本测试写入器忽略该信息 """ self.entries.append((level, message, file_path)) diff --git a/tests/test_plugin_instance_logging.py b/tests/test_plugin_instance_logging.py index a53d5c88e..746219895 100644 --- a/tests/test_plugin_instance_logging.py +++ b/tests/test_plugin_instance_logging.py @@ -40,9 +40,20 @@ class _CapturingLogWriter: """ self.entries: list[tuple[str, str, Path]] = [] - def write_log(self, level: str, message: str, file_path: Path) -> None: + def write_log( + self, + level: str, + message: str, + file_path: Path, + exc_info: tuple | None = None, + ) -> None: """ 保存单条日志的级别、内容和目标路径。 + + :param level: 日志等级名称 + :param message: 已经格式化的日志正文 + :param file_path: 目标日志文件路径 + :param exc_info: 已规范化的异常三元组，本测试写入器忽略该信息 """ self.entries.append((level, message, file_path)) diff --git a/tests/test_subscription_logging.py b/tests/test_subscription_logging.py index 4059729ed..e659bf220 100644 --- a/tests/test_subscription_logging.py +++ b/tests/test_subscription_logging.py @@ -27,7 +27,7 @@ def fixture_captured(monkeypatch, tmp_path): 在内存中捕获文件路由，隔离全局等级及控制台输出。 """ entries = [] - monkeypatch.setattr(LoggerManager, "_writer", SimpleNamespace(write_log=lambda *args: entries.append(args))) + monkeypatch.setattr(LoggerManager, "_writer", SimpleNamespace(write_log=lambda *args, **kwargs: entries.append(args))) monkeypatch.setattr(LoggerManager, "_log_path", tmp_path) monkeypatch.setattr(log_module.log_settings, "DEBUG", False) monkeypatch.setattr(log_module.log_settings, "LOG_LEVEL", "INFO")