3、第一个中间件：编写简单的日志中间件、理解中间件链、defer在中间件中的使用

好，咱们今天来动手写第一个中间件。

说实话，很多初学者一上来就被「中间件」这个词唬住了。其实没那么玄乎。说白了，中间件就是一个函数，它在请求到达你的业务逻辑之前，或者响应返回给客户端之前，帮你干点额外的事。

我个人习惯把中间件想象成「流水线上的检查员」。每个检查员只负责一件事，比如记日志、做鉴权、打点统计。它们排成一排，依次处理请求。这就是中间件链。

3.1 先写一个最简单的日志中间件

咱们用 Go 标准库 net/http 来演示。先看一个最朴素的版本：

package main

import (
    "fmt"
    "log"
    "net/http"
    "time"
)

func loggingMiddleware(next http.Handler) http.Handler {
    return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        start := time.Now()
        log.Printf("[%s] %s %s", r.Method, r.RequestURI, time.Since(start))
        next.ServeHTTP(w, r)
    })
}

func helloHandler(w http.ResponseWriter, r *http.Request) {
    fmt.Fprintf(w, "Hello, World!")
}

func main() {
    mux := http.NewServeMux()
    mux.HandleFunc("/", helloHandler)

    wrappedMux := loggingMiddleware(mux)
    http.ListenAndServe(":8080", wrappedMux)
}

你看，loggingMiddleware 接收一个 http.Handler，返回一个新的 http.Handler。它内部先记日志，再调用 next.ServeHTTP 把控制权交给下一个处理器。

嗯，这里要注意：time.Since(start) 放在日志里其实没意义，因为请求还没处理完。我故意这么写，是想引出下一个话题——defer。

小提示： 如果你只是想记录请求开始的时间，上面的写法没问题。但如果你想记录请求处理的总耗时，就得用 defer。

3.2 用 defer 精确记录耗时

为什么会这样？因为 next.ServeHTTP(w, r) 执行完之后，控制权才回到中间件函数。所以正确的做法是：

func loggingMiddleware(next http.Handler) http.Handler {
    return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        start := time.Now()
        defer func() {
            log.Printf("[%s] %s took %v", r.Method, r.RequestURI, time.Since(start))
        }()
        next.ServeHTTP(w, r)
    })
}

我在项目中遇到过好几次这样的坑。一开始图省事，把日志写在 next.ServeHTTP 前面，结果发现耗时永远是 0。你想想看，time.Since(start) 在 next 还没执行时就计算了，当然不对。

defer 在这里的作用，就是把日志记录延迟到函数返回前一刻执行。这时候 next.ServeHTTP 已经跑完了，耗时才是真实的。

注意： defer 的执行顺序是「后进先出」。如果你在中间件里用了多个 defer，最后一个会最先执行。这在多层中间件嵌套时容易搞混，我建议每个中间件只用一个 defer。

3.3 理解中间件链

单个中间件好理解，那多个中间件怎么串起来？

说白了，就是「套娃」。每个中间件包裹下一个中间件，形成一个洋葱模型。请求从最外层进入，一层层向内传递，到达核心处理器后，响应再一层层向外返回。

看个例子：

func middlewareA(next http.Handler) http.Handler {
    return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        log.Println("A - before")
        next.ServeHTTP(w, r)
        log.Println("A - after")
    })
}

func middlewareB(next http.Handler) http.Handler {
    return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        log.Println("B - before")
        next.ServeHTTP(w, r)
        log.Println("B - after")
    })
}

func main() {
    mux := http.NewServeMux()
    mux.HandleFunc("/", helloHandler)

    // 链式调用：A 包裹 B，B 包裹 mux
    chain := middlewareA(middlewareB(mux))
    http.ListenAndServe(":8080", chain)
}

输出顺序是：

A - before
B - before
(处理器执行)
B - after
A - after

我曾经在写一个网关服务时，把中间件顺序搞反了。日志中间件放在了最里面，结果鉴权失败的错误日志全没记下来。嗯，从那以后我养成了一个习惯：先写日志，再写鉴权，最后写业务。

3.4 用表格总结中间件链的执行顺序

中间件 before 执行顺序 after 执行顺序
middlewareA 第1 最后
middlewareB 第2 第3
处理器 第3 —

你看，before 部分是从外到内，after 部分是从内到外。这就是洋葱模型的核心。

3.5 避坑指南：defer 在中间件中的陷阱

用 defer 记录耗时很方便，但有个坑：如果你在 defer 里捕获了 panic，那 next.ServeHTTP 抛出的异常会被你吃掉。

我曾经这样写过：

func recoveryMiddleware(next http.Handler) http.Handler {
    return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        defer func() {
            if err := recover(); err != nil {
                log.Printf("panic recovered: %v", err)
                http.Error(w, "Internal Server Error", 500)
            }
        }()
        next.ServeHTTP(w, r)
    })
}

这个中间件本身没问题。但如果你在日志中间件的 defer 里也加了 recover，而且顺序不对，就会导致 recovery 中间件永远收不到 panic。因为 defer 是后进先出，日志中间件的 defer 先执行，它把 panic 给 recover 了，recovery 中间件就不知道了。

核心原则： recovery 中间件一定要放在最外层（第一个被调用），这样它的 defer 最后执行，才能捕获到所有内层抛出的 panic。

3.6 动手实践：写一个带 defer 的日志中间件

来，咱们把今天学的串起来。写一个完整的日志中间件：

package main

import (
    "fmt"
    "log"
    "net/http"
    "time"
)

func loggingMiddleware(next http.Handler) http.Handler {
    return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        start := time.Now()
        defer func() {
            log.Printf("[%s] %s %s | %v", 
                r.Method, r.Host, r.URL.Path, time.Since(start))
        }()
        next.ServeHTTP(w, r)
    })
}

func main() {
    mux := http.NewServeMux()
    mux.HandleFunc("/", func(w http.ResponseWriter, r *http.Request) {
        // 模拟耗时操作
        time.Sleep(100 * time.Millisecond)
        fmt.Fprintf(w, "Hello, Middleware!")
    })

    wrapped := loggingMiddleware(mux)
    log.Println("Server starting on :8080")
    http.ListenAndServe(":8080", wrapped)
}

运行后访问 http://localhost:8080/，你会看到类似这样的日志：

2025/01/15 14:30:22 [GET] localhost:8080 / | 100.123ms

这个耗时是真实的，因为 defer 保证了它在 next.ServeHTTP 执行完之后才计算。

好了，今天的内容就到这里。你想想看，中间件其实没那么神秘，就是一个函数包裹另一个函数。加上 defer 之后，你可以在请求处理前后都做点事。下一节咱们会聊更高级的中间件模式，比如如何传递上下文、如何做超时控制。

公众号:蓝海资料掘金营，微信deep3321

← 上一章 📖 返回目录 下一章 →