BIND doesn't create server TCP sockets for new interfaces detected during named start-up processing
More detail noted in Support ticket RT #18855
The scenario is a recursive server that has a scripted start-up process. named is started first, without the server anycast IPs active (this is to prevent client queries from reaching the server before it is ready to handle queries). The next step in the script is to add the anycast address to the lo interface.
It was observed (on both 9.11.33-S1 and 9.16.18) that named creates both UDP and TCP sockets for interfaces that are present when named is first starting up. These are logged as:
listening on IPv4 interface ... (interface IP address and port)
The interfaces that are missing the TCP server socket are logged as being added after named reports that the control channel socket has been created.
command channel listening on 127.0.0.1#953
And these newly added interfaces are logged thus:
additionally listening on IPv4 interface (interface, IP address and port)
This step takes place before named has finished its startup processing and has logged:
running
If a 5s delay is added to the start-up script, then the new interfaces, when added, have both TCP and UDP sockets created as expected.
Analysis of logs produced by named 9.11.33-S1 (options -g -d 255) show that named does not even attempt to create the second socket for the additional interfaces added at this point in its start up processing, whereas the ones that were already present and created earlier have two calls to open and bind to a socket.
Here's a snippet from the debug logs of named starting up and opening the server sockets on the 127.0.0.1 interface: (already present and detected at startup)
05-Aug-2021 09:49:13.322 listening on IPv4 interface lo, 127.0.0.1#53
05-Aug-2021 09:49:13.322 clientmgr @0x7f35b14f4010: create
05-Aug-2021 09:49:13.322 sendmsg: Invalid argument
05-Aug-2021 09:49:13.330 socket 0x7f35b15ca270: created
05-Aug-2021 09:49:13.330 socket 0x7f35b15ca270 127.0.0.1#53: bound << *** HERE ***
05-Aug-2021 09:49:13.330 dispatchmgr 0x7f35b15c9010: dns_dispatch_createudp: Created UDP dispatch for 127.0.0.1#53 with socket fd 512
05-Aug-2021 09:49:13.330 dispatchmgr 0x7f35b15c9010: created UDP dispatcher 0x7f35a402f7b0
05-Aug-2021 09:49:13.330 dispatch 0x7f35a402f7b0: created task 0x7f35b14f28a8
05-Aug-2021 09:49:13.330 dispatch 0x7f35a402f7b0: created socket 0x7f35b15ca270
05-Aug-2021 09:49:13.330 socket 0x7f35b15ca4d0: dupped
05-Aug-2021 09:49:13.330 dispatchmgr 0x7f35b15c9010: dns_dispatch_createudp: Created UDP dispatch for 127.0.0.1#53 with socket fd 513
05-Aug-2021 09:49:13.330 dispatchmgr 0x7f35b15c9010: created UDP dispatcher 0x7f35a402f1e0
05-Aug-2021 09:49:13.330 dispatch 0x7f35a402f1e0: created task 0x7f35b14f2970
05-Aug-2021 09:49:13.330 dispatch 0x7f35a402f1e0: created socket 0x7f35b15ca4d0
05-Aug-2021 09:49:13.330 socket 0x7f35b15ca730: dupped
05-Aug-2021 09:49:13.330 dispatchmgr 0x7f35b15c9010: dns_dispatch_createudp: Created UDP dispatch for 127.0.0.1#53 with socket fd 514
05-Aug-2021 09:49:13.330 dispatchmgr 0x7f35b15c9010: created UDP dispatcher 0x7f35a402ec10
05-Aug-2021 09:49:13.330 dispatch 0x7f35a402ec10: created task 0x7f35b14f2a38
05-Aug-2021 09:49:13.330 dispatch 0x7f35a402ec10: created socket 0x7f35b15ca730
05-Aug-2021 09:49:13.330 socket 0x7f35b15ca990: dupped
05-Aug-2021 09:49:13.330 dispatchmgr 0x7f35b15c9010: dns_dispatch_createudp: Created UDP dispatch for 127.0.0.1#53 with socket fd 515
05-Aug-2021 09:49:13.330 dispatchmgr 0x7f35b15c9010: created UDP dispatcher 0x7f35a402e640
05-Aug-2021 09:49:13.330 dispatch 0x7f35a402e640: created task 0x7f35b14f2b00
05-Aug-2021 09:49:13.330 dispatch 0x7f35a402e640: created socket 0x7f35b15ca990
05-Aug-2021 09:49:13.330 socket 0x7f35b15cabf0: dupped
05-Aug-2021 09:49:13.330 dispatchmgr 0x7f35b15c9010: dns_dispatch_createudp: Created UDP dispatch for 127.0.0.1#53 with socket fd 516
05-Aug-2021 09:49:13.330 dispatchmgr 0x7f35b15c9010: created UDP dispatcher 0x7f35a402e070
05-Aug-2021 09:49:13.330 dispatch 0x7f35a402e070: created task 0x7f35b14f2bc8
05-Aug-2021 09:49:13.330 dispatch 0x7f35a402e070: created socket 0x7f35b15cabf0
05-Aug-2021 09:49:13.330 socket 0x7f35b14f8010: dupped
05-Aug-2021 09:49:13.330 dispatchmgr 0x7f35b15c9010: dns_dispatch_createudp: Created UDP dispatch for 127.0.0.1#53 with socket fd 517
05-Aug-2021 09:49:13.330 dispatchmgr 0x7f35b15c9010: created UDP dispatcher 0x7f35a402daa0
05-Aug-2021 09:49:13.330 dispatch 0x7f35a402daa0: created task 0x7f35b14f2c90
05-Aug-2021 09:49:13.330 dispatch 0x7f35a402daa0: created socket 0x7f35b14f8010
05-Aug-2021 09:49:13.330 clientmgr @0x7f35b14f4010: createclients
05-Aug-2021 09:49:13.330 clientmgr @0x7f35b14f4010: get client
05-Aug-2021 09:49:13.330 clientmgr @0x7f35b14f4010: create new
05-Aug-2021 09:49:13.330 clientmgr @0x7f35b14f4010: clientmctx
05-Aug-2021 09:49:13.330 client @0x7f35a403a9a0 (no-peer): create
05-Aug-2021 09:49:13.330 clientmgr @0x7f35b14f4010: get client
05-Aug-2021 09:49:13.330 clientmgr @0x7f35b14f4010: create new
05-Aug-2021 09:49:13.330 clientmgr @0x7f35b14f4010: clientmctx
05-Aug-2021 09:49:13.330 client @0x7f35a40408a0 (no-peer): create
05-Aug-2021 09:49:13.330 clientmgr @0x7f35b14f4010: get client
05-Aug-2021 09:49:13.330 clientmgr @0x7f35b14f4010: create new
05-Aug-2021 09:49:13.330 clientmgr @0x7f35b14f4010: clientmctx
05-Aug-2021 09:49:13.330 client @0x7f35a40a2230 (no-peer): create
05-Aug-2021 09:49:13.330 clientmgr @0x7f35b14f4010: get client
05-Aug-2021 09:49:13.330 clientmgr @0x7f35b14f4010: create new
05-Aug-2021 09:49:13.330 clientmgr @0x7f35b14f4010: clientmctx
05-Aug-2021 09:49:13.331 client @0x7f35a40b0ae0 (no-peer): create
05-Aug-2021 09:49:13.331 clientmgr @0x7f35b14f4010: get client
05-Aug-2021 09:49:13.331 clientmgr @0x7f35b14f4010: create new
05-Aug-2021 09:49:13.331 clientmgr @0x7f35b14f4010: clientmctx
05-Aug-2021 09:49:13.331 client @0x7f35a40bf390 (no-peer): create
05-Aug-2021 09:49:13.331 clientmgr @0x7f35b14f4010: get client
05-Aug-2021 09:49:13.331 clientmgr @0x7f35b14f4010: create new
05-Aug-2021 09:49:13.331 clientmgr @0x7f35b14f4010: clientmctx
05-Aug-2021 09:49:13.331 client @0x7f35a40cdc40 (no-peer): create
05-Aug-2021 09:49:13.331 socket 0x7f35b14f8270: created
05-Aug-2021 09:49:13.331 socket 0x7f35b14f8270 127.0.0.1#53: bound << *** AND HERE ***
05-Aug-2021 09:49:13.331 clientmgr @0x7f35b14f4010: createclients
05-Aug-2021 09:49:13.331 clientmgr @0x7f35b14f4010: get client
05-Aug-2021 09:49:13.331 clientmgr @0x7f35b14f4010: create new
05-Aug-2021 09:49:13.331 clientmgr @0x7f35b14f4010: clientmctx
05-Aug-2021 09:49:13.331 client @0x7f35a40dc660 (no-peer): create(named is started with -U 6)
The same logging for the additional interfaces is completely missing the second 'socket ... created' and 'socket ... bound' pair from the logs.
There are no obvious errors being logged - named simply doesn't create the second socket (that I assume is the TCP listener that we didn't get).
The same symptoms are present both in 9.11-S and 9.16, but it's not possible to obtain useful debug logging from 9.16 - likely because the libuv-based server socket code no longer has the logging that was available from the named-based server socket code.