With issues:
custom logger

Description

What I would expect is to log the body data of the request if the method of the request is not GET. However, in the repository that handles the contents of config, it works properly. In the place where the repository is imported, the request body is output as empty.

How to reproduce

Origin Repository

package footprint

import (
    "fmt"
    "github.com/gin-gonic/gin"
    satori "github.com/satori/go.uuid"
    "io/ioutil"
    "net/http"
    "time"
)

const (
    defaultLogFormat            = "%s %-7s %s %s %3d %s [remote ip: \"%15s\", proto: \"%s\", agent: \"%s\"] -> \"%s\"(request id: %s) %v %13v error: \"%s\"\n"
    defaultLogFormatWithReqBody = "%s %-7s %s %s %3d %s [remote ip: \"%15s\", proto: \"%s\", agent: \"%s\"] -> \"%s\"(request id: %s) %v %13v request: \"%s\" error: \"%s\"\n"
)

func NewLoggerConfig(formatter func(gin.LogFormatterParams) string, skipPaths []string) gin.LoggerConfig {
    return gin.LoggerConfig{
        Formatter: formatter,
        SkipPaths: skipPaths,
    }
}

func DefaultLoggerFormatter(param gin.LogFormatterParams) string {
    requestID := generateRequestID()
    param.Request.Header.Set("X-Request-Id", requestID)

    if param.Method != http.MethodGet {
        reqBody, _ := ioutil.ReadAll(param.Request.Body)
        return loggingWithReqBodyLog(param, string(reqBody))
    }

    return loggingDefaultLog(param)
}

func loggingWithReqBodyLog(param gin.LogFormatterParams, reqBody string) string {
    var statusColor, methodColor, resetColor string
    if param.IsOutputColor() {
        statusColor = param.StatusCodeColor()
        methodColor = param.MethodColor()
        resetColor = param.ResetColor()
    }

    return fmt.Sprintf(defaultLogFormatWithReqBody,
        methodColor, param.Method, resetColor,
        statusColor, param.StatusCode, resetColor,
        param.ClientIP,
        param.Request.Proto,
        param.Request.UserAgent(),
        param.Path,
        param.Request.Header.Get("X-Request-Id"),
        param.TimeStamp.Format(time.RFC3339),
        param.Latency,
        reqBody,
        param.ErrorMessage,
    )
}

Repository to import and use

func setUpRouter() *gin.Engine {
    config := newCorsConfig()

    r := gin.New()

    r.Use(config, useLogger(footprint.DefaultLoggerFormatter), gin.Recovery())

    // health checker
    r.GET("/")

    registerRoute(r)

    return r
}

func useLogger(formatter func(params gin.LogFormatterParams) string) gin.HandlerFunc {
    loggerConfig := footprint.NewLoggerConfig(formatter, skipPaths)
    return gin.LoggerWithConfig(loggerConfig)
}

## Expectations
 POST      400  [remote ip: "               ", proto: "HTTP/1.1", agent: ""] -> "/"(request id: e3b81155-d137-45f2-9f94-a7d8ab318de8) 2020-06-23T10:34:15+09:00      16.022µs request: "{"id":1,"name":"test","created_at":"2020-06-23T10:34:15.179062+09:00"}" error: ""

## Actual result
 POST      400  [remote ip: "               ", proto: "HTTP/1.1", agent: ""] -> "/"(request id: 982ad35f-991b-4591-932a-d770dc5adb52) 2020-06-23T10:30:58+09:00       6.891µs request: "" error: ""

Environment

go version: 1.12
gin version (or commit ref): 1.6.3
operating system: MacOS Catalina(10.15.5)

Comment From: seblegall

Hi, I've just tested it and it seems to work well.

Here is the source code I used :

main.go

package main

import (
    "fmt"

    "github.com/gin-gonic/gin"
    "github.com/seblegall/gist/gin-custom-log/footprint"
)

func main() {
    r := gin.New()

    r.Use(useLogger(footprint.DefaultLoggerFormatter), gin.Recovery())
    r.GET("/")
    r.POST("/")

    r.Run(fmt.Sprintf(":%d", 8080))
}

func useLogger(formatter func(params gin.LogFormatterParams) string) gin.HandlerFunc {
    loggerConfig := footprint.NewLoggerConfig(formatter, []string{})
    return gin.LoggerWithConfig(loggerConfig)
}

footprint/footprint.go

package footprint

import (
    "fmt"
    "io/ioutil"
    "net/http"
    "time"

    "github.com/gin-gonic/gin"
)

const (
    defaultLogFormat            = "%s %-7s %s %s %3d %s [remote ip: \"%15s\", proto: \"%s\", agent: \"%s\"] -> \"%s\"(request id: %s) %v %13v error: \"%s\"\n"
    defaultLogFormatWithReqBody = "%s %-7s %s %s %3d %s [remote ip: \"%15s\", proto: \"%s\", agent: \"%s\"] -> \"%s\"(request id: %s) %v %13v request: \"%s\" error: \"%s\"\n"
)

func NewLoggerConfig(formatter func(gin.LogFormatterParams) string, skipPaths []string) gin.LoggerConfig {
    return gin.LoggerConfig{
        Formatter: formatter,
        SkipPaths: skipPaths,
    }
}

func DefaultLoggerFormatter(param gin.LogFormatterParams) string {
    if param.Method != http.MethodGet {
        reqBody, _ := ioutil.ReadAll(param.Request.Body)
        return loggingWithReqBodyLog(param, string(reqBody))
    }

    return fmt.Sprintf("Default loging")
}

func loggingWithReqBodyLog(param gin.LogFormatterParams, reqBody string) string {
    var statusColor, methodColor, resetColor string
    if param.IsOutputColor() {
        statusColor = param.StatusCodeColor()
        methodColor = param.MethodColor()
        resetColor = param.ResetColor()
    }

    return fmt.Sprintf(defaultLogFormatWithReqBody,
        methodColor, param.Method, resetColor,
        statusColor, param.StatusCode, resetColor,
        param.ClientIP,
        param.Request.Proto,
        param.Request.UserAgent(),
        param.Path,
        param.Request.Header.Get("X-Request-Id"),
        param.TimeStamp.Format(time.RFC3339),
        param.Latency,
        reqBody,
        param.ErrorMessage,
    )
}

When I call my server, here is what I get :

 POST      200  [remote ip: "            ::1", proto: "HTTP/1.1", agent: "PostmanRuntime/7.20.1"] -> "/"(request id: ) 2020-06-23T15:58:18+02:00         764ns request: "{
        "status_code": 200,
        "body" : {
                "field": "test"
        }
}" error: ""

Comment From: Kyocfe

@seblegall I don't know what's wrong. When I run it with test code in the footprint repository, I am logged as well. but, if it is imported and used, logging, whether using Postman or using test code, cannot be performed properly. so confused..

 POST      201  [remote ip: "               ", proto: "HTTP/1.1", agent: ""] -> "/schedule"(request id: 3bb4f943-4d5a-47c8-9a82-c34fd0e2961a) 2020-06-25T09:22:04+09:00      60.171µs request: "" error: ""

Comment From: granty1

@seblegall I don't know what's wrong. When I run it with test code in the footprint repository, I am logged as well. but, if it is imported and used, logging, whether using Postman or using test code, cannot be performed properly. so confused..

POST 201 [remote ip: " ", proto: "HTTP/1.1", agent: ""] -> "/schedule"(request id: 3bb4f943-4d5a-47c8-9a82-c34fd0e2961a) 2020-06-25T09:22:04+09:00 60.171µs request: "" error: ""

You should read the request body in your handle func body. When printing in the log, the response has been written, but the above example does not ?

Comment From: Kyocfe

@seblegall I don't know what's wrong. When I run it with test code in the footprint repository, I am logged as well. but, if it is imported and used, logging, whether using Postman or using test code, cannot be performed properly. so confused.. POST 201 [remote ip: " ", proto: "HTTP/1.1", agent: ""] -> "/schedule"(request id: 3bb4f943-4d5a-47c8-9a82-c34fd0e2961a) 2020-06-25T09:22:04+09:00 60.171µs request: "" error: ""

You should read the request body in your handle func body. When printing in the log, the response has been written, but the above example does not ?

@granty1 I'm sorry, i can't understand what are you talking about that. the gin.LogFormatterParams has request body parameters. doesn't that mean I should be able to use it? can you give me an example with code because my English is not good.

gin.HandlerFunc is already use it.

func main() {
        r.Use(config, useLogger(footprint.DefaultLoggerFormatter), gin.Recovery())
}
func useLogger(formatter func(params gin.LogFormatterParams) string) gin.HandlerFunc {
    loggerConfig := footprint.NewLoggerConfig(formatter, skipPaths)
    return gin.LoggerWithConfig(loggerConfig)
}

Comment From: Kyocfe

@seblegall @granty1 Thank you for the answers :) the problem was solved. this is my solution.

func loggingWithReqBodyLog(param gin.LogFormatterParams) string {
    var statusColor, methodColor, resetColor string
    if param.IsOutputColor() {
        statusColor = param.StatusCodeColor()
        methodColor = param.MethodColor()
        resetColor = param.ResetColor()
    }

    body, _ := param.Request.GetBody()
    reqBody, _ := ioutil.ReadAll(body)

    return fmt.Sprintf(defaultLogFormatWithReqBody,
        methodColor, param.Method, resetColor,
        statusColor, param.StatusCode, resetColor,
        param.ClientIP,
        param.Request.Proto,
        param.Request.UserAgent(),
        param.Path,
        param.Request.Header.Get("X-Request-Id"),
        param.TimeStamp.Format(time.RFC3339),
        param.Latency,
        string(reqBody),
        param.ErrorMessage,
    )
}

As a result of checking with the debugger, when I tried to read param.Request.Body, the data disappeared. I don't know exactly why, but when I get it through the function GetBody(), there is no problem.

Comment From: Kyocfe

go test -v is fine

body, err := param.Request.GetBody()

but, request GetBody() nil pointer error occurred

Comment From: Kyocfe

func main() {
        r := gin.New()
    loggerConfig := footprint.NewLoggerConfig(footprint.DefaultLoggerFormatter, nil)
    r.Use(corsConfig, gin.LoggerWithConfig(loggerConfig), gin.Recovery())

    r.POST("", CreateGroup())
}

If the router group is not used, the log does work. but, if a router group is used, a blank value is output.

Comment From: Kyocfe

Success case

FootPrint Repo

main.go

package main

func main() {
    router = setUpRouter()

    router.Run(":8080")
}

func setUpRouter() *gin.Engine {
    r := gin.New()

    r.Use(useLogger(footprint.DefaultLoggerFormatter))
    r.Use(gin.Recovery())

    r.GET("")
    r.POST("", postTest())
    r.PUT("")
    r.DELETE("")

    group := r.Group("group")
    groupRouter(group)

    return r
}

func groupRouter(group *gin.RouterGroup) {
    group.POST("")
}

func useLogger(formatter func(params gin.LogFormatterParams) string) gin.HandlerFunc {
    loggerConfig := footprint.NewLoggerConfig(formatter, skipPaths)
    return gin.LoggerWithConfig(loggerConfig)
}

footprint/logger.go

const (
    defaultLogFormat            = "%s %-7s %s %s %3d %s [remote ip: \"%15s\", proto: \"%s\", agent: \"%s\"] -> \"%s\"(request id: %s) %v %13v error: \"%s\"\n"
    defaultLogFormatWithReqBody = "%s %-7s %s %s %3d %s [remote ip: \"%15s\", proto: \"%s\", agent: \"%s\"] -> \"%s\"(request id: %s) %v %13v request: \"%s\" error: \"%s\"\n"
)

func NewLoggerConfig(formatter func(gin.LogFormatterParams) string, skipPaths []string) gin.LoggerConfig {
    return gin.LoggerConfig{
        Formatter: formatter,
        SkipPaths: skipPaths,
    }
}

func DefaultLoggerFormatter(param gin.LogFormatterParams) string {
    requestID := generateRequestID()
    param.Request.Header.Set("X-Request-Id", requestID)

    if param.Method != http.MethodGet {
        return loggingWithReqBodyLog(param)
    }

    return loggingDefaultLog(param)
}

func loggingWithReqBodyLog(param gin.LogFormatterParams) string {
    var statusColor, methodColor, resetColor string
    if param.IsOutputColor() {
        statusColor = param.StatusCodeColor()
        methodColor = param.MethodColor()
        resetColor = param.ResetColor()
    }

    limitedReader := &io.LimitedReader{R: param.Request.Body, N: math.MaxInt64}
    blob, err := ioutil.ReadAll(limitedReader)
    if err != nil {
        fmt.Printf("read request body error: %v", err)
    }

    return fmt.Sprintf(defaultLogFormatWithReqBody,
        methodColor, param.Method, resetColor,
        statusColor, param.StatusCode, resetColor,
        param.ClientIP,
        param.Request.Proto,
        param.Request.UserAgent(),
        param.Path,
        param.Request.Header.Get("X-Request-Id"),
        param.TimeStamp.Format(time.RFC3339),
        param.Latency,
        blob,
        param.ErrorMessage,
    )
}

Fail Case

API Repo

main.go

package main

func main() {
        router = setUpRouter()
        router.Run(fmt.Sprintf(":%d", 8080))
}

func setUpRouter() *gin.Engine {
    config := newCorsConfig()

    r := gin.New()

    r.Use(useLogger(footprint.DefaultLoggerFormatter))
    r.Use(config)
    r.Use(gin.Recovery())

    r.GET("")

    registerRoute(r)

    return r
}

func registerRoute(r *gin.Engine) {
        group := r.Group("group")
        group.POST("")
}

Debugger Result

    limitedReader := &io.LimitedReader{R: param.Request.Body, N: math.MaxInt64}
    blob, err := ioutil.ReadAll(limitedReader)
    if err != nil {
        fmt.Printf("read request body error: %v", err)
    }
// FootPrint Repo
// ReadAll Result is []byte

// API Repo
// ReadAll Result is []byte length 0
// data exists in the body src of the pointer of the limitedReader, but when ReadAll() is executed, the data is 0.
// i was check using breakpoints

Comment From: Kyocfe

anybody here?

Comment From: patarapolw

I had to do it in another Middleware, as param.Request.Body always read nil (and param.Request.GetBody() always throw nil pointer reference).

    app.Use(func(c *gin.Context) {
        b, _ := ioutil.ReadAll(c.Request.Body)

        if len(b) > 0 {
            c.Request.Body = ioutil.NopCloser(bytes.NewBuffer(b))

            gin.DefaultWriter.Write([]byte("body: "))
            gin.DefaultWriter.Write(b)
            gin.DefaultWriter.Write([]byte("\n"))
        }
        c.Next()
    })

Comment From: rohitChaku

Since the body is already consumed before the gin logger logs the request, I decoded to parse the body in another middleware and store it in the gin request context c.Set("body", <parsed_request_body>) , then use it in the gin formatter as params.Keys["body"] so that I can see all the relevant info together. Pls advise if there is a better way, thanks.

Gin Request body print does not work on custom logger.

Description

How to reproduce

Origin Repository

Repository to import and use

Environment

Success case

FootPrint Repo

main.go

footprint/logger.go

Fail Case

API Repo

main.go

Debugger Result