message_race_loop still update required header to latest even if no new nonces on source_finalized_updated.

[hackfisher]

[2021-12-06T23:53:35Z TRACE finality_relay::finality_loop] Considering range of headers (8186014; 8186010]
[2021-12-06T23:53:35Z TRACE finality_relay::finality_loop] Can not improve selected Crab finality proof None. No unjustified headers and recent proofs
[2021-12-06T23:53:35Z DEBUG messages_relay::message_lane_loop] Received state from Crab node: ClientState { best_self: HeaderId(8186018, 0x7315a7e75dce411c14b8d5e3f128ac0da1630496507111dfbf2a259aae8bf713), best_finalized_self: HeaderId(8186015, 0x4727ea887eef10242d2701b1483ffe8d98a41e2e1530f13fc6183dd1fee58804), best_finalized_peer_at_best_self: HeaderId(6225408, 0xea1db9acef190c683e953e79186d20d5e72a725701c5d1bd5f15f0aedbb4f75b) }
[2021-12-06T23:53:35Z DEBUG messages_relay::message_race_loop] Asking Crab::MessagesDelivery about best message nonces
[2021-12-06T23:53:36Z DEBUG messages_relay::message_race_loop] Received best nonces from Crab::MessagesDelivery: TargetClientNonces { latest_nonce: 0, nonces_data: DeliveryRaceTargetNoncesData { confirmed_nonce: 0, unrewarded_relayers: UnrewardedRelayersState { unrewarded_relayer_entries: 0, messages_in_oldest_entry: 0, total_messages: 0 } } }
[2021-12-06T23:53:36Z DEBUG messages_relay::message_lane_loop] Received state from Darwinia node: ClientState { best_self: HeaderId(6225497, 0x796599eb75b0ee0acffb3317dcfa89d0b7efe48cf74789e27c8966cff0fb647b), best_finalized_self: HeaderId(6225494, 0x7e59188248f05ca9e505ef07f38ca0403ccf3821b4ce6869e337ba0917a755e8), best_finalized_peer_at_best_self: HeaderId(8186014, 0xe4568141c79fbc2deb8577dd931649abcfcf0f439da657738f00b9ca0f44e11f) }
[2021-12-06T23:53:36Z DEBUG messages_relay::message_race_loop] Asking Darwinia::MessagesDelivery about message nonces
[2021-12-06T23:53:36Z DEBUG messages_relay::message_race_loop] Asking Darwinia::ReceivingConfirmationsDelivery about best message nonces
[2021-12-06T23:53:37Z DEBUG messages_relay::message_race_loop] Received best nonces from Darwinia::ReceivingConfirmationsDelivery: TargetClientNonces { latest_nonce: 0, nonces_data: () }
[2021-12-06T23:53:37Z DEBUG messages_relay::message_race_loop] Asking Darwinia::ReceivingConfirmationsDelivery about finalized message nonces
[2021-12-06T23:53:37Z DEBUG messages_relay::message_race_loop] Received nonces from Darwinia::MessagesDelivery: SourceClientNonces { new_nonces: {}, confirmed_nonce: Some(0) }
[2021-12-06T23:53:37Z DEBUG messages_relay::message_race_loop] Received finalized nonces from Darwinia::ReceivingConfirmationsDelivery: TargetClientNonces { latest_nonce: 0, nonces_data: () }
[2021-12-06T23:53:37Z TRACE relay_utils::metrics::global] Refreshed process metrics: CPU=1.656516432762146, memory=174985216
[2021-12-06T23:53:37Z TRACE relay_utils::metrics::global] Refreshed process metrics: CPU=1.657323956489563, memory=174985216
[2021-12-06T23:53:37Z DEBUG messages_relay::message_lane_loop] Asking Darwinia node about its state
[2021-12-06T23:53:38Z DEBUG messages_relay::message_lane_loop] Asking Crab node about its state
[2021-12-06T23:53:38Z DEBUG messages_relay::message_lane_loop] Received state from Crab node: ClientState { best_self: HeaderId(8186019, 0x628fb65a6d258d01edead9b4e75121fb01ff7af40ebf8a2259f47e3a58551860), best_finalized_self: HeaderId(8186016, 0x067aedc60b0832636def51959f9f08b8e33e411346c53726fa1b457d26cf3b10), best_finalized_peer_at_best_self: HeaderId(6225408, 0xea1db9acef190c683e953e79186d20d5e72a725701c5d1bd5f15f0aedbb4f75b) }
[2021-12-06T23:53:38Z DEBUG messages_relay::message_race_loop] Asking Crab::MessagesDelivery about message nonces
[2021-12-06T23:53:38Z INFO  messages_relay::message_race_loop] Synced Some(3) of Some(3) nonces in Darwinia::ReceivingConfirmationsDelivery -> Crab::ReceivingConfirmationsDelivery race
[2021-12-06T23:53:38Z DEBUG messages_relay::message_race_loop] Asking Crab::ReceivingConfirmationsDelivery about best message nonces
[2021-12-06T23:53:38Z DEBUG messages_relay::message_race_loop] Received best nonces from Crab::ReceivingConfirmationsDelivery: TargetClientNonces { latest_nonce: 3, nonces_data: () }
[2021-12-06T23:53:38Z DEBUG messages_relay::message_race_loop] Asking Crab::ReceivingConfirmationsDelivery about finalized message nonces
[2021-12-06T23:53:39Z DEBUG messages_relay::message_race_loop] Received nonces from Crab::MessagesDelivery: SourceClientNonces { new_nonces: {}, confirmed_nonce: Some(3) }
[2021-12-06T23:53:39Z TRACE substrate_relay_helper::on_demand_headers] More Crab headers required in on-demand-Crab-to-Darwinia relay. Going to sync up to the 8186016
[2021-12-06T23:53:39Z DEBUG messages_relay::message_race_loop] Received finalized nonces from Crab::ReceivingConfirmationsDelivery: TargetClientNonces { latest_nonce: 3, nonces_data: () }
[2021-12-06T23:53:39Z WARN  relay_utils::metrics] Failed to update metric 'Some("Crab_to_Darwinia_MessageLane_00000000_Crab_Darwinia_to_Crab_conversion_rate")': ()
[2021-12-06T23:53:39Z DEBUG messages_relay::message_lane_loop] Received state from Darwinia node: ClientState { best_self: HeaderId(6225497, 0xb9572a7594613a1be0f36ea81e078622eab6c0d487b9e021a9e16ae4cc159d4f), best_finalized_self: HeaderId(6225494, 0x7e59188248f05ca9e505ef07f38ca0403ccf3821b4ce6869e337ba0917a755e8), best_finalized_peer_at_best_self: HeaderId(8186014, 0xe4568141c79fbc2deb8577dd931649abcfcf0f439da657738f00b9ca0f44e11f) }
[2021-12-06T23:53:39Z DEBUG messages_relay::message_race_loop] Asking Darwinia::MessagesDelivery about best message nonces
[2021-12-06T23:53:39Z DEBUG messages_relay::message_race_loop] Asking Darwinia::ReceivingConfirmationsDelivery about message nonces
[2021-12-06T23:53:39Z DEBUG messages_relay::message_race_loop] Received nonces from Darwinia::ReceivingConfirmationsDelivery: SourceClientNonces { new_nonces: 4..=3, confirmed_nonce: None }
[2021-12-06T23:53:39Z DEBUG messages_relay::message_race_loop] Received best nonces from Darwinia::MessagesDelivery: TargetClientNonces { latest_nonce: 3, nonces_data: DeliveryRaceTargetNoncesData { confirmed_nonce: 2, unrewarded_relayers: UnrewardedRelayersState { unrewarded_relayer_entries: 1, messages_in_oldest_entry: 1, total_messages: 1 } } }
[2021-12-06T23:53:39Z DEBUG messages_relay::message_race_loop] Asking Darwinia::MessagesDelivery about finalized message nonces
[2021-12-06T23:53:40Z TRACE relay_utils::metrics::global] Refreshed process metrics: CPU=1.7638412714004517, memory=174985216
[2021-12-06T23:53:40Z TRACE relay_utils::metrics::global] Refreshed process metrics: CPU=1.6662582159042358, memory=174985216
[2021-12-06T23:53:40Z DEBUG messages_relay::message_race_loop] Received finalized nonces from Darwinia::MessagesDelivery: TargetClientNonces { latest_nonce: 3, nonces_data: DeliveryRaceTargetNoncesData { confirmed_nonce: 2, unrewarded_relayers: UnrewardedRelayersState { unrewarded_relayer_entries: 1, messages_in_oldest_entry: 1, total_messages: 1 } } }
[2021-12-06T23:53:40Z DEBUG messages_relay::message_lane_loop] Asking Crab node about its state
[2021-12-06T23:53:41Z DEBUG messages_relay::message_lane_loop] Asking Darwinia node about its state
[2021-12-06T23:53:41Z DEBUG messages_relay::message_lane_loop] Received state from Crab node: ClientState { best_self: HeaderId(8186019, 0x628fb65a6d258d01edead9b4e75121fb01ff7af40ebf8a2259f47e3a58551860), best_finalized_self: HeaderId(8186017, 0x3f3322bb4019c25b490e01bb2f212b31497bb61d90cf57fc1df03dce78f752b7), best_finalized_peer_at_best_self: HeaderId(6225408, 0xea1db9acef190c683e953e79186d20d5e72a725701c5d1bd5f15f0aedbb4f75b) }
[2021-12-06T23:53:41Z INFO  messages_relay::message_race_loop] Synced Some(0) of Some(0) nonces in Darwinia::MessagesDelivery -> Crab::MessagesDelivery race
[2021-12-06T23:53:41Z DEBUG messages_relay::message_race_loop] Asking Crab::MessagesDelivery about best message nonces
[2021-12-06T23:53:41Z INFO  messages_relay::message_race_loop] Synced Some(0) of Some(0) nonces in Crab::ReceivingConfirmationsDelivery -> Darwinia::ReceivingConfirmationsDelivery race
[2021-12-06T23:53:41Z DEBUG messages_relay::message_race_loop] Asking Crab::ReceivingConfirmationsDelivery about message nonces
[2021-12-06T23:53:41Z WARN  relay_utils::metrics] Failed to update metric 'Some("Darwinia_to_Crab_MessageLane_00000000_Darwinia_Crab_to_Darwinia_conversion_rate")': ()
[2021-12-06T23:53:41Z DEBUG messages_relay::message_race_loop] Received nonces from Crab::ReceivingConfirmationsDelivery: SourceClientNonces { new_nonces: 1..=0, confirmed_nonce: None }
[2021-12-06T23:53:42Z DEBUG messages_relay::message_race_loop] Received best nonces from Crab::MessagesDelivery: TargetClientNonces { latest_nonce: 0, nonces_data: DeliveryRaceTargetNoncesData { confirmed_nonce: 0, unrewarded_relayers: UnrewardedRelayersState { unrewarded_relayer_entries: 0, messages_in_oldest_entry: 0, total_messages: 0 } } }
[2021-12-06T23:53:42Z DEBUG messages_relay::message_race_loop] Asking Crab::MessagesDelivery about finalized message nonces
[2021-12-06T23:53:42Z DEBUG messages_relay::message_lane_loop] Received state from Darwinia node: ClientState { best_self: HeaderId(6225497, 0xb9572a7594613a1be0f36ea81e078622eab6c0d487b9e021a9e16ae4cc159d4f), best_finalized_self: HeaderId(6225495, 0xee487a12f2cc97df10936d20b79b1be80bf201bfdcea819c01bfabf3633e835f), best_finalized_peer_at_best_self: HeaderId(8186014, 0xe4568141c79fbc2deb8577dd931649abcfcf0f439da657738f00b9ca0f44e11f) }
[2021-12-06T23:53:42Z DEBUG messages_relay::message_race_loop] Asking Darwinia::ReceivingConfirmationsDelivery about best message nonces
[2021-12-06T23:53:42Z DEBUG messages_relay::message_race_loop] Asking Darwinia::MessagesDelivery about message nonces
[2021-12-06T23:53:42Z DEBUG messages_relay::message_race_loop] Received best nonces from Darwinia::ReceivingConfirmationsDelivery: TargetClientNonces { latest_nonce: 0, nonces_data: () }
[2021-12-06T23:53:42Z DEBUG messages_relay::message_race_loop] Asking Darwinia::ReceivingConfirmationsDelivery about finalized message nonces
[2021-12-06T23:53:42Z DEBUG messages_relay::message_race_loop] Received finalized nonces from Darwinia::ReceivingConfirmationsDelivery: TargetClientNonces { latest_nonce: 0, nonces_data: () }
[2021-12-06T23:53:42Z DEBUG messages_relay::message_race_loop] Received nonces from Darwinia::MessagesDelivery: SourceClientNonces { new_nonces: {}, confirmed_nonce: Some(0) }
[2021-12-06T23:53:42Z DEBUG messages_relay::message_race_loop] Received finalized nonces from Crab::MessagesDelivery: TargetClientNonces { latest_nonce: 0, nonces_data: DeliveryRaceTargetNoncesData { confirmed_nonce: 0, unrewarded_relayers: UnrewardedRelayersState { unrewarded_relayer_entries: 0, messages_in_oldest_entry: 0, total_messages: 0 } } }
[2021-12-06T23:53:42Z TRACE finality_relay::finality_loop] Considering range of headers (8186014; 8186016]
[2021-12-06T23:53:43Z TRACE finality_relay::finality_loop] Read 3 finality proofs from Darwinia finality stream for headers in range [Some(6225493); Some(6225495)]
[2021-12-06T23:53:43Z TRACE finality_relay::finality_loop] Trying to improve selected Darwinia finality proof None. Headers range: [6225409; 6225434]. Proofs range: [6225435; 6225495].Trying to improve to: 6225435. Result: failed
[2021-12-06T23:53:43Z TRACE finality_relay::finality_loop] Read 2 finality proofs from Crab finality stream for headers in range [Some(8186016); Some(8186017)]
[2021-12-06T23:53:43Z TRACE finality_relay::finality_loop] Trying to improve selected Crab finality proof None. Headers range: [8186015; 8186016]. Proofs range: [8186015; 8186017].Trying to improve to: 8186016. Result: improved
[2021-12-06T23:53:43Z DEBUG finality_relay::finality_loop] Going to submit finality proof of Crab header #8186016 to Darwinia
[2021-12-06T23:53:43Z DEBUG messages_relay::message_lane_loop] Asking Darwinia node about its state
[2021-12-06T23:53:44Z DEBUG messages_relay::message_lane_loop] Asking Crab node about its state
[2021-12-06T23:53:44Z TRACE relay_substrate_client::client] Sent transaction to Darwinia node: 0x2be2424358fecb38372f9cad9db8a11a9728a7429fc121703bf0f28ded4e9145

[hackfisher]

This can be reproduced when there are >= 2 bridger running, and be triggered to a feedback loop by one of the bridgers start to update finalized source on target(due to mandatory or new message).

This feedback loop result that two bridgers will continuing send finality proof transactions until one of them run out of funds.
Bridger is signaled to drag required_finalized_number to best_finalized, and after finalized source on target successfully, will signal other bridgers to do the same thing.

[hackfisher]

Fixed in darwinia-network/darwinia-messages-substrate@47262eb

Not merge into master yet, still in paritytech/parity-bridges-common@master...darwinia-network:denny-try-fix