lodestar icon indicating copy to clipboard operation
lodestar copied to clipboard

Redundant eth1 (Eth1Provider) logs vs execution logging when (dis)connected

Open philknows opened this issue 1 year ago • 4 comments

Describe the bug

When a connected execution client goes offline, Lodestar detects the disconnection, but prints out the two following logs:

Nov-25 21:04:33.334[execution]       error: Execution client went offline oldState=SYNCED, newState=OFFLINE
Nov-25 21:04:33.558[network]         error: Error receiving block slot=420322, peer=16Uiu2HAmC7eA5UzuYxRrUwshzEZaTkh2ByPuES7fpcBAhFVV3AuN, code=BLOCK_ERROR_EXECUTION_ERROR, execStatus=UNAVAILABLE, errorMessage=Request to http://localhost:8551 failed, reason: connect ECONNREFUSED 127.0.0.1:8551
Error: BLOCK_ERROR_EXECUTION_ERROR
    at verifyBlockExecutionPayload (file:///usr/app/packages/beacon-node/src/chain/blocks/verifyBlocksExecutionPayloads.ts:366:25)
    at verifyBlocksExecutionPayload (file:///usr/app/packages/beacon-node/src/chain/blocks/verifyBlocksExecutionPayloads.ts:157:28)
    at async Promise.all (index 0)
    at BeaconChain.verifyBlocksInEpoch (file:///usr/app/packages/beacon-node/src/chain/blocks/verifyBlock.ts:91:70)
    at BeaconChain.processBlocks (file:///usr/app/packages/beacon-node/src/chain/blocks/index.ts:75:68)
    at JobItemQueue.runJob (file:///usr/app/packages/beacon-node/src/util/queue/itemQueue.ts:101:22)
Nov-25 21:05:03.219[eth1]            error: Eth1Provider faced error state=OFFLINE, lastErrorAt=12:12:06 AM - Request to http://localhost:8551 failed, reason: connect ECONNREFUSED 127.0.0.1:8551
FetchError: Request to http://localhost:8551 failed, reason: connect ECONNREFUSED 127.0.0.1:8551
    at wrappedFetch (file:///usr/app/packages/api/src/utils/client/fetch.ts:10:11)
    at processTicksAndRejections (node:internal/process/task_queues:95:5)
    at JsonRpcHttpClient.fetchJsonOneUrl (file:///usr/app/packages/beacon-node/src/eth1/provider/jsonRpcHttpClient.ts:276:19)
    at JsonRpcHttpClient.fetchJson (file:///usr/app/packages/beacon-node/src/eth1/provider/jsonRpcHttpClient.ts:229:16)
    at wrapWithEvents.payload.payload (file:///usr/app/packages/beacon-node/src/eth1/provider/jsonRpcHttpClient.ts:147:37)
    at JsonRpcHttpClient.wrapWithEvents (file:///usr/app/packages/beacon-node/src/eth1/provider/jsonRpcHttpClient.ts:208:24)
    at Eth1Provider.getBlockNumber (file:///usr/app/packages/beacon-node/src/eth1/provider/eth1Provider.ts:186:28)
    at Eth1DepositDataTracker.update (file:///usr/app/packages/beacon-node/src/eth1/eth1DepositDataTracker.ts:197:32)
    at Eth1DepositDataTracker.runAutoUpdate (file:///usr/app/packages/beacon-node/src/eth1/eth1DepositDataTracker.ts:169:29)

We get errors from eth1, execution, and network relating to the same issue. When execution is online again, we receive the following logs:

Nov-25 21:05:25.577[eth1]             info: Eth1Provider is back online oldState=OFFLINE, newState=ONLINE
Nov-25 21:05:29.186[execution]        info: Execution client became online oldState=OFFLINE, newState=ONLINE

Expected behavior

There shouldn't be an overwhelming amount, nor redundant logging for users when an execution client goes offline. We should aim to just keep the execution logging and disregard the Eth1Provider logs unless it is necessary for something else.

Steps to reproduce

  1. Run Lodestar and an execution client locally (mine was run with Nethermind)
  2. Shut off execution client
  3. Observe logs
  4. Start execution client
  5. Observe logs

Additional context

No response

Operating system

Linux

Lodestar version or commit hash

unstable

philknows avatar Nov 25 '23 21:11 philknows

Error logs for eth1 provider where just added in v1.12.0

  • https://github.com/ChainSafe/lodestar/pull/5949

Not sure if those were necessary, maybe @nazarhussain can clarify. If we expect those to always be set to same execution client (which is pretty much the case) I guess it is quite redundant.

In that case, could also consider removing eth1 provider urls log https://github.com/ChainSafe/lodestar/blob/99a0caf4bc6cad2b1b0b370ae180d38f8eb6d9d7/packages/beacon-node/src/eth1/provider/eth1Provider.ts#L78

nflaig avatar Dec 01 '23 16:12 nflaig

Not sure if those were necessary, maybe @nazarhussain can clarify. If we expect those to always be set to same execution client (which is pretty much the case) I guess it is quite redundant.

It's not necessary if eth1 and execution are pointing to same provider url. If not then each provider can have different status.

nazarhussain avatar Dec 05 '23 11:12 nazarhussain

It's not necessary if eth1 and execution are pointing to same provider url. If not then each provider can have different status.

Does this mean we close this issue? I think it has a good point as in practice those point to the same EL which makes the logs redundant.

nflaig avatar Dec 05 '23 11:12 nflaig

Ah interesting. I guess if people wanted to have multiple ELs connected to a beacon node, this would make sense to track all of the provider statuses. If they're the same (which they generally are), can we suppress? It's super minor, but I like cleaner logs for a cleaner experience.

philknows avatar Dec 07 '23 21:12 philknows