search

danielmcclure / bitcoinj

Automatically exported from code.google.com/p/bitcoinj
Apache License 2.0
0 stars 1 forks source link

bitcoinj connects to the same server several times #611

Closed GoogleCodeExporter closed 9 years ago

GoogleCodeExporter commented 9 years ago 
I  just connect to 1 peer: a bitcoind on localhost using regtest

If the peer dies and then is up again, connections are screwed up. 

Here are the steps

1) Start a local bitcoind in regtest

2) Run
        RegTestParams params = RegTestParams.get();
        MemoryBlockStore blockStore = new MemoryBlockStore(params);
        BlockChain blockChain = new BlockChain(params, blockStore);
        PeerGroup peerGroup = new PeerGroup(params, blockChain);
        peerGroup.start();        
        new CountDownLatch(1).await();

3) This is the log:
Mar 23, 2015 8:30:16 PM org.bitcoinj.core.AbstractBlockChain <init>
INFO: chain head is at height 0:
v1 block: 
   previous block: 0000000000000000000000000000000000000000000000000000000000000000
   merkle root: 4a5e1e4baab89f3a32518a88c31bc87f618f76673e2cc77ab2127b7afdeda33b
   time: [1296688602] 2011-02-02T23:16:42Z
   difficulty target (nBits): 545259519
   nonce: 2

Mar 23, 2015 8:30:16 PM org.bitcoinj.core.Context getOrCreate
WARNING: Implicitly creating context. This is a migration step and this message 
will eventually go away.
Mar 23, 2015 8:30:16 PM org.bitcoinj.core.PeerGroup$7 run
INFO: Starting ...
Mar 23, 2015 8:30:16 PM org.bitcoinj.core.PeerGroup$3 go
INFO: Localhost peer detected, trying to use it instead of P2P discovery
Mar 23, 2015 8:30:16 PM org.bitcoinj.core.PeerGroup connectTo
INFO: Attempting connection to [127.0.0.1]:18444     (0 connected, 1 pending, 0 
max)
Mar 23, 2015 8:30:16 PM org.bitcoinj.net.NioClientManager handleKey
INFO: Successfully connected to /127.0.0.1:18444
Mar 23, 2015 8:30:16 PM org.bitcoinj.core.Peer connectionOpened
INFO: Announcing to /127.0.0.1:18444 as: /bitcoinj:0.13-SNAPSHOT/
Mar 23, 2015 8:30:16 PM org.bitcoinj.core.Peer processVersionMessage
INFO: Connected to 127.0.0.1: version=70002, subVer='/Satoshi:0.9.99/', 
services=0x1, time=2015-03-23 20:30:16, blocks=593
Mar 23, 2015 8:30:16 PM org.bitcoinj.core.PeerGroup handleNewPeer
INFO: [127.0.0.1]:18444: New peer      (1 connected, 0 pending, 1 max)
Mar 23, 2015 8:30:16 PM org.bitcoinj.core.PeerGroup setDownloadPeer
INFO: Setting download peer: [127.0.0.1]:18444

4) Stop bitcoind. This is the log:

Mar 23, 2015 8:30:21 PM org.bitcoinj.core.PeerGroup handlePeerDeath
INFO: [127.0.0.1]:18444: Peer died      (0 connected, 0 pending, 1 max)
Mar 23, 2015 8:30:21 PM org.bitcoinj.core.PeerGroup handlePeerDeath
INFO: Download peer died. Picking a new one.
Mar 23, 2015 8:30:21 PM org.bitcoinj.core.PeerGroup setDownloadPeer
INFO: Unsetting download peer: [127.0.0.1]:18444
Mar 23, 2015 8:30:21 PM org.bitcoinj.core.PeerGroup discoverPeers
INFO: Peer discovery took 0msec and returned 0 items
Mar 23, 2015 8:30:21 PM org.bitcoinj.core.PeerGroup$3 go
INFO: Waiting 1502 msec before next connect attempt to [127.0.0.1]:18444
Mar 23, 2015 8:30:23 PM org.bitcoinj.core.PeerGroup connectTo
INFO: Attempting connection to [127.0.0.1]:18444     (0 connected, 1 pending, 1 
max)
Mar 23, 2015 8:30:23 PM org.bitcoinj.net.NioClientManager handleKey
WARNING: Failed to connect with exception: java.net.ConnectException: 
Connection refused
Mar 23, 2015 8:30:23 PM org.bitcoinj.core.PeerGroup handlePeerDeath
INFO: [127.0.0.1]:18444: Peer died      (0 connected, 0 pending, 1 max)
Mar 23, 2015 8:30:23 PM org.bitcoinj.core.PeerGroup discoverPeers
INFO: Peer discovery took 1msec and returned 0 items
Mar 23, 2015 8:30:23 PM org.bitcoinj.core.PeerGroup$3 go
INFO: Waiting 3376 msec before next connect attempt to [127.0.0.1]:18444
Mar 23, 2015 8:30:26 PM org.bitcoinj.core.PeerGroup connectTo
INFO: Attempting connection to [127.0.0.1]:18444     (0 connected, 1 pending, 1 
max)
Mar 23, 2015 8:30:26 PM org.bitcoinj.net.NioClientManager handleKey
WARNING: Failed to connect with exception: java.net.ConnectException: 
Connection refused
Mar 23, 2015 8:30:26 PM org.bitcoinj.core.PeerGroup handlePeerDeath
INFO: [127.0.0.1]:18444: Peer died      (0 connected, 0 pending, 1 max)
Mar 23, 2015 8:30:26 PM org.bitcoinj.core.PeerGroup discoverPeers
INFO: Peer discovery took 0msec and returned 0 items
Mar 23, 2015 8:30:26 PM org.bitcoinj.core.PeerGroup$3 go
INFO: Waiting 7594 msec before next connect attempt to [127.0.0.1]:18444
Mar 23, 2015 8:30:28 PM org.bitcoinj.core.PeerSocketHandler timeoutOccurred
INFO: [127.0.0.1]:18444: Timed out
Mar 23, 2015 8:30:28 PM org.bitcoinj.core.PeerGroup handlePeerDeath
INFO: [127.0.0.1]:18444: Peer died      (0 connected, 0 pending, 1 max)
Mar 23, 2015 8:30:28 PM org.bitcoinj.core.PeerGroup discoverPeers
INFO: Peer discovery took 0msec and returned 0 items
Mar 23, 2015 8:30:28 PM org.bitcoinj.core.PeerGroup$3 go
INFO: Waiting 10003 msec before next connect attempt to [127.0.0.1]:18444
Mar 23, 2015 8:30:31 PM org.bitcoinj.core.PeerSocketHandler timeoutOccurred
INFO: [127.0.0.1]:18444: Timed out
Mar 23, 2015 8:30:31 PM org.bitcoinj.core.PeerGroup handlePeerDeath
INFO: [127.0.0.1]:18444: Peer died      (0 connected, 0 pending, 1 max)
Mar 23, 2015 8:30:31 PM org.bitcoinj.core.PeerGroup discoverPeers
INFO: Peer discovery took 0msec and returned 0 items
Mar 23, 2015 8:30:31 PM org.bitcoinj.core.PeerGroup$3 go
INFO: Waiting 10001 msec before next connect attempt to [127.0.0.1]:18444
Mar 23, 2015 8:30:34 PM org.bitcoinj.core.PeerGroup discoverPeers
INFO: Peer discovery took 0msec and returned 0 items
Mar 23, 2015 8:30:34 PM org.bitcoinj.core.PeerGroup$3 go
INFO: Waiting 10001 msec before next connect attempt to [127.0.0.1]:18444
Mar 23, 2015 8:30:38 PM org.bitcoinj.core.PeerGroup$3 go
INFO: Waiting 5973 msec before next connect attempt to [127.0.0.1]:18444
Mar 23, 2015 8:30:41 PM org.bitcoinj.core.PeerGroup$3 go
INFO: Waiting 2595 msec before next connect attempt to [127.0.0.1]:18444
Mar 23, 2015 8:30:44 PM org.bitcoinj.core.PeerGroup connectTo
INFO: Attempting connection to [127.0.0.1]:18444     (0 connected, 1 pending, 1 
max)
Mar 23, 2015 8:30:44 PM org.bitcoinj.core.PeerGroup connectTo
INFO: Attempting connection to [127.0.0.1]:18444     (0 connected, 2 pending, 1 
max)
Mar 23, 2015 8:30:44 PM org.bitcoinj.net.NioClientManager handleKey
WARNING: Failed to connect with exception: java.net.ConnectException: 
Connection refused
Mar 23, 2015 8:30:44 PM org.bitcoinj.core.PeerGroup connectTo
INFO: Attempting connection to [127.0.0.1]:18444     (0 connected, 3 pending, 1 
max)
Mar 23, 2015 8:30:44 PM org.bitcoinj.core.PeerGroup handlePeerDeath

5) At this point I guess the bug is shown.

Peer.connectionClosed() calls peer listeners. One of the listeners is 
PeerGroup.PeerStartupListener which calls PeerGroup.handlePeerDeath() which 
adds the peer to the inactive pool.

The problem seems to be Peer.connectionClosed() is called several times.

Peer.connectionClosed() is called from NioClientManager thread  

Daemon Thread [NioClientManager] (Suspended (breakpoint at line 293 in Peer))   
    Peer.connectionClosed() line: 293   
    ConnectionHandler.connectionClosed() line: 188  
    ConnectionHandler.closeConnection() line: 174   
    ConnectionHandler.handleKey(SelectionKey) line: 211 
    NioClientManager.handleKey(SelectionKey) line: 86   
    NioClientManager.run() line: 122    
    AbstractExecutionThreadService$1$2.run() line: 60   
    Callables$3.run() line: 93  
    ContextPropagatingThreadFactory$1.run() line: 27    
    Thread.run() line: 745  

then again from NioClientManager thread with a different stack

Daemon Thread [NioClientManager] (Suspended (breakpoint at line 293 in Peer))   
    Peer.connectionClosed() line: 293   
    ConnectionHandler.connectionClosed() line: 188  
    ConnectionHandler.closeConnection() line: 174   
    NioClientManager.handleKey(SelectionKey) line: 81   
    NioClientManager.run() line: 122    
    AbstractExecutionThreadService$1$2.run() line: 60   
    Callables$3.run() line: 93  
    ContextPropagatingThreadFactory$1.run() line: 27    
    Thread.run() line: 745  

and then from AbstractTimeoutHandlerThread

Daemon Thread [AbstractTimeoutHandler timeouts] (Suspended (breakpoint at line 
293 in Peer))   
    Peer.connectionClosed() line: 293   
    Peer.timeoutOccurred() line: 287    
    AbstractTimeoutHandler$1.run() line: 75 
    TimerThread.mainLoop() line: 555    
    TimerThread.run() line: 505 

6) But let's continue... the logs go on...

INFO: [127.0.0.1]:18444: Peer died      (0 connected, 2 pending, 1 max)
Mar 23, 2015 8:30:44 PM org.bitcoinj.net.NioClientManager handleKey
WARNING: Failed to connect with exception: java.net.ConnectException: 
Connection refused
Mar 23, 2015 8:30:44 PM org.bitcoinj.core.PeerGroup handlePeerDeath
INFO: [127.0.0.1]:18444: Peer died      (0 connected, 1 pending, 1 max)
Mar 23, 2015 8:30:44 PM org.bitcoinj.net.NioClientManager handleKey
WARNING: Failed to connect with exception: java.net.ConnectException: 
Connection refused
Mar 23, 2015 8:30:44 PM org.bitcoinj.core.PeerGroup handlePeerDeath
INFO: [127.0.0.1]:18444: Peer died      (0 connected, 0 pending, 1 max)
Mar 23, 2015 8:30:44 PM org.bitcoinj.core.PeerGroup discoverPeers
INFO: Peer discovery took 0msec and returned 0 items
Mar 23, 2015 8:30:44 PM org.bitcoinj.core.PeerGroup$3 go
INFO: Waiting 17085 msec before next connect attempt to [127.0.0.1]:18444
Mar 23, 2015 8:30:49 PM org.bitcoinj.core.PeerSocketHandler timeoutOccurred
INFO: [127.0.0.1]:18444: Timed out
Mar 23, 2015 8:30:49 PM org.bitcoinj.core.PeerGroup handlePeerDeath
INFO: [127.0.0.1]:18444: Peer died      (0 connected, 0 pending, 1 max)
Mar 23, 2015 8:30:49 PM org.bitcoinj.core.PeerSocketHandler timeoutOccurred
INFO: [127.0.0.1]:18444: Timed out
Mar 23, 2015 8:30:49 PM org.bitcoinj.core.PeerGroup discoverPeers
INFO: Peer discovery took 0msec and returned 0 items
Mar 23, 2015 8:30:49 PM org.bitcoinj.core.PeerGroup handlePeerDeath
INFO: [127.0.0.1]:18444: Peer died      (0 connected, 0 pending, 1 max)
Mar 23, 2015 8:30:49 PM org.bitcoinj.core.PeerSocketHandler timeoutOccurred
INFO: [127.0.0.1]:18444: Timed out
Mar 23, 2015 8:30:49 PM org.bitcoinj.core.PeerGroup$3 go
INFO: Waiting 38446 msec before next connect attempt to [127.0.0.1]:18444
Mar 23, 2015 8:30:49 PM org.bitcoinj.core.PeerGroup discoverPeers
INFO: Peer discovery took 0msec and returned 0 items
Mar 23, 2015 8:30:49 PM org.bitcoinj.core.PeerGroup$3 go
INFO: Waiting 38441 msec before next connect attempt to [127.0.0.1]:18444
Mar 23, 2015 8:30:49 PM org.bitcoinj.core.PeerGroup handlePeerDeath
INFO: [127.0.0.1]:18444: Peer died      (0 connected, 0 pending, 1 max)
Mar 23, 2015 8:30:49 PM org.bitcoinj.core.PeerGroup discoverPeers
INFO: Peer discovery took 0msec and returned 0 items
Mar 23, 2015 8:30:49 PM org.bitcoinj.core.PeerGroup$3 go
INFO: Waiting 57664 msec before next connect attempt to [127.0.0.1]:18444
Mar 23, 2015 8:31:01 PM org.bitcoinj.core.PeerGroup discoverPeers
INFO: Peer discovery took 0msec and returned 0 items
Mar 23, 2015 8:31:01 PM org.bitcoinj.core.PeerGroup$3 go
INFO: Waiting 45581 msec before next connect attempt to [127.0.0.1]:18444

7) I restart bitcoind. The logs show:

Mar 23, 2015 8:31:27 PM org.bitcoinj.core.PeerGroup discoverPeers
INFO: Peer discovery took 0msec and returned 0 items
Mar 23, 2015 8:31:27 PM org.bitcoinj.core.PeerGroup$3 go
INFO: Waiting 19224 msec before next connect attempt to [127.0.0.1]:18444
Mar 23, 2015 8:31:27 PM org.bitcoinj.core.PeerGroup discoverPeers
INFO: Peer discovery took 0msec and returned 0 items
Mar 23, 2015 8:31:27 PM org.bitcoinj.core.PeerGroup$3 go
INFO: Waiting 19221 msec before next connect attempt to [127.0.0.1]:18444
Mar 23, 2015 8:31:46 PM org.bitcoinj.core.PeerGroup connectTo
INFO: Attempting connection to [127.0.0.1]:18444     (0 connected, 1 pending, 1 
max)
Mar 23, 2015 8:31:46 PM org.bitcoinj.net.NioClientManager handleKey
INFO: Successfully connected to /127.0.0.1:18444
Mar 23, 2015 8:31:46 PM org.bitcoinj.core.PeerGroup connectTo
INFO: Attempting connection to [127.0.0.1]:18444     (0 connected, 2 pending, 1 
max)
Mar 23, 2015 8:31:46 PM org.bitcoinj.core.Peer connectionOpened
INFO: Announcing to /127.0.0.1:18444 as: /bitcoinj:0.13-SNAPSHOT/
Mar 23, 2015 8:31:46 PM org.bitcoinj.core.PeerGroup connectTo
INFO: Attempting connection to [127.0.0.1]:18444     (0 connected, 3 pending, 1 
max)
Mar 23, 2015 8:31:46 PM org.bitcoinj.core.PeerGroup connectTo
INFO: Attempting connection to [127.0.0.1]:18444     (0 connected, 4 pending, 1 
max)
Mar 23, 2015 8:31:46 PM org.bitcoinj.net.NioClientManager handleKey
INFO: Successfully connected to /127.0.0.1:18444
Mar 23, 2015 8:31:46 PM org.bitcoinj.core.Peer connectionOpened
INFO: Announcing to /127.0.0.1:18444 as: /bitcoinj:0.13-SNAPSHOT/
Mar 23, 2015 8:31:46 PM org.bitcoinj.net.NioClientManager handleKey
INFO: Successfully connected to /127.0.0.1:18444
Mar 23, 2015 8:31:46 PM org.bitcoinj.core.Peer connectionOpened
INFO: Announcing to /127.0.0.1:18444 as: /bitcoinj:0.13-SNAPSHOT/
Mar 23, 2015 8:31:46 PM org.bitcoinj.net.NioClientManager handleKey
INFO: Successfully connected to /127.0.0.1:18444
Mar 23, 2015 8:31:46 PM org.bitcoinj.core.Peer connectionOpened
INFO: Announcing to /127.0.0.1:18444 as: /bitcoinj:0.13-SNAPSHOT/
Mar 23, 2015 8:31:46 PM org.bitcoinj.core.Peer processVersionMessage
INFO: Connected to 127.0.0.1: version=70002, subVer='/Satoshi:0.9.99/', 
services=0x1, time=2015-03-23 20:31:46, blocks=593
Mar 23, 2015 8:31:46 PM org.bitcoinj.core.PeerGroup handleNewPeer
INFO: [127.0.0.1]:18444: New peer      (1 connected, 3 pending, 1 max)
Mar 23, 2015 8:31:46 PM org.bitcoinj.core.PeerGroup setDownloadPeer
INFO: Setting download peer: [127.0.0.1]:18444
Mar 23, 2015 8:31:46 PM org.bitcoinj.core.Peer processVersionMessage
INFO: Connected to 127.0.0.1: version=70002, subVer='/Satoshi:0.9.99/', 
services=0x1, time=2015-03-23 20:31:46, blocks=593
Mar 23, 2015 8:31:46 PM org.bitcoinj.core.PeerGroup handleNewPeer
INFO: [127.0.0.1]:18444: New peer      (2 connected, 2 pending, 1 max)
Mar 23, 2015 8:31:46 PM org.bitcoinj.core.Peer processVersionMessage
INFO: Connected to 127.0.0.1: version=70002, subVer='/Satoshi:0.9.99/', 
services=0x1, time=2015-03-23 20:31:46, blocks=593
Mar 23, 2015 8:31:46 PM org.bitcoinj.core.PeerGroup handleNewPeer
INFO: [127.0.0.1]:18444: New peer      (3 connected, 1 pending, 1 max)
Mar 23, 2015 8:31:46 PM org.bitcoinj.core.Peer processVersionMessage
INFO: Connected to 127.0.0.1: version=70002, subVer='/Satoshi:0.9.99/', 
services=0x1, time=2015-03-23 20:31:46, blocks=593
Mar 23, 2015 8:31:46 PM org.bitcoinj.core.PeerGroup handleNewPeer
INFO: [127.0.0.1]:18444: New peer      (4 connected, 0 pending, 1 max)

8) As you can see bitcoinj is connected to 4 peers. All of them are local 
bitcoind

Original issue reported on code.google.com by oscar.gu...@gmail.com on 23 Mar 2015 at 11:59

GoogleCodeExporter commented 9 years ago 
Tested with code from master branch at this commit 
https://github.com/bitcoinj/bitcoinj/commit/2fd565c3669ef726d1eb591d5aa818007937
ea76

Original comment by oscar.gu...@gmail.com on 24 Mar 2015 at 12:04

GoogleCodeExporter commented 9 years ago

Original comment by andreas....@gmail.com on 24 Mar 2015 at 12:57

GoogleCodeExporter commented 9 years ago 
Actually I'm not sure it's a duplicate. Or rather the symptom may be the same 
but the cause is different.

Original comment by mh.in.en...@gmail.com on 27 Mar 2015 at 12:53