search

tari-project / tari

The Tari protocol
https://tari.com
BSD 3-Clause "New" or "Revised" License
354 stars 219 forks source link

Fix: Peer ID confused in wallet connection service for RPC #6677

Open hansieodendaal opened 2 weeks ago

hansieodendaal commented 2 weeks ago

These logs were obtained from a receiver wallet during an interactive transaction stress test. To reproduce, run a stress test and monitor the receiving wallet.

The wallet in question only had a single base node peer to connect to, but somehow the peer ID returned form the bae node got swapped out/confused

  305971: 2024-11-07 15:46:43.552096400 [wallet::connectivity] TRACE start: check_connection.tick
  305972: 2024-11-07 15:46:43.552175500 [wallet::connectivity] TRACE check_connection: has current_base_node
  305973: 2024-11-07 15:46:43.552301800 [wallet::connectivity] TRACE check_connection: has connection with ID 22
  305974: 2024-11-07 15:46:43.552328900 [wallet::connectivity] TRACE check_connection: has rpc pool, already connected
  305978: 2024-11-07 15:46:46.071556600 [wallet::connectivity] DEBUG Obtained pool RPC 'wallet' connection to base node '12D3L7AVC3KnrNWkKic75qhXbXro8n5RB39c7wXLf1Efy57hQP7n'
  305988: 2024-11-07 15:46:46.073818900 [wallet::connectivity] DEBUG Obtained pool RPC 'wallet' connection to base node '12D3L7AVC3KnrNWkKic75qhXbXro8n5RB39c7wXLf1Efy57hQP7n'
  305999: 2024-11-07 15:46:46.077380300 [wallet::connectivity] DEBUG Obtained pool RPC 'wallet' connection to base node '12D3L7AVC3KnrNWkKic75qhXbXro8n5RB39c7wXLf1Efy57hQP7n'
  306005: 2024-11-07 15:46:46.079743100 [wallet::connectivity] DEBUG Obtained pool RPC 'wallet' connection to base node '12D3L7AVC3KnrNWkKic75qhXbXro8n5RB39c7wXLf1Efy57hQP7n'
  306006: 2024-11-07 15:46:46.079810600 [wallet::connectivity] DEBUG Obtained pool RPC 'wallet' connection to base node '12D3L7AVC3KnrNWkKic75qhXbXro8n5RB39c7wXLf1Efy57hQP7n'
  306010: 2024-11-07 15:46:46.081595300 [wallet::connectivity] DEBUG Obtained pool RPC 'wallet' connection to base node '12D3L7AVC3KnrNWkKic75qhXbXro8n5RB39c7wXLf1Efy57hQP7n'
  308618: 2024-11-07 15:46:48.562916400 [wallet::connectivity] TRACE start: check_connection.tick
  308619: 2024-11-07 15:46:48.562935600 [wallet::connectivity] TRACE check_connection: has current_base_node
  308620: 2024-11-07 15:46:48.562987900 [wallet::connectivity] TRACE check_connection: has connection with ID 22
  308621: 2024-11-07 15:46:48.563008800 [wallet::connectivity] TRACE check_connection: has rpc pool, already connected
  312306: 2024-11-07 15:46:58.779502100 [wallet::connectivity] DEBUG Obtained pool RPC 'wallet' connection to base node '12D3L7AVC3KnrNWkKic75qhXbXro8n5RB39c7wXLf1Efy57hQP7n'
  313642: 2024-11-07 15:47:11.798762800 [wallet::connectivity] WARN  Base node '12D3L7AVC3KnrNWkKic75qhXbXro8n5RB39c7wXLf1Efy57hQP7n' pool RPC 'wallet' connection failed (Failed to create client connection: Failed to open substream: Protocol negotiation timeout). Reconnecting...
  313643: 2024-11-07 15:47:11.798785800 [wallet::connectivity] TRACE Disconnecting base node '12D3L7AVC3KnrNWkKic75qhXbXro8n5RB39c7wXLf1Efy57hQP7n'...
  314297: 2024-11-07 15:47:11.883861400 [wallet::connectivity] WARN  Wallet RPC pool for base node `12D3L7AVC3KnrNWkKic75qhXbXro8n5RB39c7wXLf1Efy57hQP7n` not found, 2 requests waiting
  314299: 2024-11-07 15:47:11.883970000 [wallet::connectivity] WARN  Wallet RPC pool for base node `12D3L7AVC3KnrNWkKic75qhXbXro8n5RB39c7wXLf1Efy57hQP7n` not found, 3 requests waiting
  314300: 2024-11-07 15:47:11.883996000 [wallet::connectivity] WARN  Wallet RPC pool for base node `12D3L7AVC3KnrNWkKic75qhXbXro8n5RB39c7wXLf1Efy57hQP7n` not found, 4 requests waiting
  314301: 2024-11-07 15:47:11.884008600 [wallet::connectivity] WARN  Wallet RPC pool for base node `12D3L7AVC3KnrNWkKic75qhXbXro8n5RB39c7wXLf1Efy57hQP7n` not found, 5 requests waiting
  314302: 2024-11-07 15:47:11.884018800 [wallet::connectivity] WARN  Wallet RPC pool for base node `12D3L7AVC3KnrNWkKic75qhXbXro8n5RB39c7wXLf1Efy57hQP7n` not found, 6 requests waiting
  314303: 2024-11-07 15:47:11.884029000 [wallet::connectivity] TRACE start: check_connection.tick
  314304: 2024-11-07 15:47:11.884036100 [wallet::connectivity] TRACE check_connection: has current_base_node
  314305: 2024-11-07 15:47:11.884073800 [wallet::connectivity] TRACE check_connection: current base node has no connection, setup connection to: 'BaseNodePeerManager { current index: 0, peer list: 1 entries }'
  314778: 2024-11-07 15:47:18.439554500 [wallet::connectivity] WARN  Dial failed: An error occurred while negotiating the transport protocol(s) on a connection. /ip4/172.28.0.1/udp/62091/quic-v1/p2p/12D3L7AVC3KnrNWkKic75qhXbXro8n5RB39c7wXLf1Efy57hQP7n: Handshake with the remote timed out./ip4/172.17.192.1/udp/62091/quic-v1/p2p/12D3L7AVC3KnrNWkKic75qhXbXro8n5RB39c7wXLf1Efy57hQP7n: Handshake with the remote timed out./ip4/172.25.16.1/udp/62091/quic-v1/p2p/12D3L7AVC3KnrNWkKic75qhXbXro8n5RB39c7wXLf1Efy57hQP7n: Handshake with the remote timed out./ip4/172.29.128.1/udp/62091/quic-v1/p2p/12D3L7AVC3KnrNWkKic75qhXbXro8n5RB39c7wXLf1Efy57hQP7n: Handshake with the remote timed out./ip4/172.28.96.1/udp/62091/quic-v1/p2p/12D3L7AVC3KnrNWkKic75qhXbXro8n5RB39c7wXLf1Efy57hQP7n: Handshake with the remote timed out./ip4/127.0.0.1/udp/62091/quic-v1/p2p/12D3L7AVC3KnrNWkKic75qhXbXro8n5RB39c7wXLf1Efy57hQP7n: Handshake with the remote timed out./ip4/192.168.5.114/udp/62091/quic-v1/p2p/12D3L7AVC3KnrNWkKic75qhXbXro8n5RB39c7wXLf1Efy57hQP7n: Handshake wi
  314779: 2024-11-07 15:47:18.439596600 [wallet::connectivity] TRACE Disconnecting base node '12D3L7AVC3KnrNWkKic75qhXbXro8n5RB39c7wXLf1Efy57hQP7n'...
  315726: 2024-11-07 15:47:25.065636600 [wallet::connectivity] DEBUG Only single peer in base node peer list. Waiting 5s before retrying again ...
  317305: 2024-11-07 15:47:38.406565600 [wallet::connectivity] WARN  Dial failed: The peer ID obtained (12D3L7AUxLaCZj6gcehAG2Asx1RcUQhA4257RVLaUgBMNweojpEN) on the connection did not match the one that was expected. This is usually because a different peer is listening on the provided address.
  317306: 2024-11-07 15:47:38.406581300 [wallet::connectivity] TRACE Disconnecting base node '12D3L7AVC3KnrNWkKic75qhXbXro8n5RB39c7wXLf1Efy57hQP7n'...
  317307: 2024-11-07 15:47:38.407135600 [wallet::connectivity] DEBUG Only single peer in base node peer list. Waiting 5s before retrying again ...
  323259: 2024-11-07 15:47:43.420142600 [wallet::connectivity] WARN  Dial failed: The peer ID obtained (12D3L7AUxLaCZj6gcehAG2Asx1RcUQhA4257RVLaUgBMNweojpEN) on the connection did not match the one that was expected. This is usually because a different peer is listening on the provided address.
  323260: 2024-11-07 15:47:43.420203400 [wallet::connectivity] TRACE Disconnecting base node '12D3L7AVC3KnrNWkKic75qhXbXro8n5RB39c7wXLf1Efy57hQP7n'...