search

NethermindEth / nethermind

A robust execution client for Ethereum node operators.
https://nethermind.io/nethermind-client
GNU General Public License v3.0
1.28k stars 445 forks source link

Block processing completely stops while "Full Pruning Persist Cache" #7775

Open polyurethanegoose opened 5 days ago

polyurethanegoose commented 5 days ago

Description When Nethermind starts to "Prune Persist Cache" it stops processing new blocks which leads to missing 100% of attestations.

Steps to Reproduce

  1. Wait for Pruning to start
  2. Observe messages looping in logs.

Desktop (please complete the following information):

Additional context Observed behaviour:

  1. Nethermind does not respond to systemctl stop nethermind.service. SystemD service is always in "deactivating" state and processing still can be seen in logs.
  2. Actually it does not respond on 15 signals. Only 9 stops process.
  3. Healthcheck endpoint responds with: 
    $ curl localhost:8545/health
{"status":"Healthy","totalDuration":"00:00:00.0000821","entries":{"node-health":{"data":{"IsSyncing":false,"Errors":[]},"description":"The node is now fully synced with a network. Peers: 51.","duration":"00:00:00.0000447","status":"Healthy","tags":[]}}}
  4. Pruning does not complete even after 3 hours passing.
  5. Pruning in my case is triggered automatically via following arguments: 
    --Pruning.Mode=Hybrid \
--Pruning.FullPruningTrigger VolumeFreeSpace \
--Pruning.FullPruningThresholdMb 393216 \
  6. Issue looks similar to #7208 & #6815 but logs look little bit different.
  7. Only full resync was able to fix issue.
  8. I do not believe that this issue occurs on every resync (?)

Logs Nethermind logs looks like this:

Nov 21 04:32:49 eth nethermind[515741]: 21 Nov 04:32:49 | Synced Chain Head to 21233446 (0x61a47e...e33cde)
Nov 21 04:33:01 eth nethermind[515741]: 21 Nov 04:33:01 | Received New Block:  21233447 (0x4e1eff...8ec427)
Nov 21 04:33:01 eth nethermind[515741]: 21 Nov 04:33:01 | Processed            21233447        |     50.80 ms  |  slot     12,584 ms |⛽ Gas gwei: 9.64 .. 9.71 (12.03) .. 154.70
Nov 21 04:33:01 eth nethermind[515741]: 21 Nov 04:33:01 | - Block                14.80 MGas    |    182    txs |  calls    934 ( 16) | sload   3,125 | sstore    914 | create   0
Nov 21 04:33:01 eth nethermind[515741]: 21 Nov 04:33:01 | - Block throughput    291.31 MGas/s  |   3582.47 t/s |         19.68 Blk/s | exec code  from cache   1,115 | new      0
Nov 21 04:33:01 eth nethermind[515741]: 21 Nov 04:33:01 | Received ForkChoice: 21233447 (0x4e1eff...8ec427), Safe: 21233392 (0x4b0799...4edf3b), Finalized: 21233360 (0x9eff69...ee63ac)
Nov 21 04:33:01 eth nethermind[515741]: 21 Nov 04:33:01 | Synced Chain Head to 21233447 (0x4e1eff...8ec427)
Nov 21 04:33:12 eth nethermind[515741]: 21 Nov 04:33:12 | Received New Block:  21233448 (0x6d74cf...02a810)
Nov 21 04:33:12 eth nethermind[515741]: 21 Nov 04:33:12 | Processed            21233448        |     35.02 ms  |  slot     11,472 ms |⛽ Gas gwei: 9.62 .. 9.62 (15.00) .. 53.75
Nov 21 04:33:12 eth nethermind[515741]: 21 Nov 04:33:12 | - Block                 5.88 MGas    |     32    txs |  calls    454 ( 35) | sload   1,487 | sstore    460 | create   0
Nov 21 04:33:12 eth nethermind[515741]: 21 Nov 04:33:12 | - Block throughput    167.98 MGas/s  |    913.76 t/s |         28.56 Blk/s | exec code  from cache     485 | new      0
Nov 21 04:33:12 eth nethermind[515741]: 21 Nov 04:33:12 | ***** JSON RPC report *****
Nov 21 04:33:12 eth nethermind[515741]: -----------------------------------------------------------------------------------------------------------------------------------------------
Nov 21 04:33:12 eth nethermind[515741]: method                                  | successes |   avg (ms) |   max (ms) |    errors |   avg (ms) |   max (ms) | avg size B | total (kB) |
Nov 21 04:33:12 eth nethermind[515741]: -----------------------------------------------------------------------------------------------------------------------------------------------
Nov 21 04:33:12 eth nethermind[515741]: engine_exchangeCapabilities             |         1 |      5.754 |      5.754 |         0 |      0.000 |      0.000 |        414 |       0.40 |
Nov 21 04:33:12 eth nethermind[515741]: engine_forkchoiceUpdatedV3              |        27 |      3.282 |     20.278 |         0 |      0.000 |      0.000 |        197 |       5.19 |
Nov 21 04:33:12 eth nethermind[515741]: engine_getClientVersionV1               |         1 |     16.563 |     16.563 |         0 |      0.000 |      0.000 |        122 |       0.12 |
Nov 21 04:33:12 eth nethermind[515741]: engine_getPayloadBodiesByRangeV1        |        11 |     47.851 |     80.270 |         0 |      0.000 |      0.000 |    6580647 |   70690.54 |
Nov 21 04:33:12 eth nethermind[515741]: engine_newPayloadV3                     |        26 |     73.069 |    248.753 |         0 |      0.000 |      0.000 |        162 |       4.11 |
Nov 21 04:33:12 eth nethermind[515741]: eth_chainId                             |         3 |      1.718 |      4.174 |         0 |      0.000 |      0.000 |         39 |       0.11 |
Nov 21 04:33:12 eth nethermind[515741]: eth_getBlockByNumber                    |       898 |      1.856 |     10.137 |         0 |      0.000 |      0.000 |      15681 |   13751.88 |
Nov 21 04:33:12 eth nethermind[515741]: eth_getLogs                             |         2 |    162.104 |    309.276 |         0 |      0.000 |      0.000 |     422005 |     824.23 |
Nov 21 04:33:12 eth nethermind[515741]: eth_syncing                             |        17 |      1.387 |     20.526 |         0 |      0.000 |      0.000 |         39 |       0.65 |
Nov 21 04:33:12 eth nethermind[515741]: -----------------------------------------------------------------------------------------------------------------------------------------------
Nov 21 04:33:12 eth nethermind[515741]: TOTAL                                   |       986 |      4.621 |    309.276 |         0 |      0.000 |      0.000 |      88564 |   85277.24 |
Nov 21 04:33:12 eth nethermind[515741]: -----------------------------------------------------------------------------------------------------------------------------------------------
Nov 21 04:33:12 eth nethermind[515741]:  
Nov 21 04:33:13 eth nethermind[515741]: 21 Nov 04:33:13 | Received ForkChoice: 21233448 (0x6d74cf...02a810), Safe: 21233392 (0x4b0799...4edf3b), Finalized: 21233360 (0x9eff69...ee63ac)
Nov 21 04:33:13 eth nethermind[515741]: 21 Nov 04:33:13 | Synced Chain Head to 21233448 (0x6d74cf...02a810)
Nov 21 04:33:13 eth nethermind[515741]: 21 Nov 04:33:13 | Full Pruning Persist Cache started.
Nov 21 04:33:18 eth nethermind[515741]: 21 Nov 04:33:18 | Saving all commit set took 00:00:05.4259603 for 130 commit sets.
Nov 21 04:33:21 eth nethermind[515741]: 21 Nov 04:33:21 | Peers | node diversity :  Nethermind (57 %), Geth (38 %), Reth (5 %)
Nov 21 04:33:24 eth nethermind[515741]: 21 Nov 04:33:24 | Received New Block:  21233449 (0xa17178...b6f996)
Nov 21 04:33:31 eth nethermind[515741]: 21 Nov 04:33:31 | Processing queue wasn't empty added to queue New Block:  21233449 (0xa17178...b6f996).
Nov 21 04:33:31 eth nethermind[515741]: 21 Nov 04:33:31 | Received ForkChoice: 21233449 (0xa17178...b6f996), Safe: 21233392 (0x4b0799...4edf3b), Finalized: 21233360 (0x9eff69...ee63ac)
Nov 21 04:33:31 eth nethermind[515741]: 21 Nov 04:33:31 | Processing 1 blocks, Request: ForkChoice: 21233449 (0xa17178...b6f996), Safe: 21233392 (0x4b0799...4edf3b), Finalized: 21233360 (0x9eff69...ee63ac)
Nov 21 04:33:37 eth nethermind[515741]: 21 Nov 04:33:37 | Received New Block:  21233450 (0xc1980a...959b0e)
Nov 21 04:33:37 eth nethermind[515741]: 21 Nov 04:33:37 | BeaconPivot was null. Setting beacon pivot to 21233450 (0xc1980ab9b4f27d6dba7c9297fd024c31d6ca6f87a2eaacc08585b01fc6959b0e)
Nov 21 04:33:37 eth nethermind[515741]: 21 Nov 04:33:37 | New beacon pivot: 21233450 (0xc1980ab9b4f27d6dba7c9297fd024c31d6ca6f87a2eaacc08585b01fc6959b0e)
Nov 21 04:33:37 eth nethermind[515741]: 21 Nov 04:33:37 | Syncing... Inserting block 21233450 (0xc1980a...959b0e).
Nov 21 04:33:37 eth nethermind[515741]: 21 Nov 04:33:37 | Received ForkChoice: 21233450 (0xc1980a...959b0e), Safe: 21233392 (0x4b0799...4edf3b), Finalized: 21233360 (0x9eff69...ee63ac)
Nov 21 04:33:37 eth nethermind[515741]: 21 Nov 04:33:37 | Processing 1 blocks, Request: ForkChoice: 21233450 (0xc1980a...959b0e), Safe: 21233392 (0x4b0799...4edf3b), Finalized: 21233360 (0x9eff69...ee63ac)
Nov 21 04:33:47 eth nethermind[515741]: 21 Nov 04:33:47 | Received New Block:  21233451 (0xa0ddbc...ed08b8)
Nov 21 04:33:47 eth nethermind[515741]: 21 Nov 04:33:47 | Syncing... Inserting block 21233451 (0xa0ddbc...ed08b8).
Nov 21 04:33:48 eth nethermind[515741]: 21 Nov 04:33:48 | Received ForkChoice: 21233451 (0xa0ddbc...ed08b8), Safe: 21233392 (0x4b0799...4edf3b), Finalized: 21233360 (0x9eff69...ee63ac)
Nov 21 04:33:48 eth nethermind[515741]: 21 Nov 04:33:48 | Processing 1 blocks, Request: ForkChoice: 21233451 (0xa0ddbc...ed08b8), Safe: 21233392 (0x4b0799...4edf3b), Finalized: 21233360 (0x9eff69...ee63ac)
Nov 21 04:34:01 eth nethermind[515741]: 21 Nov 04:34:01 | Received New Block:  21233452 (0x171da4...5b9ae7)
Nov 21 04:34:01 eth nethermind[515741]: 21 Nov 04:34:01 | Syncing... Inserting block 21233452 (0x171da4...5b9ae7).
Nov 21 04:34:01 eth nethermind[515741]: 21 Nov 04:34:01 | Received ForkChoice: 21233452 (0x171da4...5b9ae7), Safe: 21233392 (0x4b0799...4edf3b), Finalized: 21233360 (0x9eff69...ee63ac)
Nov 21 04:34:01 eth nethermind[515741]: 21 Nov 04:34:01 | Processing 1 blocks, Request: ForkChoice: 21233452 (0x171da4...5b9ae7), Safe: 21233392 (0x4b0799...4edf3b), Finalized: 21233360 (0x9eff69...ee63ac)

And after that logs are looping over "Processin ... Syncing" block. After restarting Nethermind it looks the same. Nethermind start normally, starts processing block and after "Full Pruning Persist Cache started." everything stops. From the consensus clients logs I can observe:

Nov 21 04:32:02 eth lighthouse[349296]: Nov 21 03:32:02.640 INFO New block received                      root: 0xf99b6e63ad3c5ac11ee7d82827b586c8828da71b0aeac1a56a406de3ef58ff02, slot: 10444658
Nov 21 04:32:05 eth lighthouse[349296]: Nov 21 03:32:05.000 INFO Synced                                  slot: 10444658, block: 0xf99b…ff02, epoch: 326395, finalized_epoch: 326393, finalized_root: 0x32be…3ca>
Nov 21 04:32:12 eth lighthouse[349296]: Nov 21 03:32:12.591 INFO New block received                      root: 0x66ca0c9793d955d2f48a8308ad42f1c277acbce2345988ba296ffbe22fc8a9eb, slot: 10444659
Nov 21 04:32:17 eth lighthouse[349296]: Nov 21 03:32:17.001 INFO Synced                                  slot: 10444659, block: 0x66ca…a9eb, epoch: 326395, finalized_epoch: 326393, finalized_root: 0x32be…3ca>
Nov 21 04:32:25 eth lighthouse[349296]: Nov 21 03:32:25.847 INFO New block received                      root: 0xd13c91d34558919c7925f9bcbb04c8624bcc599376d985d9fcc1b18909f46a03, slot: 10444660
Nov 21 04:32:29 eth lighthouse[349296]: Nov 21 03:32:29.000 INFO Synced                                  slot: 10444660, block: 0xd13c…6a03, epoch: 326395, finalized_epoch: 326393, finalized_root: 0x32be…3ca>
Nov 21 04:32:37 eth lighthouse[349296]: Nov 21 03:32:37.130 INFO New block received                      root: 0x7e09cfe2ff64390311e33f63daaea45d4bcab068001091308faaefc409302eb2, slot: 10444661
Nov 21 04:32:41 eth lighthouse[349296]: Nov 21 03:32:41.001 INFO Synced                                  slot: 10444661, block: 0x7e09…2eb2, epoch: 326395, finalized_epoch: 326393, finalized_root: 0x32be…3ca>
Nov 21 04:32:48 eth lighthouse[349296]: Nov 21 03:32:48.578 INFO New block received                      root: 0xee1552c065f3a938b0c391d0f3405f33b251cfd7e3ad5bcafec365955d8c5ae6, slot: 10444662
Nov 21 04:32:53 eth lighthouse[349296]: Nov 21 03:32:53.000 INFO Synced                                  slot: 10444662, block: 0xee15…5ae6, epoch: 326395, finalized_epoch: 326393, finalized_root: 0x32be…3ca>
Nov 21 04:33:01 eth lighthouse[349296]: Nov 21 03:33:01.185 INFO New block received                      root: 0x5f02d132084b1d70eb65d7ea5380fefb01cc0d7fd897cff36edc2ce17c1bc4bb, slot: 10444663
Nov 21 04:33:05 eth lighthouse[349296]: Nov 21 03:33:05.000 INFO Synced                                  slot: 10444663, block: 0x5f02…c4bb, epoch: 326395, finalized_epoch: 326393, finalized_root: 0x32be…3ca>
Nov 21 04:33:12 eth lighthouse[349296]: Nov 21 03:33:12.685 INFO New block received                      root: 0xbc0da9cafe43f531025493bddbf959406c909a510f012e450c0475b9effe7e27, slot: 10444664
Nov 21 04:33:17 eth lighthouse[349296]: Nov 21 03:33:17.000 INFO Synced                                  slot: 10444664, block: 0xbc0d…7e27, epoch: 326395, finalized_epoch: 326393, finalized_root: 0x32be…3ca>
Nov 21 04:33:24 eth lighthouse[349296]: Nov 21 03:33:24.554 INFO New block received                      root: 0xc274f065313ac4fed530d83c307adf6b3a8dbfda6a9a65e045557fccd531d031, slot: 10444665
Nov 21 04:33:29 eth lighthouse[349296]: Nov 21 03:33:29.290 INFO Synced                                  slot: 10444665, block:    …  empty, epoch: 326395, finalized_epoch: 326393, finalized_root: 0x32be…3ca>
Nov 21 04:33:36 eth lighthouse[349296]: Nov 21 03:33:36.841 INFO New block received                      root: 0x9af2254f6c8ca1380751ece8c3022d3f111b218966c88c35b178f3191c68684f, slot: 10444666
Nov 21 04:33:39 eth lighthouse[349296]: Nov 21 03:33:39.001 WARN Error processing HTTP API request       method: GET, path: /eth/v1/validator/attestation_data, status: 500 Internal Server Error, elapsed: 313>
Nov 21 04:33:39 eth lighthouse[349296]: Nov 21 03:33:39.002 WARN Error processing HTTP API request       method: GET, path: /eth/v1/validator/attestation_data, status: 500 Internal Server Error, elapsed: 134>
Nov 21 04:33:41 eth lighthouse[349296]: Nov 21 03:33:41.001 WARN Head is optimistic                      execution_block_hash: 0xc1980ab9b4f27d6dba7c9297fd024c31d6ca6f87a2eaacc08585b01fc6959b0e, info: chain >
Nov 21 04:33:41 eth lighthouse[349296]: Nov 21 03:33:41.001 INFO Synced                                  slot: 10444666, block: 0x9af2…684f, epoch: 326395, finalized_epoch: 326393, finalized_root: 0x32be…3ca>
Nov 21 04:33:47 eth lighthouse[349296]: Nov 21 03:33:47.802 INFO New block received                      root: 0x68bad3034c4c1535d96f634c44b5ae9e91fdc56b034714dde817256428a5b8ff, slot: 10444667
Nov 21 04:33:53 eth lighthouse[349296]: Nov 21 03:33:53.000 WARN Head is optimistic                      execution_block_hash: 0xa0ddbceec19b038c5c1ddb67fa4da6e14dc8db457a992b3e0db420488eed08b8, info: chain >
Nov 21 04:33:53 eth lighthouse[349296]: Nov 21 03:33:53.000 INFO Synced                                  slot: 10444667, block: 0x68ba…b8ff, epoch: 326395, finalized_epoch: 326393, finalized_root: 0x32be…3ca>
Nov 21 04:34:01 eth lighthouse[349296]: Nov 21 03:34:01.086 INFO New block received                      root: 0x4724fe31855a60b0b0ce4d27d19dbb603f82eff5d2c821e36bfa6505f39d8a92, slot: 10444668
Nov 21 04:34:05 eth lighthouse[349296]: Nov 21 03:34:05.000 WARN Head is optimistic                      execution_block_hash: 0x171da4a9e3f2a8b1591d30ea073a6a9a950c33ea0f7d69f67c09985f5c5b9ae7, info: chain >
Nov 21 04:34:05 eth lighthouse[349296]: Nov 21 03:34:05.000 INFO Synced                                  slot: 10444668, block: 0x4724…8a92, epoch: 326395, finalized_epoch: 326393, finalized_root: 0x32be…3ca>
Nov 21 04:34:12 eth lighthouse[349296]: Nov 21 03:34:12.913 INFO New block received                      root: 0xaa99d294113b518a721cbd9b8732e19d64772eeb3720e60fc628996b842012c7, slot: 10444669
Nov 21 04:34:17 eth lighthouse[349296]: Nov 21 03:34:17.000 WARN Head is optimistic                      execution_block_hash: 0x7a8bdba3ab28ecc56489ecb5d34f1ce6663f358cf640d0e30c11f4a304d71520, info: chain >
Nov 21 04:34:17 eth lighthouse[349296]: Nov 21 03:34:17.000 INFO Synced                                  slot: 10444669, block: 0xaa99…12c7, epoch: 326395, finalized_epoch: 326393, finalized_root: 0x32be…3ca>
Nov 21 04:34:26 eth lighthouse[349296]: Nov 21 03:34:26.376 INFO New block received                      root: 0x8bc3bb0191cad0a255a1256b173b7a5188b07ebe261ed650fe685189f66acfb6, slot: 10444670
Nov 21 04:34:27 eth lighthouse[349296]: Nov 21 03:34:27.001 WARN Error processing HTTP API request       method: GET, path: /eth/v1/validator/attestation_data, status: 500 Internal Server Error, elapsed: 647>
Nov 21 04:34:29 eth lighthouse[349296]: Nov 21 03:34:29.315 WARN Head is optimistic                      execution_block_hash: 0x1a8115706f0289111d455c6b0af3824578fd3126ed3c2067547342e5d4a040c3, info: chain >
Nov 21 04:34:29 eth lighthouse[349296]: Nov 21 03:34:29.315 INFO Synced                                  slot: 10444670, block: 0x8bc3…cfb6, epoch: 326395, finalized_epoch: 326393, finalized_root: 0x32be…3ca>
Nov 21 04:34:36 eth lighthouse[349296]: Nov 21 03:34:36.700 INFO New block received                      root: 0x9718e3eb743404830f3a4fb78d9eef3604389f21c7a5e46fa45080780d9d7d62, slot: 10444671
No

As you can see it works until the time when Nethermind start Pruning cache. Then Nethermind stops responding on API requests.