From bfd32d5b05b31bb47645e1bfa78dcf06604fc9df Mon Sep 17 00:00:00 2001 From: lordspinach Date: Mon, 19 Dec 2022 14:03:20 +0300 Subject: [PATCH] src: refactored logging and recovery middlewares --- src/infrastructure/LogrusHttpLogDbHook.go | 15 +- src/infrastructure/LogrusLogDbHook.go | 21 +- src/webapi/GinHttpServer.go | 2 +- src/webapi/controllers/GinHelpers.go | 4 +- src/webapi/middleware/Logger.go | 274 +++++++++++------- .../middleware/{recovery.go => Recovery.go} | 38 +-- 6 files changed, 191 insertions(+), 163 deletions(-) rename src/webapi/middleware/{recovery.go => Recovery.go} (73%) diff --git a/src/infrastructure/LogrusHttpLogDbHook.go b/src/infrastructure/LogrusHttpLogDbHook.go index 67c136ff..0659e317 100644 --- a/src/infrastructure/LogrusHttpLogDbHook.go +++ b/src/infrastructure/LogrusHttpLogDbHook.go @@ -9,7 +9,6 @@ import ( "rol/app/interfaces" "rol/app/utils" "rol/domain" - "strings" "sync" "time" @@ -20,9 +19,6 @@ import ( //HTTPBufSize buffer size for async hooks var HTTPBufSize uint = 8192 -const httpAPIName = "httplog" -const appAPIName = "applog" - //HTTPHook log hook struct type HTTPHook struct { repo interfaces.IGenericRepository[uuid.UUID, domain.HTTPLog] @@ -41,7 +37,7 @@ type HTTPAsyncHook struct { } var httpInsertFunc = func(entry *logrus.Entry, repository interfaces.IGenericRepository[uuid.UUID, domain.HTTPLog]) error { - if entry.Data["method"] != nil && !fromLogController(entry) { + if entry.Data["method"] != nil { ent := newEntityFromHTTP(entry) _, err := repository.Insert(nil, *ent) if err != nil { @@ -210,12 +206,3 @@ func (h *HTTPHook) Levels() []logrus.Level { logrus.DebugLevel, } } - -func fromLogController(entry *logrus.Entry) bool { - if entry.Data["path"] == nil { - return false - } else if strings.Contains(entry.Data["path"].(string), httpAPIName) || strings.Contains(entry.Data["path"].(string), appAPIName) { - return true - } - return false -} diff --git a/src/infrastructure/LogrusLogDbHook.go b/src/infrastructure/LogrusLogDbHook.go index 5b95a1b5..d4d1f30a 100644 --- a/src/infrastructure/LogrusLogDbHook.go +++ b/src/infrastructure/LogrusLogDbHook.go @@ -7,6 +7,7 @@ import ( "rol/app/errors" "rol/app/interfaces" "rol/domain" + "strings" "sync" "time" @@ -35,7 +36,7 @@ type AppAsyncHook struct { } var insertAppFunc = func(entry *logrus.Entry, repository interfaces.IGenericRepository[uuid.UUID, domain.AppLog]) error { - if entry.Data["method"] == nil && !fromLogController(entry) { + if entry.Data["method"] == nil { ent := newEntityFromApp(entry) _, err := repository.Insert(nil, *ent) if err != nil { @@ -59,12 +60,30 @@ var asyncAppInsertFunc = func(entry *logrus.Entry, repository interfaces.IGeneri func newEntityFromApp(entry *logrus.Entry) *domain.AppLog { var actionID uuid.UUID var source string + var messagePrefix string if entry.Data["actionID"] != nil { actionID = entry.Data["actionID"].(uuid.UUID) } if entry.Data["source"] != nil { source = entry.Data["source"].(string) } + + var sb strings.Builder + if _, ok := entry.Data["file"]; ok { + sb.WriteString(entry.Data["file"].(string) + ":") + } + if _, ok := entry.Data["line"]; ok { + line := entry.Data["line"].(int) + sb.WriteString(fmt.Sprintf("%d", line)) + } + if sb.String() != "" { + messagePrefix = sb.String() + "\n" + } + if source == "" { + source = sb.String() + } else { + entry.Message = messagePrefix + entry.Message + } return &domain.AppLog{ EntityUUID: domain.EntityUUID{ ID: uuid.New(), diff --git a/src/webapi/GinHttpServer.go b/src/webapi/GinHttpServer.go index 748f20b5..b0e03726 100644 --- a/src/webapi/GinHttpServer.go +++ b/src/webapi/GinHttpServer.go @@ -27,7 +27,7 @@ type GinHTTPServer struct { func NewGinHTTPServer(log *logrus.Logger, config *domain.AppConfig) *GinHTTPServer { ginEngine := gin.New() url := ginSwagger.URL("swagger/doc.json") - ginEngine.Use(middleware.Logger(log), middleware.Recovery(log)) + ginEngine.Use(middleware.Logger(log, "/swagger/", "/log/"), middleware.Recovery(log)) ginEngine.GET("/swagger/*any", ginSwagger.WrapHandler(swaggerFiles.Handler, url)) return &GinHTTPServer{ Engine: ginEngine, diff --git a/src/webapi/controllers/GinHelpers.go b/src/webapi/controllers/GinHelpers.go index 4e991dcc..e0e89082 100644 --- a/src/webapi/controllers/GinHelpers.go +++ b/src/webapi/controllers/GinHelpers.go @@ -63,7 +63,7 @@ func validationErrorToValidationErrorDto(err error) dtos.ValidationErrorDto { //if error = nil, then abort with http.StatusInternalServerError func abortWithStatusByErrorType(ctx *gin.Context, err error) { if errors.As(err, errors.Internal) || errors.As(err, errors.NoType) { - ctx.AbortWithStatus(http.StatusInternalServerError) + _ = ctx.AbortWithError(http.StatusInternalServerError, err) return } else if errors.As(err, errors.Validation) { ctx.JSON(http.StatusBadRequest, validationErrorToValidationErrorDto(err)) @@ -72,7 +72,7 @@ func abortWithStatusByErrorType(ctx *gin.Context, err error) { ctx.AbortWithStatus(http.StatusNotFound) return } - ctx.AbortWithStatus(http.StatusInternalServerError) + _ = ctx.AbortWithError(http.StatusInternalServerError, err) } //handle current request by error type, if error = nil, set http status to 204 (No Content) diff --git a/src/webapi/middleware/Logger.go b/src/webapi/middleware/Logger.go index 7272d7e9..c998f778 100644 --- a/src/webapi/middleware/Logger.go +++ b/src/webapi/middleware/Logger.go @@ -3,16 +3,16 @@ package middleware import ( "bytes" "fmt" + "github.com/gin-gonic/gin" + "github.com/google/uuid" + "github.com/sirupsen/logrus" "io/ioutil" "math" "net/http" "os" + "rol/app/errors" "strings" "time" - - "github.com/gin-gonic/gin" - "github.com/google/uuid" - "github.com/sirupsen/logrus" ) // 2016-09-27 09:38:21.541541811 +0200 CEST @@ -31,21 +31,163 @@ func (b bodyLogWriter) Write(bytes []byte) (int, error) { return b.ResponseWriter.Write(bytes) } -//Logger is the logrus logger handler -func Logger(logger logrus.FieldLogger, notLogged ...string) gin.HandlerFunc { - hostname, err := os.Hostname() - if err != nil { - hostname = "unknown" +func notLog(path string, notLogged []string) bool { + for _, n := range notLogged { + if strings.Contains(path, n) { + return true + } + } + return false +} + +func getOriginHeaders() map[string]bool { + return map[string]bool{ + "Accept": true, + "Accept-Encoding": true, + "Connection": true, + "Content-Length": true, + "Content-Type": true, + "User-Agent": true, + "Sec-Fetch-Dest": true, + "Accept-Language": true, + "Sec-Ch-Ua": true, + "Sec-Ch-Ua-Platform": true, + "Sec-Ch-Ua-Mobile": true, + "Sec-Fetch-Site": true, + "Sec-Fetch-Mode": true, + "Sec-Fetch-User": true, + "Referer": true, + "Cache-Control": true, + "Upgrade-Insecure-Requests": true, + } +} + +type handlerHelper struct { + c *gin.Context + logger logrus.FieldLogger + requestData +} + +func newHandlerHelper(c *gin.Context, logger logrus.FieldLogger, stop time.Duration) *handlerHelper { + h := &handlerHelper{ + c: c, + logger: logger, + } + h.requestData = h.getRequestData(stop) + return h +} + +type requestData struct { + latency int + statusCode int + clientIP string + clientUserAgent string + referer string + requestID uuid.UUID +} + +func (h *handlerHelper) getRequestData(stop time.Duration) requestData { + return requestData{ + latency: int(math.Ceil(float64(stop.Nanoseconds()) / 1000000.0)), + statusCode: h.c.Writer.Status(), + clientIP: h.c.ClientIP(), + clientUserAgent: h.c.Request.UserAgent(), + referer: h.c.Request.Referer(), + } +} + +func (h *handlerHelper) getStringHeaders() (string, string) { + originHeaders := getOriginHeaders() + headers := h.c.Request.Header + var headersString string + var customHeadersString string + for key, values := range headers { + for _, value := range values { + if originHeaders[key] { + headersString = fmt.Sprint(headersString + key + ":" + value + " ") + } else { + customHeadersString = fmt.Sprint(customHeadersString + key + ":" + value + " ") + } + } } + return headersString, customHeadersString +} + +func (h *handlerHelper) getBytesAndRestoreBody() []byte { + var bodyBytes []byte + if h.c.Request.Body != nil { + bodyBytes, _ = ioutil.ReadAll(h.c.Request.Body) + } + // Restore the io.ReadCloser to its original state + h.c.Request.Body = ioutil.NopCloser(bytes.NewBuffer(bodyBytes)) + + return bodyBytes +} - var skip map[string]struct{} +func (h *handlerHelper) getResponseHeaders() string { + var respHeadersArr []string + for header := range h.c.Writer.Header() { + respHeadersArr = append(respHeadersArr, header) + } + var respHeaders string + for _, value := range respHeadersArr { + respHeaders += value + ":" + h.c.Writer.Header().Get(value) + " " + } + return respHeaders +} - if length := len(notLogged); length > 0 { - skip = make(map[string]struct{}, length) +func (h *handlerHelper) createEntry(stop time.Duration) *logrus.Entry { + requestData := h.getRequestData(stop) + bodyBytes := h.getBytesAndRestoreBody() + respHeaders := h.getResponseHeaders() + headersString, customHeadersString := h.getStringHeaders() + queryParams := h.c.Request.URL.Query().Encode() + domain := h.c.Request.Host + return h.logger.WithFields(logrus.Fields{ + "domain": domain, + "statusCode": requestData.statusCode, + "latency": requestData.latency, // time to process + "clientIP": requestData.clientIP, + "method": h.c.Request.Method, + "referer": requestData.referer, + "userAgent": requestData.clientUserAgent, + "queryParams": queryParams, + "headers": headersString, + "requestBody": string(bodyBytes), + "customHeaders": customHeadersString, + "responseHeaders": respHeaders, + "requestID": h.requestID, + }) +} - for _, p := range notLogged { - skip[p] = struct{}{} +func (h *handlerHelper) handleEntry(entry *logrus.Entry) { + if len(h.c.Errors) > 0 { + internalEntry := h.logger.WithFields(logrus.Fields{ + "actionID": h.requestID, + }) + err := h.c.Errors.Last().Err + if file := errors.GetCallerFile(err); file != "" { + internalEntry = internalEntry.WithField("file", file) + } + if line := errors.GetCallerLine(err); line != -1 { + internalEntry = internalEntry.WithField("line", line) } + internalEntry.Error(err.Error()) + } + if h.c.Writer.Status() >= http.StatusInternalServerError { + entry.Error() + } else if h.c.Writer.Status() >= http.StatusBadRequest { + entry.Warn() + } else { + entry.Info() + } +} + +//Logger is the logrus logger handler +func Logger(logger logrus.FieldLogger, notLogged ...string) gin.HandlerFunc { + hostname, err := os.Hostname() + if err != nil { + hostname = "unknown" } return func(c *gin.Context) { @@ -58,104 +200,16 @@ func Logger(logger logrus.FieldLogger, notLogged ...string) gin.HandlerFunc { blw := &bodyLogWriter{body: bytes.NewBufferString(""), ResponseWriter: c.Writer} c.Writer = blw c.Next() - if strings.Contains(path, "/swagger/") { - return - } stop := time.Since(start) - latency := int(math.Ceil(float64(stop.Nanoseconds()) / 1000000.0)) - statusCode := c.Writer.Status() - clientIP := c.ClientIP() - clientUserAgent := c.Request.UserAgent() - referer := c.Request.Referer() - - if _, ok := skip[path]; ok { + if notLog(path, notLogged) { return } - - queryParams := c.Request.URL.Query().Encode() - - originHeaders := map[string]bool{ - "Accept": true, - "Accept-Encoding": true, - "Connection": true, - "Content-Length": true, - "Content-Type": true, - "User-Agent": true, - "Sec-Fetch-Dest": true, - "Accept-Language": true, - "Sec-Ch-Ua": true, - "Sec-Ch-Ua-Platform": true, - "Sec-Ch-Ua-Mobile": true, - "Sec-Fetch-Site": true, - "Sec-Fetch-Mode": true, - "Sec-Fetch-User": true, - "Referer": true, - "Cache-Control": true, - "Upgrade-Insecure-Requests": true, - } - - headers := c.Request.Header - var headersString string - var customHeadersString string - for key, values := range headers { - for _, value := range values { - if originHeaders[key] { - headersString = fmt.Sprint(headersString + key + ":" + value + " ") - } else { - customHeadersString = fmt.Sprint(customHeadersString + key + ":" + value + " ") - } - } - } - domain := c.Request.Host - - var bodyBytes []byte - if c.Request.Body != nil { - bodyBytes, _ = ioutil.ReadAll(c.Request.Body) - } - // Restore the io.ReadCloser to its original state - c.Request.Body = ioutil.NopCloser(bytes.NewBuffer(bodyBytes)) - - respBody := blw.body.String() - - var respHeadersArr []string - for header := range c.Writer.Header() { - respHeadersArr = append(respHeadersArr, header) - } - var respHeaders string - for _, value := range respHeadersArr { - respHeaders += value + ":" + c.Writer.Header().Get(value) + " " - } - - entry := logger.WithFields(logrus.Fields{ - "hostname": hostname, - "domain": domain, - "statusCode": statusCode, - "latency": latency, // time to process - "clientIP": clientIP, - "method": c.Request.Method, - "path": path, - "referer": referer, - "userAgent": clientUserAgent, - "queryParams": queryParams, - "headers": headersString, - "requestBody": string(bodyBytes), - "requestID": requestID, - "customHeaders": customHeadersString, - "responseBody": respBody, - "responseHeaders": respHeaders, - }) - - if len(c.Errors) > 0 { - entry.Warn(c.Errors.ByType(gin.ErrorTypePrivate).String()) - } else { - //msg := fmt.Sprintf("%s - %s [%s] \"%s %s\" %d %d \"%s\" \"%s\" (%dms)", clientIP, hostname, time.Now().Format(timeFormat), c.Request.Method, path, statusCode, dataLength, referer, clientUserAgent, latency) - if statusCode >= http.StatusInternalServerError { - entry.Error() - } else if statusCode >= http.StatusBadRequest { - entry.Warn() - } else { - entry.Info() - } - } + helper := newHandlerHelper(c, logger, stop) + helper.requestID = requestID + entry := helper.createEntry(stop) + entry = entry.WithField("responseBody", blw.body.String()) + entry = entry.WithField("hostname", hostname) + entry = entry.WithField("path", path) + helper.handleEntry(entry) } } diff --git a/src/webapi/middleware/recovery.go b/src/webapi/middleware/Recovery.go similarity index 73% rename from src/webapi/middleware/recovery.go rename to src/webapi/middleware/Recovery.go index db9a580a..5fae93e0 100644 --- a/src/webapi/middleware/recovery.go +++ b/src/webapi/middleware/Recovery.go @@ -11,7 +11,6 @@ import ( "github.com/sirupsen/logrus" "net" - "net/http/httputil" "os" "strings" "time" @@ -102,42 +101,11 @@ func Recovery(logger *logrus.Logger) gin.HandlerFunc { } if logger != nil { stack := stack(3) - httpRequest, _ := httputil.DumpRequest(c.Request, false) - headers := strings.Split(string(httpRequest), "\r\n") - for idx, header := range headers { - current := strings.Split(header, ":") - if current[0] == "Authorization" { - headers[idx] = current[0] + ": *" - } - } - headersToStr := strings.Join(headers, "\r\n") - - var bodyBytes []byte - if c.Request.Body != nil { - bodyBytes, _ = ioutil.ReadAll(c.Request.Body) - // Restore the io.ReadCloser to its original state - c.Request.Body = ioutil.NopCloser(bytes.NewBuffer(bodyBytes)) - } - entry := logger.WithFields(logrus.Fields{ - "headers": headersToStr, - "error": err, - "body": string(bodyBytes), - "stack": string(stack), + "source": string(stack), + "actionID": c.GetHeader("X-Request-ID"), }) - - entry.Error() - - //if brokenPipe { - // logger.Printf("%s\n%s%s", err, headersToStr, reset) - //} else if gin.IsDebugging() { - // fmt.Printf("[BODY] %s\n", string(bodyBytes)) - // logger.Printf("[Recovery] %s panic recovered:\n%s\n%s\n%s%s\n", - // TimeFormat(time.Now()), headersToStr, err, stack, reset) - //} else { - // logger.Printf("[Recovery] %s panic recovered:\n%s\n%s%s\n", - // TimeFormat(time.Now()), err, stack, reset) - //} + entry.Panic(err) } if brokenPipe { // If the connection is dead, we can't write a status to it.