Skip to content

Add trace-level logging of RPC requests #1441

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

Merged
merged 5 commits into from
Jan 19, 2023
Merged

Add trace-level logging of RPC requests #1441

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
d91f86a
Add trace-level logging of RPC requests
PlasmaPower Jan 18, 2023
a4f8d6f
Update geth pin and use new request hook API
PlasmaPower Jan 18, 2023
4b7b80a
Address PR comments
PlasmaPower Jan 19, 2023
d721711
Merge branch 'master' into l1-rpc-logging
PlasmaPower Jan 19, 2023
41b01eb
Merge branch 'master' into l1-rpc-logging
PlasmaPower Jan 19, 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
25 changes: 24 additions & 1 deletion cmd/nitro/nitro.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down Expand Up @@ -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.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)
}
}
Copy link
Contributor

@tsahee tsahee Jan 19, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

To log all l1 - we should also add a print in HeaderReader when receiving events from SubscribeNewHead, same loglevel as OnResult. I think that's the only subscribe in nitro node.
We could add a hook in client for subscriptions - but since subscription is already a hook it seems redundant.

Copy link
Contributor Author

@PlasmaPower PlasmaPower Jan 19, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I've added a log line there


func ParseNode(ctx context.Context, args []string) (*NodeConfig, *genericconf.WalletConfig, *genericconf.WalletConfig, *ethclient.Client, *big.Int, error) {
f := flag.NewFlagSet("", flag.ContinueOnError)

Expand All @@ -584,8 +606,9 @@ 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.DialContextWithRequestHook(ctx, l1URL, RpcLogger{})
if err == nil {
l1Client = ethclient.NewClient(rawRpc)
l1ChainId, err = l1Client.ChainID(ctx)
if err == nil {
// Successfully got chain ID
Expand Down
2 changes: 1 addition & 1 deletion go-ethereum
Open in desktop
Submodule go-ethereum updated 3 files
+9 −0 metrics/sample.go
+22 −2 rpc/client.go
+50 −0 rpc/client_arbitrum.go
4 changes: 2 additions & 2 deletions staker/l1_validator.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
}
Expand All @@ -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
Expand Down
1 change: 1 addition & 0 deletions util/headerreader/header_reader.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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:
Expand Down