<h3>Description</h3>
<p>During startup, the Bisq client connects to 2 seednodes to sync the initial date. In the event that one seednode closes the connection w/ CLOSE_REQUESTED_BY_PEER and the other times out, the client hangs at (3/4) for the full 90s timeout window.</p>
<p>There isn't much that can be done w.r.t. timeouts, but if a seednode closes the connection intentionally, we can do a better job of sending another request in its place in the event the "backup" connection is going to time out.</p>
<p>I'm not sure if we track metrics on seednode intentional disconnects, but this might be a sign of overloaded seednodes.</p>
<h4>Version</h4>
<p>v1.2.4</p>
<h3>Steps to reproduce</h3>
<p>I haven't fabricated this scenario for testing, but in my normal usage of Bisq there have been a few instances where (3/4) will hang for the full 90s before cycling to another seed node and starting. The logs indicate the error described above.</p>
<h3>Expected behaviour</h3>
<p>If a seednode intentionally disconnects a starting client, the client will retry with another valid node "immediately".</p>
<h3>Actual behaviour</h3>
<p>Connections intentionally closed by the seednode are not restarted with another valid seednode.</p>
<h3>Screenshots</h3>
<h4>Device or machine</h4>
<p>Ubuntu 19.10</p>
<h4>Additional info</h4>
<p>I don't have a lot of experience with the networking code, but it looks like <code>RequestDataManager::onDisconnect</code> only removes the handler from the internal map and doesn't trigger any action.</p>
<p><strong>Dec-16 09:24:25.738 - CLOSE_REQUESTED_BY_PEER</strong> (Seednode 1)<br>
<strong>Dec-16 09:25:40.094 - Timeout</strong> (Seednode 2)<br>
<strong>Dec-16 09:25:43.691 - Retry</strong></p>
<pre><code>Dec-16 09:24:09.937 [JavaFX Application Thread] INFO b.n.p.p.g.RequestDataHandler: We send a PreliminaryGetDataRequest to peer fl3mmribyxgrv63c.onion:8000.
Dec-16 09:24:10.083 [JavaFX Application Thread] INFO b.n.p.p.g.RequestDataHandler: We send a PreliminaryGetDataRequest to peer jhgcy2won7xnslrb.onion:8000.
Dec-16 09:24:10.084 [ STARTING] INFO o.b.core.AbstractBlockChain: chain head is at height 608391:
block:
hash: 000000000000000000033aaf6baf36c29cfd1273b4534be10a3f9b5b429e5ef0
version: 536928256 (BIP34, BIP66, BIP65)
previous block: 00000000000000000012df7e87203e2570e61a2dd9eb75dd483804e6f3e8ed95
merkle root: 0f3d965d7a966af8ee45f09e2b1081b299630e29268f4551c9248e52b87e2337
time: 1576516776 (2019-12-16T17:19:36Z)
difficulty target (nBits): 387308498
nonce: 3598059532
Dec-16 09:24:10.326 [ STARTING] INFO b.core.btc.setup.WalletConfig: We try to connect to 9 btc nodes
Dec-16 09:24:10.353 [PeerGroup Thread] INFO org.bitcoinj.core.PeerGroup: Starting ...
Dec-16 09:24:10.356 [PeerGroup Thread] INFO org.bitcoinj.core.PeerGroup: Localhost peer not detected.
Dec-16 09:24:10.361 [PeerGroup Thread] INFO org.bitcoinj.core.PeerGroup: Attempting connection to [fz6nsij6jiyuwlsc.onion]:8333 (0 connected, 1 pending, 9 max)
Dec-16 09:24:10.363 [PeerGroup Thread] INFO org.bitcoinj.core.PeerGroup: Attempting connection to [sslnjjhnmwllysv4.onion]:8333 (0 connected, 2 pending, 9 max)
Dec-16 09:24:10.382 [PeerGroup Thread] INFO org.bitcoinj.core.PeerGroup: Attempting connection to [jiuuuislm7ooesic.onion]:8333 (0 connected, 3 pending, 9 max)
Dec-16 09:24:10.384 [PeerGroup Thread] INFO org.bitcoinj.core.PeerGroup: Attempting connection to [22tg6ufbwz6o3l2u.onion]:8333 (0 connected, 4 pending, 9 max)
Dec-16 09:24:10.395 [PeerGroup Thread] INFO org.bitcoinj.core.PeerGroup: Attempting connection to [z33nukt7ngik3cpe.onion]:8333 (0 connected, 5 pending, 9 max)
Dec-16 09:24:10.421 [PeerGroup Thread] INFO org.bitcoinj.core.PeerGroup: Attempting connection to [lva54pnbq2nsmjyr.onion]:8333 (0 connected, 6 pending, 9 max)
Dec-16 09:24:10.432 [PeerGroup Thread] INFO org.bitcoinj.core.PeerGroup: Attempting connection to [i3a5xtzfm4xwtybd.onion]:8333 (0 connected, 7 pending, 9 max)
Dec-16 09:24:10.436 [PeerGroup Thread] INFO org.bitcoinj.core.PeerGroup: Attempting connection to [3r44ddzjitznyahw.onion]:8333 (0 connected, 8 pending, 9 max)
Dec-16 09:24:10.437 [PeerGroup Thread] INFO org.bitcoinj.core.PeerGroup: Attempting connection to [mxdtrjhe2yfsx3pg.onion]:8333 (0 connected, 9 pending, 9 max)
Dec-16 09:24:10.438 [JavaFX Application Thread] INFO bisq.core.app.BisqSetup: walletInitialized=true, p2pNetWorkReady=false
Dec-16 09:24:13.856 [BlockingClient network thread for sslnjjhnmwllysv4.onion:8333] INFO org.bitcoinj.core.Peer: Announcing to sslnjjhnmwllysv4.onion:8333 as: /bitcoinj:0.14.7.bisq.1-SNAPSHOT/Bisq:1.2.4/
Dec-16 09:24:14.352 [BlockingClient network thread for sslnjjhnmwllysv4.onion:8333] INFO org.bitcoinj.core.Peer: [sslnjjhnmwllysv4.onion]:8333: Got version=70015, subVer='/Satoshi:0.18.1/', services=0x1037, time=2019-12-16 09:24:16, blocks=608391
Dec-16 09:24:14.354 [BlockingClient network thread for sslnjjhnmwllysv4.onion:8333] INFO org.bitcoinj.core.PeerGroup: [sslnjjhnmwllysv4.onion]:8333: New peer (1 connected, 8 pending, 9 max)
Dec-16 09:24:14.355 [BlockingClient network thread for sslnjjhnmwllysv4.onion:8333] INFO org.bitcoinj.core.PeerGroup: Setting download peer: [sslnjjhnmwllysv4.onion]:8333
Dec-16 09:24:15.333 [BlockingClient network thread for lva54pnbq2nsmjyr.onion:8333] INFO org.bitcoinj.core.Peer: Announcing to lva54pnbq2nsmjyr.onion:8333 as: /bitcoinj:0.14.7.bisq.1-SNAPSHOT/Bisq:1.2.4/
Dec-16 09:24:15.508 [BlockingClient network thread for jiuuuislm7ooesic.onion:8333] INFO org.bitcoinj.core.Peer: Announcing to jiuuuislm7ooesic.onion:8333 as: /bitcoinj:0.14.7.bisq.1-SNAPSHOT/Bisq:1.2.4/
Dec-16 09:24:15.508 [BlockingClient network thread for i3a5xtzfm4xwtybd.onion:8333] INFO org.bitcoinj.core.Peer: Announcing to i3a5xtzfm4xwtybd.onion:8333 as: /bitcoinj:0.14.7.bisq.1-SNAPSHOT/Bisq:1.2.4/
Dec-16 09:24:15.580 [BlockingClient network thread for z33nukt7ngik3cpe.onion:8333] INFO org.bitcoinj.core.Peer: Announcing to z33nukt7ngik3cpe.onion:8333 as: /bitcoinj:0.14.7.bisq.1-SNAPSHOT/Bisq:1.2.4/
Dec-16 09:24:15.981 [BlockingClient network thread for lva54pnbq2nsmjyr.onion:8333] INFO org.bitcoinj.core.Peer: [lva54pnbq2nsmjyr.onion]:8333: Got version=70015, subVer='/Satoshi:0.18.1/', services=0x1037, time=2019-12-16 09:24:18, blocks=608391
Dec-16 09:24:15.982 [BlockingClient network thread for lva54pnbq2nsmjyr.onion:8333] INFO org.bitcoinj.core.PeerGroup: [lva54pnbq2nsmjyr.onion]:8333: New peer (2 connected, 7 pending, 9 max)
Dec-16 09:24:16.130 [BlockingClient network thread for 22tg6ufbwz6o3l2u.onion:8333] INFO org.bitcoinj.core.Peer: Announcing to 22tg6ufbwz6o3l2u.onion:8333 as: /bitcoinj:0.14.7.bisq.1-SNAPSHOT/Bisq:1.2.4/
Dec-16 09:24:16.131 [BlockingClient network thread for i3a5xtzfm4xwtybd.onion:8333] INFO org.bitcoinj.core.Peer: [i3a5xtzfm4xwtybd.onion]:8333: Got version=70015, subVer='/Satoshi:0.18.1/', services=0x1037, time=2019-12-16 09:24:18, blocks=608391
Dec-16 09:24:16.135 [BlockingClient network thread for i3a5xtzfm4xwtybd.onion:8333] INFO org.bitcoinj.core.PeerGroup: [i3a5xtzfm4xwtybd.onion]:8333: New peer (3 connected, 6 pending, 9 max)
Dec-16 09:24:16.144 [BlockingClient network thread for z33nukt7ngik3cpe.onion:8333] INFO org.bitcoinj.core.Peer: [z33nukt7ngik3cpe.onion]:8333: Got version=70015, subVer='/Satoshi:0.16.3/', services=0x1037, time=2019-12-16 09:20:48, blocks=608391
Dec-16 09:24:16.151 [BlockingClient network thread for z33nukt7ngik3cpe.onion:8333] INFO org.bitcoinj.core.PeerGroup: [z33nukt7ngik3cpe.onion]:8333: New peer (4 connected, 5 pending, 9 max)
Dec-16 09:24:16.193 [NetworkNode:SendMessage-to-jhgcy2won7xnslrb.onion:8000] INFO b.n.p.p.g.m.PreliminaryGetDataRequest: Sending a PreliminaryGetDataRequest with 1980.089 kB
Dec-16 09:24:16.347 [BlockingClient network thread for 3r44ddzjitznyahw.onion:8333] INFO org.bitcoinj.core.Peer: Announcing to 3r44ddzjitznyahw.onion:8333 as: /bitcoinj:0.14.7.bisq.1-SNAPSHOT/Bisq:1.2.4/
Dec-16 09:24:16.369 [NetworkNode:SendMessage-to-fl3mmribyxgrv63c.onion:8000] INFO b.n.p.p.g.m.PreliminaryGetDataRequest: Sending a PreliminaryGetDataRequest with 1980.089 kB
Dec-16 09:24:16.448 [BlockingClient network thread for jiuuuislm7ooesic.onion:8333] INFO org.bitcoinj.core.Peer: [jiuuuislm7ooesic.onion]:8333: Got version=70015, subVer='/Satoshi:0.18.1/', services=0x1037, time=2019-12-16 09:24:18, blocks=608391
Dec-16 09:24:16.449 [BlockingClient network thread for jiuuuislm7ooesic.onion:8333] INFO org.bitcoinj.core.PeerGroup: [jiuuuislm7ooesic.onion]:8333: New peer (5 connected, 4 pending, 9 max)
Dec-16 09:24:16.460 [BlockingClient network thread for mxdtrjhe2yfsx3pg.onion:8333] INFO org.bitcoinj.core.Peer: Announcing to mxdtrjhe2yfsx3pg.onion:8333 as: /bitcoinj:0.14.7.bisq.1-SNAPSHOT/Bisq:1.2.4/
Dec-16 09:24:16.484 [pool-39-thread-1] INFO b.n.p.p.g.m.PreliminaryGetDataRequest: Sending a PreliminaryGetDataRequest with 1980.089 kB
Dec-16 09:24:16.534 [pool-41-thread-1] INFO b.n.p.p.g.m.PreliminaryGetDataRequest: Sending a PreliminaryGetDataRequest with 1980.089 kB
Dec-16 09:24:16.851 [BlockingClient network thread for 3r44ddzjitznyahw.onion:8333] INFO org.bitcoinj.core.Peer: [3r44ddzjitznyahw.onion]:8333: Got version=70015, subVer='/Satoshi:0.18.1/', services=0x1037, time=2019-12-16 09:24:19, blocks=608391
Dec-16 09:24:16.852 [BlockingClient network thread for 3r44ddzjitznyahw.onion:8333] INFO org.bitcoinj.core.PeerGroup: [3r44ddzjitznyahw.onion]:8333: New peer (6 connected, 3 pending, 9 max)
Dec-16 09:24:16.994 [BlockingClient network thread for mxdtrjhe2yfsx3pg.onion:8333] INFO org.bitcoinj.core.Peer: [mxdtrjhe2yfsx3pg.onion]:8333: Got version=70015, subVer='/Satoshi:0.18.0/', services=0x1037, time=2019-12-16 09:24:19, blocks=608391
Dec-16 09:24:16.994 [BlockingClient network thread for mxdtrjhe2yfsx3pg.onion:8333] INFO org.bitcoinj.core.PeerGroup: [mxdtrjhe2yfsx3pg.onion]:8333: New peer (7 connected, 2 pending, 9 max)
Dec-16 09:24:17.101 [BlockingClient network thread for 22tg6ufbwz6o3l2u.onion:8333] INFO org.bitcoinj.core.Peer: [22tg6ufbwz6o3l2u.onion]:8333: Got version=70015, subVer='/Satoshi:0.19.0.1/', services=0x1037, time=2019-12-16 09:24:19, blocks=608391
Dec-16 09:24:17.102 [BlockingClient network thread for 22tg6ufbwz6o3l2u.onion:8333] INFO org.bitcoinj.core.PeerGroup: [22tg6ufbwz6o3l2u.onion]:8333: New peer (8 connected, 1 pending, 9 max)
Dec-16 09:24:25.734 [JavaFX Application Thread] INFO b.n.p2p.peers.PeerManager: onDisconnect called: nodeAddress=Optional[fl3mmribyxgrv63c.onion:8000], closeConnectionReason=CloseConnectionReason{sendCloseMessage=false, isIntended=true} CLOSE_REQUESTED_BY_PEER
Dec-16 09:24:25.738 [JavaFX Application Thread] INFO b.n.p.p.p.PeerExchangeManager: onDisconnect closeConnectionReason=CloseConnectionReason{sendCloseMessage=false, isIntended=true} CLOSE_REQUESTED_BY_PEER, nodeAddressOpt=Optional[fl3mmribyxgrv63c.onion:8000]
Dec-16 09:24:26.191 [JavaFX Application Thread] INFO b.n.p2p.peers.PeerManager: We have 1 connections open. Our limit is 12
Dec-16 09:24:43.511 [TorControlParser] INFO o.b.netlayer.tor.Tor: Hidden Service shavx2j47oghl62o.onion.onion has been announced to the Tor network.
Dec-16 09:24:43.519 [Thread-18] INFO b.n.p2p.network.TorNetworkNode:
################################################################
Tor hidden service published after 33917 ms. Socked=HiddenServiceSocket[addr=shavx2j47oghl62o.onion,port=9999]
################################################################
Dec-16 09:24:43.992 [TorControlParser] INFO o.b.netlayer.tor.Tor: Hidden Service shavx2j47oghl62o.onion.onion has been announced to the Tor network.
Dec-16 09:24:44.187 [TorControlParser] INFO o.b.netlayer.tor.Tor: Hidden Service shavx2j47oghl62o.onion.onion has been announced to the Tor network.
Dec-16 09:24:44.298 [TorControlParser] INFO o.b.netlayer.tor.Tor: Hidden Service shavx2j47oghl62o.onion.onion has been announced to the Tor network.
Dec-16 09:24:44.472 [TorControlParser] INFO o.b.netlayer.tor.Tor: Hidden Service shavx2j47oghl62o.onion.onion has been announced to the Tor network.
Dec-16 09:24:45.390 [TorControlParser] INFO o.b.netlayer.tor.Tor: Hidden Service shavx2j47oghl62o.onion.onion has been announced to the Tor network.
Dec-16 09:25:40.094 [JavaFX Application Thread] INFO b.n.p.p.g.RequestDataHandler: A timeout occurred at sending getDataRequest:PreliminaryGetDataRequest(supportedCapabilities=[0, 1, 2, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14]) on nodeAddress:jhgcy2won7xnslrb.onion:8000
Dec-16 09:25:40.131 [JavaFX Application Thread] INFO b.n.p.p.g.RequestDataHandler: We send a PreliminaryGetDataRequest to peer 723ljisnynbtdohi.onion:8000.
Dec-16 09:25:43.691 [NetworkNode:SendMessage-to-723ljisnynbtdohi.onion:8000] INFO b.n.p.p.g.m.PreliminaryGetDataRequest: Sending a PreliminaryGetDataRequest with 1980.084 kB
Dec-16 09:25:43.798 [pool-43-thread-1] INFO b.n.p.p.g.m.PreliminaryGetDataRequest: Sending a PreliminaryGetDataRequest with 1980.084 kB
Dec-16 09:25:47.522 [InputHandler-jhgcy2won7xnslrb.onion:8000] INFO b.n.p.p.g.m.GetDataResponse: Received a GetDataResponse with 3166.148 kB
Dec-16 09:25:53.682 [JavaFX Application Thread] INFO b.n.p2p.peers.PeerManager: We have 2 connections open. Our limit is 12
Dec-16 09:26:02.276 [InputHandler-723ljisnynbtdohi.onion:8000] INFO b.n.p.p.g.m.GetDataResponse: Received a GetDataResponse with 3521.577 kB
Dec-16 09:26:02.388 [JavaFX Application Thread] INFO b.n.p.p.g.RequestDataHandler:
#################################################################
Connected to node: 723ljisnynbtdohi.onion:8000
Received 892 instances
RefundAgent: 1
Filter: 2
MailboxStoragePayload: 544
Mediator: 2
Alert: 1
OfferPayload: 342
#################################################################
</code></pre>
<p style="font-size:small;-webkit-text-size-adjust:none;color:#666;">—<br />You are receiving this because you are subscribed to this thread.<br />Reply to this email directly, <a href="https://github.com/bisq-network/bisq/issues/3797?email_source=notifications&email_token=AJFFTNWFJ362COBHECBI7NDQY67L5A5CNFSM4J3NZF5KYY3PNVWWK3TUL52HS4DFUVEXG43VMWVGG33NNVSW45C7NFSM4IAZ4MYQ">view it on GitHub</a>, or <a href="https://github.com/notifications/unsubscribe-auth/AJFFTNQQA4G2UASMKQ3SXG3QY67L5ANCNFSM4J3NZF5A">unsubscribe</a>.<img src="https://github.com/notifications/beacon/AJFFTNQMEH2XGQ23ETOXAETQY67L5A5CNFSM4J3NZF5KYY3PNVWWK3TUL52HS4DFUVEXG43VMWVGG33NNVSW45C7NFSM4IAZ4MYQ.gif" height="1" width="1" alt="" /></p>
<script type="application/ld+json">[
{
"@context": "http://schema.org",
"@type": "EmailMessage",
"potentialAction": {
"@type": "ViewAction",
"target": "https://github.com/bisq-network/bisq/issues/3797?email_source=notifications\u0026email_token=AJFFTNWFJ362COBHECBI7NDQY67L5A5CNFSM4J3NZF5KYY3PNVWWK3TUL52HS4DFUVEXG43VMWVGG33NNVSW45C7NFSM4IAZ4MYQ",
"url": "https://github.com/bisq-network/bisq/issues/3797?email_source=notifications\u0026email_token=AJFFTNWFJ362COBHECBI7NDQY67L5A5CNFSM4J3NZF5KYY3PNVWWK3TUL52HS4DFUVEXG43VMWVGG33NNVSW45C7NFSM4IAZ4MYQ",
"name": "View Issue"
},
"description": "View this Issue on GitHub",
"publisher": {
"@type": "Organization",
"name": "GitHub",
"url": "https://github.com"
}
}
]</script>