search

sparrowwallet / sparrow

Desktop Bitcoin Wallet focused on security and privacy. Free and open source.
https://sparrowwallet.com/
Apache License 2.0
1.32k stars 188 forks source link

[Bug] Sparrow server doesn't re-connect to fulcrum #899

Closed RequestPrivacy closed 1 year ago

RequestPrivacy commented 1 year ago

Problem description

I run sparrow server 1.7.2 on a pi connected to a fulcrum instance. Somehow my fulcrum seems to have problems maintaining its connection to the bitcoind running on the same pi. I opened an issue at the fulcrum github.

The point for THIS issue is that Sparrow doesn't re-connect to the fulcrum once the indexer seems to recover its connection to bitcoind.

Following shows the logs of fulcrum, note the time in the timestamps:

# fulcrum working
Mar 15 16:10:59 debian Fulcrum[1554690]: [2023-03-15 16:10:59.882] <Controller> 18468 mempool txs involving 208255 addresses
Mar 15 16:11:59 debian Fulcrum[1554690]: [2023-03-15 16:11:59.883] <Controller> 18727 mempool txs involving 209259 addresses
Mar 15 16:13:00 debian Fulcrum[1554690]: [2023-03-15 16:12:59.959] <Controller> 18926 mempool txs involving 209990 addresses

# fulcrum loosing the connection to bitcoind
Mar 15 16:13:21 debian Fulcrum[1554690]: [2023-03-15 16:13:20.948] <BitcoinD.1> Lost connection to bitcoind, will retry every 5 seconds ...
Mar 15 16:13:21 debian Fulcrum[1554690]: [2023-03-15 16:13:20.948] <Task.GetChainInfo> 413045: FAIL: bitcoind connection lost
Mar 15 16:13:21 debian Fulcrum[1554690]: [2023-03-15 16:13:21.087] <Controller> Failed to synch blocks and/or mempool

# regaining connection
Mar 15 16:13:28 debian Fulcrum[1554690]: [2023-03-15 16:13:27.464] <Controller> Block height 780927, downloading new blocks ...
Mar 15 16:13:31 debian Fulcrum[1554690]: [2023-03-15 16:13:31.139] <Controller> Processed 1 new block with 3344 txs (6646 inputs, 9964 outputs, 13459 addresses), verified ok.
Mar 15 16:13:31 debian Fulcrum[1554690]: [2023-03-15 16:13:31.666] <Controller> Block height 780927, up-to-date

# that's sparrow server re-connecting automatically to fulcrum like a charm
Mar 15 16:13:33 debian Fulcrum[1554690]: [2023-03-15 16:13:33.098] <TcpSrv 127.0.0.1:port> New TCP Client.413217 127.0.0.1:port, 1 client total
Mar 15 16:31:26 debian Fulcrum[1554690]: [2023-03-15 16:14:11.475] <Controller> 15814 mempool txs involving 198202 addresses

# fulcrum having issues again
Mar 15 16:31:26 debian Fulcrum[1554690]: [2023-03-15 16:14:21.303] <BitcoinD.1> Lost connection to bitcoind, will retry every 5 seconds ...
Mar 15 16:31:26 debian Fulcrum[1554690]: [2023-03-15 16:14:21.356] <BitcoinD.3> Lost connection to bitcoind, will retry every 5 seconds ...
Mar 15 16:31:26 debian Fulcrum[1554690]: [2023-03-15 16:14:22.120] <BitcoinD.2> Lost connection to bitcoind, will retry every 5 seconds ...
Mar 15 16:31:26 debian Fulcrum[1554690]: [2023-03-15 16:15:33.747] <BitcoinD.1> Lost connection to bitcoind, will retry every 5 seconds ...
Mar 15 16:31:26 debian Fulcrum[1554690]: [2023-03-15 16:15:35.230] <SynchMempool> 413418: FAIL: Unable to find a good BitcoinD connection
Mar 15 16:31:26 debian Fulcrum[1554690]: [2023-03-15 16:15:32.332] <Controller> Waiting for bitcoind...
# ...
# ...
# ...

# sparrow server connection timeout
Mar 15 16:31:26 debian Fulcrum[1554690]: [2023-03-15 16:15:55.878] <TcpSrv 127.0.0.1:port> Client.413217 BatchProcessor.413414 (100): timed out after not receiving a batch response for 20 seconds.

Mar 15 16:31:26 debian Fulcrum[1554690]: [2023-03-15 16:15:57.989] <BitcoinD.1> Lost connection to bitcoind, will retry every 5 seconds ...

# fulcrum is here again
Mar 15 16:31:26 debian Fulcrum[1554690]: [2023-03-15 16:16:00.138] <Controller> Block height 780927, up-to-date

# and so is sparrow
Mar 15 16:31:26 debian Fulcrum[1554690]: [2023-03-15 16:16:16.566] <TcpSrv 127.0.0.1:port> New TCP Client.413447 127.0.0.1:54490, 1 client total

# nope, fulcrum still having issues
Mar 15 16:31:26 debian Fulcrum[1554690]: [2023-03-15 16:17:45.689] <BitcoinD.3> Lost connection to bitcoind, will retry every 5 seconds ...
Mar 15 16:31:26 debian Fulcrum[1554690]: [2023-03-15 16:17:54.546] <BitcoinD.2> Lost connection to bitcoind, will retry every 5 seconds ...
Mar 15 16:31:26 debian Fulcrum[1554690]: [2023-03-15 16:17:49.764] <SynchMempool> 413463: FAIL: bitcoind connection lost
Mar 15 16:31:26 debian Fulcrum[1554690]: [2023-03-15 16:18:28.906] <BitcoinD.1> Lost connection to bitcoind, will retry every 5 seconds ...
Mar 15 16:31:26 debian Fulcrum[1554690]: [2023-03-15 16:19:24.193] <BitcoinD.2> Lost connection to bitcoind, will retry every 5 seconds ...

# oh hello there fulcrum, now once again working properly (from alone)!
Mar 15 16:34:08 debian Fulcrum[1554690]: [2023-03-15 16:34:08.061] <Controller> We have height 780927, but bitcoind reports height 780926. Possible reorg, will rewind back 1 block and try again ...
Mar 15 16:35:01 debian Fulcrum[1554690]: [2023-03-15 16:35:01.870] <Controller> Applied undo for block 780927 hash 000000000000000000004fc10fe0a646ebb03ed0066747a7fc4cf559250cd025, 3344 transactions involving 13459 scripthashes, in 53807.03 msec, new height now: 780926
Mar 15 16:35:19 debian Fulcrum[1554690]: [2023-03-15 16:35:19.568] <Controller> Block height 780928, downloading new blocks ...
Mar 15 16:35:24 debian Fulcrum[1554690]: [2023-03-15 16:35:24.978] <Controller> Processed 2 new blocks with 6251 txs (14261 inputs, 16636 outputs, 25640 addresses), verified ok.
Mar 15 16:35:43 debian Fulcrum[1554690]: [2023-03-15 16:35:43.048] <Controller> Block height 780929, downloading new blocks ...
Mar 15 16:35:47 debian Fulcrum[1554690]: [2023-03-15 16:35:47.731] <Controller> Processed 1 new block with 2831 txs (8011 inputs, 7026 outputs, 12517 addresses), verified ok.
Mar 15 16:36:04 debian Fulcrum[1554690]: [2023-03-15 16:36:04.197] <Controller> Block height 780930, downloading new blocks ...
Mar 15 16:36:07 debian Fulcrum[1554690]: [2023-03-15 16:36:07.890] <Controller> Processed 1 new block with 3476 txs (6692 inputs, 10393 outputs, 14242 addresses), verified ok.
Mar 15 16:36:22 debian Fulcrum[1554690]: [2023-03-15 16:36:22.304] <Controller> Block height 780931, downloading new blocks ...
Mar 15 16:36:24 debian Fulcrum[1554690]: [2023-03-15 16:36:24.644] <Controller> Processed 1 new block with 1291 txs (6557 inputs, 3014 outputs, 7807 addresses), verified ok.
Mar 15 16:36:24 debian Fulcrum[1554690]: [2023-03-15 16:36:24.676] <Controller> Block height 780931, up-to-date
Mar 15 16:36:27 debian Fulcrum[1554690]: [2023-03-15 16:36:27.248] <SynchMempool> Tx dropped out of mempool (possibly due to RBF): 13073ea9d6ae5097ae93dab8065e325917a127a5679ff4349df8547d08626f9b (error response: No such mempool or blockchain transaction. Use gettransaction for wallet transactions.), ignoring mempool tx ...
Mar 15 16:36:34 debian Fulcrum[1554690]: [2023-03-15 16:36:34.878] <Controller> 712 mempool txs involving 3753 addresses
Mar 15 16:37:34 debian Fulcrum[1554690]: [2023-03-15 16:37:34.881] <Controller> 1011 mempool txs involving 4793 addresses
Mar 15 16:37:46 debian Fulcrum[1554690]: [2023-03-15 16:37:46.515] <Controller> Block height 780932, downloading new blocks ...
Mar 15 16:37:48 debian Fulcrum[1554690]: [2023-03-15 16:37:48.492] <Controller> Processed 1 new block with 2556 txs (6405 inputs, 6267 outputs, 10477 addresses), verified ok.
Mar 15 16:37:48 debian Fulcrum[1554690]: [2023-03-15 16:37:48.496] <Controller> Block height 780932, up-to-date

# back to regular business...but where is Sparrow Server trying to re-connect?!
Mar 15 16:38:38 debian Fulcrum[1554690]: [2023-03-15 16:38:38.877] <Controller> 816 mempool txs involving 2807 addresses
Mar 15 16:39:38 debian Fulcrum[1554690]: [2023-03-15 16:39:38.879] <Controller> 1238 mempool txs involving 4506 addresses
Mar 15 16:40:48 debian Fulcrum[1554690]: [2023-03-15 16:40:48.878] <Controller> 1642 mempool txs involving 6307 addresses
Mar 15 16:41:48 debian Fulcrum[1554690]: [2023-03-15 16:41:48.879] <Controller> 1917 mempool txs involving 7730 addresses

Sparrows logs:

# no problems with fulcrum at that time, maybe only a minor networking issue
2023-03-15 12:02:08,780 WARN [Thread-2018] c.s.s.n.TcpTransport [null:-1] No response from server, setting read timeout to 8 secs

# that's the timeframe from the fulcrum logs above
2023-03-15 16:13:15,752 WARN [Thread-2287] c.s.s.n.TcpTransport [null:-1] No response from server, setting read timeout to 16 secs
2023-03-15 16:13:27,210 ERROR [Whirlpool-HttpClient-COORDINATOR_WEBSOCKET-1212] c.s.w.c.m.d.MixSession[1678891561649] [null:-1]  ! connexion lost, reconnecting for a new mix...
2023-03-15 16:13:27,211 ERROR [Whirlpool-HttpClient-COORDINATOR_WEBSOCKET-1216] c.s.w.c.m.d.MixSession[1678888411622] [null:-1]  ! connexion lost, reconnecting for a new mix...
2023-03-15 16:13:27,219 ERROR [Whirlpool-HttpClient-COORDINATOR_WEBSOCKET-1217] c.s.w.c.m.d.MixSession[1678891561658] [null:-1]  ! connexion lost, reconnecting for a new mix...
2023-03-15 16:13:27,241 ERROR [Whirlpool-HttpClient-COORDINATOR_WEBSOCKET-1479] c.s.w.c.m.d.MixSession[1678891610939] [null:-1]  ! connexion lost, reconnecting for a new mix...
2023-03-15 16:13:27,243 ERROR [Whirlpool-HttpClient-COORDINATOR_WEBSOCKET-1481] c.s.w.c.m.d.MixSession[1678891834181] [null:-1]  ! connexion lost, reconnecting for a new mix...
2023-03-15 16:13:27,243 ERROR [Whirlpool-HttpClient-COORDINATOR_WEBSOCKET-1486] c.s.w.c.m.d.MixSession[1678891640950] [null:-1]  ! connexion lost, reconnecting for a new mix...
2023-03-15 16:13:27,267 ERROR [Whirlpool-HttpClient-COORDINATOR_WEBSOCKET-6190] c.s.w.c.m.d.MixSession[1678878131073] [null:-1]  ! connexion lost, reconnecting for a new mix...
2023-03-15 16:31:54,434 ERROR [stop-whirlpoolClient] c.s.w.c.w.WhirlpoolWallet [null:-1] com.samourai.wallet.api.backend.beans.HttpException: java.util.concurrent.TimeoutException: Total timeout 30000 ms elapsed
2023-03-15 16:31:54,460 ERROR [stop-whirlpoolClient] c.s.w.c.w.WhirlpoolWallet [null:-1] com.samourai.wallet.api.backend.beans.HttpException: java.util.concurrent.TimeoutException: Total timeout 30000 ms elapsed
2023-03-15 16:31:54,468 ERROR [stop-whirlpoolClient] c.s.w.c.w.WhirlpoolWallet [null:-1] com.samourai.wallet.api.backend.beans.HttpException: java.util.concurrent.TimeoutException: Total timeout 30000 ms elapsed
2023-03-15 16:31:54,498 ERROR [stop-whirlpoolClient] c.s.w.c.w.WhirlpoolWallet [null:-1] com.samourai.wallet.api.backend.beans.HttpException: java.util.concurrent.TimeoutException: Total timeout 30000 ms elapsed
2023-03-15 16:31:54,498 ERROR [stop-whirlpoolClient] c.s.w.c.w.WhirlpoolWallet [null:-1] com.samourai.wallet.api.backend.beans.HttpException: java.util.concurrent.TimeoutException: Total timeout 30000 ms elapsed
2023-03-15 16:31:54,498 ERROR [stop-whirlpoolClient] c.s.w.c.w.WhirlpoolWallet [null:-1] com.samourai.wallet.api.backend.beans.HttpException: java.util.concurrent.TimeoutException: Total timeout 30000 ms elapsed

# log ends here, sparrow sits idle disconnected and waits until I manually re-connect via the server settings although fulcrum is now working again.

So my question is why sparrow server first tries to (successfully) re-connect (but since fulcrum still has some issue at that time to no avail) but then stops completely from doing so?

RequestPrivacy commented 1 year ago

Some more log outputs from sparrow during today's occurrence:

2023-03-16 13:08:06,932 WARN [Thread-3865] c.s.s.n.TcpTransport [null:-1] No response from server, setting read timeout to 8 secs
2023-03-16 13:08:15,974 WARN [Thread-3865] c.s.s.n.TcpTransport [null:-1] No response from server, setting read timeout to 16 secs
2023-03-16 13:08:54,946 WARN [Thread-3866] c.s.s.n.TcpTransport [null:-1] No response from server, setting read timeout to 8 secs
2023-03-16 13:09:03,765 WARN [Thread-3866] c.s.s.n.TcpTransport [null:-1] No response from server, setting read timeout to 16 secs
2023-03-16 13:11:09,187 WARN [Thread-3874] c.s.s.n.TcpTransport [null:-1] No response from server, setting read timeout to 8 secs
2023-03-16 13:11:24,056 ERROR [JavaFX Application Thread] c.s.s.w.WalletForm [null:-1] Error retrieving wallet history
com.sparrowwallet.sparrow.net.ServerException: Failed to subscribe to paths: [m/1/0-m/1/391]
        at com.sparrowwallet.sparrow@1.7.2/com.sparrowwallet.sparrow.net.ElectrumServer.subscribeWalletNodes(Unknown Source)
        at com.sparrowwallet.sparrow@1.7.2/com.sparrowwallet.sparrow.net.ElectrumServer.getHistory(Unknown Source)
        at com.sparrowwallet.sparrow@1.7.2/com.sparrowwallet.sparrow.net.ElectrumServer.getHistory(Unknown Source)
        at com.sparrowwallet.sparrow@1.7.2/com.sparrowwallet.sparrow.net.ElectrumServer$TransactionHistoryService.getTransactionHistory(Unknown Source)
        at com.sparrowwallet.sparrow@1.7.2/com.sparrowwallet.sparrow.net.ElectrumServer$TransactionHistoryService$1.call(Unknown Source)
        at com.sparrowwallet.sparrow@1.7.2/com.sparrowwallet.sparrow.net.ElectrumServer$TransactionHistoryService$1.call(Unknown Source)
        at javafx.graphics@18/javafx.concurrent.Task$TaskCallable.call(Unknown Source)
        at java.base/java.util.concurrent.FutureTask.run(Unknown Source)
        at javafx.graphics@18/javafx.concurrent.Service.lambda$executeTask$6(Unknown Source)
        at java.base/java.security.AccessController.doPrivileged(Unknown Source)
        at javafx.graphics@18/javafx.concurrent.Service.lambda$executeTask$7(Unknown Source)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
        at java.base/java.lang.Thread.run(Unknown Source)
Caused by: com.sparrowwallet.sparrow.net.ServerException: Retries exhausted
        at com.sparrowwallet.sparrow@1.7.2/com.sparrowwallet.sparrow.net.RetryLogic.getResult(Unknown Source)
        at com.sparrowwallet.sparrow@1.7.2/com.sparrowwallet.sparrow.net.PagedBatchRequestBuilder.execute(Unknown Source)
        at com.sparrowwallet.sparrow@1.7.2/com.sparrowwallet.sparrow.net.PagedBatchRequestBuilder.execute(Unknown Source)
        at com.sparrowwallet.sparrow@1.7.2/com.sparrowwallet.sparrow.net.BatchedElectrumServerRpc.subscribeScriptHashes(Unknown Source)
        ... 14 common frames omitted
Caused by: java.lang.IllegalStateException: I/O error during a request processing
        at simple.json.rpc.client@1.3/com.github.arteam.simplejsonrpc.client.builder.BatchRequestBuilder.executeRequest(Unknown Source)
        at simple.json.rpc.client@1.3/com.github.arteam.simplejsonrpc.client.builder.BatchRequestBuilder.execute(Unknown Source)
        ... 18 common frames omitted
Caused by: java.io.IOException: Error reading response: Could not connect to server at tcp://127.0.0.1:50011
        at com.sparrowwallet.sparrow@1.7.2/com.sparrowwallet.sparrow.net.TcpTransport.readResponse(Unknown Source)
        at com.sparrowwallet.sparrow@1.7.2/com.sparrowwallet.sparrow.net.TcpTransport.pass(Unknown Source)
        ... 20 common frames omitted
Caused by: java.io.IOException: Could not connect to server at tcp://127.0.0.1:50011
        at com.sparrowwallet.sparrow@1.7.2/com.sparrowwallet.sparrow.net.TcpTransport.readInputStream(Unknown Source)
        at com.sparrowwallet.sparrow@1.7.2/com.sparrowwallet.sparrow.net.TcpTransport.readInputLoop(Unknown Source)
        at com.sparrowwallet.sparrow@1.7.2/com.sparrowwallet.sparrow.net.ElectrumServer$ReadRunnable.run(Unknown Source)
        ... 1 common frames omitted
2023-03-16 13:11:26,158 ERROR [JavaFX Application Thread] c.s.s.w.WalletForm [null:-1] Error retrieving wallet history
com.sparrowwallet.sparrow.net.ServerException: Failed to subscribe to paths: [m/0/0-m/0/6074]
        at com.sparrowwallet.sparrow@1.7.2/com.sparrowwallet.sparrow.net.ElectrumServer.subscribeWalletNodes(Unknown Source)
        at com.sparrowwallet.sparrow@1.7.2/com.sparrowwallet.sparrow.net.ElectrumServer.getHistory(Unknown Source)
        at com.sparrowwallet.sparrow@1.7.2/com.sparrowwallet.sparrow.net.ElectrumServer.getHistory(Unknown Source)
        at com.sparrowwallet.sparrow@1.7.2/com.sparrowwallet.sparrow.net.ElectrumServer$TransactionHistoryService.getTransactionHistory(Unknown Source)
        at com.sparrowwallet.sparrow@1.7.2/com.sparrowwallet.sparrow.net.ElectrumServer$TransactionHistoryService$1.call(Unknown Source)
        at com.sparrowwallet.sparrow@1.7.2/com.sparrowwallet.sparrow.net.ElectrumServer$TransactionHistoryService$1.call(Unknown Source)
        at javafx.graphics@18/javafx.concurrent.Task$TaskCallable.call(Unknown Source)
        at java.base/java.util.concurrent.FutureTask.run(Unknown Source)
        at javafx.graphics@18/javafx.concurrent.Service.lambda$executeTask$6(Unknown Source)
        at java.base/java.security.AccessController.doPrivileged(Unknown Source)
        at javafx.graphics@18/javafx.concurrent.Service.lambda$executeTask$7(Unknown Source)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
        at java.base/java.lang.Thread.run(Unknown Source)
Caused by: com.sparrowwallet.sparrow.net.ServerException: Retries exhausted
        at com.sparrowwallet.sparrow@1.7.2/com.sparrowwallet.sparrow.net.RetryLogic.getResult(Unknown Source)
        at com.sparrowwallet.sparrow@1.7.2/com.sparrowwallet.sparrow.net.PagedBatchRequestBuilder.execute(Unknown Source)
        at com.sparrowwallet.sparrow@1.7.2/com.sparrowwallet.sparrow.net.PagedBatchRequestBuilder.execute(Unknown Source)
        at com.sparrowwallet.sparrow@1.7.2/com.sparrowwallet.sparrow.net.BatchedElectrumServerRpc.subscribeScriptHashes(Unknown Source)
        ... 14 common frames omitted
Caused by: java.lang.IllegalStateException: I/O error during a request processing
        at simple.json.rpc.client@1.3/com.github.arteam.simplejsonrpc.client.builder.BatchRequestBuilder.executeRequest(Unknown Source)
        at simple.json.rpc.client@1.3/com.github.arteam.simplejsonrpc.client.builder.BatchRequestBuilder.execute(Unknown Source)
        ... 18 common frames omitted
Caused by: java.io.IOException: Error reading response: Could not connect to server at tcp://127.0.0.1:50011
        at com.sparrowwallet.sparrow@1.7.2/com.sparrowwallet.sparrow.net.TcpTransport.readResponse(Unknown Source)
        at com.sparrowwallet.sparrow@1.7.2/com.sparrowwallet.sparrow.net.TcpTransport.pass(Unknown Source)
        ... 20 common frames omitted
Caused by: java.io.IOException: Could not connect to server at tcp://127.0.0.1:50011
        at com.sparrowwallet.sparrow@1.7.2/com.sparrowwallet.sparrow.net.TcpTransport.readInputStream(Unknown Source)
        at com.sparrowwallet.sparrow@1.7.2/com.sparrowwallet.sparrow.net.TcpTransport.readInputLoop(Unknown Source)
        at com.sparrowwallet.sparrow@1.7.2/com.sparrowwallet.sparrow.net.ElectrumServer$ReadRunnable.run(Unknown Source)
        ... 1 common frames omitted
2023-03-16 13:11:41,297 ERROR [Whirlpool-HttpClient-COORDINATOR_WEBSOCKET-12713] c.s.w.c.m.d.MixSession[1678968636105] [null:-1]  ! connexion lost, reconnecting for a new mix...
2023-03-16 13:11:41,301 ERROR [Whirlpool-HttpClient-COORDINATOR_WEBSOCKET-12727] c.s.w.c.m.d.MixSession[1678968636384] [null:-1]  ! connexion lost, reconnecting for a new mix...
2023-03-16 13:11:41,297 ERROR [Whirlpool-HttpClient-COORDINATOR_WEBSOCKET-12712] c.s.w.c.m.d.MixSession[1678968636108] [null:-1]  ! connexion lost, reconnecting for a new mix...
2023-03-16 13:11:41,299 ERROR [Whirlpool-HttpClient-COORDINATOR_WEBSOCKET-12704] c.s.w.c.m.d.MixSession[1678968635751] [null:-1]  ! connexion lost, reconnecting for a new mix...
2023-03-16 13:11:41,313 ERROR [Whirlpool-HttpClient-COORDINATOR_WEBSOCKET-12725] c.s.w.c.m.d.MixSession[1678968636373] [null:-1]  ! connexion lost, reconnecting for a new mix...
2023-03-16 13:12:44,674 WARN [Thread-3947] c.s.s.n.TcpTransport [null:-1] No response from server, setting read timeout to 8 secs
2023-03-16 13:13:35,402 WARN [Thread-3948] c.s.s.n.TcpTransport [null:-1] No response from server, setting read timeout to 8 secs
2023-03-16 13:13:44,269 WARN [Thread-3948] c.s.s.n.TcpTransport [null:-1] No response from server, setting read timeout to 16 secs
2023-03-16 13:14:26,642 WARN [Thread-3948] c.s.s.n.TcpTransport [null:-1] No response from server, setting read timeout to 34 secs
2023-03-16 13:15:57,281 WARN [Thread-3992] c.s.s.n.TcpTransport [null:-1] No response from server, setting read timeout to 34 secs
2023-03-16 13:17:57,217 WARN [Thread-3994] c.s.s.n.TcpTransport [null:-1] No response from server, setting read timeout to 34 secs
2023-03-16 13:23:58,013 WARN [Thread-4000] c.s.s.n.TcpTransport [null:-1] No response from server, setting read timeout to 34 secs
2023-03-16 13:25:00,037 WARN [Thread-4001] c.s.s.n.TcpTransport [null:-1] No response from server, setting read timeout to 34 secs
2023-03-16 13:27:11,572 WARN [Thread-4003] c.s.s.n.TcpTransport [null:-1] No response from server, setting read timeout to 34 secs
2023-03-16 13:30:09,327 WARN [Thread-4006] c.s.s.n.TcpTransport [null:-1] No response from server, setting read timeout to 34 secs
2023-03-16 13:32:00,175 WARN [Thread-4008] c.s.s.n.TcpTransport [null:-1] No response from server, setting read timeout to 34 secs
2023-03-16 13:34:57,308 WARN [Thread-4011] c.s.s.n.TcpTransport [null:-1] No response from server, setting read timeout to 34 secs
2023-03-16 13:34:59,987 ERROR [Whirlpool-HttpClient-COORDINATOR_WEBSOCKET-12831] c.s.w.c.m.d.MixSession[1678968883593] [null:-1]  ! connexion lost, reconnecting for a new mix...
2023-03-16 13:34:59,989 ERROR [Whirlpool-HttpClient-COORDINATOR_WEBSOCKET-12829] c.s.w.c.m.d.MixSession[1678968883589] [null:-1]  ! connexion lost, reconnecting for a new mix...
2023-03-16 13:35:00,001 ERROR [Whirlpool-HttpClient-COORDINATOR_WEBSOCKET-12825] c.s.w.c.m.d.MixSession[1678968883598] [null:-1]  ! connexion lost, reconnecting for a new mix...
2023-03-16 13:35:00,004 ERROR [Whirlpool-HttpClient-COORDINATOR_WEBSOCKET-12847] c.s.w.c.m.d.MixSession[1678968888869] [null:-1]  ! connexion lost, reconnecting for a new mix...
2023-03-16 13:35:00,008 ERROR [Whirlpool-HttpClient-COORDINATOR_WEBSOCKET-12840] c.s.w.c.m.d.MixSession[1678968888872] [null:-1]  ! connexion lost, reconnecting for a new mix...
2023-03-16 13:35:00,026 ERROR [Whirlpool-HttpClient-COORDINATOR_WEBSOCKET-12857] c.s.w.c.m.d.MixSession[1678968889078] [null:-1]  ! connexion lost, reconnecting for a new mix...
craigraw commented 1 year ago

Can I suggest turning on DEBUG logging in Sparrow so you can see when it is trying to reconnect? See https://github.com/sparrowwallet/sparrow/issues/583#issuecomment-1150755303 for notes on how to do this, and what to filter on.

RequestPrivacy commented 1 year ago

I will do just that.

Note however that I finally figured out the underlining issue (OOM and bitcoind getting killed) and tried to mitigate the cause. Once I'm satisfied that the underling issue is indeed resolved and I have a stable system again I will try to reproduce the OOM and this issue with the help of DEBUG setting.

RequestPrivacy commented 1 year ago

After my mitigation actions all went smooth without further issues - until a power outage killed the power supply to the Pi.

After a restart I checked bitcoind and fulcrum running again (no corruption). So I restarted Sparrow Server, but now it seems the issue (sparrow stops trying to re-connect?) is back although it looks like the cause might be another thing:

# fulcrum log
[...]
Apr 03 03:48:03 debian Fulcrum[4643]: [2023-04-03 03:48:03.628] <Controller> 5696 mempool txs involving 187204 addresses
Apr 03 03:49:13 debian Fulcrum[4643]: [2023-04-03 03:49:13.626] <Controller> 5916 mempool txs involving 187848 addresses
Apr 03 03:50:13 debian Fulcrum[4643]: [2023-04-03 03:50:13.627] <Controller> 6106 mempool txs involving 188579 addresses
Apr 03 03:51:01 debian Fulcrum[4643]: [2023-04-03 03:51:01.791] <Controller> Block height 783695, downloading new blocks ...

# first issue (new connection) in the logs since last successful mix from sparrow WITHOUT bitcoind or fulcrum getting killed due to the Pi getting OOM
Apr 03 03:51:33 debian Fulcrum[4643]: [2023-04-03 03:51:33.311] <TcpSrv 127.0.0.1:50011> New TCP Client.1067361 127.0.0.1:51094, 1 client total
Apr 03 03:51:43 debian Fulcrum[4643]: [2023-04-03 03:51:43.971] <Controller> Processed 1 new block with 1162 txs (8504 inputs, 3142 outputs, 8533 addresses), verified ok.
Apr 03 03:51:44 debian Fulcrum[4643]: [2023-04-03 03:51:44.008] <Controller> Block height 783696, downloading new blocks ...
Apr 03 03:51:47 debian Fulcrum[4643]: [2023-04-03 03:51:47.199] <Controller> Processed 1 new block with 216 txs (10370 inputs, 547 outputs, 7286 addresses), verified ok.
Apr 03 03:51:47 debian Fulcrum[4643]: [2023-04-03 03:51:47.203] <Controller> Block height 783696, up-to-date
Apr 03 03:51:57 debian Fulcrum[4643]: [2023-04-03 03:51:57.626] <Controller> 5217 mempool txs involving 184637 addresses

# next/same problem only 2 minutes later? Note the timed out status at the end
Apr 03 03:52:53 debian Fulcrum[4643]: [2023-04-03 03:52:53.648] <TcpSrv 127.0.0.1:50011> Client.1067361 BatchProcessor.1068107 (8): timed out after not receiving a batch response for 20 seconds.
Apr 03 03:52:57 debian Fulcrum[4643]: [2023-04-03 03:52:57.634] <Controller> 5343 mempool txs involving 184983 addresses
Apr 03 03:53:02 debian Fulcrum[4643]: [2023-04-03 03:53:02.640] <Controller> Block height 783697, downloading new blocks ...

# last time fulcrum recieves a connection from sparrow
Apr 03 03:53:04 debian Fulcrum[4643]: [2023-04-03 03:53:04.784] <TcpSrv 127.0.0.1:50011> New TCP Client.1068134 127.0.0.1:34858, 1 client total

# fulcrum keeps working seemingly flawless
Apr 03 03:53:09 debian Fulcrum[4643]: [2023-04-03 03:53:09.383] <Controller> Processed 1 new block with 335 txs (10480 inputs, 846 outputs, 7557 addresses), verified ok.
Apr 03 03:53:09 debian Fulcrum[4643]: [2023-04-03 03:53:09.387] <Controller> Block height 783697, up-to-date
Apr 03 03:53:59 debian Fulcrum[4643]: [2023-04-03 03:53:59.627] <Controller> 5294 mempool txs involving 184660 addresses
[...]

so matching the last time sparrow tried to connect I found following in its DEBUG logs

#sparrow.log
[...]

2023-04-03 03:53:04,786 DEBUG [Thread-834] c.s.s.n.TcpTransport [null:-1] Created Socket[addr=/127.0.0.1,port=50011,localport=34858]
2023-04-03 03:53:43,476 DEBUG [HikariPool-2 connection closer] c.z.h.p.PoolBase [null:-1] HikariPool-2 - Closing connection conn420: url=jdbc:h2:/home/pi/.sparrow/wallets/my_wallet_name user=SA: (connection has passed maxLifetime)

[...many whirlpool stuff...]

2023-04-03 03:54:25,338 DEBUG [HikariPool-1 connection closer] c.z.h.p.PoolBase [null:-1] HikariPool-1 - Closing connection conn423: url=jdbc:h2:/home/pi/.sparrow/wallets/my_wallet_name_2 user=SA: (connection has passed maxLifetime)
2023-04-03 03:54:36,112 DEBUG [HikariPool-1 connection closer] c.z.h.p.PoolBase [null:-1] HikariPool-1 - Closing connection conn422: url=jdbc:h2:/home/pi/.sparrow/wallets/my_wallet_name_2 user=SA: (connection has passed maxLifetime)
2023-04-03 03:54:44,851 DEBUG [HikariPool-1 connection closer] c.z.h.p.PoolBase [null:-1] HikariPool-1 - Closing connection conn421: url=jdbc:h2:/home/pi/.sparrow/wallets/my_wallet_name_2 user=SA: (connection has passed maxLifetime)
2023-04-03 03:54:48,679 DEBUG [HikariPool-1 connection closer] c.z.h.p.PoolBase [null:-1] HikariPool-1 - Closing connection conn424: url=jdbc:h2:/home/pi/.sparrow/wallets/my_wallet_name_2 user=SA: (connection has passed maxLifetime)
2023-04-03 03:54:56,868 DEBUG [HikariPool-1 connection closer] c.z.h.p.PoolBase [null:-1] HikariPool-1 - Closing connection conn427: url=jdbc:h2:/home/pi/.sparrow/wallets/my_wallet_name_2 user=SA: (connection has passed maxLifetime)
2023-04-03 03:55:08,133 DEBUG [HikariPool-2 connection closer] c.z.h.p.PoolBase [null:-1] HikariPool-2 - Closing connection conn425: url=jdbc:h2:/home/pi/.sparrow/wallets/my_wallet_name user=SA: (connection has passed maxLifetime)
2023-04-03 03:55:08,296 DEBUG [HikariPool-1 connection closer] c.z.h.p.PoolBase [null:-1] HikariPool-1 - Closing connection conn426: url=jdbc:h2:/home/pi/.sparrow/wallets/my_wallet_name_2 user=SA: (connection has passed maxLifetime)
2023-04-03 03:55:37,555 DEBUG [HikariPool-2 connection closer] c.z.h.p.PoolBase [null:-1] HikariPool-2 - Closing connection conn431: url=jdbc:h2:/home/pi/.sparrow/wallets/my_wallet_name user=SA: (connection has passed maxLifetime)
2023-04-03 03:55:42,745 DEBUG [HikariPool-1 connection closer] c.z.h.p.PoolBase [null:-1] HikariPool-1 - Closing connection conn430: url=jdbc:h2:/home/pi/.sparrow/wallets/my_wallet_name_2 user=SA: (connection has passed maxLifetime)
2023-04-03 03:55:53,176 DEBUG [HikariPool-2 connection closer] c.z.h.p.PoolBase [null:-1] HikariPool-2 - Closing connection conn428: url=jdbc:h2:/home/pi/.sparrow/wallets/my_wallet_name user=SA: (connection has passed maxLifetime)
2023-04-03 03:55:53,409 DEBUG [HikariPool-2 connection closer] c.z.h.p.PoolBase [null:-1] HikariPool-2 - Closing connection conn432: url=jdbc:h2:/home/pi/.sparrow/wallets/my_wallet_name user=SA: (connection has passed maxLifetime)
2023-04-03 03:56:07,520 DEBUG [HikariPool-1 connection closer] c.z.h.p.PoolBase [null:-1] HikariPool-1 - Closing connection conn429: url=jdbc:h2:/home/pi/.sparrow/wallets/my_wallet_name_2 user=SA: (connection has passed maxLifetime)
2023-04-03 03:56:11,880 DEBUG [HikariPool-2 connection closer] c.z.h.p.PoolBase [null:-1] HikariPool-2 - Closing connection conn433: url=jdbc:h2:/home/pi/.sparrow/wallets/my_wallet_name user=SA: (connection has passed maxLifetime)
2023-04-03 03:56:14,541 DEBUG [HikariPool-2 connection closer] c.z.h.p.PoolBase [null:-1] HikariPool-2 - Closing connection conn435: url=jdbc:h2:/home/pi/.sparrow/wallets/my_wallet_name user=SA: (connection has passed maxLifetime)
[...]

this continues until now with sparrow sitting in the "Disconnected" state.

Does this give you a hint or should I investigate why Sparrow dropped the connection in the first place? There's a lot of output there so maybe you can already narrow down what to search for?

craigraw commented 1 year ago

The HikariPool log messages are actually just database connection management related, and not relevant to connecting to Fulcrum.

This message actually indicates that Sparrow managed to connect successfully:

2023-04-03 03:53:04,786 DEBUG [Thread-834] c.s.s.n.TcpTransport [null:-1] Created Socket[addr=/127.0.0.1,port=50011,localport=34858]

A failure to connect would look like:

2022-06-09 08:45:09,062 DEBUG Connection failed
com.sparrowwallet.sparrow.net.ServerException: java.net.ConnectException: Connection refused
...

Sparrow tries to reconnect after 60 seconds has elapsed from a disconnection, increasing this delay logarithmically if it fails again. This should all be visible in the DEBUG logging.

As to what might be going wrong here, I'm really not sure. The only error we see is this:

Apr 03 03:52:53 debian Fulcrum[4643]: [2023-04-03 03:52:53.648] <TcpSrv 127.0.0.1:50011> Client.1067361 BatchProcessor.1068107 (8): timed out after not receiving a batch response for 20 seconds.

This is from https://github.com/cculianu/Fulcrum/blob/baf9acd30393b951509ca0c2ed441d2bb279ce2a/src/RPC.cpp#L1280. It's unclear why Fulcrum gets to this branch, and I think it might be worth opening an issue on the Fulcrum project to try understand this better.

craigraw commented 1 year ago

Are you still experiencing this?

RequestPrivacy commented 1 year ago

Sorry for not following up on this more actively but rn my time is very limited -> no time for investigating.

If you want to clean up the issue tracker feel free to close. Once I have more time at hand I will potentially re-open.

craigraw commented 1 year ago

Ok no problem. Closing it off for now.

RequestPrivacy commented 1 year ago

A failure to connect would look like:

I have found something that might look like this:

# ...

2023-07-08 01:22:12,319 DEBUG [JavaFX Application Thread] c.s.s.AppServices [null:-1] Connection failed
com.sparrowwallet.sparrow.net.ServerException: Error getting fee estimates for target blocks: [1, 2, 3, 4, 5, 10, 25, 50]
        at com.sparrowwallet.sparrow@1.7.7/com.sparrowwallet.sparrow.net.ElectrumServer.getFeeEstimates(Unknown Source)
        at com.sparrowwallet.sparrow@1.7.7/com.sparrowwallet.sparrow.net.ElectrumServer$ConnectionService$1.call(Unknown Source)
        at com.sparrowwallet.sparrow@1.7.7/com.sparrowwallet.sparrow.net.ElectrumServer$ConnectionService$1.call(Unknown Source)
        at javafx.graphics@18/javafx.concurrent.Task$TaskCallable.call(Unknown Source)
        at java.base/java.util.concurrent.FutureTask.run(Unknown Source)
        at javafx.graphics@18/javafx.concurrent.Service.lambda$executeTask$6(Unknown Source)
        at java.base/java.security.AccessController.doPrivileged(Unknown Source)
        at javafx.graphics@18/javafx.concurrent.Service.lambda$executeTask$7(Unknown Source)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
        at java.base/java.lang.Thread.run(Unknown Source)
Caused by: com.sparrowwallet.sparrow.net.ElectrumServerRpcException: Error getting fee estimates for target blocks: [1, 2, 3, 4, 5, 10, 25, 50]
        at com.sparrowwallet.sparrow@1.7.7/com.sparrowwallet.sparrow.net.BatchedElectrumServerRpc.getFeeEstimates(Unknown Source)
        ... 11 common frames omitted
Caused by: com.sparrowwallet.sparrow.net.ServerException: Retries exhausted
        at com.sparrowwallet.sparrow@1.7.7/com.sparrowwallet.sparrow.net.RetryLogic.getResult(Unknown Source)
        at com.sparrowwallet.sparrow@1.7.7/com.sparrowwallet.sparrow.net.PagedBatchRequestBuilder.execute(Unknown Source)
        at com.sparrowwallet.sparrow@1.7.7/com.sparrowwallet.sparrow.net.PagedBatchRequestBuilder.execute(Unknown Source)
        ... 12 common frames omitted
Caused by: java.lang.IllegalStateException: I/O error during a request processing
        at simple.json.rpc.client@1.3/com.github.arteam.simplejsonrpc.client.builder.BatchRequestBuilder.executeRequest(Unknown Source)
        at simple.json.rpc.client@1.3/com.github.arteam.simplejsonrpc.client.builder.BatchRequestBuilder.execute(Unknown Source)
        ... 15 common frames omitted
Caused by: java.io.IOException: Error reading response: Could not connect to server at tcp://127.0.0.1:50011
        at com.sparrowwallet.sparrow@1.7.7/com.sparrowwallet.sparrow.net.TcpTransport.readResponse(Unknown Source)
        at com.sparrowwallet.sparrow@1.7.7/com.sparrowwallet.sparrow.net.TcpTransport.pass(Unknown Source)
        ... 17 common frames omitted
Caused by: java.io.IOException: Could not connect to server at tcp://127.0.0.1:50011
        at com.sparrowwallet.sparrow@1.7.7/com.sparrowwallet.sparrow.net.TcpTransport.readInputStream(Unknown Source)
        at com.sparrowwallet.sparrow@1.7.7/com.sparrowwallet.sparrow.net.TcpTransport.readInputLoop(Unknown Source)
        at com.sparrowwallet.sparrow@1.7.7/com.sparrowwallet.sparrow.net.ElectrumServer$ReadRunnable.run(Unknown Source)
        ... 1 common frames omitted

# Afterwards Sparrow seems to close the wallets:
2023-07-08 01:22:12,335 DEBUG [Thread-2463] c.s.w.c.w.WhirlpoolWallet [null:-1] Closing wallet < path-to-wallet> 
2023-07-08 01:22:12,335 INFO [Thread-2463] c.s.w.c.w.WhirlpoolWallet [null:-1]  • Stopping WhirlpoolWallet

# [A bunch of whirlpool stuff follows] 

# ... Log ends with
2023-07-08 01:23:29,316 DEBUG [Whirlpool-HttpClient-COORDINATOR_REGISTER_OUTPUT-7415] o.e.j.i.FillInterest [null:-1] onClose FillInterest@17f4ae1f{null}
2023-07-08 01:23:29,317 DEBUG [Whirlpool-HttpClient-COORDINATOR_REGISTER_OUTPUT-7417] o.e.j.i.AbstractConnection [null:-1] onClose HttpConnectionOverHTTP@eab731b::SocketChannelEndPoint@41c4cdbd{/127.0.0.1:9050<->/127.0.0.1:53880,CLOSED,fill=-,flush=-,to=75113/0}{io=0/0,kio=-1,kro=-1}->HttpConnectionOverHTTP@eab731b(l:/127.0.0.1:53880 <-> r:/127.0.0.1:9050,closed=true)=>HttpChannelOverHTTP@3ad3a3ee(exchange=null)[send=HttpSenderOverHTTP@7660c8c1(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@4ae0e845{s=START}],recv=HttpReceiverOverHTTP@1f0679a9(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]
2023-07-08 01:23:29,317 DEBUG [Whirlpool-HttpClient-COORDINATOR_REGISTER_OUTPUT-7415] o.e.j.c.h.HttpConnectionOverHTTP [null:-1] Closed HttpConnectionOverHTTP@eab731b::SocketChannelEndPoint@41c4cdbd{/127.0.0.1:9050<->/127.0.0.1:53880,CLOSED,fill=-,flush=-,to=75114/0}{io=0/0,kio=-1,kro=-1}->HttpConnectionOverHTTP@eab731b(l:/127.0.0.1:53880 <-> r:/127.0.0.1:9050,closed=true)=>HttpChannelOverHTTP@3ad3a3ee(exchange=null)[send=HttpSenderOverHTTP@7660c8c1(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@4ae0e845{s=START}],recv=HttpReceiverOverHTTP@1f0679a9(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]
2023-07-08 01:44:37,008 DEBUG [HikariPool-1 connection closer] c.z.h.p.PoolBase [null:-1] HikariPool-1 - Closing connection conn2100: url=jdbc:h2:<path-to-wallet> user=SA: (connection has passed maxLifetime) 
...
2023-07-08 10:45:50,510 DEBUG [HikariPool-2 connection closer] c.z.h.p.PoolBase [null:-1] HikariPool-2 - Closing connection conn2669: url=jdbc:h2:<path-to-wallet> user=SA: (connection has passed maxLifetime)

# Me reading out the log

On fulcrum.conf:

Jul 08 01:21:30 debian Fulcrum[1163034]: [2023-07-08 01:21:30.090] <Controller> 52954 mempool txs involving 390980 addresses
Jul 08 01:22:09 debian Fulcrum[1163034]: [2023-07-08 01:22:09.085] <TcpSrv 127.0.0.1:50011> Client.839901 BatchProcessor.930979 (8): timed out after not receiving a batch response for 20 seconds.
Jul 08 01:22:09 debian Fulcrum[1163034]: [2023-07-08 01:22:09.089] <TcpSrv 127.0.0.1:50011> (Debug) do_disconnect (graceful) 839901
Jul 08 01:22:09 debian Fulcrum[1163034]: [2023-07-08 01:22:09.089] <TcpSrv 127.0.0.1:50011> (Debug) do_disconnect 839901 (graceful); delayed socket delete (wait for disconnect) ...
Jul 08 01:22:09 debian Fulcrum[1163034]: [2023-07-08 01:22:09.089] <TcpSrv 127.0.0.1:50011> (Debug) Client.839901 BatchProcessor.930979 (8): has 1 extant zombie requests, will filter subsequent responses matching this BatchId
Jul 08 01:22:09 debian Fulcrum[1163034]: [2023-07-08 01:22:09.089] <TcpSrv 127.0.0.1:50011> (Debug) TCP Client.839901 (id: 839901) 127.0.0.1:34332 socket disconnected
Jul 08 01:22:09 debian Fulcrum[1163034]: [2023-07-08 01:22:09.089] <TcpSrv 127.0.0.1:50011> (Debug) TCP Client.839901 (id: 839901) 127.0.0.1:34332 lost connection
Jul 08 01:22:09 debian Fulcrum[1163034]: [2023-07-08 01:22:09.090] <TcpSrv 127.0.0.1:50011> (Debug) killClient (id: 839901)
Jul 08 01:22:09 debian Fulcrum[1163034]: [2023-07-08 01:22:09.090] <TcpSrv 127.0.0.1:50011> (Debug) do_disconnect (abort) 839901
Jul 08 01:22:09 debian Fulcrum[1163034]: [2023-07-08 01:22:09.090] <TcpSrv 127.0.0.1:50011> (Debug) Client 839901 destructing
Jul 08 01:22:09 debian Fulcrum[1163034]: [2023-07-08 01:22:09.090] <TcpSrv 127.0.0.1:50011> (Debug) PerIP: 127.0.0.1 is no longer subscribed to any subscribables
Jul 08 01:22:09 debian Fulcrum[1163034]: [2023-07-08 01:22:09.175] <TcpSrv 127.0.0.1:50011> (Debug) Client.839901 BatchProcessor.930989 (8): (costDelta handler) per-IP data already gone, doing nothing
Jul 08 01:22:09 debian Fulcrum[1163034]: [2023-07-08 01:22:09.175] <TcpSrv 127.0.0.1:50011> (Debug) Client.839901 BatchProcessor.930989 (8): (destroyed handler) per-IP data already gone, doing nothing
Jul 08 01:22:09 debian Fulcrum[1163034]: [2023-07-08 01:22:09.554] <BitcoinDMgr> (Debug) handleMessageCommon<BitcoinDMgrHelper::ReqCtxObj> - request id 930987 method `estimatesmartfee` not found in request context table (sender object may have already been deleted)
Jul 08 01:22:16 debian Fulcrum[1163034]: [2023-07-08 01:22:16.396] <BitcoinDMgr> (Debug) handleMessageCommon<BitcoinDMgrHelper::ReqCtxObj> - request id 930990 method `estimatesmartfee` not found in request context table (sender object may have already been deleted)
Jul 08 01:22:16 debian Fulcrum[1163034]: [2023-07-08 01:22:16.437] <BitcoinDMgr> (Debug) handleMessageCommon<BitcoinDMgrHelper::ReqCtxObj> - request id 930991 method `estimatesmartfee` not found in request context table (sender object may have already been deleted)
Jul 08 01:22:16 debian Fulcrum[1163034]: [2023-07-08 01:22:16.437] <BitcoinDMgr> (Debug) handleMessageCommon<BitcoinDMgrHelper::ReqCtxObj> - request id 930992 method `estimatesmartfee` not found in request context table (sender object may have already been deleted)
Jul 08 01:22:16 debian Fulcrum[1163034]: [2023-07-08 01:22:16.437] <BitcoinDMgr> (Debug) handleMessageCommon<BitcoinDMgrHelper::ReqCtxObj> - request id 930993 method `estimatesmartfee` not found in request context table (sender object may have already been deleted)
Jul 08 01:22:22 debian Fulcrum[1163034]: [2023-07-08 01:22:22.927] <BitcoinDMgr> (Debug) handleMessageCommon<BitcoinDMgrHelper::ReqCtxObj> - request id 930994 method `estimatesmartfee` not found in request context table (sender object may have already been deleted)
Jul 08 01:22:22 debian Fulcrum[1163034]: [2023-07-08 01:22:22.942] <BitcoinDMgr> (Debug) handleMessageCommon<BitcoinDMgrHelper::ReqCtxObj> - request id 930995 method `estimatesmartfee` not found in request context table (sender object may have already been deleted)
Jul 08 01:22:22 debian Fulcrum[1163034]: [2023-07-08 01:22:22.944] <BitcoinDMgr> (Debug) handleMessageCommon<BitcoinDMgrHelper::ReqCtxObj> - request id 930996 method `estimatesmartfee` not found in request context table (sender object may have already been deleted)
Jul 08 01:22:22 debian Fulcrum[1163034]: [2023-07-08 01:22:22.964] <BitcoinDMgr> (Debug) handleMessageCommon<BitcoinDMgrHelper::ReqCtxObj> - request id 930997 method `estimatesmartfee` not found in request context table (sender object may have already been deleted)
Jul 08 01:22:24 debian Fulcrum[1163034]: [2023-07-08 01:22:24.770] <TcpSrv 127.0.0.1:50011> (Debug) Got connection from: 127.0.0.1:58304
Jul 08 01:22:24 debian Fulcrum[1163034]: [2023-07-08 01:22:24.771] <TcpSrv 127.0.0.1:50011> (Debug) on_connected 931001
Jul 08 01:22:24 debian Fulcrum[1163034]: [2023-07-08 01:22:24.771] <TcpSrv 127.0.0.1:50011> New TCP Client.931001 127.0.0.1:58304, 1 client total
Jul 08 01:23:18 debian Fulcrum[1163034]: [2023-07-08 01:23:18.112] <SubsMgr> (Debug) SubsMgr: Removed 16193 zombie subs out of 16193 in 30.8311 msec
Jul 08 01:23:21 debian Fulcrum[1163034]: [2023-07-08 01:23:21.784] <SynchMempool> (Debug) downloaded 273 txs (failed: 0, ignored: 0), elapsed so far: 135.875 secs
Jul 08 01:23:33 debian Fulcrum[1163034]: [2023-07-08 01:23:33.698] <SynchMempool> (Debug) Mempool: pre-cache of 9253 confirmed spends from db took 11913.688 msec
Jul 08 01:23:33 debian Fulcrum[1163034]: [2023-07-08 01:23:33.783] <SynchMempool> (Debug) 53227 mempool txs involving 396834 addresses (exclusive lock held for 84.474 msec)

# Fulcrum keeps working

A manual re-connection to fulcrum (Prefereces -> Server -> ... Done) instantaneously lets Sparrow re-connect to fulcrum. So it still feels like the Sparrow Server re-connection logic has a flaw? If I can manually trigger a successful re-connection without doing stuff on fulcrum Sparrow Server should be able to automatically do this too?

craigraw commented 1 year ago

Are you seeing Sparrow's automatic reconnection attempts in the log?

My feeling is that there is something else going on here. There should be no issues maintaining a long-lived TCP connection to a server running on localhost, unless that server itself is experiencing issues serving requests. Is it possible there is some kind of configuration which is killing long running TCP connections? Is Bitcoin Core running on a different machine?

FWIW Sparrow Server uses the exact same code to do connection/reconnection as Sparrow itself.

RequestPrivacy commented 1 year ago

Bitcoind (v25), Fulcrum (v1.9.1), Sparrow Terminal (v1.7.7) all run on a dedicated Pi.

Of course I'm not entirely sure that I have my bitcoin.conf and fulcrum.conf properly set but I have described parameters differing from default in the System section in the issue description over at fulcrum + I compared them to defaults in guides.

Are you seeing Sparrow's automatic reconnection attempts in the log?

I guess you mean this or else what can I grep for? Note this is all I got since flushing the log:

user@host:~/.sparrow $ cat sparrow.log | grep -iE "No response from server"

2023-07-07 19:35:59,755 WARN [Thread-1883] c.s.s.n.TcpTransport [null:-1] No response from server, setting read timeout to 16 secs
2023-07-07 19:36:24,695 WARN [Thread-1953] c.s.s.n.TcpTransport [null:-1] No response from server, setting read timeout to 8 secs
2023-07-07 20:32:25,161 WARN [Thread-2102] c.s.s.n.TcpTransport [null:-1] No response from server, setting read timeout to 16 secs
2023-07-07 22:35:52,359 WARN [Thread-2295] c.s.s.n.TcpTransport [null:-1] No response from server, setting read timeout to 8 secs
2023-07-07 22:36:02,472 WARN [Thread-2295] c.s.s.n.TcpTransport [null:-1] No response from server, setting read timeout to 16 secs
2023-07-08 01:22:05,405 WARN [Thread-2460] c.s.s.n.TcpTransport [null:-1] No response from server, setting read timeout to 34 secs
2023-07-08 01:22:05,405 WARN [Thread-2460] c.s.s.n.TcpTransport [null:-1] No response from server, setting read timeout to 34 secs

Apart from the question why the connection is lost in the first place, I really don't get that Sparrow (Server and GUI) are sitting somehow disconnected (label in Sparrow Server / pulsating toggle in GUI) until I trigger a new connection via Preferences / toggle on again. Hows that possible?

craigraw commented 1 year ago

Apart from the question why the connection is lost in the first place, I really don't get that Sparrow (Server and GUI) are sitting somehow disconnected... Hows that possible?

Unfortunately I think both questions are related. I have a similar setup myself (although on more capable hardware), and experience no disconnections at all. From the log, Sparrow is not getting timeous responses from Fulcrum, trying to reconnect, failing, and then backing off on the regularity of its attempts over time. There should however be no issue connecting to a local Fulcrum at all.

My best guess is that it's something hardware related. The complete logs from both applications might tell more.

RequestPrivacy commented 1 year ago

I don't want to jinx it but it seems the issue is resolved. Maybe the cause was mixing deep...like multiple thousand addresses deep...wallets. Furthermore, to see all transactions one had to open these wallets in the Sparrow GUI with gap limits as big as 1000. Not sure what happened there but this doesn't sound like normal.

I advised to mix out to a new wallet and there was apparently a distinct time after which Sparrow Server now keeps its connection to fulcrum (3-4 days now. Before one had to manually re-connect every day). Sooooooo maybe...lets hope for it.

craigraw commented 1 year ago

With this additional context, I think hardware was indeed the issue. A RPi can only take you so far :)