From 21d4907f022981031a8d91ad080d0b6e13ac7db1 Mon Sep 17 00:00:00 2001 From: chendelian <116870791@qq.com> Date: Tue, 2 Jun 2026 15:18:38 +0800 Subject: [PATCH] fix: unified logging probe before file handler attach --- src/jiangchang_skill_core/unified_logging.py | 101 ++++++++++++------- tests/test_unified_logging.py | 64 ++++++++++++ 2 files changed, 129 insertions(+), 36 deletions(-) create mode 100644 tests/test_unified_logging.py diff --git a/src/jiangchang_skill_core/unified_logging.py b/src/jiangchang_skill_core/unified_logging.py index f5e6daf..0e3c788 100644 --- a/src/jiangchang_skill_core/unified_logging.py +++ b/src/jiangchang_skill_core/unified_logging.py @@ -10,13 +10,16 @@ import os import sys import uuid from logging.handlers import TimedRotatingFileHandler -from typing import Optional +from typing import Optional, Tuple from .runtime_env import get_data_root, get_user_id _skill_slug: str = "" _logger_name: str = "" +# 避免 logging 内部错误再向 stderr 打印 "--- Logging error ---" +logging.raiseExceptions = False + def get_unified_logs_dir() -> str: path = os.path.join(get_data_root(), get_user_id(), "logs") @@ -41,6 +44,19 @@ def get_skill_log_file_path() -> str: return os.path.join(get_unified_logs_dir(), "jiangchang.log") +def _can_open_log_file(log_path: str) -> Tuple[bool, str]: + """探测日志文件是否可追加写入（真实 open，非 os.access）。""" + try: + parent = os.path.dirname(os.path.abspath(log_path)) + if parent: + os.makedirs(parent, exist_ok=True) + with open(log_path, "a", encoding="utf-8"): + pass + return True, "" + except Exception as exc: + return False, str(exc) + + def ensure_trace_for_process() -> str: """本进程调用链 ID：沿用 JIANGCHANG_TRACE_ID，否则生成并写入环境（子进程可继承）。""" existing = (os.getenv("JIANGCHANG_TRACE_ID") or "").strip() @@ -87,8 +103,17 @@ def _backup_count() -> int: return 30 -def _attach_fallback_handler(log: logging.Logger, fmt: logging.Formatter) -> None: - """文件日志不可用时仅挂内存 handler，不向 stderr 打印 logging 异常。""" +def _clear_logger_handlers(log: logging.Logger) -> None: + for h in list(log.handlers): + log.removeHandler(h) + try: + h.close() + except Exception: + pass + + +def _attach_fallback_handler(log: logging.Logger) -> None: + """文件日志不可用时仅挂 NullHandler，不向 stderr 打印 logging 异常。""" log.addHandler(logging.NullHandler()) @@ -96,37 +121,39 @@ def setup_skill_logging(skill_slug: str, logger_name: str) -> None: """ 幂等：为指定 logger 挂载统一文件日志与可选 stderr。 须在进程早期调用（如 CLI main 在业务日志之前）。 - 文件日志目录无权限或不可写时降级为 no-op，不影响 CLI 返回码。 + 文件日志不可写时降级为 NullHandler，不影响 CLI 返回码。 """ global _skill_slug, _logger_name + logging.raiseExceptions = False ensure_trace_for_process() _skill_slug = skill_slug _logger_name = logger_name log = logging.getLogger(logger_name) - if log.handlers: - return + _clear_logger_handlers(log) log.setLevel(_log_level_from_env()) fmt = logging.Formatter(_FORMAT, datefmt=_DATEFMT) filt = _SkillContextFilter() - try: - path = get_skill_log_file_path() - fh = TimedRotatingFileHandler( - path, - when="midnight", - interval=1, - backupCount=_backup_count(), - encoding="utf-8", - delay=True, - ) - fh.setFormatter(fmt) - fh.addFilter(filt) - log.addHandler(fh) - except (OSError, PermissionError, ValueError): - _attach_fallback_handler(log, fmt) - except Exception: - _attach_fallback_handler(log, fmt) + log_path = get_skill_log_file_path() + ok, _err = _can_open_log_file(log_path) + if ok: + try: + fh = TimedRotatingFileHandler( + log_path, + when="midnight", + interval=1, + backupCount=_backup_count(), + encoding="utf-8", + delay=False, + ) + fh.setFormatter(fmt) + fh.addFilter(filt) + log.addHandler(fh) + except Exception: + _attach_fallback_handler(log) + else: + _attach_fallback_handler(log) if (os.getenv("JIANGCHANG_LOG_TO_STDERR") or "").strip().lower() in ( "1", @@ -162,23 +189,25 @@ def attach_unified_file_handler( 独立子进程内追加同一日志文件（如 login 检测子进程），格式与主进程一致。 """ global _skill_slug + logging.raiseExceptions = False ensure_trace_for_process() _skill_slug = skill_slug lg = logging.getLogger(logger_name) - lg.handlers.clear() + _clear_logger_handlers(lg) lg.setLevel(level) fmt = logging.Formatter(_FORMAT, datefmt=_DATEFMT) - try: - parent = os.path.dirname(os.path.abspath(log_path)) - if parent: - os.makedirs(parent, exist_ok=True) - fh = logging.FileHandler(log_path, encoding="utf-8") - fh.setFormatter(fmt) - fh.addFilter(_SkillContextFilter()) - lg.addHandler(fh) - except (OSError, PermissionError, ValueError): - lg.addHandler(logging.NullHandler()) - except Exception: - lg.addHandler(logging.NullHandler()) + filt = _SkillContextFilter() + + ok, _err = _can_open_log_file(log_path) + if ok: + try: + fh = logging.FileHandler(log_path, encoding="utf-8", delay=False) + fh.setFormatter(fmt) + fh.addFilter(filt) + lg.addHandler(fh) + except Exception: + _attach_fallback_handler(lg) + else: + _attach_fallback_handler(lg) lg.propagate = False return lg diff --git a/tests/test_unified_logging.py b/tests/test_unified_logging.py new file mode 100644 index 0000000..d9370eb --- /dev/null +++ b/tests/test_unified_logging.py @@ -0,0 +1,64 @@ +# -*- coding: utf-8 -*- +"""统一日志：文件不可写时降级，首次 emit 不抛 PermissionError。""" +from __future__ import annotations + +import logging +import os +import tempfile +import unittest +from logging.handlers import TimedRotatingFileHandler +from unittest.mock import patch + +from jiangchang_skill_core import unified_logging as ul + + +class TestUnifiedLogging(unittest.TestCase): + def setUp(self) -> None: + ul._skill_slug = "" + ul._logger_name = "" + + def test_can_open_log_file_writable(self) -> None: + with tempfile.TemporaryDirectory() as tmp: + path = os.path.join(tmp, "test.log") + ok, err = ul._can_open_log_file(path) + self.assertTrue(ok) + self.assertEqual(err, "") + self.assertTrue(os.path.isfile(path)) + + def test_setup_skill_logging_writable(self) -> None: + with tempfile.TemporaryDirectory() as tmp: + log_path = os.path.join(tmp, "skill.log") + logger_name = "test.logger.writable" + with patch.object(ul, "get_skill_log_file_path", return_value=log_path): + ul.setup_skill_logging("receive-order", logger_name) + ul.get_skill_logger().info("hello") + self.assertTrue(os.path.isfile(log_path)) + ul._clear_logger_handlers(logging.getLogger(logger_name)) + + def test_setup_skill_logging_unwritable_no_file_handler(self) -> None: + logger_name = "test.logger.unwritable" + with patch.object(ul, "_can_open_log_file", return_value=(False, "permission denied")): + ul.setup_skill_logging("receive-order", logger_name) + lg = logging.getLogger(logger_name) + lg.info("hello") + handlers = logging.getLogger(logger_name).handlers + self.assertFalse(any(isinstance(h, TimedRotatingFileHandler) for h in handlers)) + self.assertTrue(any(isinstance(h, logging.NullHandler) for h in handlers)) + + def test_attach_unified_file_handler_unwritable(self) -> None: + logger_name = "test.logger.attach.unwritable" + with patch.object(ul, "_can_open_log_file", return_value=(False, "permission denied")): + lg = ul.attach_unified_file_handler( + "/no/access/test.log", + skill_slug="receive-order", + logger_name=logger_name, + ) + lg.info("hello") + self.assertFalse( + any(isinstance(h, logging.FileHandler) for h in lg.handlers) + ) + self.assertTrue(any(isinstance(h, logging.NullHandler) for h in lg.handlers)) + + +if __name__ == "__main__": + unittest.main()