BIND ignores "packets received correctly"

classic Classic list List threaded Threaded
4 messages Options
Reply | Threaded
Open this post in threaded view
|

BIND ignores "packets received correctly"

Bernardo
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

Libre de virus. www.avast.com

_______________________________________________
Please visit https://lists.isc.org/mailman/listinfo/bind-users to unsubscribe from this list

ISC funds the development of this software with paid support subscriptions. Contact us at https://www.isc.org/contact/ for more information.


bind-users mailing list
[hidden email]
https://lists.isc.org/mailman/listinfo/bind-users
Reply | Threaded
Open this post in threaded view
|

Re: BIND ignores "packets received correctly"

Ondřej Surý
Hi,

we can’t really help you if you don’t use the real domain names and real IP addresses.

Ondrej
--
Ondřej Surý (He/Him)
[hidden email]

> On 7. 1. 2021, at 16:56, - <[hidden email]> wrote:
>
> 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
>
> Libre de virus. www.avast.com
> _______________________________________________
> Please visit https://lists.isc.org/mailman/listinfo/bind-users to unsubscribe from this list
>
> ISC funds the development of this software with paid support subscriptions. Contact us at https://www.isc.org/contact/ for more information.
>
>
> bind-users mailing list
> [hidden email]
> https://lists.isc.org/mailman/listinfo/bind-users

_______________________________________________
Please visit https://lists.isc.org/mailman/listinfo/bind-users to unsubscribe from this list

ISC funds the development of this software with paid support subscriptions. Contact us at https://www.isc.org/contact/ for more information.


bind-users mailing list
[hidden email]
https://lists.isc.org/mailman/listinfo/bind-users

signature.asc (849 bytes) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: BIND ignores "packets received correctly"

Bernardo
In reply to this post by Bernardo
The problem of BIND ignoring "packets received correctly" has definitely something to do with queries using UDP packets.

Here's an example:

# dig +nssearch EXAMPLE.COM
SOA ns1.DOMAIN.com. hostmaster.DOMAIN.com. 2021010707 3600 600 2419200 600 from server M.N.O.P in 3 ms.
SOA ns1.DOMAIN.com. hostmaster.DOMAIN.com. 2021010707 3600 600 2419200 600 from server Q.R.S.T in 3 ms.
SOA ns1.DOMAIN.com. hostmaster.DOMAIN.com. 2021010707 3600 600 2419200 600 from server U.V.W.X in 3 ms.
;; no response from A.B.C.D

Forcing queries to use TCP makes BIND not to ignore any QUERY (never)

# dig +tcp +nssearch EXAMPLE.COM
SOA ns1.DOMAIN.com. hostmaster.DOMAIN.com. 2021010707 3600 600 2419200 600 from server A.B.C.D in 0 ms.
SOA ns1.DOMAIN.com. hostmaster.DOMAIN.com. 2021010707 3600 600 2419200 600 from server E.F.G.H in 0 ms.
SOA ns1.DOMAIN.com. hostmaster.DOMAIN.com. 2021010707 3600 600 2419200 600 from server I.J.K.L in 0 ms.
SOA ns1.DOMAIN.com. hostmaster.DOMAIN.com. 2021010707 3600 600 2419200 600 from server M.N.O.P in 3 ms.
SOA ns1.DOMAIN.com. hostmaster.DOMAIN.com. 2021010707 3600 600 2419200 600 from server Q.R.S.T in 3 ms.
SOA ns1.DOMAIN.com. hostmaster.DOMAIN.com. 2021010707 3600 600 2419200 600 from server U.V.W.X in 3 ms.

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

Libre de virus. www.avast.com

El jue, 7 ene 2021 a las 16:56, - (<[hidden email]>) escribió:
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

Libre de virus. www.avast.com


--
Bernardo

_______________________________________________
Please visit https://lists.isc.org/mailman/listinfo/bind-users to unsubscribe from this list

ISC funds the development of this software with paid support subscriptions. Contact us at https://www.isc.org/contact/ for more information.


bind-users mailing list
[hidden email]
https://lists.isc.org/mailman/listinfo/bind-users
Reply | Threaded
Open this post in threaded view
|

[SOLVED] Re: BIND ignores "packets received correctly"

Bernardo
Hi all,

Finally I've found the solution.
The problem seems to be caused by a known issue since BIND version 9.16.1

Commenting out these lines in /etc/named.conf solves the issue:

query-source address 192.168.10.100;
notify-source 192.168.10.100 port 53;
transfer-source 192.168.10.100 port 53;

This problem causes other major problems with BIND (notify messages get lost, zone changes propagation takes longer, dynamic updates get lost, etc...)

Other related posts at [hidden email]:  
- See my post ( bind listening on UDP port 53 using 2 fd ) from January 2020
- Look also the post ( No response from localhost with "allow-query { any; };"  ) from September 2020

Notes for BIND 9.16.1
Known Issues
UDP network ports used for listening can no longer simultaneously be used for sending traffic. An example configuration which triggers this issue would be one which uses the same address:port pair for listen-on(-v6) statements as for notify-source(-v6) or transfer-source(-v6). While this issue affects all operating systems, it only triggers log messages (e.g. “unable to create dispatch for reserved port”) on some of them. There are currently no plans to make such a combination of settings work again.

Hope this helps someone else to avoid loosing a lot of time.

Regards,

-- 
Bernardo


El dom, 10 ene 2021 a las 14:33, Bernardo (<[hidden email]>) escribió:
The problem of BIND ignoring "packets received correctly" has definitely something to do with queries using UDP packets.

Here's an example:

# dig +nssearch EXAMPLE.COM
SOA ns1.DOMAIN.com. hostmaster.DOMAIN.com. 2021010707 3600 600 2419200 600 from server M.N.O.P in 3 ms.
SOA ns1.DOMAIN.com. hostmaster.DOMAIN.com. 2021010707 3600 600 2419200 600 from server Q.R.S.T in 3 ms.
SOA ns1.DOMAIN.com. hostmaster.DOMAIN.com. 2021010707 3600 600 2419200 600 from server U.V.W.X in 3 ms.
;; no response from A.B.C.D

Forcing queries to use TCP makes BIND not to ignore any QUERY (never)

# dig +tcp +nssearch EXAMPLE.COM
SOA ns1.DOMAIN.com. hostmaster.DOMAIN.com. 2021010707 3600 600 2419200 600 from server A.B.C.D in 0 ms.
SOA ns1.DOMAIN.com. hostmaster.DOMAIN.com. 2021010707 3600 600 2419200 600 from server E.F.G.H in 0 ms.
SOA ns1.DOMAIN.com. hostmaster.DOMAIN.com. 2021010707 3600 600 2419200 600 from server I.J.K.L in 0 ms.
SOA ns1.DOMAIN.com. hostmaster.DOMAIN.com. 2021010707 3600 600 2419200 600 from server M.N.O.P in 3 ms.
SOA ns1.DOMAIN.com. hostmaster.DOMAIN.com. 2021010707 3600 600 2419200 600 from server Q.R.S.T in 3 ms.
SOA ns1.DOMAIN.com. hostmaster.DOMAIN.com. 2021010707 3600 600 2419200 600 from server U.V.W.X in 3 ms.

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

Libre de virus. www.avast.com

El jue, 7 ene 2021 a las 16:56, - (<[hidden email]>) escribió:
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

Libre de virus. www.avast.com


--
Bernardo


--
Bernardo

_______________________________________________
Please visit https://lists.isc.org/mailman/listinfo/bind-users to unsubscribe from this list

ISC funds the development of this software with paid support subscriptions. Contact us at https://www.isc.org/contact/ for more information.


bind-users mailing list
[hidden email]
https://lists.isc.org/mailman/listinfo/bind-users