[NODE] RPC requests up 3-4x due to redundant backfill requests as of v2.11.0 release

[derek1287]

Description

(LinkWell Nodes)

After upgrading our nodes from version 2.10.0 -> 2.11.0, we are experiencing an extreme spike in RPC requests from the Chainlink node runtime (~3-4x that of previous versions).

We believe this to be due the node attempting to backfill blocks in a redundant manner, possibly as a side effect of the new FinalityTagEnabled functionality - although flipping this config setting between true/false does not seem to make any difference here.

Log excerpts are below, and fuller log excerpt is attached.

Basic Information

Sequence of events (per our logs):

BACKFILL BATCH 1 (2024-06-30T21:59:57.366Z):

1. Node backfills from 59913334 to 59913383 (50 blocks):

{"level":"debug","ts":"2024-06-30T21:59:57.366Z","logger":"EVM.421614.HeadTracker","caller":"headtracker/head_tracker.go:365","msg":"Starting backfill","version":"2.12.0@ef8a79c","blockNumber":59913384,"n":50,"fromBlockHeight":59913334,"toBlockHeight":59913383}

2. Node marks block 59913334 as finalized:

{"level":"debug","ts":"2024-06-30T21:59:57.368Z","logger":"EVM.421614.HeadTracker","caller":"headtracker/head_tracker.go:410","msg":"marked block as finalized","version":"2.12.0@ef8a79c","blockNumber":59913384,"n":50,"fromBlockHeight":59913334,"toBlockHeight":59913383,"latest_finalized_block_hash":"0x82a5236daee1c2ebc29042cc9eed3d4ccf376b354de9ed6069322e8316490e81","latest_finalized_block_number":59913334}

3. Node claims "backfill complete":

{"level":"debug","ts":"2024-06-30T21:59:57.368Z","logger":"EVM.421614.HeadTracker","caller":"headtracker/head_tracker.go:371","msg":"Finished backfill","version":"2.12.0@ef8a79c","blockNumber":59913384,"n":50,"fromBlockHeight":59913334,"toBlockHeight":59913383,"latest_finalized_block_hash":"0x82a5236daee1c2ebc29042cc9eed3d4ccf376b354de9ed6069322e8316490e81","latest_finalized_block_number":59913334,"fetched":0,"time":0.002245959,"err":null}

4. Node receives a new head (59913385):

{"level":"debug","ts":"2024-06-30T21:59:57.524Z","logger":"EVM.421614.HeadTracker","caller":"headtracker/head_tracker.go:221","msg":"Received new head 59913385","version":"2.12.0@ef8a79c","blockHash":"0x435d45d95e4fab7593d5d4a5810c4ae9e51adc795297f2c1c4130147b8cde429","parentHeadHash":"0xc6c0b39ae034ab33e4f162e973423bcb3fc36f648f1ac9ed4865c67767021263","blockTs":"2024-06-30T21:59:57.000Z","blockTsUnix":1719784797,"blockDifficulty":"1"}

BACKFILL BATCH 2 (2024-06-30T21:59:57.658Z):

5. Node backfills from 59913335 to 59913384 (50 blocks).

{"level":"debug","ts":"2024-06-30T21:59:57.658Z","logger":"EVM.421614.HeadTracker","caller":"headtracker/head_tracker.go:365","msg":"Starting backfill","version":"2.12.0@ef8a79c","blockNumber":59913385,"n":50,"fromBlockHeight":59913335,"toBlockHeight":59913384}

6. Node marks block 59913335 as finalized

{"level":"debug","ts":"2024-06-30T21:59:57.660Z","logger":"EVM.421614.HeadTracker","caller":"headtracker/head_tracker.go:410","msg":"marked block as finalized","version":"2.12.0@ef8a79c","blockNumber":59913385,"n":50,"fromBlockHeight":59913335,"toBlockHeight":59913384,"latest_finalized_block_hash":"0x85a18d31adac04f7ded6983428b1914310799ae933582810cf3b751927436ccc","latest_finalized_block_number":59913335}

7. Node claims "backfill complete"

{"level":"debug","ts":"2024-06-30T21:59:57.660Z","logger":"EVM.421614.HeadTracker","caller":"headtracker/head_tracker.go:371","msg":"Finished backfill","version":"2.12.0@ef8a79c","blockNumber":59913385,"n":50,"fromBlockHeight":59913335,"toBlockHeight":59913384,"latest_finalized_block_hash":"0x85a18d31adac04f7ded6983428b1914310799ae933582810cf3b751927436ccc","latest_finalized_block_number":59913335,"fetched":0,"time":0.002655164,"err":null}

8. Node receives a new head (59913386):

{"level":"debug","ts":"2024-06-30T21:59:57.835Z","logger":"EVM.421614.HeadTracker","caller":"headtracker/head_tracker.go:221","msg":"Received new head 59913386","version":"2.12.0@ef8a79c","blockHash":"0x350e6cd82c69b4997b75be1d8e2b4bf04dbac62756cf179907fed92f9987ebe7","parentHeadHash":"0x435d45d95e4fab7593d5d4a5810c4ae9e51adc795297f2c1c4130147b8cde429","blockTs":"2024-06-30T21:59:57.000Z","blockTsUnix":1719784797,"blockDifficulty":"1"}

NOTE that "BACKFILL BATCH 2" overlaps "BACKFILL BATCH 1" by 49 blocks, which we believe is redundant.

Note also that above two backfill attempts span only ~300 milliseconds. This pattern repeats every ~300ms in perpetuity. We believe this is causing the dramatic spike in RPC requests (~300%+) between CL versions. Node restarts do not help help here; only downgrading.

---

• The issue only appears as of 2.11.0. We are viewing this as a regression, and have rolled our nodes back to 2.10.0 to avoid this issue.

• [[EVM]] node config settings are kept largely as default (including all backfill settings).

• We have tried both FinalityTagEnabled = true and FinalityTagEnabled = false, to no avail.

• Network: Any (log excerpts are from Arbitrum Sepolia testnet, but this is occuring on all testnet/mainnet chains, as far as we have observed)

• Operating System: Unix

• Commit: Docker v2.11.0 snapshot

Environment Variables
(private, will communicate if needed)

Steps to Reproduce
Upgrade node to 2.11.0+

Additional Information
Log file excerpt is attached:
CL backfill logs.log

[CQuerini247]

Someone's hash tag is in the operation!