We have adopted gRPC within the team and are proceeding with development, There are still few articles in Japanese, especially detailed articles on log implementation. It was hard to find and it took time to collect information. .. Therefore, I would like to share information with the team and write an article in addition to my memorandum.
This time, while developing a gRPC server in Go language,
High-speed log output is possible and is built into grpc-middleware
Let's implement a simple and simple structured log using grpc_zap.
This article does not give an overview or mechanism of gRPC.
Uber can use zapLogger provided by OSS and incorporate it into gRPC
It is a package built into grpc-middleware as one of the Interceptors.
Zap structured logging is easy to implement and can be combined with grpc_ctxtags
You can freely add fields.
Sample is available on the GitHub repository. I will explain based on this sample.
The operating environment is confirmed below.
OS: macOS Catalina 10.15.4 @ 2.7GHz 2Core, 16GB
Docker Desktop: 2.3.0.5(48029), Engine:19.03.12
This time, let's consider a gRPC server that can get student information when you make a request.
gRPC uses Protocol Buffer (protobuf) as an IDL common to servers and clients.
Since many implementations have been used, this article also uses protobuf.
proto/sample.proto
package sample;
service Student {
//Get student information
rpc Get (StudentRequest) returns (StudentResponse) {}
}
message StudentRequest {
int32 id = 1; //Student ID you want to get
}
message StudentResponse {
int32 id = 1; //Student ID
string name = 2; //name
int32 age = 3; //age
School school = 4; //Affiliated school
}
message School {
int32 id = 1; //School ID
string name = 2; //school name
string grade = 3; //School year
}
If you request with the student ID, you can get the student and his school / grade as a response, I'm assuming a simple gRPC server.
First is the main.go file.
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 and option settings
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
},
)
//Set up Interceptor and initialize gRPC server
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)
}
}
I would like to explain one by one.
①
zap, _ := zap.NewProduction()
First, initialize the zap Logger. You will need it when you embed it in grpc_zap.
Here, it is NewProduction (), but for the sake of clarity when outputting the log.
It is output as a structured log including the log level.
(There is also an initialization function called NewDevelopment (),
It seems that the log level is not included in JSON and is output here)
②
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 sets the log level corresponding to the status code
It is relatively easy to set as an option.
If you set the log level you want to distribute to codes.Code of grpc as in the implementation example,
At the corresponding log level, just specify the status code when implementing the response
It will output.
③
grpc := grpc.NewServer(
grpc_middleware.WithUnaryServerChain(
grpc_ctxtags.UnaryServerInterceptor(),
grpc_zap.UnaryServerInterceptor(zap, zap_opt),
),
)
Integrate the Interceptor when initializing the gRPC server.
If there is only one Interceptor to integrate, use WithUnaryServerChain
You don't have to put it together, but this time I want to add any fields to the structured log, so
Use WithUnaryServerChain to integrate grpc_ctxtags and grpc_zap.
Next, let's look at the server.go file, which is the response part.
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",
},
}
//Define fields to log
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.") // --- ③
}
}
Regarding the processing part, when the requested ID is 1, Taro's information is returned.
It is a simple response.
The order of the explanation is not the same as the code flow, but I will explain it step by step.
①
grpc_ctxtags.Extract(ctx).Set("request_id", req.Id)
You can add fields to the context log using grpc_ctxtags.
By adding Set (key, value) to the context passed as an argument
You can put it on the output of 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
Since the value to be set is supported by the interface {} type, it can also be supported by map.
If the value to be passed is map [string] interface {}, the key name and value will be structured respectively, so
It is also possible to nest and output.
If the response is normal, you can process it in the same way as normal gRPC.
The integrated grpc_zap as an Interceptor will output a structured log.
It is very easy and simple because you can output structured logs without complicated configuration.
③
return nil, status.Errorf(codes.Internal, "No students found.")
Even if you return the process with an error, just implement the error process as it is
It can be output as a response log, but if you use gRPC's status package
It is possible to handle the error by specifying the status code.
By combining with the grpc_zap option defined in main.go
It is output at the log level that matches the status code.
In the above example, it will be output as a Error Level log.
Let's do a post-implementation test.
In the sample, main.go is executed with docker-compose.
grpc-sample/
docker-compose up -d --build
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
grpcurl -plaintext -d '{"id": 2}' localhost:50051 sample.Student.Get
ERROR:
Code: Internal
Message: No students found.
It was confirmed that if the ID is 1, normal processing occurs, otherwise an error occurs.
In case of an error, it is output as specified by code.Internal.
Let's check the output log.
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
}
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/[email protected]/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/[email protected]/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/[email protected]/chain.go:25\ngithub.com/grpc-ecosystem/go-grpc-middleware/tags.UnaryServerInterceptor.func1\n\t/go/pkg/mod/github.com/grpc-ecosystem/[email protected]/tags/interceptors.go:23\ngithub.com/grpc-ecosystem/go-grpc-middleware.ChainUnaryServer.func1.1.1\n\t/go/pkg/mod/github.com/grpc-ecosystem/[email protected]/chain.go:25\ngithub.com/grpc-ecosystem/go-grpc-middleware.ChainUnaryServer.func1\n\t/go/pkg/mod/github.com/grpc-ecosystem/[email protected]/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/[email protected]/server.go:1210\ngoogle.golang.org/grpc.(*Server).handleStream\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:1533\ngoogle.golang.org/grpc.(*Server).serveStreams.func1.2\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:871"
}
(The above is formatted with line breaks and indents for readability)
You can see that the log in JSON format is output.
Also, by using grpc_ctxtags, the following fields have been added.
docker-logs(OK, excerpt)
"data":{
"age":11,
"name":"Taro",
"school_grade":"5th",
"school_name":"ABC school"
},
docker-logs(Error, excerpt)
"request_id":2,
Finally, it is a reference site.
By using grpc_zap, I was able to easily and simply incorporate zapLogger into gRPC.
You can also add fields with grpc_ctxtags and set log levels with Option.
I think it's relatively easy to implement and flexible to customize.
I think it's easy to design a log, so please use it.
Pointing out ・ Sharing such as "There is also such a usage!" Is welcome.
Recommended Posts