unbound returns SERVFAIL although forwarder works just fine

Wed Dec 23 11:33:48 UTC 2015

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Hi Martin,

Did you encounter this issue also with versions of unbound before
1.5.7? Does it happen after switching networks or immediately after
booting?

Are you sure the tcpdump output corresponds to this part of the log?
The log indicates that no query is send out because the only suitable
delegation point (the forwarding server) is marked as unusable, due to
earlier timeouts. Flushing this entry from the infra cache should make
it work again (unbound-control flush_infra 192.168.1.1).

- -- Ralph

On 22-12-15 18:25, martin f krafft via Unbound-users wrote:
> 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
> 
> 
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1

iQEcBAEBAgAGBQJWeoaQAAoJEDCRjYJ1ckIi63kIAJO8G+cr05PDwSj3wU7iG64C
oLn9CUqYjnbaa73LBTC+pfJYTzT8OGEXxYXGjdJp/BV1wI8CVtqOG+MJlExooyar
O1sd4U5Ct1aUJC22UrSeuWBkXeyMKekHaV7peT8T5MLKJY87GLdGVNOirU9Bvjs+
kKr+gMaH83T1EYHP39xQxrfyqKS3HWW8SWqBAu909txTw+2efLzYxyMl9kIZ6nLH
irAqX/r8fXVganCEm8Gm5fJqh4vQ4BGLu8VospIwQ4+2O2F7ye5vWUwFO3DRYe4R
QO0a5HLEp2Yz/waA0noNhwse4yrLQ/d3NQdlQA7t9S1TKhK8BS1dPGXQrCSJNkQ=
=iRZ7
-----END PGP SIGNATURE-----