addnode RPC call taking a long time on regtest #15593

Issue description

addnode RPC call takes a very long time when adding a second connection on regtest.

Expected behaviour

I'm trying to connect multiple local bitcoind nodes on regtest. I'm doing this through the addnode RPC call. I expect these connections to become active more or less instantaneously, seeing as there is almost no data to sync and no real network latency.

My flow:

1. Start three bitcoind processes (see below for logs and config)
2. bitcoin-cli addnode localhost:<port for second node> add
3. bitcoin-cli addnode localhost:<port for third node> add

Actual behavior

The first connections resolves almost immediately. The second connection takes almost one minute to complete.

Relevant logs from first bitcoind process (the one receiving the addnode command):

2019-03-13T15:14:57Z ThreadRPCServer method=addnode user=__cookie__
2019-03-13T15:14:59Z trying connection localhost:6666 lastseen=0.0hrs
2019-03-13T15:14:59Z Added connection peer=0
2019-03-13T15:14:59Z sending version (104 bytes) peer=0
2019-03-13T15:14:59Z send version message: version 70015, blocks=0, us=[::]:0, peer=0
2019-03-13T15:14:59Z received: version (104 bytes) peer=0
2019-03-13T15:14:59Z sending verack (0 bytes) peer=0
2019-03-13T15:14:59Z sending getaddr (0 bytes) peer=0
2019-03-13T15:14:59Z receive version message: /Satoshi:0.17.0.1/: version 70015, blocks=0, us=[::]:0, peer=0
2019-03-13T15:14:59Z added time data, samples 2, offset +0 (+0 minutes)
2019-03-13T15:14:59Z received: verack (0 bytes) peer=0
2019-03-13T15:14:59Z New outbound peer connected: version: 70015, blocks=0, peer=0
2019-03-13T15:14:59Z sending sendheaders (0 bytes) peer=0
2019-03-13T15:14:59Z sending sendcmpct (9 bytes) peer=0
2019-03-13T15:14:59Z sending sendcmpct (9 bytes) peer=0
2019-03-13T15:14:59Z sending ping (8 bytes) peer=0
2019-03-13T15:14:59Z initial getheaders (0) to peer=0 (startheight:0)
2019-03-13T15:14:59Z sending getheaders (69 bytes) peer=0
2019-03-13T15:14:59Z sending feefilter (8 bytes) peer=0
2019-03-13T15:14:59Z received: sendheaders (0 bytes) peer=0
2019-03-13T15:14:59Z received: sendcmpct (9 bytes) peer=0
2019-03-13T15:14:59Z received: sendcmpct (9 bytes) peer=0
2019-03-13T15:14:59Z received: ping (8 bytes) peer=0
2019-03-13T15:14:59Z sending pong (8 bytes) peer=0
2019-03-13T15:14:59Z received: getheaders (69 bytes) peer=0
2019-03-13T15:14:59Z Ignoring getheaders from peer=0 because node is in initial block download
2019-03-13T15:14:59Z received: feefilter (8 bytes) peer=0
2019-03-13T15:14:59Z received: feefilter of 0.00001000 BTC/kB from peer=0
2019-03-13T15:14:59Z received: pong (8 bytes) peer=0
2019-03-13T15:15:07Z ThreadRPCServer method=addnode user=__cookie__
2019-03-13T15:15:42Z Adding fixed seed nodes as DNS doesn't seem to be available.
2019-03-13T15:15:59Z trying connection localhost:5555 lastseen=0.0hrs
2019-03-13T15:15:59Z Added connection peer=1

Relevant logs from the second node (the one being added in step 2):

2019-03-13T15:14:41Z init message: Starting network threads...
2019-03-13T15:14:41Z dnsseed thread start
2019-03-13T15:14:41Z Loading addresses from DNS seeds (could take a while)
2019-03-13T15:14:41Z 0 addresses found from DNS seeds
2019-03-13T15:14:41Z dnsseed thread exit
2019-03-13T15:14:41Z init message: Done loading
2019-03-13T15:14:41Z opencon thread start
2019-03-13T15:14:41Z net thread start
2019-03-13T15:14:41Z msghand thread start
2019-03-13T15:14:41Z addcon thread start
2019-03-13T15:14:59Z Added connection peer=0
2019-03-13T15:14:59Z connection from 127.0.0.1:52358 accepted

Relevant logs from the third node (the one being added in step 3):

2019-03-13T15:14:41Z init message: Starting network threads...
2019-03-13T15:14:41Z net thread start
2019-03-13T15:14:41Z dnsseed thread start
2019-03-13T15:14:41Z addcon thread start
2019-03-13T15:14:41Z Loading addresses from DNS seeds (could take a while)
2019-03-13T15:14:41Z 0 addresses found from DNS seeds
2019-03-13T15:14:41Z opencon thread start
2019-03-13T15:14:41Z init message: Done loading
2019-03-13T15:14:41Z dnsseed thread exit
2019-03-13T15:14:41Z msghand thread start
2019-03-13T15:15:42Z Adding fixed seed nodes as DNS doesn't seem to be available.
2019-03-13T15:15:59Z Added connection peer=0
2019-03-13T15:15:59Z connection from 127.0.0.1:35740 accepted

<!--- How reliably can you reproduce the issue, what are the steps to do so? -->

Reproducing

I'm able to reproduce this consitently. Here's the config file for the bitcoind instances:

First:

regtest=1
server=1
debug=rpc
debug=net
daemon=1

rpcport=18350
port=7777

Second:

regtest=1
server=1
debug=rpc
debug=net
daemon=1

rpcport=18336
port=6666

Third:

regtest=1
server=1
debug=rpc
debug=net
daemon=1

rpcport=18336
port=6666

Bitcoin Core version

I've been able to reproduce this issue with both 0.16.3 and 0.17.0.1. The binaries were downloaded from bitcoincore.org.

Machine type

Ubuntu 18.10 x86_64

Thanks for the report. Does all 3 nodes share the same datadir? Have you tried separate hosts?

@torkelrogstad looks like this is expected, 60 seconds passed between the 2 added nodes. Relevant code is: https://github.com/bitcoin/bitcoin/blob/7b13c646457980f44599412f243694fa682a1abf/src/net.cpp#L1878-L1903

I suggest to call both addnode in a row.

You can close this, and if you feel this behavior should be changed please open a new issue.