From 644b10c73855143860e57916679016f9ace08f0d Mon Sep 17 00:00:00 2001 From: Franco Ferraguti Date: Mon, 6 Nov 2023 02:20:59 -0300 Subject: [PATCH] Whoa huge logging changes --- .env_example | 2 +- cmd/main.go | 34 ++-- pkg/common/common.go | 18 -- pkg/common/config/config_structs.go | 7 +- pkg/common/enums.go | 15 ++ pkg/common/middleware/error_handler.go | 4 +- pkg/common/middleware/logger.go | 204 +++++++++++----------- pkg/common/middleware/logger_formatter.go | 147 ++++++++++++++++ pkg/common/middleware/new_relic.go | 16 +- pkg/common/middleware/prometheus.go | 28 +-- pkg/repository/database.go | 29 ++- pkg/repository/database_logger.go | 47 ----- pkg/transport/endpoints.go | 18 +- pkg/transport/router.go | 13 +- pkg/transport/transport.go | 8 +- 15 files changed, 344 insertions(+), 246 deletions(-) create mode 100644 pkg/common/enums.go create mode 100644 pkg/common/middleware/logger_formatter.go delete mode 100644 pkg/repository/database_logger.go diff --git a/.env_example b/.env_example index 44b084b..c94213b 100644 --- a/.env_example +++ b/.env_example @@ -1,6 +1,7 @@ GO_REST_EXAMPLE_APP_NAME = "go-rest-example" # Name of the app GO_REST_EXAMPLE_PORT = "8040" # Port in which the app is running GO_REST_EXAMPLE_DEBUG = true # Enables debug mode for gin +GO_REST_EXAMPLE_LOG_INFO = true # Enables logs not just for errors GO_REST_EXAMPLE_PROFILING = false # Enables profiling endpoints GO_REST_EXAMPLE_TIMEOUT_SECONDS = 15 # Timeout for requests GO_REST_EXAMPLE_RATE_LIMITER_RPS = 10 # Max requests per second @@ -12,7 +13,6 @@ GO_REST_EXAMPLE_DATABASE_HOSTNAME = "go-rest-example-db" # DB host GO_REST_EXAMPLE_DATABASE_PORT = "3306" # DB port GO_REST_EXAMPLE_DATABASE_SCHEMA = "go-rest-example-db" # DB database name GO_REST_EXAMPLE_DATABASE_CLEAN = true # If true, all records will be deleted -GO_REST_EXAMPLE_DATABASE_DEBUG = false # If true, all queries will be logged GO_REST_EXAMPLE_DATABASE_DESTROY = false # If true, all tables will be deleted GO_REST_EXAMPLE_DATABASE_ADMIN_INSERT = true # If true, an admin user will be created on server init GO_REST_EXAMPLE_DATABASE_ADMIN_PASSWORD = "p4ssw0rd" # Said admin password diff --git a/cmd/main.go b/cmd/main.go index 2cfb0e7..cc27a09 100644 --- a/cmd/main.go +++ b/cmd/main.go @@ -14,7 +14,7 @@ import ( ) // Note: This is the entrypoint of the application. -// The HTTP Requests entrypoint is the Prometheus HandlerFunc in prometheus.go +// The HTTP Requests entrypoint is the Prometheus HandlerFunc in pkg/common/middleware/prometheus.go func main() { @@ -22,13 +22,13 @@ func main() { /*------------------------- // DEPENDENCIES - //-----------------------*/ + //------------------------*/ config := config.New() log.Println("Config OK") - logger := middleware.NewLogger() - logger.Info("Logger OK", nil) + logger := middleware.NewLogger(config.General.LogInfo) + logger.Logger.Info("Logger OK", nil) middlewares := []gin.HandlerFunc{ gin.Recovery(), // Panic recovery @@ -39,32 +39,32 @@ func main() { middleware.NewTimeoutMiddleware(config.General.Timeout), // Timeout middleware.NewErrorHandlerMiddleware(logger), // Error Handler } - logger.Info("Middlewares OK", nil) + logger.Logger.Info("Middlewares OK", nil) auth := auth.New(config.Auth.JWTSecret, config.Auth.SessionDurationDays) - logger.Info("Auth OK", nil) + logger.Logger.Info("Auth OK", nil) - database := repository.NewDatabase(config, repository.NewDBLogger(logger.Out)) - logger.Info("Database OK", nil) + database := repository.NewDatabase(config, logger) + logger.Logger.Info("Database OK", nil) repositoryLayer := repository.New(database) - logger.Info("Repository Layer OK", nil) + logger.Logger.Info("Repository Layer OK", nil) serviceLayer := service.New(repositoryLayer, auth, config) - logger.Info("Service Layer OK", nil) + logger.Logger.Info("Service Layer OK", nil) transportLayer := transport.New(serviceLayer) - logger.Info("Transport Layer OK", nil) + logger.Logger.Info("Transport Layer OK", nil) router := transport.NewRouter(transportLayer, config, auth, logger, middlewares...) - logger.Info("Router & Endpoints OK", nil) + logger.Logger.Info("Router & Endpoints OK", nil) - /*------------------------- - // START SERVER - //------------------------*/ + /*--------------------------- + // START SERVER + //--------------------------*/ port := config.General.Port - logger.Info("Running server on port "+port, nil) + logger.Logger.Info("Running server on port "+port, nil) err := router.Run(":" + port) if err != nil { @@ -80,10 +80,8 @@ func main() { // - Batch insert // - Reset password // - Roles to DB -// - Prometheus enable flag // - Request IDs // - Logic from DeleteUser to service layer // - Search & Fix TODOs // - Replace user.Exists when you can -// - Change in config JWT -> Auth // - OpenAPI (Swagger) diff --git a/pkg/common/common.go b/pkg/common/common.go index d40afee..bed8d51 100644 --- a/pkg/common/common.go +++ b/pkg/common/common.go @@ -21,21 +21,3 @@ func Hash(data string, salt string) string { hasher.Write([]byte(data + salt)) return base64.URLEncoding.EncodeToString(hasher.Sum(nil)) } - -const ( - Reset = "\033[0m" - Red = "\033[31m" - Green = "\033[32m" - Yellow = "\033[33m" - Blue = "\033[34m" - Magenta = "\033[35m" - Cyan = "\033[36m" - White = "\033[37m" - BlueBold = "\033[34;1m" - MagentaBold = "\033[35;1m" - RedBold = "\033[31;1m" - YellowBold = "\033[33;1m" - WhiteBold = "\033[37;1m" - GreenBold = "\033[32;1m" - Gray = "\033[90m" -) diff --git a/pkg/common/config/config_structs.go b/pkg/common/config/config_structs.go index 51828af..ad6d800 100644 --- a/pkg/common/config/config_structs.go +++ b/pkg/common/config/config_structs.go @@ -7,6 +7,7 @@ import "fmt" type General struct { AppName string `envconfig:"GO_REST_EXAMPLE_APP_NAME"` Debug bool `envconfig:"GO_REST_EXAMPLE_DEBUG"` + LogInfo bool `envconfig:"GO_REST_EXAMPLE_LOG_INFO"` Port string `envconfig:"GO_REST_EXAMPLE_PORT"` Profiling bool `envconfig:"GO_REST_EXAMPLE_PROFILING"` Timeout int `envconfig:"GO_REST_EXAMPLE_TIMEOUT_SECONDS"` @@ -21,10 +22,8 @@ type Database struct { Port string `envconfig:"GO_REST_EXAMPLE_DATABASE_PORT"` Schema string `envconfig:"GO_REST_EXAMPLE_DATABASE_SCHEMA"` - Clean bool `envconfig:"GO_REST_EXAMPLE_DATABASE_CLEAN"` - Debug bool `envconfig:"GO_REST_EXAMPLE_DATABASE_DEBUG"` - Destroy bool `envconfig:"GO_REST_EXAMPLE_DATABASE_DESTROY"` - + Clean bool `envconfig:"GO_REST_EXAMPLE_DATABASE_CLEAN"` + Destroy bool `envconfig:"GO_REST_EXAMPLE_DATABASE_DESTROY"` AdminInsert bool `envconfig:"GO_REST_EXAMPLE_DATABASE_ADMIN_INSERT"` AdminPassword string `envconfig:"GO_REST_EXAMPLE_DATABASE_ADMIN_PASSWORD"` diff --git a/pkg/common/enums.go b/pkg/common/enums.go new file mode 100644 index 0000000..6d1e2ca --- /dev/null +++ b/pkg/common/enums.go @@ -0,0 +1,15 @@ +package common + +type LogSource int + +const ( + Unknown LogSource = iota // 0 + NewRelic // 1 + Prometheus // 2 + Gin // 3 + Gorm // 4 +) + +func (ls LogSource) String() string { + return [...]string{"unknown", "new_relic", "prometheus", "gin", "gorm"}[ls] +} diff --git a/pkg/common/middleware/error_handler.go b/pkg/common/middleware/error_handler.go index ab67d35..63432ac 100644 --- a/pkg/common/middleware/error_handler.go +++ b/pkg/common/middleware/error_handler.go @@ -9,7 +9,7 @@ import ( "github.com/gin-gonic/gin" ) -func NewErrorHandlerMiddleware(logger *Logger) gin.HandlerFunc { +func NewErrorHandlerMiddleware(logger *LoggerAdapter) gin.HandlerFunc { return func(c *gin.Context) { // Wait until the request is finished @@ -63,7 +63,7 @@ func getErrorInfo(err error) (int, string, string) { return customErr.Status(), messages[len(messages)-1], stackTrace } -func logStackTrace(logger *Logger, status int, stackTrace, path, method string) { +func logStackTrace(logger *LoggerAdapter, status int, stackTrace, path, method string) { logContext := logger.WithField("status", status).WithField("path", path).WithField("method", method) logContext.Error(stackTrace) } diff --git a/pkg/common/middleware/logger.go b/pkg/common/middleware/logger.go index 905b80a..036dff5 100644 --- a/pkg/common/middleware/logger.go +++ b/pkg/common/middleware/logger.go @@ -1,151 +1,147 @@ package middleware import ( - "encoding/json" - "fmt" + "context" "os" - "regexp" "strings" + "time" - c "github.com/gilperopiola/go-rest-example/pkg/common" - + "github.com/gilperopiola/go-rest-example/pkg/common" "github.com/sirupsen/logrus" + gormLogger "gorm.io/gorm/logger" ) +type LoggerAdapter struct { + Logger +} + type Logger struct { *logrus.Logger } -func NewLogger() *Logger { - l := &logrus.Logger{ - Out: os.Stdout, Formatter: &CustomJSONFormatter{}, - Hooks: make(logrus.LevelHooks), Level: logrus.InfoLevel, +func NewLogger(logInfo bool) *LoggerAdapter { + + level := logrus.ErrorLevel + if logInfo { + level = logrus.InfoLevel } - return &Logger{l} -} -// CustomJSONFormatter is a custom formatter for logrus -type CustomJSONFormatter struct{} + return &LoggerAdapter{ + Logger: Logger{ + Logger: &logrus.Logger{ + Out: os.Stdout, Formatter: &CustomFormatter{}, + Hooks: make(logrus.LevelHooks), Level: level, + }, + }, + } +} -// Format leaves the messages like this: -// -// 2023-11-02 14:47:44 -> GetUser: user.Deleted -> error, user already deleted -// -// { -// "path": "/v1/users/8", -// "status": 404 -// } -// -// - -func (f *CustomJSONFormatter) Format(entry *logrus.Entry) ([]byte, error) { +func (l *Logger) Error(msg string, context map[string]interface{}) { + l.prepareLogger(&msg, context).Error(msg) +} - if entry.Message == "" { - return nil, nil - } +func (l *Logger) Warn(msg string, context map[string]interface{}) { + l.prepareLogger(&msg, context).Warn(msg) +} - // We always output first the time - formattedTime := entry.Time.Format("2006-01-02 15:04:05") +func (l *Logger) Info(msg string, context map[string]interface{}) { + l.prepareLogger(&msg, context).Info(msg) +} - // If it's a New Relic log, we put it in BlueBold - if isNewRelicLog(entry.Message) { - return []byte(fmt.Sprintf("%s%s %s[New Relic]%s %s%s", c.WhiteBold, formattedTime, c.BlueBold, c.Reset, c.White, entry.Message)), nil - } +func (l *Logger) Debug(msg string, context map[string]interface{}) { + l.prepareLogger(&msg, context).Debug(msg) +} - // If it's a Prometheus log, we put it in MagentaBold - if isPrometheusLog(entry.Data) { - return []byte(fmt.Sprintf("%s%s %s[Prometheus]%s %s%s", c.WhiteBold, formattedTime, c.MagentaBold, c.Reset, c.White, entry.Message)), nil - } +func (l *Logger) DebugEnabled() bool { + return l.IsLevelEnabled(logrus.DebugLevel) +} - if isGinLog(entry.Message) { - message, _ := strings.CutPrefix(entry.Message, "[GIN-debug]") - return []byte(fmt.Sprintf("%s%s %s[GIN]%s %s%s\n", c.WhiteBold, formattedTime, c.GreenBold, c.Reset, c.White, message)), nil - } +// prepareLogger adds the necessary fields to the log and a new line to the message if it's not there +func (l *Logger) prepareLogger(msg *string, context map[string]interface{}) *logrus.Entry { - // We only use the custom formatter for errors. TODO rework this! - if entry.Level > logrus.ErrorLevel { - return []byte(fmt.Sprintf("%s%s%s %s%s%s", c.WhiteBold, formattedTime, c.Reset, c.White, entry.Message, c.Reset)), nil + // Add fields to log + log := l.Logger.WithField("msg", *msg) + for k, v := range context { + log = log.WithField(k, v) } - // Entry to JSON - logJSON, err := json.MarshalIndent(entry.Data, "", " ") - if err != nil { - return nil, fmt.Errorf("error marshalling fields to JSON -> %v", err) + // New Relic + if *msg == "application created" || *msg == "application connected" || *msg == "final configuration" || *msg == "collector message" { + log = log.WithField("from", common.NewRelic.String()) } - // Colorize status code - isError := false - status, ok := entry.Data["status"].(int) - if ok { - isError = status >= 500 + // Gin + if strings.Contains(*msg, "[GIN-debug]") || strings.Contains(*msg, "GIN_MODE") || strings.Contains(*msg, "gin.SetMode") { + log = log.WithField("from", common.Gin.String()) } - colorizedJSON := colorizeJSON(string(logJSON), isError) - - // Layout: \n + WhiteBold + [time] + Reset + Red + [message] + \n + White + [JSON] + \n - layout := "\n%s%s ->%s %s%s\n%s%s\n" - return []byte(fmt.Sprintf(layout, c.WhiteBold, formattedTime, c.Reset, c.Red, entry.Message, c.White, colorizedJSON)), nil -} - -// colorizeJSON just colors the status code in the JSON -func colorizeJSON(json string, isError bool) string { - beforeStatus := c.RedBold - if !isError { - beforeStatus = c.YellowBold + // Add new line if it's not there + if !strings.Contains(*msg, "\n") { // TODO endswith + *msg += "\n" } - afterStatus := c.Reset - - // Regular expression to find the status code - re := regexp.MustCompile(`"status": (\d+)`) - // Replace the status code with the new string using a regular expression - return re.ReplaceAllString(json, `"status": `+beforeStatus+`$1`+afterStatus) + return log } +/*---------------------------- +// GORM LOGGER ADAPTER // +// This adapter is used to unify our Logger with GORM's Logger +//--------------------------------------------------------------*/ -func (l *Logger) Error(msg string, context map[string]interface{}) { - l.Logger.Error(msg, context) -} -func (l *Logger) Warn(msg string, context map[string]interface{}) { - l.Logger.Warn(msg, context) -} -func (l *Logger) Info(msg string, context map[string]interface{}) { - log := l.Logger.WithField("msg", msg) - for k, v := range context { - log = log.WithField(k, v) - } +func (l *LoggerAdapter) Trace(ctx context.Context, begin time.Time, fc func() (string, int64), err error) { + elapsed := time.Since(begin) + sql, rows := fc() - if !strings.Contains(msg, "\n") { - msg += "\n" + if err != nil { + l.Logger.Error( + sql, + map[string]interface{}{ + "from": common.Gorm.String(), + "rows": rows, + "elapsed": float64(elapsed.Nanoseconds()) / 1e6, + "err": err, + }, + ) + } else { + l.Logger.Info( + sql, + map[string]interface{}{ + "from": common.Gorm.String(), + "rows": rows, + "elapsed": float64(elapsed.Nanoseconds()) / 1e6, + }, + ) } - - log.Info(msg) } -func (l *Logger) Debug(msg string, context map[string]interface{}) { - log := l.Logger.WithField("msg", msg) - for k, v := range context { - log = log.WithField(k, v) - } - if !strings.Contains(msg, "\n") { - msg += "\n" +func (l *LoggerAdapter) LogMode(level gormLogger.LogLevel) gormLogger.Interface { + switch level { + case gormLogger.Info: + l.Logger.SetLevel(logrus.InfoLevel) + case gormLogger.Warn: + l.Logger.SetLevel(logrus.WarnLevel) + case gormLogger.Error: + l.Logger.SetLevel(logrus.ErrorLevel) + case gormLogger.Silent: + l.Logger.SetLevel(logrus.PanicLevel) } - - log.Debug(msg) + return l } -func (l *Logger) DebugEnabled() bool { - return l.IsLevelEnabled(logrus.DebugLevel) + +func (l *LoggerAdapter) Info(ctx context.Context, msg string, data ...interface{}) { + l.Logger.Info(msg, map[string]interface{}{}) } -func isNewRelicLog(msg string) bool { - return msg == "application created\n" || msg == "final configuration\n" || msg == "application connected\n" || msg == "collector message\n" +func (l *LoggerAdapter) Warn(ctx context.Context, msg string, data ...interface{}) { + l.Logger.Warn(msg, map[string]interface{}{}) } -func isPrometheusLog(data logrus.Fields) bool { - val, ok := data["from"] - return ok && val == "Prometheus" +func (l *LoggerAdapter) Error(ctx context.Context, msg string, data ...interface{}) { + l.Logger.Error(msg, map[string]interface{}{}) } -func isGinLog(msg string) bool { - return strings.Contains(msg, "[GIN-debug]") || strings.Contains(msg, "GIN_MODE") || strings.Contains(msg, "gin.SetMode") +func (l *LoggerAdapter) Write(p []byte) (n int, err error) { + l.Logger.Info(string(p), map[string]interface{}{}) + return len(p), nil } diff --git a/pkg/common/middleware/logger_formatter.go b/pkg/common/middleware/logger_formatter.go new file mode 100644 index 0000000..55100f3 --- /dev/null +++ b/pkg/common/middleware/logger_formatter.go @@ -0,0 +1,147 @@ +package middleware + +import ( + "encoding/json" + "fmt" + "regexp" + "strings" + + "github.com/gilperopiola/go-rest-example/pkg/common" + "github.com/sirupsen/logrus" +) + +/* --- Our custom error messages log like this: +// +// 2023-11-02 14:47:44 -> GetUser: user.Deleted -> error, user already deleted +// +// { +// "path": "/v1/users/8", +// "status": 404 +// } +// +// Other types of logs have other formats: +// +// - Middlewares OK +// - [New Relic] application created +// - [SQL] SELECT DATABASE() (-1 rows affected) [0.280ms] +// +//------------------------------------------------------*/ + +type CustomFormatter struct{} + +func (f *CustomFormatter) Format(entry *logrus.Entry) ([]byte, error) { + + // Discard empty messages + if entry.Message == "" { + return nil, nil + } + + formattedTime := entry.Time.Format("2006-01-02 15:04:05") + + // Sources: New Relic, Prometheus, Gin, Gorm + if ok, log := getLogFromSources(entry, formattedTime); ok { + return log, nil + } + + // If it's less than an error, we log it without much formatting + if entry.Level > logrus.ErrorLevel { + return formatLogDefault(entry.Message, formattedTime), nil + } + + // Only our custom errors should get up to this point. + // We parse the JSON and colorize the status code. + // Layout: \n + WhiteBold + [time] + Reset + Red + [message] + \n + White + [JSON] + \n + return formatLogCustomError(entry.Message, parseAndColorJSON(entry.Data), formattedTime), nil +} + +func isFromSource(data logrus.Fields, source common.LogSource) bool { + val, ok := data["from"] + return ok && val == source.String() +} + +func getLogFromSources(entry *logrus.Entry, time string) (bool, []byte) { + + if isFromSource(entry.Data, common.NewRelic) { + return true, formatLogFromSource("New Relic", entry.Message, BlueBold, time) + } + + if isFromSource(entry.Data, common.Prometheus) { + return true, formatLogFromSource("Prometheus", entry.Message, MagentaBold, time) + } + + if isFromSource(entry.Data, common.Gin) { + message, _ := strings.CutPrefix(entry.Message, "[GIN-debug]") + return true, formatLogFromSource("Gin", message, GreenBold, time) + } + + if isFromSource(entry.Data, common.Gorm) { + return true, formatLogSQL(entry.Message, time, entry.Data) + } + + return false, []byte{} +} + +func formatLogCustomError(message, json, time string) []byte { + layout := "\n%s%s ->%s %s%s\n%s%s%s\n" + return []byte(fmt.Sprintf(layout, WhiteBold, time, Nil, Red, message, White, json, Nil)) +} + +func formatLogFromSource(source, message, color, time string) []byte { + layout := "%s%s %s[%s]%s %s%s%s" + return []byte(fmt.Sprintf(layout, WhiteBold, time, color, source, Nil, White, message, Nil)) +} + +func formatLogSQL(message, time string, fields logrus.Fields) []byte { + + prefix := fmt.Sprintf("\n%s%s ", WhiteBold, time) // Log beginning + message = strings.ReplaceAll(message, "\n", "") + rows, elapsed, err := fields["rows"], fields["elapsed"], fields["err"] + + // Print Error or SQL + if err != nil { + layout := prefix + "%s[SQL Error]%s %s%s%s (%d rows affected) %s[%.3fms] %s%v%s\n" + return []byte(fmt.Sprintf(layout, RedBold, Nil, White, message, Gray, rows, Green, elapsed, Red, err, Nil)) + } + + layout := prefix + "%s[SQL]%s %s%s%s (%d rows affected) %s[%.3fms]%s\n" + return []byte(fmt.Sprintf(layout, YellowBold, Nil, White, message, Gray, rows, Green, elapsed, Nil)) +} + +func formatLogDefault(message, time string) []byte { + return []byte(fmt.Sprintf("%s%s %s%s%s%s", WhiteBold, time, Nil, White, message, Nil)) +} + +// parseAndColorJSON takes a logrus.Fields and returns it as JSON with the status code colored accordingly +func parseAndColorJSON(fields logrus.Fields) string { + json, err := json.MarshalIndent(fields, "", " ") + if err != nil { + return fmt.Sprintf("error marshalling fields to JSON -> %v", err) + } + + status, ok := fields["status"].(int) + statusColor := YellowBold + if ok && status >= 500 { + statusColor = RedBold + } + + return regexp.MustCompile(`"status": (\d+)`).ReplaceAllString(string(json), `"status": `+statusColor+`$1`+Nil) +} + +// Colors +const ( + Nil = "\033[0m" + Red = "\033[31m" + Green = "\033[32m" + Yellow = "\033[33m" + Blue = "\033[34m" + Magenta = "\033[35m" + Cyan = "\033[36m" + White = "\033[37m" + Gray = "\033[90m" + RedBold = "\033[31;1m" + GreenBold = "\033[32;1m" + YellowBold = "\033[33;1m" + BlueBold = "\033[34;1m" + MagentaBold = "\033[35;1m" + WhiteBold = "\033[37;1m" +) diff --git a/pkg/common/middleware/new_relic.go b/pkg/common/middleware/new_relic.go index 6fcb0a2..876f217 100644 --- a/pkg/common/middleware/new_relic.go +++ b/pkg/common/middleware/new_relic.go @@ -1,8 +1,10 @@ package middleware import ( - "log" + "fmt" + "os" + "github.com/gilperopiola/go-rest-example/pkg/common" "github.com/gilperopiola/go-rest-example/pkg/common/config" "github.com/gin-gonic/gin" @@ -14,32 +16,34 @@ func NewNewRelicMiddleware(app *newrelic.Application) gin.HandlerFunc { return nrgin.Middleware(app) } -func NewNewRelic(config config.Monitoring, logger *Logger) *newrelic.Application { +func NewNewRelic(config config.Monitoring, logger *LoggerAdapter) *newrelic.Application { // If New Relic is not enabled, return empty app if !config.NewRelicEnabled { - log.Println("New Relic Disabled") + logger.Logger.Info("New Relic Disabled", map[string]interface{}{"from": common.NewRelic.String()}) return nil } // If monitoring is enabled, use license to create New Relic app license := config.NewRelicLicenseKey if license == "" { - log.Fatalf("New Relic license not found") + logger.Logger.Error("New Relic license not found", map[string]interface{}{"from": common.NewRelic.String()}) + os.Exit(1) } // Create app newRelicApp, err := newrelic.NewApplication( newrelic.ConfigAppName(config.NewRelicAppName), newrelic.ConfigLicense(license), - newrelic.ConfigLogger(logger), + newrelic.ConfigLogger(&logger.Logger), newrelic.ConfigAppLogForwardingEnabled(true), newrelic.ConfigDistributedTracerEnabled(true), ) // Panic on failure if err != nil { - log.Fatalf("Failed to start New Relic: %v", err) + logger.Logger.Info(fmt.Sprintf("Failed to start New Relic: %v", err), map[string]interface{}{"from": common.NewRelic.String()}) + os.Exit(1) } return newRelicApp diff --git a/pkg/common/middleware/prometheus.go b/pkg/common/middleware/prometheus.go index 6fe0e0e..0585893 100644 --- a/pkg/common/middleware/prometheus.go +++ b/pkg/common/middleware/prometheus.go @@ -2,12 +2,12 @@ package middleware import ( "fmt" - "log" "net/http" "strconv" "strings" "time" + "github.com/gilperopiola/go-rest-example/pkg/common" "github.com/gilperopiola/go-rest-example/pkg/common/config" "github.com/gin-gonic/gin" @@ -15,17 +15,18 @@ import ( ) func NewPrometheusMiddleware(p *Prometheus) gin.HandlerFunc { - if p == nil { - return func(c *gin.Context) { - c.Next() - } + if p != nil { + return p.HandlerFunc() + } + + return func(c *gin.Context) { + c.Next() } - return p.HandlerFunc() } -func NewPrometheus(cfg config.Monitoring, logger *Logger) *Prometheus { +func NewPrometheus(cfg config.Monitoring, logger *LoggerAdapter) *Prometheus { if !cfg.PrometheusEnabled { - log.Println("Prometheus Disabled") + logger.Logger.Info("Prometheus disabled", map[string]interface{}{"from": common.Prometheus.String()}) return nil } @@ -83,7 +84,7 @@ type Prometheus struct { replaceURLKeys func(c *gin.Context) string - logger *Logger + logger *LoggerAdapter } // prometheus.Collector type (i.e. CounterVec, Summary, etc) of each metric @@ -220,7 +221,12 @@ func (p *Prometheus) registerMetrics(subsystem string) { for _, metricDefinition := range p.metricsList { metric := NewMetric(metricDefinition, subsystem) if err := prometheus.Register(metric); err != nil { - p.logger.Error(err.Error(), map[string]interface{}{"error": fmt.Errorf("%s could not be registered in Prometheus", metricDefinition.Name)}) + p.logger.Logger.Error( + err.Error(), + map[string]interface{}{ + "error": fmt.Errorf("%s could not be registered in Prometheus", metricDefinition.Name), + "from": common.Prometheus.String(), + }) } switch metricDefinition { case metricTotalRequests: @@ -235,7 +241,7 @@ func (p *Prometheus) registerMetrics(subsystem string) { metricDefinition.MetricCollector = metric } - p.logger.Info("Prometheus metrics registered", map[string]interface{}{"from": "Prometheus"}) + p.logger.Logger.Info("Prometheus metrics registered", map[string]interface{}{"from": common.Prometheus.String()}) } // From https://github.com/DanielHeckrath/gin-prometheus/blob/master/gin_prometheus.go diff --git a/pkg/repository/database.go b/pkg/repository/database.go index 19ee81b..d0fba20 100644 --- a/pkg/repository/database.go +++ b/pkg/repository/database.go @@ -3,11 +3,11 @@ package repository import ( "fmt" "log" - "os" "time" "github.com/gilperopiola/go-rest-example/pkg/common" "github.com/gilperopiola/go-rest-example/pkg/common/config" + "github.com/gilperopiola/go-rest-example/pkg/common/middleware" "github.com/gilperopiola/go-rest-example/pkg/common/models" "gorm.io/driver/mysql" @@ -18,7 +18,7 @@ type database struct { db *gorm.DB } -func NewDatabase(config *config.Config, logger *DBLogger) *database { +func NewDatabase(config *config.Config, logger *middleware.LoggerAdapter) *database { var database database database.setup(config, logger) return &database @@ -28,13 +28,12 @@ func (database *database) DB() *gorm.DB { return database.db } -func (database *database) setup(config *config.Config, logger *DBLogger) { +func (database *database) setup(config *config.Config, logger *middleware.LoggerAdapter) { // Create connection. It's deferred closed in main.go. // Retry connection if it fails due to Docker's orchestration. if err := database.connectToDB(config, logger); err != nil { log.Fatalf("error connecting to database: %v", err) - os.Exit(1) } // Set connection pool limits @@ -45,10 +44,10 @@ func (database *database) setup(config *config.Config, logger *DBLogger) { database.configure(config) } -func (database *database) connectToDB(config *config.Config, logger *DBLogger) error { - var err error - retries := 0 +func (database *database) connectToDB(config *config.Config, logger *middleware.LoggerAdapter) error { dbConfig := config.Database + retries := 0 + var err error // Retry connection if it fails due to Docker's orchestration for retries < dbConfig.MaxRetries { @@ -58,10 +57,11 @@ func (database *database) connectToDB(config *config.Config, logger *DBLogger) e retries++ if retries >= dbConfig.MaxRetries { - return fmt.Errorf("error connecting to database after %d retries: %v", dbConfig.MaxRetries, err) + logger.Logger.Error(fmt.Sprintf("error connecting to database after %d retries: %v", dbConfig.MaxRetries, err), nil) + return err } - fmt.Println("error connecting to database, retrying... ") + logger.Logger.Info("error connecting to database, retrying... ", map[string]interface{}{}) time.Sleep(time.Duration(dbConfig.RetryDelay) * time.Second) } return nil @@ -76,11 +76,6 @@ func (database *database) configure(config *config.Config) { mySQLDB.SetMaxOpenConns(dbConfig.MaxOpenConns) mySQLDB.SetConnMaxLifetime(time.Hour) - // Log queries if debug = true - if dbConfig.Debug { - database.db.Debug() - } - // Destroy or clean tables if dbConfig.Destroy { for _, model := range models.AllModels { @@ -98,13 +93,15 @@ func (database *database) configure(config *config.Config) { // Insert admin user if dbConfig.AdminInsert { admin := makeAdminModel("ferra.main@gmail.com", common.Hash(dbConfig.AdminPassword, config.Auth.HashSalt)) - if err := database.DB().Create(admin).Error; err != nil { + if err := database.db.Create(admin).Error; err != nil { fmt.Println(err.Error()) } } // Just for formatting the logs :) - fmt.Println("") + if config.General.LogInfo { + fmt.Println("") + } } func makeAdminModel(email, password string) *models.User { diff --git a/pkg/repository/database_logger.go b/pkg/repository/database_logger.go deleted file mode 100644 index 4a5c7eb..0000000 --- a/pkg/repository/database_logger.go +++ /dev/null @@ -1,47 +0,0 @@ -package repository - -import ( - "context" - "io" - "log" - "time" - - c "github.com/gilperopiola/go-rest-example/pkg/common" - - "gorm.io/gorm/logger" -) - -// Logrus logger is not compatible with GORM v2 -type DBLogger struct { - *log.Logger -} - -func NewDBLogger(out io.Writer) *DBLogger { - prefix := c.WhiteBold + "\r\n" - return &DBLogger{log.New(out, prefix, log.LstdFlags)} -} - -// Trace is a callback that can be registered with GORM to track every SQL query -func (l *DBLogger) Trace(ctx context.Context, begin time.Time, fc func() (string, int64), err error) { - elapsed := time.Since(begin) - sql, rows := fc() - - if err != nil { - layout := "%s[ERR]%s %s%s%s (%d rows affected) %s[%.3fms] %s%v%s\n" - l.Printf(layout, c.RedBold, c.Reset, c.White, sql, c.Reset, rows, c.Green, float64(elapsed.Nanoseconds())/1e6, c.Red, err, c.Reset) - } else { - layout := "%s[SQL]%s %s%s%s (%d rows affected) %s[%.3fms]%s\n" - l.Printf(layout, c.YellowBold, c.Reset, c.White, sql, c.Gray, rows, c.Green, float64(elapsed.Nanoseconds())/1e6, c.Reset) - } -} - -func (l *DBLogger) LogMode(level logger.LogLevel) logger.Interface { - newLogger := *l - return &newLogger -} - -func (l *DBLogger) Info(ctx context.Context, msg string, data ...interface{}) {} - -func (l *DBLogger) Warn(ctx context.Context, msg string, data ...interface{}) {} - -func (l *DBLogger) Error(ctx context.Context, msg string, data ...interface{}) {} diff --git a/pkg/transport/endpoints.go b/pkg/transport/endpoints.go index a6111ef..b29bd65 100644 --- a/pkg/transport/endpoints.go +++ b/pkg/transport/endpoints.go @@ -48,11 +48,11 @@ func HandleRequest[req requests.All, resp responses.All](c *gin.Context, emptyRe //-----------------*/ func (t transport) signup(c *gin.Context) { - HandleRequest(c, &requests.SignupRequest{}, requests.MakeRequest[*requests.SignupRequest], t.Service().Signup) + HandleRequest(c, &requests.SignupRequest{}, requests.MakeRequest[*requests.SignupRequest], t.Signup) } func (t transport) login(c *gin.Context) { - HandleRequest(c, &requests.LoginRequest{}, requests.MakeRequest[*requests.LoginRequest], t.Service().Login) + HandleRequest(c, &requests.LoginRequest{}, requests.MakeRequest[*requests.LoginRequest], t.Login) } /*------------------- @@ -60,27 +60,27 @@ func (t transport) login(c *gin.Context) { //----------------*/ func (t transport) createUser(c *gin.Context) { - HandleRequest(c, &requests.CreateUserRequest{}, requests.MakeRequest[*requests.CreateUserRequest], t.Service().CreateUser) + HandleRequest(c, &requests.CreateUserRequest{}, requests.MakeRequest[*requests.CreateUserRequest], t.CreateUser) } func (t transport) getUser(c *gin.Context) { - HandleRequest(c, &requests.GetUserRequest{}, requests.MakeRequest[*requests.GetUserRequest], t.Service().GetUser) + HandleRequest(c, &requests.GetUserRequest{}, requests.MakeRequest[*requests.GetUserRequest], t.GetUser) } func (t transport) updateUser(c *gin.Context) { - HandleRequest(c, &requests.UpdateUserRequest{}, requests.MakeRequest[*requests.UpdateUserRequest], t.Service().UpdateUser) + HandleRequest(c, &requests.UpdateUserRequest{}, requests.MakeRequest[*requests.UpdateUserRequest], t.UpdateUser) } func (t transport) deleteUser(c *gin.Context) { - HandleRequest(c, &requests.DeleteUserRequest{}, requests.MakeRequest[*requests.DeleteUserRequest], t.Service().DeleteUser) + HandleRequest(c, &requests.DeleteUserRequest{}, requests.MakeRequest[*requests.DeleteUserRequest], t.DeleteUser) } func (t transport) searchUsers(c *gin.Context) { - HandleRequest(c, &requests.SearchUsersRequest{}, requests.MakeRequest[*requests.SearchUsersRequest], t.Service().SearchUsers) + HandleRequest(c, &requests.SearchUsersRequest{}, requests.MakeRequest[*requests.SearchUsersRequest], t.SearchUsers) } func (t transport) changePassword(c *gin.Context) { - HandleRequest(c, &requests.ChangePasswordRequest{}, requests.MakeRequest[*requests.ChangePasswordRequest], t.Service().ChangePassword) + HandleRequest(c, &requests.ChangePasswordRequest{}, requests.MakeRequest[*requests.ChangePasswordRequest], t.ChangePassword) } /*-------------------- @@ -88,7 +88,7 @@ func (t transport) changePassword(c *gin.Context) { //-----------------*/ func (t transport) createUserPost(c *gin.Context) { - HandleRequest(c, &requests.CreateUserPostRequest{}, requests.MakeRequest[*requests.CreateUserPostRequest], t.Service().CreateUserPost) + HandleRequest(c, &requests.CreateUserPostRequest{}, requests.MakeRequest[*requests.CreateUserPostRequest], t.CreateUserPost) } /*-------------------- diff --git a/pkg/transport/router.go b/pkg/transport/router.go index e7b0d08..9446e24 100644 --- a/pkg/transport/router.go +++ b/pkg/transport/router.go @@ -2,6 +2,7 @@ package transport import ( "fmt" + "io" "net/http/pprof" "github.com/gilperopiola/go-rest-example/pkg/common/auth" @@ -16,13 +17,13 @@ type router struct { *gin.Engine } -func NewRouter(t TransportLayer, cfg *config.Config, auth auth.AuthI, logger *middleware.Logger, middlewares ...gin.HandlerFunc) router { +func NewRouter(t TransportLayer, cfg *config.Config, auth auth.AuthI, logger *middleware.LoggerAdapter, middlewares ...gin.HandlerFunc) router { var router router router.setup(t, cfg, auth, logger, middlewares...) return router } -func (router *router) setup(t TransportLayer, cfg *config.Config, auth auth.AuthI, logger *middleware.Logger, middlewares ...gin.HandlerFunc) { +func (router *router) setup(t TransportLayer, cfg *config.Config, auth auth.AuthI, logger *middleware.LoggerAdapter, middlewares ...gin.HandlerFunc) { // Create router. Set debug/release mode router.prepare(!cfg.General.Debug, logger) @@ -36,12 +37,14 @@ func (router *router) setup(t TransportLayer, cfg *config.Config, auth auth.Auth router.setEndpoints(t, cfg, auth) } -func (router *router) prepare(isProd bool, logger *middleware.Logger) { +func (router *router) prepare(isProd bool, logger *middleware.LoggerAdapter) { if isProd { gin.SetMode(gin.ReleaseMode) } - gin.DefaultWriter = logger.Writer() - gin.DefaultErrorWriter = logger.Writer() + + gin.DefaultWriter = io.MultiWriter(logger) // Logger + gin.DefaultErrorWriter = io.MultiWriter(logger) // Logger + router.Engine = gin.New() router.Engine.SetTrustedProxies(nil) } diff --git a/pkg/transport/transport.go b/pkg/transport/transport.go index d2aa171..320f50b 100644 --- a/pkg/transport/transport.go +++ b/pkg/transport/transport.go @@ -31,15 +31,13 @@ type TransportLayer interface { } type transport struct { - service service.ServiceLayer + service.ServiceLayer } func New(service service.ServiceLayer) *transport { - return &transport{ - service: service, - } + return &transport{service} } func (t transport) Service() service.ServiceLayer { - return t.service + return t.ServiceLayer }