grpc_zapで簡単シンプルにgRPCの構造化ログを実装してみる

# はじめに
チーム内でgRPCを採用し開発を進めていますが、
まだまだ日本語の記事も少なく、とくにログの実装については詳細な記事が
なかなか見つからなく、情報収集に時間がかかりました。。
そのため、チームへの情報共有と自分の備忘録ついでに記事にしたいと思います。

今回はGo言語によるgRPCサーバ開発を進める中で、
高速なログ出力ができ、grpc-middlewareに組み込まれている
`grpc_zap`を使って簡単シンプルな構造化ログを実装してみます。
なお、今回の記事ではgRPCの概要や仕組みについては触れていません。

## grpc_zapとは
UberがOSSで提供している`zap`Loggerを利用し、gRPCに組み込めるよう
Interceptorの一つとしてgrpc-middlewareに組み込まれているパッケージです。
zapの構造化ログが簡単に実装でき、`grpc_ctxtags`と組み合わせることで、
自由にフィールドを追加することができます。

## サンプルと動作環境
GitHubリポジトリにて[サンプル](https://github.com/y-harashima/grpc-sample)を公開しています。
こちらのサンプルを元に説明していきます。

動作環境は以下で確認しています。

```
OS: macOS Catalina 10.15.4 @ 2.7GHz 2Core, 16GB
Docker Desktop: 2.3.0.5(48029), Engine:19.03.12
```


## 要件
今回はリクエストを行うと、生徒の情報が取得できるgRPCサーバを考えます。
gRPCはサーバ・クライアント共通のIDLとして`Protocol Buffer（protobuf）`を
使った実装が多いため、当記事でもprotobufを使います。

```proto:proto/sample.proto
package sample;

service Student {
    // 生徒の情報を取得する
    rpc Get (StudentRequest) returns (StudentResponse) {}
}

message StudentRequest {
    int32 id = 1;       // 取得したい生徒ID
}

message StudentResponse {
    int32 id = 1;       // 生徒ID
    string name = 2;    // 名前
    int32 age = 3;      // 年齢
    School school = 4;  // 所属の学校
}

message School {
    int32 id = 1;       // 学校ID
    string name = 2;    // 学校名
    string grade = 3;   // 学年
}
```
生徒IDでリクエストするとレスポンスとして生徒とその所属学校・学年が取得できる、
簡単なgRPCサーバを想定しています。

## 実装
まずはmain.goファイルです。

```go:main.go
package main

import (
	"log"
	"net"

	"google.golang.org/grpc"
	"google.golang.org/grpc/codes"
	"google.golang.org/grpc/reflection"
	grpc_middleware "github.com/grpc-ecosystem/go-grpc-middleware"
	grpc_zap "github.com/grpc-ecosystem/go-grpc-middleware/logging/zap"
	grpc_ctxtags "github.com/grpc-ecosystem/go-grpc-middleware/tags"
	"go.uber.org/zap"
	"go.uber.org/zap/zapcore"

	sv "github.com/y-harashima/grpc-sample/server"
	pb "github.com/y-harashima/grpc-sample/proto"
)

func main() {

	port, err := net.Listen("tcp", ":50051")
	if err != nil {
		log.Fatal(err)
	}
        
    // zap loggerとオプションの設定 
	zap, _ := zap.NewProduction()     // --- ①
	zap_opt := grpc_zap.WithLevels(          // --- ②
		func(c codes.Code) zapcore.Level {   
			var l zapcore.Level              
			switch c {                       
			case codes.OK:                   
				l = zapcore.InfoLevel        
				                             
			case codes.Internal:             
				l = zapcore.ErrorLevel       

			default:
				l = zapcore.DebugLevel
			}
			return l
		},
	)
    // Interceptorを設定しgRPCサーバを初期化
	grpc := grpc.NewServer(    // --- ③
		grpc_middleware.WithUnaryServerChain(    
			grpc_ctxtags.UnaryServerInterceptor(),   
			grpc_zap.UnaryServerInterceptor(zap, zap_opt),
		),
	)
	
	server := &sv.Server{}
	pb.RegisterStudentServer(grpc, server)
	reflection.Register(grpc)
	log.Println("Server process starting...")
	if err := grpc.Serve(port); err != nil {
		log.Fatal(err)
	}
}
```

一つずつ解説していきたいと思います。
<br>

```go:①
zap, _ := zap.NewProduction()
```
まずはzap Loggerを初期化します。`grpc_zap`に組み込む際に必要となります。
ここでは`NewProduction()`としていますが、log出力時わかりやすくするために
ログレベルなども含めて構造化ログとして出力しています。
（`NewDevelopment()`という初期化関数もありますが、
こちらはログレベルはJSONの中には含まれず出力されるようです）
<br>

```go:②
    zap_opt := grpc_zap.WithLevels(
        func(c codes.Code) zapcore.Level {   
            var l zapcore.Level              
            switch c {                       
            case codes.OK:                   
                l = zapcore.InfoLevel        

            case codes.Internal:             
                l = zapcore.ErrorLevel       

            default:
                l = zapcore.DebugLevel
            }
            return l
        },
    )
```
`grpc_zap`ではステータスコードに対応するログレベルを
比較的簡単にオプションとして設定できます。
実装例のようにgrpcの`codes.Code`に対して、振り分けたいログレベルを設定すると、
レスポンスを実装する際ステータスコードの指定をするだけで対応するログレベルで
出力を行ってくれます。
<br>

```go:③
	grpc := grpc.NewServer(
		grpc_middleware.WithUnaryServerChain(    
			grpc_ctxtags.UnaryServerInterceptor(),   
			grpc_zap.UnaryServerInterceptor(zap, zap_opt),
		),
	)
```
gRPCサーバの初期化を行う際にInterceptorを統合します。
統合するInterceptorが一つの場合は`WithUnaryServerChain`で
まとめる必要はありませんが、今回は構造化ログに任意のフィールドも追加したいので、
`WithUnaryServerChain`を使って`grpc_ctxtags`と`grpc_zap`を統合します。
<br>

つづいて、レスポンス部分であるserver.goファイルをみていきます。

```go:server/server.go
package server

import (
	"context"

	"google.golang.org/grpc/codes"
	"google.golang.org/grpc/status"
	grpc_ctxtags "github.com/grpc-ecosystem/go-grpc-middleware/tags"
	pb "github.com/y-harashima/grpc-sample/proto"
)

type Server struct{}

func (s *Server) Get(ctx context.Context, req *pb.StudentRequest) (*pb.StudentResponse, error) {
	if req.Id == 1 {
		res := &pb.StudentResponse{
			Id: 1,
			Name: "Taro",
			Age: 11,
			School: &pb.School{
				Id: 1,
				Name: "ABC school",
				Grade: "5th",
			},
		}
        // ログ出力するフィールドを定義
		log := map[string]interface{}{  // --- ②
			"name": res.Name, 
			"age": res.Age, 
			"school_name": res.School.Name,
			"school_grade": res.School.Grade,
		}
		grpc_ctxtags.Extract(ctx).Set("data", log)
		return res, nil
	} else {
		grpc_ctxtags.Extract(ctx).Set("request_id", req.Id) // --- ①
		return nil, status.Errorf(codes.Internal, "No students found.") // --- ③
	}
}
```
処理部についてはリクエストされたIDが1の時は`Taro`君の情報を返す、
簡単なレスポンスになっています。
説明の順番がコードの流れ通りではありませんが、順を追って説明します。
<br>

```go:①
		grpc_ctxtags.Extract(ctx).Set("request_id", req.Id)
```
`grpc_ctxtags`を使うとcontextのlogにフィールドを追加することができます。
引数として渡したcontextに、`Set(キー, 値)`を追加することで
`grpc_zap`の出力に乗せることができます。
<br>

```go:②
		log := map[string]interface{}{
			"name": res.Name, 
			"age": res.Age, 
			"school_name": res.School.Name,
			"school_grade": res.School.Grade,
		}
		grpc_ctxtags.Extract(ctx).Set("data", log)
		return res, nil
```
セットする値は`interface{}`型で対応しているため、mapでも対応可能です。
渡す値が`map[string]interface{}`の場合、キー名と値がそれぞれ構造化されるため、
ネストさせて出力することも可能です。
正常なレスポンスの場合は、通常のgRPCと同様に処理することで、
Interceptorとして統合された`grpc_zap`が構造化されたログを出力してくれます。
複雑な構成をせずに構造化ログが出せるのでとても簡単シンプルです。
<br>

```go:③
		return nil, status.Errorf(codes.Internal, "No students found.")
```

エラーで処理を返す場合も、そのままエラー処理を実装するだけで
レスポンスのログとして出力が可能ですが、gRPCの`status`パッケージを使うと
ステータスコードを指定してエラー処理を行うことが可能です。
main.goで定義した`grpc_zap`のオプションと組み合わせることで
ステータスコードに合わせたログレベルで出力されます。
上記の例だと`ErrorLevel`のログとして出力されるということになります。
## テスト
実装後のテストを行ってみます。
サンプルでは`docker-compose`でmain.goを実行するようにしています。

```shell:grpc-sample/
docker-compose up -d --build
```

<br>
gRPCの動作テストは[gRPCurl](https://github.com/fullstorydev/grpcurl)、[evans](https://github.com/ktr0731/evans)などで実施します。
今回はgRPCurlを使用します。

```shell:shell
grpcurl -plaintext -d '{"id": 1}' localhost:50051 sample.Student.Get
{
  "id": 1,
  "name": "Taro",
  "age": 11,
  "school": {
    "id": 1,
    "name": "ABC school",
    "grade": "5th"
  }
} 
```
```shell:shell
grpcurl -plaintext -d '{"id": 2}' localhost:50051 sample.Student.Get
ERROR:
  Code: Internal
  Message: No students found.
```
IDが1の場合は正常な処理、それ以外はエラーとなることが確認できました。
エラーの場合は`code.Internal`で指定した通りに出力されています。
出力ログを確認してみましょう。
<br>

```json:docker-logs(OK)
{
  "level":"info",
  "ts":1602527196.8505046,
  "caller":"zap/options.go:203",
  "msg":"finished unary call with code OK",
  "grpc.start_time":"2020-10-12T18:26:36Z", 
  "system":"grpc",
  "span.kind":"server",
  "grpc.service":"sample.Student",
  "grpc.method":"Get",
  "peer.address":"192.168.208.1:54062",
  "data":{
    "age":11,
    "name":"Taro",
    "school_grade":"5th",
    "school_name":"ABC school"
  },
  "grpc.code":"OK",
  "grpc.time_ms":0.03400000184774399
}
```

```json:docker-log(Error)
{
  "level":"error",
  "ts":1602651069.7882483,
  "caller":"zap/options.go:203",
  "msg":"finished unary call with code Internal",
  "grpc.start_time":"2020-10-14T04:51:09Z",
  "system":"grpc",
  "span.kind":"server",
  "grpc.service":"sample.Student",
  "grpc.method":"Get",
  "peer.address":"192.168.208.1:54066",
  "request_id":2,
  "error":"rpc error: code = Internal desc = No students found.",
  "grpc.code":"Internal",
  "grpc.time_ms":1.3320000171661377,
  "stacktrace":"github.com/grpc-ecosystem/go-grpc-middleware/logging/zap.DefaultMessageProducer\n\t/go/pkg/mod/github.com/grpc-ecosystem/go-grpc-middleware@v1.2.2/logging/zap/options.go:203\ngithub.com/grpc-ecosystem/go-grpc-middleware/logging/zap.UnaryServerInterceptor.func1\n\t/go/pkg/mod/github.com/grpc-ecosystem/go-grpc-middleware@v1.2.2/logging/zap/server_interceptors.go:39\ngithub.com/grpc-ecosystem/go-grpc-middleware.ChainUnaryServer.func1.1.1\n\t/go/pkg/mod/github.com/grpc-ecosystem/go-grpc-middleware@v1.2.2/chain.go:25\ngithub.com/grpc-ecosystem/go-grpc-middleware/tags.UnaryServerInterceptor.func1\n\t/go/pkg/mod/github.com/grpc-ecosystem/go-grpc-middleware@v1.2.2/tags/interceptors.go:23\ngithub.com/grpc-ecosystem/go-grpc-middleware.ChainUnaryServer.func1.1.1\n\t/go/pkg/mod/github.com/grpc-ecosystem/go-grpc-middleware@v1.2.2/chain.go:25\ngithub.com/grpc-ecosystem/go-grpc-middleware.ChainUnaryServer.func1\n\t/go/pkg/mod/github.com/grpc-ecosystem/go-grpc-middleware@v1.2.2/chain.go:34\ngithub.com/y-harashima/grpc-sample/proto._Student_Get_Handler\n\t/app/proto/sample.pb.go:389\ngoogle.golang.org/grpc.(*Server).processUnaryRPC\n\t/go/pkg/mod/google.golang.org/grpc@v1.33.0/server.go:1210\ngoogle.golang.org/grpc.(*Server).handleStream\n\t/go/pkg/mod/google.golang.org/grpc@v1.33.0/server.go:1533\ngoogle.golang.org/grpc.(*Server).serveStreams.func1.2\n\t/go/pkg/mod/google.golang.org/grpc@v1.33.0/server.go:871"
}
```
（上記は可読性のため、改行とインデントで整形をしています）  

JSON形式のログが出力されていることがわかります。
また、`grpc_ctxtags`を使うことで、以下のようなフィールドが追加されています。

```JSON:docker-logs(OK、抜粋)
  "data":{
    "age":11,
    "name":"Taro",
    "school_grade":"5th",
    "school_name":"ABC school"
  },
```

```JSON:docker-logs(Error、抜粋)
  "request_id":2,
```

## 参考サイト
最後に、参考としたサイトです。

- [grpc-middleware - GitHub](https://github.com/grpc-ecosystem/go-grpc-middleware/blob/master/logging/zap/examples_test.go)  
grpc_zapの使用例が書かれています。
- [grpc-go の interceptor を理解した](https://gomiba.co.in/blog/archives/3071)  
  日本のサイトの中でもフィールドの追加など詳しく解説があり、  
  かなり参考になりました。
- [Git repositories on Chromium]  (https://chromium.googlesource.com/infra/goma/server/+/v0.0.13/log/zap.go)  
ChromiumのGitリポジトリ内、  
goma serverにステータスコードからログレベルの出し分けについて  
参考にさせていただきました。  
ここが一番苦労したところで、調査中、  
参考文献がこれぐらいしかなかった記憶があります。。

## まとめ
`grpc_zap`を使うことで`zap`Loggerを簡単シンプルにgRPCに組み込むことができました。
また、`grpc_ctxtags`によるフィールドの追加やOptionでログレベルの出しわけも
比較的簡単に実装することができ、カスタマイズも柔軟だと思います。
ログの設計も立てやすいかなと思いますので、ぜひ利用してみてください。
ご指摘・「こういう使い方もあります！」などの共有も歓迎です。