gRPC-Go基础（5）middleware

0. 简介

gRPC的middleware一般指的是gRPC-Go生态中的go-grpc-middleware，middleware主要体现在对拦截器的支持，目前官方实现的主要拦截器有以下几种。

Auth

grpc_auth - 可定制的auth中间件。

Logging

grpc_ctxtags - 将标签映射成上下文的库；
grpc_zap - 集成zap日志处理；
grpc_logrus - 集成logrus日志处理；
grpc_kit - 8集成go-kit/log日志处理；
grpc_grpc_logsettable - grpclog.LoggerV2的包装器，允许在运行时替换记录器（线程安全）。

Monitoring

grpc_prometheus? - 普罗米修斯的拦截器；
otgrpc? - OpenTracing 拦截器；
grpc_opentracing - OpenTracing 拦截器，支持流和处理程序返回的标签；
otelgrpc - OpenTelemetry 拦截器。

Client

grpc_retry - 通用的 gRPC 响应代码重试机制，客户端中间件。

Server

grpc_validator - 用于gRPC的.proto文件的请求参数校验；
grpc_recovery - 将panic转换为gRPC的error；
ratelimit - 自定义的限制器限制gRPC速率。

除了这些middleware，我们还可以实现定制的拦截器，实现自己的功能。下面我将简单介绍一下grpc_zap，然后介绍一下如何实现自己的拦截器。

1. grpc_zap日志插件

1.1 服务端

在服务端，插入grpc_zap的日志插件，基本代码如下：
go复制代码

// 创建一个zap.Logger对象
logger, err := zap.NewDevelopment()
if err != nil {
   log.Fatalf("failed to initialize zap logger: %v", err)
}

// 将grpc内部的打印logger替换为以上创建的logger
grpc_zap.ReplaceGrpcLoggerV2(logger)

// 新建gRPC的服务端实例
grpcServer := grpc.NewServer(
   grpc.StreamInterceptor(grpc_middleware.ChainStreamServer(
      grpc_zap.StreamServerInterceptor(logger),
   )),
   grpc.UnaryInterceptor(grpc_middleware.ChainUnaryServer(
      grpc_zap.UnaryServerInterceptor(logger),
   )),
)

在新建grpcServer过程中，传入一元和流式RPC的拦截器处理插件，其中集成了grpc_zap的一些插件，其代码如下：

// UnaryServerInterceptor returns a new unary server interceptors that adds zap.Logger to the context.
func UnaryServerInterceptor(logger *zap.Logger, opts ...Option) grpc.UnaryServerInterceptor {
   o := evaluateServerOpt(opts)
   return func(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (interface{}, error) {
      startTime := time.Now()

      newCtx := newLoggerForCall(ctx, logger, info.FullMethod, startTime, o.timestampFormat)

      resp, err := handler(newCtx, req)
      if !o.shouldLog(info.FullMethod, err) {
         return resp, err
      }
      code := o.codeFunc(err)
      level := o.levelFunc(code)
      duration := o.durationFunc(time.Since(startTime))

      o.messageFunc(newCtx, "finished unary call with code "+code.String(), level, code, err, duration)
      return resp, err
   }
}

其实以上代码主要完成了两件事，一个是通过newLoggerForCall将传入的logger集成到上下文中，另一个是在请求完成后打印此次请求的一些信息。

func newLoggerForCall(ctx context.Context, logger *zap.Logger, fullMethodString string, start time.Time, timestampFormat string) context.Context {
   var f []zapcore.Field
   f = append(f, zap.String("grpc.start_time", start.Format(timestampFormat)))
   if d, ok := ctx.Deadline(); ok {
      f = append(f, zap.String("grpc.request.deadline", d.Format(timestampFormat)))
   }
   callLog := logger.With(append(f, serverCallFields(fullMethodString)...)...)
   return ctxzap.ToContext(ctx, callLog)
}

一般而言，我们在一个服务进程中维持一份日志对象logger，保证日志打印等属性的一致性。

自定义日志
针对gRPC服务端的自定义日志，当我们选择设置拦截器之后，可以使用自己生成的logger直接打印，也可以选择ctxzap.Extract函数将我们传入拦截器的logger提取出来，这二者使用的是同一个对象，但是后者会包含更多的信息，并且更新了grpc_ctxtags信息。

// Extract takes the call-scoped Logger from grpc_zap middleware.
//
// It always returns a Logger that has all the grpc_ctxtags updated.
func Extract(ctx context.Context) *zap.Logger {
   l, ok := ctx.Value(ctxMarkerKey).(*ctxLogger)
   if !ok || l == nil {
      return nullLogger
   }
   // Add grpc_ctxtags tags metadata until now.
   fields := TagsToFields(ctx)
   // Add zap fields added until now.
   fields = append(fields, l.fields...)
   return l.logger.With(fields...)
}

gRPC内部日志
在gRPC的内部，日志会被默认输入到stderr，并且在未设置GRPC_GO_LOG_SEVERITY_LEVEL这个环境变量的情况下，只会输出error级别的日志，如果我们想替换其内部的logger，需要调用SetLoggerV2函数。

// SetLoggerV2 sets logger that is used in grpc to a V2 logger.
// Not mutex-protected, should be called before any gRPC functions.
func SetLoggerV2(l LoggerV2) {
   if _, ok := l.(*componentData); ok {
      panic("cannot use component logger as grpclog logger")
   }
   grpclog.Logger = l
   grpclog.DepthLogger, _ = l.(grpclog.DepthLoggerV2)
}

而在middleware中，提供了各个不同的日志体系对于SetLoggerV2函数的封装，譬如grpc_zap包提供的ReplaceGrpcLoggerV2，可以使用自定义的logger代替gRPC内部的默认logger。

// ReplaceGrpcLoggerV2 replaces the grpc_log.LoggerV2 with the provided logger.
// It should be called before any gRPC functions.
func ReplaceGrpcLoggerV2(logger *zap.Logger) {
   ReplaceGrpcLoggerV2WithVerbosity(logger, 0)
}

// ReplaceGrpcLoggerV2WithVerbosity replaces the grpc_.LoggerV2 with the provided logger and verbosity.
// It should be called before any gRPC functions.
func ReplaceGrpcLoggerV2WithVerbosity(logger *zap.Logger, verbosity int) {
   zgl := &zapGrpcLoggerV2{
      logger:    logger.With(SystemField, zap.Bool("grpc_log", true)),
      verbosity: verbosity,
   }
   grpclog.SetLoggerV2(zgl)
}

打印

2023-02-06T10:26:31.494+0800	INFO	zap/grpclogger.go:92	[core][Server #1] Server created	{"system": "grpc", "grpc_log": true}
2023-02-06T10:26:31.494+0800	INFO	zap/grpclogger.go:92	[core][Server #1 ListenSocket #2] ListenSocket created	{"system": "grpc", "grpc_log": true}
2023-02-06T10:26:56.141+0800	INFO	zap/grpclogger.go:92	[core]CPU time info is unavailable on non-linux environments.	{"system": "grpc", "grpc_log": true}
2023-02-06T10:26:57.153+0800	INFO	zap/options.go:212	finished unary call with code OK	{"grpc.start_time": "2023-02-06T10:26:56+08:00", "system": "grpc", "span.kind": "server", "grpc.service": "simplepb.Route", "grpc.method": "SimpleRoute", "grpc.code": "OK", "grpc.time_ms": 1001.357}
2023-02-06T10:26:57.158+0800	INFO	zap/grpclogger.go:92	[transport]transport: loopyWriter.run returning. connection error: desc = "transport is closing"	{"system": "grpc", "grpc_log": true}

以上日志，第四行是拦截器打印的，其他都是gRPC内部的日志打印。

1.2 客户端

客户端有关grpc_zap的拦截器使用很简单，只需要在连接服务器的时候带上选项即可。

logger, err := zap.NewDevelopment()
if err != nil {
   log.Fatalf("failed to initialize zap logger: %v", err)
}

// 连接服务器
conn, err := grpc.Dial(Address, grpc.WithInsecure(),
   grpc.WithUnaryInterceptor(grpc_middleware.ChainUnaryClient(grpc_zap.UnaryClientInterceptor(logger))),
   grpc.WithStreamInterceptor(grpc_middleware.ChainStreamClient(grpc_zap.StreamClientInterceptor(logger))),
)
if err != nil {
   log.Fatalf("net.Connect err: %v", err)
}

打印如下：

2023-02-06T13:10:21.069+0800	DEBUG	zap/options.go:212	finished client unary call	{"system": "grpc", "span.kind": "client", "grpc.service": "simplepb.Route", "grpc.method": "SimpleRoute", "grpc.code": "OK", "grpc.time_ms": 1018.059}

2. 自定义拦截器

自定义拦截器其实很简单，只需要实现gRPC定义的注册函数就好了，我们以服务端的一元RPC请求为例，实现一个拦截器如下：

func ExampleUnaryInterceptor() grpc.UnaryServerInterceptor {
   return func(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (resp interface{}, err error) {
      // do something before handler
      log.Println("before handler")

      resp, err = handler(ctx, req)
      if err != nil {
         return nil, err
      }

      // do something after handler
      log.Println("after handler")

      return resp, nil
   }
}

类似于grpc_zap.UnaryServerInterceptor，我们在建立服务的时候设置拦截器。

grpcServer := grpc.NewServer(
   grpc.StreamInterceptor(grpc_middleware.ChainStreamServer(
      grpc_zap.StreamServerInterceptor(logger),
   )),
   grpc.UnaryInterceptor(grpc_middleware.ChainUnaryServer(
      grpc_zap.UnaryServerInterceptor(logger),
      ExampleUnaryInterceptor(),
   )),
)

在日志中的打印如下：

2023/02/06 14:48:06 before handler
2023-02-06T14:48:07.125+0800	INFO	server/server.go:60	handling	{"grpc.start_time": "2023-02-06T14:48:06+08:00", "system": "grpc", "span.kind": "server", "grpc.service": "simplepb.Route", "grpc.method": "SimpleRoute"}
2023/02/06 14:48:07 after handler
2023-02-06T14:48:07.125+0800	INFO	zap/options.go:212	finished unary call with code OK	{"grpc.start_time": "2023-02-06T14:48:06+08:00", "system": "grpc", "span.kind": "server", "grpc.service": "simplepb.Route", "grpc.method": "SimpleRoute", "grpc.code": "OK", "grpc.time_ms": 1001.325}

注意，拦截器的调用顺序是符合出栈入栈规则的，即：

• 在handler之前的部分，先注册的拦截器先执行；
• 在handler之后的部分，先注册的拦截器后执行；

原因是，在ChainUnaryServer函数中，是倒序将注册的拦截器函数一个个包装，最里面的就是核心的处理逻辑，故而会展现出以上的规则。

// ChainUnaryServer creates a single interceptor out of a chain of many interceptors.
//
// Execution is done in left-to-right order, including passing of context.
// For example ChainUnaryServer(one, two, three) will execute one before two before three, and three
// will see context changes of one and two.
func ChainUnaryServer(interceptors ...grpc.UnaryServerInterceptor) grpc.UnaryServerInterceptor {
   n := len(interceptors)

   return func(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (interface{}, error) {
      chainer := func(currentInter grpc.UnaryServerInterceptor, currentHandler grpc.UnaryHandler) grpc.UnaryHandler {
         return func(currentCtx context.Context, currentReq interface{}) (interface{}, error) {
            return currentInter(currentCtx, currentReq, info, currentHandler)
         }
      }

      // 以下逻辑可以实现：
      // 处理interceptors[n-1]函数中执行核心处理逻辑（核心服务处理函数作为handler(ctx, req)的handler，也就是此函数传入的handler）
      // 处理interceptors[n-2]函数中执行interceptors[n-1]（interceptors[n-1]作为handler）
      // ......
      // 处理interceptors[0]函数后执行interceptors[1]（interceptors[1]作为handler）
      // 从而实现层层包裹。
      chainedHandler := handler
      for i := n - 1; i >= 0; i-- {
         chainedHandler = chainer(interceptors[i], chainedHandler)
      }

      return chainedHandler(ctx, req)
   }
}

如下，ExampleUnaryInterceptor1和ExampleUnaryInterceptor唯一的区别就是打印时加了1：

grpcServer := grpc.NewServer(
   grpc.StreamInterceptor(grpc_middleware.ChainStreamServer(
      grpc_zap.StreamServerInterceptor(logger),
   )),
   grpc.UnaryInterceptor(grpc_middleware.ChainUnaryServer(
      ExampleUnaryInterceptor(),
      ExampleUnaryInterceptor1(),
   )),
)

日志如下：

2023/02/06 14:49:59 before handler
2023/02/06 14:49:59 before handler 1
2023-02-06T14:50:00.393+0800	INFO	server/server.go:60	handling	{"grpc.start_time": "2023-02-06T14:49:59+08:00", "system": "grpc", "span.kind": "server", "grpc.service": "simplepb.Route", "grpc.method": "SimpleRoute"}
2023/02/06 14:50:00 after handler 1
2023/02/06 14:50:00 after handler

3. 小结

gRPC的生态提供了拦截器的中间件功能，我们既可以使用社区提供的拦截器，也可以自定义这些拦截器，这为我们实现gRPC的一些前置和后置操作提供了方便。