Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

feat: improve wallet connectivity status for console wallet #3577

Conversation

hansieodendaal
Copy link
Contributor

@hansieodendaal hansieodendaal commented Nov 16, 2021

Description

  • Improved base node connection status feedback to the console wallet UI.
  • Added disconnect logic for the wallet connectivity service to enable closing bad base node connections if RPC connections cannot be obtained, which will force the connection cycle to restart from scratch, rather than just waiting for the connection to become alive again.
  • Disabled obtaining latency information after obtaining tip information in the wallet's base node monitor, as it sometimes introduces huge additional delays.
    Note: Fixing this behaviour is marked for another PR. (Fixed in PR fix: remove delay from last request latency call #3579)

Motivation and Context

  • Connectivity status was not always current in the console wallet under certain edge cases, observed when switching base nodes.
  • Retrying to obtain an RPC connection from a bad base node connection is not efficient; this sometimes results in the base node staying offline for extended (> 30 minutes) durations.

How Has This Been Tested?

  • System-level testing:
    • Switching base nodes and observing the connection status while (a) mining and (b) monitoring transactions to be mined.
    • Stress testing make-it-rain.
    • Stress testing coin-split.
    • Stress testing simaltaneous make-it-rain and coin-split.

See sample profiling measurements below depicting the added delay sometimes introduced by obtaining latency information, without the fix mentioned above:

2021-11-16 14:18:07.490078500 [wallet::base_node_service::chain_metadata_monitor] TRACE Obtain RPC client 160 ms
2021-11-16 14:18:08.062610200 [wallet::base_node_service::chain_metadata_monitor] TRACE Obtain tip info in 572 ms
2021-11-16 14:18:08.062646600 [wallet::base_node_service::chain_metadata_monitor] TRACE Obtain latency info in 0 ms
2021-11-16 14:18:08.062944600 [wallet::base_node_service::chain_metadata_monitor] DEBUG Base node ece4c616a156c1e4fe34d94d8c Tip: 52127 (Synced) Latency: 572 ms
2021-11-16 14:18:37.491546100 [wallet::base_node_service::chain_metadata_monitor] TRACE Obtain RPC client 0 ms
2021-11-16 14:20:28.971178900 [wallet::base_node_service::chain_metadata_monitor] TRACE Obtain tip info in 111479 ms
2021-11-16 14:25:07.794774200 [wallet::base_node_service::chain_metadata_monitor] TRACE Obtain latency info in 278823 ms
2021-11-16 14:25:07.795167000 [wallet::base_node_service::chain_metadata_monitor] DEBUG Base node ece4c616a156c1e4fe34d94d8c Tip: 52127 (Synced) Latency: 11011 ms
2021-11-16 14:25:26.789903600 [wallet::base_node_service::chain_metadata_monitor] TRACE Obtain RPC client 0 ms
2021-11-16 14:30:35.914526200 [wallet::base_node_service::chain_metadata_monitor] TRACE Obtain tip info in 309124 ms
2021-11-16 14:34:04.569556900 [wallet::base_node_service::chain_metadata_monitor] TRACE Obtain latency info in 208654 ms
2021-11-16 14:34:04.569945400 [wallet::base_node_service::chain_metadata_monitor] DEBUG Base node ece4c616a156c1e4fe34d94d8c Tip: 52130 (Synced) Latency: 9699 ms
2021-11-16 14:34:24.885048300 [wallet::base_node_service::chain_metadata_monitor] TRACE Obtain RPC client 0 ms
2021-11-16 14:34:44.260586300 [wallet::base_node_service::chain_metadata_monitor] TRACE Obtain tip info in 19375 ms
2021-11-16 14:34:44.260734900 [wallet::base_node_service::chain_metadata_monitor] TRACE Obtain latency info in 0 ms
2021-11-16 14:34:44.261005000 [wallet::base_node_service::chain_metadata_monitor] DEBUG Base node ece4c616a156c1e4fe34d94d8c Tip: 52133 (Synced) Latency: 10712 ms
2021-11-16 14:35:03.552244200 [wallet::base_node_service::chain_metadata_monitor] TRACE Obtain RPC client 0 ms
2021-11-16 14:35:22.417825800 [wallet::base_node_service::chain_metadata_monitor] TRACE Obtain tip info in 18865 ms
2021-11-16 14:35:22.417869200 [wallet::base_node_service::chain_metadata_monitor] TRACE Obtain latency info in 0 ms
2021-11-16 14:35:22.418075300 [wallet::base_node_service::chain_metadata_monitor] DEBUG Base node ece4c616a156c1e4fe34d94d8c Tip: 52134 (Synced) Latency: 18865 ms

@sdbondi
Copy link
Member

sdbondi commented Nov 16, 2021

Good catch, I'm now convinced that for the wallet this is the correct method and shouldn't change to use get_last_request_latency

I fixed an issue in a previous PR where it would use the time for the entire stream to finish rather than just the first response. Looking deeper, measuring last_request latency is further complicated by the chunking of responses. So I would say that you can remove the commented out code and stick with this approach. As you say in a busy system, an async call to the RPC client backend is not necessary when you can just measure it directly.

@sdbondi
Copy link
Member

sdbondi commented Nov 16, 2021

The delays experienced by calling get_last_request_latency alone are because of the fact that we use a shared client pool and so there is a higher probability that the client will be tied up with other requests on a busy system - by design a single client runs on a single task and so can only handle one service request at a time.

@sdbondi
Copy link
Member

sdbondi commented Nov 16, 2021

Fixed in PR #3579, I used a watch instead of a service call for get_last_request_latency to allow it to be called and returned without waiting even when a client is busy.

@hansieodendaal
Copy link
Contributor Author

Fixed in PR #3579, I used a watch instead of a service call for get_last_request_latency to allow it to be called and returned without waiting even when a client is busy.

Reviewed that one, thanks @sdbondi. Removing the commented out code for the next commit and will run another stress test to verify.

@@ -185,6 +193,9 @@ impl WalletConnectivityService {
target: LOG_TARGET,
"Base node connection failed: {}. Reconnecting...", e
);
if let Some(node_id) = self.current_base_node() {
self.disconnect_base_node(node_id).await;
Copy link
Member

@sdbondi sdbondi Nov 17, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

btw disconnecting a base can happens automatically after a period of time (unless the base node happens to be a neighbour/randomly selected) if no one is holding the PeerConnection handle. Not sure if there was a particular reason to disconnect, but you can probably let comms handle that for you. Disconnecting the peer may interrupt other services e.g. dht sync

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Understood. As commented in the PR description, the reason for this is to not have to restart the wallet if for some reason we have a bad connection to start with. The disconnect_base_node statements have been selectively inserted only when a bad connection is detected from the client's side. In all the tests I have done for the console wallet, disconnecting a bad base node connection definitely improves communication all around, even in the middle of a stress test, as all dependent protocols are self rectifying.

The log extract below shows such a bad connection where eventually the console wallet had to be restarted after 1.5 hours - for this, the connected base node stayed online and was not restarted and communicated perfectly with other nodes.

2021-11-16 08:56:02.799226800 [wallet::connectivity] DEBUG Attempting to connect to base node peer ece4c616a156c1e4fe34d94d8c...
2021-11-16 08:57:22.523497500 [wallet::connectivity] DEBUG Successfully established peer connection to base node ece4c616a156c1e4fe34d94d8c
2021-11-16 08:57:36.891108100 [wallet::connectivity] DEBUG Successfully established RPC connection ece4c616a156c1e4fe34d94d8c
2021-11-16 08:57:36.891124100 [wallet::connectivity] DEBUG Wallet is ONLINE and connected to base node ece4c616a156c1e4fe34d94d8c
2021-11-16 09:00:13.084042000 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 09:01:43.096424800 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 09:03:13.101571800 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 09:04:43.111513700 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 09:06:13.120089200 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 09:07:43.124323400 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 09:09:13.129675900 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 09:10:43.133135700 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 09:12:13.144324100 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 09:13:43.154570400 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 09:15:13.169172200 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 09:16:43.181434500 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 09:18:13.182299500 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 09:21:51.244670000 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 09:23:21.250904200 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 09:24:51.263524700 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 09:26:21.268379800 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 09:27:51.279295000 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 09:29:21.283854200 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 09:30:51.299524200 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 09:32:21.309984300 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 09:33:51.320823900 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 09:35:21.325223200 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 09:36:51.330991400 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 09:38:21.347124100 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 09:39:51.359091600 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 09:41:21.368998600 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 09:42:51.381214200 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 09:44:21.385566300 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 09:45:51.386209300 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 09:47:21.387524000 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 09:48:51.397354900 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 09:50:21.411220200 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 09:51:51.414259600 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 09:53:21.420962400 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 09:54:51.434485500 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 09:56:21.449505500 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 09:57:51.456611100 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 09:59:21.464595700 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 10:00:51.473677500 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 10:02:21.477033700 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 10:03:51.478407900 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 10:05:21.488478100 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 10:06:51.490239500 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 10:08:21.500649700 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 10:09:51.512070400 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 10:11:21.514823900 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 10:12:51.521282700 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 10:14:21.528710300 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 10:15:51.543031900 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 10:17:21.554784400 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 10:18:51.559731900 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 10:20:21.565718000 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 10:21:51.574891500 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 10:23:21.587307500 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 10:24:51.603359900 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...
2021-11-16 10:26:21.609144200 [wallet::connectivity] WARN  Base node connection failed: Failed to create client connection: Handshake error: RPC handshake timed out. Reconnecting...

2021-11-16 11:26:56.432504900 [wallet::connectivity] DEBUG Wallet connectivity service has started.
2021-11-16 11:26:56.432718400 [wallet::connectivity] WARN  1 requests are waiting for base node to be set
2021-11-16 11:26:56.457973900 [wallet::connectivity] DEBUG Attempting to connect to base node peer ece4c616a156c1e4fe34d94d8c...
2021-11-16 11:27:00.660710200 [wallet::connectivity] DEBUG Successfully established peer connection to base node ece4c616a156c1e4fe34d94d8c
2021-11-16 11:27:01.872023300 [wallet::connectivity] DEBUG Successfully established RPC connection ece4c616a156c1e4fe34d94d8c
2021-11-16 11:27:01.872042000 [wallet::connectivity] DEBUG Wallet is ONLINE and connected to base node ece4c616a156c1e4fe34d94d8c

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ok understood, give a good clue, maybe something we need to do to keep the connection alive - thought occurs that this happens in the base node with ping/pong but not on the console wallet which may be the cause.

- Improved status feedback to the console wallet UI
- Added disconnect logic for the wallet connectivity service to enable
closing bad base node connections if RPC connections cannot be obtained.
@hansieodendaal hansieodendaal force-pushed the ho_wallet_connectivity_status branch from fc78449 to 89d0987 Compare November 17, 2021 10:27
@hansieodendaal
Copy link
Contributor Author

Fixed in PR #3579, I used a watch instead of a service call for get_last_request_latency to allow it to be called and returned without waiting even when a client is busy.

Reviewed that one, thanks @sdbondi. Removing the commented out code for the next commit and will run another stress test to verify.

Confirmed with system-level stress testing that PR #3579 fixes the latency issue.

@@ -185,6 +193,9 @@ impl WalletConnectivityService {
target: LOG_TARGET,
"Base node connection failed: {}. Reconnecting...", e
);
if let Some(node_id) = self.current_base_node() {
self.disconnect_base_node(node_id).await;
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ok understood, give a good clue, maybe something we need to do to keep the connection alive - thought occurs that this happens in the base node with ping/pong but not on the console wallet which may be the cause.

@aviator-app aviator-app bot added mq-failed and removed mq-failed labels Nov 17, 2021
@aviator-app aviator-app bot merged commit e191e27 into tari-project:development Nov 17, 2021
sdbondi added a commit to sdbondi/tari that referenced this pull request Nov 17, 2021
* development:
  feat: improve wallet connectivity status for console wallet (tari-project#3577)
  v0.21.1
  feat: add error codes to LibWallet for CipherSeed errors (tari-project#3578)
  ci: split cucumber job into two (tari-project#3583)
  feat(wallet): import utxo’s as EncumberedToBeReceived rather than Unspent (tari-project#3575)
  docs: rfc 0250_Covenants (tari-project#3574)
@hansieodendaal hansieodendaal deleted the ho_wallet_connectivity_status branch November 17, 2021 14:18
sdbondi added a commit to sdbondi/tari that referenced this pull request Nov 18, 2021
* development: (32 commits)
  feat: add atomic swap refund transaction handling (tari-project#3573)
  feat: improve wallet connectivity status for console wallet (tari-project#3577)
  v0.21.1
  feat: add error codes to LibWallet for CipherSeed errors (tari-project#3578)
  ci: split cucumber job into two (tari-project#3583)
  feat(wallet): import utxo’s as EncumberedToBeReceived rather than Unspent (tari-project#3575)
  docs: rfc 0250_Covenants (tari-project#3574)
  feat: get fee for transactions for stratum transcoder (tari-project#3571)
  test: make monerod stagenet usage resilient (tari-project#3572)
  feat: add atomic swap htlc sending and claiming (tari-project#3552)
  feat: implement prometheus metrics for base node (tari-project#3563)
  feat: implement multiple read single write for sqlite (tari-project#3568)
  feat: trigger time lock balance update when block received (tari-project#3567)
  test: reduce cucumber ci to critical only (tari-project#3566)
  test: fix cucumber console wallet startup (tari-project#3564)
  chore: add node id/public key to log mdc (tari-project#3559)
  fix: avoid implicit using of the time crate (tari-project#3562)
  feat: one-click installer - cli edition (tari-project#3534)
  ci: add workflow dispatch to libwallet build action (tari-project#3556)
  fix: stop leak of value of recovered output (tari-project#3558)
  ...
stringhandler added a commit that referenced this pull request Nov 19, 2021
Description
---

- Allows the last_request_latency to be instantly queried even when a client is busy with another request.

Motivation and Context
---
Ref #3577

A delay could be experienced when calling get_last_request_latency because a single client runs on a single task and so can only handle one service request at a time.

How Has This Been Tested?
---
Added unit test
sdbondi added a commit to sdbondi/tari that referenced this pull request Nov 23, 2021
* development: (46 commits)
  refactor: remove tari_common dependency from tari_comms (tari-project#3580)
  feat: language detection for mnemonic seed words (tari-project#3590)
  chore: minor clippy fixes (tari-project#3576)
  fix: be more permissive of responses for the incorrect request_id (tari-project#3588)
  feat: track ping failures and disconnect (tari-project#3597)
  chore: upgrade tokio deps tari-project#3581 (tari-project#3595)
  feat: standardize output hash for unblinded output, transaction output and transaction input (tari-project#3592)
  fix: allow bullet proof value only rewinding off one-sided transaction (tari-project#3587)
  refactor: update miningcore repository links (tari-project#3593)
  refactor: clean up unwraps in wallet_ffi (tari-project#3585)
  fix: update daily test start times and seed phrase (tari-project#3584)
  fix: allow bullet proof value only rewinding in atomic swaps (tari-project#3586)
  v0.21.2
  feat: add atomic swap refund transaction handling (tari-project#3573)
  feat: improve wallet connectivity status for console wallet (tari-project#3577)
  v0.21.1
  feat: add error codes to LibWallet for CipherSeed errors (tari-project#3578)
  ci: split cucumber job into two (tari-project#3583)
  feat(wallet): import utxo’s as EncumberedToBeReceived rather than Unspent (tari-project#3575)
  docs: rfc 0250_Covenants (tari-project#3574)
  ...
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants