grpc-go の interceptor を理解した

元実装はここ GitHub - grpc/grpc-go: The Go language implementation of gRPC. HTTP/2 based RPC

Interceptor の例としてはここ GitHub - grpc-ecosystem/go-grpc-middleware: Golang gRPC Middlewares: interceptor chaining auth logging retries and more.

要はなにかというと Laravel をやっていたときに使っていた Middleware と自分では理解した。 Middleware - Laravel - The PHP Framework For Web Artisans

リクエストを処理する前後に、任意の処理を差し込めるもの。

リクエストを中断したり、ウェイトしたり、前処理したり。 あるいはリクエスト処理の後に、かかった時間やステータスについてのメトリクスを取ったり、といったことができる。

これはサーバだけでなく、クライアント側にも差し込めるので、クライアントリクエストする前に何処に対してリクエストしようとしているか、とか、なんか色々できそうではある。

自分でも書いてみる。

func AccessLogUnaryServerInterceptor() grpc.UnaryServerInterceptor {
	return func(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (resp interface{}, err error) {
		clientIP := "unknown"
		if p, ok := peer.FromContext(ctx); ok {
			clientIP = p.Addr.String()
		}

		ua := ""
		if md, ok := metadata.FromIncomingContext(ctx); ok {
			if u, ok := md["user-agent"]; ok {
				ua = strings.Join(u, ",")
			}
		}

		ctxzap.AddFields(
			ctx,
			zap.String("access.clientip", clientIP),
			zap.String("access.useragent", ua),
		)

		return handler(ctx, req)
	}
}

これは UnaryServerInterceptor で、つまりは単一リクエスト用のもの。 peer を使ってリクエスト元 IP と Metadata に入っている UserAgent を取得し、それを ctxzap を使って追加フィールドとして設定しておくもの。

なので go-grpc-middleware の grpc_zap.UnaryServerInterceptor が設定されていないと使えない。（そこで ctxzap が設定されるので） go-grpc-middleware/logging/zap at master · grpc-ecosystem/go-grpc-middleware · GitHub

peer はここ。リクエスト元についての情報が簡単に入っている。 grpc-go/peer at master · grpc/grpc-go · GitHub

Metadata についてはここ。ざっくりとは HTTP Header みたいなやつ、と理解したけど大体あってそう。 grpc-go/grpc-metadata.md at master · grpc/grpc-go · GitHub

ctxzap は先に出した go-grpc-middleware で定義されるもの。 go-grpc-middleware/logging/zap/ctxzap at master · grpc-ecosystem/go-grpc-middleware · GitHub

gRPC リクエストの context に zap.Logger を出し入れできるもので、リクエストごとに Logger が設定されているような状態にできる。 ので、例えばリクエストの認証情報を詰めたりとかできて便利ちゃん。

実際に組み込もうとするとこんな感じ。

func NewGRPCServer() *grpc.Server {
	return grpc.NewServer(
		grpc_middleware.WithUnaryServerChain(
			grpc_zap.UnaryServerInterceptor(zap.L()),
			interceptor.AccessLogUnaryServerInterceptor(),
		),
	)
}

で、この interceptor を使った gRPC サーバに対してリクエストを送ってみると、こんな感じにログがでる。よさそう

{
  "level": "info",
  "ts": 1562940752.853247,
  "caller": "zap/server_interceptors.go:40",
  "msg": "finished unary call with code OK",
  "grpc.start_time": "2019-07-12T23:12:32+09:00",
  "system": "grpc",
  "span.kind": "server",
  "grpc.service": "helloworld.Greeter",
  "grpc.method": "SayHello",
  "access.clientip": "127.0.0.1:65516",
  "access.useragent": "my-user-agent/1.0.0 grpc-go/1.19.1",
  "grpc.code": "OK",
  "grpc.time_ms": 0.3019999861717224
}

ちなみにクライアントから UserAgent をどうやって設定するかはこうする。

client, err := grpc.DialContext(ctx, address, grpc.WithUserAgent("my-user-agent/1.0.0"), ...)

後ろに grpc-go/1.19.1 的な文言がついてしまうのはそうなんだけど、まあ、いいんじゃないかな。

あと余談なのだけど grpc-go と go-grpc-middleware とで grpc と go が入れ替わってていつもどっちだ！？！？となる

ワンソースでドッと試したのはこんなかんじ。 example にある helloworld な proto をそのまま利用するとお手軽簡単に gRPC 周辺の様子みれて便利。

package main

import (
	"context"
	"net"
	"strings"
	"time"

	grpc_middleware "github.com/grpc-ecosystem/go-grpc-middleware"
	grpc_zap "github.com/grpc-ecosystem/go-grpc-middleware/logging/zap"
	"github.com/grpc-ecosystem/go-grpc-middleware/logging/zap/ctxzap"
	"go.uber.org/zap"
	"google.golang.org/grpc"
	pb "google.golang.org/grpc/examples/helloworld/helloworld"
	"google.golang.org/grpc/metadata"
	"google.golang.org/grpc/peer"
)

// server is used to implement helloworld.GreeterServer.
type server struct{}

// SayHello implements helloworld.GreeterServer
func (s *server) SayHello(ctx context.Context, in *pb.HelloRequest) (*pb.HelloReply, error) {
	ctxzap.Extract(ctx).Info("Received", zap.Any("in.name", in.Name))
	return &pb.HelloReply{Message: "Hello " + in.Name}, nil
}

func main() {
	port := "127.0.0.1:13000"

	l, _ := zap.NewDevelopment()
	zap.ReplaceGlobals(l)

	// server
	go func() {
		logger := zap.L().Named("Server")

		listener, err := net.Listen("tcp", port)
		if err != nil {
			logger.Error("failed to listen: %v", zap.Error(err))
		}
		defer listener.Close()

		s := grpc.NewServer(
			grpc_middleware.WithUnaryServerChain(
				grpc_zap.UnaryServerInterceptor(logger),
				accessLogUnaryServerInterceptor(),
			),
		)
		defer s.Stop()

		pb.RegisterGreeterServer(s, &server{})

		if err := s.Serve(listener); err != nil {
			logger.Error("failed to serve: %v", zap.Error(err))
		}
	}()

	// client
	go func() {
		time.Sleep(2 * time.Second)
		ctx := context.Background()
		logger := zap.L().Named("Client")

		client, err := grpc.DialContext(
			ctx,
			port,
			grpc.WithUserAgent("my-user-agent/1.0.0"),
			grpc.WithInsecure(),
		)
		defer client.Close()

		if err != nil {
			logger.Error("failed create client", zap.Error(err))
		}

		greeterClient := pb.NewGreeterClient(client)

		logger.Info("Do request")

		response, err := greeterClient.SayHello(ctx, &pb.HelloRequest{Name: "sters"})

		logger.Info("", zap.Any("response.Message", response.Message), zap.Error(err))
	}()

	time.Sleep(5 * time.Second)
	zap.L().Info("Shutdown")
}

func accessLogUnaryServerInterceptor() grpc.UnaryServerInterceptor {
	return func(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (resp interface{}, err error) {
		clientIP := "unknown"
		if p, ok := peer.FromContext(ctx); ok {
			clientIP = p.Addr.String()
		}

		useragent := ""
		if md, ok := metadata.FromIncomingContext(ctx); ok {
			if ua, ok := md["user-agent"]; ok {
				useragent = strings.Join(ua, ",")
			}
		}

		ctxzap.AddFields(
			ctx,
			zap.String("access.clientip", clientIP),
			zap.String("access.useragent", useragent),
		)

		return handler(ctx, req)
	}
}

最近パッケージ読み込み出来るようになったって聞いたので The Go Playground で実行できる。 ココ にある