dnsproxy: unpacking udp packet: dns: buffer size too small

bcookatpcsd commented 7 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

Other (please mention in the description)

Setup

On one machine

AdGuard Home version

v0.107.48

Action

the logs go back to 107.43 showing this error:

grep -c 'buffer size too small' /var/log/adguard.log 4241

Almost 1k hosts, wired, wireless, etc

All using 53/udp

Alpine linux bare metal vlans and subinterfaces:

ip a | grep UP | grep -c eth0. 17

Expected result

confused what the buffer too small error is related to, and obviously how to deal with it..

Actual result

N/A

Additional information and/or screenshots

regarding ticket #5903, I thought it might be something with that.. but can confirm:

sysctl -a | grep 'rmem_max|wmem_max' net.core.rmem_max = 16777216 net.core.wmem_max = 16777216

6.6.22-0-lts #1-Alpine SMP PREEMPT_DYNAMIC Mon, 18 Mar 2024 10:31:24 +0000

2024/04/05 11:47:13.055240 [info] AdGuard Home, version v0.107.48
2024/04/05 11:47:13.055279 [info] AdGuard Home is running as a service
2024/04/05 11:47:13.150214 [info] AdGuard Home is available at the following addresses:

2024/04/05 11:48:00.723559 [error] dnsproxy: unpacking udp packet: dns: buffer size too small
2024/04/05 11:48:03.779221 [error] dnsproxy: unpacking udp packet: dns: buffer size too small
2024/04/05 11:48:15.029021 [error] dnsproxy: unpacking udp packet: dns: buffer size too small
2024/04/05 11:48:18.031156 [error] dnsproxy: unpacking udp packet: dns: buffer size too small
2024/04/05 11:48:33.088434 [error] dnsproxy: unpacking udp packet: dns: buffer size too small
2024/04/05 11:48:36.118920 [error] dnsproxy: unpacking udp packet: dns: buffer size too small
2024/04/05 11:48:52.737866 [error] dnsproxy: unpacking udp packet: dns: buffer size too small
2024/04/05 11:48:55.767258 [error] dnsproxy: unpacking udp packet: dns: buffer size too small
2024/04/05 11:49:13.112032 [error] dnsproxy: unpacking udp packet: dns: buffer size too small
2024/04/05 11:49:16.218602 [error] dnsproxy: unpacking udp packet: dns: buffer size too small

ghost commented 7 months ago

Hi @bcookatpcsd, thanks for the report. I've seen this pop up a few times in the past, but it rarely has an easy solution.

Could you please

Configure AdGuard Home to collect logs:
Specify log_file
Set verbose to True
Restart AdGuard Home and reproduce the issue
Post the log file here.

thecode commented 6 months ago

To reduce the need to start investigating from scratch, https://github.com/AdguardTeam/AdGuardHome/issues/4094#issuecomment-1820766264 may help

thecode commented 6 months ago

Some problem: 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)"

This is a different issue, reported already multiple times

bcookatpcsd commented 6 months ago

(sorry for the lag..)

--logfile /var/log/adguard.log"

seems to override whatever is in the yaml

log_file is old syntax

Version: v0.107.48 at the time of this debug..

(and the log file is all over the place.. )

;; QUESTION SECTION:
;www.youtube.com.       IN       A

;; ANSWER SECTION:
www.youtube.com.        300     IN      CNAME   restrictmoderate.youtube.com.
restrictmoderate.youtube.com.   300     IN      A       216.239.38.119

2024/04/16 08:48:55.596267 15598#21515 [debug] dnsproxy: handling new udp packet from 10.120.57.3:41655
2024/04/16 08:48:55.596378 15598#21515 [error] dnsproxy: unpacking udp packet: dns: buffer size too small
2024/04/16 08:48:55.643305 15598#21516 [debug] dnsproxy: handling new udp packet from 10.120.57.7:63037
2024/04/16 08:48:55.643409 15598#21516 [debug] github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).logDNSMessage(): IN: ;; opcode: QUERY, status: NOERROR, id: 24544
;; flags: rd; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0

;; QUESTION SECTION:
;api16-normal-useast5.us.tiktokv.com.   IN       A

It seems the upper request goes with the lower log

So I believe www.youtube.com A was asked for.. got the CNAME.. then the A for the CNAME

which I think is request 21515

same host (hmm)

2024/04/16 08:50:08.686596 15598#24453 [debug] dnsforward: finished processing initial
2024/04/16 08:50:08.686639 15598#24471 [debug] dnsforward: finished processing ddr
2024/04/16 08:50:08.686653 15598#5 [debug] clients: processing 10.120.57.3 with rdns
2024/04/16 08:50:08.686834 15598#24475 [debug] github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).logDNSMessage(): IN: ;; opcode: QUERY, status: NOERROR, id: 24463
;; flags: rd; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0

;; QUESTION SECTION:
;www.google.com.        IN       A

2024/04/16 08:50:08.686841 15598#5 [debug] clients: finished processing 10.120.57.3 with rdns in 139.318µs
2024/04/16 08:50:08.686950 15598#5 [debug] clients: processing 10.120.57.3 with whois
2024/04/16 08:50:08.687032 15598#24473 [debug] dnsproxy: handling new udp packet from 10.120.57.3:34598
2024/04/16 08:50:08.687041 15598#24474 [debug] dnsproxy: handling new udp packet from 10.120.57.3:34181
2024/04/16 08:50:08.687059 15598#5 [debug] clients: finished processing 10.120.57.3 with whois in 105.01µs
2024/04/16 08:50:08.687111 15598#24475 [debug] dnsforward: started processing recursion
2024/04/16 08:50:08.687198 15598#5 [debug] clients: processing 10.120.57.3 with rdns
2024/04/16 08:50:08.687214 15598#24473 [error] dnsproxy: unpacking udp packet: dns: buffer size too small
2024/04/16 08:50:08.685272 15598#24428 [debug] dnsforward: started processing local detection
2024/04/16 08:50:08.687382 15598#24428 [debug] dnsforward: finished processing local detection
2024/04/16 08:50:08.685090 15598#24452 [debug] applying filters: looking for client with ip 10.120.57.3 and clientid ""
2024/04/16 08:50:08.687455 15598#24428 [debug] dnsforward: started processing dhcp hosts
2024/04/16 08:50:08.686835 15598#24471 [debug] dnsforward: started processing local detection
2024/04/16 08:50:08.687535 15598#24452 [debug] applying filters: using settings for client "v512" (10.120.57.3; "")
2024/04/16 08:50:08.686342 15598#24472 [debug] dnsforward: started processing local detection
2024/04/16 08:50:08.687601 15598#24428 [debug] dnsforward: finished processing dhcp hosts
2024/04/16 08:50:08.687668 15598#24471 [debug] dnsforward: finished processing local detection
2024/04/16 08:50:08.687789 15598#24452 [debug] dnsforward: finished processing initial
2024/04/16 08:50:08.687836 15598#24471 [debug] dnsforward: started processing dhcp hosts
2024/04/16 08:50:08.687840 15598#24472 [debug] dnsforward: finished processing local detection
2024/04/16 08:50:08.687903 15598#24452 [debug] dnsforward: started processing ddr
2024/04/16 08:50:08.687847 15598#24428 [debug] dnsforward: started processing local restriction
2024/04/16 08:50:08.687982 15598#24471 [debug] dnsforward: finished processing dhcp hosts
2024/04/16 08:50:08.688043 15598#24472 [debug] dnsforward: started processing dhcp hosts
2024/04/16 08:50:08.688132 15598#24452 [debug] dnsforward: finished processing ddr
2024/04/16 08:50:08.688180 15598#24471 [debug] dnsforward: started processing local restriction
2024/04/16 08:50:08.688249 15598#24428 [debug] dnsforward: finished processing local restriction
2024/04/16 08:50:08.688258 15598#24472 [debug] dnsforward: finished processing dhcp hosts
2024/04/16 08:50:08.688379 15598#24452 [debug] dnsforward: started processing local detection
2024/04/16 08:50:08.688440 15598#24428 [debug] dnsforward: started processing dhcp addrs
2024/04/16 08:50:08.688469 15598#24472 [debug] dnsforward: started processing local restriction
2024/04/16 08:50:08.688534 15598#24471 [debug] dnsforward: finished processing local restriction
2024/04/16 08:50:08.688589 15598#24428 [debug] dnsforward: finished processing dhcp addrs
2024/04/16 08:50:08.687303 15598#24474 [debug] github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).logDNSMessage(): IN: ;; opcode: QUERY, status: NOERROR, id: 18
;; flags: rd; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0

;; QUESTION SECTION:
;google.com.    IN       NS

(sorry) I have no idea what logs go with what entries..

more logs

2024/04/16 08:50:11.664521 15598#24675 [debug] dnsforward: started processing initial
2024/04/16 08:50:11.664587 15598#24675 [debug] IPv6 is disabled. Reply with NoError to global.turn.twilio.com. AAAA request
2024/04/16 08:50:11.664668 15598#24675 [debug] dnsforward: finished processing initial
2024/04/16 08:50:11.664643 15598#5 [debug] clients: processing 10.120.56.174 with rdns
2024/04/16 08:50:11.664760 15598#24675 [debug] github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).logDNSMessage(): OUT: ;; opcode: QUERY, status: NOERROR, id: 54055
;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 1, ADDITIONAL: 0

;; QUESTION SECTION:
;global.turn.twilio.com.        IN       AAAA

;; AUTHORITY SECTION:
global.turn.twilio.com. 10      IN      SOA     fake-for-negative-caching.adguard.com. hostmaster.global.turn.twilio.com. 100500 1800 60 604800 86400

2024/04/16 08:50:11.664761 15598#5 [debug] clients: finished processing 10.120.56.174 with rdns in 119.588µs
2024/04/16 08:50:11.664895 15598#5 [debug] clients: processing 10.120.56.174 with whois
2024/04/16 08:50:11.664942 15598#5 [debug] clients: finished processing 10.120.56.174 with whois in 61.807µs
2024/04/16 08:50:11.687223 15598#24676 [debug] dnsproxy: handling new udp packet from 10.120.57.3:34598
2024/04/16 08:50:11.687323 15598#24676 [error] dnsproxy: unpacking udp packet: dns: buffer size too small
2024/04/16 08:50:11.725417 15598#24677 [debug] dnsproxy: handling new tcp request from 10.120.56.174:62711
2024/04/16 08:50:11.726457 15598#24677 [debug] github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).logDNSMessage(): IN: ;; opcode: QUERY, status: NOERROR, id: 42725
;; flags: rd; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0

;; QUESTION SECTION:
;global.turn.twilio.com.        IN       AAAA

2024/04/16 08:50:11.726540 15598#24677 [debug] dnsforward: started processing recursion
2024/04/16 08:50:11.726598 15598#24677 [debug] dnsforward: finished processing recursion
2024/04/16 08:50:11.726649 15598#24677 [debug] dnsforward: started processing initial
2024/04/16 08:50:11.726713 15598#24677 [debug] IPv6 is disabled. Reply with NoError to global.turn.twilio.com. AAAA request
2024/04/16 08:50:11.726782 15598#24677 [debug] dnsforward: finished processing initial
2024/04/16 08:50:11.726801 15598#5 [debug] clients: processing 10.120.56.174 with rdns
2024/04/16 08:50:11.726872 15598#5 [debug] clients: finished processing 10.120.56.174 with rdns in 72.11µs
2024/04/16 08:50:11.726876 15598#24677 [debug] github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).logDNSMessage(): OUT: ;; opcode: QUERY, status: NOERROR, id: 42725
;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 1, ADDITIONAL: 0

;; QUESTION SECTION:
;global.turn.twilio.com.        IN       AAAA

;; AUTHORITY SECTION:
global.turn.twilio.com. 10      IN      SOA     fake-for-negative-caching.adguard.com. hostmaster.global.turn.twilio.com. 100500 1800 60 604800 86400

2024/04/16 08:50:11.726913 15598#5 [debug] clients: processing 10.120.56.174 with whois
2024/04/16 08:50:11.726957 15598#5 [debug] clients: finished processing 10.120.56.174 with whois in 41.194µs
2024/04/16 08:50:11.731453 15598#24677 [debug] handling tcp: reading msg: connection is closed; original error: reading len: EOF
2024/04/16 08:50:11.775742 15598#24639 [debug] dnsproxy: handling new udp packet from 10.120.56.222:54335
2024/04/16 08:50:11.775845 15598#24639 [debug] github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).logDNSMessage(): IN: ;; opcode: QUERY, status: NOERROR, id: 2551
;; flags: rd; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0

;; QUESTION SECTION:
;tile-service.weather.microsoft.com.    IN       A

dhcp via AGH is not enabled.. not sure what the:

2024/04/16 08:50:08.685272 15598#24428 [debug] dnsforward: started processing local detection
2024/04/16 08:50:08.687382 15598#24428 [debug] dnsforward: finished processing local detection
2024/04/16 08:50:08.685090 15598#24452 [debug] applying filters: looking for client with ip 10.120.57.3 and clientid ""
2024/04/16 08:50:08.687455 15598#24428 [debug] dnsforward: started processing dhcp hosts
2024/04/16 08:50:08.686835 15598#24471 [debug] dnsforward: started processing local detection
2024/04/16 08:50:08.687535 15598#24452 [debug] applying filters: using settings for client "v512" (10.120.57.3; "")
2024/04/16 08:50:08.686342 15598#24472 [debug] dnsforward: started processing local detection
2024/04/16 08:50:08.687601 15598#24428 [debug] dnsforward: finished processing dhcp hosts
2024/04/16 08:50:08.687668 15598#24471 [debug] dnsforward: finished processing local detection
2024/04/16 08:50:08.687789 15598#24452 [debug] dnsforward: finished processing initial
2024/04/16 08:50:08.687836 15598#24471 [debug] dnsforward: started processing dhcp hosts
2024/04/16 08:50:08.687840 15598#24472 [debug] dnsforward: finished processing local detection
2024/04/16 08:50:08.687903 15598#24452 [debug] dnsforward: started processing ddr
2024/04/16 08:50:08.687847 15598#24428 [debug] dnsforward: started processing local restriction
2024/04/16 08:50:08.687982 15598#24471 [debug] dnsforward: finished processing dhcp hosts
2024/04/16 08:50:08.688043 15598#24472 [debug] dnsforward: started processing dhcp hosts
2024/04/16 08:50:08.688132 15598#24452 [debug] dnsforward: finished processing ddr
2024/04/16 08:50:08.688180 15598#24471 [debug] dnsforward: started processing local restriction
2024/04/16 08:50:08.688249 15598#24428 [debug] dnsforward: finished processing local restriction
2024/04/16 08:50:08.688258 15598#24472 [debug] dnsforward: finished processing dhcp hosts
2024/04/16 08:50:08.688379 15598#24452 [debug] dnsforward: started processing local detection
2024/04/16 08:50:08.688440 15598#24428 [debug] dnsforward: started processing dhcp addrs
2024/04/16 08:50:08.688469 15598#24472 [debug] dnsforward: started processing local restriction
2024/04/16 08:50:08.688534 15598#24471 [debug] dnsforward: finished processing local restriction
2024/04/16 08:50:08.688589 15598#24428 [debug] dnsforward: finished processing dhcp addrs

is all about..

HTH

disabling the verbose

Please let me know if I can give other information..

robinjoo1 commented 4 months ago

any update on this ?

robinjoo1 commented 4 months ago

i noticed the moment i connect my s24+ 2 of those errors shoot out at the log in have in my asus router what more can i do

blamaz commented 3 months ago

Strange, I start having the same errors shortly after changing my smartphone to a S24

LukePWilkins commented 1 month ago

I have two Android phones connecting to the network and making DNS requests. One or both of these phones is generating this error. When the phones are off the network, I don't get any errors.

nihilt commented 1 month ago

S24U switched to quad9 from cloudflare and the error disappeared.

9000000 commented 1 month ago

I also got the same error, when I checked the log of adguardhome, I found that when it processes a string like ".in-addr.arpa" it will cause the status "[error] dnsproxy: unpacking udp packet: dns: buffer size too small"

please help me fix this error

yuxuan0107 commented 1 month ago

我将使用中文和英文两种方式尝试回答这个问题首先这个问题我也出现很久了大概从我多年前使用ADG开始，今天查阅错误日志，发现大量同样的错误，通过排查发现了问题的出现原因，目前错误已经消失，大家可以参考一下【ADG=AdGardHome】如果你在网络出口网关的地方将DNS劫持到你的ADG，那么ADG将会出现两个错误，一个是BAD RDNS，另外一个是dns: buffer size too small，这两个问题是同步出现的而且都是出现在由网关劫持dns到ADG的时候，如果将网关或其他局域网内劫持DNS的功能关掉，这个问题将会解决，目前我通过这样的方式已经成功解决了这个错误，大家可以尝试一下

I will try to answer this question in both Chinese and English First of all, I have had this problem for a long time. I started using ADG many years ago. Today, I checked the error log and found a large number of the same errors. Through investigation, I found the cause of the problem. Now the error has disappeared. You can refer to [ADG=AdGardHome] If you hijack DNS to your ADG at the point where the network exits the gateway, two errors will appear in ADG. One is BAD RDNS, and the other is dns: buffer size too small. These two problems occur simultaneously and both occur when the gateway hijacks dns to ADG. If you turn off the function of hijacking DNS in the gateway or other local area network, this problem will be solved. So far, I have successfully solved this error in this way. You can try it

thecode commented 1 month ago

If you hijack DNS to your ADG at the point where the network exits the gateway, two errors will appear in ADG. One is BAD RDNS, and the other is dns: buffer size too small. These two problems occur simultaneously and both occur when the gateway hijacks dns to ADG. If you turn off the function of hijacking DNS in the gateway or other local area network, this problem will be solved. So far, I have successfully solved this error in this way. You can try it

I have never used DNS hijacking, I only set the DHCP to offer ADG as default DNS server, but client can use any DNS, I still have this errror and the only thing I found which is cofired by multiple users, when Samsung based smartphones are connected to the network this error occurs, without them there is no errror.

bcookatpcsd commented 1 month ago

@yuxuan0107

Thank you for your response..

Can you provide an example of what you changed which changed your situation?

Thank you in advance.

yuxuan0107 commented 1 month ago

@yuxuan0107

Thank you for your response..感谢您的回复..

Can you provide an example of what you changed which changed your situation?您能否举例说明您改变了什么，从而改变了您的情况？

Thank you in advance. 提前谢谢你。

在我这里，ADG 的ip地址是192.168.1.5，网关地址是192.168.1.1，之前的设置是把所有设置dns地址是192.168.1.1或其他dns的客户端发出的dns查询流量劫持到192.168.1.5，当然我也在dhcp服务中指定了dns服务器地址为192.168.1.5，但是我们无法决定的是有些应用会内置dns解析地址，这导致他们不会使用dhcp发出的dns地址去解析，而是使用应用内置的dns发出查询请求，这时网关就会将这些查询请求劫持到192.168.1.5，这样就会出现文中描述的错误，我将网关的dns劫持关闭之后，所有错误消失

In my case, the IP address of ADG is 192.168.1.5, and the gateway address is 192.168.1.1. The previous setting was to hijack all dns query traffic sent by clients whose dns address is 192.168.1.1 or other dns to 192.168.1.5. Of course, I also specified the dns server address as 192.168.1.5 in the dhcp service, but what we can't decide is that some applications will have built-in dns resolution addresses. This causes them to not use the dns address issued by dhcp to resolve it, but use the built-in dns in the application to issue query requests. At this time, the gateway will hijack these query requests to 192.168.1.5, which will cause the errors described in the article. After I turned off the dns hijacking of the gateway, all errors disappeared

9000000 commented 4 weeks ago

In my case, the IP address of ADG is 192.168.1.5, and the gateway address is 192.168.1.1. The previous setting was to hijack all dns query traffic sent by clients whose dns address is 192.168.1.1 or other dns to 192.168.1.5. Of course, I also specified the dns server address as 192.168.1.5 in the dhcp service, but what we can't decide is that some applications will have built-in dns resolution addresses. This causes them to not use the dns address issued by dhcp to resolve it, but use the built-in dns in the application to issue query requests. At this time, the gateway will hijack these query requests to 192.168.1.5, which will cause the errors described in the article. After I turned off the dns hijacking of the gateway, all errors disappeared

Can you guide me where to turn it off in adg?

bcookatpcsd commented 2 weeks ago

dnsproxy: max goroutines is set count=300

I found a miekg ticket 997 relating to goroutines..

Can someone ELI5 if this could possibly be related?

Could we also talk about cache size being set?

2024/10/22 09:15:10.628700 [info] web: initializing
2024/10/22 09:15:10.865575 [info] dnsproxy: upstream mode is set mode=load_balance
2024/10/22 09:15:10.865603 [info] dnsproxy: cache enabled size=4096
2024/10/22 09:15:10.865612 [info] dnsproxy: max goroutines is set count=300
2024/10/22 09:15:10.865678 [info] dnsproxy: cache ttl override is enabled min=2400 max=14400
2024/10/22 09:15:10.865697 [info] dnsproxy: ratelimit is enabled rps=64 ipv4_subnet_mask_len=24 ipv6_subnet_mask_len=56
2024/10/22 09:15:10.865703 [info] dnsproxy: server will refuse requests of type any
2024/10/22 09:15:10.865710 [info] dnsproxy: upstream mode is set mode=load_balance
2024/10/22 09:15:10.865715 [info] dnsproxy: cache enabled size=67108864
2024/10/22 09:15:10.865723 [info] dnsproxy: max goroutines is set count=300

the above machine is being used an an ipv6 resolver and I rarely, if at all, see this dns: buffer size too small

2024/10/20 15:52:36.545089 [info] AdGuard Home updates are disabled
2024/10/20 15:52:36.545091 [info] web: initializing
2024/10/20 15:52:36.635726 [info] dnsproxy: upstream mode is set mode=load_balance
2024/10/20 15:52:36.635742 [info] dnsproxy: cache enabled size=4096
2024/10/20 15:52:36.635749 [info] dnsproxy: max goroutines is set count=300
2024/10/20 15:52:36.635788 [info] dnsproxy: cache ttl override is enabled min=900 max=9600
2024/10/20 15:52:36.635794 [info] dnsproxy: server will refuse requests of type any
2024/10/20 15:52:36.635798 [info] dnsproxy: upstream mode is set mode=load_balance
2024/10/20 15:52:36.635801 [info] dnsproxy: cache enabled size=134217728
2024/10/20 15:52:36.635807 [info] dnsproxy: max goroutines is set count=300
2024/10/20 15:52:36.635898 [info] clients: processing addresses

this is an ipv4 resolver used for the same purpose and has tons of 'buffer size too small' error messages..

Both using the same upstream (nextdns) but again, one is purely ipv6 (no errors & less cache) and the other is purely ipv4 (many errors & more cache)

ipv6 is linux on a vm at vultr

ipv4 is freebsd on baremetal

ipv6 has ratelimit, ipv4 does not have ratelimit..

HTH

AdguardTeam / AdGuardHome