Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

DNS queries are fine, but a failure log appears. #6714

Open
4 tasks done
colaH16 opened this issue Feb 7, 2024 · 12 comments
Open
4 tasks done

DNS queries are fine, but a failure log appears. #6714

colaH16 opened this issue Feb 7, 2024 · 12 comments
Labels
waiting for data Waiting for users to provide more data.

Comments

@colaH16
Copy link

colaH16 commented Feb 7, 2024

Prerequisites

Platform (OS and CPU architecture)

Linux, AMD64 (aka x86_64)

Installation

Docker

Setup

On a router, DHCP is handled by the router

AdGuard Home version

v0.107.44

Action

docker logs -f adg

Expected result

Attaching to adg
adg  | 2024/02/07 11:08:26.656715 [info] AdGuard Home, version v0.107.44
adg  | 2024/02/07 11:08:26.658716 [info] tls: using default ciphers
adg  | 2024/02/07 11:08:26.659697 [info] safesearch default: disabled
adg  | 2024/02/07 11:08:26.670313 [info] Initializing auth module: /opt/adguardhome/work/data/sessions.db
adg  | 2024/02/07 11:08:26.670811 [info] auth: initialized.  users:1  sessions:6
adg  | 2024/02/07 11:08:26.670982 [info] tls: number of certs: 2
adg  | 2024/02/07 11:08:26.671055 [info] tls: got an intermediate cert
adg  | 2024/02/07 11:08:26.692360 [info] AdGuard Home updates are disabled
adg  | 2024/02/07 11:08:26.692371 [info] web: initializing
adg  | 2024/02/07 11:08:26.762724 [info] dnsproxy: cache: enabled, size 4096 b
adg  | 2024/02/07 11:08:26.762737 [info] dnsproxy: max goroutines is set to 300
adg  | 2024/02/07 11:08:26.763395 [info] dnsproxy: cache: disabled
adg  | 2024/02/07 11:08:26.763733 [info] clients: processing addresses
adg  | 2024/02/07 11:08:26.764023 [info] AdGuard Home is available at the following addresses:
adg  | 2024/02/07 11:08:26.764087 [info] go to https://---.---.app:443
adg  | 2024/02/07 11:08:26.764180 [info] go to http://127.0.0.1:80
adg  | 2024/02/07 11:08:26.764183 [info] go to http://172.26.0.2:80
adg  | 2024/02/07 11:08:28.648623 [info] dnsproxy: starting dns proxy server
adg  | 2024/02/07 11:08:28.648643 [info] Cache TTL override is enabled. Min=210, Max=4294967295
adg  | 2024/02/07 11:08:28.648645 [info] The server is configured to refuse ANY requests
adg  | 2024/02/07 11:08:28.648647 [info] dnsproxy: cache: enabled, size 4194304 b
adg  | 2024/02/07 11:08:28.648653 [info] dnsproxy: max goroutines is set to 300
adg  | 2024/02/07 11:08:28.648660 [info] dnsproxy: creating udp server socket 0.0.0.0:53
adg  | 2024/02/07 11:08:28.648730 [info] dnsproxy: listening to udp://[::]:53
adg  | 2024/02/07 11:08:28.648738 [info] dnsproxy: creating tcp server socket 0.0.0.0:53
adg  | 2024/02/07 11:08:28.648764 [info] dnsproxy: listening to tcp://[::]:53
adg  | 2024/02/07 11:08:28.648768 [info] dnsproxy: creating tls server socket 0.0.0.0:853
adg  | 2024/02/07 11:08:28.648801 [info] dnsproxy: listening to tls://[::]:853
adg  | 2024/02/07 11:08:28.648806 [info] Creating a QUIC listener
adg  | 2024/02/07 11:08:28.648976 [info] Listening to quic://[::]:853
adg  | 2024/02/07 11:08:28.649088 [info] dnsproxy: entering udp listener loop on [::]:53
adg  | 2024/02/07 11:08:28.649158 [info] Entering the DNS-over-QUIC listener loop on [::]:853
adg  | 2024/02/07 11:08:28.649298 [info] dnsproxy: entering tcp listener loop on [::]:53
adg  | 2024/02/07 11:08:28.649327 [info] dnsproxy: entering tls listener loop on [::]:853

Actual result

Attaching to adg
adg  | 2024/02/07 11:08:26.656715 [info] AdGuard Home, version v0.107.44
adg  | 2024/02/07 11:08:26.658716 [info] tls: using default ciphers
adg  | 2024/02/07 11:08:26.659697 [info] safesearch default: disabled
adg  | 2024/02/07 11:08:26.670313 [info] Initializing auth module: /opt/adguardhome/work/data/sessions.db
adg  | 2024/02/07 11:08:26.670811 [info] auth: initialized.  users:1  sessions:6
adg  | 2024/02/07 11:08:26.670982 [info] tls: number of certs: 2
adg  | 2024/02/07 11:08:26.671055 [info] tls: got an intermediate cert
adg  | 2024/02/07 11:08:26.692360 [info] AdGuard Home updates are disabled
adg  | 2024/02/07 11:08:26.692371 [info] web: initializing
adg  | 2024/02/07 11:08:26.762724 [info] dnsproxy: cache: enabled, size 4096 b
adg  | 2024/02/07 11:08:26.762737 [info] dnsproxy: max goroutines is set to 300
adg  | 2024/02/07 11:08:26.763395 [info] dnsproxy: cache: disabled
adg  | 2024/02/07 11:08:26.763733 [info] clients: processing addresses
adg  | 2024/02/07 11:08:26.764023 [info] AdGuard Home is available at the following addresses:
adg  | 2024/02/07 11:08:26.764087 [info] go to https://---.---.app:443
adg  | 2024/02/07 11:08:26.764180 [info] go to http://127.0.0.1:80
adg  | 2024/02/07 11:08:26.764183 [info] go to http://172.26.0.2:80
adg  | 2024/02/07 11:08:28.648623 [info] dnsproxy: starting dns proxy server
adg  | 2024/02/07 11:08:28.648643 [info] Cache TTL override is enabled. Min=210, Max=4294967295
adg  | 2024/02/07 11:08:28.648645 [info] The server is configured to refuse ANY requests
adg  | 2024/02/07 11:08:28.648647 [info] dnsproxy: cache: enabled, size 4194304 b
adg  | 2024/02/07 11:08:28.648653 [info] dnsproxy: max goroutines is set to 300
adg  | 2024/02/07 11:08:28.648660 [info] dnsproxy: creating udp server socket 0.0.0.0:53
adg  | 2024/02/07 11:08:28.648730 [info] dnsproxy: listening to udp://[::]:53
adg  | 2024/02/07 11:08:28.648738 [info] dnsproxy: creating tcp server socket 0.0.0.0:53
adg  | 2024/02/07 11:08:28.648764 [info] dnsproxy: listening to tcp://[::]:53
adg  | 2024/02/07 11:08:28.648768 [info] dnsproxy: creating tls server socket 0.0.0.0:853
adg  | 2024/02/07 11:08:28.648801 [info] dnsproxy: listening to tls://[::]:853
adg  | 2024/02/07 11:08:28.648806 [info] Creating a QUIC listener
adg  | 2024/02/07 11:08:28.648976 [info] Listening to quic://[::]:853
adg  | 2024/02/07 11:08:28.649088 [info] dnsproxy: entering udp listener loop on [::]:53
adg  | 2024/02/07 11:08:28.649158 [info] Entering the DNS-over-QUIC listener loop on [::]:853
adg  | 2024/02/07 11:08:28.649298 [info] dnsproxy: entering tcp listener loop on [::]:53
adg  | 2024/02/07 11:08:28.649327 [info] dnsproxy: entering tls listener loop on [::]:853
adg  | 2024/02/07 11:08:49.074292 [error] dnsproxy: 8.20.247.20:53: response received over udp: "exchanging with 8.20.247.20:53 over udp: read udp 172.26.0.2:52726->8.20.247.20:53: i/o timeout"
adg  | 2024/02/07 11:08:49.074306 [error] dnsproxy: 168.126.63.2:53: response received over udp: "exchanging with 168.126.63.2:53 over udp: read udp 172.26.0.2:52248->168.126.63.2:53: i/o timeout"
adg  | 2024/02/07 11:08:49.074327 [error] dnsproxy: 168.126.63.2:53: response received over udp: "exchanging with 168.126.63.2:53 over udp: read udp 172.26.0.2:54699->168.126.63.2:53: i/o timeout"
adg  | 2024/02/07 11:08:49.074332 [error] dnsproxy: 8.20.247.20:53: response received over udp: "exchanging with 8.20.247.20:53 over udp: read udp 172.26.0.2:42247->8.20.247.20:53: i/o timeout"
adg  | 2024/02/07 11:08:49.074335 [error] dnsproxy: 208.67.220.220:53: response received over udp: "exchanging with 208.67.220.220:53 over udp: read udp 172.26.0.2:45407->208.67.220.220:53: i/o timeout"
adg  | 2024/02/07 11:08:49.074347 [error] dnsproxy: 168.126.63.1:53: response received over udp: "exchanging with 168.126.63.1:53 over udp: read udp 172.26.0.2:43850->168.126.63.1:53: i/o timeout"
adg  | 2024/02/07 11:08:49.074350 [error] dnsproxy: 8.8.4.4:53: response received over udp: "exchanging with 8.8.4.4:53 over udp: read udp 172.26.0.2:38987->8.8.4.4:53: i/o timeout"
adg  | 2024/02/07 11:08:49.074355 [error] dnsproxy: 156.154.71.2:53: response received over udp: "exchanging with 156.154.71.2:53 over udp: read udp 172.26.0.2:48121->156.154.71.2:53: i/o timeout"
adg  | 2024/02/07 11:08:49.074363 [error] dnsproxy: 203.248.252.2:53: response received over udp: "exchanging with 203.248.252.2:53 over udp: read udp 172.26.0.2:45793->203.248.252.2:53: i/o timeout"
adg  | 2024/02/07 11:08:49.074365 [error] dnsproxy: 1.0.0.1:53: response received over udp: "exchanging with 1.0.0.1:53 over udp: read udp 172.26.0.2:34784->1.0.0.1:53: i/o timeout"
adg  | 2024/02/07 11:08:49.074370 [error] dnsproxy: 208.67.220.220:53: response received over udp: "exchanging with 208.67.220.220:53 over udp: read udp 172.26.0.2:60015->208.67.220.220:53: i/o timeout"
adg  | 2024/02/07 11:08:49.074381 [error] dnsproxy: 8.8.4.4:53: response received over udp: "exchanging with 8.8.4.4:53 over udp: read udp 172.26.0.2:56328->8.8.4.4:53: i/o timeout"
adg  | 2024/02/07 11:08:49.074381 [error] dnsproxy: 208.67.220.220:53: response received over udp: "exchanging with 208.67.220.220:53 over udp: read udp 172.26.0.2:34987->208.67.220.220:53: i/o timeout"
adg  | 2024/02/07 11:08:49.074386 [error] dnsproxy: 149.112.112.112:53: response received over udp: "exchanging with 149.112.112.112:53 over udp: read udp 172.26.0.2:33072->149.112.112.112:53: i/o timeout"
adg  | 2024/02/07 11:08:49.074393 [error] dnsproxy: 1.0.0.1:53: response received over udp: "exchanging with 1.0.0.1:53 over udp: read udp 172.26.0.2:55983->1.0.0.1:53: i/o timeout"
adg  | 2024/02/07 11:08:49.074398 [error] dnsproxy: 168.126.63.2:53: response received over udp: "exchanging with 168.126.63.2:53 over udp: read udp 172.26.0.2:49823->168.126.63.2:53: i/o timeout"
adg  | 2024/02/07 11:08:49.074402 [error] dnsproxy: 8.8.4.4:53: response received over udp: "exchanging with 8.8.4.4:53 over udp: read udp 172.26.0.2:42199->8.8.4.4:53: i/o timeout"
adg  | 2024/02/07 11:08:49.074310 [error] dnsproxy: 8.8.4.4:53: response received over udp: "exchanging with 8.8.4.4:53 over udp: read udp 172.26.0.2:45792->8.8.4.4:53: i/o timeout"
adg  | 2024/02/07 11:08:49.074408 [error] dnsproxy: 156.154.71.2:53: response received over udp: "exchanging with 156.154.71.2:53 over udp: read udp 172.26.0.2:47391->156.154.71.2:53: i/o timeout"

Additional information and/or screenshots

dns query from docker exec

of course, adg container can query dns from 8.8.4.4 172.26.0.2 1.0.0.1, etc.

adg is the adguard home docker container

cola@docker-adguard:/_DATA/appdata/docker-compose/adg> docker exec adg nslookup naver.com 8.8.4.4
Server:		8.8.4.4
Address:	8.8.4.4:53

Non-authoritative answer:
Name:	naver.com
Address: 223.130.200.107
Name:	naver.com
Address: 223.130.200.104
Name:	naver.com
Address: 223.130.195.200
Name:	naver.com
Address: 223.130.195.95

Non-authoritative answer:

A log of successful queries is left.

of course, adg query dns from 168.126.63.2 successfully.
image

failed on test upstream

image

However, the docker logs are showing i/o time out errors.
It appears that you are checking the connection status in a different way than the actual DNS query.
What method are you using?
@ainar-g
Copy link
Contributor

ainar-g commented Feb 7, 2024

Thanks for the thorough report. Temporary or intermittent timeouts can happen, and the way all of them time out at the same time might suggest that there were network issues around that time. If you want to investigate further, enabling the verbose logging should help.

@ainar-g ainar-g added the waiting for data Waiting for users to provide more data. label Feb 7, 2024
@colaH16
Copy link
Author

colaH16 commented Feb 7, 2024

I checked the "Disable resolving of IPv6 addresses" option, and it doesn't seem to cause the problem anymore.
But why do I see ipv4 in the logs?
Do you think it's related?

image

@colaH16
Copy link
Author

colaH16 commented Feb 7, 2024

I enabled "Disable resolving of IPv6 addresses" and the UDP timeout error was significantly reduced.
Before this, the error like "exchanging with 8.8.4.4:53 over udp: read udp 172.26.0.2:42199->8.8.4.4:53: i/o timeout" occurred about every 2 seconds, but now it occurred 3 times in about 10 minutes.
And after 10 minutes, it decreases even more.
From 10 minutes after startup to 40 minutes after startup, it didn't happen for about 30 minutes.

When I restart the container, the same thing happens 3 times in 5-10 minutes, then not for about 30 minutes.

@bayasdev
Copy link

bayasdev commented Feb 7, 2024

same problem, after v0.107.44 I'm getting DNS timeouts from time to time

@dkarter
Copy link

dkarter commented Feb 8, 2024

Same here.. this got really bad and ended up filling my drive due to the log file getting out of control.

I had this issue in v0.107.41 and it is still happening in v0.107.44

Disabling ipv6 resolution did not help, nor did changing the upstream.

Example logs 
02/07/2024 9:44:11 PM
2024/02/08 03:44:11.483017 [error] dnsproxy: upstream 192.168.7.99:53 failed to exchange ;99.7.168.192.in-addr.arpa.	IN	 PTR in 2.00090522s: exchanging with 192.168.7.99:53 over udp: read udp 172.17.0.7:33596->192.168.7.99:53: i/o timeout
02/07/2024 9:44:11 PM
2024/02/08 03:44:11.484225 [error] dnsproxy: 192.168.7.99:53: response received over udp: "exchanging with 192.168.7.99:53 over udp: read udp 172.17.0.7:35971->192.168.7.99:53: i/o timeout"
02/07/2024 9:44:11 PM
2024/02/08 03:44:11.484278 [error] dnsproxy: upstream 192.168.7.99:53 failed to exchange ;208.7.168.192.in-addr.arpa.	IN	 PTR in 2.001014108s: exchanging with 192.168.7.99:53 over udp: read udp 172.17.0.7:35971->192.168.7.99:53: i/o timeout
02/07/2024 9:44:11 PM
2024/02/08 03:44:11.508942 [error] dnsproxy: 192.168.7.99:53: response received over udp: "exchanging with 192.168.7.99:53 over udp: read udp 172.17.0.7:50655->192.168.7.99:53: i/o timeout"
02/07/2024 9:44:11 PM
2024/02/08 03:44:11.508992 [error] dnsproxy: upstream 192.168.7.99:53 failed to exchange ;1.7.168.192.in-addr.arpa.	IN	 PTR in 2.001581085s: exchanging with 192.168.7.99:53 over udp: read udp 172.17.0.7:50655->192.168.7.99:53: i/o timeout
02/07/2024 9:44:11 PM
2024/02/08 03:44:11.544358 [error] dnsproxy: 192.168.7.99:53: response received over udp: "exchanging with 192.168.7.99:53 over udp: read udp 172.17.0.7:55514->192.168.7.99:53: i/o timeout"
02/07/2024 9:44:11 PM
2024/02/08 03:44:11.544402 [error] dnsproxy: upstream 192.168.7.99:53 failed to exchange ;lb._dns-sd._udp.0.7.168.192.in-addr.arpa.	IN	 PTR in 2.002036543s: exchanging with 192.168.7.99:53 over udp: read udp 172.17.0.7:55514->192.168.7.99:53: i/o timeout
02/07/2024 9:44:11 PM
2024/02/08 03:44:11.551940 [error] dnsproxy: 192.168.7.99:53: response received over udp: "exchanging with 192.168.7.99:53 over udp: read udp 172.17.0.7:41047->192.168.7.99:53: i/o timeout"
02/07/2024 9:44:11 PM
2024/02/08 03:44:11.551989 [error] dnsproxy: upstream 192.168.7.99:53 failed to exchange ;lb._dns-sd._udp.0.64.168.192.in-addr.arpa.	IN	 PTR in 2.002112672s: exchanging with 192.168.7.99:53 over udp: read udp 172.17.0.7:41047->192.168.7.99:53: i/o timeout
02/07/2024 9:44:11 PM
2024/02/08 03:44:11.735040 [error] dnsproxy: 192.168.7.99:53: response received over udp: "exchanging with 192.168.7.99:53 over udp: read udp 172.17.0.7:46351->192.168.7.99:53: i/o timeout"
02/07/2024 9:44:11 PM
2024/02/08 03:44:11.735097 [error] dnsproxy: upstream 192.168.7.99:53 failed to exchange ;lb._dns-sd._udp.0.7.168.192.in-addr.arpa.	IN	 PTR in 2.002159857s: exchanging with 192.168.7.99:53 over udp: read udp 172.17.0.7:46351->192.168.7.99:53: i/o timeout
02/07/2024 9:44:11 PM
2024/02/08 03:44:11.858850 [error] dnsproxy: 192.168.7.99:53: response received over udp: "exchanging with 192.168.7.99:53 over udp: read udp 172.17.0.7:45924->192.168.7.99:53: i/o timeout"
02/07/2024 9:44:11 PM
2024/02/08 03:44:11.858904 [error] dnsproxy: upstream 192.168.7.99:53 failed to exchange ;lb._dns-sd._udp.0.7.168.192.in-addr.arpa.	IN	 PTR in 2.000766054s: exchanging with 192.168.7.99:53 over udp: read udp 172.17.0.7:45924->192.168.7.99:53: i/o timeout
02/07/2024 9:44:11 PM
2024/02/08 03:44:11.859226 [error] dnsproxy: 192.168.7.99:53: response received over udp: "exchanging with 192.168.7.99:53 over udp: read udp 172.17.0.7:40287->192.168.7.99:53: i/o timeout"
02/07/2024 9:44:11 PM
2024/02/08 03:44:11.859264 [error] dnsproxy: upstream 192.168.7.99:53 failed to exchange ;lb._dns-sd._udp.0.7.168.192.in-addr.arpa.	IN	 PTR in 2.000920127s: exchanging with 192.168.7.99:53 over udp: read udp 172.17.0.7:40287->192.168.7.99:53: i/o timeout
02/07/2024 9:44:12 PM
2024/02/08 03:44:12.001471 [error] dnsproxy: 192.168.7.99:53: response received over udp: "exchanging with 192.168.7.99:53 over udp: read udp 172.17.0.7:41856->192.168.7.99:53: i/o timeout"

@bayasdev
Copy link

bayasdev commented Feb 8, 2024 •
edited
Loading

same problem, after v0.107.44 I'm getting DNS timeouts from time to time

Just reviewed the logs and my Adguard Home is trying to perform the requests over IPv6 but it fails due to no IPv6 connectivity inside the container.

2024/02/07 23:14:09.993049 [error] dnsproxy: upstream tls://dns.quad9.net:853 failed to exchange ;update.googleapis.com.    IN       A in 611.011µs: getting conn to tls://dns.quad9.net:853: connecting to dns.quad9.net: dial tcp [2620:fe::9]:853: connect: cannot assign requested address
dial tcp [2620:fe::fe]:853: connect: cannot assign requested address

I double checked that prefer IPv6 is disabled as well on the config file but still no luck.

bootstrap_prefer_ipv6: false

@colaH16
Copy link
Author

colaH16 commented Feb 8, 2024

I already disabled it
#6714 (comment)

Before I disabled that setting, I was seeing that error log about every 2-3 seconds
Now that I've disabled that setting, I'm down to about 53 errors in 12 hours.
53 is about 4 per hour.
But it's still happening.

adguardhome-75bb55f667-h98nm_adguardhome.log

I'll post the log again with verbose.

@colaH16
Copy link
Author

colaH16 commented Feb 8, 2024

here is the verbose log.
thank you.
adguardhome-6b587c4464-8r9db_adguardhome.log

@dermoeck
Copy link

dermoeck commented Mar 1, 2024 •
edited
Loading

Same here one two instances - one installed on raspi directly and one installed as docker container. Both running with latest version, tested also with edge version.
I see several (2-5) errors a second

@blub2
Copy link

blub2 commented Mar 25, 2024

For me this solved the problem https://www.reddit.com/r/Adguard/comments/1ajijuh/adguard_failed_to_exchange_with_upstream_router/

After that no more error messages in log files and CPU usage went from 25% to 1%

@colaH16
Copy link
Author

colaH16 commented Mar 25, 2024

Unfortunately, I don't have a reverse DNS server registered with AdAds or DNS servers. My AdAds only point to public DNS servers

@geraistec
Copy link

Same error Versão: v0.107.48

2024/04/09 11:36:50.586816 [error] dnsproxy: https://dns12.quad9.net:443/dns-query: response received over tcp: "requesting https://dns12.quad9.net:443/dns-query: Get \"https://dns12.quad9.net:443/dns-query?dns=AAABAAABAAAAAAABBXdob2lzBGFyaW4DbmV0AAABAAEAACkIAAAAgAAAAA\": net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)"

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
waiting for data Waiting for users to provide more data.
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
7 participants
@dkarter @ainar-g @blub2 @colaH16 @bayasdev @dermoeck @geraistec