RPC: --http.dbg.single=true and custom HTTP header dbg: true (eri…

…gontech#10039)

- Added method `tx.Context()` - because Tx already bounded to context by
`db.BeginRo(ctx)`
- Removed ctx parameter from `BlockWithSenders` method in interfaces
- Added `dbg.ToContext()` and `dbg.Enabled(ctx)` methods to set/get
debugging tag to `ctx`.

Added way to debug single http request: 
To print more detailed logs for 1 request - add `--http.dbg.single=true`
flag. Then can send HTTP header `"dbg: true"`:

```
curl -X POST -H "dbg: true" -H "Content-Type: application/json" --data '{"jsonrpc": "2.0", "method": "eth_blockNumber", "params": [], "id":1}' localhost:8545
```

---------

Co-authored-by: battlmonstr <[email protected]>

cmd/rpcdaemon/README.md

@@ -1,21 +1,21 @@
 - [Introduction](#introduction)
 - [Getting Started](#getting-started)
-  - [Running locally](#running-locally)
-  - [Running remotely](#running-remotely)
-  - [Healthcheck](#healthcheck)
-  - [Testing](#testing)
+    - [Running locally](#running-locally)
+    - [Running remotely](#running-remotely)
+    - [Healthcheck](#healthcheck)
+    - [Testing](#testing)
 - [FAQ](#faq)
-  - [Relations between prune options and rpc methods](#relations-between-prune-options-and-rpc-method)
-  - [RPC Implementation Status](#rpc-implementation-status)
-  - [Securing the communication between RPC daemon and Erigon instance via TLS and authentication](#securing-the-communication-between-rpc-daemon-and-erigon-instance-via-tls-and-authentication)
-  - [Ethstats](#ethstats)
-  - [Allowing only specific methods (Allowlist)](#allowing-only-specific-methods--allowlist-)
-  - [Trace transactions progress](#trace-transactions-progress)
-  - [Clients getting timeout, but server load is low](#clients-getting-timeout--but-server-load-is-low)
-  - [Server load too high](#server-load-too-high)
-  - [Faster Batch requests](#faster-batch-requests)
+    - [Relations between prune options and rpc methods](#relations-between-prune-options-and-rpc-method)
+    - [RPC Implementation Status](#rpc-implementation-status)
+    - [Securing the communication between RPC daemon and Erigon instance via TLS and authentication](#securing-the-communication-between-rpc-daemon-and-erigon-instance-via-tls-and-authentication)
+    - [Ethstats](#ethstats)
+    - [Allowing only specific methods (Allowlist)](#allowing-only-specific-methods--allowlist-)
+    - [Trace transactions progress](#trace-transactions-progress)
+    - [Clients getting timeout, but server load is low](#clients-getting-timeout--but-server-load-is-low)
+    - [Server load too high](#server-load-too-high)
+    - [Faster Batch requests](#faster-batch-requests)
 - [For Developers](#for-developers)
-  - [Code generation](#code-generation)
+    - [Code generation](#code-generation)
 
 ## Introduction
 
@@ -72,7 +72,8 @@ it may scale well for some workloads that are heavy on the current state queries
 
 ### Healthcheck
 
-There are 2 options for running healtchecks, POST request, or GET request with custom headers. Both options are available
+There are 2 options for running healtchecks, POST request, or GET request with custom headers. Both options are
+available
 at the `/health` endpoint.
 
 #### POST request
@@ -172,6 +173,14 @@ Also, there
 are [extensive instructions for using Postman](https://github.com/ledgerwatch/erigon/wiki/Using-Postman-to-Test-TurboGeth-RPC)
 to test the RPC.
 
+### Debugging
+
+To print more detailed logs for 1 request - add `--rpc.dbg.single=true` flag. Then can send HTTP header `"dbg: true"`:
+
+```
+curl -X POST -H "dbg: true" -H "Content-Type: application/json" --data '{"jsonrpc": "2.0", "method": "eth_blockNumber", "params": [], "id":1}' localhost:8545
+```
+
 ## FAQ
 
 ### Relations between prune options and RPC methods
@@ -191,7 +200,8 @@ Some methods, if not found historical data in DB, can fallback to old blocks re-
 
 ### The --http.url flag
 
-the `--http.url` flag is an optional flag which allows one to bind the HTTP server to a socket, for example, `tcp6://:8545` or `unix:///erigon_http.socket`
+the `--http.url` flag is an optional flag which allows one to bind the HTTP server to a socket, for
+example, `tcp6://:8545` or `unix:///erigon_http.socket`
 
 If the `--http.url` flag is set, then `--http.addr` and `--http.port` with both be ignored.
 
@@ -201,11 +211,13 @@ note that this is NOT geth-style IPC. for that, read the next section, IPC endpo
 
 Erigon supports HTTPS, HTTP2, and H2C out of the box. H2C is served by the default HTTP handler.
 
-To enable the HTTPS+HTTP2 server, add flag `--https.enabled`, along with providing flags `-https.cert="/path/to.cert"` and `--https.key=/path/to.key`
+To enable the HTTPS+HTTP2 server, add flag `--https.enabled`, along with providing flags `-https.cert="/path/to.cert"`
+and `--https.key=/path/to.key`
 
 By default, the HTTPS server will run on the HTTP port + 363. use flag `--https.port` to set the port
 
-The HTTPS server will inherit all other configuration parameters from http, for instance, enabling the websocket server, cors domains, or enabled namespaces
+The HTTPS server will inherit all other configuration parameters from http, for instance, enabling the websocket server,
+cors domains, or enabled namespaces
 
 If the `--https.url` flag is set, then `--https.addr` and `--https.port` with both be ignored.
 
@@ -226,7 +238,7 @@ Label "remote" means: `--private.api.addr` flag is required.
 The following table shows the current implementation status of Erigon's RPC daemon.
 
 | Command                                    | Avail   | Notes                                |
-| ------------------------------------------ | ------- | ------------------------------------ |
+|--------------------------------------------|---------|--------------------------------------|
 | admin_nodeInfo                             | Yes     |                                      |
 | admin_peers                                | Yes     |                                      |
 | admin_addPeer                              | Yes     |                                      |
@@ -374,7 +386,7 @@ The following table shows the current implementation status of Erigon's RPC daem
 ### GraphQL
 
 | Command         | Avail | Notes |
-| --------------- | ----- | ----- |
+|-----------------|-------|-------|
 | GetBlockDetails | Yes   |       |
 | GetChainID      | Yes   |       |
 
@@ -503,9 +515,9 @@ Then update your `app.json` for ethstats-client like that:
       "RPC_PORT": "8545",
       "LISTENING_PORT": "30303",
       "INSTANCE_NAME": "Erigon node",
-      "CONTACT_DETAILS": <your twitter handle>,
+      "CONTACT_DETAILS": "<your twitter handle>",
       "WS_SERVER": "wss://ethstats.net/api",
-      "WS_SECRET": <put your secret key here>,
+      "WS_SECRET": "<put your secret key here>",
       "VERBOSITY": 2
     }
   }
@@ -532,7 +544,10 @@ with `rpc.accessList` flag.
 
 ```json
 {
-  "allow": ["net_version", "web3_eth_getBlockByHash"]
+  "allow": [
+    "net_version",
+    "web3_eth_getBlockByHash"
+  ]
 }
 ```
 

cmd/rpcdaemon/cli/config.go

@@ -95,6 +95,7 @@ func RootCommand() (*cobra.Command, *httpcfg.HttpCfg) {
 	rootCmd.PersistentFlags().StringVar(&cfg.RpcAllowListFilePath, utils.RpcAccessListFlag.Name, "", "Specify granular (method-by-method) API allowlist")
 	rootCmd.PersistentFlags().UintVar(&cfg.RpcBatchConcurrency, utils.RpcBatchConcurrencyFlag.Name, 2, utils.RpcBatchConcurrencyFlag.Usage)
 	rootCmd.PersistentFlags().BoolVar(&cfg.RpcStreamingDisable, utils.RpcStreamingDisableFlag.Name, false, utils.RpcStreamingDisableFlag.Usage)
+	rootCmd.PersistentFlags().BoolVar(&cfg.DebugSingleRequest, utils.HTTPDebugSingleFlag.Name, false, utils.HTTPDebugSingleFlag.Usage)
 	rootCmd.PersistentFlags().IntVar(&cfg.DBReadConcurrency, utils.DBReadConcurrencyFlag.Name, utils.DBReadConcurrencyFlag.Value, utils.DBReadConcurrencyFlag.Usage)
 	rootCmd.PersistentFlags().BoolVar(&cfg.TraceCompatibility, "trace.compat", false, "Bug for bug compatibility with OE for trace_ routines")
 	rootCmd.PersistentFlags().StringVar(&cfg.TxPoolApiAddr, "txpool.api.addr", "", "txpool api network address, for example: 127.0.0.1:9090 (default: use value of --private.api.addr)")
@@ -566,7 +567,7 @@ func StartRpcServerWithJwtAuthentication(ctx context.Context, cfg *httpcfg.HttpC
 
 func startRegularRpcServer(ctx context.Context, cfg *httpcfg.HttpCfg, rpcAPI []rpc.API, logger log.Logger) error {
 	// register apis and create handler stack
-	srv := rpc.NewServer(cfg.RpcBatchConcurrency, cfg.TraceRequests, cfg.RpcStreamingDisable, logger, cfg.RPCSlowLogThreshold)
+	srv := rpc.NewServer(cfg.RpcBatchConcurrency, cfg.TraceRequests, cfg.DebugSingleRequest, cfg.RpcStreamingDisable, logger, cfg.RPCSlowLogThreshold)
 
 	allowListForRPC, err := parseAllowListForRPC(cfg.RpcAllowListFilePath)
 	if err != nil {
@@ -749,7 +750,7 @@ type engineInfo struct {
 }
 
 func startAuthenticatedRpcServer(cfg *httpcfg.HttpCfg, rpcAPI []rpc.API, logger log.Logger) (*engineInfo, error) {
-	srv := rpc.NewServer(cfg.RpcBatchConcurrency, cfg.TraceRequests, cfg.RpcStreamingDisable, logger, cfg.RPCSlowLogThreshold)
+	srv := rpc.NewServer(cfg.RpcBatchConcurrency, cfg.TraceRequests, cfg.DebugSingleRequest, cfg.RpcStreamingDisable, logger, cfg.RPCSlowLogThreshold)
 
 	engineListener, engineSrv, engineHttpEndpoint, err := createEngineListener(cfg, rpcAPI, logger)
 	if err != nil {
@@ -839,7 +840,7 @@ func createHandler(cfg *httpcfg.HttpCfg, apiList []rpc.API, httpHandler http.Han
 func createEngineListener(cfg *httpcfg.HttpCfg, engineApi []rpc.API, logger log.Logger) (*http.Server, *rpc.Server, string, error) {
 	engineHttpEndpoint := fmt.Sprintf("tcp://%s:%d", cfg.AuthRpcHTTPListenAddress, cfg.AuthRpcPort)
 
-	engineSrv := rpc.NewServer(cfg.RpcBatchConcurrency, cfg.TraceRequests, true, logger, cfg.RPCSlowLogThreshold)
+	engineSrv := rpc.NewServer(cfg.RpcBatchConcurrency, cfg.TraceRequests, cfg.DebugSingleRequest, true, logger, cfg.RPCSlowLogThreshold)
 
 	if err := node.RegisterApisFromWhitelist(engineApi, nil, engineSrv, true, logger); err != nil {
 		return nil, nil, "", fmt.Errorf("could not start register RPC engine api: %w", err)

cmd/rpcdaemon/cli/httpcfg/http_cfg.go

@@ -68,7 +68,8 @@ type HttpCfg struct {
 	SocketListenUrl     string
 
 	JWTSecretPath             string // Engine API Authentication
-	TraceRequests             bool   // Always trace requests in INFO level
+	TraceRequests             bool   // Print requests to logs at INFO level
+	DebugSingleRequest        bool   // Print single-request-related debugging info to logs at INFO level
 	HTTPTimeouts              rpccfg.HTTPTimeouts
 	AuthRpcTimeouts           rpccfg.HTTPTimeouts
 	EvmCallTimeout            time.Duration

cmd/utils/flags.go

@@ -403,7 +403,11 @@ var (
 	}
 	HTTPTraceFlag = cli.BoolFlag{
 		Name:  "http.trace",
-		Usage: "Trace HTTP requests with INFO level",
+		Usage: "Print all HTTP requests to logs with INFO level",
+	}
+	HTTPDebugSingleFlag = cli.BoolFlag{
+		Name:  "http.dbg.single",
+		Usage: "Allow pass HTTP header 'dbg: true' to printt more detailed logs - how this request was executed",
 	}
 	DBReadConcurrencyFlag = cli.IntFlag{
 		Name:  "db.read.concurrency",

erigon-lib/common/dbg/dbg_ctx.go

@@ -0,0 +1,23 @@
+package dbg
+
+import (
+	"context"
+)
+
+type debugContextKey struct{}
+
+// Enabling detailed debugging logs for given context
+func ContextWithDebug(ctx context.Context, v bool) context.Context {
+	return context.WithValue(ctx, debugContextKey{}, v)
+}
+func Enabled(ctx context.Context) bool {
+	v := ctx.Value(debugContextKey{})
+	if v == nil {
+		return false
+	}
+	return v.(bool)
+}
+
+// https://stackoverflow.com/a/3561399 -> https://www.rfc-editor.org/rfc/rfc6648
+// https://stackoverflow.com/a/65241869 -> https://www.odata.org/documentation/odata-version-3-0/abnf/ -> https://docs.oasis-open.org/odata/odata/v4.01/cs01/abnf/odata-abnf-construction-rules.txt
+var HTTPHeader = "dbg" // curl --header "dbg: true" www.google.com

node/rpcstack.go

@@ -265,7 +265,7 @@ func (h *httpServer) enableRPC(apis []rpc.API, config httpConfig, allowList rpc.
 	}
 
 	// Create RPC server and handler.
-	srv := rpc.NewServer(50, false /* traceRequests */, true, h.logger, 0)
+	srv := rpc.NewServer(50, false /* traceRequests */, false /* traceSingleRequest */, true, h.logger, 0)
 	srv.SetAllowList(allowList)
 	if err := RegisterApisFromWhitelist(apis, config.Modules, srv, false, h.logger); err != nil {
 		return err
@@ -298,7 +298,7 @@ func (h *httpServer) enableWS(apis []rpc.API, config wsConfig, allowList rpc.All
 	}
 
 	// Create RPC server and handler.
-	srv := rpc.NewServer(50, false /* traceRequests */, true, h.logger, 0)
+	srv := rpc.NewServer(50, false /* traceRequests */, false /* debugSingleRequest */, true, h.logger, 0)
 	srv.SetAllowList(allowList)
 	if err := RegisterApisFromWhitelist(apis, config.Modules, srv, false, h.logger); err != nil {
 		return err

rpc/http.go

@@ -33,6 +33,7 @@ import (
 
 	"github.com/golang-jwt/jwt/v4"
 	jsoniter "github.com/json-iterator/go"
+	"github.com/ledgerwatch/erigon-lib/common/dbg"
 	"github.com/ledgerwatch/log/v3"
 )
 
@@ -245,6 +246,12 @@ func (s *Server) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 	if origin := r.Header.Get("Origin"); origin != "" {
 		ctx = context.WithValue(ctx, "Origin", origin)
 	}
+	if s.debugSingleRequest {
+		if v := r.Header.Get(dbg.HTTPHeader); v == "true" {
+			ctx = dbg.ContextWithDebug(ctx, true)
+
+		}
+	}
 
 	w.Header().Set("content-type", contentType)
 	codec := newHTTPServerConn(r, w)

rpc/http_test.go

@@ -107,7 +107,7 @@ func TestHTTPRespBodyUnlimited(t *testing.T) {
 	logger := log.New()
 	const respLength = maxRequestContentLength * 3
 
-	s := NewServer(50, false /* traceRequests */, true, logger, 100)
+	s := NewServer(50, false /* traceRequests */, false /* debugSingleRequests */, true, logger, 100)
 	defer s.Stop()
 	if err := s.RegisterName("test", largeRespService{respLength}); err != nil {
 		t.Fatal(err)

rpc/server.go

@@ -54,15 +54,16 @@ type Server struct {
 	batchConcurrency    uint
 	disableStreaming    bool
 	traceRequests       bool // Whether to print requests at INFO level
+	debugSingleRequest  bool // Whether to print requests at INFO level
 	batchLimit          int  // Maximum number of requests in a batch
 	logger              log.Logger
 	rpcSlowLogThreshold time.Duration
 }
 
 // NewServer creates a new server instance with no registered handlers.
-func NewServer(batchConcurrency uint, traceRequests, disableStreaming bool, logger log.Logger, rpcSlowLogThreshold time.Duration) *Server {
+func NewServer(batchConcurrency uint, traceRequests, debugSingleRequest, disableStreaming bool, logger log.Logger, rpcSlowLogThreshold time.Duration) *Server {
 	server := &Server{services: serviceRegistry{logger: logger}, idgen: randomIDGenerator(), codecs: mapset.NewSet(), run: 1, batchConcurrency: batchConcurrency,
-		disableStreaming: disableStreaming, traceRequests: traceRequests, logger: logger, rpcSlowLogThreshold: rpcSlowLogThreshold}
+		disableStreaming: disableStreaming, traceRequests: traceRequests, debugSingleRequest: debugSingleRequest, logger: logger, rpcSlowLogThreshold: rpcSlowLogThreshold}
 	// Register the default service providing meta information about the RPC service such
 	// as the services and methods it offers.
 	rpcService := &RPCService{server: server}

rpc/server_test.go

@@ -34,7 +34,7 @@ import (
 
 func TestServerRegisterName(t *testing.T) {
 	logger := log.New()
-	server := NewServer(50, false /* traceRequests */, true, logger, 100)
+	server := NewServer(50, false /* traceRequests */, false /* debugSingleRequests */, true, logger, 100)
 	service := new(testService)
 
 	if err := server.RegisterName("test", service); err != nil {

rpc/subscription_test.go

@@ -56,7 +56,7 @@ func TestSubscriptions(t *testing.T) {
 		subCount          = len(namespaces)
 		notificationCount = 3
 
-		server                 = NewServer(50, false /* traceRequests */, true, logger, 100)
+		server                 = NewServer(50, false /* traceRequests */, false /* debugSingleRequests */, true, logger, 100)
 		clientConn, serverConn = net.Pipe()
 		out                    = json.NewEncoder(clientConn)
 		in                     = json.NewDecoder(clientConn)

rpc/testservice_test.go

@@ -28,7 +28,7 @@ import (
 )
 
 func newTestServer(logger log.Logger) *Server {
-	server := NewServer(50, false /* traceRequests */, true, logger, 100)
+	server := NewServer(50, false /* traceRequests */, false /* debugSingleRequests */, true, logger, 100)
 	server.idgen = sequentialIDGenerator()
 	if err := server.RegisterName("test", new(testService)); err != nil {
 		panic(err)

rpc/websocket_test.go

@@ -168,7 +168,7 @@ func TestClientWebsocketPing(t *testing.T) {
 func TestClientWebsocketLargeMessage(t *testing.T) {
 	logger := log.New()
 	var (
-		srv     = NewServer(50, false /* traceRequests */, true, logger, 100)
+		srv     = NewServer(50, false /* traceRequests */, false /* debugSingleRequests */, true, logger, 100)
 		httpsrv = httptest.NewServer(srv.WebsocketHandler(nil, nil, false, logger))
 		wsURL   = "ws:" + strings.TrimPrefix(httpsrv.URL, "http:")
 	)

turbo/cli/default_flags.go

@@ -68,6 +68,7 @@ var DefaultFlags = []cli.Flag{
 	&utils.WSEnabledFlag,
 	&utils.WsCompressionFlag,
 	&utils.HTTPTraceFlag,
+	&utils.HTTPDebugSingleFlag,
 	&utils.StateCacheFlag,
 	&utils.RpcBatchConcurrencyFlag,
 	&utils.RpcStreamingDisableFlag,

turbo/cli/flags.go

@@ -462,6 +462,7 @@ func setEmbeddedRpcDaemon(ctx *cli.Context, cfg *nodecfg.Config, logger log.Logg
 		AuthRpcPort:              ctx.Int(utils.AuthRpcPort.Name),
 		JWTSecretPath:            jwtSecretPath,
 		TraceRequests:            ctx.Bool(utils.HTTPTraceFlag.Name),
+		DebugSingleRequest:       ctx.Bool(utils.HTTPDebugSingleFlag.Name),
 		HttpCORSDomain:           libcommon.CliString2Array(ctx.String(utils.HTTPCORSDomainFlag.Name)),
 		HttpVirtualHost:          libcommon.CliString2Array(ctx.String(utils.HTTPVirtualHostsFlag.Name)),
 		AuthRpcVirtualHost:       libcommon.CliString2Array(ctx.String(utils.AuthRpcVirtualHostsFlag.Name)),