erigon icon indicating copy to clipboard operation
erigon copied to clipboard
verified publisher icon erigontech

running as a validator, erigon will be jailed because it will frequently mine and broadcast the block which already mined by other peers .

Open zeech3 opened this issue 3 years ago • 0 comments

System information

Erigon version: ./erigon --version erigon version 2022.99.99-dev-74e0a623

OS & Version: Windows/Linux/OSX linux

Commit hash : 74e0a62349495462db262287cd82d79e395f34d8

Expected behaviour

As a validator, it will not be jailed.

Actual behaviour

it will be jailed after running a while because it will frequently mined and broadcasted the block which already mined by other peers.

Steps to reproduce the behaviour

  1. deploy a local private chain with three validator
  2. replace one of those from geth client to erigon client
  3. start mining with erigon in mining stage
  4. sync stage running in another go routine
  5. so sometimes when sync stage executed a block, and mining stage also mined this block. then cause erigon unwind frequently.

Backtrace

related code: eth/stagedsync/stage_execute.go:438

	if err = s.Update(batch, stageProgress); err != nil {
		return err
	}
	if err = batch.Commit(); err != nil {
		return fmt.Errorf("batch commit: %v", err)
	}

	num, _ := s.ExecutionAt(tx)
	log.Info(fmt.Sprintf("use external tx: %v, execution: %v", useExternalTx, num))
	if !useExternalTx {
		if err = tx.Commit(); err != nil {
			return err
		}
	}

turbo/stages/stageloop.go:166

	err = sync.Run(db, tx, initialCycle)
	if err != nil {
		return headBlockHash, err
	}
	if canRunCycleInOneTransaction {
		commitStart := time.Now()
		errTx := tx.Commit()
		if errTx != nil {
			return headBlockHash, errTx
		}
		log.Info("Commit cycle", "in", time.Since(commitStart))
	}

eth/stagedsync/stage_mining_create_block.go:105

	logPrefix := s.LogPrefix()
	executionAt, err := s.ExecutionAt(tx)
	if err != nil {
		return fmt.Errorf("getting last executed block: %w", err)
	}
	parent := rawdb.ReadHeaderByNumber(tx, executionAt)
	if parent == nil { // todo: how to return error and don't stop Erigon?
		return fmt.Errorf("empty block %d", executionAt)
	}

	if cfg.blockBuilderParameters != nil && cfg.blockBuilderParameters.ParentHash != parent.Hash() {
		return fmt.Errorf("wrong head block: %x (current) vs %x (requested)", parent.Hash(), cfg.blockBuilderParameters.ParentHash)
	}

	if cfg.miner.MiningConfig.Etherbase == (common.Address{}) {
		if cfg.blockBuilderParameters == nil {
			return fmt.Errorf("refusing to mine without etherbase")
		}
		// If we do not have an etherbase, let's use the suggested one
		coinbase = cfg.blockBuilderParameters.SuggestedFeeRecipient
	}

	blockNum := executionAt + 1

log

[INFO] [08-16|03:47:14.006] Header content, number 2665, before 2664, after 2665
[INFO] [08-16|03:47:14.006] RPC Daemon notified of new headers       from=2664 to=2665 header sending=5.161µs log sending=169ns
[INFO] [08-16|03:47:14.006] Sync state 0, ID: Headers
[INFO] [08-16|03:47:14.006] [1/16 Headers] Waiting for headers...    from=2665
[INFO] [08-16|03:47:17.001] [parlia] Add miner block to results channel
[INFO] [08-16|03:47:17.001] Timings (slower than 50ms)               MiningFinish=5.986s
[INFO] [08-16|03:47:17.001] Tables                                   PlainState=0B AccountChangeSet=0B StorageChangeSet=0B BlockTransaction=0B TransactionLog=0B FreeList=0B
[INFO] [08-16|03:47:17.001] Add Mined Header, number=2665
[INFO] [08-16|03:47:17.001] ProcessHeader, peerID=m,newBlock= false, topSeenHeightPoW=2665, sh numer=2665, respMaxBlock=2475, respMinBlock=2475
[INFO] [08-16|03:47:17.001] After ProcessHeader, newBlock= false, topSeenHeightPoW=2665, sh numer=2665, respMaxBlock=2665, respMinBlock=2284
[INFO] [08-16|03:47:17.001] fountparent: true, shnumber: 2665, FullImmutabilityThreshold: 90000, highestInDb: 2665
[INFO] [08-16|03:47:17.001] parent: 0x90142e941c8f54f244b3963e8f9186b9b11ee497508f4f2e9de8ae05fefdc030, persisted: true, linkqueue: 1, insertQueue: 0, anchorQueue: 0
[INFO] [08-16|03:47:20.001] ProcessHeader, peerID=ù,newBlock= true, topSeenHeightPoW=2665, sh numer=2666, respMaxBlock=2475, respMinBlock=2475
[INFO] [08-16|03:47:20.001] After ProcessHeader, newBlock= true, topSeenHeightPoW=2666, sh numer=2666, respMaxBlock=2666, respMinBlock=2284
[INFO] [08-16|03:47:20.001] fountparent: true, shnumber: 2666, FullImmutabilityThreshold: 90000, highestInDb: 2665
[INFO] [08-16|03:47:20.001] parent: 0x7c36c887f6f593db5a94b00bb5c8b7d2116f290d41dff1ff04b3256e532315a8, persisted: true, linkqueue: 1, insertQueue: 0, anchorQueue: 0
[INFO] [08-16|03:47:20.001] [1/16 Headers] Processed                 highest inserted=2666 age=0
[INFO] [08-16|03:47:20.001] Sync state 1, ID: CumulativeIndex
[INFO] [08-16|03:47:20.001] Sync state 2, ID: BlockHashes
[INFO] [08-16|03:47:20.001] Sync state 3, ID: Bodies
[INFO] [08-16|03:47:20.001] Sync state 4, ID: Senders
[INFO] [08-16|03:47:20.002] Sync state 5, ID: Execution
[INFO] [08-16|03:47:20.002] use external tx: true, execution: 2666
[INFO] [08-16|03:47:20.002] [6/16 Execution] Completed on            block=2666
[INFO] [08-16|03:47:20.002] Sync state 6, ID: Translation
[INFO] [08-16|03:47:20.002] Sync state 7, ID: HashState
[INFO] [08-16|03:47:20.002] Sync state 8, ID: IntermediateHashes
[INFO] [08-16|03:47:20.002] Sync state 9, ID: CallTraces
[INFO] [08-16|03:47:20.002] Sync state 10, ID: AccountHistoryIndex
[INFO] [08-16|03:47:20.002] Sync state 11, ID: StorageHistoryIndex
[INFO] [08-16|03:47:20.002] Sync state 12, ID: LogIndex
[INFO] [08-16|03:47:20.002] Sync state 13, ID: TxLookup
[INFO] [08-16|03:47:20.002] Sync state 14, ID: WatchTheBurn
[INFO] [08-16|03:47:20.002] Sync state 15, ID: Finish
[INFO] [08-16|03:47:20.003] Timings (slower than 50ms)               Headers=5.995s
[INFO] [08-16|03:47:20.004] Tables                                   PlainState=12.0KB AccountChangeSet=24.0KB StorageChangeSet=52.0KB BlockTransaction=36.0KB TransactionLog=28.0KB FreeList=4.0KB ReclaimableSpace=4.0MB
[INFO] [08-16|03:47:20.007] begin mining step
[INFO] [08-16|03:47:20.007] Sync state 0, ID: MiningCreateBlock
[INFO] [08-16|03:47:20.007] start mining: executionAt: 2665, blockNum: 2666
[INFO] [08-16|03:47:20.007] stage mining create block, header.time = 2022-08-16 03:47:20 +0000 UTC, parent time: 2022-08-16 03:47:14 +0000 UTC, config time: %!v(MISSING)
[INFO] [08-16|03:47:20.007] [1/5 MiningCreateBlock] Start mine       block=2666 baseFee=<nil> gasLimit=30000000
[INFO] [08-16|03:47:20.007] header time: 2022-08-16 03:47:20 +0000 UTC, time.Now: 2022-08-16 03:47:20.007886359 +0000 UTC m=+639.865701209
[INFO] [08-16|03:47:20.007] Sync state 1, ID: MiningExecution
[INFO] [08-16|03:47:20.007] Sync state 2, ID: HashState
[INFO] [08-16|03:47:20.008] Sync state 3, ID: IntermediateHashes
[INFO] [08-16|03:47:20.008] Sync state 4, ID: MiningFinish
[INFO] [08-16|03:47:20.008] [parlia] snap.Validator: 3, number: 2666, seen: 2665, recent: 0xa59a569ffdB875b5F6F69C9C8C6b3Bd992C244C1, val: 0xeE06551B99525B8C3ef93f6472caC2F79Aa584AF
[INFO] [08-16|03:47:20.008] [parlia] snap.Validator: 3, number: 2666, seen: 2664, recent: 0x0e7FeAe80bcc9a2Bca8a611Eb6bEB464139DF7c8, val: 0xeE06551B99525B8C3ef93f6472caC2F79Aa584AF
[INFO] [08-16|03:47:20.008] delay: -8.234279ms, now: 2022-08-16 03:47:20.00823447 +0000 UTC m=+639.866049320, header time: 2022-08-16 03:47:20 +0000 UTC
[INFO] [08-16|03:47:20.008] return delay, chain ramanujan: 0, header number: 2666
[INFO] [08-16|03:47:20.008] Sealing block with                       number=2666 delay=-8.234279ms headerDifficulty=2 val=0xeE06551B99525B8C3ef93f6472caC2F79Aa584AF Hash=0xce4195c5cf1c72c96878eb250bfa3840cb12113c1d7c33f14af475f2f1e4815d
[INFO] [08-16|03:47:20.008] [parlia] Add miner block to results channel
[INFO] [08-16|03:47:20.008] Add Mined Header, number=2666
[INFO] [08-16|03:47:20.008] ProcessHeader, peerID=m,newBlock= false, topSeenHeightPoW=2666, sh numer=2666, respMaxBlock=2475, respMinBlock=2475
[INFO] [08-16|03:47:20.008] After ProcessHeader, newBlock= false, topSeenHeightPoW=2666, sh numer=2666, respMaxBlock=2666, respMinBlock=2284
[INFO] [08-16|03:47:20.008] fountparent: true, shnumber: 2666, FullImmutabilityThreshold: 90000, highestInDb: 2666
[INFO] [08-16|03:47:20.008] parent: 0x7c36c887f6f593db5a94b00bb5c8b7d2116f290d41dff1ff04b3256e532315a8, persisted: true, linkqueue: 1, insertQueue: 0, anchorQueue: 0
[INFO] [08-16|03:47:20.009] Commit cycle                             in=4.933331ms
[INFO] [08-16|03:47:20.009] Header content, number 2666, before 2665, after 2666
[INFO] [08-16|03:47:20.009] RPC Daemon notified of new headers       from=2665 to=2666 header sending=5.819µs log sending=157ns
[INFO] [08-16|03:47:20.009] Sync state 0, ID: Headers
[INFO] [08-16|03:47:20.009] [1/16 Headers] Waiting for headers...    from=2666
[INFO] [08-16|03:47:20.009] UnwindTo                                 block=2665 bad_block_hash=0x0000000000000000000000000000000000000000000000000000000000000000
[INFO] [08-16|03:47:20.009] [1/16 Headers] Processed                 highest inserted=2666 age=0
[INFO] [08-16|03:47:20.009] [8/16 HashState] Unwinding started       from=2666 to=2665 storage=false codes=true
[INFO] [08-16|03:47:20.009] [8/16 HashState] Unwinding started       from=2666 to=2665 storage=false codes=false
[INFO] [08-16|03:47:20.009] [8/16 HashState] Unwinding started       from=2666 to=2665 storage=true codes=false
[INFO] [08-16|03:47:20.009] [9/16 IntermediateHashes] Unwinding      from=2666 to=2665 csbucket=AccountChangeSet
[INFO] [08-16|03:47:20.009] [9/16 IntermediateHashes] Unwinding      from=2666 to=2665 csbucket=StorageChangeSet
[INFO] [08-16|03:47:20.009] [9/16 IntermediateHashes] Trie root      hash=0x1a0360762395bc8e77c422e6c593d03d07336e56e71a7d232531e4891a4d23d0
[INFO] [08-16|03:47:20.009] [6/16 Execution] Unwind Execution        from=2666 to=2665
[INFO] [08-16|03:47:20.009] Sync state 0, ID: Headers

zeech3 avatar Aug 16 '22 06:08 zeech3