日志凭空消失？Filter 顺序错了——Dubbo 一个 order 值让 ExceptionFilter 成了摆设

场景：Provider 端 SecurityFilter 拦截了非法请求，返回了错误——但 ExceptionFilter 没写那行日志 路径：ProtocolFilterWrapper.buildInvokerChain() → ActivateComparator → FilterNode.invoke() → ExceptionFilter.onResponse()

【遗迹】SecurityFilter 拦了请求，ExceptionFilter 没日志

上篇讲了 Dubbo 版本升级导致 Listener 注册了两次的问题，这篇来看 filter 链顺序引起的一个更隐蔽的问题：日志凭空消失。

现象：Consumer 收到了"拒绝访问"，Provider 没日志

一个自定义 SecurityFilter 负责校验调用方 IP 白名单。非法请求进来，Consumer 收到了错误响应——但 Provider 日志里 ExceptionFilter 那行 logger.error 就是不出现。

Dubbo（2.7.23）配置：

<dubbo:provider filter="securityFilter,accesslog"/>

accesslog 配置正确，logback 级别也是 DEBUG。手工 telnet 调接口确认异常返回了——但 ExceptionFilter 就是没动笔。

问题代码初现：SecurityFilter 返回了干净 Result

翻到 SecurityFilter 的实现，看到了问题所在：

public Result invoke(Invoker<?> invoker, Invocation inv) {
    if (!isAllowed(inv)) {
        // ← 直接返回了一个没有异常的普通 Result
        return AsyncRpcResult.newDefaultAsyncResult(inv);
    }
    return invoker.invoke(inv);
}

它返回了一个不带异常的 Result。异常被"吞"了——框架层面没有报错，Consumer 能拿到响应体，但 ExceptionFilter 的 onResponse() 看不到异常信息。

转向源码：ExceptionFilter 确实有 logger.error

检查 ExceptionFilter 源码（Dubbo 2.7.23）的第 79 行：

logger.error("Got unchecked and undeclared exception which called by "
    + RpcContext.getContext().getRemoteHost()
    + ". service: " + invoker.getInterface().getName()
    + ", method: " + invocation.getMethodName()
    + ", exception: " + exception.getClass().getName()
    + ": " + exception.getMessage(), exception);

代码写死了 logger.error，为什么就是不走？两种可能：filter 没被加载，或者异常根本没走到它这里。

【发掘】① 构建 filter 链：ProtocolFilterWrapper.buildInvokerChain()

Layer 1: 构建入口——哪种协议都会走这

Provider 被调用时，Dubbo 通过 ProtocolFilterWrapper.export() 在真实 Invoker 外面包一层 filter 链（ProtocolFilterWrapper.java#L51-L63）：

private static <T> Invoker<T> buildInvokerChain(final Invoker<T> invoker, String key, String group) {
    Invoker<T> last = invoker;
    List<Filter> filters = ExtensionLoader.getExtensionLoader(Filter.class)
        .getActivateExtension(invoker.getUrl(), key, group);

    if (!filters.isEmpty()) {
        for (int i = filters.size() - 1; i >= 0; i--) {
            final Filter filter = filters.get(i);
            last = new FilterNode<T>(invoker, last, filter);
        }
    }
    return last;
}

Layer 2: ActivateComparator 决定 filter 内外顺序

getActivateExtension 返回按 ActivateComparator 升序排列的 filter 列表——order 小的在前，order 大的在后。

index 0: ContextFilter          (order=Integer.MIN_VALUE)
index 1: ClassLoaderFilter      (order=0)
index 2: ExceptionFilter        (order=0)
...
index n: SecurityFilter         (order=100)

Layer 3: 从后往前遍历——第一个 filter 在最外层

buildInvokerChain 从列表末尾开始遍历。排在前面的 filter（order 小）成为最外层节点：

最外层 ← ContextFilter(0) → ... → ExceptionFilter(0) → ... → SecurityFilter(100) → 真实 Invoker

order 小的在外层，order 大的在内层。SecurityFilter（order=100）在最内层，ExceptionFilter（order=0）在 SecurityFilter 外层。

这个顺序决定了一切：RPC 调用从外层流向内层到达真实 Invoker，异常和结果从内层流回外层。SecurityFilter 在内层意味着——它先拿到结果，它有选择权决定"向上层返回什么"。

【发掘】② FilterNode 回调路径：ExceptionFilter 的"信息源"是上游喂给它的

Layer 1: 每个 FilterNode 独立管理回调

每个 FilterNode 在 invoke() 中处理 Listener 回调（FilterNode.java#L58-L105）。源码见截图。

Layer 2: ExceptionFilter 的信任模型——它信任上游如实传递异常

ExceptionFilter 实现了 Filter.Listener。它的 invoke() 纯透传，真正的异常感知在 onResponse() 中（同见截图）：

public void onResponse(Result appResponse, Invoker<?> invoker, Invocation invocation) {
    if (appResponse.hasException() && GenericService.class != invoker.getInterface()) {
        // 只日志未在接口签名中声明的非受检异常
        ...
        logger.error("Got unchecked and undeclared exception...", exception);
    }
}

这里有一个重要的设计假设：ExceptionFilter 信任上游 filter（即内层 filter）会如实把异常状态填进 Result。appResponse.hasException() 为 true 的前提是——上游 filter 在返回 Result 之前确实把异常放进去了。

换句话说，ExceptionFilter 没有"主动侦查异常"的能力，它是被动接收的。上游给它什么结果，它就信什么。

Layer 3: 调用链——异常从内向外，SecurityFilter 最先决定"给什么"

调用顺序：

ContextFilter.invoke()
  → ClassLoaderFilter.invoke()
    → ExceptionFilter.invoke()
      → ...
        → SecurityFilter.invoke()
          → invoker.invoke()

SecurityFilter 在内层最先拿到真实结果。它有两个选择： - 如实传播：把真实异常的 Result 往上抛 - 消化掉：自己构造一个干净的 Result 返回

问题代码走的是第二条路——返回了不带异常的 Result。ExceptionFilter 拿到这个干净 Result，appResponse.hasException() 为 false，logger.error 不执行。

这不是 ExceptionFilter 不工作——是它压根没收到异常信号。

【解读】为什么 ExceptionFilter 不日志 + 怎么修

Layer 1: 因果链——SecurityFilter 在内层做了"无害化处理"

SecurityFilter (order=100) 在内层拦截非法请求
  → 返回 AsyncRpcResult.newDefaultAsyncResult(inv)  ← 不含异常
    → 异常不传播到外层
      → ExceptionFilter.onResponse() 收到 clean Result
        → appResponse.hasException() = false
          → logger.error 不执行
            → 日志凭空消失

Layer 2: 这不是 ExceptionFilter 的 bug——是信任模型被打破了

ExceptionFilter 的设计哲学是"被动感知"——它相信上游 filter 会把异常如实传递到 Result 里。这个信任基于一条隐含规则：每个 filter 要么通过 invoker.invoke() 传播异常，要么把异常塞进 Result 再返回。

SecurityFilter 违反的是这条规则——它既没有 invoker.invoke()（因为被拦截了），也没有把异常塞进 Result。它返回了一个"看起来正常"的 Result，从 ExceptionFilter 的视角看，这次调用一切正常。

"一个 filter 有 logger.error 不代表它每次都能输出——它依赖上游 filter 先把异常传到它这里。"

Layer 3: 修复方案——让 SecurityFilter 如实传递异常

方案 A（推荐）：拦截后把异常设进 Result：

public Result invoke(Invoker<?> invoker, Invocation inv) {
    if (!isAllowed(inv)) {
        return AsyncRpcResult.newDefaultAsyncResult(
            new RpcException("Access denied: " + inv.getMethodName()), inv);
    }
    return invoker.invoke(inv);
}

RpcException 是未在接口签名中声明的非受检异常 → ExceptionFilter.onResponse() 看到 hasException=true → 执行 logger.error。

方案 B：SecurityFilter 自行日志：

public Result invoke(Invoker<?> invoker, Invocation inv) {
    if (!isAllowed(inv)) {
        log.warn("Access denied: {}", inv);
        return invoker.invoke(inv);
    }
    return invoker.invoke(inv);
}

方案 B 的问题在于：如果多个 filter 都有类似的"自己处理不留痕迹"的逻辑，异常信息就分散在各处，无法统一归集到 ExceptionFilter。

【收获】排查锚点

下次遇到 Provider 端异常没被 ExceptionFilter 日志时：

1. 确认异常是否到达 ExceptionFilter：查看 ExceptionFilter.onResponse() 收到的 appResponse 是否包含异常
2. 没到达：从内到外检查各 filter 的 invoke() 返回的 Result 是否如实传递了异常状态。AsyncRpcResult.newDefaultAsyncResult(inv) 这种调用是"吞异常"的常见信号
3. Dubbo（2.7.23）filter 排序规则：@Activate(order) 升序。外层 order 小，内层 order 大。自定义 filter 的 order 决定它在 ExceptionFilter 的哪一侧

一个 filter 有 logger.error 不代表它每次都能输出——它依赖上游 filter 先把异常传到它这里。

下篇我们聊 Dubbo 服务版本管理不善导致灰度失败。