From c9d43c85c733081aabf420c87e23fe291678db90 Mon Sep 17 00:00:00 2001 From: Belyenochi <491537461q@gmail.com> Date: Mon, 7 Mar 2022 20:27:23 +0800 Subject: [PATCH 1/6] feat: format gin logger --- pkg/api/server.go | 2 +- pkg/log/gin_logger.go | 67 ++++++++++++++++++++++++ pkg/log/gin_logger_test.go | 101 +++++++++++++++++++++++++++++++++++++ 3 files changed, 169 insertions(+), 1 deletion(-) create mode 100644 pkg/log/gin_logger.go create mode 100644 pkg/log/gin_logger_test.go diff --git a/pkg/api/server.go b/pkg/api/server.go index 6474d46690..95027d8d10 100644 --- a/pkg/api/server.go +++ b/pkg/api/server.go @@ -50,7 +50,7 @@ func NewServer(cfg *config.Config) (*Server, error) { } gin.SetMode(gin.ReleaseMode) httpServer := gin.New() - httpServer.Use(gin.Recovery(), gin.Logger()) + httpServer.Use(log.GinRecovery(log.DefaultLogger, true), log.GinLogger(log.DefaultLogger)) apirouter.Mount(httpServer) srv := &Server{ diff --git a/pkg/log/gin_logger.go b/pkg/log/gin_logger.go new file mode 100644 index 0000000000..8b5fb96d37 --- /dev/null +++ b/pkg/log/gin_logger.go @@ -0,0 +1,67 @@ +package log + +import ( + "github.com/gin-gonic/gin" + "net" + "net/http" + "net/http/httputil" + "os" + "runtime/debug" + "strings" + "time" +) + +func GinLogger(logger *Logger) gin.HandlerFunc { + return func(c *gin.Context) { + start := time.Now() + path := c.Request.URL.Path + query := c.Request.URL.RawQuery + c.Next() + cost := time.Since(start) + + logger.Infof("path: %s, status: %d, method: %s, query: %s, ip: %s, user-agent: %s, errors: %s, cost: %s", + path, c.Writer.Status(), c.Request.Method, query, c.ClientIP(), c.Request.UserAgent(), c.Errors.ByType(gin.ErrorTypePrivate).String(), cost) + } +} + +// GinRecovery recover Drop the project that may appear panic +func GinRecovery(logger *Logger, stack bool) gin.HandlerFunc { + return func(c *gin.Context) { + defer func() { + if err := recover(); err != nil { + // Check for a broken connection, as it is not really a + // condition that warrants a panic stack trace. + var brokenPipe bool + if ne, ok := err.(*net.OpError); ok { + if se, ok := ne.Err.(*os.SyscallError); ok { + if strings.Contains(strings.ToLower(se.Error()), "broken pipe") || + strings.Contains(strings.ToLower(se.Error()), "connection reset by peer") { + brokenPipe = true + } + } + } + httpRequest, _ := httputil.DumpRequest(c.Request, false) + if brokenPipe { + logger.Errorf("path: %s, error: %s, request: %s", + c.Request.URL.Path, err, string(httpRequest)) + // If the connection is dead, we can't write a status to it. + c.Error(err.(error)) // nolint: errcheck + c.Abort() + + return + } + if stack { + logger.Errorf("error: [Recovery from panic] %s, request: %s, stack: %s", + err, string(httpRequest), string(debug.Stack()), + ) + } else { + logger.Errorf("error: [Recovery from panic] %s, request: %s", + err, string(httpRequest)) + } + c.AbortWithStatus(http.StatusInternalServerError) + } + }() + c.Next() + } +} + diff --git a/pkg/log/gin_logger_test.go b/pkg/log/gin_logger_test.go new file mode 100644 index 0000000000..0136879b6b --- /dev/null +++ b/pkg/log/gin_logger_test.go @@ -0,0 +1,101 @@ +// Licensed to the Apache Software Foundation (ASF) under one or more +// contributor license agreements. See the NOTICE file distributed with +// this work for additional information regarding copyright ownership. +// The ASF licenses this file to You under the Apache License, Version 2.0 +// (the "License"); you may not use this file except in compliance with +// the License. You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. +package log + +import ( + "fmt" + "github.com/gin-gonic/gin" + "net/http" + "net/http/httptest" + "testing" + + "github.com/stretchr/testify/assert" +) + +const TestMode = "test" + +func init() { + gin.SetMode(TestMode) +} + +type header struct { + Key string + Value string +} + +func performRequest(r http.Handler, method, path string, headers ...header) *httptest.ResponseRecorder { + req := httptest.NewRequest(method, path, nil) + for _, h := range headers { + req.Header.Add(h.Key, h.Value) + } + w := httptest.NewRecorder() + r.ServeHTTP(w, req) + return w +} + +func TestGinLogger(t *testing.T) { + t.Run("test log with gin logger", func(t *testing.T) { + fws := &fakeWriteSyncer{} + logger, err := NewLogger(WithLogLevel("debug"), WithWriteSyncer(fws)) + assert.Nil(t, err, "failed to new logger: ", err) + defer logger.Close() + + router := gin.New() + router.Use(GinLogger(logger)) + router.GET("/healthz", func(c *gin.Context) {}) + performRequest(router, "GET", "/healthz") + res := string(fws.bytes()) + assert.Contains(t, res, "200") + assert.Contains(t, res, "GET") + assert.Contains(t, res, "/healthz") + }) +} + +func TestGinRecovery(t *testing.T) { + t.Run("test log with gin recovery with stack", func(t *testing.T) { + fws := &fakeWriteSyncer{} + logger, err := NewLogger(WithLogLevel("debug"), WithWriteSyncer(fws)) + assert.Nil(t, err, "failed to new logger: ", err) + defer logger.Close() + + router := gin.New() + router.Use(GinRecovery(logger, true)) + router.GET("/healthz", func(c *gin.Context) {panic("test log with gin recovery")}) + performRequest(router, "GET", "/healthz") + res := string(fws.bytes()) + fmt.Println(res) + assert.Contains(t, res, "caller") + assert.Contains(t, res, "GET") + assert.Contains(t, res, "/healthz") + assert.Contains(t, res, "stack") + }) + t.Run("test log with gin recovery", func(t *testing.T) { + fws := &fakeWriteSyncer{} + logger, err := NewLogger(WithLogLevel("debug"), WithWriteSyncer(fws)) + assert.Nil(t, err, "failed to new logger: ", err) + defer logger.Close() + + router := gin.New() + router.Use(GinRecovery(logger, false)) + router.GET("/healthz", func(c *gin.Context) {panic("test log with gin recovery")}) + performRequest(router, "GET", "/healthz") + res := string(fws.bytes()) + fmt.Println(res) + assert.Contains(t, res, "caller") + assert.Contains(t, res, "GET") + assert.Contains(t, res, "/healthz") + assert.NotContains(t, res, "stack") + }) +} \ No newline at end of file From 85dd53221a8df7cc1c094688ce24be9cd93af9b8 Mon Sep 17 00:00:00 2001 From: Belyenochi <491537461q@gmail.com> Date: Tue, 8 Mar 2022 11:19:15 +0800 Subject: [PATCH 2/6] fix: run go-fmt and add apache license --- pkg/log/gin_logger.go | 18 ++++++++++++++++-- pkg/log/gin_logger_test.go | 10 +++++----- 2 files changed, 21 insertions(+), 7 deletions(-) diff --git a/pkg/log/gin_logger.go b/pkg/log/gin_logger.go index 8b5fb96d37..d1d4e5402e 100644 --- a/pkg/log/gin_logger.go +++ b/pkg/log/gin_logger.go @@ -1,7 +1,20 @@ +// Licensed to the Apache Software Foundation (ASF) under one or more +// contributor license agreements. See the NOTICE file distributed with +// this work for additional information regarding copyright ownership. +// The ASF licenses this file to You under the Apache License, Version 2.0 +// (the "License"); you may not use this file except in compliance with +// the License. You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. package log import ( - "github.com/gin-gonic/gin" "net" "net/http" "net/http/httputil" @@ -9,6 +22,8 @@ import ( "runtime/debug" "strings" "time" + + "github.com/gin-gonic/gin" ) func GinLogger(logger *Logger) gin.HandlerFunc { @@ -64,4 +79,3 @@ func GinRecovery(logger *Logger, stack bool) gin.HandlerFunc { c.Next() } } - diff --git a/pkg/log/gin_logger_test.go b/pkg/log/gin_logger_test.go index 0136879b6b..4e749be6db 100644 --- a/pkg/log/gin_logger_test.go +++ b/pkg/log/gin_logger_test.go @@ -16,17 +16,17 @@ package log import ( "fmt" - "github.com/gin-gonic/gin" "net/http" "net/http/httptest" "testing" + "github.com/gin-gonic/gin" "github.com/stretchr/testify/assert" ) const TestMode = "test" -func init() { +func init() { gin.SetMode(TestMode) } @@ -72,7 +72,7 @@ func TestGinRecovery(t *testing.T) { router := gin.New() router.Use(GinRecovery(logger, true)) - router.GET("/healthz", func(c *gin.Context) {panic("test log with gin recovery")}) + router.GET("/healthz", func(c *gin.Context) { panic("test log with gin recovery") }) performRequest(router, "GET", "/healthz") res := string(fws.bytes()) fmt.Println(res) @@ -89,7 +89,7 @@ func TestGinRecovery(t *testing.T) { router := gin.New() router.Use(GinRecovery(logger, false)) - router.GET("/healthz", func(c *gin.Context) {panic("test log with gin recovery")}) + router.GET("/healthz", func(c *gin.Context) { panic("test log with gin recovery") }) performRequest(router, "GET", "/healthz") res := string(fws.bytes()) fmt.Println(res) @@ -98,4 +98,4 @@ func TestGinRecovery(t *testing.T) { assert.Contains(t, res, "/healthz") assert.NotContains(t, res, "stack") }) -} \ No newline at end of file +} From 8cf264886f876ce27507245670773c09d5431d8f Mon Sep 17 00:00:00 2001 From: Belyenochi <491537461q@gmail.com> Date: Tue, 8 Mar 2022 13:01:43 +0800 Subject: [PATCH 3/6] fix: add go mod entry --- test/e2e/go.sum | 9 +++++++++ 1 file changed, 9 insertions(+) diff --git a/test/e2e/go.sum b/test/e2e/go.sum index 04d2bc0fdf..b197130157 100644 --- a/test/e2e/go.sum +++ b/test/e2e/go.sum @@ -221,7 +221,9 @@ github.com/gavv/httpexpect/v2 v2.2.0 h1:0VwaEBmQaNFHX9x591A8Up+8shCwdF/nF0qlRd/n github.com/gavv/httpexpect/v2 v2.2.0/go.mod h1:lnd0TqJLrP+wkJk3SFwtrpSlOAZQ7HaaIFuOYbgqgUM= github.com/ghodss/yaml v0.0.0-20150909031657-73d445a93680/go.mod h1:4dBDuWmgqj2HViK6kFavaiC9ZROes6MMH2rRYeMEF04= github.com/ghodss/yaml v1.0.0/go.mod h1:4dBDuWmgqj2HViK6kFavaiC9ZROes6MMH2rRYeMEF04= +github.com/gin-contrib/sse v0.1.0 h1:Y/yl/+YNO8GZSjAhjMsSuLt29uWRFHdHYUb5lYOV9qE= github.com/gin-contrib/sse v0.1.0/go.mod h1:RHrZQHXnP2xjPF+u1gW/2HnVO7nvIa9PG3Gm+fLHvGI= +github.com/gin-gonic/gin v1.7.7 h1:3DoBmSbJbZAWqXJC3SLjAPfutPJJRN1U5pALB7EeTTs= github.com/gin-gonic/gin v1.7.7/go.mod h1:axIBovoeJpVj8S3BwE0uPMTeReE4+AfFtqpqaZ1qq1U= github.com/go-errors/errors v1.0.1/go.mod h1:f4zRHt4oKfwPJE5k8C9vpYG+aDHdBFUsgrm6/TyX73Q= github.com/go-errors/errors v1.0.2-0.20180813162953-d98b870cc4e0 h1:skJKxRtNmevLqnayafdLe2AsenqRupVmzZSqrvb5caU= @@ -255,9 +257,13 @@ github.com/go-openapi/swag v0.0.0-20160704191624-1d0bd113de87/go.mod h1:DXUve3Dp github.com/go-openapi/swag v0.19.2/go.mod h1:POnQmlKehdgb5mhVOsnJFsivZCEZ/vjK9gh66Z9tfKk= github.com/go-openapi/swag v0.19.5/go.mod h1:POnQmlKehdgb5mhVOsnJFsivZCEZ/vjK9gh66Z9tfKk= github.com/go-openapi/swag v0.19.14/go.mod h1:QYRuS/SOXUCsnplDa677K7+DxSOj6IPNl/eQntq43wQ= +github.com/go-playground/assert/v2 v2.0.1 h1:MsBgLAaY856+nPRTKrp3/OZK38U/wa0CcBYNjji3q3A= github.com/go-playground/assert/v2 v2.0.1/go.mod h1:VDjEfimB/XKnb+ZQfWdccd7VUvScMdVu0Titje2rxJ4= +github.com/go-playground/locales v0.13.0 h1:HyWk6mgj5qFqCT5fjGBuRArbVDfE4hi8+e8ceBS/t7Q= github.com/go-playground/locales v0.13.0/go.mod h1:taPMhCMXrRLJO55olJkUXHZBHCxTMfnGwq/HNwmWNS8= +github.com/go-playground/universal-translator v0.17.0 h1:icxd5fm+REJzpZx7ZfpaD876Lmtgy7VtROAbHHXk8no= github.com/go-playground/universal-translator v0.17.0/go.mod h1:UkSxE5sNxxRwHyU+Scu5vgOQjsIJAF8j9muTVoKLVtA= +github.com/go-playground/validator/v10 v10.4.1 h1:pH2c5ADXtd66mxoE0Zm9SUhxE20r7aM3F26W0hOn+GE= github.com/go-playground/validator/v10 v10.4.1/go.mod h1:nlOn6nFhuKACm19sB/8EGNn9GlaMV7XkbRSipzJ0Ii4= github.com/go-sql-driver/mysql v1.4.1 h1:g24URVg0OFbNUTx9qqY1IRZ9D9z3iPyi5zKhQZpNwpA= github.com/go-sql-driver/mysql v1.4.1/go.mod h1:zAC/RDZ24gD3HViQzih4MyKcchzm+sOG5ZlKdlhCg5w= @@ -462,6 +468,7 @@ github.com/kr/text v0.1.0/go.mod h1:4Jbv+DJW3UT/LiOwJeYQe1efqtUx/iVham/4vfdArNI= github.com/kr/text v0.2.0 h1:5Nx0Ya0ZqY2ygV366QzturHI13Jq95ApcVaJBhpS+AY= github.com/kr/text v0.2.0/go.mod h1:eLer722TekiGuMkidMxC/pM04lWEeraHUUmBw8l2grE= github.com/kylelemons/godebug v0.0.0-20170820004349-d65d576e9348/go.mod h1:B69LEHPfb2qLo0BaaOLcbitczOKLWTsrBG9LczfCD4k= +github.com/leodido/go-urn v1.2.0 h1:hpXL4XnriNwQ/ABnpepYM/1vCLWNDfUNts8dX3xTG6Y= github.com/leodido/go-urn v1.2.0/go.mod h1:+8+nEpDfqqsY+g338gtMEUOtuK+4dEMhiQEgxpxOKII= github.com/lithammer/dedent v1.1.0/go.mod h1:jrXYCQtgg0nJiN+StA2KgR7w6CiQNv9Fd/Z9BP0jIOc= github.com/magiconair/properties v1.8.0/go.mod h1:PppfXfuXeibc/6YijjN8zIbojt8czPbwD3XqdrwzmxQ= @@ -652,8 +659,10 @@ github.com/stretchr/testify v1.7.0/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/ github.com/subosito/gotenv v1.2.0/go.mod h1:N0PQaV/YGNqwC0u51sEeR/aUtSLEXKX9iv69rRypqCw= github.com/tmc/grpc-websocket-proxy v0.0.0-20170815181823-89b8d40f7ca8/go.mod h1:ncp9v5uamzpCO7NfCPTXjqaC+bZgJeR0sMTm6dMHP7U= github.com/tmc/grpc-websocket-proxy v0.0.0-20190109142713-0ad062ec5ee5/go.mod h1:ncp9v5uamzpCO7NfCPTXjqaC+bZgJeR0sMTm6dMHP7U= +github.com/ugorji/go v1.1.7 h1:/68gy2h+1mWMrwZFeD1kQialdSzAb432dtpeJ42ovdo= github.com/ugorji/go v1.1.7/go.mod h1:kZn38zHttfInRq0xu/PH0az30d+z6vm202qpg1oXVMw= github.com/ugorji/go/codec v0.0.0-20181204163529-d75b2dcb6bc8/go.mod h1:VFNgLljTbGfSG7qAOspJ7OScBnGdDN/yBr0sguwnwf0= +github.com/ugorji/go/codec v1.1.7 h1:2SvQaVZ1ouYrrKKwoSk2pzd4A9evlKJb9oTL+OaLUSs= github.com/ugorji/go/codec v1.1.7/go.mod h1:Ax+UKWsSmolVDwsd+7N3ZtXu+yMGCf907BLYF3GoBXY= github.com/urfave/cli v1.20.0/go.mod h1:70zkFmudgCuE/ngEzBv17Jvp/497gISqfk5gWijbERA= github.com/urfave/cli v1.22.1/go.mod h1:Gos4lmkARVdJ6EkW0WaNv/tZAAMe9V7XWyB60NtXRu0= From b378263c4577d647aa779e9f3f622a6e2bee0aa4 Mon Sep 17 00:00:00 2001 From: Belyenochi <491537461q@gmail.com> Date: Tue, 8 Mar 2022 15:13:58 +0800 Subject: [PATCH 4/6] fix: add annotation for the GinLogger --- pkg/log/gin_logger.go | 1 + 1 file changed, 1 insertion(+) diff --git a/pkg/log/gin_logger.go b/pkg/log/gin_logger.go index d1d4e5402e..ae17316fac 100644 --- a/pkg/log/gin_logger.go +++ b/pkg/log/gin_logger.go @@ -26,6 +26,7 @@ import ( "github.com/gin-gonic/gin" ) +// GinLogger receive gin The default log of the framework func GinLogger(logger *Logger) gin.HandlerFunc { return func(c *gin.Context) { start := time.Now() From e1e2a7808eefcc05fe7a88cf5164323c1d152c35 Mon Sep 17 00:00:00 2001 From: Belyenochi <491537461q@gmail.com> Date: Tue, 8 Mar 2022 15:57:16 +0800 Subject: [PATCH 5/6] fix: change log level for 4xx and 5xx http status code --- pkg/log/gin_logger.go | 10 +++++++--- 1 file changed, 7 insertions(+), 3 deletions(-) diff --git a/pkg/log/gin_logger.go b/pkg/log/gin_logger.go index ae17316fac..f52e8a6127 100644 --- a/pkg/log/gin_logger.go +++ b/pkg/log/gin_logger.go @@ -34,9 +34,13 @@ func GinLogger(logger *Logger) gin.HandlerFunc { query := c.Request.URL.RawQuery c.Next() cost := time.Since(start) - - logger.Infof("path: %s, status: %d, method: %s, query: %s, ip: %s, user-agent: %s, errors: %s, cost: %s", - path, c.Writer.Status(), c.Request.Method, query, c.ClientIP(), c.Request.UserAgent(), c.Errors.ByType(gin.ErrorTypePrivate).String(), cost) + if c.Writer.Status() >= 400 && c.Writer.Status() <= 599 { + logger.Errorf("path: %s, status: %d, method: %s, query: %s, ip: %s, user-agent: %s, errors: %s, cost: %s", + path, c.Writer.Status(), c.Request.Method, query, c.ClientIP(), c.Request.UserAgent(), c.Errors.ByType(gin.ErrorTypePrivate).String(), cost) + } else { + logger.Infof("path: %s, status: %d, method: %s, query: %s, ip: %s, user-agent: %s, errors: %s, cost: %s", + path, c.Writer.Status(), c.Request.Method, query, c.ClientIP(), c.Request.UserAgent(), c.Errors.ByType(gin.ErrorTypePrivate).String(), cost) + } } } From 36fa4d3dd0dc86326b6e7f662cade094328c5b1e Mon Sep 17 00:00:00 2001 From: Belyenochi <491537461q@gmail.com> Date: Tue, 8 Mar 2022 16:11:58 +0800 Subject: [PATCH 6/6] fix: add error log level test case --- pkg/log/gin_logger_test.go | 23 +++++++++++++++++++++++ 1 file changed, 23 insertions(+) diff --git a/pkg/log/gin_logger_test.go b/pkg/log/gin_logger_test.go index 4e749be6db..c4cad47527 100644 --- a/pkg/log/gin_logger_test.go +++ b/pkg/log/gin_logger_test.go @@ -61,6 +61,29 @@ func TestGinLogger(t *testing.T) { assert.Contains(t, res, "GET") assert.Contains(t, res, "/healthz") }) + t.Run("test log with gin logger 4xx and 5xx", func(t *testing.T) { + fws := &fakeWriteSyncer{} + logger, err := NewLogger(WithLogLevel("debug"), WithWriteSyncer(fws)) + assert.Nil(t, err, "failed to new logger: ", err) + defer logger.Close() + + router := gin.New() + router.Use(GinLogger(logger)) + router.GET("/healthz", func(c *gin.Context) { c.JSON(500, nil) }) + performRequest(router, "GET", "/healthz") + res := string(fws.bytes()) + assert.Contains(t, res, "500") + assert.Contains(t, res, "GET") + assert.Contains(t, res, "/healthz") + assert.Contains(t, res, "error") + router.GET("/healthz-check", func(c *gin.Context) { c.JSON(400, nil) }) + performRequest(router, "GET", "/healthz-check") + res = string(fws.bytes()) + assert.Contains(t, res, "400") + assert.Contains(t, res, "GET") + assert.Contains(t, res, "/healthz-check") + assert.Contains(t, res, "error") + }) } func TestGinRecovery(t *testing.T) {