DNS queries are fine, but a failure log appears.

colaH16 commented 9 months ago

Prerequisites

[X] I have checked the Wiki and Discussions and found no answer
[X] I have searched other issues and found no duplicates
[X] I want to report a bug and not ask a question or ask for help
[X] I have set up AdGuard Home correctly and configured clients to use it. (Use the Discussions for help with installing and configuring clients.)

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.

failed on test upstream

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 commented 9 months ago

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.

colaH16 commented 9 months ago

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?

colaH16 commented 9 months ago

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 commented 9 months ago

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

dkarter commented 9 months ago

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 commented 9 months ago

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 commented 9 months ago

I already disabled it https://github.com/AdguardTeam/AdGuardHome/issues/6714#issuecomment-1932417139

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 commented 9 months ago

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

dermoeck commented 8 months ago

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 commented 7 months ago

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 commented 7 months ago

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

AdguardTeam / AdGuardHome