BIND ignores "packets received correctly"

[-]

Hi all,

We are running BIND 9.16.6 DNS servers that are receiving queries from
clients but randomly ignore "packets received correctly" as shown in this
logs.

When the DNS server answers the query, BIND is logging this:

30-Dec-2020 10:16:55.071 client: debug 3: client @0x7f9808000c80
A.B.C.D#47290: UDP request
30-Dec-2020 10:16:55.071 client: debug 5: client @0x7f9808000c80
A.B.C.D#47290: using view '_default'
30-Dec-2020 10:16:55.071 security: debug 3: client @0x7f9808000c80
A.B.C.D#47290: request is not signed
30-Dec-2020 10:16:55.071 security: debug 3: client @0x7f9808000c80
A.B.C.D#47290: recursion available
30-Dec-2020 10:16:55.071 queries: info: client @0x7f9808000c80
A.B.C.D#47290 (EXAMPLE.COM): query: EXAMPLE.COM IN SOA -E(0)K (E.F.G.H)
30-Dec-2020 10:16:55.071 security: debug 3: client @0x7f9808000c80
A.B.C.D#47290 (EXAMPLE.COM): query 'EXAMPLE.COM/SOA/IN' approved
30-Dec-2020 10:16:55.071 rate-limit: debug 99: client @0x7f9808000c80
A.B.C.D#47290 (EXAMPLE.COM): rrl=0x7f9810365a20, HAVECOOKIE=0,
result=ISC_R_SUCCESS, fname=0x7f9814d523d0(1), is_zone=1, RECURSIONOK=0,
query.rpz_st=(nil)(0), RRL_CHECKED=0
30-Dec-2020 10:16:55.071 security: debug 3: client @0x7f9808000c80
A.B.C.D#47290 (EXAMPLE.COM): reset client

while TCPDUMP output (command "tcpdump -i eth0 port 53 -n -vvv") is showing
this:

A.B.C.D.47290 > E.F.G.H.53: [udp sum ok] 47783 [1au] SOA? EXAMPLE.COM. ar:
. OPT UDPsize=4096 (49)
E.F.G.H.53 > A.B.C.D.47290: [bad udp cksum 0x3f6d -> 0x7b61!] 47783* q:
SOA? EXAMPLE.COM. 1/6/1 EXAMPLE.COM. [1h] SOA ns1.DOMAIN.COM. dns.DOMAIN.COM.
2020122901 3600 600 2419200 600 ns: EXAMPLE.COM. [1d] NS ns3.DOMAIN.NET.,
EXAMPLE.COM. [1d] NS ns2.DOMAIN.NET., EXAMPLE.COM. [1d] NS ns1.DOMAIN.COM.,
EXAMPLE.COM. [1d] NS ns3.DOMAIN.COM., EXAMPLE.COM. [1d] NS ns1.DOMAIN.NET.,
EXAMPLE.COM. [1d] NS ns2.DOMAIN.COM. ar: . OPT UDPsize=4096 (246)

So far, everything's fine.

But, when the DNS server doesn't answer the query, BIND is logging this:

30-Dec-2020 10:16:47.487 general: debug 60: socket 0x7f9815aa2178
A.B.C.D#36113: packet received correctly
30-Dec-2020 10:16:48.487 general: debug 60: socket 0x7f9815aa2178
A.B.C.D#36113: packet received correctly
30-Dec-2020 10:16:48.487 general: debug 60: socket 0x7f9815aa2178
A.B.C.D#36113: packet received correctly
30-Dec-2020 10:16:49.491 general: debug 60: socket 0x7f9815aa2178
A.B.C.D#36113: packet received correctly

while TCPDUMP output is showing this:

A.B.C.D.36113 > E.F.G.H.53: [udp sum ok] 13628 [1au] SOA? EXAMPLE.COM. ar:
. OPT UDPsize=4096 (49)
A.B.C.D.36113 > E.F.G.H.53: [udp sum ok] 13628 [1au] SOA? EXAMPLE.COM. ar:
. OPT UDPsize=4096 (49)
A.B.C.D.36113 > E.F.G.H.53: [udp sum ok] 13628 [1au] SOA? EXAMPLE.COM. ar:
. OPT UDPsize=4096 (49)
A.B.C.D.36113 > E.F.G.H.53: [udp sum ok] 13628 [1au] SOA? EXAMPLE.COM. ar:
. OPT UDPsize=4096 (49)

UDP packets received in both cases are the same but BIND randomly ignores
them sometimes (causing the client to query again) and finally it never
answers the query received in the first time.

The host CPU, memory and NIC utilization are low so it's very unlikely that
computing resource bottlenecks are causing packets to be dumped.
In fact, command "netstat -suna" shows that apparently the host has no
problem processing UDP packets.

Udp:
    1349954 packets received
    27 packets to unknown port received
    0 packet receive errors
    631757 packets sent
    0 receive buffer errors
    0 send buffer errors

It's a little bit surprising that "packet received correctly" is only being
logged when things go wrong.
The only place in the code that I've found where "packet received
correctly" is being logged is here at socket.c

        /*
         * On TCP and UNIX sockets, zero length reads indicate EOF,
         * while on UDP sockets, zero length reads are perfectly valid,
         * although strange.
         */
        switch (sock->type) {
        case isc_sockettype_tcp:
        case isc_sockettype_unix:
                if (cc == 0) {
                        return (DOIO_EOF);
                }
                break;
        case isc_sockettype_udp:
        case isc_sockettype_raw:
                break;
        default:
                INSIST(0);
                ISC_UNREACHABLE();
        }

        if (sock->type == isc_sockettype_udp) {
                dev->address.length = msghdr.msg_namelen;
                if (isc_sockaddr_getport(&dev->address) == 0) {
                        if (isc_log_wouldlog(isc_lctx, IOEVENT_LEVEL)) {
                                socket_log(sock, &dev->address, IOEVENT,
                                           "dropping source port zero
packet");
                        }
                        return (DOIO_SOFT);
                }
                /*
                 * Simulate a firewall blocking UDP responses bigger than
                 * 'maxudp' bytes.
                 */
                if (sock->manager->maxudp != 0 &&
                    cc > (int)sock->manager->maxudp) {
                        return (DOIO_SOFT);
                }
        }

        socket_log(sock, &dev->address, IOEVENT, "packet received
correctly");


I'd rather avoid having to dive deeper in the code to understand what
conditions can cause BIND to ignore "packets received correctly" that seems
to happen when this socket_log function is called.

I would appreciate if anybody can help with this or give some hint.

Thank you,

-- 
Bernardo

<https://www.avast.com/sig-email?utm_medium=email&utm_source=link&utm_campaign=sig-email&utm_content=webmail>
Libre
de virus. www.avast.com
<https://www.avast.com/sig-email?utm_medium=email&utm_source=link&utm_campaign=sig-email&utm_content=webmail>
<#DAB4FAD8-2DD7-40BB-A1B8-4E2AA1F9FDF2>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.isc.org/pipermail/bind-users/attachments/20210107/c718c1c4/attachment.htm>