用 Go 编写日志中间件的指南

这是关于如何为 Go Web 服务编写可扩展日志记录中间件的指南。

我收到了很多请求，要求向gorilla/mux添加内置记录器并扩展gorilla/handlers记录的内容，但它们很难分类。许多要求都是针对不同的事情，因为记录“什么”、记录多少以及使用哪个库并不是所有人都同意的。此外，特别是在mux的情况下，日志记录不是库的重点，编写您自己的日志记录“中间件”可能比您预期的更简单。

本指南中的模式可以扩展到任何 HTTP 中间件用例，包括身份验证和授权、指标、跟踪和 Web 安全。日志记录恰好是最常见的用例之一，并且是一个很好的例子。

为什么中间件有用？

中间件使我们能够分离关注点并编写可组合的应用程序，并且在微服务的世界中，允许特定组件的所有权更加清晰。

具体来说：

• 身份验证和授权（“authn”和“authz”）可以统一处理：我们可以将其与主要业务逻辑分开，和/或在整个组织中共享相同的 authn/authz 处理。将其分开可以使添加新的身份验证提供程序变得更容易，或者（重要的是）随着团队的发展更容易修复潜在的安全问题。
• 与 authn 和 authz 类似，我们可以为我们的应用程序定义一组可重用的日志记录、指标和跟踪中间件，这样跨服务和/或团队的故障排除就不会那么简单。
• 测试变得更简单，因为我们可以在每个组件周围划定更清晰的界限：请注意，集成测试对于端到端验证仍然很重要。

考虑到这一点，让我们看看在 Go 中定义“可重用”中间件实际上是如何工作的。

通用中间件接口

编写任何中间件时，重要的一件事是它与您选择的框架或特定于路由器的 API 松散耦合。处理程序应该可供任何使用 HTTP 的 Go 服务使用：如果团队 A 选择net/http，团队 B 选择gorilla/mux，并且团队 C 想要使用Twirp，那么我们的中间件不应该强制选择或被限制在特定框架内。Go 的 net/http 库定义了http.Handler接口，满足这一点可以轻松编写可移植的 HTTP 处理代码。唯一需要满足的方法http.Handler是ServeHTTP(http.ResponseWriter, *http.Request)- 并且具体http.HandlerFunc类型意味着您可以将具有匹配签名的任何类型转换为满足 的类型http.Handler。

例子：

func ExampleMiddleware(next http.Handler) http.Handler {
  // We wrap our anonymous function, and cast it to a http.HandlerFunc
  // Because our function signature matches ServeHTTP(w, r), this allows
  // our function (type) to implicitly satisify the http.Handler interface.
  return http.HandlerFunc(
    func(w http.ResponseWriter, r *http.Request) {
      // Logic before - reading request values, putting things into the
      // request context, performing authentication

      // Important that we call the 'next' handler in the chain. If we don't,
      // then request handling will stop here.
      next.ServeHTTP(w, r)
      // Logic after - useful for logging, metrics, etc.
      //
      // It's important that we don't use the ResponseWriter after we've called the
      // next handler: we may cause conflicts when trying to write the response
    }
  )
}

这实际上是我们想要构建的任何中间件的秘诀。每个中间件组件（这只是一个http.Handler实现！）都包装另一个中间件组件，执行它需要的任何工作，然后调用它通过next.ServeHTTP(w, r).如果我们需要在处理程序之间传递值，例如经过身份验证的用户的 ID，或者请求或跟踪 ID，我们可以使用Go 1.7 中引入的方法context.Context附加到*http.Requestvia 。*Request.Context()

中间件堆栈如下所示：

router := http.NewServeMux()
router.HandleFunc("/", indexHandler)

// Requests traverse LoggingMiddleware -> OtherMiddleware -> YetAnotherMiddleware -> final handler
configuredRouter := LoggingMiddleware(OtherMiddleware(YetAnotherMiddleware(router))))
log.Fatal(http.ListenAndServe(":8000", configuredRouter))

这看起来是可组合的（检查！），但是如果我们想注入依赖项或以其他方式自定义堆栈中每个处理程序的行为怎么办？

注入依赖项

在上面ExampleMiddleware，我们创建了一个简单的函数，它接受 ahttp.Handler并返回 a http.Handler。但是，如果我们想提供自己的记录器实现、注入其他配置和/或不依赖全局单例怎么办？让我们看一下如何实现这一目标，同时仍然让我们的中间件接受（和返回）http.Handler。

func NewExampleMiddleware(someThing string) func(http.Handler) http.Handler {
  return func(next http.Handler) http.Handler {
    fn := func(w http.ResponseWriter, r *http.Request) {
      // Logic here

      // Call the next handler
      next.ServeHTTP(w, r)
    }

    return http.HandlerFunc(fn)
  }
}

通过返回a，func(http.Handler) http.Handler我们可以使中间件的依赖关系更加清晰，并允许中间件的使用者根据自己的需求进行配置。在我们的日志记录示例中，我们希望将具有某些现有配置（例如服务名称和时间戳格式）的应用程序级记录器传递给我们的LoggingMiddleware，而不必复制粘贴它或以其他方式依赖于包全局变量，这使得我们的代码更难推理和测试。

代码：LoggingMiddleware

让我们利用上面学到的所有内容，使用一个记录以下内容的中间件函数：

• 请求方法及路径
• 使用我们自己的实现写入响应的状态代码

http.ResponseWriter

• （更多内容见下文）
• HTTP 请求和响应的持续时间 - 直到最后一个字节写入响应
• 允许我们从kit/log注入我们自己的

logger.Log

• 实例。

// request_logger.go
import (
  "net/http"
  "runtime/debug"
  "time"

  log "github.com/go-kit/kit/log"
)

// responseWriter is a minimal wrapper for http.ResponseWriter that allows the
// written HTTP status code to be captured for logging.
type responseWriter struct {
  http.ResponseWriter
  status      int
  wroteHeader bool
}

func wrapResponseWriter(w http.ResponseWriter) *responseWriter {
  return &responseWriter{ResponseWriter: w}
}

func (rw *responseWriter) Status() int {
  return rw.status
}

func (rw *responseWriter) WriteHeader(code int) {
  if rw.wroteHeader {
    return
  }

  rw.status = code
  rw.ResponseWriter.WriteHeader(code)
  rw.wroteHeader = true

  return
}

// LoggingMiddleware logs the incoming HTTP request & its duration.
func LoggingMiddleware(logger log.Logger) func(http.Handler) http.Handler {
  return func(next http.Handler) http.Handler {
    fn := func(w http.ResponseWriter, r *http.Request) {
      defer func() {
        if err := recover(); err != nil {
          w.WriteHeader(http.StatusInternalServerError)
          logger.Log(
            "err", err,
            "trace", debug.Stack(),
          )
        }
      }()

      start := time.Now()
      wrapped := wrapResponseWriter(w)
      next.ServeHTTP(wrapped, r)
      logger.Log(
        "status", wrapped.status,
        "method", r.Method,
        "path", r.URL.EscapedPath(),
        "duration", time.Since(start),
      )
    }

    return http.HandlerFunc(fn)
  }
}

审查：

• 我们实现自己的

responseWriter

• 类型来捕获响应的状态代码，允许我们记录它（因为在写入响应之前它是不知道的）。重要的是，我们不必重新实现 的每一个方法

http.ResponseWriter

• - 我们嵌入我们收到的方法，并且仅重写

Status() int

• 和方法，因此我们可以在和结构字段

WriteHeader(int)

• 中携带状态。

.status.wroteHeader

• http.HandlerFunc 将我们的返回类型转换为 http.HandlerFunc，这会自动使其满足

ServeHTTP

• 的方法

http.Handler

• 。
• 我们的记录器还记录恐慌（可选，但有用），因此我们也可以在日志系统中捕获它们。
• 因为我们直接注入

log.Logger

• - 我们可以配置它，并在测试期间模拟它。
• 调用

.Log()

• 允许我们传递我们需要的任何值 - 我们可能不想一次记录所有值，但它也很容易根据需要进行扩展。不存在“一刀切”的记录仪。

值得注意的是，我在这里使用kit/log，尽管您可以使用您喜欢的任何记录器，包括标准库 - 请注意，如果您沿着这条路走下去，您将失去结构化日志记录的好处。

一个完整的例子

LoggingMiddleware下面是一个完整的（可运行！）示例，使用我们之前从包中定义的版本elithrar/admission-control：

// server.go
package main

import (
  "fmt"
  stdlog "log"
  "net/http"
  "os"

  "github.com/elithrar/admission-control"
  log "github.com/go-kit/kit/log"
)

func myHandler(w http.ResponseWriter, r *http.Request) {
  fmt.Fprintln(w, "hello!")
}

func main() {
  router := http.NewServeMux()
  router.HandleFunc("/", myHandler)

  var logger log.Logger
  // Logfmt is a structured, key=val logging format that is easy to read and parse
  logger = log.NewLogfmtLogger(log.NewSyncWriter(os.Stderr))
  // Direct any attempts to use Go's log package to our structured logger
  stdlog.SetOutput(log.NewStdlibAdapter(logger))
  // Log the timestamp (in UTC) and the callsite (file + line number) of the logging
  // call for debugging in the future.
  logger = log.With(logger, "ts", log.DefaultTimestampUTC, "loc", log.DefaultCaller)

  // Create an instance of our LoggingMiddleware with our configured logger
  loggingMiddleware := admissioncontrol.LoggingMiddleware(logger)
  loggedRouter := loggingMiddleware(router)

  // Start our HTTP server
  if err := http.ListenAndServe(":8000", loggedRouter); err != nil {
    logger.Log("status", "fatal", "err", err)
    os.Exit(1)
  }
}

如果我们运行此服务器，然后对其发出请求，我们将看到日志行输出到 stderr：

$ go run server.go
    # Make a request with: curl localhost:8000/
    ts=2020-03-21T18:30:58.8816186Z loc=server.go:62 status=0 method=GET path=/ duration=7.6µs

如果我们想要记录更多信息 - 例如*Request.Host来自（例如跟踪 ID）的值或特定响应标头，我们可以通过在我们自己的中间件版本中根据需要*Request.Context()扩展调用来轻松实现这一点。logger.Log

概括

我们能够通过以下方式构建灵活的、可重用的中间件组件：

• 满足Go现有的

http.Handler

• 接口，允许我们的代码与底层框架选择松散耦合
• 返回闭包以注入我们的依赖项并避免全局（包级）配置
• 使用组合（当我们围绕

http.ResponseWriter

• 接口定义包装器时）来覆盖特定方法，就像我们对日志记录中间件所做的那样。

借此，您有望了解如何为身份验证中间件或计算状态代码和响应大小的指标中间件提供基础。

而且因为我们用作http.Handler基础，所以我们编写的中间件可以很容易地被其他人使用！

相当不错吧？

后记：日志、指标、跟踪

值得花点时间来定义“日志记录”的含义。日志记录是关于捕获（希望）结构化事件数据，日志有利于详细调查，但数量很大并且查询速度可能很慢。指标是定向的（例如：请求数、登录失败等），有利于监控趋势，但不能让您了解全貌。跟踪跟踪跨系统的请求或查询的生命周期。