Warp框架非匹配路由重复执行返回404 日志指标统计异常

问题现象 #

开发搭载Prometheus指标端点的Web服务器时发现指标统计失真：Warp框架会对每个进入的请求遍历执行所有已注册路由的逻辑，和当前请求不匹配的路由会返回404响应，导致挂载在路由上的日志打印、404计数逻辑被无效触发。

复现代码 #

最简复现代码如下：

extern crate warp;
extern crate tokio;
extern crate fern;

use warp::Filter;

#[tokio::main]
async fn main() {
    fern::Dispatch::new()
    .format(|out, message, record| {
    out.finish(format_args!(
        "{}[{}][{}] {}",
        chrono::Local::now().format("[%Y-%m-%d][%H:%M:%S]"),
        record.target(),
        record.level(),
        message
    ))
    })
    .level(log::LevelFilter::Debug)
    .chain(std::io::stdout())
    .apply();

    let hlog = warp::log("hlog");
    let glog = warp::log("glog");
    // GET /hello/warp => 200 OK with body "Hello, warp!"
    let hello = warp::path!("hello" / String)
        .map(|name| format!("Hello, {}!", name))
        .with(hlog);
        
    let goodbye = warp::path!("goodbye")
        .map(|| format!("goodbye"))
        .with(glog);

    let routes = hello.or(goodbye);
    
    warp::serve(routes)
        .run(([127, 0, 0, 1], 8080))
        .await;
}

访问localhost:8080/goodbye路径时，绑定在/hello路由上的hlog日志组件也会输出404响应的日志，日志输出如下：

[2022-06-27][18:57:59][warp::server][INFO] Server::run; addr=127.0.0.1:8080
[2022-06-27][18:57:59][warp::server][INFO] listening on http://127.0.0.1:8080
[2022-06-27][18:58:04][hyper::proto::h1::io][DEBUG] parsed 12 headers
[2022-06-27][18:58:04][hyper::proto::h1::conn][DEBUG] incoming body is empty
[2022-06-27][18:58:04][hlog][INFO] 127.0.0.1:62698 "GET /goodbye HTTP/1.1" 404 "-" "Mozilla/5.0 (Windows NT 10.0; rv:91.0) Gecko/20100101 Firefox/91.0" 68µs
[2022-06-27][18:58:04][glog][INFO] 127.0.0.1:62698 "GET /goodbye HTTP/1.1" 200 "-" "Mozilla/5.0 (Windows NT 10.0; rv:91.0) Gecko/20100101 Firefox/91.0" 25.3µs
[2022-06-27][18:58:04][hyper::proto::h1::io][DEBUG] flushed 123 bytes
[2022-06-27][18:58:04][hyper::proto::h1::io][DEBUG] parsed 11 headers
[2022-06-27][18:58:04][hyper::proto::h1::conn][DEBUG] incoming body is empty
[2022-06-27][18:58:04][hyper::server::server::new_svc][DEBUG] connection error: connection closed before message completed

如果在.with()方法中挂载404响应计数的Prometheus逻辑，每个被路由正常匹配的合法请求，都会同时触发所有其他未匹配路由的404计数，导致统计结果完全失真。

根因说明 #

Warp的Filter::or组合逻辑是顺序尝试匹配路由：前一个路由返回rejection（路径/方法不匹配）时，会自动把请求传给下一个路由继续尝试。如果把日志、指标中间件挂载在单个子路由内部，只要请求进入过该路由的处理流程，哪怕最后因为不匹配返回rejection，中间件也会被执行，这就是无效日志、错误计数的来源。

解决方案 #

• 通用日志、全局指标中间件统一挂载到所有路由组合完成后的最外层，不要绑定在单个子路由上。这种写法下中间件只会在最终路由匹配完成、确定实际响应结果的时候执行，不会捕获路由匹配过程中产生的临时404 rejection。示例写法：

  // 先定义业务路由，不要在单个路由上挂日志/指标
  let hello = warp::path!("hello" / String)
      .map(|name| format!("Hello, {}!", name));
  let goodbye = warp::path!("goodbye")
      .map(|| format!("goodbye"));
  // 组合所有业务路由
  let routes = hello.or(goodbye);
  // 最后统一在最外层挂载日志、Prometheus指标中间件
  let routes = routes.with(warp::log("access_log"));
  // 自定义Prometheus指标中间件也挂在这里
  

• 如果需要按路由分维度做独立的日志、指标统计，不要直接用with把中间件挂在未做匹配兜底的路由上，要在路由确定匹配成功后的逻辑（map/and_then处理块）里做埋点，此时路由已经匹配完成，不会统计到匹配阶段的临时拒绝。
• Prometheus指标采集场景可以直接使用成熟的warp指标中间件实现，这类实现默认挂载在路由最外层，会自动识别最终匹配的路由路径、响应状态码，不会把路由遍历过程中的临时rejection计入统计。

内容的提问来源于stack exchange，提问作者myaple