Node won't serve blocks when connect=0, listen=1 set due to IBD logic #25048

I have a 2 machine setup on my local network that I use for testing and I've performed dozens of syncs without any issues until recently.

I have a node on a laptop that is configured not to make any outbound connections via connect=0 but does listen for connections via listen=1. This node, as a result, never downloads new blocks.

I then run a node on a desktop that it set to ONLY connect to the laptop node via connect=<local network IP>

Expected behavior

This node then downloads all of the blocks it can from the laptop node and then stops. This has been the case for many months of testing I've performed.

Actual behavior

However, when trying to run a test recently, the desktop node wasn't syncing. After enabling net debugging I see that the laptop node is deciding not to serve any blocks because it considers itself to be in IBD. This is odd because it's unclear WHY it would know that there are more blocks available out on the network when it is explicitly told not to connect to any peers.

To reproduce

Hard to reproduce this far. Easy to fix by having the main node connect to other peers and sync to chain tip.

System information

Bitcoin Core 23.0 on Debian, official build

<!-- Any extra information that might be useful in the debugging process. -->

Example startup log from previous testing runs that went as expected. I find it interesting that it says "progress=0.999996"

<pre> 2022-02-12T17:35:39Z Bitcoin Core version v22.0.0 (release build) 2022-02-12T17:35:39Z Assuming ancestors of block 00000000000000000008a89e854d57e5667df88f1cdef6fde2fbca1de5b639ad have valid signatures. 2022-02-12T17:35:39Z Setting nMinimumChainWork=00000000000000000000000000000000000000001fa4663bbbe19f82de910280 2022-02-12T17:35:39Z Using the 'sse4(1way),sse41(4way),avx2(8way)' SHA256 implementation 2022-02-12T17:35:39Z Using RdSeed as additional entropy source 2022-02-12T17:35:39Z Using RdRand as an additional entropy source 2022-02-12T17:35:39Z Default data directory /home/jameson/.bitcoin 2022-02-12T17:35:39Z Using data directory /media/jameson/Blockchain/bitcoin 2022-02-12T17:35:39Z Config file: /media/jameson/Blockchain/bitcoin/bitcoin.conf (not found, skipping) 2022-02-12T17:35:39Z Config file arg: blockfilterindex="1" 2022-02-12T17:35:39Z Config file arg: connect="0" 2022-02-12T17:35:39Z Config file arg: datadir="/media/jameson/Blockchain/bitcoin" 2022-02-12T17:35:39Z Config file arg: dns="0" 2022-02-12T17:35:39Z Config file arg: dnsseed="0" 2022-02-12T17:35:39Z Config file arg: listen="1" 2022-02-12T17:35:39Z Config file arg: rpcauth=**** 2022-02-12T17:35:39Z Config file arg: rpcthreads="12" 2022-02-12T17:35:39Z Config file arg: rpcworkqueue="48" 2022-02-12T17:35:39Z Config file arg: server="1" 2022-02-12T17:35:39Z Config file arg: txindex="1" 2022-02-12T17:35:39Z Config file arg: wallet="0" 2022-02-12T17:35:39Z Config file arg: zmqpubrawblock="tcp://127.0.0.1:28332" 2022-02-12T17:35:39Z Config file arg: zmqpubrawtx="tcp://127.0.0.1:28333" 2022-02-12T17:35:39Z Command-line arg: daemon="" 2022-02-12T17:35:39Z Using at most 125 automatic connections (1024 file descriptors available) 2022-02-12T17:35:39Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements 2022-02-12T17:35:39Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements 2022-02-12T17:35:39Z Script verification uses 11 additional threads 2022-02-12T17:35:39Z scheduler thread start 2022-02-12T17:35:39Z HTTP: creating work queue of depth 48 2022-02-12T17:35:39Z Using random cookie authentication. 2022-02-12T17:35:39Z Generated RPC authentication cookie /media/jameson/Blockchain/bitcoin/.cookie 2022-02-12T17:35:39Z Using rpcauth authentication. 2022-02-12T17:35:39Z HTTP: starting 12 worker threads 2022-02-12T17:35:39Z Using wallet directory /media/jameson/Blockchain/bitcoin 2022-02-12T17:35:39Z init message: Verifying wallet(s)… 2022-02-12T17:35:39Z Warning: Skipping -wallet path that doesn't exist. Failed to load database path '/media/jameson/Blockchain/bitcoin/0'. Path does not exist. 2022-02-12T17:35:39Z init message: Loading banlist… 2022-02-12T17:35:39Z SetNetworkActive: true 2022-02-12T17:35:39Z Using /16 prefix for IP bucketing 2022-02-12T17:35:39Z Cache configuration: 2022-02-12T17:35:39Z * Using 2.0 MiB for block index database 2022-02-12T17:35:39Z * Using 56.0 MiB for transaction index database 2022-02-12T17:35:39Z * Using 49.0 MiB for basic block filter index database 2022-02-12T17:35:39Z * Using 8.0 MiB for chain state database 2022-02-12T17:35:39Z * Using 335.0 MiB for in-memory UTXO set (plus up to 286.1 MiB of unused mempool space) 2022-02-12T17:35:39Z init message: Loading block index… 2022-02-12T17:35:39Z Switching active chainstate to Chainstate [ibd] @ height -1 (null) 2022-02-12T17:35:39Z Opening LevelDB in /media/jameson/Blockchain/bitcoin/blocks/index 2022-02-12T17:35:39Z Opened LevelDB successfully 2022-02-12T17:35:39Z Using obfuscation key for /media/jameson/Blockchain/bitcoin/blocks/index: 0000000000000000 2022-02-12T17:35:42Z LoadBlockIndexDB: last block file = 2921 2022-02-12T17:35:42Z LoadBlockIndexDB: last block file info: CBlockFileInfo(blocks=32, size=50279941, heights=722928...722965, time=2022-02-12...2022-02-12) 2022-02-12T17:35:42Z Checking all blk files are present... 2022-02-12T17:35:42Z Opening LevelDB in /media/jameson/Blockchain/bitcoin/chainstate 2022-02-12T17:35:42Z Opened LevelDB successfully 2022-02-12T17:35:42Z Using obfuscation key for /media/jameson/Blockchain/bitcoin/chainstate: 05e83c6994e2e4d1 2022-02-12T17:35:42Z Loaded best chain: hashBestChain=00000000000000000008c2190b3b7f475db5a19123e8e19da20af0629e3aeaa1 height=722965 date=2022-02-12T17:14:26Z progress=0.999996 2022-02-12T17:35:42Z init message: Verifying blocks… 2022-02-12T17:35:42Z Verifying last 6 blocks at level 3 2022-02-12T17:35:42Z [0%]...[16%]...[33%]...[50%]...[66%]...[83%]...[99%]...[DONE]. 2022-02-12T17:35:42Z No coin database inconsistencies in last 6 blocks (9180 transactions) 2022-02-12T17:35:42Z block index 3455ms 2022-02-12T17:35:42Z Opening LevelDB in /media/jameson/Blockchain/bitcoin/indexes/txindex 2022-02-12T17:35:42Z Opened LevelDB successfully 2022-02-12T17:35:42Z Using obfuscation key for /media/jameson/Blockchain/bitcoin/indexes/txindex: 0000000000000000 2022-02-12T17:35:42Z txindex thread start 2022-02-12T17:35:42Z txindex is enabled at height 722965 2022-02-12T17:35:42Z txindex thread exit 2022-02-12T17:35:42Z Opening LevelDB in /media/jameson/Blockchain/bitcoin/indexes/blockfilter/basic/db 2022-02-12T17:35:42Z Opened LevelDB successfully 2022-02-12T17:35:42Z Using obfuscation key for /media/jameson/Blockchain/bitcoin/indexes/blockfilter/basic/db: 0000000000000000 2022-02-12T17:35:42Z basic block filter index thread start 2022-02-12T17:35:42Z basic block filter index is enabled at height 722965 2022-02-12T17:35:42Z basic block filter index thread exit 2022-02-12T17:35:42Z block tree size = 722968 2022-02-12T17:35:42Z nBestHeight = 722965 2022-02-12T17:35:42Z loadblk thread start 2022-02-12T17:35:42Z Bound to 127.0.0.1:8334 2022-02-12T17:35:42Z Bound to [::]:8333 2022-02-12T17:35:42Z Bound to 0.0.0.0:8333 2022-02-12T17:35:42Z torcontrol thread start 2022-02-12T17:35:42Z init message: Loading P2P addresses… 2022-02-12T17:35:42Z Leaving InitialBlockDownload (latching to false) 2022-02-12T17:35:42Z Loaded 62684 addresses from peers.dat 122ms 2022-02-12T17:35:42Z init message: Starting network threads… 2022-02-12T17:35:42Z DNS seeding disabled 2022-02-12T17:35:42Z init message: Done loading 2022-02-12T17:35:42Z addcon thread start 2022-02-12T17:35:42Z net thread start 2022-02-12T17:35:42Z msghand thread start 2022-02-12T17:35:44Z Imported mempool transactions from disk: 781 succeeded, 0 failed, 0 expired, 0 already there, 0 waiting for initial broadcast 2022-02-12T17:35:44Z loadblk thread exit </pre>

Here's the network debug log; note it says "progress=0.982959" Why did this change if the node was instructed to never connect to any other nodes outside of my LAN?

<pre> 2022-04-29T14:11:22Z Bitcoin Core version v23.0.0 (release build) 2022-04-29T14:11:22Z Assuming ancestors of block 000000000000000000052d314a259755ca65944e68df6b12a067ea8f1f5a7091 have valid signatures. 2022-04-29T14:11:22Z Setting nMinimumChainWork=00000000000000000000000000000000000000002927cdceccbd5209e81e80db 2022-04-29T14:11:22Z Using the 'sse4(1way),sse41(4way),avx2(8way)' SHA256 implementation 2022-04-29T14:11:22Z Using RdSeed as additional entropy source 2022-04-29T14:11:22Z Using RdRand as an additional entropy source 2022-04-29T14:11:22Z Default data directory /home/jameson/.bitcoin 2022-04-29T14:11:22Z Using data directory /media/jameson/Blockchain/bitcoin 2022-04-29T14:11:22Z Config file: /media/jameson/Blockchain/bitcoin/bitcoin.conf (not found, skipping) 2022-04-29T14:11:22Z Config file arg: blockfilterindex="1" 2022-04-29T14:11:22Z Config file arg: connect="0" 2022-04-29T14:11:22Z Config file arg: datadir="/media/jameson/Blockchain/bitcoin" 2022-04-29T14:11:22Z Config file arg: debug="net" 2022-04-29T14:11:22Z Config file arg: dns="0" 2022-04-29T14:11:22Z Config file arg: dnsseed="0" 2022-04-29T14:11:22Z Config file arg: listen="1" 2022-04-29T14:11:22Z Config file arg: rpcauth=**** 2022-04-29T14:11:22Z Config file arg: rpcthreads="12" 2022-04-29T14:11:22Z Config file arg: rpcworkqueue="48" 2022-04-29T14:11:22Z Config file arg: server="1" 2022-04-29T14:11:22Z Config file arg: txindex="1" 2022-04-29T14:11:22Z Config file arg: wallet="0" 2022-04-29T14:11:22Z Config file arg: zmqpubrawblock="tcp://127.0.0.1:28332" 2022-04-29T14:11:22Z Config file arg: zmqpubrawtx="tcp://127.0.0.1:28333" 2022-04-29T14:11:22Z Command-line arg: daemon="" 2022-04-29T14:11:22Z Using at most 125 automatic connections (1024 file descriptors available) 2022-04-29T14:11:22Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements 2022-04-29T14:11:22Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements 2022-04-29T14:11:22Z Script verification uses 11 additional threads 2022-04-29T14:11:22Z scheduler thread start 2022-04-29T14:11:22Z HTTP: creating work queue of depth 48 2022-04-29T14:11:22Z Using random cookie authentication. 2022-04-29T14:11:22Z Generated RPC authentication cookie /media/jameson/Blockchain/bitcoin/.cookie 2022-04-29T14:11:22Z Using rpcauth authentication. 2022-04-29T14:11:22Z HTTP: starting 12 worker threads 2022-04-29T14:11:22Z Using wallet directory /media/jameson/Blockchain/bitcoin 2022-04-29T14:11:22Z init message: Verifying wallet(s)… 2022-04-29T14:11:22Z Warning: Skipping -wallet path that doesn't exist. Failed to load database path '/media/jameson/Blockchain/bitcoin/0'. Path does not exist. 2022-04-29T14:11:22Z Using /16 prefix for IP bucketing 2022-04-29T14:11:22Z init message: Loading P2P addresses… 2022-04-29T14:11:22Z Loaded 0 addresses from peers.dat 0ms 2022-04-29T14:11:22Z init message: Loading banlist… 2022-04-29T14:11:22Z banlist.dat ignored because it can only be read by Bitcoin Core version 22.x. Remove "/media/jameson/Blockchain/bitcoin/banlist.dat" to silence this warning. 2022-04-29T14:11:22Z Loaded 0 banned node addresses/subnets 0ms 2022-04-29T14:11:22Z net: setting try another outbound peer=false 2022-04-29T14:11:22Z SetNetworkActive: true 2022-04-29T14:11:22Z Cache configuration: 2022-04-29T14:11:22Z * Using 2.0 MiB for block index database 2022-04-29T14:11:22Z * Using 56.0 MiB for transaction index database 2022-04-29T14:11:22Z * Using 49.0 MiB for basic block filter index database 2022-04-29T14:11:22Z * Using 8.0 MiB for chain state database 2022-04-29T14:11:22Z * Using 335.0 MiB for in-memory UTXO set (plus up to 286.1 MiB of unused mempool space) 2022-04-29T14:11:22Z init message: Loading block index… 2022-04-29T14:11:22Z Switching active chainstate to Chainstate [ibd] @ height -1 (null) 2022-04-29T14:11:22Z Opening LevelDB in /media/jameson/Blockchain/bitcoin/blocks/index 2022-04-29T14:11:22Z Opened LevelDB successfully 2022-04-29T14:11:22Z Using obfuscation key for /media/jameson/Blockchain/bitcoin/blocks/index: 0000000000000000 2022-04-29T14:11:25Z LoadBlockIndexDB: last block file = 2954 2022-04-29T14:11:25Z LoadBlockIndexDB: last block file info: CBlockFileInfo(blocks=50, size=67330220, heights=726115...726749, time=2022-03-06...2022-03-10) 2022-04-29T14:11:25Z Checking all blk files are present... 2022-04-29T14:11:25Z Opening LevelDB in /media/jameson/Blockchain/bitcoin/chainstate 2022-04-29T14:11:25Z Opened LevelDB successfully 2022-04-29T14:11:25Z Using obfuscation key for /media/jameson/Blockchain/bitcoin/chainstate: 05e83c6994e2e4d1 2022-04-29T14:11:25Z Loaded best chain: hashBestChain=000000000000000000014ccfdf28b7b062aec08384456eba68e2070fc61ec811 height=726750 date=2022-03-10T20:26:32Z progress=0.982959 2022-04-29T14:11:25Z init message: Verifying blocks… 2022-04-29T14:11:25Z Verifying last 6 blocks at level 3 2022-04-29T14:11:25Z [0%]...[16%]...[33%]...[50%]...[66%]...[83%]...[99%]...[DONE]. 2022-04-29T14:11:26Z No coin database inconsistencies in last 6 blocks (9585 transactions) 2022-04-29T14:11:26Z block index 3744ms 2022-04-29T14:11:26Z Opening LevelDB in /media/jameson/Blockchain/bitcoin/indexes/txindex 2022-04-29T14:11:26Z Opened LevelDB successfully 2022-04-29T14:11:26Z Using obfuscation key for /media/jameson/Blockchain/bitcoin/indexes/txindex: 0000000000000000 2022-04-29T14:11:26Z txindex thread start 2022-04-29T14:11:26Z txindex is enabled at height 726750 2022-04-29T14:11:26Z txindex thread exit 2022-04-29T14:11:26Z Opening LevelDB in /media/jameson/Blockchain/bitcoin/indexes/blockfilter/basic/db 2022-04-29T14:11:26Z Opened LevelDB successfully 2022-04-29T14:11:26Z Using obfuscation key for /media/jameson/Blockchain/bitcoin/indexes/blockfilter/basic/db: 0000000000000000 2022-04-29T14:11:26Z block tree size = 726753 2022-04-29T14:11:26Z nBestHeight = 726750 2022-04-29T14:11:26Z basic block filter index thread start 2022-04-29T14:11:26Z basic block filter index is enabled at height 726750 2022-04-29T14:11:26Z basic block filter index thread exit 2022-04-29T14:11:26Z loadblk thread start 2022-04-29T14:11:26Z torcontrol thread start 2022-04-29T14:11:26Z Imported mempool transactions from disk: 0 succeeded, 0 failed, 0 expired, 0 already there, 0 waiting for initial broadcast 2022-04-29T14:11:26Z loadblk thread exit 2022-04-29T14:11:26Z Bound to 127.0.0.1:8334 2022-04-29T14:11:26Z Bound to [::]:8333 2022-04-29T14:11:26Z Bound to 0.0.0.0:8333 2022-04-29T14:11:26Z init message: Starting network threads… 2022-04-29T14:11:26Z DNS seeding disabled 2022-04-29T14:11:26Z init message: Done loading 2022-04-29T14:11:26Z net thread start 2022-04-29T14:11:26Z addcon thread start 2022-04-29T14:11:26Z msghand thread start 2022-04-29T14:11:52Z Added connection peer=0 2022-04-29T14:11:52Z connection from 192.168.2.42:53516 accepted 2022-04-29T14:11:52Z received: version (102 bytes) peer=0 2022-04-29T14:11:52Z sending version (102 bytes) peer=0 2022-04-29T14:11:52Z send version message: version 70016, blocks=726750, txrelay=1, peer=0 2022-04-29T14:11:52Z sending wtxidrelay (0 bytes) peer=0 2022-04-29T14:11:52Z sending sendaddrv2 (0 bytes) peer=0 2022-04-29T14:11:52Z sending verack (0 bytes) peer=0 2022-04-29T14:11:52Z receive version message: /Satoshi:0.21.2/: version 70016, blocks=0, us=[::]:0, txrelay=1, peer=0 2022-04-29T14:11:52Z received: wtxidrelay (0 bytes) peer=0 2022-04-29T14:11:52Z received: sendaddrv2 (0 bytes) peer=0 2022-04-29T14:11:52Z received: verack (0 bytes) peer=0 2022-04-29T14:11:52Z sending sendheaders (0 bytes) peer=0 2022-04-29T14:11:52Z sending sendcmpct (9 bytes) peer=0 2022-04-29T14:11:52Z sending sendcmpct (9 bytes) peer=0 2022-04-29T14:11:52Z sending ping (8 bytes) peer=0 2022-04-29T14:11:52Z initial getheaders (726749) to peer=0 (startheight:0) 2022-04-29T14:11:52Z sending getheaders (1029 bytes) peer=0 2022-04-29T14:11:52Z sending feefilter (8 bytes) peer=0 2022-04-29T14:11:52Z received: getaddr (0 bytes) peer=0 2022-04-29T14:11:52Z received: sendheaders (0 bytes) peer=0 2022-04-29T14:11:52Z received: sendcmpct (9 bytes) peer=0 2022-04-29T14:11:52Z received: sendcmpct (9 bytes) peer=0 2022-04-29T14:11:52Z received: ping (8 bytes) peer=0 2022-04-29T14:11:52Z sending pong (8 bytes) peer=0 2022-04-29T14:11:52Z received: getheaders (69 bytes) peer=0 2022-04-29T14:11:52Z Ignoring getheaders from peer=0 because node is in initial block download 2022-04-29T14:11:52Z received: feefilter (8 bytes) peer=0 2022-04-29T14:11:52Z received: feefilter of 0.09170997 BTC/kvB from peer=0 2022-04-29T14:11:52Z received: pong (8 bytes) peer=0 2022-04-29T14:12:48Z socket closed for peer=0 2022-04-29T14:12:48Z disconnecting peer=0 2022-04-29T14:12:48Z Cleared nodestate for peer=0 </pre>

Looking at the code, it should be possible to restart the node that thinks it is in IBD and assign inbound connections the download flag:

src/net_processing.cpp-        if (m_chainman.ActiveChainstate().IsInitialBlockDownload() && !pfrom.HasPermission(NetPermissionFlags::Download)) {
src/net_processing.cpp:            LogPrint(BCLog::NET, "Ignoring getheaders from peer=%d because node is in initial block download\n", pfrom.GetId());
src/net_processing.cpp-            return;
src/net_processing.cpp-        }

I guess there are 2 questions / issues posed by my report:

1. How would a node that (is not supposed to) ever connect to nodes on the public network get into a state where it considers itself in IBD?
2. If a node thinks it is in IBD but has "connect=0" then shouldn't the node consider itself NOT in IBD and thus serve blocks if a connected node requests it? This one is a bit trickier.

As for your first question, see here: the node compares the timestamp of its best block with the system time and considers itself in IBD when the time difference is >24h (DEFAULT_MAX_TIP_AGE).

DEFAULT_MAX_TIP_AGE

Right. So yet another workaround would be to pass the -maxtipage option

If a node thinks it is in IBD but has "connect=0" then shouldn't the node consider itself NOT in IBD and thus serve blocks if a connected node requests it?

IBD + "connect=0" = "I don't know what the most-work chain is, and also know that I have no way of catching up." Doesn't seem like it should be serving blocks?

As for your first question, see here: the node compares the timestamp of its best block with the system time and considers itself in IBD when the time difference is >24h (DEFAULT_MAX_TIP_AGE).

Interesting, but now this is even more confusing. Because I've been running these tests on my local network for the past ~9 months and never ran into this issue until last week. My computers all have up to date system times.

The maxtipage option sounds like a sufficient workaround; I'll try that.

Looks like the ibd check may be relaxed to a chainwork check in #24178

After 24178 the -maxtipage workaround mentioned above no longer works. Though, a -minimumchainwork workaround should be possible to use as an alternative, if needed at all.

Anything left to be done here?