Agora node sometimes cannot catch up

[kchulj]

I observed a strange situation where two nodes were moving forward, but the other one got stuck.
It's probably triggered by #1367 .

Node 2

Nov 19 01:26:59 eu-002 docker[14703]: 2020-11-19 01:26:59,707 Info [agora.consensus.protocol.Nominator] - Nomination started at 1605749219
Nov 19 01:26:59 eu-002 docker[14703]: 2020-11-19 01:26:59,707 Info [agora.consensus.protocol.Nominator] - agora.consensus.protocol.Nominator.Nominator.nominate(): Proposing tx set for slot 34
Nov 19 01:26:59 eu-002 docker[14703]: 2020-11-19 01:26:59,714 Info [agora.consensus.protocol.Nominator] - agora.consensus.protocol.Nominator.Nominator.nominate(): Tx set rejected nomination
Nov 19 01:27:00 eu-002 docker[14703]: 2020-11-19 01:27:00,899 Info [agora.consensus.state.ValidatorSet] - Rejected pre-image: validator not enrolled for key: 0x1375e5c856754286a57523cfbb79779c2e75ebb766a4c731
Nov 19 01:27:01 eu-002 docker[14703]: 2020-11-19 01:27:01,262 Info [agora.consensus.protocol.Nominator] - combineCandidates: 34
Nov 19 01:27:02 eu-002 docker[14703]: 2020-11-19 01:27:02,273 Info [agora.consensus.protocol.Nominator] - Externalized consensus data set at 34: { tx_set: [{ type: TxType.Payment, inputs: [{ utxo: 0x057a061be
Nov 19 01:27:03 eu-002 docker[14703]: 2020-11-19 01:27:03,321 Info [agora.network.NetworkManager] - Retrieving blocks [34..34] from http://na-001.bosagora.io:4826..
Nov 19 01:27:03 eu-002 docker[14703]: 2020-11-19 01:27:03,573 Info [agora.network.NetworkManager] - Received blocks [34..34]

Node 4

Nov 19 01:26:58 na-001 docker[13449]: 2020-11-19 01:26:58,122 Info [agora.consensus.protocol.Nominator] - Nomination started at 1605749218
Nov 19 01:26:58 na-001 docker[13449]: 2020-11-19 01:26:58,122 Info [agora.consensus.protocol.Nominator] - agora.consensus.protocol.Nominator.Nominator.nominate(): Proposing tx set for slot 34
Nov 19 01:26:58 na-001 docker[13449]: 2020-11-19 01:26:58,129 Info [agora.consensus.protocol.Nominator] - agora.consensus.protocol.Nominator.Nominator.nominate(): Tx set rejected nomination
Nov 19 01:27:00 na-001 docker[13449]: 2020-11-19 01:27:00,703 Info [agora.consensus.state.ValidatorSet] - Rejected pre-image: validator not enrolled for key: 0x1375e5c856754286a57523cfbb79779c2e75ebb766a4c73114631
Nov 19 01:27:01 na-001 docker[13449]: 2020-11-19 01:27:01,462 Info [agora.consensus.protocol.Nominator] - combineCandidates: 34
Nov 19 01:27:02 na-001 docker[13449]: 2020-11-19 01:27:02,694 Info [agora.consensus.protocol.Nominator] - Externalized consensus data set at 34: { tx_set: [{ type: TxType.Payment, inputs: [{ utxo: 0x057a061be14b63
Nov 19 01:27:03 na-001 docker[13449]: 2020-11-19 01:27:03,384 Info [agora.network.NetworkManager] - Retrieving blocks [34..34] from http://eu-002.bosagora.io:3826..
Nov 19 01:27:03 na-001 docker[13449]: 2020-11-19 01:27:03,633 Info [agora.network.NetworkManager] - Received blocks [34..34]

Node 6

Nov 19 01:27:12 na-002 docker[5797]: 2020-11-19 01:27:12,538 Info [agora.node.FullNode] - Accepted transaction: Type : Payment, Inputs (1): 0xa8ed...6dbb:0x067e...8aed
Nov 19 01:27:12 na-002 docker[5797]: Outputs (1): GA5W...SKYH(162,666.6,666,666) (0x778bf150e9695142f223e469295b3afdd3e2158c0a38ed97977a9214251e150bdbb5b020d1342411a3386eabe97758ba30f6804b972e5123809ccf105576cc1a)
Nov 19 01:27:12 na-002 docker[5797]: 2020-11-19 01:27:12,805 Info [agora.network.NetworkManager] - Retrieving blocks [16..34] from http://eu-002.bosagora.io:3826..
Nov 19 01:27:13 na-002 docker[5797]: 2020-11-19 01:27:13,112 Info [agora.node.FullNode] - Accepted transaction: Type : Payment, Inputs (1): 0xc0f6...ce5f:0x0311...24eb
Nov 19 01:27:13 na-002 docker[5797]: Outputs (1): GDAR...4HTP(162,666.6,666,666) (0xa87594c336bc9f164f227fd430be52dcea45795cb2d8b43e376edb4f649fd42f7c9b265287efe2009a9db2c06dfe3a8a975818eddd1cb0b9030a9f3280b3fb58)
Nov 19 01:27:13 na-002 docker[5797]: 2020-11-19 01:27:13,383 Info [agora.network.NetworkManager] - Received blocks [16..34]
Nov 19 01:27:13 na-002 docker[5797]: 2020-11-19 01:27:13,770 Info [agora.node.FullNode] - Accepted transaction: Type : Payment, Inputs (1): 0xf3d6...65a7:0x07c2...2d70
Nov 19 01:27:13 na-002 docker[5797]: Outputs (1): GDSO...SMMD(162,666.6,666,666) (0x7213daf13e3b44e6c8733cda7f853d69fb7119239d787d8d1b377bca143612097eb1a1e774e6f02fe042c9991f5253bed90c16d6c93e2d4b70c3245807099b13)
Nov 19 01:27:14 na-002 docker[5797]: 2020-11-19 01:27:14,287 Info [agora.node.FullNode] - Accepted transaction: Type : Payment, Inputs (1): 0x8684...c2bd:0x0a7a...b32b
Nov 19 01:27:14 na-002 docker[5797]: Outputs (1): GDUE...H3DY(2,440,000) (0xac6576474bc28e0f62e52a068657f6369a205d01ae18543171d254672694eb046a15aae65455aa443653ecfa7ff356c3a78c6356a75470773fc9063ec676a59f)
Nov 19 01:27:14 na-002 docker[5797]: 2020-11-19 01:27:14,747 Info [agora.node.Ledger] - Rejected tx. Reason: Transaction: Input ref not in UTXO. Tx: { type: TxType.Payment, inputs: [{ utxo: 0x14fa2b9cc180b84765dee0cc08a2f1d
Nov 19 01:27:14 na-002 docker[5797]: 2020-11-19 01:27:14,825 Info [agora.node.Ledger] - Rejected tx. Reason: Transaction: Input ref not in UTXO. Tx: { type: TxType.Payment, inputs: [{ utxo: 0x14fa2b9cc180b84765dee0cc08a2f1d
Nov 19 01:27:14 na-002 docker[5797]: 2020-11-19 01:27:14,911 Info [agora.node.Ledger] - Rejected tx. Reason: Transaction: Input ref not in UTXO. Tx: { type: TxType.Payment, inputs: [{ utxo: 0x14fa2b9cc180b84765dee0cc08a2f1d
Nov 19 01:27:15 na-002 docker[5797]: 2020-11-19 01:27:15,34 Info [agora.network.NetworkManager] - Retrieving blocks [16..34] from http://eu-002.bosagora.io:3826..
Nov 19 01:27:15 na-002 docker[5797]: 2020-11-19 01:27:15,203 Info [agora.node.Ledger] - Rejected tx. Reason: Transaction: Input ref not in UTXO. Tx: { type: TxType.Payment, inputs: [{ utxo: 0x14fa2b9cc180b84765dee0cc08a2f1d
Nov 19 01:27:15 na-002 docker[5797]: 2020-11-19 01:27:15,386 Info [agora.node.FullNode] - Accepted transaction: Type : Payment, Inputs (1): 0x5f93...4ef4:0x0de2...ab6a
Nov 19 01:27:15 na-002 docker[5797]: Outputs (1): GDAK...G6T6(2,440,000) (0x26779e8b47476184a93d36484837df75602a0d96628e7709d1e8178e479e43c820c4fdf9f8371516904a23b83f07b33eed4fb8d977788db0fd1ff28b966c1ec4)
Nov 19 01:27:15 na-002 docker[5797]: 2020-11-19 01:27:15,596 Info [agora.network.NetworkManager] - Received blocks [16..34]
Nov 19 01:27:16 na-002 docker[5797]: 2020-11-19 01:27:16,778 Info [agora.network.NetworkManager] - Retrieving blocks [16..34] from http://eu-002.bosagora.io:3826..
Nov 19 01:27:17 na-002 docker[5797]: 2020-11-19 01:27:17,321 Info [agora.network.NetworkManager] - Received blocks [16..34]

[kchulj]

Worked around by #1397. Will close.

[Geod24]

Note that I submitted a patch upstream for the issue, so once we use v2.095.0 as a minimum, it will just work again.