Unbound always returns SERVFAIL with forwarders
martin f krafft
madduck at madduck.net
Tue Apr 30 05:26:37 UTC 2024
Hey there,
I am trying to run Unbound 1.19.2 on my Debian laptop because I want
the ability to inject DNS data using `zone-data` as well as
`stub-zone`/`forward-zone` e.g. when I have certain VPN connections
open.
But I am constantly running up against walls:
```
% dig @127.0.0.1 a debian.org
; <<>> DiG 9.19.21-1+b1-Debian <<>> @127.0.0.1 a debian.org
; (1 server found)
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: SERVFAIL, id: 15380
;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1
;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 1232
;; QUESTION SECTION:
;debian.org. IN A
;; Query time: 4 msec
;; SERVER: 127.0.0.1#53(127.0.0.1) (UDP)
;; WHEN: Mon Apr 29 11:32:00 CEST 2024
;; MSG SIZE rcvd: 39
```
This is when a forwarder is configured, e.g.:
```
# unbound-control list_forwards
. IN forward fc00:39:39::1 192.168.39.1
```
If I remove the forwarder, then unbound recursively does it's thing
alright, but with a forwarder, I get `SERVFAIL`.
So I crank up the logging, but I cannot see anything in the output
that would indicate anything about what's going on, no error,
warning, failure, lame result, nothing.
Maybe one of yous can have a look and see what's wrong?
```
% sudo unbound-control verbosity 255
ok
% sudo unbound-control flush_zone debian.org
ok removed 0 rrsets, 0 messages and 0 key entries
% journalctl -u unbound.service -fn0 &
[1] 625540
% dig @127.0.0.1 a debian.org
; <<>> DiG 9.19.21-1+b1-Debian <<>> @127.0.0.1 a debian.org
; (1 server found)
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: SERVFAIL, id: 15380
;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1
;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 1232
;; QUESTION SECTION:
;debian.org. IN A
;; Query time: 4 msec
;; SERVER: 127.0.0.1#53(127.0.0.1) (UDP)
;; WHEN: Mon Apr 29 11:32:00 CEST 2024
;; MSG SIZE rcvd: 39
%
unbound[623703]: [623703:0] debug: answer from the cache failed
unbound[623703]: [623703:0] debug: udp request from ip4 127.0.0.1 port 43325 (len 16)
unbound[623703]: [623703:0] debug: mesh_run: start
unbound[623703]: [623703:0] debug: subnetcache[module 0] operate: extstate:module_state_initial event:module_event_new
unbound[623703]: [623703:0] info: subnetcache operate: query debian.org. A IN
unbound[623703]: [623703:0] debug: subnetcache: not found in cache. pass to next module
unbound[623703]: [623703:0] debug: mesh_run: subnetcache module exit state is module_wait_module
unbound[623703]: [623703:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_pass
unbound[623703]: [623703:0] info: validator operate: query debian.org. A IN
unbound[623703]: [623703:0] debug: validator: pass to next module
unbound[623703]: [623703:0] debug: mesh_run: validator module exit state is module_wait_module
unbound[623703]: [623703:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
unbound[623703]: [623703:0] debug: process_request: new external request event
unbound[623703]: [623703:0] debug: iter_handle processing q with state INIT REQUEST STATE
unbound[623703]: [623703:0] info: resolving debian.org. A IN
unbound[623703]: [623703:0] debug: request has dependency depth of 0
unbound[623703]: [623703:0] debug: forwarding request
unbound[623703]: [623703:0] debug: iter_handle processing q with state QUERY TARGETS STATE
unbound[623703]: [623703:0] info: processQueryTargets: debian.org. A IN
unbound[623703]: [623703:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0
unbound[623703]: [623703:0] info: DelegationPoint<.>: 0 names (0 missing), 3 addrs (0 result, 3 avail) parentNS
unbound[623703]: [623703:0] debug: ip4 192.168.178.1 port 53 (len 16)
unbound[623703]: [623703:0] debug: ip6 fd00::3ea6:2fff:fe84:6729 port 53 (len 28)
unbound[623703]: [623703:0] debug: ip6 2001:a61:1013:6f01:3ea6:2fff:fe84:6729 port 53 (len 28)
unbound[623703]: [623703:0] debug: attempt to get extra 3 targets
unbound[623703]: [623703:0] debug: rpz: iterator module callback: have_rpz=0
unbound[623703]: [623703:0] debug: servselect ip6 2001:a61:1013:6f01:3ea6:2fff:fe84:6729 port 53 (len 28)
unbound[623703]: [623703:0] debug: rtt=71
unbound[623703]: [623703:0] debug: servselect ip6 fd00::3ea6:2fff:fe84:6729 port 53 (len 28)
unbound[623703]: [623703:0] debug: rtt=70
unbound[623703]: [623703:0] debug: servselect ip4 192.168.178.1 port 53 (len 16)
unbound[623703]: [623703:0] debug: rtt=122
unbound[623703]: [623703:0] debug: selrtt 70
unbound[623703]: [623703:0] info: sending query: debian.org. A IN
unbound[623703]: [623703:0] debug: sending to target: <.> 192.168.178.1#53
unbound[623703]: [623703:0] debug: dnssec status: not expected
unbound[623703]: [623703:0] debug: mesh_run: iterator module exit state is module_wait_reply
unbound[623703]: [623703:0] info: mesh_run: end 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 317 recursion replies sent, 0 replies dropped, 0 states jostled out
unbound[623703]: [623703:0] info: average recursion processing time 0.036455 sec
unbound[623703]: [623703:0] info: histogram of recursion processing times
unbound[623703]: [623703:0] info: [25%]=0.00421507 median[50%]=0.0278918 [75%]=0.0542118
unbound[623703]: [623703:0] info: lower(secs) upper(secs) recursions
unbound[623703]: [623703:0] info: 0.001024 0.002048 11
unbound[623703]: [623703:0] info: 0.002048 0.004096 67
unbound[623703]: [623703:0] info: 0.004096 0.008192 43
unbound[623703]: [623703:0] info: 0.008192 0.016384 8
unbound[623703]: [623703:0] info: 0.016384 0.032768 42
unbound[623703]: [623703:0] info: 0.032768 0.065536 102
unbound[623703]: [623703:0] info: 0.065536 0.131072 34
unbound[623703]: [623703:0] info: 0.131072 0.262144 9
unbound[623703]: [623703:0] info: 0.524288 1.000000 1
unbound[623703]: [623703:0] info: 0RDd mod2 rep debian.org. A IN
unbound[623703]: [623703:0] debug: cache memory msg=118093 rrset=100141 infra=9722 val=66561 subnet=74536
unbound[623703]: [623703:0] debug: serviced send timer
unbound[623703]: [623703:0] debug: EDNS lookup known=1 vs=0
unbound[623703]: [623703:0] debug: serviced query UDP timeout=122 msec
unbound[623703]: [623703:0] debug: inserted new pending reply id=5a58
unbound[623703]: [623703:0] debug: opened UDP if=0 port=43197
unbound[623703]: [623703:0] debug: comm point start listening 14 (-1 msec)
unbound[623703]: [623703:0] debug: answer cb
unbound[623703]: [623703:0] debug: Incoming reply id = 5a58
unbound[623703]: [623703:0] debug: Incoming reply addr = ip4 192.168.178.1 port 53 (len 16)
unbound[623703]: [623703:0] debug: lookup size is 1 entries
unbound[623703]: [623703:0] debug: received udp reply.
unbound[623703]: [623703:0] debug: udp message[337:0] 5A5881A000010005000000010664656269616E036F72670000010001C00C0001000100000072000497654284C00C0001000100000072000497658284C00C000100010000007200049765C284C00C0001000100000072000497650284C00C002E00010000007200DE000108020000012C665E40FA6629801AE98C0664656269616E036F72670067F6EE00CC04DC6719E9AC5D97599FA767470305528F08A00FB6D303C690A6B06F825201B80A9302B9F51D444098F86B93E9C9551D9BC6CD4F393B428CFA83FC3F6EAD4E8BB09BDD309F9506F5A24417455836407BB8E858EC7503F1498761AE9A6ED467F33787F522647CAF296BA1DA1F1165A2FE543444482E
unbound[623703]: [623703:0] debug: udp message[337:256] CA453108648759CF16ABA3E9576736AACC1F6E698092F58B707712BFE6AFFD99C6C9E0163D7176051C4B4A9759846CB6D08E45FD56835593F1B5E48D42F8A7E044ADE80D99DA00002905A4000080000000
unbound[623703]: [623703:0] debug: outnet handle udp reply
unbound[623703]: [623703:0] debug: measured roundtrip at 4 msec
unbound[623703]: [623703:0] debug: svcd callbacks start
unbound[623703]: [623703:0] debug: worker svcd callback for qstate 0x55bd1fc0a5e0
unbound[623703]: [623703:0] debug: mesh_run: start
unbound[623703]: [623703:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
unbound[623703]: [623703:0] info: iterator operate: query debian.org. A IN
unbound[623703]: [623703:0] debug: process_response: new external response event
unbound[623703]: [623703:0] info: scrub for . NS IN
unbound[623703]: [623703:0] info: response for debian.org. A IN
unbound[623703]: [623703:0] info: reply from <.> 192.168.178.1#53
unbound[623703]: [623703:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0
;; flags: qr rd ra ; QUERY: 1, ANSWER: 5, AUTHORITY: 0, ADDITIONAL: 0
;; QUESTION SECTION:
debian.org. IN A
;; ANSWER SECTION:
debian.org. 114 IN A 151.101.66.132
debian.org. 114 IN A 151.101.130.132
debian.org. 114 IN A 151.101.194.132
debian.org. 114 IN A 151.101.2.132
debian.org. 114 IN RRSIG A 8 2 300 20240603221730 20240424215642 59788 debian.org. Z/buAMwE3GcZ6axdl1mfp2dHAwVSjwigD7bTA8aQprBvglIBuAqTArn1HURAmPhrk+nJVR2bxs1POTtCjPqD/D9urU6LsJvdMJ+VBvWiRBdFWDZAe7joWOx1A/FJh2Gumm7UZ/M3h/UiZHyvKWuh2h8RZaL+VDRESC7KRTEIZIdZzxaro+lXZzaqzB9uaYCS9YtwdxK/5q/9mcbJ4BY9cXYFHEtKl1mEbLbQjkX9VoNVk/G15I1C+KfgRK3oDZna ;{id = 59788}
;; AUTHORITY SECTION:
;; ADDITIONAL SECTION:
;; MSG SIZE rcvd: 326
```
In fact, up until this point, everything seems hunky dory, and the
unbound received the exact right data from the forwarder, right?
But what happens now?
```
unbound[623703]: [623703:0] debug: iter_handle processing q with state QUERY RESPONSE STATE
unbound[623703]: [623703:0] info: query response was ANSWER
unbound[623703]: [623703:0] debug: iter_handle processing q with state FINISHED RESPONSE STATE
unbound[623703]: [623703:0] info: finishing processing for debian.org. A IN
unbound[623703]: [623703:0] debug: mesh_run: iterator module exit state is module_finished
unbound[623703]: [623703:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
unbound[623703]: [623703:0] info: validator operate: query debian.org. A IN
unbound[623703]: [623703:0] debug: validator: nextmodule returned
unbound[623703]: [623703:0] debug: val handle processing q with state VAL_INIT_STATE
unbound[623703]: [623703:0] debug: validator classification positive
unbound[623703]: [623703:0] info: signer is debian.org. TYPE0 CLASS0
unbound[623703]: [623703:0] debug: val handle processing q with state VAL_FINISHED_STATE
unbound[623703]: [623703:0] debug: mesh_run: validator module exit state is module_finished
unbound[623703]: [623703:0] debug: subnetcache[module 0] operate: extstate:module_wait_module event:module_event_moddone
unbound[623703]: [623703:0] info: subnetcache operate: query debian.org. A IN
unbound[623703]: [623703:0] debug: reply has edns subnet (null)
unbound[623703]: [623703:0] debug: mesh_run: subnetcache module exit state is module_finished
unbound[623703]: [623703:0] debug: query took 0.004561 sec
unbound[623703]: [623703:0] info: mesh_run: end 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 318 recursion replies sent, 0 replies dropped, 0 states jostled out
unbound[623703]: [623703:0] info: average recursion processing time 0.036355 sec
unbound[623703]: [623703:0] info: histogram of recursion processing times
unbound[623703]: [623703:0] info: [25%]=0.00423564 median[50%]=0.0276968 [75%]=0.0541315
unbound[623703]: [623703:0] info: lower(secs) upper(secs) recursions
unbound[623703]: [623703:0] info: 0.001024 0.002048 11
unbound[623703]: [623703:0] info: 0.002048 0.004096 67
unbound[623703]: [623703:0] info: 0.004096 0.008192 44
unbound[623703]: [623703:0] info: 0.008192 0.016384 8
unbound[623703]: [623703:0] info: 0.016384 0.032768 42
unbound[623703]: [623703:0] info: 0.032768 0.065536 102
unbound[623703]: [623703:0] info: 0.065536 0.131072 34
unbound[623703]: [623703:0] info: 0.131072 0.262144 9
unbound[623703]: [623703:0] info: 0.524288 1.000000 1
unbound[623703]: [623703:0] debug: cache memory msg=118093 rrset=100141 infra=9722 val=66561 subnet=74536
unbound[623703]: [623703:0] debug: svcd callbacks end
unbound[623703]: [623703:0] debug: serviced_delete
unbound[623703]: [623703:0] debug: close of port 43197
unbound[623703]: [623703:0] debug: comm_point_close of 14: event_del
unbound[623703]: [623703:0] debug: close fd 14
```
Thank you!
--
martin krafft | https://matrix.to/#/#madduck:madduck.net
i find television very educating.
every time somebody turns on the set,
I go into the other room and read a book.
-- groucho marx
{: .blockquote }
spamtraps: madduck.bogus at madduck.net
{: .hidden }
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.nlnetlabs.nl/pipermail/unbound-users/attachments/20240430/39a01334/attachment-0001.htm>
More information about the Unbound-users
mailing list