soroban-rpc: Add logging for HTTP requests and JSONRPC requests (#584)

Each HTTP request is assigned an ID logged using the the stellar/go/support/http middleware

Within each HTTP request, each JSONRPC request is logged using the global HTTP ID and the per-request JSONRPC id.

Additionally, I added the version and commit of soroban-rpc to the startup log.

cmd/soroban-rpc/internal/daemon/daemon.go

@@ -4,7 +4,7 @@ import (
 	"context"
 	"errors"
 	"net/http"
-	"net/http/pprof"
+	"net/http/pprof" //nolint:gosec
 	"os"
 	"os/signal"
 	"sync"
@@ -17,6 +17,7 @@ import (
 	"github.com/stellar/go/historyarchive"
 	"github.com/stellar/go/ingest/ledgerbackend"
 	dbsession "github.com/stellar/go/support/db"
+	supporthttp "github.com/stellar/go/support/http"
 	supportlog "github.com/stellar/go/support/log"
 
 	"github.com/stellar/soroban-tools/cmd/soroban-rpc/internal"
@@ -39,7 +40,8 @@ type Daemon struct {
 	core                *ledgerbackend.CaptiveStellarCore
 	ingestService       *ingest.Service
 	db                  dbsession.SessionInterface
-	handler             *internal.Handler
+	jsonRPCHandler      *internal.Handler
+	httpHandler         http.Handler
 	logger              *supportlog.Entry
 	preflightWorkerPool *preflight.PreflightWorkerPool
 	prometheusRegistry  *prometheus.Registry
@@ -55,27 +57,24 @@ func (d *Daemon) PrometheusRegistry() *prometheus.Registry {
 }
 
 func (d *Daemon) ServeHTTP(writer http.ResponseWriter, request *http.Request) {
-	d.handler.ServeHTTP(writer, request)
+	d.httpHandler.ServeHTTP(writer, request)
 }
 
 func (d *Daemon) GetDB() dbsession.SessionInterface {
 	return d.db
 }
 
 func (d *Daemon) close() {
-	// Default Shutdown grace period.
 	shutdownCtx, shutdownRelease := context.WithTimeout(context.Background(), defaultShutdownGracePeriod)
 	defer shutdownRelease()
 	var closeErrors []error
 
 	if err := d.server.Shutdown(shutdownCtx); err != nil {
-		// Error from closing listeners, or context timeout:
 		d.logger.Errorf("Error during Soroban JSON RPC server Shutdown: %v", err)
 		closeErrors = append(closeErrors, err)
 	}
 	if d.adminServer != nil {
 		if err := d.adminServer.Shutdown(shutdownCtx); err != nil {
-			// Error from closing listeners, or context timeout:
 			d.logger.Errorf("Error during Soroban JSON admin server Shutdown: %v", err)
 			closeErrors = append(closeErrors, err)
 		}
@@ -89,7 +88,7 @@ func (d *Daemon) close() {
 		d.logger.WithError(err).Error("Error closing captive core")
 		closeErrors = append(closeErrors, err)
 	}
-	d.handler.Close()
+	d.jsonRPCHandler.Close()
 	if err := d.db.Close(); err != nil {
 		d.logger.WithError(err).Error("Error closing db")
 		closeErrors = append(closeErrors, err)
@@ -104,7 +103,7 @@ func (d *Daemon) Close() error {
 	return d.closeError
 }
 
-// newCaptiveCore create a new captive core backend instance and returns it.
+// newCaptiveCore creates a new captive core backend instance and returns it.
 func newCaptiveCore(cfg *config.LocalConfig, logger *supportlog.Entry) (*ledgerbackend.CaptiveStellarCore, error) {
 	httpPortUint := uint(cfg.CaptiveCoreHTTPPort)
 	var captiveCoreTomlParams ledgerbackend.CaptiveCoreTomlParams
@@ -210,7 +209,7 @@ func MustNew(cfg config.LocalConfig, endpoint string, adminEndpoint string) *Dae
 	preflightWorkerPool := preflight.NewPreflightWorkerPool(
 		cfg.PreflightWorkerCount, cfg.PreflightWorkerQueueSize, ledgerEntryReader, cfg.NetworkPassphrase, logger)
 
-	handler := internal.NewJSONRPCHandler(&cfg, internal.HandlerParams{
+	jsonRPCHandler := internal.NewJSONRPCHandler(&cfg, internal.HandlerParams{
 		EventStore:       eventStore,
 		TransactionStore: transactionStore,
 		Logger:           logger,
@@ -223,11 +222,14 @@ func MustNew(cfg config.LocalConfig, endpoint string, adminEndpoint string) *Dae
 		PreflightGetter:   preflightWorkerPool,
 	})
 
+	httpHandler := supporthttp.NewAPIMux(logger)
+	httpHandler.Handle("/", jsonRPCHandler)
 	d := &Daemon{
 		logger:              logger,
 		core:                core,
 		ingestService:       ingestService,
-		handler:             &handler,
+		jsonRPCHandler:      &jsonRPCHandler,
+		httpHandler:         httpHandler,
 		db:                  dbConn,
 		preflightWorkerPool: preflightWorkerPool,
 		prometheusRegistry:  prometheusRegistry,
@@ -239,10 +241,13 @@ func MustNew(cfg config.LocalConfig, endpoint string, adminEndpoint string) *Dae
 		ReadTimeout: defaultReadTimeout,
 	}
 	if adminEndpoint != "" {
-		adminMux := http.NewServeMux()
-		adminMux.Handle("/metrics", promhttp.HandlerFor(d.prometheusRegistry, promhttp.HandlerOpts{}))
-		adminMux.HandleFunc("/debug/pprof/heap", pprof.Index)
+		adminMux := supporthttp.NewMux(logger)
+		adminMux.HandleFunc("/debug/pprof/", pprof.Index)
+		adminMux.HandleFunc("/debug/pprof/cmdline", pprof.Cmdline)
 		adminMux.HandleFunc("/debug/pprof/profile", pprof.Profile)
+		adminMux.HandleFunc("/debug/pprof/symbol", pprof.Symbol)
+		adminMux.HandleFunc("/debug/pprof/trace", pprof.Trace)
+		adminMux.Handle("/metrics", promhttp.HandlerFor(d.prometheusRegistry, promhttp.HandlerOpts{}))
 		d.adminServer = &http.Server{Addr: adminEndpoint, Handler: adminMux}
 	}
 	d.registerMetrics()

cmd/soroban-rpc/internal/jsonrpc.go

@@ -1,12 +1,12 @@
 package internal
 
 import (
+	"context"
 	"net/http"
 
+	"github.com/creachadair/jrpc2"
 	"github.com/creachadair/jrpc2/handler"
 	"github.com/creachadair/jrpc2/jhttp"
-	"github.com/rs/cors"
-
 	"github.com/stellar/go/clients/stellarcore"
 	"github.com/stellar/go/support/log"
 
@@ -44,6 +44,12 @@ type HandlerParams struct {
 
 // NewJSONRPCHandler constructs a Handler instance
 func NewJSONRPCHandler(cfg *config.LocalConfig, params HandlerParams) Handler {
+	bridgeOptions := jhttp.BridgeOptions{
+		Server: &jrpc2.ServerOptions{
+			Logger: func(text string) { params.Logger.Debug(text) },
+			RPCLog: &rpcLogger{logger: params.Logger},
+		},
+	}
 	bridge := jhttp.NewBridge(handler.Map{
 		"getHealth":           methods.NewHealthCheck(params.TransactionStore, cfg.MaxHealthyLedgerLatency),
 		"getEvents":           methods.NewGetEventsHandler(params.EventStore, cfg.MaxEventsLimit, cfg.DefaultEventsLimit),
@@ -53,16 +59,49 @@ func NewJSONRPCHandler(cfg *config.LocalConfig, params HandlerParams) Handler {
 		"getTransaction":      methods.NewGetTransactionHandler(params.TransactionStore),
 		"sendTransaction":     methods.NewSendTransactionHandler(params.Logger, params.TransactionStore, cfg.NetworkPassphrase, params.CoreClient),
 		"simulateTransaction": methods.NewSimulateTransactionHandler(params.Logger, params.LedgerEntryReader, params.PreflightGetter),
-	}, nil)
-	corsMiddleware := cors.New(cors.Options{
-		AllowedOrigins: []string{"*"},
-		AllowedHeaders: []string{"*"},
-		AllowedMethods: []string{"GET", "PUT", "POST", "PATCH", "DELETE", "HEAD", "OPTIONS"},
-	})
+	}, &bridgeOptions)
 
 	return Handler{
 		bridge:  bridge,
 		logger:  params.Logger,
-		Handler: corsMiddleware.Handler(bridge),
+		Handler: bridge,
 	}
 }
+
+type rpcLogger struct {
+	logger *log.Entry
+}
+
+func (r *rpcLogger) LogRequest(ctx context.Context, req *jrpc2.Request) {
+	logger := r.logger.WithFields(log.F{
+		"subsys": "jsonrpc",
+		// FIXME: the HTTP request context is independent from the JSONRPC context, and thus the code below doesn't work
+		// "req":      middleware.GetReqID(ctx),
+		"json_req": req.ID(),
+		"method":   req.Method(),
+	})
+	logger.Info("starting JSONRPC request")
+
+	// Params are useful but can be really verbose, let's only print them in debug
+	logger = logger.WithField("params", req.ParamString())
+	logger.Debug("starting JSONRPC request params")
+}
+
+func (r *rpcLogger) LogResponse(ctx context.Context, rsp *jrpc2.Response) {
+	// TODO: Print the elapsed time (there doesn't seem to be a way to it with with jrpc2, since
+	//       LogRequest cannot modify the context)
+	logger := r.logger.WithFields(log.F{
+		"subsys": "jsonrpc",
+		// FIXME: the HTTP request context is independent from the JSONRPC context, and thus the code below doesn't work
+		// "req":      middleware.GetReqID(ctx),
+		"json_req": rsp.ID(),
+	})
+	if err := rsp.Error(); err != nil {
+		logger = logger.WithField("error", err.Error())
+	}
+	logger.Info("finished JSONRPC request")
+
+	// the result is useful but can be really verbose, let's only print it with debug level
+	logger = logger.WithField("result", rsp.ResultString())
+	logger.Debug("finished JSONRPC request result")
+}

go.mod

@@ -6,11 +6,11 @@ require (
 	github.com/Masterminds/squirrel v1.5.0
 	github.com/cenkalti/backoff/v4 v4.2.0
 	github.com/creachadair/jrpc2 v0.41.1
+	github.com/go-chi/chi v4.0.3+incompatible
 	github.com/go-git/go-git/v5 v5.4.2
-	github.com/jmoiron/sqlx v1.2.0
 	github.com/mattn/go-sqlite3 v1.14.16
 	github.com/pelletier/go-toml v1.9.0
-	github.com/rs/cors v0.0.0-20160617231935-a62a804a8a00
+	github.com/prometheus/client_golang v0.9.3-0.20190127221311-3c4408c8b829
 	github.com/rubenv/sql-migrate v0.0.0-20190717103323-87ce952f7079
 	github.com/sirupsen/logrus v1.4.1
 	github.com/spf13/cobra v0.0.0-20160830174925-9c28e4bbd74e
@@ -30,7 +30,6 @@ require (
 	github.com/beorn7/perks v0.0.0-20180321164747-3a771d992973 // indirect
 	github.com/davecgh/go-spew v1.1.1 // indirect
 	github.com/emirpasic/gods v1.12.0 // indirect
-	github.com/go-chi/chi v4.0.3+incompatible // indirect
 	github.com/go-errors/errors v0.0.0-20150906023321-a41850380601 // indirect
 	github.com/go-git/gcfg v1.5.0 // indirect
 	github.com/go-git/go-billy/v5 v5.3.1 // indirect
@@ -39,6 +38,7 @@ require (
 	github.com/inconshreveable/mousetrap v1.0.0 // indirect
 	github.com/jbenet/go-context v0.0.0-20150711004518-d14ea06fba99 // indirect
 	github.com/jmespath/go-jmespath v0.4.0 // indirect
+	github.com/jmoiron/sqlx v1.2.0 // indirect
 	github.com/kevinburke/ssh_config v0.0.0-20201106050909-4977a11b4351 // indirect
 	github.com/konsorten/go-windows-terminal-sequences v1.0.1 // indirect
 	github.com/kr/pretty v0.2.1 // indirect
@@ -52,10 +52,10 @@ require (
 	github.com/mitchellh/mapstructure v0.0.0-20150613213606-2caf8efc9366 // indirect
 	github.com/pkg/errors v0.9.1 // indirect
 	github.com/pmezard/go-difflib v1.0.0 // indirect
-	github.com/prometheus/client_golang v0.9.3-0.20190127221311-3c4408c8b829 // indirect
 	github.com/prometheus/client_model v0.0.0-20190812154241-14fe0d1b01d4 // indirect
 	github.com/prometheus/common v0.2.0 // indirect
 	github.com/prometheus/procfs v0.0.0-20190117184657-bf6a532e95b1 // indirect
+	github.com/rs/cors v0.0.0-20160617231935-a62a804a8a00 // indirect
 	github.com/rs/xhandler v0.0.0-20160618193221-ed27b6fd6521 // indirect
 	github.com/segmentio/go-loggly v0.5.1-0.20171222203950-eb91657e62b2 // indirect
 	github.com/sergi/go-diff v1.1.0 // indirect