HPE Community
Comware Based
1821245 Members
3120 Online
109632 Solutions
New Discussion

DNS proxy is slow on first request

 
SOLVED
Go to solution
graphite
Occasional Contributor

‎09-17-2018 09:35 AM

‎09-17-2018 09:35 AM

DNS proxy is slow on first request

I set up DNS proxy with NAT on MSR3012 router as follows:

#
nat address-group 1 name PublicIP
 address <Public IP> <Public IP>
#
 dns proxy enable
 dns server <ISP DNS1>
 dns server <ISP DNS2>
 dns server 8.8.8.8
 dns server 8.8.4.4
#
interface GigabitEthernet0/0
 port link-mode route
 description Provider uplink
 combo enable copper
 ip address <Public IP> 255.255.255.224
 packet-filter name inbound-from-public inbound
 nat outbound name outboundnat address-group 1
 nat static enable
 undo dhcp select server
#
interface GigabitEthernet0/1
 port link-mode route
 description Workstations
 ip address 192.168.1.1 255.255.255.0
 dhcp server apply ip-pool workstations
#
 ip route-static 0.0.0.0 0 <ISP Gateway>
#
acl basic name outboundnat
 rule 100 permit source 192.168.1.0 0.0.0.255
 rule 999 deny logging
#
acl advanced name inbound-from-public
 rule 100 permit 112
 rule 110 deny ip destination 10.0.0.0 0.255.255.255
 rule 120 deny ip destination 172.16.0.0 0.15.255.255
 rule 130 deny ip destination 192.168.0.0 0.0.255.255
 rule 140 deny ip source 10.0.0.0 0.255.255.255
 rule 150 deny ip source 172.16.0.0 0.15.255.255
 rule 160 deny ip source 192.168.0.0 0.0.255.255
 rule 200 permit udp destination <Public IP> 0 destination-port eq ntp
 rule 210 permit udp destination <Public IP> 0 source-port eq dns
 rule 300 permit tcp established
 rule 950 permit icmp icmp-type echo
 rule 955 permit icmp icmp-type echo-reply
 rule 960 permit icmp icmp-type port-unreachable
 rule 965 permit icmp icmp-type net-unreachable
 rule 970 permit icmp icmp-type ttl-exceeded
 rule 975 deny icmp
 rule 999 deny ip

However on all client machines initial resolution takes 4-6 seconds. Any following DNS request produces immediate response if I use dig. If I use nslookup for the second request it outputs the IP address immediately and then hangs for a few seconds and prints out SERVFAIL error:

nslookup yahoo.de
Server:		127.0.0.53
Address:	127.0.0.53#53

Non-authoritative answer:
Name:	yahoo.de
Address: 98.136.103.24
Name:	yahoo.de
Address: 106.10.248.151
Name:	yahoo.de
Address: 74.6.136.151
Name:	yahoo.de
Address: 124.108.115.101
Name:	yahoo.de
Address: 212.82.100.151
** server can't find yahoo.de: SERVFAIL

In the router I see the following suspicious messages when I turn on the debugging:

*Sep 18 00:03:51:122 2018 Main router DNS/7/PACKET: Received:
Header:
 ID = 63548
 QR = 0, OpCode = 0, AA = 0, TC = 0, RD = 1
 RA = 0, Z = 0, AD = 0, CD = 0, RCode = 0
 QDCount = 1
 ANCount = 0
 NSCount = 0
 ARCount = 0

*Sep 18 00:03:51:122 2018 Main router DNS/7/PACKET: Received:
Question:
 QName  = googleads.g.doubleclick.net
 QType  = A (1)
 QClass = IN (1)

*Sep 18 00:03:51:122 2018 Main router DNS/7/EVENT: DNS proxy received a request for resolving googleads.g.doubleclick.net
*Sep 18 00:03:51:122 2018 Main router DNS/7/EVENT: Trying to resolve googleads.g.doubleclick.net in local database
*Sep 18 00:03:51:122 2018 Main router DNS/7/EVENT: Trying to resolve googleads.g.doubleclick.net in dynamic cache
*Sep 18 00:03:51:122 2018 Main router DNS/7/EVENT: Resolving googleads.g.doubleclick.net is in processing; wait for result

*Sep 18 00:03:52:229 2018 Main router DNS/7/EVENT: Resolving googleads.g.doubleclick.net through DNS server 8.8.8.8 timed out.
*Sep 18 00:03:52:229 2018 Main router DNS/7/EVENT: Trying to resolve googleads.g.doubleclick.net by contacting DNS server 8.8.4.4 through UDP
*Sep 18 00:03:52:230 2018 Main router DNS/7/PACKET: Sent:
Header:
 ID = 7095
 QR = 0, OpCode = 0, AA = 0, TC = 0, RD = 1
 RA = 0, Z = 0, AD = 0, CD = 0, RCode = 0
 QDCount = 1
 ANCount = 0
 NSCount = 0
 ARCount = 0

*Sep 18 00:03:52:230 2018 Main router DNS/7/PACKET: Sent:
Question:
 QName  = googleads.g.doubleclick.net
 QType  = A (1)
 QClass = IN (1)

*Sep 18 00:03:52:230 2018 Main router DNS/7/EVENT: Waiting 2 seconds for server response

*Sep 18 00:03:54:229 2018 Main router DNS/7/EVENT: Resolving googleads.g.doubleclick.net through DNS server 8.8.4.4 timed out.
*Sep 18 00:03:54:229 2018 Main router DNS/7/EVENT: Trying to resolve googleads.g.doubleclick.net by contacting DNS server <ISP DNS1> through UDP
*Sep 18 00:03:54:230 2018 Main router DNS/7/PACKET: Sent:
Header:
 ID = 1541
 QR = 0, OpCode = 0, AA = 0, TC = 0, RD = 1
 RA = 0, Z = 0, AD = 0, CD = 0, RCode = 0
 QDCount = 1
 ANCount = 0
 NSCount = 0
 ARCount = 0

*Sep 18 00:03:54:230 2018 Main router DNS/7/PACKET: Sent:
Question:
 QName  = googleads.g.doubleclick.net
 QType  = A (1)
 QClass = IN (1)

*Sep 18 00:03:54:230 2018 Main router DNS/7/EVENT: Waiting 1 seconds for server response
*Sep 18 00:03:55:229 2018 Main router DNS/7/EVENT: Resolving googleads.g.doubleclick.net through DNS server <ISP DNS1> timed out.
*Sep 18 00:03:55:229 2018 Main router DNS/7/EVENT: Trying to resolve googleads.g.doubleclick.net by contacting DNS server <ISP DNS2> through UDP
*Sep 18 00:03:55:230 2018 Main router DNS/7/PACKET: Sent:
Header:
 ID = 17137
 QR = 0, OpCode = 0, AA = 0, TC = 0, RD = 1
 RA = 0, Z = 0, AD = 0, CD = 0, RCode = 0
 QDCount = 1
 ANCount = 0
 NSCount = 0
 ARCount = 0

*Sep 18 00:03:55:230 2018 Main router DNS/7/PACKET: Sent:
Question:
 QName  = googleads.g.doubleclick.net
 QType  = A (1)
 QClass = IN (1)

*Sep 18 00:03:55:230 2018 Main router DNS/7/EVENT: Waiting 1 seconds for server response

*Sep 18 00:03:56:129 2018 Main router DNS/7/PACKET: Received:
Header:
 ID = 63548
 QR = 0, OpCode = 0, AA = 0, TC = 0, RD = 1
 RA = 0, Z = 0, AD = 0, CD = 0, RCode = 0
 QDCount = 1
 ANCount = 0
 NSCount = 0
 ARCount = 0

*Sep 18 00:03:56:129 2018 Main router DNS/7/PACKET: Received:
Question:
 QName  = googleads.g.doubleclick.net
 QType  = A (1)
 QClass = IN (1)

*Sep 18 00:03:56:129 2018 Main router DNS/7/EVENT: DNS proxy received a request for resolving googleads.g.doubleclick.net
*Sep 18 00:03:56:129 2018 Main router DNS/7/EVENT: Trying to resolve googleads.g.doubleclick.net in local database
*Sep 18 00:03:56:129 2018 Main router DNS/7/EVENT: Trying to resolve googleads.g.doubleclick.net in dynamic cache
*Sep 18 00:03:56:129 2018 Main router DNS/7/EVENT: Resolving googleads.g.doubleclick.net is in processing; wait for result

*Sep 18 00:03:56:233 2018 Main router DNS/7/EVENT: Resolving googleads.g.doubleclick.net through DNS server <ISP DNS2> timed out.
*Sep 18 00:03:56:233 2018 Main router DNS/7/EVENT: Trying to resolve googleads.g.doubleclick.net by contacting DNS server 8.8.8.8 through UDP
*Sep 18 00:03:56:233 2018 Main router DNS/7/PACKET: Sent:
Header:
 ID = 4384
 QR = 0, OpCode = 0, AA = 0, TC = 0, RD = 1
 RA = 0, Z = 0, AD = 0, CD = 0, RCode = 0
 QDCount = 1
 ANCount = 0
 NSCount = 0
 ARCount = 0

*Sep 18 00:03:56:234 2018 Main router DNS/7/PACKET: Sent:
Question:
 QName  = googleads.g.doubleclick.net
 QType  = A (1)
 QClass = IN (1)

*Sep 18 00:03:56:234 2018 Main router DNS/7/EVENT: Waiting 1 seconds for server response
*Sep 18 00:03:57:229 2018 Main router DNS/7/EVENT: Resolving googleads.g.doubleclick.net through DNS server 8.8.8.8 timed out.
*Sep 18 00:03:57:229 2018 Main router DNS/7/EVENT: Trying to resolve googleads.g.doubleclick.net by contacting DNS server 8.8.4.4 through UDP
*Sep 18 00:03:57:230 2018 Main router DNS/7/PACKET: Sent:
Header:
 ID = 38450
 QR = 0, OpCode = 0, AA = 0, TC = 0, RD = 1
 RA = 0, Z = 0, AD = 0, CD = 0, RCode = 0
 QDCount = 1
 ANCount = 0
 NSCount = 0
 ARCount = 0

*Sep 18 00:03:57:230 2018 Main router DNS/7/PACKET: Sent:
Question:
 QName  = googleads.g.doubleclick.net
 QType  = A (1)
 QClass = IN (1)

*Sep 18 00:03:58:232 2018 Main router DNS/7/EVENT: Resolving googleads.g.doubleclick.net through DNS server 8.8.4.4 timed out.
*Sep 18 00:03:58:232 2018 Main router DNS/7/EVENT: Trying to resolve googleads.g.doubleclick.net by contacting DNS server <ISP DNS1> through TCP
*Sep 18 00:03:58:233 2018 Main router DNS/7/EVENT: Connecting to server <ISP DNS1>
*Sep 18 00:03:58:233 2018 Main router DNS/7/EVENT: Waiting 1 seconds for server response

*Sep 18 00:03:58:235 2018 Main router DNS/7/EVENT: Connected to server <ISP DNS1>
*Sep 18 00:03:58:235 2018 Main router DNS/7/PACKET: Sent:
Header:
 ID = 43527
 QR = 0, OpCode = 0, AA = 0, TC = 0, RD = 1
 RA = 0, Z = 0, AD = 0, CD = 0, RCode = 0
 QDCount = 1
 ANCount = 0
 NSCount = 0
 ARCount = 0

*Sep 18 00:03:58:235 2018 Main router DNS/7/PACKET: Sent:
Question:
 QName  = googleads.g.doubleclick.net
 QType  = A (1)
 QClass = IN (1)

*Sep 18 00:03:58:239 2018 Main router DNS/7/PACKET: Received:
Header:
 ID = 43527
 QR = 1, OpCode = 0, AA = 0, TC = 0, RD = 1
 RA = 1, Z = 0, AD = 0, CD = 0, RCode = 0
 QDCount = 1
 ANCount = 2
 NSCount = 4
 ARCount = 8

*Sep 18 00:03:58:239 2018 Main router DNS/7/PACKET: Received:
Question:
 QName  = googleads.g.doubleclick.net
 QType  = A (1)
 QClass = IN (1)

*Sep 18 00:03:58:239 2018 Main router DNS/7/PACKET: Received:
Answer:
 Name     = googleads.g.doubleclick.net
 Type     = CNAME (5)
 Class    = IN (1)
 TTL      = 113
 RDLength = 13
 RData    = pagead46.l.doubleclick.net

*Sep 18 00:03:58:239 2018 Main router DNS/7/PACKET: Received:
Answer:
 Name     = pagead46.l.doubleclick.net
 Type     = A (1)
 Class    = IN (1)
 TTL      = 110
 RDLength = 4
 RData    = 172.217.168.66

*Sep 18 00:03:58:239 2018 Main router DNS/7/EVENT: Received an answer: QName = googleads.g.doubleclick.net, ID = 43527
*Sep 18 00:03:58:239 2018 Main router DNS/7/EVENT: Added a dynamic DNS entry googleads.g.doubleclick.net
*Sep 18 00:03:58:240 2018 Main router DNS/7/EVENT: DNS proxy sent a reply for resolving googleads.g.doubleclick.net
*Sep 18 00:03:58:240 2018 Main router DNS/7/PACKET: Sent:
Header:
 ID = 63548
 QR = 1, OpCode = 0, AA = 0, TC = 0, RD = 1
 RA = 1, Z = 0, AD = 0, CD = 0, RCode = 0
 QDCount = 1
 ANCount = 2
 NSCount = 4
 ARCount = 8

*Sep 18 00:03:58:240 2018 Main router DNS/7/PACKET: Sent:
Question:
 QName  = googleads.g.doubleclick.net
 QType  = A (1)
 QClass = IN (1)

*Sep 18 00:03:58:240 2018 Main router DNS/7/PACKET: Sent:
Answer:
 Name     = googleads.g.doubleclick.net
 Type     = CNAME (5)
 Class    = IN (1)
 TTL      = 113
 RDLength = 13
 RData    = pagead46.l.doubleclick.net

*Sep 18 00:03:58:240 2018 Main router DNS/7/PACKET: Sent:
Answer:
 Name     = pagead46.l.doubleclick.net
 Type     = A (1)
 Class    = IN (1)
 TTL      = 110
 RDLength = 4
 RData    = 172.217.168.66

*Sep 18 00:03:58:240 2018 Main router DNS/7/EVENT: DNS proxy sent a reply for resolving googleads.g.doubleclick.net
*Sep 18 00:03:58:240 2018 Main router DNS/7/PACKET: Sent:
Header:
 ID = 63548
 QR = 1, OpCode = 0, AA = 0, TC = 0, RD = 1
 RA = 1, Z = 0, AD = 0, CD = 0, RCode = 0
 QDCount = 1
 ANCount = 2
 NSCount = 4
 ARCount = 8

*Sep 18 00:03:58:240 2018 Main router DNS/7/PACKET: Sent:
Question:
 QName  = googleads.g.doubleclick.net
 QType  = A (1)
 QClass = IN (1)

*Sep 18 00:03:58:240 2018 Main router DNS/7/PACKET: Sent:
Answer:
 Name     = googleads.g.doubleclick.net
 Type     = CNAME (5)
 Class    = IN (1)
 TTL      = 113
 RDLength = 13
 RData    = pagead46.l.doubleclick.net

*Sep 18 00:03:58:240 2018 Main router DNS/7/PACKET: Sent:
Answer:
 Name     = pagead46.l.doubleclick.net
 Type     = A (1)
 Class    = IN (1)
 TTL      = 110
 RDLength = 4
 RData    = 172.217.168.66

*Sep 18 00:03:58:240 2018 Main router DNS/7/EVENT: DNS proxy sent a reply for resolving googleads.g.doubleclick.net
*Sep 18 00:03:58:241 2018 Main router DNS/7/PACKET: Sent:
Header:
 ID = 63548
 QR = 1, OpCode = 0, AA = 0, TC = 0, RD = 1
 RA = 1, Z = 0, AD = 0, CD = 0, RCode = 0
 QDCount = 1
 ANCount = 2
 NSCount = 4
 ARCount = 8

*Sep 18 00:03:58:241 2018 Main router DNS/7/PACKET: Sent:
Question:
 QName  = googleads.g.doubleclick.net
 QType  = A (1)
 QClass = IN (1)

*Sep 18 00:03:58:241 2018 Main router DNS/7/PACKET: Sent:
Answer:
 Name     = googleads.g.doubleclick.net
 Type     = CNAME (5)
 Class    = IN (1)
 TTL      = 113
 RDLength = 13
 RData    = pagead46.l.doubleclick.net

*Sep 18 00:03:58:241 2018 Main router DNS/7/PACKET: Sent:
Answer:
 Name     = pagead46.l.doubleclick.net
 Type     = A (1)
 Class    = IN (1)
 TTL      = 110
 RDLength = 4
 RData    = 172.217.168.66

 I tried to use ISP DNS servers and 8.8.8.8 / 8.8.4.4 from Google and the behavior is the same. Ping to both Google and ISP servers is <2ms from client computers. If I plug in a laptop in place of router and run the same DNS lookups everything works fine, so it is not DNS server problem, but something with the router.

I tried to use only Google DNS, only ISP, all of them, just single DNS IP and the behavior is always the same. It times out a lot and then somehow completes the request ~6 seconds later.

It feels like my ACL rule tells the router to drop some important DNS request or response packet, but I am not sure which.

0 Kudos
1 REPLY 1
graphite
Occasional Contributor

‎09-18-2018 12:36 AM

‎09-18-2018 12:36 AM

Solution

Re: DNS proxy is slow on first request

Indeed there was a problem with a rule:

rule 210 permit udp destination <Public IP> 0 source-port eq dns

It used old public IP and did not allow any inbound DNS responses. I would have spotted it earlier, but DNS worked partially, because after failing on all DNS servers DNS proxy establishes TCP connection to a DNS server, which then falls under allowed "permit tcp established"

0 Kudos
The opinions expressed above are the personal opinions of the authors, not of Hewlett Packard Enterprise. By using this site, you accept the Terms of Use and Rules of Participation.