introduce

Through a complete example, add API logging middleware to the micro service based on Echo framework.

What is log interceptor / Middleware?

The log interceptor logs every API request.

We will use rk-boot To start the microservice of the Echo framework.

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

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

The boot.yaml file describes the original information of Echo framework startup. Rk boot starts Echo by reading boot.yaml.

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

Details: CommonService

---
echo:
  - name: greeter                   # Required, name of echo entry
    port: 8080                      # Required, port of echo entry
    enabled: true                   # Required, enable echo entry
    commonService:
      enabled: true                 # Optional, enable common service
    interceptors:
      loggingZap:
        enabled: true               # Optional, 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

4. Start main.go

$ go run main.go

5. Verification

We send the / rk / V1 / health request that comes with CommonService.

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

EventLog will be output to stdout by default.

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

------------------------------------------------------------------------
endTime=2021-11-03T16:41:03.355739+08:00
startTime=2021-11-03T16:41:03.355582+08:00
elapsedNano=156642
timezone=CST
ids={"eventId":"7894acd4-5fd3-4809-aef7-dc4cfeb88bd2"}
app={"appName":"rk-demo","appVersion":"master-2c9c6fd","entryName":"greeter","entryType":"EchoEntry"}
env={"arch":"amd64","az":"*","domain":"*","hostname":"lark.local","localIP":"192.168.1.104","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:49176
operation=/rk/v1/healthy
resCode=200
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.

echo:
  - name: greeter                    # Required, name of echo entry
    port: 8080                       # Required, port of echo entry
    enabled: true                    # Required, enable echo 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:42:16.265+0800",
    "startTime":"2021-11-03T16:42:16.265+0800",
    "elapsedNano":157537,
    "timezone":"CST",
    "ids":{
        "eventId":"420bd015-fb9f-415d-a95c-d01000520d08"
    },
    "app":{
        "appName":"rk-demo",
        "appVersion":"master-2c9c6fd",
        "entryName":"greeter",
        "entryType":"EchoEntry"
    },
    "env":{
        "arch":"amd64",
        "az":"*",
        "domain":"*",
        "hostname":"lark.local",
        "localIP":"192.168.1.104",
        "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:53840",
    "operation":"/rk/v1/healthy",
    "eventStatus":"Ended",
    "resCode":"200"
}

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.

---
echo:
  - name: greeter                                     # Required, name of echo entry
    port: 8080                                        # Required, port of echo entry
    enabled: true                                     # Required, enable echo 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

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-11-03T16:46:26.665+0800    INFO    boot/echo_entry.go:693  Bootstrapping EchoEntry.        {"eventId": "60abdcdb-5df7-43cd-b62d-c203c6b5afb4", "entryName": "greeter", "entryType": "EchoEntry", "port": 8080}

EventLogger

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

------------------------------------------------------------------------
endTime=2021-11-03T16:41:03.355739+08:00
startTime=2021-11-03T16:41:03.355582+08:00
elapsedNano=156642
timezone=CST
ids={"eventId":"7894acd4-5fd3-4809-aef7-dc4cfeb88bd2"}
app={"appName":"rk-demo","appVersion":"master-2c9c6fd","entryName":"greeter","entryType":"EchoEntry"}
env={"arch":"amd64","az":"*","domain":"*","hostname":"lark.local","localIP":"192.168.1.104","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:49176
operation=/rk/v1/healthy
resCode=200
eventStatus=Ended
EOE

Log interceptor options

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 the rkechoctx.GetLogger(ctx) method.

func Greeter(ctx echo.Context) error {
	rkechoctx.GetLogger(ctx).Info("Request received")

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

The log is printed!

2021-11-03T16:48:32.525+0800    INFO    basic/main.go:41        Request received        {"requestId": "c6468d01-4e03-4715-bcbb-2a7fa40a637c"}

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 rkechoctx.GetEvent(ctx).

func Greeter(ctx echo.Context) error {
	event := rkechoctx.GetEvent(ctx)
	event.AddPair("key", "value")

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

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

------------------------------------------------------------------------
endTime=2021-11-03T16:49:17.982001+08:00
startTime=2021-11-03T16:49:17.981771+08:00
elapsedNano=230072
timezone=CST
ids={"eventId":"51aa7536-187b-41fb-aa32-f76b45522bc7","requestId":"51aa7536-187b-41fb-aa32-f76b45522bc7"}
app={"appName":"rk-demo","appVersion":"master-2c9c6fd","entryName":"greeter","entryType":"EchoEntry"}
env={"arch":"amd64","az":"*","domain":"*","hostname":"lark.local","localIP":"192.168.1.104","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:64301
operation=/v1/greeter
resCode=200
eventStatus=Ended
EOE