mirror of
https://github.com/jxxghp/MoviePilot.git
synced 2026-11-09 23:30:13 +08:00
e47d7defe7
全局日志等级是一个开关，调试单个插件时只能整体下调。一旦下调，被调试插件那几行 日志会淹没在其他几十个插件与宿主自身的 DEBUG 输出里，找不出来；不下调又什么都 看不见。插件实例数量只会继续增长，这个矛盾不会自己消失。 因此把等级下放到实例：plugininstance 行加 log_level / log_expires_at 两列，本体与 分身共用同一张表、同一套语义。等级落在实例自己那一行而不是另起一张按实例 ID 索引 的表——它和业务参数一样是用户按实例设置的东西，同一个生命周期，实例被删时应当随行 一起消失。清除覆盖后若本体行只剩一对身份列，整行按 carries_only_identity 回收，与 清空业务参数同一规则。 覆盖带失效时间，因为它是调试设置不是长期配置：开了 DEBUG 忘记关，下次谁也想不起 某个插件为什么一直在刷日志。过期判定在读取时惰性执行并就地清理，不另起后台线程去 扫一张最多几十条的表。expires_at 在写入侧先归一到 UTC 再分发给缓存与落盘两处：客户端 提交的时间可能不带时区，两处各按进程时区折算一次，就会与读取口返回的 UTC 值差出一个 时区，表现为「提交的失效时刻和读回来的对不上」。 运行期用 ContextVar 在宿主自己控制的四类调用点绑定当前实例——构造与 init_plugin、 事件处理器、定时服务回调、插件声明的 HTTP 端点——而不是沿用 logger() 已有的栈帧内省。 内省认的是栈顶的模块与类，插件通过宿主公共方法转发调用时栈顶是宿主而不是发起调用的 插件，会把日志记到错误的来源上；分身更甚：分身共享源码，类的 __qualname__ 保持源类名 不变，内省根本分不出是哪一个分身在打日志。内省结果继续只用于文件路由，不参与等级判定。 等级过滤必须排在全局等级判定之前。官方现状是先按全局等级短路、之后才做内省，先短路 就会把实例调低的等级挡在门外，后面再怎么识别来源都看不到这条日志。 回调在注册时被捕获、稍后才由调度器或 FastAPI 调用，那时已经不在任何绑定作用域内， 故这两处改用 wrap_for_plugin_instance 把绑定包进回调自身；同一实例重复包装直接返回 原对象，避免插件缓存声明时包装链随重载次数无限增长。 进程内覆盖表按实例 ID 常驻，删分身时必须一并清掉：只删库里那一行的话，同一进程内用 相同后缀重建的分身会继承上一个分身的等级，界面显示「跟随全局」而实际仍按旧等级输出。 进程重启后反向从库预热缓存。 迁移链在 F1 之后追加：c4e1a7b9d2f6（3.0.35）-> 487f7e681955（3.0.36 加两列）。 顺带补了 agent 策略里缺失的 media.classification.policy.get 的 template 字段说明： 少了它，api_mcp_schema.json 与技能文档的两个生成脚本都跑不起来。
272 lines
9.9 KiB
Python
272 lines
9.9 KiB
Python
"""插件实例日志等级覆盖缓存与上下文绑定测试。"""
|
||
|
||
from __future__ import annotations
|
||
|
||
import asyncio
|
||
import inspect
|
||
from datetime import datetime, timedelta, timezone
|
||
from pathlib import Path
|
||
from types import SimpleNamespace
|
||
|
||
import pytest
|
||
|
||
from app.runtime import log as log_module
|
||
from app.runtime.log import (
|
||
LoggerManager,
|
||
bind_plugin_instance,
|
||
clear_plugin_instance_log_level,
|
||
current_plugin_instance_id,
|
||
get_effective_plugin_instance_log_level,
|
||
get_plugin_instance_log_level_override,
|
||
logger,
|
||
normalize_log_expiry,
|
||
set_plugin_instance_log_level,
|
||
wrap_for_plugin_instance,
|
||
)
|
||
|
||
|
||
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:
|
||
"""保存单条日志的级别、内容和目标路径。"""
|
||
self.entries.append((level, message, file_path))
|
||
|
||
@staticmethod
|
||
def shutdown() -> bool:
|
||
"""测试写入器没有待释放资源。"""
|
||
return True
|
||
|
||
|
||
@pytest.fixture(autouse=True)
|
||
def _isolate_plugin_log_state(monkeypatch):
|
||
"""快照并还原插件实例日志等级涉及的全部进程内全局状态，避免用例间互相污染。"""
|
||
monkeypatch.setattr(log_module, "_plugin_level_overrides", {})
|
||
monkeypatch.setattr(log_module.log_settings, "DEBUG", False)
|
||
monkeypatch.setattr(log_module.log_settings, "LOG_LEVEL", "INFO")
|
||
yield
|
||
|
||
|
||
@pytest.fixture(name="fake_writer")
|
||
def fixture_fake_writer(monkeypatch, tmp_path):
|
||
"""装配内存写入器，跳过真实文件 I/O。"""
|
||
writer = _CapturingLogWriter()
|
||
monkeypatch.setattr(LoggerManager, "_writer", writer)
|
||
monkeypatch.setattr(LoggerManager, "_log_path", tmp_path)
|
||
monkeypatch.setattr(
|
||
LoggerManager,
|
||
"_get_console_logger",
|
||
classmethod(
|
||
lambda _cls, _logfile: SimpleNamespace(
|
||
info=lambda *_a, **_kw: None,
|
||
debug=lambda *_a, **_kw: None,
|
||
warning=lambda *_a, **_kw: None,
|
||
error=lambda *_a, **_kw: None,
|
||
critical=lambda *_a, **_kw: None,
|
||
)
|
||
),
|
||
)
|
||
return writer
|
||
|
||
|
||
def test_set_and_get_effective_level_returns_override():
|
||
"""设置覆盖后按实例查询生效等级应返回覆盖值而非全局等级。"""
|
||
set_plugin_instance_log_level("DemoPluginWork", "DEBUG")
|
||
|
||
assert get_effective_plugin_instance_log_level("DemoPluginWork") == "DEBUG"
|
||
assert get_effective_plugin_instance_log_level("OtherInstance") == "INFO"
|
||
|
||
|
||
def test_set_invalid_level_raises_value_error():
|
||
"""非受支持的等级名必须拒绝写入缓存。"""
|
||
with pytest.raises(ValueError):
|
||
set_plugin_instance_log_level("DemoPluginWork", "LOUD")
|
||
|
||
assert get_plugin_instance_log_level_override("DemoPluginWork") is None
|
||
|
||
|
||
def test_clear_resets_to_global_level():
|
||
"""清除覆盖后立即回落全局等级。"""
|
||
set_plugin_instance_log_level("DemoPluginWork", "ERROR")
|
||
|
||
clear_plugin_instance_log_level("DemoPluginWork")
|
||
|
||
assert get_plugin_instance_log_level_override("DemoPluginWork") is None
|
||
assert get_effective_plugin_instance_log_level("DemoPluginWork") == "INFO"
|
||
|
||
|
||
def test_clear_is_idempotent_for_unset_instance():
|
||
"""清除一个从未设置过覆盖的实例不应报错。"""
|
||
clear_plugin_instance_log_level("NeverConfigured")
|
||
clear_plugin_instance_log_level("NeverConfigured")
|
||
|
||
|
||
def test_expired_override_evicts_on_read():
|
||
"""过期覆盖必须在读取时惰性判定并清理，而不是继续生效。"""
|
||
set_plugin_instance_log_level(
|
||
"DemoPluginWork",
|
||
"DEBUG",
|
||
expires_at=datetime.now(timezone.utc) - timedelta(seconds=1),
|
||
)
|
||
|
||
assert get_plugin_instance_log_level_override("DemoPluginWork") is None
|
||
assert get_effective_plugin_instance_log_level("DemoPluginWork") == "INFO"
|
||
|
||
|
||
def test_unexpired_override_survives_read():
|
||
"""未过期覆盖读取后仍然生效，失效时间按同一时刻带时区返回。
|
||
|
||
读回的是带时区的时间：不带时区会让调用方按 UTC 解读时整体偏移，表现为提交的
|
||
失效时刻与读回来的对不上。因此按时刻比较，而不是直接相减两种不同的时间。
|
||
"""
|
||
expires_at = datetime.now(timezone.utc) + timedelta(hours=1)
|
||
set_plugin_instance_log_level("DemoPluginWork", "WARNING", expires_at=expires_at)
|
||
|
||
override = get_plugin_instance_log_level_override("DemoPluginWork")
|
||
|
||
assert override is not None
|
||
level_name, returned_expiry = override
|
||
assert level_name == "WARNING"
|
||
assert returned_expiry is not None
|
||
assert returned_expiry.tzinfo is not None
|
||
assert abs(returned_expiry.timestamp() - expires_at.timestamp()) < 1
|
||
|
||
|
||
def test_normalize_log_expiry_reads_naive_input_as_utc():
|
||
"""不带时区的失效时间按 UTC 解读，而不是按进程所在时区。"""
|
||
naive = datetime(2026, 1, 1, 12, 0, 0)
|
||
|
||
normalized = normalize_log_expiry(naive)
|
||
|
||
assert normalized == datetime(2026, 1, 1, 12, 0, 0, tzinfo=timezone.utc)
|
||
assert normalize_log_expiry(None) is None
|
||
|
||
|
||
def test_normalize_log_expiry_converts_aware_input_to_utc():
|
||
"""带时区的失效时间原样换算到 UTC，描述的仍是同一个时刻。"""
|
||
aware = datetime(2026, 1, 1, 12, 0, 0, tzinfo=timezone(timedelta(hours=8)))
|
||
|
||
normalized = normalize_log_expiry(aware)
|
||
|
||
assert normalized == datetime(2026, 1, 1, 4, 0, 0, tzinfo=timezone.utc)
|
||
|
||
|
||
def test_naive_expiry_round_trips_without_timezone_shift():
|
||
"""提交裸时间再读回来必须是同一时刻，不因进程时区整体偏移。"""
|
||
naive = datetime.now(timezone.utc).replace(tzinfo=None) + timedelta(hours=2)
|
||
set_plugin_instance_log_level("DemoPluginWork", "DEBUG", expires_at=naive)
|
||
|
||
override = get_plugin_instance_log_level_override("DemoPluginWork")
|
||
|
||
assert override is not None
|
||
_level_name, returned_expiry = override
|
||
assert returned_expiry == naive.replace(tzinfo=timezone.utc)
|
||
|
||
|
||
def test_override_does_not_leak_into_unrelated_instance_effective_level():
|
||
"""一个实例的覆盖不得影响另一个未设置覆盖实例的生效等级。"""
|
||
set_plugin_instance_log_level("DemoPluginWork", "DEBUG")
|
||
|
||
assert get_effective_plugin_instance_log_level("SiblingInstance") == "INFO"
|
||
|
||
|
||
def test_current_plugin_instance_id_defaults_to_none():
|
||
"""未绑定时读取当前实例上下文应为 None。"""
|
||
assert current_plugin_instance_id() is None
|
||
|
||
|
||
def test_bind_plugin_instance_sets_and_resets_context():
|
||
"""绑定上下文管理器退出后必须恢复为未绑定状态，支持嵌套。"""
|
||
assert current_plugin_instance_id() is None
|
||
with bind_plugin_instance("Outer"):
|
||
assert current_plugin_instance_id() == "Outer"
|
||
with bind_plugin_instance("Inner"):
|
||
assert current_plugin_instance_id() == "Inner"
|
||
assert current_plugin_instance_id() == "Outer"
|
||
assert current_plugin_instance_id() is None
|
||
|
||
|
||
def test_wrap_for_plugin_instance_binds_sync_callable():
|
||
"""同步回调包装后执行期间应能读到绑定的实例 ID。"""
|
||
seen: list[str | None] = []
|
||
|
||
def _callback() -> None:
|
||
seen.append(current_plugin_instance_id())
|
||
|
||
wrapped = wrap_for_plugin_instance(_callback, "DemoPluginWork")
|
||
wrapped()
|
||
|
||
assert seen == ["DemoPluginWork"]
|
||
assert current_plugin_instance_id() is None
|
||
|
||
|
||
def test_wrap_for_plugin_instance_binds_async_callable():
|
||
"""异步回调包装后仍保持协程函数身份，且执行期间能读到绑定的实例 ID。"""
|
||
seen: list[str | None] = []
|
||
|
||
async def _callback() -> None:
|
||
seen.append(current_plugin_instance_id())
|
||
|
||
wrapped = wrap_for_plugin_instance(_callback, "DemoPluginWork")
|
||
assert inspect.iscoroutinefunction(wrapped)
|
||
asyncio.run(wrapped())
|
||
|
||
assert seen == ["DemoPluginWork"]
|
||
|
||
|
||
def test_wrap_for_plugin_instance_is_idempotent_for_the_same_instance():
|
||
"""同一实例重复包装返回原对象，避免每次刷新注册都叠一层包装。"""
|
||
|
||
def _callback() -> None:
|
||
"""空回调，只用于观察包装结果。"""
|
||
|
||
wrapped = wrap_for_plugin_instance(_callback, "DemoPluginWork")
|
||
|
||
assert wrap_for_plugin_instance(wrapped, "DemoPluginWork") is wrapped
|
||
assert wrap_for_plugin_instance(wrapped, "OtherInstance") is not wrapped
|
||
|
||
|
||
def test_bound_instance_with_lower_override_emits_debug_log(fake_writer):
|
||
"""绑定实例设了更宽松的覆盖时，全局等级挡不住的 DEBUG 日志应放行。"""
|
||
set_plugin_instance_log_level("DemoPluginWork", "DEBUG")
|
||
|
||
with bind_plugin_instance("DemoPluginWork"):
|
||
logger.debug("verbose diagnostic")
|
||
|
||
assert any("verbose diagnostic" in message for _level, message, _path in fake_writer.entries)
|
||
|
||
|
||
def test_unbound_debug_log_is_dropped_by_global_level(fake_writer):
|
||
"""未绑定任何实例时，DEBUG 日志仍按全局 INFO 等级过滤丢弃。"""
|
||
set_plugin_instance_log_level("DemoPluginWork", "DEBUG")
|
||
|
||
logger.debug("verbose diagnostic without binding")
|
||
|
||
assert fake_writer.entries == []
|
||
|
||
|
||
def test_bound_instance_with_stricter_override_drops_info_log(fake_writer):
|
||
"""绑定实例设了更严格的覆盖时，全局等级本会放行的 INFO 日志应被丢弃。"""
|
||
set_plugin_instance_log_level("DemoPluginWork", "ERROR")
|
||
|
||
with bind_plugin_instance("DemoPluginWork"):
|
||
logger.info("routine progress")
|
||
|
||
assert fake_writer.entries == []
|
||
|
||
|
||
def test_other_bound_instance_is_unaffected_by_sibling_override(fake_writer):
|
||
"""一个实例的覆盖不得影响另一个未设置覆盖实例的过滤结果。"""
|
||
set_plugin_instance_log_level("DemoPluginWork", "ERROR")
|
||
|
||
with bind_plugin_instance("SiblingInstance"):
|
||
logger.info("sibling routine progress")
|
||
|
||
assert any(
|
||
"sibling routine progress" in message for _level, message, _path in fake_writer.entries
|
||
)
|