soroban-rpc: Add logging for HTTP requests and JSONRPC requests

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

@@ -14,6 +14,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"
@@ -36,13 +37,13 @@ type Daemon struct {
 	core                *ledgerbackend.CaptiveStellarCore
 	ingestService       *ingest.Service
 	db                  dbsession.SessionInterface
-	handler             *internal.Handler
+	jsonRPCHandler      *internal.Handler
 	logger              *supportlog.Entry
 	preflightWorkerPool *preflight.PreflightWorkerPool
 }
 
 func (d *Daemon) ServeHTTP(writer http.ResponseWriter, request *http.Request) {
-	d.handler.ServeHTTP(writer, request)
+	d.jsonRPCHandler.ServeHTTP(writer, request)
 }
 
 func (d *Daemon) GetDB() dbsession.SessionInterface {
@@ -57,7 +58,7 @@ func (d *Daemon) Close() error {
 	if localErr := d.core.Close(); localErr != nil {
 		err = localErr
 	}
-	d.handler.Close()
+	d.jsonRPCHandler.Close()
 	if localErr := d.db.Close(); localErr != nil {
 		err = localErr
 	}
@@ -169,7 +170,7 @@ func MustNew(cfg config.LocalConfig) *Daemon {
 	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,
@@ -186,7 +187,7 @@ func MustNew(cfg config.LocalConfig) *Daemon {
 		logger:              logger,
 		core:                core,
 		ingestService:       ingestService,
-		handler:             &handler,
+		jsonRPCHandler:      &jsonRPCHandler,
 		db:                  dbConn,
 		preflightWorkerPool: preflightWorkerPool,
 	}
@@ -195,13 +196,17 @@ func MustNew(cfg config.LocalConfig) *Daemon {
 func Run(cfg config.LocalConfig, endpoint string, adminEndpoint string) {
 	d := MustNew(cfg)
 
+	jsonRPCMux := supporthttp.NewAPIMux(d.logger)
+	jsonRPCMux.Handle("/", d.jsonRPCHandler)
 	server := &http.Server{
 		Addr:        endpoint,
-		Handler:     d,
+		Handler:     jsonRPCMux,
 		ReadTimeout: defaultReadTimeout,
 	}
 
-	d.logger.Infof("Starting Soroban JSON RPC server on %v", endpoint)
+	d.logger.WithField("version", config.Version).
+		WithField("commit", config.CommitHash).
+		Infof("Starting Soroban JSON RPC server on %v", config.Version)
 
 	go func() {
 		if err := server.ListenAndServe(); !errors.Is(err, http.ErrServerClosed) {
@@ -211,8 +216,10 @@ func Run(cfg config.LocalConfig, endpoint string, adminEndpoint string) {
 	}()
 	var adminServer *http.Server
 	if adminEndpoint != "" {
+		adminMux := supporthttp.NewMux(d.logger)
 		// after importing net/http/pprof, debug endpoints are implicitly registered in the default serve mux
-		adminServer = &http.Server{Addr: adminEndpoint, Handler: http.DefaultServeMux}
+		adminMux.Handle("/", http.DefaultServeMux)
+		adminServer = &http.Server{Addr: adminEndpoint, Handler: adminMux}
 		go func() {
 			if err := adminServer.ListenAndServe(); !errors.Is(err, http.ErrServerClosed) {
 				d.logger.Errorf("Soroban admin server encountered fatal error: %v", err)
@@ -240,7 +247,7 @@ func Run(cfg config.LocalConfig, endpoint string, adminEndpoint string) {
 	if adminServer != nil {
 		if err := adminServer.Shutdown(shutdownCtx); err != nil {
 			// Error from closing listeners, or context timeout:
-			d.logger.Errorf("Error during Soroban JSON admin server Shutdown: %v", err)
+			d.logger.Errorf("Error during Soroban admin server Shutdown: %v", err)
 		}
 	}
 }

cmd/soroban-rpc/internal/jsonrpc.go

@@ -1,12 +1,13 @@
 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/go-chi/chi/middleware"
 	"github.com/stellar/go/clients/stellarcore"
 	"github.com/stellar/go/support/log"
 
@@ -44,6 +45,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 +60,39 @@ 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) {
+	r.logger.WithFields(log.F{
+		"subsys":   "jsonrpc",
+		"req":      middleware.GetReqID(ctx),
+		"json_req": req.ID(),
+		"method":   req.Method(),
+		// TODO: is this overkill?
+		"params": req.ParamString(),
+	}).Info("starting JSONRPC request")
+}
+
+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)
+	r.logger.WithFields(log.F{
+		"subsys":   "jsonrpc",
+		"req":      middleware.GetReqID(ctx),
+		"json_req": rsp.ID(),
+		"error":    rsp.Error().Error(),
+		// TODO: is this overkill?
+		"result": rsp.ResultString(),
+	}).Info("finished JSONRPC request")
+}

go.mod

@@ -6,11 +6,10 @@ 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/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 +29,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 +37,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
@@ -56,6 +55,7 @@ require (
 	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