Maintained by: NLnet Labs

unbound returns SERVFAIL although forwarder works just fine

martin f krafft
Tue Dec 22 18:25:07 CET 2015


Hi,

I am running unbound (1.5.7 on Debian unstable) on a laptop as
a recursive resolver for localhost and a number of test VMs running
on the machine. I am aware that others use dnsmasq for this, but
I don't particularly like this monolithic do-everything tool and am
rather familiar with unbound already.

Unfortunately, I am experiencing problems at regular intervals. One
such problem is that occasionally, unbound will be unable to resolve
records, returning SERVFAIL:

  % host debian.org
  Host debian.org not found: 2(SERVFAIL)

According to the log (full log below), unbound thinks that the
forward server is failing:

  unbound: [1144:0] debug: configured forward servers failed -- returning SERVFAIL

However, querying the configured forwarding server works just fine.

  % unbound-control lookup debian.org
  The following name servers are used for lookup of debian.org. forwarding request:
  Delegation with 0 names, of which 0 can be examined to query further addresses.
  It provides 1 IP addresses.
  192.168.1.1       rto 120000 msec, ttl 780, ping 0 var 94 rtt 376, tA 3, tAAAA 3, tother 0, probedelay 1, EDNS 0 assumed.

  % dig +short @192.168.1.1 debian.org a
  150.203.164.38
  […]

Also, if I monitor the interface to which unbound forwards, I see
the request and the response just fine:

  25 7.066215930 192.168.1.106 -> 192.168.1.1  DNS 81 Standard query 0x31d4 A debian.org OPT
  26 7.071606315  192.168.1.1 -> 192.168.1.106 DNS 193 Standard
    query response 0x31d4 A debian.org OPT A 150.203.164.38
    A 130.89.148.14 A 128.31.0.62 A 149.20.20.20 A 5.153.231.4
    A 140.211.15.34 A 200.17.202.197

All this suggests to me that unbound receives the data but then
doesn't properly handle it.

You can find the log[verbosity=255] output below.

Most of the time, simply restarting unbound fixes things, but not
always. Do you have any idea where the fault lies exactly and what
can be done to fix it or — better yet — prevent it, such that
I don't need to restart unbound all the time?

Thanks,
martin

Log:

  unbound: [1144:0] debug: answer from the cache failed
  unbound: [1144:0] debug: udp request from ip4 127.0.0.1 port 46502 (len 16)
  unbound: [1144:0] debug: mesh_run: start
  unbound: [1144:0] debug: validator[module 0] operate: extstate:module_state_initial event:module_event_new
  unbound: [1144:0] info: validator operate: query debian.org. A IN
  unbound: [1144:0] debug: validator: pass to next module
  unbound: [1144:0] debug: mesh_run: validator module exit state is module_wait_module
  unbound: [1144:0] debug: iterator[module 1] operate: extstate:module_state_initial event:module_event_pass
  unbound: [1144:0] debug: process_request: new external request event
  unbound: [1144:0] debug: iter_handle processing q with state INIT REQUEST STATE
  unbound: [1144:0] info: resolving debian.org. A IN
  unbound: [1144:0] debug: request has dependency depth of 0
  unbound: [1144:0] debug: forwarding request
  unbound: [1144:0] debug: iter_handle processing q with state QUERY TARGETS STATE
  unbound: [1144:0] info: processQueryTargets: debian.org. A IN
  unbound: [1144:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0
  unbound: [1144:0] info: DelegationPoint<.>: 0 names (0 missing), 1 addrs (0 result, 1 avail) parentNS
  unbound: [1144:0] debug:    ip4 192.168.1.1 port 53 (len 16)
  unbound: [1144:0] debug: attempt to get extra 3 targets
  unbound: [1144:0] debug: servselect ip4 192.168.1.1 port 53 (len 16)
  unbound: [1144:0] debug:    rtt=120000
  unbound: [1144:0] debug: No more query targets, attempting last resort
  unbound: [1144:0] debug: configured forward servers failed -- returning SERVFAIL
  unbound: [1144:0] debug: store error response in message cache
  unbound: [1144:0] debug: return error response SERVFAIL
  unbound: [1144:0] debug: mesh_run: iterator module exit state is module_finished
  unbound: [1144:0] debug: validator[module 0] operate: extstate:module_wait_module event:module_event_moddone
  unbound: [1144:0] info: validator operate: query debian.org. A IN
  unbound: [1144:0] debug: validator: nextmodule returned
  unbound: [1144:0] debug: cannot validate non-answer, rcode SERVFAIL
  unbound: [1144:0] debug: mesh_run: validator module exit state is module_finished
  unbound: [1144:0] debug: query took 0.000000 sec
  unbound: [1144:0] info: mesh_run: end 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 1607 recursion replies sent, 0 replies dropped, 0 states jostled out
  unbound: [1144:0] info: average recursion processing time 222.003190 sec
  unbound: [1144:0] info: histogram of recursion processing times
  unbound: [1144:0] info: [25%]=5.23112e-07 median[50%]=0.0459395 [75%]=6.61468
  unbound: [1144:0] info: lower(secs) upper(secs) recursions
  unbound: [1144:0] info:    0.000000    0.000001 768
  unbound: [1144:0] info:    0.002048    0.004096 1
  unbound: [1144:0] info:    0.004096    0.008192 5
  unbound: [1144:0] info:    0.016384    0.032768 9
  unbound: [1144:0] info:    0.032768    0.065536 51
  unbound: [1144:0] info:    0.065536    0.131072 51
  unbound: [1144:0] info:    0.131072    0.262144 48
  unbound: [1144:0] info:    0.262144    0.524288 88
  unbound: [1144:0] info:    0.524288    1.000000 31
  unbound: [1144:0] info:    1.000000    2.000000 32
  unbound: [1144:0] info:    2.000000    4.000000 50
  unbound: [1144:0] info:    4.000000    8.000000 109
  unbound: [1144:0] info:    8.000000   16.000000 172
  unbound: [1144:0] info:   16.000000   32.000000 103
  unbound: [1144:0] info:   32.000000   64.000000 55
  unbound: [1144:0] info:   64.000000  128.000000 25
  unbound: [1144:0] info: 2048.000000 4096.000000 1
  unbound: [1144:0] info: 32768.000000 65536.000000 8
  unbound: [1144:0] debug: cache memory msg=135095 rrset=125584 infra=13761 val=66344


-- 
@martinkrafft | http://madduck.net/ | http://two.sentenc.es/
 
"frank harris has been received
 in all the great houses -- once!"
                                                        -- oscar wilde
 
spamtraps: madduck.bogus at madduck.net
-------------- next part --------------
A non-text attachment was scrubbed...
Name: digital_signature_gpg.asc
Type: application/pgp-signature
Size: 1107 bytes
Desc: Digital signature (see http://martin-krafft.net/gpg/sig-policy/999bbcc4/current)
URL: <https://unbound.nlnetlabs.nl/pipermail/unbound-users/attachments/20151223/1bd9407a/attachment.sig>