BIND ignores "packets received correctly"

classic Classic list List threaded Threaded
3 messages Options
--2
Reply | Threaded
Open this post in threaded view
|

BIND ignores "packets received correctly"

--2
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
--2
Reply | Threaded
Open this post in threaded view
|

Re: BIND ignores "packets received correctly"

--2
In reply to this post by --2
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