Investigate demoting invalidated transactions

[AlexeyAkhunov]

This happens during the unwinds, not sure yet if something is wrong

INFO [08-01|14:30:36.080] Sync stage 1/10. Download headers... 
INFO [08-01|14:30:36.223] Imported new block headers               count=2   elapsed=10.884ms    number=10574423 hash="87d2a9…d6bb6d" reorg=true forkBlockNumber=10574421
INFO [08-01|14:30:36.223] UnwindTo                                 block=10574421
INFO [08-01|14:30:36.272] Sync stage 1/10. Download headers... DONE! 
INFO [08-01|14:30:36.272] Unwinding...                             stage=8
INFO [08-01|14:30:36.295] Unwinding... DONE! 
INFO [08-01|14:30:36.295] Unwinding...                             stage=7
INFO [08-01|14:30:37.065] Unwinding... DONE! 
INFO [08-01|14:30:37.065] Unwinding...                             stage=6
INFO [08-01|14:30:37.694] Unwinding... DONE! 
INFO [08-01|14:30:37.694] Unwinding...                             stage=5
INFO [08-01|14:30:37.734] Unwinding... DONE! 
INFO [08-01|14:30:37.734] Unwinding...                             stage=4
INFO [08-01|14:30:37.734] Unwinding of intermediate hashes         from=10574422 to=10574421 csbucket=PLAIN-ACS
INFO [08-01|14:30:37.735] Unwinding of intermediate hashes         from=10574422 to=10574421 csbucket=PLAIN-SCS
INFO [08-01|14:30:38.157] Collection finished                      root hash=0xbfba1a62cb8653f0f31705c77a668a6c26c757d442e3e88c4bcf4e1a742c0469 gen IH=420.082903ms
INFO [08-01|14:30:38.260] Unwinding... DONE! 
INFO [08-01|14:30:38.260] Unwinding...                             stage=3
INFO [08-01|14:30:38.260] Unwind Execution stage                   from=10574422 to=10574421
INFO [08-01|14:30:38.293] Unwinding... DONE! 
INFO [08-01|14:30:38.293] Unwinding...                             stage=9
ERROR[08-01|14:30:38.297] Demoting invalidated transaction         hash="6ee8a8…92bf22"
ERROR[08-01|14:30:38.299] Demoting invalidated transaction         hash="7abab0…eccbed"
ERROR[08-01|14:30:38.299] Demoting invalidated transaction         hash="de485c…dcd575"
ERROR[08-01|14:30:38.299] Demoting invalidated transaction         hash="3d33a1…bc8f61"
ERROR[08-01|14:30:38.299] Demoting invalidated transaction         hash="b11d49…481e7c"
ERROR[08-01|14:30:38.299] Demoting invalidated transaction         hash="832d13…076faa"
ERROR[08-01|14:30:38.299] Demoting invalidated transaction         hash="859191…0366c0"
ERROR[08-01|14:30:38.299] Demoting invalidated transaction         hash="25ee67…e73153"
ERROR[08-01|14:30:38.299] Demoting invalidated transaction         hash="166e44…77d593"
ERROR[08-01|14:30:38.300] Demoting invalidated transaction         hash="575a75…3be569"
ERROR[08-01|14:30:38.300] Demoting invalidated transaction         hash="e41535…a3820b"
ERROR[08-01|14:30:38.300] Demoting invalidated transaction         hash="9208c8…169d57"
ERROR[08-01|14:30:38.301] Demoting invalidated transaction         hash="4f5b09…ede643"
ERROR[08-01|14:30:38.302] Demoting invalidated transaction         hash="e9ba1c…54a72e"
ERROR[08-01|14:30:38.302] Demoting invalidated transaction         hash="468d1b…82ce44"
ERROR[08-01|14:30:38.304] Demoting invalidated transaction         hash="4ca2b3…9a7fa8"
ERROR[08-01|14:30:38.304] Demoting invalidated transaction         hash="e9cb21…113488"
ERROR[08-01|14:30:38.306] Demoting invalidated transaction         hash="6ed272…2485d4"
ERROR[08-01|14:30:38.306] Demoting invalidated transaction         hash="2111ab…422dfb"
ERROR[08-01|14:30:38.306] Demoting invalidated transaction         hash="d2fbff…59bf9f"
ERROR[08-01|14:30:38.306] Demoting invalidated transaction         hash="a53a6f…e1dea1"
ERROR[08-01|14:30:38.307] Demoting invalidated transaction         hash="6de8f8…064ed8"
ERROR[08-01|14:30:38.307] Demoting invalidated transaction         hash="59955f…4547c6"
ERROR[08-01|14:30:38.307] Demoting invalidated transaction         hash="bdac81…77d4b6"
ERROR[08-01|14:30:38.307] Demoting invalidated transaction         hash="6b484f…277529"
ERROR[08-01|14:30:38.307] Demoting invalidated transaction         hash="37cc7c…40e9a0"
INFO [08-01|14:30:38.328] unwind TxPoolUpdate: Reading canonical hashes complete hashes=1
INFO [08-01|14:30:38.328] unwind TxPoolUpdate: injecting txs into the pool number=0
INFO [08-01|14:30:38.328] Injection complete 
INFO [08-01|14:30:38.330] Unwinding... DONE! 
INFO [08-01|14:30:38.330] Unwinding...                             stage=2
INFO [08-01|14:30:38.331] Unwinding... DONE! 
INFO [08-01|14:30:38.331] Unwinding...                             stage=1
INFO [08-01|14:30:38.333] Unwinding... DONE! 
INFO [08-01|14:30:38.333] Unwinding...                             stage=0
INFO [08-01|14:30:38.335] Unwinding... DONE! 

[mandrigin]

		// If there's a gap in front, alert (should never happen) and postpone all transactions
		if list.Len() > 0 && list.txs.Get(nonce) == nil {
			gapped := list.Cap(0)
			for _, tx := range gapped {
				hash := tx.Hash()
				log.Error("Demoting invalidated transaction", "hash", hash)
				pool.enqueueTx(hash, tx)
			}
			pendingGauge.Dec(int64(len(gapped)))
		}

it looks like it happens because pool.currentState.GetNonce(addr) goes backward on unwinds.
maybe we can just cleanup the pending transactions on unwinds?

[AlexeyAkhunov]

I think I know the reason for this. It is because TxPool observes the wrong view of the Canonical Hashes during the unwind. It should observe the view BEFORE the unwinding, whereas it observes the view AFTER the unwind. This will be fixed in the new downloader

[denisgranha]

should this log be a WARN instead of ERROR? currently is a bit noisy.

If it will be solved, all good... but in case is something that will happen from time to time, I would vote for putting it into WARN level

[alysak6075]

Still seeing this on 2021.07.03-alpha

[mandrigin]

if repeats with txpool.v2, feel free to reopen.