From d91f86a683e6e38c7e4f68fdf449369bed5e154d Mon Sep 17 00:00:00 2001 From: Lee Bousfield Date: Tue, 17 Jan 2023 23:47:40 -0700 Subject: [PATCH 1/3] Add trace-level logging of RPC requests --- cmd/nitro/nitro.go | 27 ++++++++++++++++++++++++++- go-ethereum | 2 +- staker/l1_validator.go | 4 ++-- 3 files changed, 29 insertions(+), 4 deletions(-) diff --git a/cmd/nitro/nitro.go b/cmd/nitro/nitro.go index a9eedde29a..29369045da 100644 --- a/cmd/nitro/nitro.go +++ b/cmd/nitro/nitro.go @@ -40,6 +40,7 @@ import ( "github.com/ethereum/go-ethereum/metrics" "github.com/ethereum/go-ethereum/metrics/exp" "github.com/ethereum/go-ethereum/node" + "github.com/ethereum/go-ethereum/rpc" "github.com/offchainlabs/nitro/arbnode" "github.com/offchainlabs/nitro/cmd/conf" @@ -564,6 +565,27 @@ func (c *NodeConfig) Validate() error { return c.Node.Validate() } +type RpcLogger struct{} + +func (l RpcLogger) OnRequest(request interface{}) rpc.ResultHook { + log.Trace("sending L1 RPC request", "request", request) + return RpcResultLogger{request} +} + +type RpcResultLogger struct { + request interface{} +} + +func (l RpcResultLogger) OnResult(response interface{}, err error) { + if err != nil { + // The request might not've been logged if the log level is debug not trace, so we log it again here + log.Debug("received error response from L1 RPC", "request", l.request, "response", response, "err", err) + } else { + // The request was already logged and can be cross-referenced by JSON-RPC id + log.Trace("received response from L1 RPC", "response", response, "err", err) + } +} + func ParseNode(ctx context.Context, args []string) (*NodeConfig, *genericconf.WalletConfig, *genericconf.WalletConfig, *ethclient.Client, *big.Int, error) { f := flag.NewFlagSet("", flag.ContinueOnError) @@ -584,8 +606,11 @@ func ParseNode(ctx context.Context, args []string) (*NodeConfig, *genericconf.Wa maxConnectionAttempts = math.MaxInt } for i := 1; i <= maxConnectionAttempts; i++ { - l1Client, err = ethclient.DialContext(ctx, l1URL) + rawRpc, err := rpc.DialContext(ctx, l1URL) + var requestHook rpc.RequestHook = RpcLogger{} + rawRpc.RequestHook.Store(&requestHook) if err == nil { + l1Client = ethclient.NewClient(rawRpc) l1ChainId, err = l1Client.ChainID(ctx) if err == nil { // Successfully got chain ID diff --git a/go-ethereum b/go-ethereum index a07bb852dc..73434d8f3a 160000 --- a/go-ethereum +++ b/go-ethereum @@ -1 +1 @@ -Subproject commit a07bb852dc845ec35437ef8f8afb776e4dd1129c +Subproject commit 73434d8f3a6aee4051fc971ee06a7757ffc95932 diff --git a/staker/l1_validator.go b/staker/l1_validator.go index 95938165f5..19cdbb4fae 100644 --- a/staker/l1_validator.go +++ b/staker/l1_validator.go @@ -336,7 +336,7 @@ func (v *L1Validator) generateNodeAction(ctx context.Context, stakerInfo *OurSta } } - currentL1Block, err := v.client.BlockByNumber(ctx, nil) + currentL1BlockNum, err := v.client.BlockNumber(ctx) if err != nil { return nil, false, err } @@ -346,7 +346,7 @@ func (v *L1Validator) generateNodeAction(ctx context.Context, stakerInfo *OurSta return nil, false, err } - timeSinceProposed := new(big.Int).Sub(currentL1Block.Number(), new(big.Int).SetUint64(startStateProposed)) + timeSinceProposed := big.NewInt(int64(currentL1BlockNum) - int64(startStateProposed)) if timeSinceProposed.Cmp(minAssertionPeriod) < 0 { // Too soon to assert return nil, false, nil From a4f8d6fe514c8a7c19752d2d7d47bcc6c420e278 Mon Sep 17 00:00:00 2001 From: Lee Bousfield Date: Wed, 18 Jan 2023 00:01:39 -0700 Subject: [PATCH 2/3] Update geth pin and use new request hook API --- cmd/nitro/nitro.go | 4 +--- go-ethereum | 2 +- 2 files changed, 2 insertions(+), 4 deletions(-) diff --git a/cmd/nitro/nitro.go b/cmd/nitro/nitro.go index 29369045da..939bc727e6 100644 --- a/cmd/nitro/nitro.go +++ b/cmd/nitro/nitro.go @@ -606,9 +606,7 @@ func ParseNode(ctx context.Context, args []string) (*NodeConfig, *genericconf.Wa maxConnectionAttempts = math.MaxInt } for i := 1; i <= maxConnectionAttempts; i++ { - rawRpc, err := rpc.DialContext(ctx, l1URL) - var requestHook rpc.RequestHook = RpcLogger{} - rawRpc.RequestHook.Store(&requestHook) + rawRpc, err := rpc.DialContextWithRequestHook(ctx, l1URL, RpcLogger{}) if err == nil { l1Client = ethclient.NewClient(rawRpc) l1ChainId, err = l1Client.ChainID(ctx) diff --git a/go-ethereum b/go-ethereum index 73434d8f3a..c90128a6d0 160000 --- a/go-ethereum +++ b/go-ethereum @@ -1 +1 @@ -Subproject commit 73434d8f3a6aee4051fc971ee06a7757ffc95932 +Subproject commit c90128a6d08879b75816be74f0f382d78b58765f From 4b7b80a99f78ea4b9970e1305aecc8d10a7ad5f7 Mon Sep 17 00:00:00 2001 From: Lee Bousfield Date: Wed, 18 Jan 2023 23:06:16 -0700 Subject: [PATCH 3/3] Address PR comments --- cmd/nitro/nitro.go | 4 ++-- util/headerreader/header_reader.go | 1 + 2 files changed, 3 insertions(+), 2 deletions(-) diff --git a/cmd/nitro/nitro.go b/cmd/nitro/nitro.go index 939bc727e6..72495feb01 100644 --- a/cmd/nitro/nitro.go +++ b/cmd/nitro/nitro.go @@ -579,10 +579,10 @@ type RpcResultLogger struct { func (l RpcResultLogger) OnResult(response interface{}, err error) { if err != nil { // The request might not've been logged if the log level is debug not trace, so we log it again here - log.Debug("received error response from L1 RPC", "request", l.request, "response", response, "err", err) + log.Info("received error response from L1 RPC", "request", l.request, "response", response, "err", err) } else { // The request was already logged and can be cross-referenced by JSON-RPC id - log.Trace("received response from L1 RPC", "response", response, "err", err) + log.Trace("received response from L1 RPC", "response", response) } } diff --git a/util/headerreader/header_reader.go b/util/headerreader/header_reader.go index 7b7ed3f47a..e5c2c92a5b 100644 --- a/util/headerreader/header_reader.go +++ b/util/headerreader/header_reader.go @@ -231,6 +231,7 @@ func (s *HeaderReader) broadcastLoop(ctx context.Context) { timer := time.NewTimer(s.config().PollInterval) select { case h := <-inputChannel: + log.Trace("got new header from L1", "number", h.Number, "hash", h.Hash(), "header", h) s.possiblyBroadcast(h) timer.Stop() case <-timer.C: