はじめに
チーム内でgRPCを採用し開発を進めていますが、
まだまだ日本語の記事も少なく、とくにログの実装については詳細な記事が
なかなか見つからなく、情報収集に時間がかかりました。。
そのため、チームへの情報共有と自分の備忘録ついでに記事にしたいと思います。
今回はGo言語によるgRPCサーバ開発を進める中で、
高速なログ出力ができ、grpc-middlewareに組み込まれている
grpc_zapを使って簡単シンプルな構造化ログを実装してみます。
なお、今回の記事ではgRPCの概要や仕組みについては触れていません。
grpc_zapとは
UberがOSSで提供しているzapLoggerを利用し、gRPCに組み込めるよう
Interceptorの一つとしてgrpc-middlewareに組み込まれているパッケージです。
zapの構造化ログが簡単に実装でき、grpc_ctxtagsと組み合わせることで、
自由にフィールドを追加することができます。
サンプルと動作環境
GitHubリポジトリにてサンプルを公開しています。
こちらのサンプルを元に説明していきます。
動作環境は以下で確認しています。
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を使います。
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ファイルです。
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)
}
}
一つずつ解説していきたいと思います。
zap, _ := zap.NewProduction()
まずはzap Loggerを初期化します。grpc_zapに組み込む際に必要となります。
ここではNewProduction()としていますが、log出力時わかりやすくするために
ログレベルなども含めて構造化ログとして出力しています。
（NewDevelopment()という初期化関数もありますが、
こちらはログレベルはJSONの中には含まれず出力されるようです）
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に対して、振り分けたいログレベルを設定すると、
レスポンスを実装する際ステータスコードの指定をするだけで対応するログレベルで
出力を行ってくれます。
grpc := grpc.NewServer(
grpc_middleware.WithUnaryServerChain(
grpc_ctxtags.UnaryServerInterceptor(),
grpc_zap.UnaryServerInterceptor(zap, zap_opt),
),
)
gRPCサーバの初期化を行う際にInterceptorを統合します。
統合するInterceptorが一つの場合はWithUnaryServerChainで
まとめる必要はありませんが、今回は構造化ログに任意のフィールドも追加したいので、
WithUnaryServerChainを使ってgrpc_ctxtagsとgrpc_zapを統合します。
つづいて、レスポンス部分である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君の情報を返す、
簡単なレスポンスになっています。
説明の順番がコードの流れ通りではありませんが、順を追って説明します。
grpc_ctxtags.Extract(ctx).Set("request_id", req.Id)
grpc_ctxtagsを使うとcontextのlogにフィールドを追加することができます。
引数として渡したcontextに、Set(キー, 値)を追加することで
grpc_zapの出力に乗せることができます。
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が構造化されたログを出力してくれます。
複雑な構成をせずに構造化ログが出せるのでとても簡単シンプルです。
return nil, status.Errorf(codes.Internal, "No students found.")
エラーで処理を返す場合も、そのままエラー処理を実装するだけで
レスポンスのログとして出力が可能ですが、gRPCのstatusパッケージを使うと
ステータスコードを指定してエラー処理を行うことが可能です。
main.goで定義したgrpc_zapのオプションと組み合わせることで
ステータスコードに合わせたログレベルで出力されます。
上記の例だとErrorLevelのログとして出力されるということになります。
テスト
実装後のテストを行ってみます。
サンプルではdocker-composeでmain.goを実行するようにしています。
docker-compose up -d --build
gRPCの動作テストは[gRPCurl](https://github.com/fullstorydev/grpcurl)、[evans](https://github.com/ktr0731/evans)などで実施します。 今回はgRPCurlを使用します。
grpcurl -plaintext -d '{"id": 1}' localhost:50051 sample.Student.Get
{
"id": 1,
"name": "Taro",
"age": 11,
"school": {
"id": 1,
"name": "ABC school",
"grade": "5th"
}
}
grpcurl -plaintext -d '{"id": 2}' localhost:50051 sample.Student.Get
ERROR:
Code: Internal
Message: No students found.
IDが1の場合は正常な処理、それ以外はエラーとなることが確認できました。
エラーの場合はcode.Internalで指定した通りに出力されています。
出力ログを確認してみましょう。
{
"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
}
{
"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を使うことで、以下のようなフィールドが追加されています。
"data":{
"age":11,
"name":"Taro",
"school_grade":"5th",
"school_name":"ABC school"
},
"request_id":2,
参考サイト
最後に、参考としたサイトです。
-
grpc-middleware - GitHub
grpc_zapの使用例が書かれています。 -
grpc-go の interceptor を理解した
日本のサイトの中でもフィールドの追加など詳しく解説があり、
かなり参考になりました。 - [Git repositories on Chromium] (https://chromium.googlesource.com/infra/goma/server/+/v0.0.13/log/zap.go)
ChromiumのGitリポジトリ内、
goma serverにステータスコードからログレベルの出し分けについて
参考にさせていただきました。
ここが一番苦労したところで、調査中、
参考文献がこれぐらいしかなかった記憶があります。。
まとめ
grpc_zapを使うことでzapLoggerを簡単シンプルにgRPCに組み込むことができました。
また、grpc_ctxtagsによるフィールドの追加やOptionでログレベルの出しわけも
比較的簡単に実装することができ、カスタマイズも柔軟だと思います。
ログの設計も立てやすいかなと思いますので、ぜひ利用してみてください。
ご指摘・「こういう使い方もあります！」などの共有も歓迎です。