From fcf971979a7c0201278939274ea3a7675b8af7e4 Mon Sep 17 00:00:00 2001 From: julian Date: Sun, 28 Jan 2024 22:29:07 -0600 Subject: [PATCH] Fix rpc timeout issue and improved logging --- lib/electrumx_rpc/rpc.dart | 107 +++++++++++------- lib/wallets/wallet/wallet.dart | 5 + .../electrumx_interface.dart | 6 +- test/electrumx_test.mocks.dart | 20 ++-- 4 files changed, 83 insertions(+), 55 deletions(-) diff --git a/lib/electrumx_rpc/rpc.dart b/lib/electrumx_rpc/rpc.dart index 513a3d54c..89c1735c2 100644 --- a/lib/electrumx_rpc/rpc.dart +++ b/lib/electrumx_rpc/rpc.dart @@ -80,18 +80,32 @@ class JsonRPC { void _sendNextAvailableRequest() { _requestQueue.nextIncompleteReq.then((req) { if (req != null) { - // \r\n required by electrumx server - if (_socket != null) { + if (!Prefs.instance.useTor) { + if (_socket == null) { + Logging.instance.log( + "JsonRPC _sendNextAvailableRequest attempted with" + " _socket=null on $host:$port", + level: LogLevel.Error, + ); + } + // \r\n required by electrumx server _socket!.write('${req.jsonRequest}\r\n'); - } - if (_socksSocket != null) { - _socksSocket!.write('${req.jsonRequest}\r\n'); + } else { + if (_socksSocket == null) { + Logging.instance.log( + "JsonRPC _sendNextAvailableRequest attempted with" + " _socksSocket=null on $host:$port", + level: LogLevel.Error, + ); + } + // \r\n required by electrumx server + _socksSocket?.write('${req.jsonRequest}\r\n'); } // TODO different timeout length? req.initiateTimeout( onTimedOut: () { - _requestQueue.remove(req); + _onReqCompleted(req); }, ); } @@ -109,7 +123,7 @@ class JsonRPC { "JsonRPC request: opening socket $host:$port", level: LogLevel.Info, ); - await connect().timeout(requestTimeout, onTimeout: () { + await _connect().timeout(requestTimeout, onTimeout: () { throw Exception("Request timeout: $jsonRpcRequest"); }); } @@ -119,7 +133,7 @@ class JsonRPC { "JsonRPC request: opening SOCKS socket to $host:$port", level: LogLevel.Info, ); - await connect().timeout(requestTimeout, onTimeout: () { + await _connect().timeout(requestTimeout, onTimeout: () { throw Exception("Request timeout: $jsonRpcRequest"); }); } @@ -156,23 +170,42 @@ class JsonRPC { return future; } - Future disconnect({required String reason}) async { - await _requestMutex.protect(() async { - await _subscription?.cancel(); - _subscription = null; - _socket?.destroy(); - _socket = null; - await _socksSocket?.close(); - _socksSocket = null; - - // clean up remaining queue - await _requestQueue.completeRemainingWithError( - "JsonRPC disconnect() called with reason: \"$reason\"", - ); - }); + /// DO NOT set [ignoreMutex] to true unless fully aware of the consequences + Future disconnect({ + required String reason, + bool ignoreMutex = false, + }) async { + if (ignoreMutex) { + await _disconnectHelper(reason: reason); + } else { + await _requestMutex.protect(() async { + await _disconnectHelper(reason: reason); + }); + } } - Future connect() async { + Future _disconnectHelper({required String reason}) async { + await _subscription?.cancel(); + _subscription = null; + _socket?.destroy(); + _socket = null; + await _socksSocket?.close(); + _socksSocket = null; + + // clean up remaining queue + await _requestQueue.completeRemainingWithError( + "JsonRPC disconnect() called with reason: \"$reason\"", + ); + } + + Future _connect() async { + // ignore mutex is set to true here as _connect is already called within + // the mutex.protect block. Setting to false here leads to a deadlock + await disconnect( + reason: "New connection requested", + ignoreMutex: true, + ); + if (!Prefs.instance.useTor) { if (useSSL) { _socket = await SecureSocket.connect( @@ -352,17 +385,20 @@ class _JsonRPCRequest { } void initiateTimeout({ - VoidCallback? onTimedOut, + required VoidCallback onTimedOut, }) { Future.delayed(requestTimeout).then((_) { if (!isComplete) { - try { - throw JsonRpcException("_JsonRPCRequest timed out: $jsonRequest"); - } catch (e, s) { - completer.completeError(e, s); - onTimedOut?.call(); - } + completer.complete( + JsonRPCResponse( + data: null, + exception: JsonRpcException( + "_JsonRPCRequest timed out: $jsonRequest", + ), + ), + ); } + onTimedOut.call(); }); } @@ -375,14 +411,3 @@ class JsonRPCResponse { JsonRPCResponse({this.data, this.exception}); } - -bool isIpAddress(String host) { - try { - // if the string can be parsed into an InternetAddress, it's an IP. - InternetAddress(host); - return true; - } catch (e) { - // if parsing fails, it's not an IP. - return false; - } -} diff --git a/lib/wallets/wallet/wallet.dart b/lib/wallets/wallet/wallet.dart index 796760dbd..fe26a508f 100644 --- a/lib/wallets/wallet/wallet.dart +++ b/lib/wallets/wallet/wallet.dart @@ -482,6 +482,11 @@ abstract class Wallet { ), ); + // add some small buffer before making calls. + // this can probably be removed in the future but was added as a + // debugging feature + await Future.delayed(const Duration(milliseconds: 300)); + // TODO: [prio=low] handle this differently. Extra modification of this file for coin specific functionality should be avoided. final Set codesToCheck = {}; if (this is PaynymInterface) { diff --git a/lib/wallets/wallet/wallet_mixin_interfaces/electrumx_interface.dart b/lib/wallets/wallet/wallet_mixin_interfaces/electrumx_interface.dart index 1f425d498..0b74f4ed6 100644 --- a/lib/wallets/wallet/wallet_mixin_interfaces/electrumx_interface.dart +++ b/lib/wallets/wallet/wallet_mixin_interfaces/electrumx_interface.dart @@ -1702,7 +1702,7 @@ mixin ElectrumXInterface on Bip39HDWallet { try { final features = await electrumXClient .getServerFeatures() - .timeout(const Duration(seconds: 4)); + .timeout(const Duration(seconds: 5)); Logging.instance.log("features: $features", level: LogLevel.Info); @@ -1715,8 +1715,8 @@ mixin ElectrumXInterface on Bip39HDWallet { } catch (e, s) { // do nothing, still allow user into wallet Logging.instance.log( - "$runtimeType init() failed: $e\n$s", - level: LogLevel.Error, + "$runtimeType init() did not complete: $e\n$s", + level: LogLevel.Warning, ); } diff --git a/test/electrumx_test.mocks.dart b/test/electrumx_test.mocks.dart index 06e3082c0..aaf3e0810 100644 --- a/test/electrumx_test.mocks.dart +++ b/test/electrumx_test.mocks.dart @@ -140,20 +140,18 @@ class MockJsonRPC extends _i1.Mock implements _i2.JsonRPC { )), ) as _i5.Future<_i2.JsonRPCResponse>); @override - _i5.Future disconnect({required String? reason}) => (super.noSuchMethod( + _i5.Future disconnect({ + required String? reason, + bool? ignoreMutex = false, + }) => + (super.noSuchMethod( Invocation.method( #disconnect, [], - {#reason: reason}, - ), - returnValue: _i5.Future.value(), - returnValueForMissingStub: _i5.Future.value(), - ) as _i5.Future); - @override - _i5.Future connect() => (super.noSuchMethod( - Invocation.method( - #connect, - [], + { + #reason: reason, + #ignoreMutex: ignoreMutex, + }, ), returnValue: _i5.Future.value(), returnValueForMissingStub: _i5.Future.value(),