gin/logger_test.go

471 lines
14 KiB
Go

// Copyright 2014 Manu Martinez-Almeida. All rights reserved.
// Use of this source code is governed by a MIT style
// license that can be found in the LICENSE file.
package gin
import (
"errors"
"fmt"
"net/http"
"strings"
"testing"
"time"
"github.com/stretchr/testify/assert"
)
func init() {
SetMode(TestMode)
}
func TestLogger(t *testing.T) {
buffer := new(strings.Builder)
router := New()
router.Use(LoggerWithWriter(buffer))
router.GET("/example", func(c *Context) {})
router.POST("/example", func(c *Context) {})
router.PUT("/example", func(c *Context) {})
router.DELETE("/example", func(c *Context) {})
router.PATCH("/example", func(c *Context) {})
router.HEAD("/example", func(c *Context) {})
router.OPTIONS("/example", func(c *Context) {})
PerformRequest(router, "GET", "/example?a=100")
assert.Contains(t, buffer.String(), "200")
assert.Contains(t, buffer.String(), "GET")
assert.Contains(t, buffer.String(), "/example")
assert.Contains(t, buffer.String(), "a=100")
// I wrote these first (extending the above) but then realized they are more
// like integration tests because they test the whole logging process rather
// than individual functions. Im not sure where these should go.
buffer.Reset()
PerformRequest(router, "POST", "/example")
assert.Contains(t, buffer.String(), "200")
assert.Contains(t, buffer.String(), "POST")
assert.Contains(t, buffer.String(), "/example")
buffer.Reset()
PerformRequest(router, "PUT", "/example")
assert.Contains(t, buffer.String(), "200")
assert.Contains(t, buffer.String(), "PUT")
assert.Contains(t, buffer.String(), "/example")
buffer.Reset()
PerformRequest(router, "DELETE", "/example")
assert.Contains(t, buffer.String(), "200")
assert.Contains(t, buffer.String(), "DELETE")
assert.Contains(t, buffer.String(), "/example")
buffer.Reset()
PerformRequest(router, "PATCH", "/example")
assert.Contains(t, buffer.String(), "200")
assert.Contains(t, buffer.String(), "PATCH")
assert.Contains(t, buffer.String(), "/example")
buffer.Reset()
PerformRequest(router, "HEAD", "/example")
assert.Contains(t, buffer.String(), "200")
assert.Contains(t, buffer.String(), "HEAD")
assert.Contains(t, buffer.String(), "/example")
buffer.Reset()
PerformRequest(router, "OPTIONS", "/example")
assert.Contains(t, buffer.String(), "200")
assert.Contains(t, buffer.String(), "OPTIONS")
assert.Contains(t, buffer.String(), "/example")
buffer.Reset()
PerformRequest(router, "GET", "/notfound")
assert.Contains(t, buffer.String(), "404")
assert.Contains(t, buffer.String(), "GET")
assert.Contains(t, buffer.String(), "/notfound")
}
func TestLoggerWithConfig(t *testing.T) {
buffer := new(strings.Builder)
router := New()
router.Use(LoggerWithConfig(LoggerConfig{Output: buffer}))
router.GET("/example", func(c *Context) {})
router.POST("/example", func(c *Context) {})
router.PUT("/example", func(c *Context) {})
router.DELETE("/example", func(c *Context) {})
router.PATCH("/example", func(c *Context) {})
router.HEAD("/example", func(c *Context) {})
router.OPTIONS("/example", func(c *Context) {})
PerformRequest(router, "GET", "/example?a=100")
assert.Contains(t, buffer.String(), "200")
assert.Contains(t, buffer.String(), "GET")
assert.Contains(t, buffer.String(), "/example")
assert.Contains(t, buffer.String(), "a=100")
// I wrote these first (extending the above) but then realized they are more
// like integration tests because they test the whole logging process rather
// than individual functions. Im not sure where these should go.
buffer.Reset()
PerformRequest(router, "POST", "/example")
assert.Contains(t, buffer.String(), "200")
assert.Contains(t, buffer.String(), "POST")
assert.Contains(t, buffer.String(), "/example")
buffer.Reset()
PerformRequest(router, "PUT", "/example")
assert.Contains(t, buffer.String(), "200")
assert.Contains(t, buffer.String(), "PUT")
assert.Contains(t, buffer.String(), "/example")
buffer.Reset()
PerformRequest(router, "DELETE", "/example")
assert.Contains(t, buffer.String(), "200")
assert.Contains(t, buffer.String(), "DELETE")
assert.Contains(t, buffer.String(), "/example")
buffer.Reset()
PerformRequest(router, "PATCH", "/example")
assert.Contains(t, buffer.String(), "200")
assert.Contains(t, buffer.String(), "PATCH")
assert.Contains(t, buffer.String(), "/example")
buffer.Reset()
PerformRequest(router, "HEAD", "/example")
assert.Contains(t, buffer.String(), "200")
assert.Contains(t, buffer.String(), "HEAD")
assert.Contains(t, buffer.String(), "/example")
buffer.Reset()
PerformRequest(router, "OPTIONS", "/example")
assert.Contains(t, buffer.String(), "200")
assert.Contains(t, buffer.String(), "OPTIONS")
assert.Contains(t, buffer.String(), "/example")
buffer.Reset()
PerformRequest(router, "GET", "/notfound")
assert.Contains(t, buffer.String(), "404")
assert.Contains(t, buffer.String(), "GET")
assert.Contains(t, buffer.String(), "/notfound")
}
func TestLoggerWithFormatter(t *testing.T) {
buffer := new(strings.Builder)
d := DefaultWriter
DefaultWriter = buffer
defer func() {
DefaultWriter = d
}()
router := New()
router.Use(LoggerWithFormatter(func(param LogFormatterParams) string {
return fmt.Sprintf("[FORMATTER TEST] %v | %3d | %13v | %15s | %-7s %#v\n%s",
param.TimeStamp.Format("2006/01/02 - 15:04:05"),
param.StatusCode,
param.Latency,
param.ClientIP,
param.Method,
param.Path,
param.ErrorMessage,
)
}))
router.GET("/example", func(c *Context) {})
PerformRequest(router, "GET", "/example?a=100")
// output test
assert.Contains(t, buffer.String(), "[FORMATTER TEST]")
assert.Contains(t, buffer.String(), "200")
assert.Contains(t, buffer.String(), "GET")
assert.Contains(t, buffer.String(), "/example")
assert.Contains(t, buffer.String(), "a=100")
}
func TestLoggerWithConfigFormatting(t *testing.T) {
var gotParam LogFormatterParams
var gotKeys map[string]any
buffer := new(strings.Builder)
router := New()
router.engine.trustedCIDRs, _ = router.engine.prepareTrustedCIDRs()
router.Use(LoggerWithConfig(LoggerConfig{
Output: buffer,
Formatter: func(param LogFormatterParams) string {
// for assert test
gotParam = param
return fmt.Sprintf("[FORMATTER TEST] %v | %3d | %13v | %15s | %-7s %s\n%s",
param.TimeStamp.Format("2006/01/02 - 15:04:05"),
param.StatusCode,
param.Latency,
param.ClientIP,
param.Method,
param.Path,
param.ErrorMessage,
)
},
}))
router.GET("/example", func(c *Context) {
// set dummy ClientIP
c.Request.Header.Set("X-Forwarded-For", "20.20.20.20")
gotKeys = c.Keys
time.Sleep(time.Millisecond)
})
PerformRequest(router, "GET", "/example?a=100")
// output test
assert.Contains(t, buffer.String(), "[FORMATTER TEST]")
assert.Contains(t, buffer.String(), "200")
assert.Contains(t, buffer.String(), "GET")
assert.Contains(t, buffer.String(), "/example")
assert.Contains(t, buffer.String(), "a=100")
// LogFormatterParams test
assert.NotNil(t, gotParam.Request)
assert.NotEmpty(t, gotParam.TimeStamp)
assert.Equal(t, 200, gotParam.StatusCode)
assert.NotEmpty(t, gotParam.Latency)
assert.Equal(t, "20.20.20.20", gotParam.ClientIP)
assert.Equal(t, "GET", gotParam.Method)
assert.Equal(t, "/example?a=100", gotParam.Path)
assert.Empty(t, gotParam.ErrorMessage)
assert.Equal(t, gotKeys, gotParam.Keys)
}
func TestDefaultLogFormatter(t *testing.T) {
timeStamp := time.Unix(1544173902, 0).UTC()
termFalseParam := LogFormatterParams{
TimeStamp: timeStamp,
StatusCode: 200,
Latency: time.Second * 5,
ClientIP: "20.20.20.20",
Method: "GET",
Path: "/",
ErrorMessage: "",
isTerm: false,
}
termTrueParam := LogFormatterParams{
TimeStamp: timeStamp,
StatusCode: 200,
Latency: time.Second * 5,
ClientIP: "20.20.20.20",
Method: "GET",
Path: "/",
ErrorMessage: "",
isTerm: true,
}
termTrueLongDurationParam := LogFormatterParams{
TimeStamp: timeStamp,
StatusCode: 200,
Latency: time.Millisecond * 9876543210,
ClientIP: "20.20.20.20",
Method: "GET",
Path: "/",
ErrorMessage: "",
isTerm: true,
}
termFalseLongDurationParam := LogFormatterParams{
TimeStamp: timeStamp,
StatusCode: 200,
Latency: time.Millisecond * 9876543210,
ClientIP: "20.20.20.20",
Method: "GET",
Path: "/",
ErrorMessage: "",
isTerm: false,
}
assert.Equal(t, "[GIN] 2018/12/07 - 09:11:42 | 200 | 5s | 20.20.20.20 | GET \"/\"\n", defaultLogFormatter(termFalseParam))
assert.Equal(t, "[GIN] 2018/12/07 - 09:11:42 | 200 | 2743h29m3s | 20.20.20.20 | GET \"/\"\n", defaultLogFormatter(termFalseLongDurationParam))
assert.Equal(t, "[GIN] 2018/12/07 - 09:11:42 |\x1b[97;42m 200 \x1b[0m| 5s | 20.20.20.20 |\x1b[97;44m GET \x1b[0m \"/\"\n", defaultLogFormatter(termTrueParam))
assert.Equal(t, "[GIN] 2018/12/07 - 09:11:42 |\x1b[97;42m 200 \x1b[0m| 2743h29m3s | 20.20.20.20 |\x1b[97;44m GET \x1b[0m \"/\"\n", defaultLogFormatter(termTrueLongDurationParam))
}
func TestColorForMethod(t *testing.T) {
colorForMethod := func(method string) string {
p := LogFormatterParams{
Method: method,
}
return p.MethodColor()
}
assert.Equal(t, blue, colorForMethod("GET"), "get should be blue")
assert.Equal(t, cyan, colorForMethod("POST"), "post should be cyan")
assert.Equal(t, yellow, colorForMethod("PUT"), "put should be yellow")
assert.Equal(t, red, colorForMethod("DELETE"), "delete should be red")
assert.Equal(t, green, colorForMethod("PATCH"), "patch should be green")
assert.Equal(t, magenta, colorForMethod("HEAD"), "head should be magenta")
assert.Equal(t, white, colorForMethod("OPTIONS"), "options should be white")
assert.Equal(t, reset, colorForMethod("TRACE"), "trace is not defined and should be the reset color")
}
func TestColorForStatus(t *testing.T) {
colorForStatus := func(code int) string {
p := LogFormatterParams{
StatusCode: code,
}
return p.StatusCodeColor()
}
assert.Equal(t, white, colorForStatus(http.StatusContinue), "1xx should be white")
assert.Equal(t, green, colorForStatus(http.StatusOK), "2xx should be green")
assert.Equal(t, white, colorForStatus(http.StatusMovedPermanently), "3xx should be white")
assert.Equal(t, yellow, colorForStatus(http.StatusNotFound), "4xx should be yellow")
assert.Equal(t, red, colorForStatus(2), "other things should be red")
}
func TestResetColor(t *testing.T) {
p := LogFormatterParams{}
assert.Equal(t, string([]byte{27, 91, 48, 109}), p.ResetColor())
}
func TestIsOutputColor(t *testing.T) {
// test with isTerm flag true.
p := LogFormatterParams{
isTerm: true,
}
consoleColorMode = autoColor
assert.True(t, p.IsOutputColor())
ForceConsoleColor()
assert.True(t, p.IsOutputColor())
DisableConsoleColor()
assert.False(t, p.IsOutputColor())
// test with isTerm flag false.
p = LogFormatterParams{
isTerm: false,
}
consoleColorMode = autoColor
assert.False(t, p.IsOutputColor())
ForceConsoleColor()
assert.True(t, p.IsOutputColor())
DisableConsoleColor()
assert.False(t, p.IsOutputColor())
// reset console color mode.
consoleColorMode = autoColor
}
func TestErrorLogger(t *testing.T) {
router := New()
router.Use(ErrorLogger())
router.GET("/error", func(c *Context) {
c.Error(errors.New("this is an error")) //nolint: errcheck
})
router.GET("/abort", func(c *Context) {
c.AbortWithError(http.StatusUnauthorized, errors.New("no authorized")) //nolint: errcheck
})
router.GET("/print", func(c *Context) {
c.Error(errors.New("this is an error")) //nolint: errcheck
c.String(http.StatusInternalServerError, "hola!")
})
w := PerformRequest(router, "GET", "/error")
assert.Equal(t, http.StatusOK, w.Code)
assert.Equal(t, "{\"error\":\"this is an error\"}", w.Body.String())
w = PerformRequest(router, "GET", "/abort")
assert.Equal(t, http.StatusUnauthorized, w.Code)
assert.Equal(t, "{\"error\":\"no authorized\"}", w.Body.String())
w = PerformRequest(router, "GET", "/print")
assert.Equal(t, http.StatusInternalServerError, w.Code)
assert.Equal(t, "hola!{\"error\":\"this is an error\"}", w.Body.String())
}
func TestLoggerWithWriterSkippingPaths(t *testing.T) {
buffer := new(strings.Builder)
router := New()
router.Use(LoggerWithWriter(buffer, "/skipped"))
router.GET("/logged", func(c *Context) {})
router.GET("/skipped", func(c *Context) {})
PerformRequest(router, "GET", "/logged")
assert.Contains(t, buffer.String(), "200")
buffer.Reset()
PerformRequest(router, "GET", "/skipped")
assert.Contains(t, buffer.String(), "")
}
func TestLoggerWithConfigSkippingPaths(t *testing.T) {
buffer := new(strings.Builder)
router := New()
router.Use(LoggerWithConfig(LoggerConfig{
Output: buffer,
SkipPaths: []string{"/skipped"},
}))
router.GET("/logged", func(c *Context) {})
router.GET("/skipped", func(c *Context) {})
PerformRequest(router, "GET", "/logged")
assert.Contains(t, buffer.String(), "200")
buffer.Reset()
PerformRequest(router, "GET", "/skipped")
assert.Contains(t, buffer.String(), "")
}
func TestLoggerWithConfigSkipper(t *testing.T) {
buffer := new(strings.Builder)
router := New()
router.Use(LoggerWithConfig(LoggerConfig{
Output: buffer,
Skip: func(c *Context) bool {
return c.Writer.Status() == http.StatusNoContent
},
}))
router.GET("/logged", func(c *Context) { c.Status(http.StatusOK) })
router.GET("/skipped", func(c *Context) { c.Status(http.StatusNoContent) })
PerformRequest(router, "GET", "/logged")
assert.Contains(t, buffer.String(), "200")
buffer.Reset()
PerformRequest(router, "GET", "/skipped")
assert.Contains(t, buffer.String(), "")
}
func TestDisableConsoleColor(t *testing.T) {
New()
assert.Equal(t, autoColor, consoleColorMode)
DisableConsoleColor()
assert.Equal(t, disableColor, consoleColorMode)
// reset console color mode.
consoleColorMode = autoColor
}
func TestForceConsoleColor(t *testing.T) {
New()
assert.Equal(t, autoColor, consoleColorMode)
ForceConsoleColor()
assert.Equal(t, forceColor, consoleColorMode)
// reset console color mode.
consoleColorMode = autoColor
}
func TestLoggerWithConfigSkipQueryString(t *testing.T) {
buffer := new(strings.Builder)
router := New()
router.Use(LoggerWithConfig(LoggerConfig{
Output: buffer,
SkipQueryString: true,
}))
router.GET("/logged", func(c *Context) { c.Status(http.StatusOK) })
PerformRequest(router, "GET", "/logged?a=21")
assert.Contains(t, buffer.String(), "200")
assert.NotContains(t, buffer.String(), "a=21")
}