PPPoE WAN & Unbound race condition? No traffic possible until firewall gets reloaded

Installing and Using OpenWrt
1

I am configuring a new router with an Unbound + Odhcpd combo (which works fine on others) and I'm scratching my head. Unbound seems to come up fine but does not seem to get a response to its upstream queries?

Nslookup fails:

root@OpenWrt:~# nslookup google.com
;; connection timed out; no servers could be reached

Looks like it's listening like supposed to:

root@OpenWrt:~# netstat -puntal|grep unbound
tcp        0      0 0.0.0.0:53              0.0.0.0:*               LISTEN      5854/unbound
tcp        0      0 127.0.0.1:8953          0.0.0.0:*               LISTEN      5854/unbound
tcp        0      0 ::1:8953                :::*                    LISTEN      5854/unbound
udp        0      0 0.0.0.0:53              0.0.0.0:*                           5854/unbound
udp        0      0 0.0.0.0:23981           0.0.0.0:*                           5854/unbound

Running unbound -vv suggests Unbound tries multiple (root?) servers but it's not getting any response?

Tue Nov 24 23:15:44 2020 daemon.debug unbound: [5919:0] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new
Tue Nov 24 23:15:44 2020 daemon.info unbound: [5919:0] info: resolving google.com. A IN
Tue Nov 24 23:15:44 2020 daemon.info unbound: [5919:0] info: priming . IN NS
Tue Nov 24 23:15:44 2020 daemon.debug unbound: [5919:0] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_pass
Tue Nov 24 23:15:44 2020 daemon.info unbound: [5919:0] info: iterator operate: query . NS IN
Tue Nov 24 23:15:44 2020 daemon.info unbound: [5919:0] info: processQueryTargets: . NS IN
Tue Nov 24 23:15:44 2020 daemon.info unbound: [5919:0] info: sending query: . NS IN
Tue Nov 24 23:15:44 2020 daemon.debug unbound: [5919:0] debug: sending to target: <.> 192.112.36.4#53
Tue Nov 24 23:15:44 2020 daemon.debug unbound: [5919:0] debug: cache memory msg=8272 rrset=8272 infra=1265 val=0
Tue Nov 24 23:15:44 2020 daemon.debug unbound: [5919:0] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new
Tue Nov 24 23:15:44 2020 daemon.info unbound: [5919:0] info: resolving google.com. AAAA IN
Tue Nov 24 23:15:44 2020 daemon.info unbound: [5919:0] info: priming . IN NS
Tue Nov 24 23:15:44 2020 daemon.debug unbound: [5919:0] debug: cache memory msg=8272 rrset=8272 infra=1265 val=0
Tue Nov 24 23:15:45 2020 daemon.debug unbound: [5919:0] debug: iterator[module 0] operate: extstate:module_wait_reply event:module_event_noreply
Tue Nov 24 23:15:45 2020 daemon.info unbound: [5919:0] info: iterator operate: query . NS IN
Tue Nov 24 23:15:45 2020 daemon.info unbound: [5919:0] info: processQueryTargets: . NS IN
Tue Nov 24 23:15:45 2020 daemon.info unbound: [5919:0] info: sending query: . NS IN
Tue Nov 24 23:15:45 2020 daemon.debug unbound: [5919:0] debug: sending to target: <.> 192.203.230.10#53
Tue Nov 24 23:15:45 2020 daemon.debug unbound: [5919:0] debug: cache memory msg=8272 rrset=8272 infra=1494 val=0
Tue Nov 24 23:15:46 2020 daemon.debug unbound: [5919:0] debug: iterator[module 0] operate: extstate:module_wait_reply event:module_event_noreply
Tue Nov 24 23:15:46 2020 daemon.info unbound: [5919:0] info: iterator operate: query . NS IN
Tue Nov 24 23:15:46 2020 daemon.info unbound: [5919:0] info: processQueryTargets: . NS IN
Tue Nov 24 23:15:46 2020 daemon.info unbound: [5919:0] info: sending query: . NS IN
Tue Nov 24 23:15:46 2020 daemon.debug unbound: [5919:0] debug: sending to target: <.> 192.58.128.30#53
Tue Nov 24 23:15:46 2020 daemon.debug unbound: [5919:0] debug: cache memory msg=8272 rrset=8272 infra=1723 val=0
Tue Nov 24 23:15:46 2020 daemon.debug unbound: [5919:0] debug: iterator[module 0] operate: extstate:module_wait_reply event:module_event_noreply
Tue Nov 24 23:15:46 2020 daemon.info unbound: [5919:0] info: iterator operate: query . NS IN
Tue Nov 24 23:15:46 2020 daemon.info unbound: [5919:0] info: processQueryTargets: . NS IN
Tue Nov 24 23:15:46 2020 daemon.info unbound: [5919:0] info: sending query: . NS IN
Tue Nov 24 23:15:46 2020 daemon.debug unbound: [5919:0] debug: sending to target: <.> 199.7.83.42#53
Tue Nov 24 23:15:46 2020 daemon.debug unbound: [5919:0] debug: cache memory msg=8272 rrset=8272 infra=1952 val=0
Tue Nov 24 23:15:47 2020 daemon.debug unbound: [5919:0] debug: cache memory msg=8272 rrset=8272 infra=1952 val=0
Tue Nov 24 23:15:47 2020 daemon.debug unbound: [5919:0] debug: cache memory msg=8272 rrset=8272 infra=1952 val=0
Tue Nov 24 23:15:47 2020 daemon.debug unbound: [5919:0] debug: iterator[module 0] operate: extstate:module_wait_reply event:module_event_noreply
Tue Nov 24 23:15:47 2020 daemon.info unbound: [5919:0] info: iterator operate: query . NS IN
Tue Nov 24 23:15:47 2020 daemon.info unbound: [5919:0] info: processQueryTargets: . NS IN
Tue Nov 24 23:15:47 2020 daemon.info unbound: [5919:0] info: sending query: . NS IN
Tue Nov 24 23:15:47 2020 daemon.debug unbound: [5919:0] debug: sending to target: <.> 192.36.148.17#53
Tue Nov 24 23:15:47 2020 daemon.debug unbound: [5919:0] debug: cache memory msg=8272 rrset=8272 infra=2181 val=0
Tue Nov 24 23:15:48 2020 daemon.debug unbound: [5919:0] debug: iterator[module 0] operate: extstate:module_wait_reply event:module_event_noreply
Tue Nov 24 23:15:48 2020 daemon.info unbound: [5919:0] info: iterator operate: query . NS IN
Tue Nov 24 23:15:48 2020 daemon.info unbound: [5919:0] info: processQueryTargets: . NS IN
Tue Nov 24 23:15:48 2020 daemon.info unbound: [5919:0] info: sending query: . NS IN
Tue Nov 24 23:15:48 2020 daemon.debug unbound: [5919:0] debug: sending to target: <.> 199.7.91.13#53
Tue Nov 24 23:15:48 2020 daemon.debug unbound: [5919:0] debug: cache memory msg=8272 rrset=8272 infra=2410 val=0
Tue Nov 24 23:15:49 2020 daemon.debug unbound: [5919:0] debug: iterator[module 0] operate: extstate:module_wait_reply event:module_event_noreply
Tue Nov 24 23:15:49 2020 daemon.info unbound: [5919:0] info: iterator operate: query . NS IN
Tue Nov 24 23:15:49 2020 daemon.info unbound: [5919:0] info: processQueryTargets: . NS IN
Tue Nov 24 23:15:49 2020 daemon.info unbound: [5919:0] info: sending query: . NS IN
Tue Nov 24 23:15:49 2020 daemon.debug unbound: [5919:0] debug: sending to target: <.> 192.112.36.4#53
Tue Nov 24 23:15:49 2020 daemon.debug unbound: [5919:0] debug: cache memory msg=8272 rrset=8272 infra=2410 val=0
Tue Nov 24 23:15:50 2020 daemon.debug unbound: [5919:0] debug: iterator[module 0] operate: extstate:module_wait_reply event:module_event_noreply
Tue Nov 24 23:15:50 2020 daemon.info unbound: [5919:0] info: iterator operate: query . NS IN
Tue Nov 24 23:15:50 2020 daemon.info unbound: [5919:0] info: processQueryTargets: . NS IN
Tue Nov 24 23:15:50 2020 daemon.info unbound: [5919:0] info: sending query: . NS IN
Tue Nov 24 23:15:50 2020 daemon.debug unbound: [5919:0] debug: sending to target: <.> 199.7.91.13#53
Tue Nov 24 23:15:50 2020 daemon.debug unbound: [5919:0] debug: cache memory msg=8272 rrset=8272 infra=2410 val=0
Tue Nov 24 23:15:52 2020 daemon.debug unbound: [5919:0] debug: iterator[module 0] operate: extstate:module_wait_reply event:module_event_noreply
Tue Nov 24 23:15:52 2020 daemon.info unbound: [5919:0] info: iterator operate: query . NS IN
Tue Nov 24 23:15:52 2020 daemon.info unbound: [5919:0] info: processQueryTargets: . NS IN
Tue Nov 24 23:15:52 2020 daemon.info unbound: [5919:0] info: sending query: . NS IN
Tue Nov 24 23:15:52 2020 daemon.debug unbound: [5919:0] debug: sending to target: <.> 199.7.83.42#53
Tue Nov 24 23:15:52 2020 daemon.debug unbound: [5919:0] debug: cache memory msg=8272 rrset=8272 infra=2410 val=0
Tue Nov 24 23:15:53 2020 daemon.debug unbound: [5919:0] debug: iterator[module 0] operate: extstate:module_wait_reply event:module_event_noreply
Tue Nov 24 23:15:53 2020 daemon.info unbound: [5919:0] info: iterator operate: query . NS IN
Tue Nov 24 23:15:53 2020 daemon.info unbound: [5919:0] info: processQueryTargets: . NS IN
Tue Nov 24 23:15:53 2020 daemon.info unbound: [5919:0] info: sending query: . NS IN
Tue Nov 24 23:15:53 2020 daemon.debug unbound: [5919:0] debug: sending to target: <.> 192.5.5.241#53
Tue Nov 24 23:15:53 2020 daemon.debug unbound: [5919:0] debug: cache memory msg=8272 rrset=8272 infra=2639 val=0

That list goes on for a while, then ends up with this:

Tue Nov 24 23:16:35 2020 daemon.debug unbound: [5919:0] debug: request has exceeded the maximum number of sends with 33
Tue Nov 24 23:16:35 2020 daemon.debug unbound: [5919:0] debug: return error response SERVFAIL
Tue Nov 24 23:16:35 2020 daemon.debug unbound: [5919:0] debug: iterator[module 0] operate: extstate:module_wait_subquery event:module_event_pass
Tue Nov 24 23:16:35 2020 daemon.info unbound: [5919:0] info: iterator operate: query google.com. A IN
Tue Nov 24 23:16:35 2020 daemon.info unbound: [5919:0] info: processQueryTargets: google.com. A IN
Tue Nov 24 23:16:35 2020 daemon.debug unbound: [5919:0] debug: Failed to get a delegation, giving up
Tue Nov 24 23:16:35 2020 daemon.debug unbound: [5919:0] debug: return error response SERVFAIL
Tue Nov 24 23:16:35 2020 daemon.debug unbound: [5919:0] debug: iterator[module 0] operate: extstate:module_wait_subquery event:module_event_pass
Tue Nov 24 23:16:35 2020 daemon.info unbound: [5919:0] info: iterator operate: query google.com. AAAA IN
Tue Nov 24 23:16:35 2020 daemon.info unbound: [5919:0] info: processQueryTargets: google.com. AAAA IN
Tue Nov 24 23:16:35 2020 daemon.debug unbound: [5919:0] debug: Failed to get a delegation, giving up
Tue Nov 24 23:16:35 2020 daemon.debug unbound: [5919:0] debug: return error response SERVFAIL

Configuration:

config unbound 'ub_main'
	option add_local_fqdn '1'
	option dns64 '0'
	option dns64_prefix '64:ff9b::/96'
	option domain 'lan'
	option domain_type 'static'
	option edns_size '1232'
	option enabled '1'
	option extended_stats '0'
	option hide_binddata '1'
	option interface_auto '1'
	option listen_port '53'
	option localservice '1'
	option manual_conf '0'
	option num_threads '1'
	option query_minimize '0'
	option query_min_strict '0'
	option rate_limit '0'
	option rebind_localhost '0'
	option rebind_protection '1'
	option recursion 'default'
	option root_age '9'
	option ttl_min '120'
	option validator_ntp '1'
	option verbosity '1'
	list iface_trig 'lan'
	list iface_trig 'wan'
	list iface_wan 'wan'
	option add_wan_fqdn '1'
	option dhcp_link 'odhcpd'
	option dhcp4_slaac6 '1'
	option unbound_control '1'
	option add_extra_dns '1'
	option resource 'small'
	option validator '0'
	option protocol 'ip4_only'
	list domain_insecure '0.openwrt.pool.ntp.org'
	list domain_insecure '1.openwrt.pool.ntp.org'
	list domain_insecure '2.openwrt.pool.ntp.org'
	list domain_insecure '3.openwrt.pool.ntp.org'
	list domain_insecure 'volatilesystems.org'
	list domain_insecure 'lan.'
	list domain_insecure '0.10.in-addr.arpa.'
	

config zone 'auth_icann'
	option enabled '0'
	option fallback '1'
	option url_dir 'https://www.internic.net/domain/'
	option zone_type 'auth_zone'
	list server 'lax.xfr.dns.icann.org'
	list server 'iad.xfr.dns.icann.org'
	list zone_name '.'
	list zone_name 'arpa.'
	list zone_name 'in-addr.arpa.'
	list zone_name 'ip6.arpa.'

config zone 'fwd_isp'
	option enabled '0'
	option fallback '1'
	option resolv_conf '1'
	option zone_type 'forward_zone'
	list zone_name 'isp-bill.example.com.'
	list zone_name 'isp-mail.example.net.'

config zone 'fwd_google'
	option enabled '0'
	option fallback '1'
	option tls_index 'dns.google'
	option tls_upstream '1'
	option zone_type 'forward_zone'
	list server '8.8.4.4'
	list server '8.8.8.8'
	list server '2001:4860:4860::8844'
	list server '2001:4860:4860::8888'
	list zone_name '.'

config zone 'fwd_cloudflare'
	option enabled '0'
	option fallback '1'
	option tls_index 'cloudflare-dns.com'
	option tls_upstream '1'
	option zone_type 'forward_zone'
	list server '1.1.1.1'
	list server '1.0.0.1'
	list server '2606:4700:4700::1111'
	list server '2606:4700:4700::1001'
	list zone_name '.'
2

Try to use the default config.
Also recursive DNS without encryption may fail if there's DNS hijacking enabled somewhere upstream.

3

Well, this works, with Unbound (so no dnsmasq installed):

  • Clients querying a remote DNS server (e.g. Quad9 or Google DNS).
  • Router querying a remote DNS server.

Those basically bypass unbound listening on the router, so...

Dnsmasq works as well, but all dnsmasq does is handing off queries to an upstream DNS server AFAIK. It's not a resolver, just a forwarder.

What I'd like to know is how to diagnose this further. It's obvious something's going on here with Unbound, but I don't think my ISP is blocking port 53, since I wouldn't be able to query Quad9 either e.g.

4

Bump. So a vanilla master build (grabbed from downloads.openwrt.org) works, when I have OpenWrt handling the PPPoE session. Nslookup through dnsmasq (router LAN IP) works, as does having nslook talk to e.g. Quad9.

Any ideas?

5

I'm seeing the following behaviour when I have OpenWrt establish the PPP connection:

  • I cannot ping any remote IP addresses (e.g. 9.9.9.9) on the clients; can ping the router. Unbound does not work.
  • After reloading the firewall, I can ping remote addresses, and Unbound works fine.
6
1 Like
7

Thanks, that looks just like what I'm seeing somehow.

@vgaetera I tried the hotplug script you suggested in that topic, but it does not seem to help. I still need to reload the firewall manually before I can reach hosts outside the LAN.

8

If you are using a VPN, then replace automatic WAN detection with a specific interface name.
You can also replace restart with reload if that works for you.

Another possible workaround:

sed -i -e "\$i (sleep 20; /etc/init.d/firewall restart) &" /etc/rc.local
9

That's what I ended up doing, reloading the firewall in /etc/rc.local, thanks.

It looks like the hotplug script you shared still picks up wan instead of pppoe-wan, I might try tinkering with that.

1 Like
10

This topic was automatically closed 10 days after the last reply. New replies are no longer allowed.