Geth is losing pending transactions with the error: Demoting invalidated transaction

[begetan]

System information

Geth version: Geth/v1.9.25-stable-e7872729/linux-amd64/go1.15.6 OS & Version: Linux Ubuntu 18.04 LTS Commit hash : (if develop)

We have a Highly Available configuration with 2 Geth Node and AWS Application Load Balancer. Our software (several workers) sending quite a high number of transactions that are balanced across the nodes.

Sometimes the network fees rising high, so several transactions stuck in a pending state. We limit this number to 10. When it occurs we bumping the gas limit to push them into the network.

Expected behaviour

The transactions should stay in the queue and emit to the network ether after increasing the gas limit, or at the moment when the gas price goes down

Actual behaviour

In some very rare case under heavy network load a node drops all transactions and start to emit new with the changing nounce. There is a message in the log: Demoting invalidated transaction

Steps to reproduce the behaviour

It is quite a rare case, but it seems to become more frequent with the increase of a load of a node ( a number TX per interval) and with the growth of network fees

I am not sure if it is a bug or node misconfiguration but here is a key point of opening this issue: https://github.com/ethereum/go-ethereum/blob/27786671d28705159f15cd458045d29d732110e5/core/tx_pool.go#L1438

		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)

				// Internal shuffle shouldn't touch the lookup set.
				pool.enqueueTx(hash, tx, false, false)
			}

So it definitely goes into this function and drops pending transactions which should be never happened according to the comment.

I wonder if any setting could protect from such an event? Is it a software issue due to the loaded network?

[holiman]

The problem is that out of N transactions, n0 becomes removed due to being too cheap, compared to other transasctions. When that one is dropped, it means that n1 ... nN becomes non-executable, (gapped), and demoted to the queue instead of pending.

[fjl]

@begetan I'm trying to understand your problem. Are you sending transactions to your Geth nodes via RPC? Are you sending the RPC through load balancer?

Geth txpool has features to treat 'local' transactions in a special way. When tx is received via RPC, it is treated as local transaction, and will not be dropped from the txpool. Your app setup with the load balancer might expose bugs in our implementation of this feature.

[begetan]

@holiman you describe the situation pretty correctly. What is a workaround then?

[begetan]

@fjl we are using a load balancer with a persistent connection with WebSocket. Requests are continuously going to a single node unless a network or another long performance issue breaks the connection.

We are quite sure that most time our transactions are coming from RPC connections and staying local until get confirmed. Do you think that a handower of the connection between nodes may cause local transactions to drop?

[begetan]

@fjl I came through logs for the last 7 days and see no correlation between the Demoting invalidated transaction error and the WebSocket disconnect error from the app.

[fjl]

Thank you for the additional information.

[grayguest]

I also met so many logs, for example

INFO [06-09|06:35:37.479] Imported new chain segment               blocks=1 txs=48  mgas=7.996  elapsed=25.602ms    mgasps=312.318  number=4,937,846 hash=0db702..615a85 dirty=141.30MiB
INFO [06-09|06:35:37.479] Unindexed transactions                   blocks=1 txs=1   tail=2,587,847 elapsed="93.493µs"
INFO [06-09|06:35:38.642] Imported new chain segment               blocks=1 txs=82  mgas=7.707  elapsed=20.297ms    mgasps=379.673  number=4,937,846 hash=ba8f22..dc198c dirty=141.51MiB
INFO [06-09|06:35:52.313] Chain reorg detected                     number=4,937,845 hash=077de6..8c9c13 drop=1 dropfrom=0db702..615a85 add=2 addfrom=38391c..b9a91a
INFO [06-09|06:35:52.314] Imported new chain segment               blocks=1 txs=38  mgas=8.002  elapsed=16.564ms    mgasps=483.061  number=4,937,847 hash=38391c..b9a91a dirty=141.41MiB
INFO [06-09|06:35:52.314] Unindexed transactions                   blocks=1 txs=3   tail=2,587,848 elapsed="73.602µs"
ERROR[06-09|06:35:52.326] Demoting invalidated transaction         hash=57fe07..31cbd0
ERROR[06-09|06:35:52.326] Demoting invalidated transaction         hash=73fcf3..5aae07
ERROR[06-09|06:35:52.326] Demoting invalidated transaction         hash=a2c651..b2a4fd
ERROR[06-09|06:35:52.326] Demoting invalidated transaction         hash=7c95bd..a37d2f
ERROR[06-09|06:35:52.326] Demoting invalidated transaction         hash=071a56..16b831
ERROR[06-09|06:35:52.326] Demoting invalidated transaction         hash=595523..67bd7e
ERROR[06-09|06:35:52.326] Demoting invalidated transaction         hash=8dfb8b..1681ec
ERROR[06-09|06:35:52.326] Demoting invalidated transaction         hash=602965..fde21d
ERROR[06-09|06:35:52.326] Demoting invalidated transaction         hash=1ff634..8c5fb4
ERROR[06-09|06:35:52.329] Demoting invalidated transaction         hash=d6dfad..3e944b
ERROR[06-09|06:35:52.329] Demoting invalidated transaction         hash=cfaf23..c32e5e
ERROR[06-09|06:35:52.329] Demoting invalidated transaction         hash=1c7131..1d4375
ERROR[06-09|06:35:52.329] Demoting invalidated transaction         hash=dd3c26..dabf15
ERROR[06-09|06:35:52.331] Demoting invalidated transaction         hash=401c37..cff114
ERROR[06-09|06:35:52.332] Demoting invalidated transaction         hash=5ca986..227e48
ERROR[06-09|06:35:52.332] Demoting invalidated transaction         hash=3e39c8..f7c2f7
ERROR[06-09|06:35:52.332] Demoting invalidated transaction         hash=6a6c16..393335
ERROR[06-09|06:35:52.332] Demoting invalidated transaction         hash=e143e7..45b711
ERROR[06-09|06:35:52.332] Demoting invalidated transaction         hash=4b8f62..9dbb7b
ERROR[06-09|06:35:52.332] Demoting invalidated transaction         hash=4717b9..ddb2ce
ERROR[06-09|06:35:52.332] Demoting invalidated transaction         hash=7de7d4..fade6f
ERROR[06-09|06:35:52.332] Demoting invalidated transaction         hash=03953a..eeed09
ERROR[06-09|06:35:52.332] Demoting invalidated transaction         hash=3cb812..8f97f7
ERROR[06-09|06:35:52.336] Demoting invalidated transaction         hash=ff2077..33c51d
ERROR[06-09|06:35:52.336] Demoting invalidated transaction         hash=2fef84..62c76b
ERROR[06-09|06:35:52.342] Demoting invalidated transaction         hash=7471a8..2e1712
ERROR[06-09|06:35:52.342] Demoting invalidated transaction         hash=dc3ab8..a61ed7
ERROR[06-09|06:35:52.343] Demoting invalidated transaction         hash=11d5f4..a3b23e
INFO [06-09|06:35:53.869] Imported new chain segment               blocks=1 txs=100 mgas=7.745  elapsed=25.701ms    mgasps=301.336  number=4,937,847 hash=8864d4..4412f2 dirty=141.59MiB
INFO [06-09|06:36:07.418] Imported new chain segment               blocks=1 txs=42  mgas=7.997  elapsed=56.322ms    mgasps=141.980  number=4,937,848 hash=664cd9..496421 dirty=141.35MiB
INFO [06-09|06:36:07.418] Unindexed transactions                   blocks=1 txs=1   tail=2,587,849 elapsed="82.744µs"
INFO [06-09|06:36:09.313] Imported new chain segment               blocks=1 txs=60  mgas=7.991  elapsed=38.821ms    mgasps=205.836  number=4,937,848 hash=1ca0e7..f405f9 dirty=141.54MiB
INFO [06-09|06:36:09.366] Imported new chain segment               blocks=1 txs=58  mgas=7.986  elapsed=17.513ms    mgasps=456.009  number=4,937,848 hash=bae824..e2e26f dirty=141.56MiB
INFO [06-09|06:36:23.488] Imported new chain segment               blocks=1 txs=29  mgas=3.630  elapsed=12.695ms    mgasps=285.918  number=4,937,849 hash=6d2283..33cddb dirty=141.66MiB
INFO [06-09|06:36:23.488] Unindexed transactions                   blocks=1 txs=0   tail=2,587,850 elapsed="64.848µs"
INFO [06-09|06:36:24.057] Chain reorg detected                     number=4,937,848 hash=664cd9..496421 drop=1 dropfrom=6d2283..33cddb add=1 addfrom=f21301..45442d
INFO [06-09|06:36:24.057] Imported new chain segment               blocks=1 txs=61  mgas=7.998  elapsed=16.445ms    mgasps=486.331  number=4,937,849 hash=f21301..45442d dirty=141.75MiB
ERROR[06-09|06:36:24.079] Demoting invalidated transaction         hash=595523..67bd7e
ERROR[06-09|06:36:24.079] Demoting invalidated transaction         hash=8dfb8b..1681ec
ERROR[06-09|06:36:24.079] Demoting invalidated transaction         hash=602965..fde21d
ERROR[06-09|06:36:24.079] Demoting invalidated transaction         hash=1ff634..8c5fb4
INFO [06-09|06:36:24.226] Imported new chain segment               blocks=1 txs=58  mgas=7.990  elapsed=19.877ms    mgasps=401.964  number=4,937,849 hash=caaa04..70b327 dirty=141.77MiB
INFO [06-09|06:36:24.526] Deep froze chain segment                 blocks=4 elapsed=4.314ms     number=4,847,849 hash=da8eee..99cc23
INFO [06-09|06:36:38.442] Chain reorg detected                     number=4,937,848 hash=664cd9..496421 drop=1 dropfrom=f21301..45442d add=2 addfrom=508763..ff728b
INFO [06-09|06:36:38.443] Imported new chain segment               blocks=1 txs=81  mgas=7.986  elapsed=31.013ms    mgasps=257.500  number=4,937,850 hash=508763..ff728b dirty=141.94MiB
INFO [06-09|06:36:38.443] Unindexed transactions                   blocks=1 txs=2   tail=2,587,851 elapsed="87.705µs"
ERROR[06-09|06:36:38.457] Demoting invalidated transaction         hash=65fd63..7a6bc8
ERROR[06-09|06:36:38.457] Demoting invalidated transaction         hash=1bd81c..23525e
ERROR[06-09|06:36:38.457] Demoting invalidated transaction         hash=cfa6e5..c9a145
ERROR[06-09|06:36:38.458] Demoting invalidated transaction         hash=f7d9ed..0673d9
ERROR[06-09|06:36:38.458] Demoting invalidated transaction         hash=66ea9c..766d53
ERROR[06-09|06:36:38.458] Demoting invalidated transaction         hash=14d606..c8dbab
ERROR[06-09|06:36:38.458] Demoting invalidated transaction         hash=3a9cad..c34f40
ERROR[06-09|06:36:38.458] Demoting invalidated transaction         hash=40b390..13325a
ERROR[06-09|06:36:38.458] Demoting invalidated transaction         hash=61318f..051311
ERROR[06-09|06:36:38.458] Demoting invalidated transaction         hash=77bce2..819385
ERROR[06-09|06:36:38.458] Demoting invalidated transaction         hash=3bafc6..60a08f
ERROR[06-09|06:36:38.458] Demoting invalidated transaction         hash=a62119..c54947
ERROR[06-09|06:36:38.460] Demoting invalidated transaction         hash=9e96e6..47d6c9
ERROR[06-09|06:36:38.461] Demoting invalidated transaction         hash=0af467..9c8d6f
ERROR[06-09|06:36:38.461] Demoting invalidated transaction         hash=ea3a6a..431171
ERROR[06-09|06:36:38.462] Demoting invalidated transaction         hash=5bb416..008582
ERROR[06-09|06:36:38.464] Demoting invalidated transaction         hash=6ab7cf..6dcf41
ERROR[06-09|06:36:38.464] Demoting invalidated transaction         hash=6e1728..ac9f0d
ERROR[06-09|06:36:38.464] Demoting invalidated transaction         hash=9ce8e6..c39ea5
ERROR[06-09|06:36:38.468] Demoting invalidated transaction         hash=685b56..b0c2eb
ERROR[06-09|06:36:38.468] Demoting invalidated transaction         hash=7aa9c0..1ef14f
ERROR[06-09|06:36:38.471] Demoting invalidated transaction         hash=462e59..d9371c
INFO [06-09|06:36:52.948] Imported new chain segment               blocks=1 txs=60  mgas=7.764  elapsed=53.651ms    mgasps=144.710  number=4,937,851 hash=ab52e8..190dd4 dirty=142.14MiB

[mohamedmansour]

I recently saw these in the logs, shouldn't these be warnings instead?

INFO [09-08\|22:16:08.555] Unindexed transactions                   blocks=1          txs=322         tail=13,150,966 elapsed=2.984ms
--
  |   | INFO [09-08\|22:16:08.551] Imported new chain segment               blocks=1          txs=89          mgas=6.855   elapsed=47.287ms     mgasps=144.972  number=15,500,965 hash=4871fe..688572 dirty=1022.15MiB
  |   | INFO [09-08\|22:16:07.307] Unindexed transactions                   blocks=1          txs=277         tail=13,150,965 elapsed=2.559ms
  |   | INFO [09-08\|22:16:07.304] Imported new chain segment               blocks=1          txs=300         mgas=29.980  elapsed=199.269ms    mgasps=150.450  number=15,500,964 hash=a2f6c1..740c22 dirty=1022.97MiB
  |   | ERROR[09-08\|22:15:34.019] Demoting invalidated transaction         hash=2049b1..24c87f
  |   | ERROR[09-08\|22:15:34.019] Demoting invalidated transaction         hash=453529..718e2d
  |   | INFO [09-08\|22:15:34.003] Unindexed transactions                   blocks=1          txs=0           tail=13,150,964 elapsed="61.427µs"
  |   | INFO [09-08\|22:15:34.003] Imported new chain segment               blocks=1          txs=78          mgas=16.292  elapsed=109.574ms    mgasps=148.687  number=15,500,963 hash=aa2bb5..42b404 dirty=1021.88MiB
  |   | INFO [09-08\|22:15:33.995] Chain reorg detected                     number=15,500,961 hash=6fb67b..f96aa3 drop=1 dropfrom=abe700..79e2df add=2 addfrom=aa2bb5..42b404
  |   | INFO [09-08\|22:15:32.406] Imported new chain segment               blocks=1          txs=256         mgas=29.995  elapsed=141.899ms    mgasps=211.379  number=15,500,962 hash=abe700..79e2df dirty=1023.91MiB
  |   | INFO [09-08\|22:15:32.405] Chain reorg detected                     number=15,500,961 hash=6fb67b..f96aa3 drop=1 dropfrom=65b30d..c835fe add=1 addfrom=abe700..79e2df
  |   | INFO [09-08\|22:15:32.265] Unindexed transactions                   blocks=1          txs=38          tail=13,150,963 elapsed="897.908µs"
  |   | INFO [09-08\|22:15:32.264] Imported new chain segment               blocks=1          txs=252         mgas=29.998  elapsed=178.684ms    mgasps=167.883  number=15,500,962 hash=65b30d..c835fe dirty=1023.15MiB
  |   | INFO [09-08\|22:15:18.840] Unindexed transactions                   blocks=1          txs=15          tail=13,150,962 elapsed="410.686µs"

[fjl]

I guess we should make this a warning, yes.