gRPC に関する投稿を表示しています

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 で実行できる。
ココ にある

grpc のリクエストをガシガシ送るツールghz

gRPC なエンドポイントのパフォーマンスをみたり、負荷試験をしたいなあという話をしたら ghz というツールがあるよと教えてもらったので、これを使ってみる。

ghz · Simple gRPC benchmarking and load testing tool

公式にはリリースページからインストールしてくれやと書かれている。
が go get でとれるのでこれでいいのでは… latest を使うことになるのでリリースされてるものと微妙に差異があるかも。

go get github.com/bojand/ghz/cmd/ghz/

ab ライクに使えるので、ヘルプを見たらまあ問題なく使えるはず。
Usage · ghz

Kubernetes 上で動くアプリケーションに対して実施するとこんな感じ。
ポートフォワードしてから、

kubectl port-forward svc/foo 5000

※Service に向けてポートフォワードしてますが kubectl コマンド実行時に宛先 Pod を解決してしまうので、ロードバランスしないです。

別ターミナルで、こういう具合 proto の指定がないときは Server Reflection して勝手にやってくれる、超便利。
そっちの話題はここにある。 grpc/server-reflection.md at master · grpc/grpc · GitHub

$ ghz \
    --call foo.bar.Service.RPC \
    -d "$(jo foo='bar')" \
    -m "{\"Authorization\":\"BEARER $TOKEN\"}" \
    -q 4 \
    -c 2 \
    -n 10 \
    --insecure \
    localhost:5000

Summary:
  Count:    10
  Total:    1.37 s
  Slowest:    243.03 ms
  Fastest:    111.49 ms
  Average:    149.98 ms
  Requests/sec:    7.29

Response time histogram:
  111.491 [1]    |∎∎∎∎∎∎∎∎
  124.645 [5]    |∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎
  137.799 [0]    |
  150.953 [2]    |∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎
  164.107 [0]    |
  177.261 [0]    |
  190.415 [0]    |
  203.569 [0]    |
  216.723 [0]    |
  229.877 [0]    |
  243.031 [2]    |∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎

Latency distribution:
  10% in 118.75 ms
  25% in 119.66 ms
  50% in 123.21 ms
  75% in 243.01 ms
  90% in 243.03 ms
  0% in 0 ns
  0% in 0 ns

Status code distribution:
  [OK]   10 responses

リクエストパラメータつくるのに jo を使っている。
GitHub - jpmens/jo: JSON output from a shell

上記の例だと 最大 4 req/sec になるように、 2 並列でリクエストし、 10 リクエスト送ったら終わる、というオプションになっている。
なので、レスポンスタイム次第ではあるが、サクッとレスポンスがあれば 1 秒ちょっとで完了する。

レスポンスタイムの分布であったり、パーセンタイルもでたり、サクッと負荷かけて様子を見るのに便利そう。

もちろん、オプションの指定が必要だけど 1 リクエストだけ送ることもできるので、普段使いにもいいんじゃなかろうか。

また Go のパッケージとしても使えるっぽい。
Package · ghz
ちょっと用途が思い浮かんでないけど、例えば、複数の RPC があって、順番にテストしたいんだよね〜〜〜みたいなときとか CI 的に負荷をかけたいんだよね〜〜とか、(シェルスクリプトでさくっと ghz ラッパーでもいいのでは感)

前後の記事

Next:
Prev: