From e22bc0eb073cc93a86a2ffdbb4eb9c1a4ffeebc5 Mon Sep 17 00:00:00 2001 From: Hansie Odendaal <39146854+hansieodendaal@users.noreply.github.com> Date: Wed, 27 Nov 2024 08:42:39 +0200 Subject: [PATCH] feat: add connectivity timeout (#6703) Description --- Added a wallet connectivity timeout so that long-winded dial-peer failures can be managed timeously. Motivation and Context --- On some mobile wallets, the `dial_peer` command can take up to 6 minutes to return an error or timeout. See the nextnet mobile wallet log below and notice the timestamp difference between `Attempting base node peer` and `Connectivity error: ConnectionFailed`: ``` 2024-11-26 09:48:39.078496504 [wallet::connectivity] DEBUG Attempting base node peer '1c8b393640e1cd7d1a86957eb3'... (last attempt Some(895ns)) 2024-11-26 09:54:32.664270603 [wallet::connectivity] WARN Connectivity error: ConnectionFailed: Failed to connect to peer within the maximum number of attempts 2024-11-26 09:54:32.667991713 [wallet::connectivity] DEBUG Attempting base node peer 'a04e78a02df887a26ffa9eadaa'... (last attempt Some(122ns)) 2024-11-26 09:58:35.639455170 [wallet::connectivity] WARN Connectivity error: ConnectionFailed: Failed to connect to peer within the maximum number of attempts 2024-11-26 09:58:35.642903697 [wallet::connectivity] DEBUG Attempting base node peer 'e108eb7fbf44d58199908aa928'... (last attempt Some(244ns)) 2024-11-26 10:00:03.975743624 [wallet::connectivity] WARN Connectivity error: ConnectionFailed: Failed to connect to peer within the maximum number of attempts 2024-11-26 10:00:03.978222425 [wallet::connectivity] DEBUG Attempting base node peer '6ea597117476676d5ddcb18153'... (last attempt Some(163ns)) 2024-11-26 10:04:24.017030169 [wallet::connectivity] WARN Connectivity error: ConnectionFailed: Failed to connect to peer within the maximum number of attempts 2024-11-26 10:04:24.022077451 [wallet::connectivity] DEBUG Attempting base node peer '63718f177e749a0484a7050f8d'... (last attempt Some(366ns)) 2024-11-26 10:09:52.935971247 [wallet::connectivity] WARN Connectivity error: ConnectionFailed: Failed to connect to peer within the maximum number of attempts 2024-11-26 10:09:52.939635269 [wallet::connectivity] DEBUG Attempting base node peer 'db5ab85a84ce79bcd2ea700f13'... (last attempt Some(285ns)) 2024-11-26 10:16:01.668541211 [wallet::connectivity] WARN Connectivity error: ConnectionFailed: Failed to connect to peer within the maximum number of attempts 2024-11-26 10:16:01.672009107 [wallet::connectivity] DEBUG Attempting base node peer '81e258cb5e8419dfdd863282c3'... (last attempt Some(610ns)) 2024-11-26 10:20:25.197734699 [wallet::connectivity] WARN Connectivity error: ConnectionFailed: Failed to connect to peer within the maximum number of attempts 2024-11-26 10:20:25.202187051 [wallet::connectivity] DEBUG Attempting base node peer '6d9043bba0c196ded52a9f79da'... (last attempt Some(244ns)) 2024-11-26 10:20:26.038427123 [wallet::connectivity] DEBUG Established peer connection to base node '6d9043bba0c196ded52a9f79da' ``` This PR, as tested on Windows console wallet, with many dysfunctional peer seeds on purpose ``` 2024-11-26 16:29:06.603475100 [wallet::connectivity] DEBUG Attempting base node peer '1c8b393640e1cd7d1a86957eb3'... (last attempt Some(100ns)) 2024-11-26 16:29:06.603488500 [wallet::connectivity] TRACE Attempt dial with client timeout 1s 2024-11-26 16:29:07.615599600 [wallet::connectivity] WARN Connectivity error: Client cancelled: 'Could not connect to '1c8b393640e1cd7d1a86957eb3' in 1s' 2024-11-26 16:29:07.615740400 [wallet::connectivity] DEBUG Attempting base node peer 'e108eb7fbf44d58199908aa928'... (last attempt Some(100ns)) 2024-11-26 16:29:07.615751700 [wallet::connectivity] TRACE Attempt dial with client timeout 1s 2024-11-26 16:29:08.617694200 [wallet::connectivity] WARN Connectivity error: Client cancelled: 'Could not connect to 'e108eb7fbf44d58199908aa928' in 1s' 2024-11-26 16:29:08.617884800 [wallet::connectivity] DEBUG Attempting base node peer '63718f177e749a0484a7050f8d'... (last attempt Some(100ns)) 2024-11-26 16:29:08.617903900 [wallet::connectivity] TRACE Attempt dial with client timeout 1s 2024-11-26 16:29:09.631693800 [wallet::connectivity] WARN Connectivity error: Client cancelled: 'Could not connect to '63718f177e749a0484a7050f8d' in 1s' 2024-11-26 16:29:09.631830300 [wallet::connectivity] DEBUG Attempting base node peer 'b02156f7ec30db5d661dd9b6e2'... (last attempt Some(0ns)) 2024-11-26 16:29:09.631840600 [wallet::connectivity] TRACE Attempt dial with client timeout 1s 2024-11-26 16:29:09.650843600 [wallet::connectivity] WARN Connectivity error: ConnectionFailed: Noise handshake error: An established connection was aborted by the software in your host machine. (os error 10053) 2024-11-26 16:29:09.650927000 [wallet::connectivity] DEBUG Attempting base node peer 'a04e78a02df887a26ffa9eadaa'... (last attempt Some(0ns)) 2024-11-26 16:29:09.650937900 [wallet::connectivity] TRACE Attempt dial with client timeout 1s 2024-11-26 16:29:10.663273200 [wallet::connectivity] WARN Connectivity error: Client cancelled: 'Could not connect to 'a04e78a02df887a26ffa9eadaa' in 1s' 2024-11-26 16:29:10.663415700 [wallet::connectivity] DEBUG Attempting base node peer 'a12b205abe9023e621910f0ee9'... (last attempt Some(100ns)) 2024-11-26 16:29:10.663430500 [wallet::connectivity] TRACE Attempt dial with client timeout 1s 2024-11-26 16:29:11.678154700 [wallet::connectivity] WARN Connectivity error: Client cancelled: 'Could not connect to 'a12b205abe9023e621910f0ee9' in 1s' 2024-11-26 16:29:11.678311700 [wallet::connectivity] DEBUG Attempting base node peer '81e258cb5e8419dfdd863282c3'... (last attempt Some(0ns)) 2024-11-26 16:29:11.678338700 [wallet::connectivity] TRACE Attempt dial with client timeout 1s 2024-11-26 16:29:12.695260800 [wallet::connectivity] WARN Connectivity error: Client cancelled: 'Could not connect to '81e258cb5e8419dfdd863282c3' in 1s' 2024-11-26 16:29:12.695391800 [wallet::connectivity] DEBUG Attempting base node peer '6d9043bba0c196ded52a9f79da'... (last attempt Some(100ns)) 2024-11-26 16:29:12.695401300 [wallet::connectivity] TRACE Attempt dial with client timeout 1s 2024-11-26 16:29:13.708776300 [wallet::connectivity] WARN Connectivity error: Client cancelled: 'Could not connect to '6d9043bba0c196ded52a9f79da' in 1s' 2024-11-26 16:29:13.708929300 [wallet::connectivity] DEBUG Attempting base node peer 'fb593780d69882b938429beb69'... (last attempt Some(0ns)) 2024-11-26 16:29:13.708951900 [wallet::connectivity] TRACE Attempt dial with client timeout 1s 2024-11-26 16:29:14.721569600 [wallet::connectivity] WARN Connectivity error: Client cancelled: 'Could not connect to 'fb593780d69882b938429beb69' in 1s' 2024-11-26 16:29:14.721697500 [wallet::connectivity] DEBUG Attempting base node peer 'db5ab85a84ce79bcd2ea700f13'... (last attempt Some(100ns)) 2024-11-26 16:29:14.721708200 [wallet::connectivity] TRACE Attempt dial with client timeout 1s 2024-11-26 16:29:15.734914000 [wallet::connectivity] WARN Connectivity error: Client cancelled: 'Could not connect to 'db5ab85a84ce79bcd2ea700f13' in 1s' 2024-11-26 16:29:15.735066300 [wallet::connectivity] DEBUG Attempting base node peer '6ea597117476676d5ddcb18153'... (last attempt Some(0ns)) 2024-11-26 16:29:15.735099300 [wallet::connectivity] TRACE Attempt dial with client timeout 1s 2024-11-26 16:29:16.740185800 [wallet::connectivity] WARN Connectivity error: Client cancelled: 'Could not connect to '6ea597117476676d5ddcb18153' in 1s' 2024-11-26 16:29:16.740313200 [wallet::connectivity] DEBUG Attempting base node peer '647db13c611aa70dcd9f06a8b1'... (last attempt Some(100ns)) 2024-11-26 16:29:16.740324900 [wallet::connectivity] TRACE Attempt dial with client timeout 1s 2024-11-26 16:29:17.740956000 [wallet::connectivity] WARN Connectivity error: Client cancelled: 'Could not connect to '647db13c611aa70dcd9f06a8b1' in 1s' 2024-11-26 16:29:17.741152500 [wallet::connectivity] DEBUG Attempting base node peer 'a4dbaf87693acaa0fe92f8f4f0'... (last attempt Some(0ns)) 2024-11-26 16:29:17.741166200 [wallet::connectivity] TRACE Attempt dial with client timeout 1s 2024-11-26 16:29:18.744368800 [wallet::connectivity] WARN Connectivity error: Client cancelled: 'Could not connect to 'a4dbaf87693acaa0fe92f8f4f0' in 1s' 2024-11-26 16:29:18.744526000 [wallet::connectivity] DEBUG Attempting base node peer 'e7b0d91465d5386e9d07e53cff'... (last attempt Some(0ns)) 2024-11-26 16:29:18.744538900 [wallet::connectivity] TRACE Attempt dial with client timeout 1s 2024-11-26 16:29:19.745518100 [wallet::connectivity] WARN Connectivity error: Client cancelled: 'Could not connect to 'e7b0d91465d5386e9d07e53cff' in 1s' 2024-11-26 16:29:19.745680000 [wallet::connectivity] DEBUG Attempting base node peer '17bfe6ee47f45491ea9407ad89'... (last attempt Some(0ns)) 2024-11-26 16:29:19.745797100 [wallet::connectivity] TRACE Attempt dial with client timeout 1s 2024-11-26 16:29:20.747956700 [wallet::connectivity] WARN Connectivity error: Client cancelled: 'Could not connect to '17bfe6ee47f45491ea9407ad89' in 1s' 2024-11-26 16:29:20.748180600 [wallet::connectivity] DEBUG Attempting base node peer 'bd11a65bb14f8188e0bde642d0'... (last attempt Some(0ns)) 2024-11-26 16:29:20.748227700 [wallet::connectivity] TRACE Attempt dial with client timeout 1s 2024-11-26 16:29:21.755291100 [wallet::connectivity] WARN Connectivity error: Client cancelled: 'Could not connect to 'bd11a65bb14f8188e0bde642d0' in 1s' 2024-11-26 16:29:21.755439100 [wallet::connectivity] DEBUG Attempting base node peer 'b7c07e293f2186689e88978bff'... (last attempt Some(0ns)) 2024-11-26 16:29:21.755453200 [wallet::connectivity] TRACE Attempt dial with client timeout 10s 2024-11-26 16:29:23.810412000 [wallet::connectivity] WARN Connectivity error: ConnectionFailed: Failed to connect to peer within the maximum number of attempts 2024-11-26 16:29:23.810491600 [wallet::connectivity] DEBUG Attempting base node peer '1c8b393640e1cd7d1a86957eb3'... (last attempt Some(0ns)) 2024-11-26 16:29:23.810501100 [wallet::connectivity] TRACE Attempt dial with client timeout 10s 2024-11-26 16:29:33.811236800 [wallet::connectivity] WARN Connectivity error: Client cancelled: 'Could not connect to '1c8b393640e1cd7d1a86957eb3' in 10s' 2024-11-26 16:29:33.811393800 [wallet::connectivity] DEBUG Attempting base node peer 'e108eb7fbf44d58199908aa928'... (last attempt Some(100ns)) 2024-11-26 16:29:33.811404200 [wallet::connectivity] TRACE Attempt dial with client timeout 10s 2024-11-26 16:29:43.822083900 [wallet::connectivity] WARN Connectivity error: Client cancelled: 'Could not connect to 'e108eb7fbf44d58199908aa928' in 10s' 2024-11-26 16:29:43.822250500 [wallet::connectivity] DEBUG Attempting base node peer '63718f177e749a0484a7050f8d'... (last attempt Some(100ns)) 2024-11-26 16:29:43.822263700 [wallet::connectivity] TRACE Attempt dial with client timeout 10s 2024-11-26 16:29:53.850035700 [wallet::connectivity] WARN Connectivity error: Client cancelled: 'Could not connect to '63718f177e749a0484a7050f8d' in 10s' 2024-11-26 16:29:53.850223800 [wallet::connectivity] DEBUG Attempting base node peer 'b02156f7ec30db5d661dd9b6e2'... (last attempt Some(0ns)) 2024-11-26 16:29:53.850241100 [wallet::connectivity] TRACE Attempt dial with client timeout 10s 2024-11-26 16:29:53.870034300 [wallet::connectivity] WARN Connectivity error: ConnectionFailed: Noise handshake error: An existing connection was forcibly closed by the remote host. (os error 10054) 2024-11-26 16:29:53.870101100 [wallet::connectivity] DEBUG Attempting base node peer 'a04e78a02df887a26ffa9eadaa'... (last attempt Some(100ns)) 2024-11-26 16:29:53.870110100 [wallet::connectivity] TRACE Attempt dial with client timeout 10s 2024-11-26 16:30:00.043621300 [wallet::connectivity] WARN Connectivity error: ConnectionFailed: Failed to connect to peer within the maximum number of attempts 2024-11-26 16:30:00.047536900 [wallet::connectivity] DEBUG Attempting base node peer 'a12b205abe9023e621910f0ee9'... (last attempt Some(100ns)) 2024-11-26 16:30:00.047550400 [wallet::connectivity] TRACE Attempt dial with client timeout 10s 2024-11-26 16:30:10.053350900 [wallet::connectivity] WARN Connectivity error: Client cancelled: 'Could not connect to 'a12b205abe9023e621910f0ee9' in 10s' 2024-11-26 16:30:10.053487900 [wallet::connectivity] DEBUG Attempting base node peer '81e258cb5e8419dfdd863282c3'... (last attempt Some(100ns)) 2024-11-26 16:30:10.053501000 [wallet::connectivity] TRACE Attempt dial with client timeout 10s 2024-11-26 16:30:20.068640100 [wallet::connectivity] WARN Connectivity error: Client cancelled: 'Could not connect to '81e258cb5e8419dfdd863282c3' in 10s' 2024-11-26 16:30:20.068766200 [wallet::connectivity] DEBUG Attempting base node peer '6d9043bba0c196ded52a9f79da'... (last attempt Some(100ns)) 2024-11-26 16:30:20.068777100 [wallet::connectivity] TRACE Attempt dial with client timeout 10s 2024-11-26 16:30:20.068813900 [wallet::connectivity] DEBUG Established peer connection to base node '6d9043bba0c196ded52a9f79da' ``` How Has This Been Tested? --- System-level testing What process can a PR reviewer use to test or verify this change? --- Code review System-level testing Breaking Changes --- - [x] None - [ ] Requires data directory on base node to be deleted - [ ] Requires hard fork - [ ] Other - Please specify --- .../src/connectivity_service/service.rs | 41 +++++++++++++++---- comms/core/src/connectivity/error.rs | 2 + 2 files changed, 36 insertions(+), 7 deletions(-) diff --git a/base_layer/wallet/src/connectivity_service/service.rs b/base_layer/wallet/src/connectivity_service/service.rs index ab5ac039bf..ce097096f8 100644 --- a/base_layer/wallet/src/connectivity_service/service.rs +++ b/base_layer/wallet/src/connectivity_service/service.rs @@ -20,7 +20,12 @@ // WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE // USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. -use std::{collections::HashMap, mem, time::Duration}; +use std::{ + cmp::{max, min}, + collections::HashMap, + mem, + time::Duration, +}; use log::*; use tari_comms::{ @@ -34,7 +39,7 @@ use tari_core::base_node::{rpc::BaseNodeWalletRpcClient, sync::rpc::BaseNodeSync use tokio::{ sync::{mpsc, oneshot, watch}, time, - time::MissedTickBehavior, + time::{timeout, Duration as TokioDuration, MissedTickBehavior}, }; use crate::{ @@ -297,7 +302,10 @@ impl WalletConnectivityService { } else { return; }; + let mut loop_count = 0; + let number_of_seeds = peer_manager.get_state().1.len(); loop { + loop_count += 1; let node_id = if let Some(_time) = peer_manager.time_since_last_connection_attempt() { if peer_manager.get_current_peer().node_id == peer_manager.get_next_peer().node_id { // If we only have one peer in the list, wait a bit before retrying @@ -321,7 +329,10 @@ impl WalletConnectivityService { peer_manager.time_since_last_connection_attempt() ); self.pools.remove(&node_id); - match self.try_setup_rpc_pool(node_id.clone()).await { + match self + .try_setup_rpc_pool(node_id.clone(), loop_count / number_of_seeds + 1) + .await + { Ok(true) => { if self.peer_list_change_detected(&peer_manager) { debug!( @@ -391,13 +402,29 @@ impl WalletConnectivityService { self.online_status_watch.send(status); } - async fn try_setup_rpc_pool(&mut self, peer_node_id: NodeId) -> Result { - let conn = match self.try_dial_peer(peer_node_id.clone()).await? { - Some(c) => c, - None => { + async fn try_setup_rpc_pool( + &mut self, + peer_node_id: NodeId, + dial_cycle: usize, + ) -> Result { + // dial_timeout: 1 = 1s, 2 = 10s, 3 = 20s, 4 = 30s, 5 = 40s, 6 = 50s, 7 = 60s, 8 = 70s, 9 = 80s, 10 = 90s + let dial_timeout = TokioDuration::from_secs(min((max(1, 10 * (dial_cycle.saturating_sub(1)))) as u64, 90)); + trace!(target: LOG_TARGET, "Attempt dial with client timeout {:?}", dial_timeout); + let conn = match timeout(dial_timeout, self.try_dial_peer(peer_node_id.clone())).await { + Ok(Ok(Some(c))) => c, + Ok(Ok(None)) => { warn!(target: LOG_TARGET, "Could not dial base node peer '{}'", peer_node_id); return Ok(false); }, + Ok(Err(e)) => return Err(e), + Err(_) => { + return Err(WalletConnectivityError::ConnectivityError( + ConnectivityError::ClientCancelled(format!( + "Could not connect to '{}' in {:?}", + peer_node_id, dial_timeout + )), + )); + }, }; debug!( target: LOG_TARGET, diff --git a/comms/core/src/connectivity/error.rs b/comms/core/src/connectivity/error.rs index acb554ac79..5dbfe2849d 100644 --- a/comms/core/src/connectivity/error.rs +++ b/comms/core/src/connectivity/error.rs @@ -43,6 +43,8 @@ pub enum ConnectivityError { OnlineWaitTimeout(usize), #[error("Pending dial was cancelled")] DialCancelled, + #[error("Client cancelled: '{0}'")] + ClientCancelled(String), } impl From for ConnectivityError {