search

AdguardTeam / dnsproxy

Simple DNS proxy with DoH, DoT, DoQ and DNSCrypt support
Apache License 2.0
2.37k stars 246 forks source link

Caching appears to not be working #417

Open ryancastro opened 2 weeks ago

ryancastro commented 2 weeks ago

Pulled master as of today, and built with sudo go run main.go --config-path=config.yaml --verbose.

I run with the included configuration file, and then I simply hit the server with two dns questions over TLS. Both for google.com. Both requests make a dial out to an upstream provider, rather than using the cache, despite the cache being clearly enabled. Am I simply misunderstanding how caching works? That'd be embarrassing.

Here's some simple reproduction:

# TLS Configuration
tls-crt: fullchain.pem
tls-key: privkey.pem
tls-port: 
  - 853
https-port:
  - 443

# DNS Servers
# timeout: 2s # timeout for upstream dns request
upstream:
  - "1.1.1.1:53"
  - "8.8.8.8:53"
bootstrap:
  - "1.1.1.1:53"
  - "8.8.8.8:53"

# Cache
cache: true
cache-min-ttl: 60
cache-size: 64
ratelimit: 20

Run with Doggo: doggo google.com @tls://mydomain.example.com --time

Here is my verbose output:

Server start:

2024/09/06 11:45:52.910249 INFO dnsproxy starting version="" revision="" branch="" commit_time=""
2024/09/06 11:45:52.910496 DEBUG hosts files are enabled
2024/09/06 11:45:52.910508 DEBUG hosts files are not specified, using default paths=[private/etc/hosts]
2024/09/06 11:45:52.910830 DEBUG set upstream idx=0 addr=1.1.1.1:53
2024/09/06 11:45:52.910839 DEBUG set upstream idx=1 addr=8.8.8.8:53
2024/09/06 11:45:52.911905 INFO cache ttl override is enabled prefix=dnsproxy min=60 max=0
2024/09/06 11:45:52.911917 INFO ratelimit is enabled prefix=dnsproxy rps=20 ipv4_subnet_mask_len=24 ipv6_subnet_mask_len=56
2024/09/06 11:45:52.911941 INFO upstream mode is set prefix=dnsproxy mode=load_balance
2024/09/06 11:45:52.911946 INFO cache enabled prefix=dnsproxy size=64
2024/09/06 11:45:52.911951 INFO starting dns proxy server prefix=dnsproxy
2024/09/06 11:45:52.911989 INFO creating udp server socket prefix=dnsproxy addr=0.0.0.0:53
2024/09/06 11:45:52.912322 INFO listening to udp prefix=dnsproxy addr=[::]:53

Requests (two requests):

2024/09/06 11:46:18.240713 DEBUG handling request prefix=default_handler req=";google.com.\tIN\t A"
2024/09/06 11:46:18.240725 DEBUG no hosts records found prefix=default_handler name=google.com qtype=1
2024/09/06 11:46:18.240799 DEBUG sending request addr=8.8.8.8:53 proto=udp qtype=A qname=google.com.
2024/09/06 11:46:18.240815 DEBUG dialing prefix=bootstrap addr=8.8.8.8:53 idx=1 total=1
2024/09/06 11:46:18.241052 DEBUG connection succeeded prefix=bootstrap addr=8.8.8.8:53 elapsed=224.834µs
2024/09/06 11:46:18.268331 DEBUG response received addr=8.8.8.8:53 proto=udp status=ok
2024/09/06 11:46:18.268399 DEBUG exchange successfully finished prefix=dnsproxy upstream=8.8.8.8:53 question=";google.com.\tIN\t A" duration=27.627042ms
2024/09/06 11:46:18.268417 DEBUG resolved prefix=dnsproxy src=upstream rtt=27.678042ms
2024/09/06 11:46:18.268427 DEBUG ttl overwritten prefix=dnsproxy old=45 new=60
2024/09/06 11:46:18.268474 DEBUG out prefix=dnsproxy line_num=1 line=";; opcode: QUERY, status: NOERROR, id: 47072"
2024/09/06 11:46:18.268483 DEBUG out prefix=dnsproxy line_num=2 line=";; flags: qr rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 0"
2024/09/06 11:46:18.268487 DEBUG out prefix=dnsproxy line_num=3 line=""
2024/09/06 11:46:18.268490 DEBUG out prefix=dnsproxy line_num=4 line=";; QUESTION SECTION:"
2024/09/06 11:46:18.268493 DEBUG out prefix=dnsproxy line_num=5 line=";google.com.\tIN\t A"
2024/09/06 11:46:18.268554 DEBUG out prefix=dnsproxy line_num=6 line=""
2024/09/06 11:46:18.268571 DEBUG out prefix=dnsproxy line_num=7 line=";; ANSWER SECTION:"
2024/09/06 11:46:18.268576 DEBUG out prefix=dnsproxy line_num=8 line="google.com.\t60\tIN\tA\t142.250.188.14"
2024/09/06 11:46:18.268580 DEBUG out prefix=dnsproxy line_num=9 line=""
2024/09/06 11:46:18.269464 DEBUG connection is closed prefix=dnsproxy proto=tcp details="reading msg" err="reading len: EOF"
2024/09/06 11:47:35.106258 DEBUG handling new request prefix=dnsproxy proto=tls raddr=127.0.0.1:64826
2024/09/06 11:47:35.117224 DEBUG in prefix=dnsproxy line_num=1 line=";; opcode: QUERY, status: NOERROR, id: 55618"
2024/09/06 11:47:35.117263 DEBUG in prefix=dnsproxy line_num=2 line=";; flags: rd; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0"
2024/09/06 11:47:35.117268 DEBUG in prefix=dnsproxy line_num=3 line=""
2024/09/06 11:47:35.117273 DEBUG in prefix=dnsproxy line_num=4 line=";; QUESTION SECTION:"
2024/09/06 11:47:35.117277 DEBUG in prefix=dnsproxy line_num=5 line=";google.com.\tIN\t A"
2024/09/06 11:47:35.117281 DEBUG in prefix=dnsproxy line_num=6 line=""
2024/09/06 11:47:35.117552 DEBUG handling request prefix=default_handler req=";google.com.\tIN\t A"
2024/09/06 11:47:35.117571 DEBUG no hosts records found prefix=default_handler name=google.com qtype=1
2024/09/06 11:47:35.117649 DEBUG sending request addr=8.8.8.8:53 proto=udp qtype=A qname=google.com.
2024/09/06 11:47:35.117696 DEBUG dialing prefix=bootstrap addr=8.8.8.8:53 idx=1 total=1
2024/09/06 11:47:35.118238 DEBUG connection succeeded prefix=bootstrap addr=8.8.8.8:53 elapsed=515.209µs
2024/09/06 11:47:35.143151 DEBUG response received addr=8.8.8.8:53 proto=udp status=ok
2024/09/06 11:47:35.143215 DEBUG exchange successfully finished prefix=dnsproxy upstream=8.8.8.8:53 question=";google.com.\tIN\t A" duration=25.595083ms
2024/09/06 11:47:35.143230 DEBUG resolved prefix=dnsproxy src=upstream rtt=25.644625ms
2024/09/06 11:47:35.143339 DEBUG out prefix=dnsproxy line_num=1 line=";; opcode: QUERY, status: NOERROR, id: 55618"
2024/09/06 11:47:35.143366 DEBUG out prefix=dnsproxy line_num=2 line=";; flags: qr rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 0"
2024/09/06 11:47:35.143372 DEBUG out prefix=dnsproxy line_num=3 line=""
2024/09/06 11:47:35.143375 DEBUG out prefix=dnsproxy line_num=4 line=";; QUESTION SECTION:"
2024/09/06 11:47:35.143379 DEBUG out prefix=dnsproxy line_num=5 line=";google.com.\tIN\t A"
2024/09/06 11:47:35.143383 DEBUG out prefix=dnsproxy line_num=6 line=""
2024/09/06 11:47:35.143386 DEBUG out prefix=dnsproxy line_num=7 line=";; ANSWER SECTION:"
2024/09/06 11:47:35.143390 DEBUG out prefix=dnsproxy line_num=8 line="google.com.\t269\tIN\tA\t142.251.46.238"
2024/09/06 11:47:35.143393 DEBUG out prefix=dnsproxy line_num=9 line=""
2024/09/06 11:47:35.143777 DEBUG connection is closed prefix=dnsproxy proto=tcp details="reading msg" err="reading len: EOF"
timkgh commented 1 week ago

My guess is that cache-size: 64 is not enough. That's 64 bytes, not entries. Try something bigger, e.g. 64000 or don't specify it, 64K is default. --cache-size= Cache size (in bytes). Default: 64k