refactor(tx-submit-api): Switched logging part to go slog and removed zap part (#397)

Signed-off-by: Akhil Repala <[email protected]>
Signed-off-by: Akhil <[email protected]>

Author: arepala-uml

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

go.mod

@@ -8,15 +8,13 @@ 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
 	github.com/swaggo/files v1.0.1
 	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
 )
 

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=

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,15 +291,15 @@ 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
 	}
 	// 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").

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()
+	}
+}