introduce

This article describes how to add API log interceptors / middleware to gRPC microservices.

What is log interceptor / Middleware?

The log interceptor logs every API request.

We will use rk-boot To start the gRPC service.

Please visit the following address for a complete tutorial:

• https://rkdev.info/cn
• https://rkdocs.netlify.app/cn (standby)

install

go get github.com/rookie-ninja/rk-boot

Quick start

rk-boot By default, the following two open source libraries are integrated.

• uber-go/zap As the underlying log repository.
• logrus Scroll as log.

1. Create boot.yaml

For verification, we also started commonService. commonService contains a series of general API s.
Details: CommonService

Grpc will start grpc gateway by default to provide Restful API services. During verification, we can send Restful requests directly.

---
grpc:
  - name: greeter                   # Name of grpc entry
    port: 8080                      # Port of grpc entry
    enabled: true                   # Enable grpc entry
    commonService:
      enabled: true                 # Enable common service for testing
    interceptors:
      loggingZap:
        enabled: true               # Enable logging interceptor

2. Create main.go

package main

import (
	"context"
	"github.com/rookie-ninja/rk-boot"
)

// Application entrance.
func main() {
	// Create a new boot instance.
	boot := rkboot.NewBoot()

	// Bootstrap
	boot.Bootstrap(context.Background())

	// Wait for shutdown sig
	boot.WaitForShutdownSig(context.Background())
}

3. Folder structure

$ tree
.
├── boot.yaml
├── go.mod
├── go.sum
└── main.go

0 directories, 4 files

3. Verification

$ go run main.go

• Send request

$ curl -X GET localhost:8080/rk/v1/healthy
{"healthy":true}

• Validation log
  The default output is stdout (console).

The following log format is from rk-query , users can also choose JSON format, which will be introduced later.

------------------------------------------------------------------------
endTime=2021-07-09T23:44:09.81483+08:00
startTime=2021-07-09T23:44:09.814784+08:00
elapsedNano=46065
timezone=CST
ids={"eventId":"67d64dab-f3ea-4b77-93d0-6782caf4cfee"}
app={"appName":"rk-demo","appVersion":"master-f414049","entryName":"greeter","entryType":"GrpcEntry"}
env={"arch":"amd64","az":"*","domain":"*","hostname":"lark.local","localIP":"10.8.0.2","os":"darwin","realm":"*","region":"*"}
payloads={"grpcMethod":"Healthy","grpcService":"rk.api.v1.RkCommonService","grpcType":"unaryServer","gwMethod":"","gwPath":"","gwScheme":"","gwUserAgent":""}
error={}
counters={}
pairs={"healthy":"true"}
timing={}
remoteAddr=localhost:58205
operation=/rk.api.v1.RkCommonService/Healthy
resCode=OK
eventStatus=Ended
EOE

Modify log format

We can modify the log format by modifying boot.yaml.
At present, it supports json and console formats, and the default is console.

By changing the value of eventLoggerEncoding to JSON, we can output the log in JSON format.

grpc:
  - name: greeter                     # Name of grpc entry
    port: 8080                        # Port of grpc entry
    enabled: true                     # Enable grpc entry
    commonService:
      enabled: true                   # Enable common service for testing
    interceptors:
      loggingZap:
        enabled: true                 # Enable logging interceptor
        zapLoggerEncoding: "json"     # Override to json format, option: json or console
        eventLoggerEncoding: "json"   # Override to json format, option: json or console

Modify log path

You can specify the output path by modifying the value of eventLoggerOutputPaths.

By default, the log is after 1GB, cut and compressed.

grpc:
  - name: greeter                     # Name of grpc entry
    port: 8080                        # Port of grpc entry
    enabled: true                     # Enable grpc entry
    commonService:
      enabled: true                   # Enable common service for testing
    interceptors:
      loggingZap:
        enabled: true                 # Enable logging interceptor
        zapLoggerOutputPaths: ["logs/app.log"]        # Override output paths, option: json or console
        eventLoggerOutputPaths: ["logs/event.log"]    # Override output paths, option: json or console

concept

After verifying the log interceptor, let's talk about the functions of the log interceptor provided by rk boot.

We need to understand two concepts in advance.

• EventLogger
• ZapLogger

ZapLogger

It is used to record the error / detailed log. The user can obtain the ZapLogger instance of this RPC call and write the log. Each RPC ZapLogger instance contains the current RequestId.

2021-07-09T23:52:13.667+0800    INFO    boot/grpc_entry.go:694  Bootstrapping grpcEntry.        {"eventId": "9bc192fb-567c-45d4-8775-7a097b0dab04", "entryName": "greeter", "entryType": "GrpcEntry", "grpcPort": 8080, "commonServiceEnabled": true, "tlsEnabled": false, "gwEnabled": true, "reflectionEnabled": false, "swEnabled": false, "tvEnabled": false, "promEnabled": false, "gwClientTlsEnabled": false, "gwServerTlsEnabled": false}

EventLogger

The RK initiator treats each RPC request as an Event and uses the Event type in rk query to log.

field	details
endTime	End time
startTime	start time
elapsedNano	Event time overhead (Nanoseconds)
timezone	time zone
ids	Contains eventId, requestId and traceId. If as like as two peas, the original data interceptor is activated, or event.SetRequest() is invoked by the user, the new RequestId will be used, and eventId will be exactly the same as requestId. If the call chain interceptor is started, the traceId will be recorded.
app	contain appName, appVersion, entryName, entryType.
env	Contains the fields arch, az, domain, hostname, localIP, os, realm, region. realm, region, az, domain. These fields are from the system environment variables (real, REGION, AZ, DOMAIN). "*" means that the environment variable is empty.
payloads	Contains RPC related information.
error	Contains errors.
counters	Operate through event.SetCounter().
pairs	Operate through event.AddPair().
timing	Operate through event.StartTimer() and event.EndTimer().
remoteAddr	RPC remote address.
operation	RPC name.
resCode	RPC return code.
eventStatus	Ended or InProgress

------------------------------------------------------------------------
endTime=2021-07-09T23:44:09.81483+08:00
startTime=2021-07-09T23:44:09.814784+08:00
elapsedNano=46065
timezone=CST
ids={"eventId":"67d64dab-f3ea-4b77-93d0-6782caf4cfee"}
app={"appName":"rk-demo","appVersion":"master-f414049","entryName":"greeter","entryType":"GrpcEntry"}
env={"arch":"amd64","az":"*","domain":"*","hostname":"lark.local","localIP":"10.8.0.2","os":"darwin","realm":"*","region":"*"}
payloads={"grpcMethod":"Healthy","grpcService":"rk.api.v1.RkCommonService","grpcType":"unaryServer","gwMethod":"","gwPath":"","gwScheme":"","gwUserAgent":""}
error={}
counters={}
pairs={"healthy":"true"}
timing={}
remoteAddr=localhost:58205
operation=/rk.api.v1.RkCommonService/Healthy
resCode=OK
eventStatus=Ended
EOE

Log interceptor options

name	describe	type	Default value
grpc.interceptors.loggingZap.enabled	Start log interceptor	boolean	false
grpc.interceptors.loggingZap.zapLoggerEncoding	Log format: json or console	string	console
grpc.interceptors.loggingZap.zapLoggerOutputPaths	log file path	[]string	stdout
grpc.interceptors.loggingZap.eventLoggerEncoding	Log format: json or console	string	console
grpc.interceptors.loggingZap.eventLoggerOutputPaths	log file path	[]string	false

Get RPC log instance

Every time an RPC request comes in, the interceptor will inject the RequestId (when the original data interceptor is started) into the log instance.

In other words, each RPC request will have a new Logger instance. Let's see how to log ZapLogger for an RPC request.

Obtain the log instance of this request through rkgrpcctx.GetLogger(ctx) method.

func (server *GreeterServer) Greeter(ctx context.Context, request *greeter.GreeterRequest) (*greeter.GreeterResponse, error) {
	rkgrpcctx.GetLogger(ctx).Info("Received request")

	return &greeter.GreeterResponse{
		Message: fmt.Sprintf("Hello %s!", request.Name),
	}, nil
}

The log is printed!

2021-07-09T23:50:39.318+0800    INFO    basic/main.go:36        Received request        {"requestId": "c33698f2-3071-48d4-9d92-b1aa311e6c06"}

6. Modify Event

The log interceptor will create an Event instance for each RPC request.

Users can add pairs, counters and errors.

Get the Event instance of this RPC through rkgrpcctx.GetEvent(ctx).

func (server *GreeterServer) Greeter(ctx context.Context, request *greeter.GreeterRequest) (*greeter.GreeterResponse, error) {
	event := rkgrpcctx.GetEvent(ctx)
	event.AddPair("key", "value")

	return &greeter.GreeterResponse{
		Message: fmt.Sprintf("Hello %s!", request.Name),
	}, nil
}

pairs = {"key": "value"} is added to the Event!

------------------------------------------------------------------------
endTime=2021-07-09T23:52:39.103351+08:00
startTime=2021-07-09T23:52:39.10332+08:00
elapsedNano=31154
timezone=CST
ids={"eventId":"92001951-80c1-4dda-8f14-f920834f5c61","requestId":"92001951-80c1-4dda-8f14-f920834f5c61"}
app={"appName":"rk-demo","appVersion":"master-f414049","entryName":"greeter","entryType":"GrpcEntry"}
env={"arch":"amd64","az":"*","domain":"*","hostname":"lark.local","localIP":"10.8.0.2","os":"darwin","realm":"*","region":"*"}
payloads={"grpcMethod":"Greeter","grpcService":"api.v1.Greeter","grpcType":"unaryServer","gwMethod":"","gwPath":"","gwScheme":"","gwUserAgent":""}
error={}
counters={}
pairs={"key":"value"}
timing={}
remoteAddr=localhost:58269
operation=/api.v1.Greeter/Greeter
resCode=OK
eventStatus=Ended
EOE