Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Merged
merged 6 commits into from
Apr 18, 2023
Merged

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

Show file tree
Hide file tree
Changes from 5 commits
Commits
Show all changes
6 commits
Select commit Hold shift + click to select a range
0633833
soroban-rpc: Add logging for HTTP requests and JSONRPC requests
2opremio Apr 11, 2023
22fbf5f
Fix possible nil error during logging
2opremio Apr 13, 2023
3e4d959
Only print the parameters and result in debug mode
2opremio Apr 17, 2023
f86eac3
Address review feedback
2opremio Apr 17, 2023
aad0030
Fix typo
2opremio Apr 17, 2023
ef249be
Add a FIXME for the HTTP request IDs not working
2opremio Apr 17, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
31 changes: 18 additions & 13 deletions cmd/soroban-rpc/internal/daemon/daemon.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -4,7 +4,7 @@ import (
"context"
"errors"
"net/http"
"net/http/pprof"
"net/http/pprof" //nolint:gosec
"os"
"os/signal"
"sync"
Expand All @@ -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"
Expand All @@ -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
Expand All @@ -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)
}
Expand All @@ -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)
Expand All @@ -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
Expand Down Expand Up @@ -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,
Expand All @@ -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,
Expand All @@ -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()
Expand Down
56 changes: 47 additions & 9 deletions cmd/soroban-rpc/internal/jsonrpc.go
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -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"

Expand Down Expand Up @@ -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),
Expand All @@ -53,16 +60,47 @@ 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",
"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",
"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")
}
8 changes: 4 additions & 4 deletions go.mod
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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
Expand All @@ -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
Expand All @@ -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
Expand Down