Gin framework: add API logging Middleware

Introduce

Through a complete example , Based on Gin Add... To the microservices of the framework API Log Middleware .

What is a log interceptor / middleware ？

Log interceptors will be used for every API Request logging .

We will use rk-boot To start up Gin Microservices of the framework .

Please visit the following address for a complete tutorial ：https://rkdocs.netlify.app/cn

install

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

Quick start

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

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

1. establish boot.yaml

boot.yaml The document describes Gin Original information of framework startup ,rk-boot By reading the boot.yaml To start up Gin.

In order to verify , We started at the same time commonService.commonService It contains a series of general API.

details : CommonService

---
gin:
  - name: greeter                   # Required, name of gin entry
    port: 8080                      # Required, port of gin entry
    enabled: true                   # Required, enable gin entry
    commonService:
      enabled: true                 # Optional, enable common service
    interceptors:
      loggingZap:
        enabled: true               # Optional, enable logging interceptor

2. establish main.go

package main

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

// 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

4. start-up main.go

$ go run main.go

5. verification

We send CommonService Self contained /rk/v1/healthy request .

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

EventLog The default output is to stdout.

The following log format is from rk-query , Users can also choose JSON Format , We'll talk about .

------------------------------------------------------------------------
endTime=2021-11-03T16:07:16.163624+08:00
startTime=2021-11-03T16:07:16.16355+08:00
elapsedNano=73445
timezone=CST
ids={"eventId":"a9cc6ca1-cb54-4495-a83c-b296a8162149"}
app={"appName":"rk-demo","appVersion":"master-2c9c6fd","entryName":"greeter","entryType":"GinEntry"}
env={"arch":"amd64","az":"*","domain":"*","hostname":"lark.local","localIP":"10.8.0.2","os":"darwin","realm":"*","region":"*"}
payloads={"apiMethod":"GET","apiPath":"/rk/v1/healthy","apiProtocol":"HTTP/1.1","apiQuery":"","userAgent":"curl/7.64.1"}
error={}
counters={}
pairs={}
timing={}
remoteAddr=localhost:50722
operation=/rk/v1/healthy
resCode=200
eventStatus=Ended
EOE

Change the log format

We can modify boot.yaml To modify the log format .

At present, we support json and console Two formats , The default is console.

By modifying the eventLoggerEncoding The value of is json, We can output the log as JSON Format .

gin:
  - name: greeter                    # Required, name of gin entry
    port: 8080                       # Required, port of gin entry
    enabled: true                    # Required, enable gin entry
    commonService:
      enabled: true                  # Optional, enable common service
    interceptors:
      loggingZap:
        enabled: true                # Optional, enable logging interceptor
        zapLoggerEncoding: "json"    # Override to json format, option: json or console
        eventLoggerEncoding: "json"  # Override to json format, option: json or console

{
    "endTime":"2021-11-03T16:09:27.712+0800",
    "startTime":"2021-11-03T16:09:27.712+0800",
    "elapsedNano":81181,
    "timezone":"CST",
    "ids":{
        "eventId":"8a9ae674-d1dc-4f43-a5ad-4e30412cb69e"
    },
    "app":{
        "appName":"rk-demo",
        "appVersion":"master-2c9c6fd",
        "entryName":"greeter",
        "entryType":"GinEntry"
    },
    "env":{
        "arch":"amd64",
        "az":"*",
        "domain":"*",
        "hostname":"lark.local",
        "localIP":"10.8.0.2",
        "os":"darwin",
        "realm":"*",
        "region":"*"
    },
    "payloads":{
        "apiMethod":"GET",
        "apiPath":"/rk/v1/healthy",
        "apiProtocol":"HTTP/1.1",
        "apiQuery":"",
        "userAgent":"curl/7.64.1"
    },
    "error":{},
    "counters":{},
    "pairs":{},
    "timing":{},
    "remoteAddr":"localhost:59140",
    "operation":"/rk/v1/healthy",
    "eventStatus":"Ended",
    "resCode":"200"
}

Modify log path

By modifying the eventLoggerOutputPaths Value , You can specify an output path .

The log defaults to 1GB after , For cutting , And compress .

---
gin:
  - name: greeter                                     # Required, name of gin entry
    port: 8080                                        # Required, port of gin entry
    enabled: true                                     # Required, enable gin entry
    commonService:
      enabled: true                                   # Optional, enable common service
    interceptors:
      loggingZap:
        enabled: true                                 # Optional, enable logging interceptor
        zapLoggerOutputPaths: ["logs/app.log"]        # Override output paths
        eventLoggerOutputPaths: ["logs/event.log"]    # Override output paths

.
├── boot.yaml
├── go.mod
├── go.sum
├── logs
│   └── event.log
└── main.go

Concept

Log interceptor verified , Let's talk about it in detail rk-boot What are the functions of the provided log interceptors .

We need to understand two concepts in advance .

• EventLogger
• ZapLogger

ZapLogger

Used to record errors / Detailed log , This user can get RPC Called ZapLogger example , Log writing , Every RPC Of ZapLogger All instances contain the current RequestId.

2021-11-03T16:13:36.362+0800    INFO    boot/gin_entry.go:759   Bootstrapping GinEntry. {"eventId": "68d0c4c0-c631-4a9c-a518-2576ed6175a4", "entryName": "greeter", "entryType": "GinEntry", "port": 8080, "interceptorsCount": 2, "swEnabled": false, "tlsEnabled": false, "commonServiceEnabled": true, "tvEnabled": false}

EventLogger

RK The starter puts each RPC Request as Event, And use rk-query Medium Event Type to log .

Field	details
endTime	End time
startTime	Starting time
elapsedNano	Event Time cost （Nanoseconds）
timezone	The time zone
ids	contain eventId, requestId and traceId. If the original data interceptor is activated , perhaps event.SetRequest() Called by user , new RequestId Will be used , meanwhile eventId And requestId It will be as like as two peas. . If the call chain interceptor is started ,traceId Will be recorded .
app	contain appName, appVersion, entryName, entryType.
env	contain arch, az, domain, hostname, localIP, os, realm, region. realm, region, az, domain Field . These fields come from system environment variables （REALM,REGION,AZ,DOMAIN）. "*" Indicates that the environment variable is empty .
payloads	contain RPC Related information .
error	Contains errors .
counters	adopt event.SetCounter() To operate .
pairs	adopt event.AddPair() To operate .
timing	adopt event.StartTimer() and event.EndTimer() To operate .
remoteAddr	RPC Remote address .
operation	RPC name .
resCode	RPC Return code .
eventStatus	Ended perhaps InProgress

------------------------------------------------------------------------
endTime=2021-11-03T16:07:16.163624+08:00
startTime=2021-11-03T16:07:16.16355+08:00
elapsedNano=73445
timezone=CST
ids={"eventId":"a9cc6ca1-cb54-4495-a83c-b296a8162149"}
app={"appName":"rk-demo","appVersion":"master-2c9c6fd","entryName":"greeter","entryType":"GinEntry"}
env={"arch":"amd64","az":"*","domain":"*","hostname":"lark.local","localIP":"10.8.0.2","os":"darwin","realm":"*","region":"*"}
payloads={"apiMethod":"GET","apiPath":"/rk/v1/healthy","apiProtocol":"HTTP/1.1","apiQuery":"","userAgent":"curl/7.64.1"}
error={}
counters={}
pairs={}
timing={}
remoteAddr=localhost:50722
operation=/rk/v1/healthy
resCode=200
eventStatus=Ended
EOE

Log interceptor options

name	describe	type	The default value is
gin.interceptors.loggingZap.enabled	Start log interceptor	boolean	false
gin.interceptors.loggingZap.zapLoggerEncoding	Log format ：json perhaps console	string	console
gin.interceptors.loggingZap.zapLoggerOutputPaths	Log file path	[]string	stdout
gin.interceptors.loggingZap.eventLoggerEncoding	Log format ：json perhaps console	string	console
gin.interceptors.loggingZap.eventLoggerOutputPaths	Log file path	[]string	stdout

obtain RPC Log instance

every time RPC When asked to come in , The interceptor will RequestId（ When the original data interceptor is started ） Inject into the log instance .

let me put it another way , every last RPC request , There will be a new Logger example . Let's see how for one RPC request , Record ZapLogger journal .

adopt rkginctx.GetLogger(ctx) Method to obtain the log instance of this request .

func Greeter(ctx *gin.Context) {
	rkginctx.GetLogger(ctx).Info("Request received")

	ctx.JSON(http.StatusOK, &GreeterResponse{
		Message: fmt.Sprintf("Hello %s!", ctx.Query("name")),
	})
}

The log was printed out ！

2021-11-03T16:16:20.041+0800    INFO    basic/main.go:43        Request received        {"requestId": "f1c15b4e-d4e2-4da9-a9dd-55aa31fc35ac"}

modify Event

The log interceptor will RPC Request to create a Event example .

Users can add pairs,counters,errors.

adopt rkginctx.GetEvent(ctx) Get this RPC Of Event example .

func Greeter(ctx *gin.Context) {
	event := rkginctx.GetEvent(ctx)
	event.AddPair("key", "value")

	ctx.JSON(http.StatusOK, &GreeterResponse{
		Message: fmt.Sprintf("Hello %s!", ctx.Query("name")),
	})
}

Event It's added pairs={"key":"value"}！

------------------------------------------------------------------------
endTime=2021-11-03T16:17:42.892857+08:00
startTime=2021-11-03T16:17:42.892762+08:00
elapsedNano=94494
timezone=CST
ids={"eventId":"1ef6ceab-f6fd-4995-9272-b0ce60476e57","requestId":"1ef6ceab-f6fd-4995-9272-b0ce60476e57"}
app={"appName":"rk-demo","appVersion":"master-2c9c6fd","entryName":"greeter","entryType":"GinEntry"}
env={"arch":"amd64","az":"*","domain":"*","hostname":"lark.local","localIP":"10.8.0.2","os":"darwin","realm":"*","region":"*"}
payloads={"apiMethod":"GET","apiPath":"/v1/greeter","apiProtocol":"HTTP/1.1","apiQuery":"","userAgent":"curl/7.64.1"}
error={}
counters={}
pairs={"key":"value"}
timing={}
remoteAddr=localhost:57814
operation=/v1/greeter
resCode=200
eventStatus=Ended
EOE