Go in API routing middleware logging


First, synchronize the following project overview:

The previous article shared the planning project directory and parameter validation, in which the parameter validation uses the version of validator.v8, which has been updated to the version of validator.v9, and the latest code can be viewed in github.

Let's share this article: routing Middleware - logging.

Log is a very important thing, which is convenient for us to check the problem. In this article, we realize to record the log in the text file.

This is the parameter I planned to record:


 - request Request data    
        - request_time    
        - request_method    
        - request_uri    
        - request_proto    
        - request_ua    
        - request_referer    
        - request_post_data    
        - request_client_ip    
    - response Return data    
        - response_time    
        - response_code    
        - response_msg    
        - response_data    
    - cost_time Spend time


The Gin framework has its own Logger middleware. Do we know whether the Logger Middleware in the next framework meets our needs?


Let's use gin.Logger() first to see the effect.

Add code to route.go setuproute method:



After running, request several times, and the log output is on the command line:


   [GIN] 2019/08/30 - 21:24:16 | 200 |     178.072µs |             ::1 | GET      /ping    
    [GIN] 2019/08/30 - 21:24:27 | 200 |     367.997µs |             ::1 | POST     /product    
    [GIN] 2019/08/30 - 21:24:28 | 200 |    2.521592ms |             ::1 | POST     /product


First, how to output the log to the text?

Add code to route.go setuproute method:

    f, _ := os.Create(config.AppAccessLogName)    
    gin.DefaultWriter = io.MultiWriter(f)    


After running, request several times, and the log output is in the file:

    [GIN] 2019/08/30 - 21:36:07 | 200 |     369.023µs |             ::1 | GET      /ping    
    [GIN] 2019/08/30 - 21:36:08 | 200 |      27.585µs |             ::1 | GET      /ping    
    [GIN] 2019/08/30 - 21:36:10 | 200 |      14.302µs |             ::1 | POST     /product


Although recording to the file is successful, the recorded parameters are not what we want.

What shall I do?

We need to customize a log middleware to record according to the parameters we need.

Custom Logger()


    package logger    
    import (    
    type bodyLogWriter struct {    
        body *bytes.Buffer    
    func (w bodyLogWriter) Write(b []byte) (int, error) {    
        return w.ResponseWriter.Write(b)    
    func (w bodyLogWriter) WriteString(s string) (int, error) {    
        return w.ResponseWriter.WriteString(s)    
    func SetUp() gin.HandlerFunc {    
        return func(c *gin.Context) {    
            bodyLogWriter := &bodyLogWriter{body: bytes.NewBufferString(""), ResponseWriter: c.Writer}    
            c.Writer = bodyLogWriter    
            //start time    
            startTime := util.GetCurrentMilliTime()    
            //Processing request    
            responseBody := bodyLogWriter.body.String()    
            var responseCode int    
            var responseMsg  string    
            var responseData interface{}    
            if responseBody != "" {    
                response := util.Response{}    
                err := json.Unmarshal([]byte(responseBody), &response)    
                if err == nil {    
                    responseCode = response.Code    
                    responseMsg  = response.Message    
                    responseData = response.Data    
            //End time    
            endTime := util.GetCurrentMilliTime()    
            if c.Request.Method == "POST" {    
            //Log format    
            accessLogMap := make(map[string]interface{})    
            accessLogMap["request_time"]      = startTime    
            accessLogMap["request_method"]    = c.Request.Method    
            accessLogMap["request_uri"]       = c.Request.RequestURI    
            accessLogMap["request_proto"]     = c.Request.Proto    
            accessLogMap["request_ua"]        = c.Request.UserAgent()    
            accessLogMap["request_referer"]   = c.Request.Referer()    
            accessLogMap["request_post_data"] = c.Request.PostForm.Encode()    
            accessLogMap["request_client_ip"] = c.ClientIP()    
            accessLogMap["response_time"] = endTime    
            accessLogMap["response_code"] = responseCode    
            accessLogMap["response_msg"]  = responseMsg    
            accessLogMap["response_data"] = responseData    
            accessLogMap["cost_time"] = fmt.Sprintf("%vms", endTime - startTime)    
            accessLogJson, _ := util.JsonEncode(accessLogMap)    
            if f, err := os.OpenFile(config.AppAccessLogName, os.O_WRONLY|os.O_APPEND|os.O_CREATE, 0666); err != nil {    
            } else {    
                f.WriteString(accessLogJson + "\n")    


After running, request several times, and the log output is in the file:


   {"cost_time":"0ms","request_client_ip":"::1","request_method":"GET","request_post_data":"","request_proto":"HTTP/1.1","request_referer":"","request_time":1567172568233,"request_ua":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/75.0.3770.142 Safari/537.36","request_uri":"/ping","response_code":1,"response_data":null,"response_msg":"pong","response_time":1567172568233}    
    {"cost_time":"0ms","request_client_ip":"::1","request_method":"GET","request_post_data":"","request_proto":"HTTP/1.1","request_referer":"","request_time":1567172569158,"request_ua":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/75.0.3770.142 Safari/537.36","request_uri":"/ping","response_code":1,"response_data":null,"response_msg":"pong","response_time":1567172569158}    
    {"cost_time":"0ms","request_client_ip":"::1","request_method":"POST","request_post_data":"name=admin","request_proto":"HTTP/1.1","request_referer":"","request_time":1567172629565,"request_ua":"PostmanRuntime/7.6.0","request_uri":"/product","response_code":-1,"response_data":null,"response_msg":"Key: 'ProductAdd.Name' Error:Field validation for 'Name' failed on the 'NameValid' tag","response_time":1567172629565}


OK, all the parameters we want are recorded!

Here are a few questions:

1. Is there an open source logging tool?

Of course, logrus is the most widely used tool. This tool has powerful functions. I also shared it. You can read the original article "log collection using logrus".

2. Why log in the text?

Because the log platform can use ELK.

Use Logstash to collect text files, use elastic search engine for search analysis, and finally show it on Kibana platform.

3. When a large number of requests come, will there be any problem in writing the file?

Maybe, asynchrony can be used here. Let's use the chan of go. See the code for the specific implementation. I won't paste it.

Tags: Go github JSON Mac OS X

Posted on Sat, 09 Nov 2019 12:36:27 -0800 by Daguse