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.

field details
endTime The end of time
startTime The start time
elapsedNano Event time overhead (Nanoseconds)
timezone The time zone
ids Contains eventId, requestId, and traceId. If the original data interceptor is started, or if event.setrequest () is called by the user, the new RequestId will be used and eventId will be exactly the same as RequestId. If the invocation chain interceptor is started, traceId will be logged.
app containsappName, appVersion, entryType entryName.
env Realm contains arch, AZ, Domain, hostname, localIP, OS, realm, region. Realm, region, az, domain fields. These fields come from system environment variables (REALM, REGION, AZ, DOMAIN). “*” means the environment variable is empty.
payloads Contains RPC-related information.
error Contains errors.
counters Do this via event.setCounter ().
pairs Operate via event.addpair ().
timing Operate via event.startTimer () and event.endTimer ().
remoteAddr RPC remote address.
operation RPC name.
resCode RPC return code.
eventStatus Ended 或者 InProgress 
-- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- 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

The name describe type The default value
grpc.interceptors.loggingZap.enabled Start the 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

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