Client: fix rpc debug #3125

jochem-brouwer · 2023-10-30T13:58:10Z

The rpc debug is inconsistent and this PR fixes it. Currently it seems to always truncate RPC logs.

It adds a new flag rpcDebugVerbose which allows for a comma-separated list of methods to log in full. Same for rpcDebug, this logs the commands but will truncate those. If both rpcDebugVerbose and rpcDebug filters match the method, the log is not truncated. The necessity to --loglevel debug is removed to log the methods in full (the logs are written to INFO).

TODO: explicitly test this (but this should work)

Note: it is also possible to skip adding this new flag, and instead adding the word "verbose" to rpcDebug as suggested by Holger. However, this would imply that then all methods which match the filter are logged in verbose and I think this extra flag option gives us more freedom to explicitly verbose-log these methods.

codecov · 2023-10-30T14:01:23Z

Codecov Report

Merging #3125 (7088542) into master (1723406) will decrease coverage by 0.04%.
The diff coverage is 94.87%.

Additional details and impacted files

Flag	Coverage Δ
block	`88.80% <ø> (ø)`
blockchain	`92.27% <ø> (ø)`
client	`86.14% <94.87%> (-0.05%)`	⬇️
common	`98.19% <ø> (ø)`
devp2p	`86.32% <ø> (ø)`
ethash	`∅ <ø> (∅)`
evm	`71.93% <ø> (ø)`
statemanager	`90.13% <ø> (ø)`
trie	`89.72% <ø> (-0.34%)`	⬇️
tx	`96.36% <ø> (ø)`
util	`87.53% <ø> (ø)`
vm	`76.22% <ø> (ø)`

Flags with carried forward coverage won't be shown. Click here to find out more.

holgerd77 · 2023-10-31T08:29:28Z

RPC log truncating has a reason being mainly that from some RPC calls - particularly from the engine API - are so large that without truncating it is not possible any more to follow on the logging.

Can't completely oversee the changes from this PR respectively what it does and what not, but we need to find a good balance here to for one allow that it becomes possible - if one is interested in the outcome of one particular call - to see the full output. And on the other hand that RPC logging also allows for this "overview log", so that one has a constant ouptut of calls without getting overwhelmed.

jochem-brouwer · 2023-10-31T10:16:15Z

Just some clarification, without this PR it seems that rpcDebug does not work, we launch hive with these flags:

--gethGenesis ./genesis.json --rpc --rpcEngine --saveReceipts --rpcAddr 0.0.0.0 --rpcEngineAddr 0.0.0.0 --rpcEnginePort 8551 --ws false --logLevel debug --rpcDebug all --isSingleNode

Note: --rpcDebug all. This still truncates logs (without this PR). This PR fixes this.

holgerd77 · 2023-10-31T10:26:33Z

Yes, not sure if my comment was clear: rpcDebug logs needs to be truncated at least as an option, otherwise this becomes completely unreadable for certain use cases.

I wonder if we eventually want to bite the sour bullet or whatever and DO another explicit option here?? --truncateRPCLogs or whatever? Since this is definitely otherwise totally intransparent and also gave me headaches as well in the past. But one definitely needs both.

Side note: beyond there are some RPC log inconsistencies in the client, e.g. parts of the (core) engine API (I think FCU and newPayload() ?) is not logged through the option but on normal debug mode, which is confusing and we should fix as well at some point.

jochem-brouwer · 2023-10-31T12:08:40Z

Ah ok good point, I just re-checked, we have this (also in this PR - it is unchanged), see client/src/util/rpc.ts.

      if (show) {
        if (logger?.level === 'debug') {
          msg += `${request.method} called with params:\n${inspectParams(request.params)}`
        } else {
          msg += `${request.method} called with params: ${inspectParams(request.params, 125)}`
        }
        logger?.info(msg)
      }

Therefore, if --rpcDebug is enabled but --loglevel is not set to debug, the logs are truncated (by 125 chars) by default. So to get full logs, one has to explicitly set --loglevel to debug. (However this might raise the question: do we want an extra flag to actually --loglevel debug but not dump the rpcDebug completely (so truncate it)? (Especially for blob txs these might indeed get very large!))

scorbajio · 2023-10-31T17:55:11Z

packages/client/src/util/rpc.ts

  const onRequest = (request: any) => {
    let msg = ''
    if (rpcDebug && rpcDebug !== '') {
      let show = false
-      if (rpcDebug === 'all') {
+      if (rpcDebug === '' || rpcDebug === 'all') {


Since we are earlier checking rpcDebug !== '' then we shouldn't need to check again if rpcDebug === ''.

scorbajio · 2023-10-31T18:34:14Z

packages/client/bin/cli.ts

@@ -207,7 +207,8 @@ const args: ClientOpts = yargs(hideBin(process.argv))
  .option('rpcDebug', {
    describe:
      'Additionally log complete RPC calls filtered by name (prefix), e.g.: "eth,engine_getPayload" (use "all" for all methods).',
-    default: '',
+    coerce: (arg: string) => (arg === '' ? 'all' : arg),


When I initially changed rpcDebug to allow for indicating a specific package for full request/response log output, I included a description with details about the need for logLevel being set to debug and also included choices which allowed for boolean options or a specific module to be enabled by name, as well as a default of false: b196a13. But now that we can pass in a comma separated string that could also include specific function names (e.g. eth,engine_getPayload), I think that we can look into using a yargs check function for the rpcDebug option to first validate the input and throw helpful error messages so users aren't confused as well as extend our description to include more usage details and maybe even some examples.

Yeah, would agree that this is a thing that we should well-document (also for ourselves).

scorbajio · 2023-10-31T18:36:21Z

packages/client/bin/cli.ts

@@ -207,7 +207,8 @@ const args: ClientOpts = yargs(hideBin(process.argv))
  .option('rpcDebug', {
    describe:
      'Additionally log complete RPC calls filtered by name (prefix), e.g.: "eth,engine_getPayload" (use "all" for all methods).',
-    default: '',


Using a default value can be more intuitive than removing it and instead having to handle undefined as a value.

holgerd77 · 2023-11-01T09:48:12Z

Ah ok good point, I just re-checked, we have this (also in this PR - it is unchanged), see client/src/util/rpc.ts.
      if (show) {
        if (logger?.level === 'debug') {
          msg += `${request.method} called with params:\n${inspectParams(request.params)}`
        } else {
          msg += `${request.method} called with params: ${inspectParams(request.params, 125)}`
        }
        logger?.info(msg)
      }
Therefore, if --rpcDebug is enabled but --loglevel is not set to debug, the logs are truncated (by 125 chars) by default. So to get full logs, one has to explicitly set --loglevel to debug. (However this might raise the question: do we want an extra flag to actually --loglevel debug but not dump the rpcDebug completely (so truncate it)? (Especially for blob txs these might indeed get very large!))

Yes, I was aware of this: debug -> full RPC log, otherwise -> truncated behavior.

And, yes, I think it would be worth to be able to tackle this separately (I can vaguely remember that I might have already tried on the sideline at some point?).

So an alternative to yet-another-flag might be that we add a keyword verbose to the existing option (important to add a note to CLI help as well then).

If this is added we do full logging (--rpcDebug=all,verbose, --rpcDebug=eth,verbose,...) otherwise we truncate.

jochem-brouwer · 2023-11-05T21:39:45Z

Have tested using some hive tests and can report that it works like the top post suggests. CI should also pass.

scorbajio

This looks good to me!

scorbajio · 2023-11-05T22:38:20Z

packages/client/src/util/rpc.ts

-        }
-        logger?.info(msg)
-      }
+    if (checkFilter(request.method, rpcDebugVerbose)) {


To note, the options are:

both rpcDebugVerbose and rpcDebug are true, in which case the full version will be logged

both rpcDebugVerbose and rpcDebug are false, in which case nothing will be logged on requests and responses

rpcDebugVerbose is true and rpcDebug is false, in which case the full version will be logged

rpcDebugVerbose is false and rpcDebug is true, in which case the truncated version will be logged

Yes, so for extra for clarification: the true and false are the returned values from this method, and are thus applied on the filter. If there is no filter (the filter is the empty string by default, so "no filter") then it always returns false.

jochem-brouwer · 2023-11-06T11:17:30Z

Have opened a PR for hive to update as well: ethereum/hive#939

holgerd77 · 2023-11-07T10:02:35Z

Maybe I missed this: what was the reasoning here again to go for the yet-another-flag solution in favor to an existing-flag using version like --rpcDebug=verbose,eth or similar?

jochem-brouwer · 2023-11-07T12:09:17Z

The reasoning is that you can now for instance log verbose logs for engine_newPayload, but choose to only log truncated eth_sendRawTransaction (especially blob txs are huge). We could also settle for a very specific format inside the rpcDebug flag if that is desired and drop the new flag.

holgerd77 · 2023-11-07T12:34:14Z

Ah ok, no, makes sense, cool, thanks!

client: fix rpc debug

3a13477

jochem-brouwer added PR state: needs review package: client labels Oct 30, 2023

scorbajio mentioned this pull request Oct 31, 2023

Add rpcDebug stack collection to all rpc modules #3127

Merged

Merge branch 'master' into fix-rpc-debug

5cc67e3

scorbajio reviewed Oct 31, 2023

View reviewed changes

client/rpc: add verbosity filter

e3b2fc3

jochem-brouwer added PR state: WIP and removed PR state: needs review labels Nov 4, 2023

jochem-brouwer added 3 commits November 4, 2023 21:05

Merge branch 'master' into fix-rpc-debug

16f0466

client: fix rpc test

3a4f4c6

Merge branch 'master' into fix-rpc-debug

7088542

jochem-brouwer added PR state: needs review and removed PR state: WIP labels Nov 5, 2023

scorbajio approved these changes Nov 5, 2023

View reviewed changes

scorbajio merged commit 49f3cca into master Nov 5, 2023
44 checks passed

scorbajio deleted the fix-rpc-debug branch November 5, 2023 22:40

jochem-brouwer mentioned this pull request Nov 6, 2023

clients/ethereumjs: verbose logging ethereum/hive#939

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Client: fix rpc debug #3125

Client: fix rpc debug #3125

jochem-brouwer commented Oct 30, 2023 •

edited

Loading

codecov bot commented Oct 30, 2023 •

edited

Loading

holgerd77 commented Oct 31, 2023

jochem-brouwer commented Oct 31, 2023

holgerd77 commented Oct 31, 2023

jochem-brouwer commented Oct 31, 2023 •

edited

Loading

scorbajio Oct 31, 2023

scorbajio Oct 31, 2023 •

edited

Loading

holgerd77 Nov 1, 2023

scorbajio Oct 31, 2023 •

edited

Loading

holgerd77 commented Nov 1, 2023

jochem-brouwer commented Nov 5, 2023

scorbajio left a comment

scorbajio Nov 5, 2023 •

edited

Loading

jochem-brouwer Nov 5, 2023

jochem-brouwer commented Nov 6, 2023

holgerd77 commented Nov 7, 2023

jochem-brouwer commented Nov 7, 2023

holgerd77 commented Nov 7, 2023

Client: fix rpc debug #3125

Client: fix rpc debug #3125

Conversation

jochem-brouwer commented Oct 30, 2023 • edited Loading

codecov bot commented Oct 30, 2023 • edited Loading

Codecov Report

holgerd77 commented Oct 31, 2023

jochem-brouwer commented Oct 31, 2023

holgerd77 commented Oct 31, 2023

jochem-brouwer commented Oct 31, 2023 • edited Loading

scorbajio Oct 31, 2023

Choose a reason for hiding this comment

scorbajio Oct 31, 2023 • edited Loading

Choose a reason for hiding this comment

holgerd77 Nov 1, 2023

Choose a reason for hiding this comment

scorbajio Oct 31, 2023 • edited Loading

Choose a reason for hiding this comment

holgerd77 commented Nov 1, 2023

jochem-brouwer commented Nov 5, 2023

scorbajio left a comment

Choose a reason for hiding this comment

scorbajio Nov 5, 2023 • edited Loading

Choose a reason for hiding this comment

jochem-brouwer Nov 5, 2023

Choose a reason for hiding this comment

jochem-brouwer commented Nov 6, 2023

holgerd77 commented Nov 7, 2023

jochem-brouwer commented Nov 7, 2023

holgerd77 commented Nov 7, 2023

jochem-brouwer commented Oct 30, 2023 •

edited

Loading

codecov bot commented Oct 30, 2023 •

edited

Loading

jochem-brouwer commented Oct 31, 2023 •

edited

Loading

scorbajio Oct 31, 2023 •

edited

Loading

scorbajio Oct 31, 2023 •

edited

Loading

scorbajio Nov 5, 2023 •

edited

Loading