diff --git a/cmd/tx-submit-api/main.go b/cmd/tx-submit-api/main.go index 6889a02..6779f3f 100644 --- a/cmd/tx-submit-api/main.go +++ b/cmd/tx-submit-api/main.go @@ -34,7 +34,7 @@ var cmdlineFlags struct { } func logPrintf(format string, v ...any) { - logging.GetLogger().Infof(format, v...) + logging.GetLogger().Info(fmt.Sprintf(format, v...)) } func main() { @@ -56,31 +56,23 @@ func main() { // Configure logging logging.Setup(&cfg.Logging) logger := logging.GetLogger() - // Sync logger on exit - defer func() { - if err := logger.Sync(); err != nil { - // We don't actually care about the error here, but we have to do something - // to appease the linter - return - } - }() - logger.Infof("starting tx-submit-api %s", version.GetVersionString()) + logger.Info("starting tx-submit-api", "version", version.GetVersionString()) // Configure max processes with our logger wrapper, toss undo func _, err = maxprocs.Set(maxprocs.Logger(logPrintf)) if err != nil { // If we hit this, something really wrong happened - logger.Errorf(err.Error()) + logger.Error("maxprocs setup failed", "err", err) os.Exit(1) } // Start debug listener if cfg.Debug.ListenPort > 0 { - logger.Infof( - "starting debug listener on %s:%d", - cfg.Debug.ListenAddress, - cfg.Debug.ListenPort, + logger.Info( + "starting debug listener", + "address", cfg.Debug.ListenAddress, + "port", cfg.Debug.ListenPort, ) go func() { debugger := &http.Server{ @@ -93,14 +85,16 @@ func main() { } err := debugger.ListenAndServe() if err != nil { - logger.Fatalf("failed to start debug listener: %s", err) + logger.Error("failed to start debug listener", "err", err) + os.Exit(1) } }() } // Start API listener if err := api.Start(cfg); err != nil { - logger.Fatalf("failed to start API: %s", err) + logger.Error("failed to start API", "err", err) + os.Exit(1) } // Wait forever diff --git a/go.mod b/go.mod index 482ee57..5b3c808 100644 --- a/go.mod +++ b/go.mod @@ -8,7 +8,6 @@ require ( github.com/blinklabs-io/gouroboros v0.141.0 github.com/fxamacker/cbor/v2 v2.9.0 github.com/gin-contrib/cors v1.7.6 - github.com/gin-contrib/zap v1.1.6 github.com/gin-gonic/gin v1.11.0 github.com/kelseyhightower/envconfig v1.4.0 github.com/penglongli/gin-metrics v0.1.13 @@ -16,7 +15,6 @@ require ( github.com/swaggo/gin-swagger v1.6.1 github.com/swaggo/swag v1.16.6 go.uber.org/automaxprocs v1.6.0 - go.uber.org/zap v1.27.1 gopkg.in/yaml.v2 v2.4.0 ) diff --git a/go.sum b/go.sum index 87ab980..36b55ba 100644 --- a/go.sum +++ b/go.sum @@ -78,8 +78,6 @@ github.com/gin-contrib/gzip v0.0.6 h1:NjcunTcGAj5CO1gn4N8jHOSIeRFHIbn51z6K+xaN4d github.com/gin-contrib/gzip v0.0.6/go.mod h1:QOJlmV2xmayAjkNS2Y8NQsMneuRShOU/kjovCXNuzzk= github.com/gin-contrib/sse v1.1.0 h1:n0w2GMuUpWDVp7qSpvze6fAu9iRxJY4Hmj6AmBOU05w= github.com/gin-contrib/sse v1.1.0/go.mod h1:hxRZ5gVpWMT7Z0B0gSNYqqsSCNIJMjzvm6fqCz9vjwM= -github.com/gin-contrib/zap v1.1.6 h1:TZcXi1UR8QG6OO4rewIMth7SmweyZuCeuUyJohpRcXg= -github.com/gin-contrib/zap v1.1.6/go.mod h1:V/sSE4Rf6ptzsEW4vj1KpUUV8ptJSVdE1nqsX9HQ1II= github.com/gin-gonic/gin v1.11.0 h1:OW/6PLjyusp2PPXtyxKHU0RbX6I/l28FTdDlae5ueWk= github.com/gin-gonic/gin v1.11.0/go.mod h1:+iq/FyxlGzII0KHiBGjuNn4UNENUlKbGlNmc+W50Dls= github.com/go-openapi/jsonpointer v0.19.3/go.mod h1:Pl9vOtqEWErmShwVjC8pYs9cog34VGT37dQOVbmoatg= @@ -233,8 +231,6 @@ go.uber.org/mock v0.5.0 h1:KAMbZvZPyBPWgD14IrIQ38QCyjwpvVVV6K/bHl1IwQU= go.uber.org/mock v0.5.0/go.mod h1:ge71pBPLYDk7QIi1LupWxdAykm7KIEFchiOqd6z7qMM= go.uber.org/multierr v1.11.0 h1:blXXJkSxSSfBVBlC76pxqeO+LN3aDfLQo+309xJstO0= go.uber.org/multierr v1.11.0/go.mod h1:20+QtiLqy0Nd6FdQB9TLXag12DsQkrbs3htMFfDN80Y= -go.uber.org/zap v1.27.1 h1:08RqriUEv8+ArZRYSTXy1LeBScaMpVSTBhCeaZYfMYc= -go.uber.org/zap v1.27.1/go.mod h1:GB2qFLM7cTU87MWRP2mPIjqfIDnGu+VIO4V/SdhGo2E= golang.org/x/arch v0.20.0 h1:dx1zTU0MAE98U+TQ8BLl7XsJbgze2WnNKF/8tGp/Q6c= golang.org/x/arch v0.20.0/go.mod h1:bdwinDaKcfZUGpH09BB7ZmOfhalA8lQdzl62l8gGWsk= golang.org/x/crypto v0.0.0-20170930174604-9419663f5a44/go.mod h1:6SG95UA2DQfeDnfUPMdvaQW0Q7yPrPDi9nlGo2tz2b4= diff --git a/internal/api/api.go b/internal/api/api.go index 400dae8..6949391 100644 --- a/internal/api/api.go +++ b/internal/api/api.go @@ -21,7 +21,6 @@ import ( "io" "io/fs" "net/http" - "time" ouroboros "github.com/blinklabs-io/gouroboros" "github.com/blinklabs-io/gouroboros/protocol/localtxsubmission" @@ -31,7 +30,6 @@ import ( "github.com/blinklabs-io/tx-submit-api/submit" "github.com/fxamacker/cbor/v2" cors "github.com/gin-contrib/cors" - ginzap "github.com/gin-contrib/zap" "github.com/gin-gonic/gin" "github.com/penglongli/gin-metrics/ginmetrics" swaggerFiles "github.com/swaggo/files" // swagger embed files @@ -55,16 +53,16 @@ func Start(cfg *config.Config) error { // Standard logging logger := logging.GetLogger() if cfg.Tls.CertFilePath != "" && cfg.Tls.KeyFilePath != "" { - logger.Infof( - "starting API TLS listener on %s:%d", - cfg.Api.ListenAddress, - cfg.Api.ListenPort, + logger.Info( + "starting API TLS listener", + "address", cfg.Api.ListenAddress, + "port", cfg.Api.ListenPort, ) } else { - logger.Infof( - "starting API listener on %s:%d", - cfg.Api.ListenAddress, - cfg.Api.ListenPort, + logger.Info( + "starting API listener", + "address", cfg.Api.ListenAddress, + "port", cfg.Api.ListenPort, ) } // Disable gin debug and color output @@ -90,14 +88,10 @@ func Start(cfg *config.Config) error { skipPaths := []string{} if cfg.Logging.Healthchecks { skipPaths = append(skipPaths, "/healthcheck") - logger.Infof("disabling access logs for /healthcheck") + logger.Info("disabling access logs for /healthcheck") } - router.Use(ginzap.GinzapWithConfig(accessLogger, &ginzap.Config{ - TimeFormat: time.RFC3339, - UTC: true, - SkipPaths: skipPaths, - })) - router.Use(ginzap.RecoveryWithZap(accessLogger, true)) + router.Use(logging.GinLogger(accessLogger, skipPaths)) + router.Use(logging.GinRecovery(accessLogger, true)) // Configure static route fsys, err := fs.Sub(staticFS, "static") @@ -158,9 +152,9 @@ func Start(cfg *config.Config) error { // Start metrics listener go func() { // TODO: return error if we cannot initialize metrics - logger.Infof("starting metrics listener on %s:%d", - cfg.Metrics.ListenAddress, - cfg.Metrics.ListenPort) + logger.Info("starting metrics listener", + "address", cfg.Metrics.ListenAddress, + "port", cfg.Metrics.ListenPort) _ = metricsRouter.Run(fmt.Sprintf("%s:%d", cfg.Metrics.ListenAddress, cfg.Metrics.ListenPort)) @@ -213,7 +207,7 @@ func handleHasTx(c *gin.Context) { var uriParams TxHashPathParams if err := c.ShouldBindUri(&uriParams); err != nil { - logger.Errorf("failed to bind transaction hash from path: %s", err) + logger.Error("failed to bind transaction hash from path", "err", err) c.JSON(400, fmt.Sprintf("invalid transaction hash: %s", err)) return } @@ -222,7 +216,7 @@ func handleHasTx(c *gin.Context) { // convert to cbor bytes cborData, err := cbor.Marshal(txHash) if err != nil { - logger.Errorf("failed to encode transaction hash to CBOR: %s", err) + logger.Error("failed to encode transaction hash to CBOR", "err", err) c.JSON( 400, fmt.Sprintf("failed to encode transaction hash to CBOR: %s", err), @@ -236,19 +230,19 @@ func handleHasTx(c *gin.Context) { ouroboros.WithNodeToNode(false), ) if err != nil { - logger.Errorf("failure creating Ouroboros connection: %s", err) + logger.Error("failure creating Ouroboros connection", "err", err) c.JSON(500, "failure communicating with node") return } if cfg.Node.Address != "" && cfg.Node.Port > 0 { if err := oConn.Dial("tcp", fmt.Sprintf("%s:%d", cfg.Node.Address, cfg.Node.Port)); err != nil { - logger.Errorf("failure connecting to node via TCP: %s", err) + logger.Error("failure connecting to node via TCP", "err", err) c.JSON(500, "failure communicating with node") return } } else { if err := oConn.Dial("unix", cfg.Node.SocketPath); err != nil { - logger.Errorf("failure connecting to node via UNIX socket: %s", err) + logger.Error("failure connecting to node via UNIX socket", "err", err) c.JSON(500, "failure communicating with node") return } @@ -259,7 +253,7 @@ func handleHasTx(c *gin.Context) { }() hasTx, err := oConn.LocalTxMonitor().Client.HasTx(cborData) if err != nil { - logger.Errorf("failure getting transaction: %s", err) + logger.Error("failure getting transaction", "err", err) c.JSON(500, fmt.Sprintf("failure getting transaction: %s", err)) return } @@ -288,7 +282,7 @@ func handleSubmitTx(c *gin.Context) { // Check our headers for content-type if c.ContentType() != "application/cbor" { // Log the error, return an error to the user, and increment failed count - logger.Errorf("invalid request body, should be application/cbor") + logger.Error("invalid request body, should be application/cbor") c.JSON(415, "invalid request body, should be application/cbor") _ = ginmetrics.GetMonitor().GetMetric("tx_submit_fail_count").Inc(nil) return @@ -297,7 +291,7 @@ func handleSubmitTx(c *gin.Context) { txRawBytes, err := io.ReadAll(c.Request.Body) if err != nil { // Log the error, return an error to the user, and increment failed count - logger.Errorf("failed to read request body: %s", err) + logger.Error("failed to read request body", "err", err) c.JSON(500, "failed to read request body") _ = ginmetrics.GetMonitor().GetMetric("tx_submit_fail_count").Inc(nil) return @@ -305,7 +299,7 @@ func handleSubmitTx(c *gin.Context) { // Close request body after read if c.Request.Body != nil { if err := c.Request.Body.Close(); err != nil { - logger.Errorf("failed to close request body: %s", err) + logger.Error("failed to close request body", "err", err) } } // Send TX @@ -341,7 +335,7 @@ func handleSubmitTx(c *gin.Context) { go func() { err, ok := <-errorChan if ok { - logger.Errorf("failure communicating with node: %s", err) + logger.Error("failure communicating with node", "err", err) c.JSON(500, "failure communicating with node") _ = ginmetrics.GetMonitor(). GetMetric("tx_submit_fail_count"). diff --git a/internal/logging/gin.go b/internal/logging/gin.go new file mode 100644 index 0000000..95dd01c --- /dev/null +++ b/internal/logging/gin.go @@ -0,0 +1,64 @@ +package logging + +import ( + "log/slog" + "net/http" + "runtime/debug" + "time" + + "github.com/gin-gonic/gin" +) + +// GinLogger returns a middleware that logs HTTP requests with slog. +func GinLogger(logger *slog.Logger, skipPaths []string) gin.HandlerFunc { + skip := make(map[string]struct{}, len(skipPaths)) + for _, path := range skipPaths { + skip[path] = struct{}{} + } + + return func(c *gin.Context) { + start := time.Now() + path := c.Request.URL.Path + raw := c.Request.URL.RawQuery + + c.Next() + + if _, ok := skip[path]; ok { + return + } + + latency := time.Since(start) + entry := []any{ + "status", c.Writer.Status(), + "method", c.Request.Method, + "path", path, + "query", raw, + "ip", c.ClientIP(), + "userAgent", c.Request.UserAgent(), + "latency", latency.String(), + "size", c.Writer.Size(), + } + if len(c.Errors) > 0 { + entry = append(entry, "errors", c.Errors.String()) + } + + logger.Info("request completed", entry...) + } +} + +// GinRecovery recovers from panics and logs them. +func GinRecovery(logger *slog.Logger, includeStack bool) gin.HandlerFunc { + return func(c *gin.Context) { + defer func() { + if err := recover(); err != nil { + fields := []any{"err", err} + if includeStack { + fields = append(fields, "stack", string(debug.Stack())) + } + logger.Error("panic recovered", fields...) + c.AbortWithStatus(http.StatusInternalServerError) + } + }() + c.Next() + } +} diff --git a/internal/logging/logging.go b/internal/logging/logging.go index 8446a63..cc9a13c 100644 --- a/internal/logging/logging.go +++ b/internal/logging/logging.go @@ -15,57 +15,65 @@ package logging import ( + "fmt" "log" + "log/slog" + "os" + "strings" "time" "github.com/blinklabs-io/tx-submit-api/internal/config" - "go.uber.org/zap" - "go.uber.org/zap/zapcore" ) -type Logger = zap.SugaredLogger - -var globalLogger *Logger +var ( + globalLogger *slog.Logger + accessLogger *slog.Logger +) func Setup(cfg *config.LoggingConfig) { - // Build our custom logging config - loggerConfig := zap.NewProductionConfig() - // Change timestamp key name - loggerConfig.EncoderConfig.TimeKey = "timestamp" - // Use a human readable time format - loggerConfig.EncoderConfig.EncodeTime = zapcore.TimeEncoderOfLayout( - time.RFC3339, - ) - - // Set level - if cfg.Level != "" { - level, err := zapcore.ParseLevel(cfg.Level) - if err != nil { - log.Fatalf("error configuring logger: %s", err) - } - loggerConfig.Level.SetLevel(level) + level, err := parseLevel(cfg.Level) + if err != nil { + log.Fatalf("error configuring logger: %s", err) } - // Create the logger - l, err := loggerConfig.Build() - if err != nil { - log.Fatal(err) + opts := &slog.HandlerOptions{ + Level: level, + ReplaceAttr: func(groups []string, attr slog.Attr) slog.Attr { + if attr.Key == slog.TimeKey { + attr.Key = "timestamp" + attr.Value = slog.StringValue(attr.Value.Time().Format(time.RFC3339)) + } + return attr + }, } - // Store the "sugared" version of the logger - globalLogger = l.Sugar() + handler := slog.NewJSONHandler(os.Stdout, opts) + globalLogger = slog.New(handler) + accessLogger = globalLogger.With(slog.String("type", "access")) } -func GetLogger() *zap.SugaredLogger { +func GetLogger() *slog.Logger { return globalLogger } -func GetDesugaredLogger() *zap.Logger { - return globalLogger.Desugar() +func GetAccessLogger() *slog.Logger { + return accessLogger } -func GetAccessLogger() *zap.Logger { - return globalLogger.Desugar(). - With(zap.String("type", "access")). - WithOptions(zap.WithCaller(false)) +func parseLevel(level string) (slog.Leveler, error) { + if level == "" { + return slog.LevelInfo, nil + } + switch strings.ToLower(level) { + case "debug": + return slog.LevelDebug, nil + case "info": + return slog.LevelInfo, nil + case "warn", "warning": + return slog.LevelWarn, nil + case "error": + return slog.LevelError, nil + default: + return nil, fmt.Errorf("invalid log level: %s", level) + } }