腾讯 tRPC-Go 教学——（5）filter、context 和日志组件

本文咱们来介绍一下在 tRPC 中的 filter 机制、context 用法，以及在相关机制上可以实现的 tracing log 能力。

说实话，这一部份是我个人最不喜欢的 tRPC 的实现模式，不过这不妨碍咱们使用它——只要把它封装成让人更为舒服的模式也未尝不可。

---

系列文章

• 腾讯 tRPC-Go 教学——（1）搭建服务
• 腾讯 tRPC-Go 教学——（2）trpc HTTP 能力
• 腾讯 tRPC-Go 教学——（3）微服务间调用
• 腾讯 tRPC-Go 教学——（4）tRPC 组件生态和使用
• 腾讯 tRPC-Go 教学——（5）filter、context 和日志组件
• 腾讯 tRPC-Go 教学——（6）服务发现
• 腾讯 tRPC-Go 教学——（7）服务配置和指标上报
• …… 还会有更多，敬请期待 ……

---

tracelog 代码简介

本文所涉及的内容，都可以使用笔者的一个 tracelog package 来作辅助讲解。这个包所提供的功能有：

1. 基于 tRPC context 和 message 机制 (下文说明)，在日志中包含 trace ID 信息便于跟踪一个调用链
2. 基于 tRPC filter 机制，跨微服务传递 trace ID 并自动实现 1
3. 通过日志记录每次主调和被调的整体情况

具体的实现方法，本文放在最后，等讲完涉及的 tRPC 机制之后再作说明。

---

filter 机制

在 gRPC 中，实现了拦截器 interceptor 功能；类似的在著名的 HTTP 框架 gin 中，也提供了中间件模式。这两种机制的功能非常类似，都是在作为 server 时收到请求、以及作为 client 时发送请求时，优先对数据进行一些处理、检查等逻辑，非常适合用来做一些非业务逻辑，比如：

• 接口鉴权
• 日志记录
• 监控上报
• ……

在 tRPC 中，类似的机制被称为 filter 过滤器 / 拦截器。在 gRPC 中 interceptor 有四种，但 tRPC 中简化为 server filter 和 client filter 两种。

我们可以参考 tracelog filter.go 文件的 RegisterTraceLogFilter 函数。该函数向 tRPC 框架注册了一个名为 tracelog (参见 tracelog.FilterName 常量) 的 filter，包含 server filter 和 client filter。

函数格式

其中 server filter 回调的格式为:

func(ctx context.Context, req any, next filter.ServerHandleFunc) (rsp any, err error)

而 client filter 为:

func(ctx context.Context, req, rsp any, next filter.ClientHandleFunc) error

实现

在 filter 函数中，我们可以撰写代码观察当前的调用情况。不论是 server 还是 client filter 函数，都包含一个 next 参数。类似于 gRPC 的 interceptor 机制，tRPC 也是使用类似于堆栈形式组织各 filter 的，对于每一个 filter 函数，应当将 next 视作真正的业务处理逻辑。在 next 之前处理业务前置逻辑，在 next 之后撰写业务后置逻辑。

比如最简单的例子——打印一下耗时日志:

func clientFilter(ctx context.Context, req, rsp any, next filter.ClientHandleFunc) error {
    start := time.Now()
    err := next(ctx, req, rsp)
    log.DebugContextf(ctx, "ela: %v, err: %v", time.Since(start), err)
    return err
}

filter.Register 函数所传递的两个 filter 函数均不应为空，如果 filter 逻辑就是透传即可，那么就简单实现:

func emptyServerFilter(ctx context.Context, req any, next filter.ServerHandleFunc) (any, error) {
    return next(ctx, req)
}

tRPC 也内置了一些常用的 filter，导入方式为:

import _ "trpc.group/trpc-go/trpc-filter/$(filter_name)"

实际的仓库地址为: github.com/trpc-ecosystem/go-filter

其中我们在业务中必备的 filter 是 recovery，防止业务逻辑 panic 导致服务重启。其他的比如 debuglog 和 validation 我们也用，但相对少。读者可以查阅文档后再选用。

filter 配置

可以看到，filter 分 server 侧和 client 侧。首先在代码中需要导入相关的包，从而在二进制中支持相关能力。目前大部分官方默认的 filter 是通过 init 函数的方式注册到 trpc 框架中的。

让我们以前文给出的几个服务作为例子，配置方式是在 trpc_go.yaml 的 server 和 client 侧各有一个名为 filter 的字符串数组类型的字段，我们可以将 filter 按名称配置在此处，分别对应 server filter 和 client filter，此处的配置对所有的 server / client 生效。请注意，filter 配置的顺序也会影响 trpc 框架调用 filter 的顺序。

---

context 和 "message"

从 Go 1.13 版开始，以 net/http 包的 NewRequestWithContext 函数为标志，开始全面支持 context 机制。gRPC 很快跟进，在所有 client 和 server 端的实现上，均包含 ctx 参数。作为后浪的 tRPC，也继承了这一特性。

超时控制

在 tRPC 中有多个超时配置。我们以之前的文章中提过的 http-auth-server 的 trpc_go.yaml 文件为例:

server:
  timeout: 2000
  service:
    - name: demo.httpauth.Auth
      nic: eth0
      port: 8001
      network: tcp
      protocol: http
      timeout: 1800

client:
  timeout: 3000
  service:
    - name: demo.account.User
      target: ip://127.0.0.1:8002
      network: tcp
      protocol: trpc
      timeout: 1000

在上述配置文件中的超时时间单位均为毫秒，分别有:

配置项	说明
server.service[n].timeout	具体 server 端的处理超时时间
server.timeout	当上一配置缺失时，所对应的缺省超时时间
client.service[n].timeout	发起一个 client 调用的超时时间
client.timeout	当上一配置缺失时，所对应的缺省超时时间

其次，下文中会提及 tRPC 的 metadata，而 tRPC 发起调用的时候，超时时间也会通过 metadata 的形式往下进一步传递。如果你的上游服务也是 tRPC 的话，那么要注意：超时时间还可能受到上游的限制。

此外，开发者也可以在代码中显式地为 context 设置一个超时时间，比如通过 WithTimeout 和 WithDeadline 函数，获得一个附带超时时间的 context，传递给 tRPC 框架用于发起主调。

这么多的超时时间，到底取哪一个呢？

• 答：tRPC 框架在调用 server 端业务代码，以及发起 client 主调时，均会选择上述超时时间中最短的一个。

codec.Msg

在 tRPC 中对 context 的使用逻辑，请参见代码的 codec 包实现。tRPC 使用 codec 包，提供了扩展任意第三方编码格式的能力。

如果读者需要实现除了默认支持的几种协议之外的其他编解码格式（比如腾讯 tars 所使用的 jce），可以阅读相关的 README 并进行实现。不过对于本文而言，我们更关注 tRPC 使用 message 功能所提供的更多能力。所谓的 "message"，指的是 codec.Msg 接口类型，读者可以查看这个接口的实现。

正如前文所述，tRPC 的所有 server 端方法中，第一个函数均为 context.Context 类型，而 tRPC 基于 context 的 WithValue 方法，内置了 codec.Msg 类型数据。只要你的 server 方法是通过 tRPC 框架调用的，那么开发者均可以使用 codec.EnsureMessage 函数，从 context 中提取出 Msg 实例。

Msg 接口的功能很多，读者可以一一了解。本文我们只介绍 Msg 的其中几个最常用的功能：

• metadata
• 超时机制
• 日志器和 tracing

---

日志

在 tRPC 中，日志的 tracing（跟踪）主要是通过在写入日志时，额外添加若干的信息。tRPC 的 log 底层呢是使用 zap 来实现的，不过 zap 虽然是结构化的日志，但是 tRPC 暴露出来的实际上更多的是非结构化的日志接口。

功能

以 INFO 级别为例，tRPC 有四种日志函数格式:

log.Info(xxx, xxx...)
log.Infof("format", xxx...)
log.InfoContext(ctx, xxx, xxx...)
log.InfoContextf(ctx, "format", xxx...)

其中 log.Info 的输出效果类似于 fmt.Print 函数，而 log.Infof 则类似于 fmt.Printf。而带 ctx 参数的另外两个函数，则可以在前面两个日志函数的基础上，输出在 ctx 中携带的一些额外信息。往往我们可以在 ctx 中给 tRPC 的日志器携带 tracing 数据，此时利用带 ctx 的日志函数就可以打印出这些数据了。

至于如何携带信息，我们在本文最后关于 tracelog 的实现中再作说明。

Fatal 级别日志

在 tRPC 中，日志的级别从低到高分别是: TRACE、DEBUG、INFO、WARN、ERROR、FATAL。其中 trace 级别在实际业务中非常少用。

Fatal 级别的日志比较特殊，它会先完成日志的输出，然后再退出服务。如果在业务中遇到了某些导致服务无法运行下去的情况，我们不使用 panic 函数，而是使用 log.Fatal 系列调用，保留足够的现场信息之后再退出服务。

配置

tRPC 日志的 官方文档，个人觉得是一众 tRPC 文档中最详尽和清晰的文档之一了。简单而言，就是开发者只要配置 trpc_go.yaml 中的 plugins.log.default 中的相关字段就可以了。我个人常用的配置如下：

plugins:
  log:
    default:
      - writer: console
        level: fatal       # 标准输出我一般就不打日志了, 只保留严重异常
        formatter: console
      - writer: file
        level: debug       # 本地文件的日志级别看情况, 调试 / 测试用 debug, 正常线上环境用 info, 如果日志量太大则使用 warn 或 error
        formatter: json    # 文件日志我喜欢用 JSON, 便于各种日志采集器采集
        formatter_config:  # 格式化配置
          time_fmt: 2006-01-02 15:04:05  # 日期格式化, 与 go time 的格式化格式相同
          time_key: time   # 日志时间字段名称，不填默认"T"，填 "none" 可禁用此字段
          level_key: level # 日志级别字段名称，不填默认"L"，填 "none" 可禁用此字段
          name_key: none   # 日志名称字段名称，不填默认"N"，填 "none" 可禁用此字段
          caller_key: caller   # 日志调用方字段名称，不填默认"C"，填 "none" 可禁用此字段
          message_key: message # 日志消息体字段名称，不填默认"M"，填 "none" 可禁用此字段
          stacktrace_key: stack_trace  # 日志堆栈字段名称，不填默认"S"，填 "none" 可禁用此字段
        writer_config:
          log_path: ./log/   # 表示日志放在哪个目录下
          filename: trpc.log # 表示日志文件的基础名称
          write_mode: 2      # 日志写入模式，1-同步，2-异步，3-极速 (异步丢弃), 不配置默认异步模式
          roll_type: size    # 文件滚动类型，time 为按时间滚动, size 表示按文件大小滚动
          max_size: 1000     # 单位: MB
          max_backups: 10    # 最大日志文件数, 超出则自动删除

更详细的字段说明请参照 官方文档。

---

metadata

在 gRPC 中，通过 incoming metadata 和 outgoing metadata 的机制，可以在请求 / 响应包体数据之外，额外传输与业务不直接相关的元数据。

在 tRPC 中，则使用 server metadata 的机制进行传递（还有一个 client metadata，但是笔者没有完全把握其日常用法，就暂时不讲了）。tRPC 的 metadata 也是基于 codec.Msg 接口进行封装的，但是业务开发者可以不需要太关注这个 feature，感兴趣的话再仔细研究就可以了。

实际应用中，metadata 一般是用来承载非业务数据，比如说可观测性参数、数据埋点、用户画像、标签、染色信息等等，而不是具体某个业务的逻辑数据。

个人不建议在业务逻辑中直接操作 metadata，业务代码专注做业务逻辑就行了。至于 metadata 的操作方式，可以通过 filter 机制来实现。只要上下游都是 trpc，那么 metadata 都能够很顺畅地传输。

---

tracelog 的实现逻辑

上面我们了解完了基础知识，可能读者还是觉得有点懵。没关系，让我们来看看全文作为实际例子的 tracelog 是如何实现的。笔者的这个 tracelog 工具，思路借鉴了我所在团队所开发的的一个同名 filter，但是在实现上完全不同。

trace ID

在 tracelog 中实现 trace ID 的逻辑可参见 tracelog.go 文件。笔者将 trace ID 视为一组堆栈式的字段，每一级栈可以一层一层地追加 trace ID，从而在不同高度或层面上进行 tracing——这就是在设计理念上与笔者所在团队的实现完全不同的一个点，这种模式非常适合单体服务，这是另一个大课题了，笔者以后再讲哈。

至于如何将自定义的 trace ID 添加到日志器中，请读者参考笔者的 cloneCtxAndGenerateLog() 函数即可。从这个函数中可以看到，每当添加一个 tracing 字段的时候，tRPC 会新建一个 logger。这也是笔者认为不太妥当的一点：这个模式太重了。但是框架如此，也没办法。

server filter

tracelog 的 filter 代码请参见 filter.go。让我们先来看一下 server filter，该 filter 的功能有两个：

1. 如果有的话，从 metadata 中提取出 trace ID；如果没有的话，用雪花算法生成一个并存入 ctx 中
2. 在日志中打印出 server 端执行情况，包括入参、header、metadata、响应、错误等信息。

其中 1，调用的是前文提到的 Msg 类型的 ServerMetaData 来获得 metadata。

至于 2，请读者实际看 函数实现 更加直观。

client filter

client 实现的逻辑其实也跟 server 侧类似：

1. 如果有 trace ID，则放入 metadata
2. 在日志中打印出 client 端执行情况，包括入参、header、metadata、响应、错误等信息。

使用

我们参照前文的说明，在 配置 中加上 tracelog filter 以及日志相关配置。前面我们提到的 http-auth-server 和 user 两个服务都配置上。然后，按照之前我们提到的方法启动两个服务。

然后我们发送命令: curl '127.0.0.1:8001/demo/auth/Login?username=amc'。

因为没有指定密码，所以我们还是正常获得错误响应: {"err_code":404,"err_msg":"密码错误"}。

错误不重要，本文我们要看的是日志。我们来看看在这个配置下自动生成的日志文件: log/trpc.log。我们看 http-auth-server 的日志文件。可以看到，文件的每一行就是一个 JSON 数据。我们取刚才的请求产生的日志来看：

{"level":"INFO","time":"2024-03-04 02:19:28","caller":"server/service.go:167","message":"process:1016, http service:demo.httpauth.Auth launch success, tcp:127.0.0.1:8001, serving ..."}
{"level":"DEBUG","time":"2024-03-04 02:19:32","caller":"tracelog/filter.go:107","message":"{\"callee\":\"unknown\",\"http_req\":&{GET /demo/auth/Login?username=amc HTTP/1.1 1 1 map[Accept:[*/*] User-Agent:[curl/7.68.0]] {} <nil> 0 [] false 127.0.0.1:8001 map[] map[] <nil> map[] 127.0.0.1:39774 /demo/auth/Login?username=amc <nil> <nil> <nil> 0xc000279b00 <nil> [] map[]},\"server_metadata\":{\"trace_id_stack\":\"WyJjYXN5cDdwOXpiNCJd\"},\"req\":{\"username\":\"amc\"},\"req_type\":\"github.com/Andrew-M-C/trpc-go-demo/proto/user.*GetAccountByUserNameRequest\",\"rsp\":{\"err_msg\":\"success\",\"user_id\":\"1\",\"username\":\"amc\",\"password_hash\":\"8d969eef6ecad3c29a3a629280e686cf0c3f5d5a86aff3ca12020c923adc6c92\"},\"rsp_type\":\"github.com/Andrew-M-C/trpc-go-demo/proto/user.*GetAccountByUserNameResponse\",\"cost\":\"303.230671ms\"}","trace_id":"casyp7p9zb4"}
{"level":"DEBUG","time":"2024-03-04 02:19:32","caller":"service/http_auth_service.go:50","message":"请求的密码为: , 实际密码为 8d969eef6ecad3c29a3a629280e686cf0c3f5d5a86aff3ca12020c923adc6c92","trace_id":"casyp7p9zb4"}
{"level":"DEBUG","time":"2024-03-04 02:19:32","caller":"tracelog/filter.go:63","message":"{\"caller\":\"unknown\",\"http_req\":&{GET /demo/auth/Login?username=amc HTTP/1.1 1 1 map[Accept:[*/*] User-Agent:[curl/7.68.0]] {} <nil> 0 [] false 127.0.0.1:8001 map[] map[] <nil> map[] 127.0.0.1:39774 /demo/auth/Login?username=amc <nil> <nil> <nil> 0xc000279b00 <nil> [] map[]},\"server_metadata\":null,\"req\":{\"username\":\"amc\"},\"req_type\":\"github.com/Andrew-M-C/trpc-go-demo/proto/httpauth.*LoginRequest\",\"rsp\":{\"err_code\":404,\"err_msg\":\"密码错误\"},\"rsp_type\":\"github.com/Andrew-M-C/trpc-go-demo/proto/httpauth.*LoginResponse\",\"cost\":\"303.953412ms\"}","trace_id":"casyp7p9zb4"}

呃，太长了……取一条短的吧：

{"level":"DEBUG","time":"2024-03-04 02:19:32","caller":"service/http_auth_service.go:50","message":"请求的密码为: , 实际密码为 8d969eef6ecad3c29a3a629280e686cf0c3f5d5a86aff3ca12020c923adc6c92","trace_id":"casyp7p9zb4"}

可以清晰地看到，这一行日志输出了级别、时间、日志调用方信息、日志正文。此外，还有一个名为 trace_id 的字段，这就是 tracelog 自动生成并插入的效果。

---

下一步

本文相比前面的文章而言杂了很多，主要是涉及的内容相互强耦合，所以我把他们都放在同一篇文章里。推荐读者还是尽量动手实验把这些功能跑一遍，能够在实际开发中更好地理解 tPPC 的这些 feature，这是自己开发 filter 的重要基础知识。

下一篇文章我们来学习一下 tRPC 的名字服务、服务发现和寻址相关的功能吧。笔者还是会尽量把这系列坚持下去的💪

---

参考阅读

• gin 中间件
• gRPC(Go)教程(五)---拦截器Interceptor
• GRPC的metadata使用

---

本文章采用 知识共享署名-非商业性使用-相同方式共享 4.0 国际许可协议 进行许可。

原作者： amc，原文发布于腾讯云开发者社区，也是本人的博客。欢迎转载，但请注明出处。

原文标题：《腾讯 tRPC-Go 教学——（5）filter、context 和日志组件》

发布日期：2024-03-04

原文链接：https://cloud.tencent.com/developer/article/2393468。