Logger 中间件:输出格式与耗时怎么算

一行日志的构成

实测 · 本机执行输出

  logger.go(Gin v1.12.0):
     166 | // defaultLogFormatter is the default log format function Logger middleware uses.
     167 | var defaultLogFormatter = func(param LogFormatterParams) string {
     168 |     var statusColor, methodColor, resetColor, latencyColor string
     169 |     if param.IsOutputColor() {
     170 |         statusColor = param.StatusCodeColor()
     171 |         methodColor = param.MethodColor()
     172 |         resetColor = param.ResetColor()
     173 |         latencyColor = param.LatencyColor()
     174 |     }
     175 | 
     176 |     switch {
     177 |     case param.Latency > time.Minute:
     178 |         param.Latency = param.Latency.Truncate(time.Second * 10)
     179 |     case param.Latency > time.Second:
     180 |         param.Latency = param.Latency.Truncate(time.Millisecond * 10)
     181 |     case param.Latency > time.Millisecond:
     182 |         param.Latency = param.Latency.Truncate(time.Microsecond * 10)
     183 |     }
     184 | 
     185 |     return fmt.Sprintf("[GIN] %v |%s %3d %s|%s %8v %s| %15s |%s %-7s %s %#v\n%s",
     186 |         param.TimeStamp.Format("2006/01/02 - 15:04:05"),
     187 |         statusColor, param.StatusCode, resetColor,
     188 |         latencyColor, param.Latency, resetColor,
     189 |         param.ClientIP,
     190 |         methodColor, param.Method, resetColor,
     191 |         param.Path,
     192 |         param.ErrorMessage,
     193 |     )
     194 | }
     195 | 
    "[GIN] 2026/10/11 - 19:18:24 | 200 |      3µs |       192.0.2.1 | GET      \"/ok\""
    "[GIN] 2026/10/11 - 19:18:24 | 200 |    833ns |       192.0.2.1 | GET      \"/ok?token=SECRET&a=1\""
    "[GIN] 2026/10/11 - 19:18:25 | 200 |    1.23s |       192.0.2.1 | GET      \"/slow\""
    "[GIN] 2026/10/11 - 19:18:25 | 404 |     42ns |       192.0.2.1 | GET      \"/nope\""
    "[GIN] 2026/10/11 - 19:18:25 | 500 |  10.25µs |       192.0.2.1 | GET      \"/err\""
    "Error #01: 数据库超时"
    "[GIN] 2026/10/11 - 19:18:25 | 201 |     83ns |       192.0.2.1 | POST     \"/p\""
    "[GIN] 2026/10/11 - 19:18:25 | 404 |     42ns |       192.0.2.1 | GET      \"/中文/path with space\""
    "[GIN] 2026/10/11 - 19:18:25 | 404 |     83ns |       192.0.2.1 | DELETE   \"/ok\""

[GIN] 时间、状态码(%3d)、耗时(%8v,按量级截断)、客户端 IP(%15s)、方法(%-7s)、路径(%#v 带引号)和该请求里 Private 类型的错误。404、405 也会记录,因为 Logger 是全局中间件,在 404 的 handler 链里。

耗时的含义

实测 · 本机执行输出

    Logger 在前,slow 在后:
    "[GIN] 2026/10/11 - 19:18:26 | 200 |  51.62ms |       192.0.2.1 | GET      \"/x\""
    slow 在前,Logger 在后(slow 的 50ms 不被计入):
    "[GIN] 2026/10/11 - 19:18:26 | 200 | 13.166µs |       192.0.2.1 | GET      \"/x\""
    真实 HTTP 往返(含建立连接)客户端测得 1.04 ms;服务端日志里记录的是:
    "[GIN] 2026/10/11 - 19:18:26 | 200 | 77.709µs |       127.0.0.1 | GET      \"/x\""

起点是 Logger 自己开始运行,终点是 c.Next() 返回:Logger 之前的中间件不计入,建立连接、读取请求头、把响应字节真正送到客户端的时间也不计入。所以 Logger 要放在最外层(gin.Default() 就是这么放的),而且日志里的耗时不等于用户感受到的延迟。

颜色

实测 · 本机执行输出

    默认(buffer 不是终端):
    "[GIN] 2026/10/11 - 19:18:27 | 200 |  3.333µs |       192.0.2.1 | GET      \"/ok\""
    ForceConsoleColor:
    "[GIN] 2026/10/11 - 19:18:27 |\x1b[97;42m 200 \x1b[0m|\x1b[90;47m  1.708µs \x1b[0m|       192.0.2.1 |\x1b[97;44m GET     \x1b[0m \"/ok\""
    "[GIN] 2026/10/11 - 19:18:27 |\x1b[90;43m 404 \x1b[0m|\x1b[90;47m     42ns \x1b[0m|       192.0.2.1 |\x1b[97;44m GET     \x1b[0m \"/bad\""
    DisableConsoleColor:
    "[GIN] 2026/10/11 - 19:18:27 | 200 |    792ns |       192.0.2.1 | GET      \"/ok\""

是否上色由输出是不是终端决定(isatty),写到文件、buffer 时没有转义码;ForceConsoleColor 和 DisableConsoleColor 是全局开关。在容器里用 docker logs 看到乱码一般是因为被强制开了颜色。

配置项

实测 · 本机执行输出

    共 4 个请求,日志行数: 2
    "{\"t\":\"19:18:28\",\"status\":404,\"latency_us\":0,\"ip\":\"192.0.2.1\",\"method\":\"GET\",\"path\":\"/quiet/missing\",\"size\":-1,\"ua\":\"curl/8\",\"user\":<nil>}"
    "{\"t\":\"19:18:28\",\"status\":200,\"latency_us\":1,\"ip\":\"192.0.2.1\",\"method\":\"GET\",\"path\":\"/api\",\"size\":5,\"ua\":\"curl/8\",\"user\":alice}"

SkipPaths 精确匹配路径(健康检查),Skip 可以按任意条件跳过,SkipQueryString 避免把 API 密钥、令牌写进日志,Formatter 拿到完整的参数(含 Keys、BodySize、Request)可以输出 JSON。结构化日志需要的字段(请求 ID、用户)用 c.Set 存、在 Formatter 里取。

与 Recovery 的顺序

实测 · 本机执行输出

    Logger 在外、Recovery 在内(gin.Default 的顺序) → 响应状态 500,访问日志 1 行
    "[GIN] 2026/10/11 - 19:18:28 | 500 |   1.47ms |       192.0.2.1 | GET      \"/boom\""
    Recovery 在外、Logger 在内 → 响应状态 500,访问日志 0 行
    ""

日志代码在 c.Next() 之后,panic 会跳过它。Recovery 必须放在 Logger 的里面,这样 panic 先被 Recovery 接住并写成 500,Logger 再把这个 500 记下来;反过来 panic 的请求在访问日志里会消失。

开销

实测 · 本机执行输出

    第 1 轮
    无 Logger                           中位 23 ns/请求,0 allocs/请求
    Logger(io.Discard)                 中位 801 ns/请求,10 allocs/请求
    Logger(空 Formatter)                中位 280 ns/请求,2 allocs/请求
    第 2 轮
    无 Logger                           中位 23 ns/请求,0 allocs/请求
    Logger(io.Discard)                 中位 800 ns/请求,10 allocs/请求
    Logger(空 Formatter)                中位 280 ns/请求,2 allocs/请求

默认 Logger 约 800 ns / 请求、10 次分配,相对于真实服务的毫秒级耗时可以忽略;但对每秒几十万请求的空 handler(压测、基准)来说是主要开销。大头在格式化字符串,不在计时。

分步演示

Logger 中间件

本步的对象

本文用到的工具与边界

本机 macOS 27 arm64 / Go 1.27.1(brew)/ Gin v1.12.0(go.mod 里 require,源码在模块缓存里);用 go run / go test 直接编译运行,需要库时经代理从 proxy.golang.org 下载;HTTP 实验用 httptest 或本机回环端口(9700 以上);计时用 time.Now / testing.B,数字每次运行会有小幅抖动。日志输出到 bytes.Buffer;请求用 httptest 直接调用 ServeHTTP(客户端 IP 是 httptest 固定的 192.0.2.1),真实往返用 httptest.NewServer;开销用 testing.Benchmark 测 ServeHTTP + 丢弃输出的 writer,7 轮中位数,整个实验跑了两轮;其余每种情形各一次
没有验证:输出到真实终端时 isatty 的判断;输出到文件的并发写入(Logger 没有加锁,fmt.Fprint 对 *os.File 的并发安全性未测);反向代理后 ClientIP 的取值(见后面 ClientIP 一篇);gin.DefaultWriter 的修改;结构化日志库(zap、slog)的集成

下一篇 · GIN 46

Recovery:捕获 panic 之后做了什么,broken pipe 的特判