GRPC: How to add API log blocker/middleware?

introduce

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

What is a 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 the full tutorial:

• rkdev.info/cn
• Rkdocs.net lilify. app/cn (standby)

The installation

go get github.com/rookie-ninja/rk-boot
Copy the code

Quick start

Rk-boot integrates the following two open source libraries by default.

• Uber-go/Zap serves as the underlying log library.
• Logrus scrolls as a log.

1. Create the boot. Yaml

To verify, we also started commonService. CommonService contains a set of common apis. Details: CommonService

GRPC enables grPC-gateway by default to provide Restful API services. During validation, 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
Copy the code

2. Create a 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())
}
Copy the code

3. Folder structure

$tree. └── Go. ├─ go. ├─ goCopy the code

3. Verify

$ go run main.go
Copy the code

• Send the request

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

• Verify the log

The default output is stdout (console).

The following log format is from RK-Query, or the user can choose JSON format, which we’ll cover later.

-- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- endTime = 2021-07-09 T23:44:09. 81483 + 08:00 StartTime = 2021-07-09 T23: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":"","gwPat h":"","gwScheme":"","gwUserAgent":""} error={} counters={} pairs={"healthy":"true"} timing={} remoteAddr=localhost:58205  operation=/rk.api.v1.RkCommonService/Healthy resCode=OK eventStatus=Ended EOECopy the code

Changing the Log Format

We can modify the log format by modifying boot.yaml. Currently, two formats are supported: JSON and Console. The default format is Console.

By changing the value of eventLoggerEncoding to JSON, we can convert the log output to 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
Copy the code

Changing a Log Path

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

Logs are cut and compressed after 1GB by default.

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
Copy the code

concept

After verifying the log interceptor, let’s talk about the log interceptor provided by RK-boot in detail.

There are two concepts we need to understand in advance.

• EventLogger
• ZapLogger

ZapLogger

Users can obtain the ZapLogger instance of the RPC call and write logs. Each ZapLogger instance of the RPC call 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}
Copy the code

EventLogger

The RK initiator treats each RPC request as an Event and logs it using the Event type in RK-Query.

-- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- endTime = 2021-07-09 T23:44:09. 81483 + 08:00 StartTime = 2021-07-09 T23: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":"","gwPat h":"","gwScheme":"","gwUserAgent":""} error={} counters={} pairs={"healthy":"true"} timing={} remoteAddr=localhost:58205  operation=/rk.api.v1.RkCommonService/Healthy resCode=OK eventStatus=Ended EOECopy the code

Log interceptor option

Obtain the RPC log instance

Every time an RPC request comes in, the interceptor injects the RequestId (when the raw data interceptor is enabled) into the log instance.

In other words, for every RPC request, there is a new Logger instance. Let’s look at how to log a ZapLogger for an RPC request.

The rkgrpCCtx.getLogger (CTX) method is used to obtain the log instance of this request.

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 }Copy the code

The log is printed!

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

6. Modify the Event

The log interceptor creates an Event instance for each RPC request.

Users can add pairs, counters, and errors.

Run the rkgrpCCtx.getevent (CTX) command to obtain the Event instance of the RPC.

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 }Copy the code

Pairs ={“key”:”value”}!

-- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- endTime = 2021-07-09 T23:52:39. 103351 + 08:00 StartTime = 2021-07-09 T23: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":"","gwSc heme":"","gwUserAgent":""} error={} counters={} pairs={"key":"value"} timing={} remoteAddr=localhost:58269 operation=/api.v1.Greeter/Greeter resCode=OK eventStatus=Ended EOECopy the code