erigontech / erigontech/erigon

erigon --chain=dev hangs after 65 blocks when --dev.period > 0

Open
#16,749 3 comments 0 reactions 0 assignees View on GitHub
support
Dominant language
Go
Stars
3.6k
Forks
1.5k
Avg merge
1d 16h
Merged PRs (30d)
455

Description

#### System information

erigon version 3.2.0-dev-8c4414f9 (built from source)

Linux : Ubuntu 22.04 lts

Erigon Command (with flags/config):

`./erigon --datadir=dev --chain=dev --dev.period=5 --private.api.addr=localhost:9090 --mine --http.api=eth,erigon,web3,net,debug,trace,txpool,parity,admin --nodiscover`

Chain/Network:

dev (1337)

#### Expected behaviour

Erigon should keep chugging blocks every 5 seconds

#### Actual behaviour

At exactly block height 65 erigon stops chugging and begin to emit message "[2/8 Headers] No block headers to write in this log period"

```
INFO[08-20|17:52:58.002] [6/8 Execution] starting from=0 to=63 fromTxNum=1 offsetFromBlockBeginning=0 initialCycle=false useExternalTx=true inMem=false
INFO[08-20|17:52:58.002] [6/8 Execution] starting from=1 to=63 fromTxNum=2 offsetFromBlockBeginning=0 initialCycle=false useExternalTx=true
INFO[08-20|17:52:58.003] [6/8 Execution] Done blk=63 blks=64 blk/s=44286.6 txs=126 tx/s=87.18k gas/s=0 buf=4B/512.0MB stepsInDB=0.00 step=0.0 inMem=false alloc=114.1MB sys=191.3MB
INFO[08-20|17:52:58.006] Timings Headers=4.992s alloc=114.1MB sys=191.3MB
INFO[08-20|17:52:58.013] [2/8 Headers] Waiting for headers... from=63 hash=0xdf7be15b937b2f90be3a2a8eb79f2008b36237ed9af5117f74f721e88e08ef96
INFO[08-20|17:52:58.016] [1/3 MiningCreateBlock] Start mine block=64 baseFee=194322 gasLimit=12241216
INFO[08-20|17:52:58.024] Filtration initial=0 no sender=0 no account=0 nonce too low=0 nonceTooHigh=0 sender not EOA=0 fee too low=0 overflow=0 balance too low=0 bad chain id=0 filtered=0
INFO[08-20|17:52:58.024] [2/3 MiningExecution] starting from=0 to=64 fromTxNum=1 offsetFromBlockBeginning=0 initialCycle=false useExternalTx=true inMem=true
INFO[08-20|17:52:58.024] [2/3 MiningExecution] starting from=1 to=64 fromTxNum=2 offsetFromBlockBeginning=0 initialCycle=false useExternalTx=true
INFO[08-20|17:52:58.025] [2/3 MiningExecution] Done blk=64 blks=65 blk/s=77680.2 txs=128 tx/s=152.97k gas/s=0 buf=4B/512.0MB stepsInDB=0.00 step=0.0 inMem=true alloc=117.0MB sys=191.3MB
INFO[08-20|17:52:58.025] FinalizeBlockExecution block=64 txn=0 gas=0 receipt=0 payload=0
INFO[08-20|17:53:03.000] [2/8 Headers] Processed highest=64 age=0 headers=1 in=4.987 blk/sec=0
INFO[08-20|17:53:03.001] [6/8 Execution] starting from=0 to=64 fromTxNum=1 offsetFromBlockBeginning=0 initialCycle=false useExternalTx=true inMem=false
INFO[08-20|17:53:03.001] [6/8 Execution] starting from=1 to=64 fromTxNum=2 offsetFromBlockBeginning=0 initialCycle=false useExternalTx=true
INFO[08-20|17:53:03.003] [6/8 Execution] Done blk=64 blks=65 blk/s=55060.9 txs=128 tx/s=108.42k gas/s=0 buf=4B/512.0MB stepsInDB=0.00 step=0.0 inMem=false alloc=119.3MB sys=191.3MB
INFO[08-20|17:53:03.005] Timings Headers=4.987s alloc=119.3MB sys=191.3MB
INFO[08-20|17:53:03.011] [2/8 Headers] Waiting for headers... from=64 hash=0x0c3668e5cee7688c2bae5ffccef275fe91af99ccbd876930668f36b992086c59
INFO[08-20|17:53:03.014] [1/3 MiningCreateBlock] Start mine block=65 baseFee=170032 gasLimit=12253169
INFO[08-20|17:53:03.022] Filtration initial=0 no sender=0 no account=0 nonce too low=0 nonceTooHigh=0 sender not EOA=0 fee too low=0 overflow=0 balance too low=0 bad chain id=0 filtered=0
INFO[08-20|17:53:03.023] [2/3 MiningExecution] starting from=0 to=65 fromTxNum=1 offsetFromBlockBeginning=0 initialCycle=false useExternalTx=true inMem=true
INFO[08-20|17:53:03.023] [2/3 MiningExecution] starting from=1 to=65 fromTxNum=2 offsetFromBlockBeginning=0 initialCycle=false useExternalTx=true
INFO[08-20|17:53:03.024] [2/3 MiningExecution] Done blk=65 blks=66 blk/s=63093.1 txs=130 tx/s=124.27k gas/s=0 buf=4B/512.0MB stepsInDB=0.00 step=0.0 inMem=true alloc=122.2MB sys=191.3MB
INFO[08-20|17:53:03.024] FinalizeBlockExecution block=65 txn=0 gas=0 receipt=0 payload=0
WARN[08-20|17:53:06.986] [downloader] Added future link hash=0x18b1aec8a77309761c9619858358a036d8ceed5eb00555c6a7b0fd341a7dbb3c height=65 timestamp=1755705188
WARN[08-20|17:53:07.987] [downloader] Added future link hash=0x18b1aec8a77309761c9619858358a036d8ceed5eb00555c6a7b0fd341a7dbb3c height=65 timestamp=1755705188
INFO[08-20|17:53:08.000] [1/3 MiningCreateBlock] Start mine block=65 baseFee=170032 gasLimit=12253169
INFO[08-20|17:53:08.009] Filtration initial=0 no sender=0 no account=0 nonce too low=0 nonceTooHigh=0 sender not EOA=0 fee too low=0 overflow=0 balance too low=0 bad chain id=0 filtered=0
INFO[08-20|17:53:08.010] [2/3 MiningExecution] starting from=0 to=65 fromTxNum=1 offsetFromBlockBeginning=0 initialCycle=false useExternalTx=true inMem=true
INFO[08-20|17:53:08.010] [2/3 MiningExecution] starting from=1 to=65 fromTxNum=2 offsetFromBlockBeginning=0 initialCycle=false useExternalTx=true
INFO[08-20|17:53:08.011] [2/3 MiningExecution] Done blk=65 blks=66 blk/s=66375.5 txs=130 tx/s=130.73k gas/s=0 buf=4B/512.0MB stepsInDB=0.00 step=0.0 inMem=true alloc=125.8MB sys=191.3MB
INFO[08-20|17:53:08.011] FinalizeBlockExecution block=65 txn=0 gas=0 receipt=0 payload=0
INFO[08-20|17:53:08.020] [2/8 Headers] Processed highest=65 age=0 headers=1 in=6.023 blk/sec=0
INFO[08-20|17:53:08.020] [6/8 Execution] starting from=0 to=65 fromTxNum=1 offsetFromBlockBeginning=0 initialCycle=false useExternalTx=true inMem=false
INFO[08-20|17:53:08.020] [6/8 Execution] starting from=1 to=65 fromTxNum=2 offsetFromBlockBeginning=0 initialCycle=false useExternalTx=true
INFO[08-20|17:53:08.022] [6/8 Execution] Done blk=65 blks=66 blk/s=33737.8 txs=130 tx/s=66.45k gas/s=0 buf=4B/512.0MB stepsInDB=0.00 step=0.0 inMem=false alloc=127.4MB sys=191.3MB
INFO[08-20|17:53:08.024] Timings Headers=6.023s alloc=127.5MB sys=191.3MB
INFO[08-20|17:53:08.030] [2/8 Headers] Waiting for headers... from=65 hash=0x18b1aec8a77309761c9619858358a036d8ceed5eb00555c6a7b0fd341a7dbb3c
INFO[08-20|17:53:11.002] [1/3 MiningCreateBlock] Start mine block=66 baseFee=148778 gasLimit=12265133
INFO[08-20|17:53:37.023] [2/8 Headers] No block headers to write in this log period number=65 blk/second=0.000 alloc=134.0MB sys=191.3MB invalidHeaders=0 rejectedBadHeaders=0
INFO[08-20|17:54:07.023] [2/8 Headers] No block headers to write in this log period number=65 blk/second=0.000 alloc=138.1MB sys=191.3MB invalidHeaders=0 rejectedBadHeaders=0
WARN[08-20|17:54:11.689] [p2p] No GoodPeers
INFO[08-20|17:54:11.691] [mem] memory stats Rss=201.4MB Size=0B Pss=198.0MB SharedClean=3.6MB SharedDirty=0B PrivateClean=78.0MB PrivateDirty=119.8MB Referenced=197.4MB Anonymous=119.8MB Swap=0B alloc=138.9MB sys=191.3MB
INFO[08-20|17:54:11.721] [txpool] stat pending=0 baseFee=0 queued=0
INFO[08-20|17:54:35.994] [2/8 Headers] No block headers to write in this log period number=65 blk/second=0.000 alloc=142.3MB sys=191.3MB invalidHeaders=0 rejectedBadHeaders=0
```

At this point erigon instance is in dangling state and no way to stop it using CTR+C (unless done 10x times to panic)

#### Panic Trace

````
INFO[08-20|17:56:02.956] Req/resp stats req=0 reqMin=0 reqMax=0 skel=0 skelMin=0 skelMax=0 resp=0 respMin=0 respMax=0 dups=0 alloc=114.7MB sys=191.3MB
^CINFO[08-20|17:56:27.320] Got interrupt, shutting down...
INFO[08-20|17:56:27.320] [snapshots] stopping downloader files=0
INFO[08-20|17:56:27.321] [snapshots] closing torrents
INFO[08-20|17:56:27.321] [snapshots] downloader stopped
INFO[08-20|17:56:27.321] Exiting Engine...
INFO[08-20|17:56:27.321] RPC server shutting down
INFO[08-20|17:56:27.321] RPC server shutting down
INFO[08-20|17:56:27.321] Engine HTTP endpoint close url=127.0.0.1:8551
INFO[08-20|17:56:27.321] [rpc] Exiting...
INFO[08-20|17:56:27.321] HTTP endpoint closed url=127.0.0.1:8545
INFO[08-20|17:56:27.321] RPC server shutting down
INFO[08-20|17:56:27.326] [txpool] stopped
INFO[08-20|17:56:27.326] [devp2p] txn pool goroutine terminated
^CWARN[08-20|17:56:27.895] Already shutting down, interrupt more to panic. times=9
^CWARN[08-20|17:56:28.999] Already shutting down, interrupt more to panic. times=8
^CWARN[08-20|17:56:29.236] Already shutting down, interrupt more to panic. times=7
^CWARN[08-20|17:56:29.432] Already shutting down, interrupt more to panic. times=6
^CWARN[08-20|17:56:29.670] Already shutting down, interrupt more to panic. times=5
^CWARN[08-20|17:56:29.908] Already shutting down, interrupt more to panic. times=4
^CWARN[08-20|17:56:30.147] Already shutting down, interrupt more to panic. times=3
^CWARN[08-20|17:56:30.384] Already shutting down, interrupt more to panic. times=2
^CWARN[08-20|17:56:30.640] Already shutting down, interrupt more to panic. times=1
^Cpanic: boom

goroutine 134 [running]:
github.com/erigontech/erigon/turbo/debug.LoudPanic(...)
github.com/erigontech/erigon/turbo/debug/loudpanic.go:27
github.com/erigontech/erigon/turbo/debug.ListenSignals({0x3ba2c40, 0xc0009e8770}, {0x3be0550, 0xc000a40980})
github.com/erigontech/erigon/turbo/debug/signal.go:55 +0x332
created by github.com/erigontech/erigon/node.StartNode in goroutine 1
github.com/erigontech/erigon/node/node.go:413 +0xd2

goroutine 1 [chan receive, 8 minutes]:
github.com/erigontech/erigon/node.(*Node).Wait(...)
github.com/erigontech/erigon/node/node.go:267
github.com/erigontech/erigon/turbo/node.(*ErigonNode).Serve(0xc001214a30)
github.com/erigontech/erigon/turbo/node/node.go:58 +0x65
main.runErigon(0xc002904640)
github.com/erigontech/erigon/cmd/erigon/main.go:101 +0x552
github.com/erigontech/erigon/turbo/app.MakeApp.func1(0xc002904640)
github.com/erigontech/erigon/turbo/app/make_app.go:70 +0x17f
github.com/urfave/cli/v2.(*Command).Run(0xc0001eac60, 0xc002904640, {0xc00014e000, 0x8, 0x8})
github.com/urfave/cli/v2@v2.27.5/command.go:276 +0x7be
github.com/urfave/cli/v2.(*App).RunContext(0xc002962200, {0x3bc4640, 0x6c2af00}, {0xc00014e000, 0x8, 0x8})
github.com/urfave/cli/v2@v2.27.5/app.go:333 +0x5a5
github.com/urfave/cli/v2.(*App).Run(...)
github.com/urfave/cli/v2@v2.27.5/app.go:307
main.main()
github.com/erigontech/erigon/cmd/erigon/main.go:44 +0xba

goroutine 9 [chan receive, 8 minutes]:
gopkg.in/natefinch/lumberjack%2ev2.(*Logger).millRun(...)
gopkg.in/natefinch/lumberjack.v2@v2.2.1/lumberjack.go:379
created by gopkg.in/natefinch/lumberjack%2ev2.(*Logger).mill.func1 in goroutine 1
gopkg.in/natefinch/lumberjack.v2@v2.2.1/lumberjack.go:390 +0x96

goroutine 1860 [sync.Cond.Wait, 3 minutes, locked to thread]:
sync.runtime_notifyListWait(0xc002624750, 0x0)
runtime/sema.go:597 +0x159
sync.(*Cond).Wait(0x0?)
sync/cond.go:71 +0x85
github.com/erigontech/erigon/txnprovider/txpool.(*TxPool).best(0xc002961808, {0x3bc4bd0, 0xc00296e9b0}, 0x32, 0xc007f86f68, 0x41, 0xbb26ad, 0x0, {0x3bfeca0, 0xc00186ece0}, ...)
github.com/erigontech/erigon/txnprovider/txpool/pool.go:784 +0x165
github.com/erigontech/erigon/txnprovider/txpool.(*TxPool).YieldBest(0x0?, {0x3bc4bd0?, 0xc00296e9b0?}, 0x0?, 0x0?, 0x0?, 0x0?, 0x9?, {0x3bfeca0, 0xc00186ece0}, ...)
github.com/erigontech/erigon/txnprovider/txpool/pool.go:943 +0x36
github.com/erigontech/erigon/txnprovider/txpool.(*TxPool).ProvideTxns(0xc002961808, {0x3bc4bd0, 0xc00296e9b0}, {0xc009eb7840, 0x7, 0x8?})
github.com/erigontech/erigon/txnprovider/txpool/pool.go:912 +0x1ea
github.com/erigontech/erigon/execution/stagedsync.getNextTransactions({0x3bc4bd0, 0xc00296e9b0}, {{0x7d95146df7d8, 0xc000a44780}, {0xc0024f8bd8, 0xc0001ee4d0, 0xc0001ee540, 0xc001b7a000}, {0x3bc52d8, 0xc0009f6540}, ...}, ...)
github.com/erigontech/erigon/execution/stagedsync/stage_mining_exec.go:287 +0x333
github.com/erigontech/erigon/execution/stagedsync.SpawnMiningExecStage(_, {{_, _}, {_, _}, _}, {{0x7d95146df7d8, 0xc000a44780}, {0xc0024f8bd8, 0xc0001ee4d0, ...}, ...}, ...)
github.com/erigontech/erigon/execution/stagedsync/stage_mining_exec.go:155 +0x1fcd
github.com/erigontech/erigon/execution/stagedsync.MiningStages.func4(0xf?, 0x3bee940?, {0xc0015dcc30?, 0x0?}, {{0x3c06ad8, 0xc0015dcc30}, {0x3bfe5a0, 0xc0015dcc30}, 0xc0099a8780}, {0x3be0550, ...})
github.com/erigontech/erigon/execution/stagedsync/stagebuilder.go:62 +0x158
github.com/erigontech/erigon/execution/stagedsync.(*Sync).runStage(0xc0005cec00, 0xc0025726e0, {0x0, 0x0}, {{0x3c06ad8, 0xc0015dcc30}, {0x3bfe5a0, 0xc0015dcc30}, 0xc0099a8780}, 0x0, ...)
github.com/erigontech/erigon/execution/stagedsync/sync.go:540 +0x24e
github.com/erigontech/erigon/execution/stagedsync.(*Sync).Run(0xc0005cec00, {0x0, 0x0}, {{0x3c06ad8, 0xc0015dcc30}, {0x3bfe5a0, 0xc0015dcc30}, 0xc0099a8780}, 0x40?, 0x0)
github.com/erigontech/erigon/execution/stagedsync/sync.go:445 +0x2d5
github.com/erigontech/erigon/execution/stages.MiningStep({0x3bc4bd0, 0xc00296e9b0}, {0x7d95146df7d8, 0xc000a44780}, 0xc0005cec00, {0xc001026570, 0x26}, {0x3be0550, 0xc000a40980})
github.com/erigontech/erigon/execution/stages/stageloop.go:513 +0x3c5
github.com/erigontech/erigon/eth.(*Ethereum).StartMining.func5.1()
github.com/erigontech/erigon/eth/backend.go:1386 +0x98
created by github.com/erigontech/erigon/eth.(*Ethereum).StartMining.func5 in goroutine 94
github.com/erigontech/erigon/eth/backend.go:1385 +0x8dc

goroutine 136 [syscall]:
os/signal.signal_recv()
runtime/sigqueue.go:152 +0x29
os/signal.loop()
os/signal/signal_unix.go:23 +0x13
created by os/signal.Notify.func1.1 in goroutine 134
os/signal/signal.go:152 +0x1f

goroutine 2326 [sync.Cond.Wait]:
sync.runtime_notifyListWait(0xc000bf0790, 0x0)
runtime/sema.go:597 +0x159
sync.(*Cond).Wait(0xc000cc3140?)
sync/cond.go:71 +0x85
github.com/erigontech/erigon/db/kv/mdbx.(*MdbxKV).waitTxsAllDoneOnClose(0xc000acb040)
github.com/erigontech/erigon/db/kv/mdbx/kv_mdbx.go:557 +0x85
github.com/erigontech/erigon/db/kv/mdbx.(*MdbxKV).Close(0xc000052488?)
github.com/erigontech/erigon/db/kv/mdbx/kv_mdbx.go:567 +0x3c
github.com/erigontech/erigon/db/kv/temporal.(*DB).Close(0xc000a44780)
github.com/erigontech/erigon/db/kv/temporal/kv_temporal.go:201 +0x2e
github.com/erigontech/erigon/eth.(*Ethereum).Stop(0xc000a54708)
github.com/erigontech/erigon/eth/backend.go:1788 +0x24c
github.com/erigontech/erigon/node.(*Node).stopServices(0x98f3f5?, {0xc001214a20, 0x1, 0xc0009f6470?})
github.com/erigontech/erigon/node/node.go:215 +0xae
github.com/erigontech/erigon/node.(*Node).Close(0xc0009e8770)
github.com/erigontech/erigon/node/node.go:163 +0x165
created by github.com/erigontech/erigon/turbo/debug.ListenSignals in goroutine 134
github.com/erigontech/erigon/turbo/debug/signal.go:46 +0x239
````

### Other observations
* Omitting cli argument `--dev.period` or setting it =0 doesn't exhibit the bad behavior (but of course blocks are mined only on the happening of new transactions). In such case erigon instance runs continuosly.
* The value of --dev.period (when set >0) is irrelevant: the hang happens always at block 65
* Restarting the instance does not help ... it reaches the point depicted above and hangs
* Up to moment block 65 is reached I see stages `[2/3 MiningExecution]` `[6/8 Execution]` always start from block 0

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.