From 443e5c664e5cabcbd85ea70ac4d5de8960f6fd79 Mon Sep 17 00:00:00 2001 From: Chris Hager Date: Fri, 25 Oct 2024 09:40:56 +0200 Subject: [PATCH 1/2] systemapi cleanup --- README.md | 6 +++--- cmd/system-api/main.go | 5 +++-- {cmd/system-api => systemapi}/server.go | 2 +- 3 files changed, 7 insertions(+), 6 deletions(-) rename {cmd/system-api => systemapi}/server.go (99%) diff --git a/README.md b/README.md index fd032df..cf34cd2 100644 --- a/README.md +++ b/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 ``` diff --git a/cmd/system-api/main.go b/cmd/system-api/main.go index 6718a05..db92990 100644 --- a/cmd/system-api/main.go +++ b/cmd/system-api/main.go @@ -9,13 +9,14 @@ 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{ @@ -48,7 +49,7 @@ func runCli(cCtx *cli.Context) error { }) // Setup and start the server (in the background) - server, err := NewServer(&HTTPServerConfig{ + server, err := systemapi.NewServer(&systemapi.HTTPServerConfig{ ListenAddr: listenAddr, Log: log, PipeFilename: pipeFile, diff --git a/cmd/system-api/server.go b/systemapi/server.go similarity index 99% rename from cmd/system-api/server.go rename to systemapi/server.go index 537390e..2bcda29 100644 --- a/cmd/system-api/server.go +++ b/systemapi/server.go @@ -1,4 +1,4 @@ -package main +package systemapi import ( "bufio" From 46169b2087fb0e9a465fa6a54efa46111033ca6c Mon Sep 17 00:00:00 2001 From: Chris Hager Date: Fri, 25 Oct 2024 11:17:01 +0200 Subject: [PATCH 2/2] cleanup and use chi logger --- cmd/system-api/main.go | 22 +++++++- common/logging.go | 112 ++++++++++------------------------------- common/vars.go | 4 -- go.mod | 1 + go.sum | 2 + systemapi/server.go | 43 +++++++++------- 6 files changed, 74 insertions(+), 110 deletions(-) diff --git a/cmd/system-api/main.go b/cmd/system-api/main.go index db92990..4e15955 100644 --- a/cmd/system-api/main.go +++ b/cmd/system-api/main.go @@ -24,6 +24,16 @@ var flags []cli.Flag = []cli.Flag{ 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() { @@ -43,9 +53,19 @@ 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) diff --git a/common/logging.go b/common/logging.go index 148c0cc..274608b 100644 --- a/common/logging.go +++ b/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 } diff --git a/common/vars.go b/common/vars.go index e4cbdb6..f6c5d47 100644 --- a/common/vars.go +++ b/common/vars.go @@ -1,7 +1,3 @@ package common var Version = "dev" - -const ( - PackageName = "github.com/flashbots/system-api" -) diff --git a/go.mod b/go.mod index 3b28419..599728d 100644 --- a/go.mod +++ b/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 ) diff --git a/go.sum b/go.sum index 07d670d..bfb97a0 100644 --- a/go.sum +++ b/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= diff --git a/systemapi/server.go b/systemapi/server.go index 2bcda29..95c7743 100644 --- a/systemapi/server.go +++ b/systemapi/server.go @@ -1,3 +1,4 @@ +// Package systemapi provides components for the System API service. package systemapi import ( @@ -5,7 +6,6 @@ import ( "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,20 +66,9 @@ 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, } @@ -86,6 +76,25 @@ func NewServer(cfg *HTTPServerConfig) (srv *Server, err error) { 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) {