Unbound 1.7.2 - A lookups being performed for NAPTR requests.
Jon
jon at badplace.net
Fri Aug 3 00:28:15 UTC 2018
We are using a stub zone to forward NAPTR requests to two servers. The
maintainers of the servers that handle the NAPTR requests are saying
that they are seeing non NAPTR requests.
I ran a tcpdump and sure enough A requests are being run before almost
all of the NAPTR requests. The DNS clients that are using the unbound
server are only sending NAPTR requests.
10.xxx.x.46 is the unbound server and 10.xxx.x.201 is the NAPTR server.
Any ideas on how to stop the A requests?
1 0.000000 10.xxx.x.46 10.xxx.x.201 DNS 74
Standard query 0x1b92 A 3.1 OPT
2 0.000327 10.xxx.x.201 10.xxx.x.46 DNS 74
Standard query response 0x1b92 Refused A 3.1 OPT
3 0.000863 10.xxx.x.46 10.xxx.x.201 DNS 92
Standard query 0x6889 NAPTR 9.9.9.9.9.9.9.9.6.3.1 OPT
4 0.001007 10.xxx.x.201 10.xxx.x.46 DNS 165
Standard query response 0x6889 NAPTR 9.9.9.9.9.9.9.9.6.3.1 NAPTR 10 10 U OPT
Part of unbound.conf
access-control: 10.0.0.0/8 allow
access-control: 10.0.0.0/8 allow_setrd
stub-zone:
name: "1"
stub-addr: 10.xxx.x.201
stub-addr: 10.xxx.x.202
An example query with log level set to 5:
Aug 02 14:40:46 unbound[91794:0] info: 10.xxx.xx.11
9.9.9.9.9.9.9.9.5.9.1. NAPTR IN
Aug 02 14:40:46 unbound[91794:0] debug: udp request from ip4
10.254.18.11 port 52045 (len 16)
Aug 02 14:40:46 unbound[91794:0] debug: mesh_run: start
Aug 02 14:40:46 unbound[91794:0] debug: iterator[module 0] operate:
extstate:module_state_initial event:module_event_
new
Aug 02 14:40:46 unbound[91794:0] debug: process_request: new external
request event
Aug 02 14:40:46 unbound[91794:0] debug: iter_handle processing q with
state INIT REQUEST STATE
Aug 02 14:40:46 unbound[91794:0] info: resolving 9.9.9.9.9.9.9.9.5.9.1.
NAPTR IN
Aug 02 14:40:46 unbound[91794:0] debug: request has dependency depth of 0
Aug 02 14:40:46 unbound[91794:0] info: use stub 1. NS IN
Aug 02 14:40:46 unbound[91794:0] debug: cache delegation returns delegpt
Aug 02 14:40:46 unbound[91794:0] info: DelegationPoint<1.>: 0 names (0
missing), 2 addrs (0 result, 2 avail) parentNS
Aug 02 14:40:46 unbound[91794:0] debug: ip4 10.xxx.x.202 port 53 (len 16)
Aug 02 14:40:46 unbound[91794:0] debug: ip4 10.xxx.x.201 port 53 (len 16)
Aug 02 14:40:46 unbound[91794:0] debug: iter_handle processing q with
state INIT REQUEST STATE (stage 2)
Aug 02 14:40:46 unbound[91794:0] info: resolving (init part 2):
9.9.9.9.9.9.9.9.5.9.1. NAPTR IN
Aug 02 14:40:46 unbound[91794:0] info: use stub 1. NS IN
Aug 02 14:40:46 unbound[91794:0] debug: iter_handle processing q with
state INIT REQUEST STATE (stage 3)
Aug 02 14:40:46 unbound[91794:0] info: resolving (init part 3):
9.9.9.9.9.9.9.9.5.9.1. NAPTR IN
Aug 02 14:40:46 unbound[91794:0] debug: iter_handle processing q with
state QUERY TARGETS STATE
Aug 02 14:40:46 unbound[91794:0] info: processQueryTargets:
9.9.9.9.9.9.9.9.5.9.1. NAPTR IN
Aug 02 14:40:46 unbound[91794:0] debug: processQueryTargets:
targetqueries 0, currentqueries 0 sentcount 0
Aug 02 14:40:46 unbound[91794:0] info: DelegationPoint<1.>: 0 names (0
missing), 2 addrs (0 result, 2 avail) parentNS
Aug 02 14:40:46 unbound[91794:0] debug: ip4 10.xxx.x.202 port 53 (len 16)
Aug 02 14:40:46 unbound[91794:0] debug: ip4 10.xxx.x.201 port 53 (len 16)
Aug 02 14:40:46 unbound[91794:0] debug: removing 9 labels
Aug 02 14:40:46 unbound[91794:0] debug: attempt to get extra 3 targets
Aug 02 14:40:46 unbound[91794:0] debug: servselect ip4 10.xxx.x.201 port
53 (len 16)
Aug 02 14:40:46 unbound[91794:0] debug: rtt=12
Aug 02 14:40:46 unbound[91794:0] debug: servselect ip4 10.xxx.x.202 port
53 (len 16)
Aug 02 14:40:46 unbound[91794:0] debug: rtt=12
Aug 02 14:40:46 unbound[91794:0] debug: selrtt 12
Aug 02 14:40:46 unbound[91794:0] info: sending query: 9.1. A IN
Aug 02 14:40:46 unbound[91794:0] debug: sending to target: <1.>
10.xxx.x.201#53
Aug 02 14:40:46 unbound[91794:0] debug: dnssec status: not expected
Aug 02 14:40:46 unbound[91794:0] debug: EDNS lookup known=1 vs=0
Aug 02 14:40:46 unbound[91794:0] debug: serviced query UDP timeout=50 msec
Aug 02 14:40:46 unbound[91794:0] debug: inserted new pending reply id=83df
Aug 02 14:40:46 unbound[91794:0] debug: opened UDP if=0 port=19590
Aug 02 14:40:46 unbound[91794:0] debug: comm point start listening 9
Aug 02 14:40:46 unbound[91794:0] debug: mesh_run: iterator module exit
state is module_wait_reply
Aug 02 14:40:46 unbound[91794:0] info: mesh_run: end 1 recursion states
(1 with reply, 0 detached), 1 waiting replies, 6116 recursion replies
sent, 0 replies dropped, 0 states jostled out
Aug 02 14:40:46 unbound[91794:0] info: average recursion processing time
0.000952 sec
Aug 02 14:40:46 unbound[91794:0] info: histogram of recursion processing
times
Aug 02 14:40:46 unbound[91794:0] info: [25%]=0.000690529
median[50%]=0.000869057 [75%]=0.00114625
Aug 02 14:40:46 unbound[91794:0] info: lower(secs) upper(secs) recursions
Aug 02 14:40:46 unbound[91794:0] info: 0.000512 0.001024 4385
Aug 02 14:40:46 unbound[91794:0] info: 0.001024 0.002048 1692
Aug 02 14:40:46 unbound[91794:0] info: 0.002048 0.004096 29
Aug 02 14:40:46 unbound[91794:0] info: 0.004096 0.008192 7
Aug 02 14:40:46 unbound[91794:0] info: 0.008192 0.016384 3
Aug 02 14:40:46 unbound[91794:0] info: 0RDd mod0 rep
9.9.9.9.9.9.9.9.5.9.1. NAPTR IN
Aug 02 14:40:46 unbound[91794:0] debug: cache memory msg=35113573
rrset=68947070 infra=18879 val=0
Aug 02 14:40:46 unbound[91794:0] debug: answer cb
Aug 02 14:40:46 unbound[91794:0] debug: Incoming reply id = 83df
Aug 02 14:40:46 unbound[91794:0] debug: Incoming reply addr = ip4
10.xxx.x.201 port 53 (len 16)
Aug 02 14:40:46 unbound[91794:0] debug: lookup size is 1 entries
Aug 02 14:40:46 unbound[91794:0] debug: received udp reply.
Aug 02 14:40:46 unbound[91794:0] debug: udp message[32:0]
83DF841500010000000000010139013100000100010000290200000080000000
Aug 02 14:40:46 unbound[91794:0] debug: outnet handle udp reply
Aug 02 14:40:46 unbound[91794:0] debug: measured roundtrip at 0 msec
Aug 02 14:40:46 unbound[91794:0] debug: svcd callbacks start
Aug 02 14:40:46 unbound[91794:0] debug: worker svcd callback for qstate
0x14e31d50
Aug 02 14:40:46 unbound[91794:0] debug: mesh_run: start
Aug 02 14:40:46 unbound[91794:0] debug: iterator[module 0] operate:
extstate:module_wait_reply event:module_event_reply
Aug 02 14:40:46 unbound[91794:0] info: iterator operate: query
9.9.9.9.9.9.9.9.5.9.1. NAPTR IN
Aug 02 14:40:46 unbound[91794:0] debug: process_response: new external
response event
Aug 02 14:40:46 unbound[91794:0] info: scrub for 1. NS IN
Aug 02 14:40:46 unbound[91794:0] info: response for
9.9.9.9.9.9.9.9.5.9.1. NAPTR IN
Aug 02 14:40:46 unbound[91794:0] info: reply from <1.> 10.xxx.x.201#53
Aug 02 14:40:46 unbound[91794:0] info: incoming scrubbed packet: ;;
->>HEADER<<- opcode: QUERY, rcode: REFUSED, id: 0
;; flags: qr aa ; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0
;; QUESTION SECTION:
9.1. IN A
;; ANSWER SECTION:
;; AUTHORITY SECTION:
;; ADDITIONAL SECTION:
;; MSG SIZE rcvd: 21
Aug 02 14:40:46 unbound[91794:0] debug: iter_handle processing q with
state QUERY RESPONSE STATE
Aug 02 14:40:46 unbound[91794:0] info: query response was THROWAWAY
Aug 02 14:40:46 unbound[91794:0] debug: iter_handle processing q with
state QUERY TARGETS STATE
Aug 02 14:40:46 unbound[91794:0] info: processQueryTargets:
9.9.9.9.9.9.9.9.5.9.1. NAPTR IN
Aug 02 14:40:46 unbound[91794:0] debug: processQueryTargets:
targetqueries 0, currentqueries 0 sentcount 1
Aug 02 14:40:46 unbound[91794:0] info: DelegationPoint<1.>: 0 names (0
missing), 2 addrs (2 result, 0 avail) parentNS
Aug 02 14:40:46 unbound[91794:0] debug: ip4 10.xxx.x.202 port 53 (len 16)
Aug 02 14:40:46 unbound[91794:0] debug: ip4 10.xxx.x.201 port 53 (len 16)
Aug 02 14:40:46 unbound[91794:0] debug: attempt to get extra 3 targets
Aug 02 14:40:46 unbound[91794:0] debug: servselect ip4 10.xxx.x.202 port
53 (len 16)
Aug 02 14:40:46 unbound[91794:0] debug: rtt=12
Aug 02 14:40:46 unbound[91794:0] debug: servselect ip4 10.xxx.x.201 port
53 (len 16)
Aug 02 14:40:46 unbound[91794:0] debug: rtt=12
Aug 02 14:40:46 unbound[91794:0] debug: selrtt 12
Aug 02 14:40:46 unbound[91794:0] info: sending query:
9.9.9.9.9.9.9.9.5.9.1. NAPTR IN
Aug 02 14:40:46 unbound[91794:0] debug: sending to target: <1.>
10.xxx.x.202#53
Aug 02 14:40:46 unbound[91794:0] debug: dnssec status: not expected
Aug 02 14:40:46 unbound[91794:0] debug: EDNS lookup known=1 vs=0
Aug 02 14:40:46 unbound[91794:0] debug: serviced query UDP timeout=50 msec
Aug 02 14:40:46 unbound[91794:0] debug: inserted new pending reply id=e4e7
Aug 02 14:40:46 unbound[91794:0] debug: opened UDP if=0 port=56357
Aug 02 14:40:46 unbound[91794:0] debug: comm point start listening 10
Aug 02 14:40:46 unbound[91794:0] debug: mesh_run: iterator module exit
state is module_wait_reply
Aug 02 14:40:46 unbound[91794:0] info: mesh_run: end 1 recursion states
(1 with reply, 0 detached), 1 waiting replies, 6116 recursion replies
sent, 0 replies dropped, 0 states jostled out
Aug 02 14:40:46 unbound[91794:0] info: average recursion processing time
0.000952 sec
Aug 02 14:40:46 unbound[91794:0] info: histogram of recursion processing
times
Aug 02 14:40:46 unbound[91794:0] info: [25%]=0.000690529
median[50%]=0.000869057 [75%]=0.00114625
Aug 02 14:40:46 unbound[91794:0] info: lower(secs) upper(secs) recursions
Aug 02 14:40:46 unbound[91794:0] info: 0.000512 0.001024 4385
Aug 02 14:40:46 unbound[91794:0] info: 0.001024 0.002048 1692
Aug 02 14:40:46 unbound[91794:0] info: 0.002048 0.004096 29
Aug 02 14:40:46 unbound[91794:0] info: 0.004096 0.008192 7
Aug 02 14:40:46 unbound[91794:0] info: 0.008192 0.016384 3
Aug 02 14:40:46 unbound[91794:0] info: 0RDd mod0 rep
9.9.9.9.9.9.9.9.5.9.1. NAPTR IN
Aug 02 14:40:46 unbound[91794:0] debug: cache memory msg=35113573
rrset=68947070 infra=18879 val=0
Aug 02 14:40:46 unbound[91794:0] debug: svcd callbacks end
Aug 02 14:40:46 unbound[91794:0] debug: close of port 19590
Aug 02 14:40:46 unbound[91794:0] debug: close fd 9
Aug 02 14:40:46 unbound[91794:0] debug: answer cb
Aug 02 14:40:46 unbound[91794:0] debug: Incoming reply id = e4e7
Aug 02 14:40:46 unbound[91794:0] debug: Incoming reply addr = ip4
10.xxx.x.202 port 53 (len 16)
Aug 02 14:40:46 unbound[91794:0] debug: lookup size is 1 entries
Aug 02 14:40:46 unbound[91794:0] debug: received udp reply.
Aug 02 14:40:46 unbound[91794:0] debug: udp message[123:0]
E4E784100001000100000001013101340139013401370135013801340135013901310000230001C00C002300010000003C003D000A000A01550C4532552B7073746E3A74656C28215E2E2A242174656C3A2B31393534383537343934313B6369633D2B3130303333353B6E70646921000000290200000080000000
Aug 02 14:40:46 unbound[91794:0] debug: outnet handle udp reply
Aug 02 14:40:46 unbound[91794:0] debug: measured roundtrip at 0 msec
Aug 02 14:40:46 unbound[91794:0] debug: svcd callbacks start
Aug 02 14:40:46 unbound[91794:0] debug: worker svcd callback for qstate
0x14e31d50
Aug 02 14:40:46 unbound[91794:0] debug: mesh_run: start
Aug 02 14:40:46 unbound[91794:0] debug: iterator[module 0] operate:
extstate:module_wait_reply event:module_event_reply
Aug 02 14:40:46 unbound[91794:0] info: iterator operate: query
9.9.9.9.9.9.9.9.5.9.1. NAPTR IN
Aug 02 14:40:46 unbound[91794:0] debug: process_response: new external
response event
Aug 02 14:40:46 unbound[91794:0] info: scrub for 1. NS IN
Aug 02 14:40:46 unbound[91794:0] info: response for
9.9.9.9.9.9.9.9.5.9.1. NAPTR IN
Aug 02 14:40:46 unbound[91794:0] info: reply from <1.> 10.xxx.x.202#53
Aug 02 14:40:46 unbound[91794:0] info: incoming scrubbed packet: ;;
->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0
;; flags: qr aa ; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 0
;; QUESTION SECTION:
9.9.9.9.9.9.9.9.5.9.1. IN NAPTR
;; ANSWER SECTION:
9.9.9.9.9.9.9.9.5.9.1. 86400 IN NAPTR 10 10 "U" "xxxxxxxxxxxx"
"!^.*$!xxxxxxxxxxxxxxxx;cic=+xxxxxx;xxxx!" .
;; AUTHORITY SECTION:
;; ADDITIONAL SECTION:
;; MSG SIZE rcvd: 112
Aug 02 14:40:46 unbound[91794:0] debug: iter_handle processing q with
state QUERY RESPONSE STATE
Aug 02 14:40:46 unbound[91794:0] info: query response was ANSWER
Aug 02 14:40:46 unbound[91794:0] debug: iter_handle processing q with
state FINISHED RESPONSE STATE
Aug 02 14:40:46 unbound[91794:0] info: finishing processing for
9.9.9.9.9.9.9.9.5.9.1. NAPTR IN
Aug 02 14:40:46 unbound[91794:0] debug: mesh_run: iterator module exit
state is module_finished
Aug 02 14:40:46 unbound[91794:0] debug: query took 0.000902 sec
Aug 02 14:40:46 unbound[91794:0] info: 10.254.18.11
9.9.9.9.9.9.9.9.5.9.1. NAPTR IN NOERROR 0.000902 0 112
Aug 02 14:40:46 unbound[91794:0] info: mesh_run: end 0 recursion states
(0 with reply, 0 detached), 0 waiting replies, 6117 recursion replies
sent, 0 replies dropped, 0 states jostled out
Aug 02 14:40:46 unbound[91794:0] info: average recursion processing time
0.000952 sec
Aug 02 14:40:46 unbound[91794:0] info: histogram of recursion processing
times
Aug 02 14:40:46 unbound[91794:0] info: [25%]=0.000690517
median[50%]=0.000869034 [75%]=0.0011461
Aug 02 14:40:46 unbound[91794:0] info: lower(secs) upper(secs) recursions
More information about the Unbound-users
mailing list