Confusing log order regarding DNS seeds #18332

I just started a mainnet node (which had been dormant for a while) and saw the following:

2020-03-12T13:32:33Z Loading addresses from DNS seed seed.bitcoin.jonasschnelli.ch
2020-03-12T13:32:34Z Loading addresses from DNS seed seed.btc.petertodd.org
2020-03-12T13:32:34Z Loading addresses from DNS seed dnsseed.bitcoin.dashjr.org
2020-03-12T13:32:46Z Loading addresses from DNS seed seed.bitcoin.sprovoost.nl
2020-03-12T13:32:46Z Loading addresses from DNS seed dnsseed.emzy.de
2020-03-12T13:32:46Z Loading addresses from DNS seed dnsseed.bluematt.me
2020-03-12T13:32:51Z New outbound peer connected: version: 70015, blocks=621347, peer=0 (full-relay)
2020-03-12T13:32:52Z New outbound peer connected: version: 70015, blocks=621347, peer=1 (full-relay)
2020-03-12T13:32:52Z Synchronizing blockheaders, height: 618802 (~99.61%)
2020-03-12T13:32:53Z Synchronizing blockheaders, height: 620802 (~99.91%)
2020-03-12T13:32:53Z New outbound peer connected: version: 70015, blocks=621347, peer=2 (full-relay)
2020-03-12T13:32:58Z P2P peers available. Skipped DNS seeding.

I'm not sure if this is actually a bug or not, but it looks a bit strange to me: First it queries all the DNS seeds, makes outgoing connections, then concludes "P2P peers available. Skipped DNS seeding." Isn't it a bit late for that?

Ok, I see, this happens in the same loop in CConnman::ThreadDNSAddressSeed() . https://github.com/bitcoin/bitcoin/blob/master/src/net.cpp#L1605

It goes through the seeds in random order, querying them and adding their results, then stops when there are at least a few connections. It's just the message that is confusing, it would be better to say something like "stopped DNS seeding" instead of "skipped DNS seeding" if at least one seed was queried.

cc @ajtowns

#16939 changes this to "nnn addresses found from DNS seeds \n P2P peers available. Finished DNS seeding." in the case where some addresses were found.

I can reproduce this post-16939 merge.

Steps:

• make sure you don't have a peers.dat
• start node

2020-08-10T22:25:36Z dnsseed thread start
2020-08-10T22:25:36Z Loading addresses from DNS seed seed.testnet.bitcoin.sprovoost.nl
2020-08-10T22:25:36Z opencon thread start
2020-08-10T22:25:36Z msghand thread start
2020-08-10T22:25:36Z init message: Done loading
2020-08-10T22:25:36Z Loading addresses from DNS seed seed.tbtc.petertodd.org
2020-08-10T22:25:36Z Loading addresses from DNS seed testnet-seed.bitcoin.jonasschnelli.ch
2020-08-10T22:25:38Z New outbound peer connected: version: 70015, blocks=1806673, peer=0 (full-relay)
2020-08-10T22:25:38Z Synchronizing blockheaders, height: 69997 (~15.45%)
2020-08-10T22:25:39Z Synchronizing blockheaders, height: 71997 (~15.87%)
2020-08-10T22:25:39Z Synchronizing blockheaders, height: 73997 (~16.26%)
2020-08-10T22:25:40Z Loading addresses from DNS seed testnet-seed.bluematt.me
2020-08-10T22:25:40Z 70 addresses found from DNS seeds
2020-08-10T22:25:40Z dnsseed thread exit
...

• Shut down node, mid-sync
• Restart node

2020-08-10T22:27:15Z Loaded 3621 addresses from peers.dat  27ms
2020-08-10T22:27:15Z init message: Starting network threads...
2020-08-10T22:27:15Z net thread start
2020-08-10T22:27:15Z dnsseed thread start
2020-08-10T22:27:15Z addcon thread start
2020-08-10T22:27:15Z opencon thread start
2020-08-10T22:27:15Z msghand thread start
2020-08-10T22:27:15Z init message: Done loading
2020-08-10T22:27:15Z Waiting 300 seconds before querying DNS seeds.
2020-08-10T22:27:17Z New outbound peer connected: version: 70015, blocks=1806673, peer=0 (full-relay)
2020-08-10T22:27:19Z Synchronizing blockheaders, height: 297996 (~49.20%)
...
2020-08-10T22:27:29Z New outbound peer connected: version: 70015, blocks=1806673, peer=1 (full-relay)
2020-08-10T22:27:29Z New outbound peer connected: version: 70015, blocks=1806673, peer=2 (full-relay)
...
2020-08-10T22:27:37Z P2P peers available. Skipped DNS seeding.
2020-08-10T22:27:37Z dnsseed thread exit

I added some more logging and here's my best guess at what's going on:

1. start node and it goes out and checks for seeds and if successful seeds_right_now > 0 so this code path is skipped.

   <details><summary>log</summary>

2020-08-14T16:30:39Z init message: Starting network threads...
...
2020-08-14T16:30:39Z dnsseed thread start
...
2020-08-14T16:30:39Z 4 seeds_right_now line 1631
2020-08-14T16:30:39Z Loading addresses from DNS seed seed.tbtc.petertodd.org
2020-08-14T16:30:39Z 0 incrementing DNS seeds on line 1695
...
2020-08-14T16:30:39Z 22 incrementing DNS seeds on line 1695
2020-08-14T16:30:39Z 3 seeds_right_now line 1631
2020-08-14T16:30:39Z Loading addresses from DNS seed testnet-seed.bitcoin.jonasschnelli.ch
2020-08-14T16:30:39Z 23 incrementing DNS seeds on line 1695
...
2020-08-14T16:30:39Z 44 incrementing DNS seeds on line 1695
2020-08-14T16:30:39Z 2 seeds_right_now line 1631
2020-08-14T16:30:39Z Loading addresses from DNS seed testnet-seed.bluematt.me
2020-08-14T16:30:39Z 45 incrementing DNS seeds on line 1695
2020-08-14T16:30:39Z 46 incrementing DNS seeds on line 1695
2020-08-14T16:30:39Z 47 incrementing DNS seeds on line 1695
2020-08-14T16:30:39Z 1 seeds_right_now line 1631
2020-08-14T16:30:39Z Loading addresses from DNS seed seed.testnet.bitcoin.sprovoost.nl
2020-08-14T16:30:39Z 48 incrementing DNS seeds on line 1695
...
2020-08-14T16:30:39Z 69 incrementing DNS seeds on line 1695
2020-08-14T16:30:39Z 70 addresses found from DNS seeds
2020-08-14T16:30:39Z dnsseed thread exit

</details>

2. shutdown and restart

3. Now you have a bunch of addresses loaded from peers.dat, this time seeds_right_now == 0, new outbound connections start being made, nRelevant == lots (6 for me), but found == 0. So you get the wrong message.

   <details><summary>log</summary> The specific line numbers may vary, but this is the idea:

2020-08-14T16:30:58Z init message: Loading P2P addresses...
2020-08-14T16:30:58Z Loaded 947 addresses from peers.dat  7ms
2020-08-14T16:30:58Z init message: Starting network threads...
2020-08-14T16:30:58Z dnsseed thread start
...
2020-08-14T16:30:58Z 0 seeds_right_now line 1631
2020-08-14T16:30:58Z Waiting 11 seconds before querying DNS seeds.
2020-08-14T16:30:59Z New outbound peer connected: version: 70015, blocks=1414448, peer=0 (full-relay)
2020-08-14T16:30:59Z Synchronizing blockheaders, height: 13999 (~3.14%)
...
2020-08-14T16:31:09Z 6 nRelevant found line 1652
2020-08-14T16:31:09Z 0 addresses found from DNS seeds on line 1653
2020-08-14T16:31:09Z P2P peers available. Skipped DNS seeding.
2020-08-14T16:31:09Z dnsseed thread exit

</details>

So you get the wrong message.

Which message do you mean? In the first run, DNS seeds were queried and the message "70 addresses found from DNS seeds" seems correct. Then, in the restart run, no DNS seeds were queried because connections were made to addrman peers - so the message "P2P peers available. Skipped DNS seeding." - seems accurate too.

Or is the issue that "Skipped DNS seeding" might more precisely be "No DNS seeds were queried" because the dnsseed thread still gets started and stopped, only the actual querying part was skipped?

I think this can be close now that the log messages are no longer returned in a confusing way since #16939:

2023-03-13T14:30:03Z 0 block-relay-only anchors will be tried for connections.
2023-03-13T14:30:03Z init message: Starting network threads…
2023-03-13T14:30:03Z dnsseed thread start
2023-03-13T14:30:03Z init message: Done loading
2023-03-13T14:30:03Z opencon thread start
2023-03-13T14:30:03Z Loading addresses from DNS seed seed.bitcoin.sprovoost.nl.
2023-03-13T14:30:03Z net thread start
2023-03-13T14:30:03Z msghand thread start
2023-03-13T14:30:03Z addcon thread start
2023-03-13T14:30:03Z [tor] Got service ID 3kwltujshw3zphtzh24hdyl6gkodrrilsq4urqot5wxy6rg5bc3m5aqd, advertising service 3kwltujshw3zphtzh24hdyl6gkodrrilsq4urqot5wxy6rg5bc3m5aqd.onion:8333
2023-03-13T14:30:03Z AddLocal(3kwltujshw3zphtzh24hdyl6gkodrrilsq4urqot5wxy6rg5bc3m5aqd.onion:8333,4)
2023-03-13T14:30:04Z Loading addresses from DNS seed dnsseed.emzy.de.
2023-03-13T14:30:04Z Loading addresses from DNS seed seed.bitcoin.jonasschnelli.ch.
2023-03-13T14:30:04Z Loading addresses from DNS seed dnsseed.bluematt.me.
2023-03-13T14:30:05Z New outbound peer connected: version: 70016, blocks=780638, peer=0 (outbound-full-relay)
2023-03-13T14:30:05Z Loading addresses from DNS seed seed.btc.petertodd.org.
2023-03-13T14:30:05Z New outbound peer connected: version: 70016, blocks=780638, peer=1 (outbound-full-relay)
2023-03-13T14:30:05Z Loading addresses from DNS seed dnsseed.bitcoin.dashjr.org.
2023-03-13T14:30:06Z Loading addresses from DNS seed seed.bitcoin.wiz.biz.
2023-03-13T14:30:06Z Pre-synchronizing blockheaders, height: 2000 (~0.27%)
2023-03-13T14:30:06Z Pre-synchronizing blockheaders, height: 4000 (~0.54%)
2023-03-13T14:30:06Z New outbound peer connected: version: 70016, blocks=780638, peer=2 (outbound-full-relay)
2023-03-13T14:30:07Z Pre-synchronizing blockheaders, height: 6000 (~0.81%)
2023-03-13T14:30:07Z Pre-synchronizing blockheaders, height: 8000 (~1.08%)
2023-03-13T14:30:07Z New outbound peer connected: version: 70016, blocks=780638, peer=3 (outbound-full-relay)
2023-03-13T14:30:07Z Pre-synchronizing blockheaders, height: 10000 (~1.35%)
2023-03-13T14:30:07Z Loading addresses from DNS seed seed.bitcoinstats.com.
2023-03-13T14:30:07Z Pre-synchronizing blockheaders, height: 12000 (~1.62%)
2023-03-13T14:30:07Z Loading addresses from DNS seed seed.bitcoin.sipa.be.
2023-03-13T14:30:08Z Pre-synchronizing blockheaders, height: 14000 (~1.89%)
2023-03-13T14:30:08Z 317 addresses found from DNS seeds
2023-03-13T14:30:08Z dnsseed thread exit

Closing as per the two previous comments that this is fixed.