Unbound 1.7.2 - A lookups being performed for NAPTR requests.
Wouter Wijngaards
wouter at nlnetlabs.nl
Fri Aug 3 07:17:50 UTC 2018
Hi Jon,
On 03/08/18 02:28, Jon via Unbound-users wrote:
> 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.
This is because of qname minimisation, it is on by default. It makes
type A requests to make the qtype private. Normally, the queries that
qname minimisation makes are answer(-able) with contents or with nodata
answers. Or delegations.
You could turn off qname minimisation, with the config option for it.
qname-minimisation: no
But for NAPTR requests also, qname minimisation provides privacy, and
this may be valuable to you. It does not reveal the full NAPTR string
to higher-up servers in the chain of delegations. It also hides that
you are making type NAPTR queries by using type A, this is what you are
seeing in the packet dumps.
Best regards, Wouter
>
> 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