Files
MoviePilot/tests/test_plugin_log_level_control.py
Aqr-K e47d7defe7 feat(plugin): 插件本体与分身可各自设置独立日志等级
全局日志等级是一个开关,调试单个插件时只能整体下调。一旦下调,被调试插件那几行
日志会淹没在其他几十个插件与宿主自身的 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 与技能文档的两个生成脚本都跑不起来。
2026-09-12 19:05:05 -04:00

161 lines
6.4 KiB
Python
Raw Blame History

This file contains ambiguous Unicode characters
This file contains Unicode characters that might be confused with other characters. If you think that this is intentional, you can safely ignore this warning. Use the Escape button to reveal them.
"""插件实例日志等级控制面的身份校验与读写分发测试。"""
from __future__ import annotations
from datetime import datetime, timedelta, timezone
import pytest
from app.runtime import log as log_module
from app.runtime.extensions.plugin.loglevel import PluginLogLevelControl
from app.runtime.log import get_plugin_instance_log_level_override
from app.schemas.plugin import PluginInstance
@pytest.fixture(autouse=True)
def _isolate_plugin_log_state(monkeypatch):
"""隔离进程内覆盖缓存与全局等级,避免与其他用例的实例 ID 相互污染。"""
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
def _control(
*,
instances: dict[str, PluginInstance],
stored: dict | None = None,
writes: list | None = None,
) -> PluginLogLevelControl:
"""按测试所需装配最小依赖,配置侧读写落在内存字典上。"""
stored = stored if stored is not None else {}
writes = writes if writes is not None else []
def _write(instance_id: str, level, expires_at) -> None:
"""记录一次落盘写入并同步内存中的已存值。"""
writes.append((instance_id, level, expires_at))
if level is None and expires_at is None:
stored.pop(instance_id, None)
else:
stored[instance_id] = (level, expires_at)
return PluginLogLevelControl(
plugin_exists=lambda plugin_id: True,
get_instance=instances.get,
instances_for_source=lambda source_plugin_id: [
instance
for instance in instances.values()
if instance.source_plugin_id == source_plugin_id
],
read_log_level=lambda instance_id: stored.get(instance_id, (None, None)),
write_log_level=_write,
)
def test_list_levels_rejects_clone_own_id_as_plugin_id():
"""用分身自身的实例 ID 查询日志等级总览必须拒绝,不能把分身伪装成本体。"""
clone = PluginInstance(instance_id="DemoPluginWork", source_plugin_id="DemoPlugin")
control = _control(instances={"DemoPluginWork": clone})
with pytest.raises(LookupError):
control.list_levels("DemoPluginWork")
def test_set_level_rejects_clone_own_id_as_plugin_id():
"""写路径同样要拒绝分身自身实例 ID,否则会把该行改写成本体记录。"""
clone = PluginInstance(instance_id="DemoPluginWork", source_plugin_id="DemoPlugin")
control = _control(instances={"DemoPluginWork": clone})
with pytest.raises(LookupError):
control.set_level("DemoPluginWork", "DemoPluginWork", "DEBUG")
def test_clear_level_rejects_clone_own_id_as_plugin_id():
"""清除路径同样拒绝分身自身实例 ID。"""
clone = PluginInstance(instance_id="DemoPluginWork", source_plugin_id="DemoPlugin")
control = _control(instances={"DemoPluginWork": clone})
with pytest.raises(LookupError):
control.clear_level("DemoPluginWork", "DemoPluginWork")
def test_set_level_rejects_instance_of_another_plugin():
"""实例必须真实归属被点名的源插件,跨插件写入要拒绝。"""
foreign = PluginInstance(instance_id="OtherWork", source_plugin_id="OtherPlugin")
control = _control(instances={"OtherWork": foreign})
with pytest.raises(LookupError):
control.set_level("DemoPlugin", "OtherWork", "DEBUG")
def test_list_levels_lists_host_and_clones_for_a_real_source_plugin_id():
"""用真正的源插件 ID 查询时正常返回本体与全部分身。"""
clone = PluginInstance(instance_id="DemoPluginWork", source_plugin_id="DemoPlugin")
control = _control(instances={"DemoPluginWork": clone})
levels = control.list_levels("DemoPlugin")
assert [item["instance_id"] for item in levels] == [
"DemoPlugin",
"DemoPluginWork",
]
assert all(item["effective_level"] == "INFO" for item in levels)
assert all(item["configured_level"] is None for item in levels)
def test_set_level_writes_cache_and_storage_then_clear_reverts_both():
"""设置要同时落进程内缓存与配置行,清除后两处都回到未设置。"""
clone = PluginInstance(instance_id="DemoPluginWork", source_plugin_id="DemoPlugin")
stored: dict = {}
writes: list = []
control = _control(instances={"DemoPluginWork": clone}, stored=stored, writes=writes)
control.set_level("DemoPlugin", "DemoPluginWork", "debug")
assert get_plugin_instance_log_level_override("DemoPluginWork") == ("DEBUG", None)
assert writes == [("DemoPluginWork", "DEBUG", None)]
control.clear_level("DemoPlugin", "DemoPluginWork")
assert get_plugin_instance_log_level_override("DemoPluginWork") is None
assert writes[-1] == ("DemoPluginWork", None, None)
assert stored == {}
def test_clear_level_skips_storage_write_when_nothing_was_configured():
"""从未设置过覆盖时清除不该产生一次多余的落盘写入。"""
clone = PluginInstance(instance_id="DemoPluginWork", source_plugin_id="DemoPlugin")
writes: list = []
control = _control(instances={"DemoPluginWork": clone}, writes=writes)
control.clear_level("DemoPlugin", "DemoPluginWork")
assert writes == []
def test_set_level_normalizes_naive_expiry_to_utc_before_persisting():
"""裸时间在写入侧就归一到 UTC,落盘值与缓存读回值描述同一个时刻。"""
clone = PluginInstance(instance_id="DemoPluginWork", source_plugin_id="DemoPlugin")
writes: list = []
control = _control(instances={"DemoPluginWork": clone}, writes=writes)
naive = (datetime.now(timezone.utc) + timedelta(hours=3)).replace(tzinfo=None)
control.set_level("DemoPlugin", "DemoPluginWork", "WARNING", naive)
_instance_id, _level, persisted_expiry = writes[0]
assert persisted_expiry == naive.replace(tzinfo=timezone.utc)
override = get_plugin_instance_log_level_override("DemoPluginWork")
assert override is not None
assert override[1] == persisted_expiry
def test_set_level_on_host_uses_plugin_id_as_instance_id():
"""本体自身不需要实例行也能设置覆盖,实例 ID 就是插件 ID。"""
writes: list = []
control = _control(instances={}, writes=writes)
control.set_level("DemoPlugin", "DemoPlugin", "ERROR")
assert writes == [("DemoPlugin", "ERROR", None)]
assert get_plugin_instance_log_level_override("DemoPlugin") == ("ERROR", None)