AdGuard Home cannot work for 5 minutes after boot, DNS timeouts (Raspberry Pi)

[ghost]

When setting the Upstream DNS servers from the default TLS to Cloudflare's DoH (https://cloudflare-dns.com/dns-query), rebooting the Pi causes AdGuard Home to behave unexpectedly once booted.

No clients can use DNS, the DNS requests all timeout. Trying to visit the admin page causes the settings page to freeze and not load for a very long time, with errors about timeouts for version checks to github. If I can get it to eventually load, I need to clear the DoH entry so it reverts back to the default TLS entries.

Once it uses TLS again, all clients can use DNS fine and the AdGuard Home admin interface works normally again.

So DNS-over-HTTPS does not work for me once I restart the Pi.

[ameshkov]

Could you please collect AGH logs (preferably, with verbose logging enabled)?

[ameshkov]

Tbh, it sounds like some kind of a recursion issue (AGH tries to resolve Cloudflare domain name through itself). What bootstrap DNS server do you have configured?

[ghost]

Oops, you are right. I do have 1.1.1.1 as the bootstrap DNS server, does this mean the bootstrap must be different to the Upstream DNS server, or can I use IP addresses instead of the domain name, since the default TLS works at the moment?

eg. instead of https://cloudflare-dns.com/dns-query, I set
https://1.1.1.1/dns-query and
https://1.0.0.1/dns-query

[ameshkov]

Oops, you are right. I do have 1.1.1.1 as the bootstrap DNS server, does this mean the bootstrap must be different to the Upstream DNS server

Well, actually it should've worked just okay, what matters is that bootstrap DNS shouldn't be 127.0.0.1.

Could you please export logs just in case? We want to make a DOH upstream default so it might be important.

[ghost]

Could you please export logs just in case? We want to make a DOH upstream default so it might be important.

I've done it with verbose, but there is quite a bit of metadata. Could I email it to you so it's not public on here?

From what I see, if you set the DoH without rebooting, it can work fine:
2019/03/12 09:51:22 [42] proxy.exchangeWithUpstream(): upstream https://cloudflare-dns.com:443/dns-query successfully finished exchange of ;adguardteam.github.io

But once rebooted you get this instead:
2019/03/12 09:54:18 [40] proxy.exchangeWithUpstream(): upstream https://cloudflare-dns.com:443/dns-query failed to exchange ;sb.adtidy.org.

And since the admin interface relies on external connections, it also suffers.

[ameshkov]

I've done it with verbose, but there is quite a bit of metadata. Could I email it to you so it's not public on here?

Sure, please send it to devteam@adguard.com

[ghost]

Thank you, sent it now.

[ameshkov]

Got the log, thank you!

Quick analysis:

1. Bootstrap DNS is okay, it managed to resolve cloudflare-dns.com

   2019/03/12 09:54:08 [40] upstream.lookup(): successfully finish lookup for cloudflare-dns.com in 34 milliseconds using 1.1.1.1:53. Result : [{104.16.112.25 } {104.16.111.25 } {2606:4700::6810:7019 } {2606:4700::6810:6f19 }]
   

2. It has successfully connected to the DOH server:

   2019/03/12 09:54:13 [75] upstream.createDialContext.func1(): Dialing to 104.16.112.25:443
   2019/03/12 09:54:13 [75] upstream.createDialContext.func1(): dialer successfully initialize connection to 104.16.112.25:443 in 25 milliseconds
   

3. Then the HTTP request timed out:

   2019/03/12 09:54:18 [40] proxy.exchangeWithUpstream(): upstream https://cloudflare-dns.com:443/dns-query failed to exchange ;sb.adtidy.org.	IN	 A in 10043665621 milliseconds. Cause: couldn't do a POST request to 'https://cloudflare-dns.com:443/dns-query', cause: Post https://cloudflare-dns.com:443/dns-query: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
   

It means that the TLS connection was also established without issues, but there's no response from CF to the DNS query.

Is this how it behaves every time or is it just after rebooting the pi?

[ghost]

Is this how it behaves every time or is it just after rebooting the pi?

Once I save the settings for the DoH server to overwrite the existing TLS defaults, it can still function (as you saw in the logs). But, once I either restart the service or restart the Pi, all DNS stops working no matter what I do. Once I set it back to TLS defaults and restart the service or Pi, all is working again.

[ameshkov]

@planet0 is it specific to Cloudflare or to any DOH resolver? Have you tried any other DOH server?

[ghost]

I tried to use Quad9's DoH and the same issue occurred. Unfortunately I also managed to completely break the entire AdGuard Home service as the default Cloudflare TLS also stopped working and rebooting the Pi wasn't doing anything either. Deleting the .yaml file and setting it up again still didn't work. Reinstalling the service didn't work either.

I reinstalled Pi-hole and the DNS started to work again without a reboot.

I think I need to try using AdGuard Home with a fresh install of Raspbian and not from a previous Pi-hole installation, and revisit this another time.

[ameshkov]

Sounds really unusual, I don't understand what can possibly cause all this:( As if something is preventing connecting to non-standard ports or smth like this.

[ghost]

It might be how much Pi-hole modifies or configs the Pi, but I won't know until I fresh install... does any over at AdGuard have a Raspberry Pi that could replicate installing Pi-hole, uninstalling it and then trying to run AdGuard Home for this?

[ameshkov]

@planet0 yeah, I guess we can try that. Btw, have you been using the built-in DHCP in pi-hole and AGH?

@szolin could you please try doing it?

[ghost]

Btw, have you been using the built-in DHCP in pi-hole and AGH?

For Pi-hole I was using the built-in DHCP as it works really good, for this instance I used my TP-Link to manage DHCP for using AdGuard Home as there are still some bugs to iron out, and no ability for static leases from memory.

The only other thing I can think of is that I was able to use 'cloudflared' alongside Pi-hole so I could use DNS-over-HTTPS for 1.1.1.1, with this guide: https://docs.pi-hole.net/guides/dns-over-https/

It was working really well.

I did uninstall the service and remove all cloudflared files before trying AdGuard Home, but the fact that cloudflared can work for DoH and not AdGuard Home is confusing.

[ameshkov]

@planet0 btw, any idea where Koala postfix comes from in the DNS questions after the service restart?

;; QUESTION SECTION:
;adguardteam.github.io.Koala.	IN	 A

[ameshkov]

Ah, nvm

[ghost]

It was the DHCP Domain name, yeah.

[ameshkov]

It'd interesting to check a couple more things:

1. Try using https://1.1.1.1/dns-query as a DOH upstream
2. After restart try this command to check connectivity to CF DNS: openssl s_client -connect 104.16.112.25:443 -servername cloudflare-dns.com. Make sure that this command is executed under the same user as AGH.
3. Also, I'd like to see what you have in /etc/resolv.conf

[ghost]

Okay, I've played around with it some more after uninstalling Pi-hole again.

I found the root issue, and it's that when I reboot the Pi, AdGuard Home is unable to use the DNS port for about 5 minutes (I timed it with a stopwatch).

Once 5 minutes passes, all DNS traffic works and the version checks in the Admin page pass, and I can also change to use and test upstream for any DNS, so both https://cloudflare-dns.com/dns-query and https://1.1.1.1/dns-query works. I used v0.92-hotfix1 so I can see the banner appear for the new version. I can stop and restart AdGuard Home afterwards and it works straight away.

It's not related to the install or uninstall of the service, as running directly via sudo ./AdGuardHome --host 192.168.0.2 produces the same results (and was useful for testing).

This is why setting the DoH was working before rebooting when I opened this issue. Something on this Pi isn't letting AdGuard Home work for 5 minutes after booting up, yet Pi-hole is able to load instantly.

3. Also, I'd like to see what you have in /etc/resolv.conf

Pi-hole forces this to be 127.0.0.1 and leaves the static config on the Pi, but removing the static entry afterwards defaults resolv.conf to the IP of the Pi, in my case 192.168.0.2. Changing it to 1.1.1.1 or 8.8.8.8 doesn't help during these 5 minutes regardless.

[ameshkov]

to use the DNS port

The issue is valid for DOH only, right?
Is it okay when you select a plain DNS upstream?

yet Pi-hole is able to load instantly

Were you using it's own DHCP when testing?

[ghost]

It got to the point where nothing was working, including regular upstreams or changing the bootstrap. After 5 minutes, all DNS types can work.

Pi-hole was still using the TP-Link DHCP device, I simply ran the install command and once finished, dns started to work. Rebooting the Pi also works seconds after finishing boot.

Another thought I had is that I had a few ‘apt-get’ updates on the Pi, perhaps one of them has changed the behaviour of Raspbian in the last few weeks since I last used AdGuard Home.

[ameshkov]

Do they both (AGH and Pi-Hole) work under the same user?
Is it root?

[ghost]

Do they both (AGH and Pi-Hole) work under the same user?
Is it root?

AdGuard Home doesn't require any user setup does it, it just uses the person's regular user account (eg. default 'pi')?

From what I can see and from looking at their install script, I believe Pi-hole uses their own user (cloudflared does too).

Line 1708 in that script adds a user 'pihole'.

Also looking at this issue over at Pi-hole (pi-hole/pi-hole#1547), they mention that they use setcaps for binding ports, which I personally do not understand but might shed some light in how they operate it. They also seem to use root for some actions.

FTLDNS now runs as non-root but with setcap's for binding to lower ports and that's a big exposure reduced.

[ghost]

I think this is a wider non-AGH related issue, as I have had the same issue with cloudflared. Others are experiencing the same issue as me, so I suspect something Pi related and not an issue with AdGuard Home.

cloudflare/cloudflared#23

[saltama]

And this is the log of the service after a reboot, but WITH verbose enabled:
adh3.log.txt.zip

Not much too see other than some requests failing after 200s. Still hundreds of threads in htop.
Both these tests are using only tls and parallel enabled.

But... i got it working right at boot with two DoH servers and no parallel, first time ever.

Edit: Tried again after 2 minutes, it stopped working again. :(

[szolin]

In the log file above there are 1228 attempted connections to 4 upstream servers from function AdguardTeam/dnsproxy/upstream.createDialContext() - 4 connections per 1 DNS request, plus 16 times AGH tried to get an update for a filter.

148 out of those 1228 requests failed with "i/o timeout" error after ~3 minutes.
It means that 1k requests are still pending (and their socket fd's are still opened) while they are waiting for network I/O.

So looking at this log I can only see that AGH simply can't reach the Internet servers - they all fail after timeout.
I recommend using a network traffic sniffer like tcpdump or wireshark to ensure that those connection attempts are really delivered to the network interface. And if they do, we need to check whether any packets from the upstream servers are delivered back to AGH.

Currently we don't know where the packets get stuck, so the first step is to find where this issue comes from.

[ameshkov]

@planet0 @saltama I just stumbled upon this comment in the similar issue of CF repo:
cloudflare/cloudflared#23 (comment)

BUT after the connection is restored it still doesn't return DNS responses. I can fix it by pinging 1.0.0.1 (not restarting cloudflared) . This makes me suspect a lower layer issue - routing, perhaps?

Could you please check if it helps to ping 1.1.1.1/1.0.0.1?

[saltama]

Could you please check if it helps to ping 1.1.1.1/1.0.0.1?

Doesn't work for me, the pings go through but adguard is still blocked(after 20 mins it still is) with the hundreds of threads.

It means that 1k requests are still pending (and their socket fd's are still opened) while they are waiting for network I/O.

Should these be there in the first place? I mean, if we have another thread trying to make i/o to an unresponding address, should we open more? (also, shouldn't we have some limit?)
But ok, i don't even know what creates those threads and why so... nevermind.

I recommend using a network traffic sniffer like tcpdump or wireshark to ensure that those connection attempts are really delivered to the network interface.

As last resort yes.

[ghost]

Quickly adding that it is possible to ping 1.1.1.1/1.0.0.1 during this time, but it doesn’t affect AGH regardless until 5 minutes after boot.

It was the same behaviour with cloudflared, I couldn’t do anything to fix it until 5 minutes as well for cloudflared to start working.

[ameshkov]

Should these be there in the first place? I mean, if we have another thread trying to make i/o to an unresponding address, should we open more? (also, shouldn't we have some limit?)

@saltama well, yeah, but it will only fix one of the symptoms, it will not fix the root cause.

Also, I think the i/o timeout issue you're experiencing is different from this one.

There are two different issues:

1. No connection for the first 5 min after RPi reboot.
2. i/o timeout errors that starting to appear after a few minutes of working without issues.

We tried updating our test RPi and installing the same packages, but still, we weren't able to reproduce it. So it seems we really need your help to figure what's wrong.

@planet0 @saltama could you please collect tcpdump for us?

Here's what needs to be done:

1. Wait until the issue is reproduced.
2. Run tcpdump -i IFACE -w FILE.pcap where IFACE is the name of the network interface, FILE is the dump filename.
3. We'll need this file to analyze.

[saltama]

There are two different issues:

100% agree.

I'd prefer to send you the dump only when I'll be able to isolate the router and the pi0 in a somewhat proper testbed. Need some time to be able to set it up.

[ameshkov]

Sure, np.

Btw, as I recall, you can limit tcpdump to specific IP addresses so that there will be no risk in leaking anything private (communication with DOH/DOT is encrypted anyways).

[ghost]

Haven't had the chance to test it yet, but Raspbian had a new update released on April 8, I would like to see if that has made any changes regarding this issue.

Forgot to mention, I'm running Raspbian Lite instead of the desktop version.

[ghost]

Tried with cloudflared, still experiencing the same issue even with the recent updates for Raspbian and cloudflared. Going to assume that AdGuard Home would still experience the same issue then. Mentioned it at cloudflare/cloudflared#91.

[szolin]

@planet0 Does the issue still persist? If yes, how about that tcpdump data for DNS requests? You can use tcpdump's filters (IPs, ports) and give us only related information.

[ghost]

@szolin I haven't forgotten about this! I've found some time to work on this now - would you be able to help me figure out how to get the required tcpdump data from a Raspberry Pi running Raspbian Lite?

Edit: Oops, I forgot about the instructions that @ameshkov provided above. Will get onto this, still sending to devteam[at]adguard.com?

[ghost]

Some good news @szolin @ameshkov, it seems that with Raspbian Buster, I no longer need to wait 5 minutes on boot - network connections are going through just fine. 🎉

[szolin]

Glad to hear!

[saltama]

Can confirm this too!

[cwyin7788]

When setting the Upstream DNS servers from the default TLS to Cloudflare's DoH (https://cloudflare-dns.com/dns-query), rebooting the Pi causes AdGuard Home to behave unexpectedly once booted.

No clients can use DNS, the DNS requests all timeout. Trying to visit the admin page causes the settings page to freeze and not load for a very long time, with errors about timeouts for version checks to github. If I can get it to eventually load, I need to clear the DoH entry so it reverts back to the default TLS entries.

Once it uses TLS again, all clients can use DNS fine and the AdGuard Home admin interface works normally again.

So DNS-over-HTTPS does not work for me once I restart the Pi.

I have this problem too,I found that when u reboot the Pi,systemd-resolved this process will run,listen udp port 53,it make AGH cannot use port 53,it make AGH fail to run,so use this command to disable systemd-resolved.

sudo service systemd-resolved stop
sudo systemctl disable systemd-resolved
sudo reboot

after reboot,everything will back to normal

sorry for my bad english.

[ghost]

@i553041 I'm not sure if it's universal, but it seems that on my vanilla install of Raspbian, systemd-resolved is already disabled on my end. But this is still good, thank you.