[Unbound-users] forward-zone bug (out of query targets -- returning SERVFAIL)

Dmitriy Demidov dima_bsd at inbox.lv
Mon Nov 24 22:42:57 UTC 2008 

Hi Wouter.

Looks like there is a problem with forward-zone: mechanism. If I'l setup 
unbound for request forwarding to my ISP's DNS cache server, and during this 
time of operations my Internet connection fails for a couple of minutes (3-7 
min average), then unbound freazes in strange condition and do not makes any 
queing at all until hard restarting (restarting using unbound-control do not 
helps - only via rc.d script). In the same time, unbound continues to answer 
for names what remained in it's cache, but if I do nslookup for something 
what is not cached, then it says SERVFAIL in the same moment - SERVFAIL 
without any timeout for queuing. And bad news is that unbound stays in 
this "freaze condition" after Internet connection has been reistablished...

Internet connection do not fails physically (ethernet no-carrier) but only 
logicaly (no respons from GW or somthing like this). 

How to repeate:

1) start unbound in ' forward-zone name: "." ' mode
2) prevent it's communication with forward-addr: DNS server
3) wait for ~5min and make during this time a lot of resolving queues
4) connect internet back - unbound will stays in "freaze" 

My system is FreeBSD 7.1-PRERELEASE, unbound is compilled from ports with 
threads and are linked with libevent-1.4.8.

==============
My unbound.conf


server:
        verbosity: 5
        statistics-interval: 120
        num-threads: 1
        interface: 0.0.0.0
        outgoing-range: 512
        msg-cache-size: 16m
        msg-cache-slabs: 4
        num-queries-per-thread: 1024
        rrset-cache-size: 32m
        rrset-cache-slabs: 4
        cache-max-ttl: 86400
        do-ip4: yes
        do-ip6: no
        do-udp: yes
        do-tcp: yes
        do-daemonize: yes
        access-control: 0.0.0.0/0 refuse
        access-control: 192.168.1.0/24 allow
        access-control: 127.0.0.0/8 allow
        chroot: "/usr/local/etc/unbound"
        username: "unbound"
        directory: "/usr/local/etc/unbound"
        logfile: "/usr/local/etc/unbound/unbound.log"
        use-syslog: no
        pidfile: "/usr/local/etc/unbound/unbound.pid"
        root-hints: "/usr/local/etc/unbound/named.cache"
        harden-glue: yes
        do-not-query-address: 127.0.0.1/8
        module-config: "iterator"
remote-control:
        control-enable: yes
        control-interface: 0.0.0.0
forward-zone: 
       name: "."
       forward-addr: 195.122.12.242
==========


=========
information from unbound.log during unbound's "freaze" time (at this moment 
Internet is connected back):



[1227561922] unbound[8395:0] info: average recursion processing time 0.000000 
sec
[1227561922] unbound[8395:0] info: histogram of recursion processing times
[1227561922] unbound[8395:0] info: [25%]=2.5e-07 median[50%]=5e-07 
[75%]=7.5e-07
[1227561922] unbound[8395:0] info: lower(secs) upper(secs) recursions
[1227561922] unbound[8395:0] info:    0.000000    0.000001 765
[1227561922] unbound[8395:0] debug: cache memory msg=59428 rrset=71260 
infra=1500 val=0
[1227561922] unbound[8395:0] debug: mesh_run: start
[1227561922] unbound[8395:0] debug: iterator[module 0] operate: 
extstate:module_state_initial event:module_event_new
[1227561922] unbound[8395:0] debug: process_request: new external request 
event
[1227561922] unbound[8395:0] debug: iter_handle processing q with state INIT 
REQUEST STATE
[1227561922] unbound[8395:0] info: resolving <top6.mail.ru. A IN>
[1227561922] unbound[8395:0] debug: request has dependency depth of 0
[1227561922] unbound[8395:0] debug: forwarding request
[1227561922] unbound[8395:0] debug: iter_handle processing q with state QUERY 
TARGETS STATE
[1227561922] unbound[8395:0] info: processQueryTargets: <top6.mail.ru. A IN>
[1227561922] unbound[8395:0] debug: processQueryTargets: targetqueries 0, 
currentqueries 0
[1227561922] unbound[8395:0] info: DelegationPoint<.>: 0 names (0 missing), 1 
addrs (0 result, 1 avail)
[1227561922] unbound[8395:0] debug:    ip4 195.122.12.242 port 53 (len 16)
[1227561922] unbound[8395:0] debug: attempt to get extra 3 targets
[1227561922] unbound[8395:0] debug: out of query targets -- returning SERVFAIL
[1227561922] unbound[8395:0] debug: return error response SERVFAIL
[1227561922] unbound[8395:0] debug: mesh_run: iterator module exit state is 
module_finished
[1227561922] unbound[8395:0] debug: query took 0.000000 sec
[1227561922] unbound[8395:0] info: mesh_run: end 0 recursion states (0 with 
reply, 0 detached), 0 waiting replies, 766 recursion replies sent, 0 replies 
dropped, 0 states jostled out
[1227561922] unbound[8395:0] info: average recursion processing time 0.000000 
sec
[1227561922] unbound[8395:0] info: histogram of recursion processing times
[1227561922] unbound[8395:0] info: [25%]=2.5e-07 median[50%]=5e-07 
[75%]=7.5e-07
[1227561922] unbound[8395:0] info: lower(secs) upper(secs) recursions
[1227561922] unbound[8395:0] info:    0.000000    0.000001 766
[1227561922] unbound[8395:0] debug: cache memory msg=59428 rrset=71260 
infra=1500 val=0
[1227561922] unbound[8395:0] debug: mesh_run: start
[1227561922] unbound[8395:0] debug: iterator[module 0] operate: 
extstate:module_state_initial event:module_event_new
[1227561922] unbound[8395:0] debug: process_request: new external request 
event
[1227561922] unbound[8395:0] debug: iter_handle processing q with state INIT 
REQUEST STATE
[1227561922] unbound[8395:0] info: resolving <top6.mail.ru.apollo.lv. A IN>
[1227561922] unbound[8395:0] debug: request has dependency depth of 0
[1227561922] unbound[8395:0] debug: forwarding request
[1227561922] unbound[8395:0] debug: iter_handle processing q with state QUERY 
TARGETS STATE
[1227561922] unbound[8395:0] info: processQueryTargets: 
<top6.mail.ru.apollo.lv. A IN>
[1227561922] unbound[8395:0] debug: processQueryTargets: targetqueries 0, 
currentqueries 0
[1227561922] unbound[8395:0] info: DelegationPoint<.>: 0 names (0 missing), 1 
addrs (0 result, 1 avail)
[1227561922] unbound[8395:0] debug:    ip4 195.122.12.242 port 53 (len 16)
[1227561922] unbound[8395:0] debug: attempt to get extra 3 targets
[1227561922] unbound[8395:0] debug: out of query targets -- returning SERVFAIL
[1227561922] unbound[8395:0] debug: return error response SERVFAIL
[1227561922] unbound[8395:0] debug: mesh_run: iterator module exit state is 
module_finished
[1227561922] unbound[8395:0] debug: query took 0.000000 sec
[1227561922] unbound[8395:0] info: mesh_run: end 0 recursion states (0 with 
reply, 0 detached), 0 waiting replies, 767 recursion replies sent, 0 replies 
dropped, 0 states jostled out
[1227561922] unbound[8395:0] info: average recursion processing time 0.000000 
sec
[1227561922] unbound[8395:0] info: histogram of recursion processing times
[1227561922] unbound[8395:0] info: [25%]=2.5e-07 median[50%]=5e-07 
[75%]=7.5e-07
[1227561922] unbound[8395:0] info: lower(secs) upper(secs) recursions
[1227561922] unbound[8395:0] info:    0.000000    0.000001 767
[1227561922] unbound[8395:0] debug: cache memory msg=59428 rrset=71260 
infra=1500 val=0
[1227561922] unbound[8395:0] debug: mesh_run: start
[1227561922] unbound[8395:0] debug: iterator[module 0] operate: 
extstate:module_state_initial event:module_event_new
[1227561922] unbound[8395:0] debug: process_request: new external request 
event
[1227561922] unbound[8395:0] debug: iter_handle processing q with state INIT 
REQUEST STATE
[1227561922] unbound[8395:0] info: resolving <top6.mail.ru.apollo.lv. A IN>
[1227561922] unbound[8395:0] debug: request has dependency depth of 0
[1227561922] unbound[8395:0] debug: forwarding request
[1227561922] unbound[8395:0] debug: iter_handle processing q with state QUERY 
TARGETS STATE
[1227561922] unbound[8395:0] info: processQueryTargets: 
<top6.mail.ru.apollo.lv. A IN>
[1227561922] unbound[8395:0] debug: processQueryTargets: targetqueries 0, 
currentqueries 0
[1227561922] unbound[8395:0] info: DelegationPoint<.>: 0 names (0 missing), 1 
addrs (0 result, 1 avail)
[1227561922] unbound[8395:0] debug:    ip4 195.122.12.242 port 53 (len 16)
[1227561922] unbound[8395:0] debug: attempt to get extra 3 targets
[1227561922] unbound[8395:0] debug: out of query targets -- returning SERVFAIL
[1227561922] unbound[8395:0] debug: return error response SERVFAIL
[1227561922] unbound[8395:0] debug: mesh_run: iterator module exit state is 
module_finished
[1227561922] unbound[8395:0] debug: query took 0.000000 sec
[1227561922] unbound[8395:0] info: mesh_run: end 0 recursion states (0 with 
reply, 0 detached), 0 waiting replies, 768 recursion replies sent, 0 replies 
dropped, 0 states jostled out
[1227561922] unbound[8395:0] info: average recursion processing time 0.000000 
sec
[1227561922] unbound[8395:0] info: histogram of recursion processing times
[1227561922] unbound[8395:0] info: [25%]=2.5e-07 median[50%]=5e-07 
[75%]=7.5e-07
[1227561922] unbound[8395:0] info: lower(secs) upper(secs) recursions
[1227561922] unbound[8395:0] info:    0.000000    0.000001 768
[1227561922] unbound[8395:0] debug: cache memory msg=59428 rrset=71260 
infra=1500 val=0
=======


=======
from unbound.log during unbound's "freaze" time "statistics-interval:" (at 
this moment Internet is connected back)



[1227562148] unbound[8395:0] info: server stats for thread 0: 1019 queries, 83 
answers from cache, 936 recursions
[1227562148] unbound[8395:0] info: server stats for thread 0: requestlist max 
0 avg 0 exceeded 0
[1227562148] unbound[8395:0] info: mesh has 0 recursion states (0 with reply, 
0 detached), 0 waiting replies, 936 recursion replies sent, 0 replies 
dropped, 0 states jostled out
[1227562148] unbound[8395:0] info: average recursion processing time 0.000000 
sec
[1227562148] unbound[8395:0] info: histogram of recursion processing times
[1227562148] unbound[8395:0] info: [25%]=2.5e-07 median[50%]=5e-07 
[75%]=7.5e-07
[1227562148] unbound[8395:0] info: lower(secs) upper(secs) recursions
[1227562148] unbound[8395:0] info:    0.000000    0.000001 936
[1227562148] unbound[8395:0] debug: cache memory msg=59428 rrset=71260 
infra=1500 val=0
=======

More information about the Unbound-users mailing list