Re: bin/51313: named caching server timeouts

To: gnats-bugs%NetBSD.org@localhost
Subject: Re: bin/51313: named caching server timeouts
From: Thor Lancelot Simon <tls%netbsd.org@localhost>
Date: Thu, 5 Apr 2018 21:10:52 +0000
I see this misbehavior with NetBSD-8 built on 2017-12-30.

Here are some snippets from /var/log/messages as well as from packet captures
on the client-serving (interior) and internet-facing (exterior) interfaces
of my NetBSD firewall, showing a query for pool.ntp.org, which:

1) Appears to have succeded, returning a response to the caching server, but
2) Results in ServFail being returned to the interior client, after a delay.

The client appears to repeatedly query beginning at 20:17:49
(as seen in the packet capture immediately following) but gets no response
until at 20:17:59 finally it elicits a ServFail (corresponding to the
log message you'll see next).  After the syslog messages you'll see the
packet capture of the outside-interface traffic, witha successful query
recursing all the way up at 20:17:49, corresponding to the client's first
query, but no further traffic, perhaps because the successful lookup's cached).

Inside-interface traffic:

20:17:49.051563 IP (tos 0x0, ttl 255, id 2935, offset 0, flags [none], proto UDP (17), length 58)
    192.168.100.112.64751 > 192.168.100.1.53: [udp sum ok] 53844+ A? pool.ntp.org. (30)
20:17:49.054393 IP (tos 0x0, ttl 255, id 48697, offset 0, flags [none], proto UDP (17), length 58)
    192.168.100.112.62578 > 192.168.100.1.53: [udp sum ok] 62879+ AAAA? pool.ntp.org. (30)
20:17:50.043729 IP (tos 0x0, ttl 255, id 55255, offset 0, flags [none], proto UDP (17), length 58)
    192.168.100.112.64751 > 192.168.100.1.53: [udp sum ok] 53844+ A? pool.ntp.org. (30)
20:17:50.054569 IP (tos 0x0, ttl 255, id 9128, offset 0, flags [none], proto UDP (17), length 58) 
    192.168.100.112.62578 > 192.168.100.1.53: [udp sum ok] 62879+ AAAA? pool.ntp.org. (30)
20:17:52.046166 IP (tos 0x0, ttl 255, id 26324, offset 0, flags [none], proto UDP (17), length 58)
    192.168.100.112.64751 > 192.168.100.1.53: [udp sum ok] 53844+ A? pool.ntp.org. (30)
20:17:52.083412 IP (tos 0x0, ttl 255, id 42478, offset 0, flags [none], proto UDP (17), length 58)
    192.168.100.112.62578 > 192.168.100.1.53: [udp sum ok] 62879+ AAAA? pool.ntp.org. (30)
20:17:56.084653 IP (tos 0x0, ttl 255, id 64050, offset 0, flags [none], proto UDP (17), length 58)
    192.168.100.112.64751 > 192.168.100.1.53: [udp sum ok] 53844+ A? pool.ntp.org. (30)
20:17:56.084745 IP (tos 0x0, ttl 255, id 64500, offset 0, flags [none], proto UDP (17), length 58)
    192.168.100.112.62578 > 192.168.100.1.53: [udp sum ok] 62879+ AAAA? pool.ntp.org. (30)
20:17:59.073639 IP (tos 0x0, ttl 64, id 0, offset 0, flags [none], proto UDP (17), length 58)
    192.168.100.1.53 > 192.168.100.112.64751: [udp sum ok] 53844 ServFail q: A? pool.ntp.org. 0/0/0 (30)
20:17:59.073758 IP (tos 0x0, ttl 64, id 0, offset 0, flags [none], proto UDP (17), length 58)
    192.168.100.1.53 > 192.168.100.112.62578: [udp sum ok] 62879 ServFail q: AAAA? pool.ntp.org. 0/0/0 (30)

Log messages from named:

Apr  5 20:17:59 hotpoint named[451]: query client=0x72f4cd103800 thread=0x72f4d4105000 (pool.ntp.org/A): query_find: unexpected error after resuming: timed out 
Apr  5 20:17:59 hotpoint named[451]: query client=0x72f4cd105800 thread=0x72f4d4107000 (pool.ntp.org/AAAA): query_find: unexpected error after resuming: timed out

Outside-interface traffic (there's no further occurrence of the string "ntp" in this
capture after what's quoted here):

20:17:49.193754 IP (tos 0x0, ttl 51, id 15102, offset 0, flags [DF], proto UDP (17), length 170) 
    207.171.17.42.53 > 24.104.251.72.64596: [udp sum ok] 59751*- q: A? pool.ntp.org. 4/0/0 pool.ntp.org. [2m30s] A 129.250.35.250, pool.ntp.org. [2m30s] A 173.230.144.109, pool.ntp.org. [2m30s] A 96.126.100.203, pool.ntp.org. [2m30s] A 173.255.206.154 (142) 
20:17:49.194893 IP (tos 0x0, ttl 64, id 48395, offset 0, flags [none], proto UDP (17), length 76, bad cksum 0 (->a9d0)!)
    24.104.251.72.54793 > 199.19.57.1.53: [udp sum ok] 21225 [1au] DS? ntp.org. ar: . OPT UDPsize=512 DO (48)
20:17:49.199728 IP (tos 0x0, ttl 51, id 15104, offset 0, flags [DF], proto UDP (17), length 111)
    207.171.17.42.53 > 24.104.251.72.53033: [udp sum ok] 34246*- q: A? g.ntpns.org. 2/0/0 g.ntpns.org. [2h53m20s] A 199.188.48.59, g.ntpns.org. [2h53m20s] A 198.105.223.32 (83)
20:17:49.200701 IP (tos 0x0, ttl 51, id 15105, offset 0, flags [DF], proto UDP (17), length 137)
    207.171.17.42.53 > 24.104.251.72.57221: [udp sum ok] 32487*- q: AAAA? g.ntpns.org. 0/1/0 ns: g.ntpns.org. [1h] SOA a.ntpns.org. hostmaster.g.ntpns.org. 1516976433 5400 5400 1209600 3600 (109)
20:17:49.207982 IP (tos 0x0, ttl 51, id 15107, offset 0, flags [DF], proto UDP (17), length 140)
    207.171.17.42.53 > 24.104.251.72.56537: [udp sum ok] 59870*- q: AAAA? pool.ntp.org. 0/1/0 ns: pool.ntp.org. [25m] SOA h.ntpns.org. hostmaster.pool.ntp.org. 1522959062 5400 5400 1209600 3600 (112)
20:17:49.217755 IP (tos 0x0, ttl 54, id 32683, offset 0, flags [none], proto UDP (17), length 64)
    199.19.57.1.53 > 24.104.251.72.54793: [udp sum ok] 21225*-| q: DS? ntp.org. 0/0/1 ar: . OPT UDPsize=4096 DO (36)
20:17:49.218310 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 60, bad cksum 0 (->26f7)!)
    24.104.251.72.50135 > 199.19.57.1.53: Flags [S], cksum 0xa627 (correct), seq 3888800318, win 32768, options [mss 1460,nop,wscale 3,sackOK,TS val 1 ecr 0], length 0
20:17:49.240802 IP (tos 0x0, ttl 56, id 47144, offset 0, flags [DF], proto TCP (6), length 60)
    199.19.57.1.53 > 24.104.251.72.50135: Flags [S.], cksum 0xb370 (correct), seq 1121150816, ack 3888800319, win 65535, options [mss 1460,nop,wscale 6,sackOK,TS val 1740464306 ecr 1], length 0
20:17:49.240898 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 52, bad cksum 0 (->26ff)!)
    24.104.251.72.50135 > 199.19.57.1.53: Flags [.], cksum 0xd1d6 (correct), seq 1, ack 1, win 4197, options [nop,nop,TS val 1 ecr 1740464306], length 0
20:17:49.241199 IP (tos 0x0, ttl 64, id 48422, offset 0, flags [DF], proto TCP (6), length 102, bad cksum 0 (->69a6)!)
    24.104.251.72.50135 > 199.19.57.1.53: Flags [P.], cksum 0xeed4 (correct), seq 1:51, ack 1, win 4197, options [nop,nop,TS val 1 ecr 1740464306], length 506747 [1au] DS? ntp.org. ar: . OPT UDPsize=4096 DO (48)
20:17:49.263006 IP (tos 0x0, ttl 56, id 47173, offset 0, flags [DF], proto TCP (6), length 801)
    199.19.57.1.53 > 24.104.251.72.50135: Flags [P.], cksum 0x4dbc (correct), seq 1:750, ack 51, win 1040, options [nop,nop,TS val 1740464328 ecr 1], length 7496747*- q: DS? ntp.org. 0/6/1 ns: h9p7u7tr2u91d0v0ljs9l1gidnp90u3h.org. [1d] Type50, h9p7u7tr2u91d0v0ljs9l1gidnp
90u3h.org. [1d] RRSIG, org. [15m] SOA a0.org.afilias-nst.info. noc.afilias-nst.info. 2012934004 1800 900 604800 86400, org. [15m] RRSIG, d7fdd278p5up3itk58hk4vor3le6df4s.org. [1d] Type50, d7fdd278p5up3itk58hk4vor3le6df4s.org. [1d] RRSIG ar: . OPT UDPsize=4096 DO (747)
20:17:49.263397 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 52, bad cksum 0 (->26ff)!)
    24.104.251.72.50135 > 199.19.57.1.53: Flags [F.], cksum 0xce9f (correct), seq 51, ack 750, win 4197, options [nop,nop,TS val 2 ecr 1740464328], length 0
20:17:49.290458 IP (tos 0x0, ttl 56, id 47197, offset 0, flags [DF], proto TCP (6), length 52)
    199.19.57.1.53 > 24.104.251.72.50135: Flags [.], cksum 0xdad9 (correct), seq 750, ack 52, win 1040, options [nop,nop,TS val 1740464355 ecr 2], length 0
20:17:49.291434 IP (tos 0x0, ttl 56, id 47198, offset 0, flags [DF], proto TCP (6), length 52)
    199.19.57.1.53 > 24.104.251.72.50135: Flags [F.], cksum 0xdad8 (correct), seq 750, ack 52, win 1040, options [nop,nop,TS val 1740464355 ecr 2], length 0
20:17:49.291472 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 52, bad cksum 0 (->26ff)!)
    24.104.251.72.50135 > 199.19.57.1.53: Flags [.], cksum 0xce83 (correct), seq 52, ack 751, win 4197, options [nop,nop,TS val 2 ecr 1740464355], length 0
References:
- bin/51313: named caching server timeouts
  - From: Hauke Fath
Prev by Date: NetBSD Nightly Trouble Ticket Report
Next by Date: Re: bin/51313: named caching server timeouts
Previous by Thread: bin/51313: named caching server timeouts
Next by Thread: Re: bin/51313: named caching server timeouts
Indexes:
Home | Main Index | Thread Index | Old Index