cleanup logging

README.md

@@ -22,14 +22,14 @@ Future features:
 
 ```bash
 # Start the server
-$ go run cmd/system-api/*
+$ go run cmd/system-api/main.go
 
 # Add events
 $ echo "hello world" > pipe.fifo
-$ curl localhost:8082/api/v1/new_event?message=this+is+a+test
+$ curl localhost:3535/api/v1/new_event?message=this+is+a+test
 
 # Query events (plain text or JSON is supported)
-$ curl -s localhost:8082/api/v1/events?format=text
+$ curl -s localhost:3535/api/v1/events?format=text
 2024-10-23T12:04:01Z     hello world
 2024-10-23T12:04:07Z     this is a test
 ```

cmd/system-api/main.go

@@ -9,20 +9,31 @@ import (
 	"time"
 
 	"github.com/flashbots/system-api/common"
+	"github.com/flashbots/system-api/systemapi"
 	cli "github.com/urfave/cli/v2" // imports as package "cli"
 )
 
 var flags []cli.Flag = []cli.Flag{
 	&cli.StringFlag{
 		Name:  "listen-addr",
-		Value: "0.0.0.0:8082",
+		Value: "0.0.0.0:3535",
 		Usage: "address to serve certificate on",
 	},
 	&cli.StringFlag{
 		Name:  "pipe-file",
 		Value: "pipe.fifo",
 		Usage: "filename for named pipe (for sending events into this service)",
 	},
+	&cli.BoolFlag{
+		Name:  "log-json",
+		Value: false,
+		Usage: "log in JSON format",
+	},
+	&cli.BoolFlag{
+		Name:  "log-debug",
+		Value: true,
+		Usage: "log debug messages",
+	},
 }
 
 func main() {
@@ -42,13 +53,23 @@ func main() {
 func runCli(cCtx *cli.Context) error {
 	listenAddr := cCtx.String("listen-addr")
 	pipeFile := cCtx.String("pipe-file")
+	logJSON := cCtx.Bool("log-json")
+	logDebug := cCtx.Bool("log-debug")
+
+	logTags := map[string]string{
+		"version": common.Version,
+	}
 
 	log := common.SetupLogger(&common.LoggingOpts{
-		Version: common.Version,
+		JSON:           logJSON,
+		Debug:          logDebug,
+		Concise:        true,
+		RequestHeaders: true,
+		Tags:           logTags,
 	})
 
 	// Setup and start the server (in the background)
-	server, err := NewServer(&HTTPServerConfig{
+	server, err := systemapi.NewServer(&systemapi.HTTPServerConfig{
 		ListenAddr:   listenAddr,
 		Log:          log,
 		PipeFilename: pipeFile,

common/logging.go

@@ -2,103 +2,43 @@
 package common
 
 import (
-	"fmt"
 	"log/slog"
-	"net/http"
-	"os"
-	"runtime/debug"
-	"strconv"
-	"time"
+
+	httplog "github.com/go-chi/httplog/v2"
 )
 
 type LoggingOpts struct {
-	Debug   bool
-	JSON    bool
-	Service string
-	Version string
-}
-
-func SetupLogger(opts *LoggingOpts) (log *slog.Logger) {
-	logLevel := slog.LevelInfo
-	if opts.Debug {
-		logLevel = slog.LevelDebug
-	}
-
-	if opts.JSON {
-		log = slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{Level: logLevel}))
-	} else {
-		log = slog.New(slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{Level: logLevel}))
-	}
-
-	if opts.Service != "" {
-		log = log.With("service", opts.Service)
-	}
+	ServiceName string
 
-	if opts.Version != "" {
-		log = log.With("version", opts.Version)
-	}
-
-	return log
-}
+	// Whether to log in JSON format
+	JSON bool
 
-// LoggingMiddlewareSlog logs the incoming HTTP request & its duration.
-func LoggingMiddlewareSlog(logger *slog.Logger, next http.Handler) http.Handler {
-	return http.HandlerFunc(
-		func(w http.ResponseWriter, r *http.Request) {
-			defer func() {
-				if err := recover(); err != nil {
-					w.WriteHeader(http.StatusInternalServerError)
+	// Whether to log debug messages
+	Debug bool
 
-					method := ""
-					url := ""
-					if r != nil {
-						method = r.Method
-						url = r.URL.EscapedPath()
-					}
+	// Concise mode includes fewer log details during the request flow. For example excluding details like
+	// request content length, user-agent and other details. This is useful if during development your console is too noisy.
+	Concise bool
 
-					logger.Error(fmt.Sprintf("http request panic: %s %s", method, url),
-						"err", err,
-						"trace", string(debug.Stack()),
-						"method", r.Method,
-					)
-				}
-			}()
-			start := time.Now()
-			wrapped := wrapResponseWriter(w)
-			next.ServeHTTP(wrapped, r)
-			logger.Info(fmt.Sprintf("http: %s %s %d", r.Method, r.URL.EscapedPath(), wrapped.status),
-				"status", wrapped.status,
-				"method", r.Method,
-				"path", r.URL.EscapedPath(),
-				"duration", fmt.Sprintf("%f", time.Since(start).Seconds()),
-				"durationUs", strconv.FormatInt(time.Since(start).Microseconds(), 10),
-			)
-		},
-	)
-}
-
-// responseWriter is a minimal wrapper for http.ResponseWriter that allows the
-// written HTTP status code to be captured for logging.
-type responseWriter struct {
-	http.ResponseWriter
-	status      int
-	wroteHeader bool
-}
+	// RequestHeaders enables logging of all request headers, however sensitive headers like authorization, cookie and set-cookie are hidden.
+	RequestHeaders bool
 
-func wrapResponseWriter(w http.ResponseWriter) *responseWriter {
-	return &responseWriter{ResponseWriter: w}
+	// Tags are additional fields included at the root level of all logs. These can be useful for example the commit hash of a build, or an environment name like prod/stg/dev
+	Tags map[string]string
 }
 
-func (rw *responseWriter) Status() int {
-	return rw.status
-}
-
-func (rw *responseWriter) WriteHeader(code int) {
-	if rw.wroteHeader {
-		return
+func SetupLogger(opts *LoggingOpts) (log *httplog.Logger) {
+	logLevel := slog.LevelInfo
+	if opts.Debug {
+		logLevel = slog.LevelDebug
 	}
 
-	rw.status = code
-	rw.ResponseWriter.WriteHeader(code)
-	rw.wroteHeader = true
+	logger := httplog.NewLogger(opts.ServiceName, httplog.Options{
+		JSON:           opts.JSON,
+		LogLevel:       logLevel,
+		Concise:        opts.Concise,
+		RequestHeaders: opts.RequestHeaders,
+		Tags:           opts.Tags,
+	})
+	return logger
 }

common/vars.go

@@ -1,7 +1,3 @@
 package common
 
 var Version = "dev"
-
-const (
-	PackageName = "github.com/flashbots/system-api"
-)

go.mod

@@ -7,6 +7,7 @@ toolchain go1.23.1
 require (
 	github.com/ethereum/go-ethereum v1.14.9
 	github.com/go-chi/chi/v5 v5.1.0
+	github.com/go-chi/httplog/v2 v2.1.1
 	github.com/urfave/cli/v2 v2.27.2
 )
 

go.sum

@@ -14,6 +14,8 @@ github.com/ethereum/go-ethereum v1.14.9 h1:J7iwXDrtUyE9FUjUYbd4c9tyzwMh6dTJsKzo9
 github.com/ethereum/go-ethereum v1.14.9/go.mod h1:QeW+MtTpRdBEm2pUFoonByee8zfHv7kGp0wK0odvU1I=
 github.com/go-chi/chi/v5 v5.1.0 h1:acVI1TYaD+hhedDJ3r54HyA6sExp3HfXq7QWEEY/xMw=
 github.com/go-chi/chi/v5 v5.1.0/go.mod h1:DslCQbL2OYiznFReuXYUmQ2hGd1aDpCnlMNITLSKoi8=
+github.com/go-chi/httplog/v2 v2.1.1 h1:ojojiu4PIaoeJ/qAO4GWUxJqvYUTobeo7zmuHQJAxRk=
+github.com/go-chi/httplog/v2 v2.1.1/go.mod h1:/XXdxicJsp4BA5fapgIC3VuTD+z0Z/VzukoB3VDc1YE=
 github.com/holiman/uint256 v1.3.1 h1:JfTzmih28bittyHM8z360dCjIA9dbPIBlcTI6lmctQs=
 github.com/holiman/uint256 v1.3.1/go.mod h1:EOMSn4q6Nyt9P6efbI3bueV4e1b3dGlUCXeiRV4ng7E=
 github.com/russross/blackfriday/v2 v2.1.0 h1:JIOH55/0cWyOuilr9/qlrm0BSXldqnqwMsf35Ld67mk=

cmd/system-api/server.go → systemapi/server.go

@@ -1,11 +1,11 @@
-package main
+// Package systemapi provides components for the System API service.
+package systemapi
 
 import (
 	"bufio"
 	"context"
 	"encoding/json"
 	"errors"
-	"log/slog"
 	"net/http"
 	"os"
 	"strings"
@@ -16,13 +16,14 @@ import (
 	"github.com/flashbots/system-api/common"
 	chi "github.com/go-chi/chi/v5"
 	"github.com/go-chi/chi/v5/middleware"
+	"github.com/go-chi/httplog/v2"
 )
 
 var MaxEvents = common.GetEnvInt("MAX_EVENTS", 1000)
 
 type HTTPServerConfig struct {
 	ListenAddr   string
-	Log          *slog.Logger
+	Log          *httplog.Logger
 	PipeFilename string
 	EnablePprof  bool
 
@@ -39,7 +40,7 @@ type Event struct {
 
 type Server struct {
 	cfg *HTTPServerConfig
-	log *slog.Logger
+	log *httplog.Logger
 
 	srv *http.Server
 
@@ -65,27 +66,35 @@ func NewServer(cfg *HTTPServerConfig) (srv *Server, err error) {
 		go srv.readPipeInBackground()
 	}
 
-	mux := chi.NewRouter()
-	mux.With(srv.httpLogger).Get("/", srv.handleLivenessCheck)
-	mux.With(srv.httpLogger).Get("/livez", srv.handleLivenessCheck)
-	mux.With(srv.httpLogger).Get("/api/v1/new_event", srv.handleNewEvent)
-	mux.With(srv.httpLogger).Get("/api/v1/events", srv.handleGetEvents)
-
-	if cfg.EnablePprof {
-		srv.log.Info("pprof API enabled")
-		mux.Mount("/debug", middleware.Profiler())
-	}
-
 	srv.srv = &http.Server{
 		Addr:         cfg.ListenAddr,
-		Handler:      mux,
+		Handler:      srv.getRouter(),
 		ReadTimeout:  cfg.ReadTimeout,
 		WriteTimeout: cfg.WriteTimeout,
 	}
 
 	return srv, nil
 }
 
+func (s *Server) getRouter() http.Handler {
+	mux := chi.NewRouter()
+
+	mux.Use(httplog.RequestLogger(s.log))
+	mux.Use(middleware.Recoverer)
+
+	mux.Get("/", s.handleLivenessCheck)
+	mux.Get("/livez", s.handleLivenessCheck)
+	mux.Get("/api/v1/new_event", s.handleNewEvent)
+	mux.Get("/api/v1/events", s.handleGetEvents)
+
+	if s.cfg.EnablePprof {
+		s.log.Info("pprof API enabled")
+		mux.Mount("/debug", middleware.Profiler())
+	}
+
+	return mux
+}
+
 func (s *Server) readPipeInBackground() {
 	file, err := os.OpenFile(s.cfg.PipeFilename, os.O_CREATE, os.ModeNamedPipe)
 	if err != nil {
@@ -108,10 +117,6 @@ func (s *Server) readPipeInBackground() {
 	}
 }
 
-func (s *Server) httpLogger(next http.Handler) http.Handler {
-	return common.LoggingMiddlewareSlog(s.log, next)
-}
-
 func (s *Server) Start() {
 	s.log.Info("Starting HTTP server", "listenAddress", s.cfg.ListenAddr)
 	if err := s.srv.ListenAndServe(); err != nil && !errors.Is(err, http.ErrServerClosed) {