search

getdnsapi / stubby

Stubby is the name given to a mode of using getdns which enables it to act as a local DNS Privacy stub resolver (using DNS-over-TLS).
https://dnsprivacy.org/dns_privacy_daemon_-_stubby/
BSD 3-Clause "New" or "Revised" License
1.2k stars 99 forks source link

Stubby(v0.2.6)DNS resolvers are changed again and again even if the round_robin_upstreams='0' #346

Open sangs303 opened 1 year ago

sangs303 commented 1 year ago

(OpenWrt v18.06.8, r7989-82fbd85747)

root@OpenWrt:~# uci show stubby stubby.global=stubby stubby.global.manual='0' stubby.global.trigger='wan' stubby.global.tls_query_padding_blocksize='128' stubby.global.appdata_dir='/var/lib/stubby' stubby.global.edns_client_subnet_private='1' stubby.global.idle_timeout='10000' stubby.global.listen_address='127.0.0.1@5453' '0::1@5453' stubby.global.round_robin_upstreams='0' stubby.global.tls_authentication='GETDNS_AUTHENTICATION_NONE' stubby.global.log_level='7' stubby.global.dns_transport='GETDNS_TRANSPORT_TLS' 'GETDNS_TRANSPORT_TCP' 'GETDNS_TRANSPORT_UDP' stubby.@resolver[0]=resolver stubby.@resolver[0].address='44.194.59.83' stubby.@resolver[0].tls_auth_name='yyy' stubby.@resolver[1]=resolver stubby.@resolver[1].address='100.25.249.20' stubby.@resolver[1].tls_auth_name='xxx' stubby.@resolver[2]=resolver stubby.@resolver[2].address='34.195.80.81' stubby.@resolver[2].tls_auth_name='zzz' stubby.@resolver[3]=resolver stubby.@resolver[3].address='10.12.158.254' stubby.@resolver[3].tls_auth_name='xxx' stubby.@resolver[4]=resolver stubby.@resolver[4].address='10.176.254.254' stubby.@resolver[4].tls_auth_name='xxx' stubby.@resolver[5]=resolver stubby.@resolver[5].address='10.180.254.254' stubby.@resolver[5].tls_auth_name='xxx'

root@OpenWrt:~# stubby -V Stubby 0.2.6

Executed the below command from the OpenWrt terminal,

while true; do dig @127.0.0.1 -p 5453 google.com; sleep 11; done

Logs:


Thu Aug 31 06:53:47 2023 daemon.err stubby[2897]: [06:53:47.130219] STUBBY: 34.195.80.81                             : Conn closed: TLS - Resps=     1, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)= 10000
Thu Aug 31 06:53:47 2023 daemon.err stubby[2897]: [06:53:47.130254] STUBBY: 34.195.80.81                             : Upstream   : TLS - Resps=    27, Timeouts  =     2, Best_auth =Success
Thu Aug 31 06:53:47 2023 daemon.err stubby[2897]: [06:53:47.130267] STUBBY: 34.195.80.81                             : Upstream   : TLS - Conns=    18, Conn_fails=     0, Conn_shuts=     18, Backoffs     =     0
Thu Aug 31 06:53:50 2023 daemon.err stubby[2897]: [06:53:50.142211] STUBBY: 44.194.59.83                             : Conn opened: TLS - Opportunistic Profile
Thu Aug 31 06:53:59 2023 daemon.err stubby[2897]: [06:53:59.100064] STUBBY: 44.194.59.83                             : Conn closed: TLS - Resps=     1, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)= 10000
Thu Aug 31 06:53:59 2023 daemon.err stubby[2897]: [06:53:59.100098] STUBBY: 44.194.59.83                             : Upstream   : TLS - Resps=    33, Timeouts  =     4, Best_auth =Success
Thu Aug 31 06:53:59 2023 daemon.err stubby[2897]: [06:53:59.100112] STUBBY: 44.194.59.83                             : Upstream   : TLS - Conns=    23, Conn_fails=     0, Conn_shuts=     19, Backoffs     =     0
Thu Aug 31 06:54:00 2023 daemon.err stubby[2897]: [06:54:00.483966] STUBBY: 100.25.249.20                            : Conn opened: TLS - Opportunistic Profile
Thu Aug 31 06:54:10 2023 daemon.err stubby[2897]: [06:54:10.354949] STUBBY: 100.25.249.20                            : Conn closed: TLS - Resps=     3, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)= 10000
Thu Aug 31 06:54:10 2023 daemon.err stubby[2897]: [06:54:10.354983] STUBBY: 100.25.249.20                            : Upstream   : TLS - Resps=    35, Timeouts  =     5, Best_auth =Success
Thu Aug 31 06:54:10 2023 daemon.err stubby[2897]: [06:54:10.354996] STUBBY: 100.25.249.20                            : Upstream   : TLS - Conns=    21, Conn_fails=     0, Conn_shuts=     19, Backoffs     =     0
Thu Aug 31 06:54:13 2023 daemon.err stubby[2897]: [06:54:13.365225] STUBBY: 100.25.249.20                            : Conn opened: TLS - Opportunistic Profile
Thu Aug 31 06:54:22 2023 daemon.err stubby[2897]: [06:54:22.275697] STUBBY: 100.25.249.20                            : Conn closed: TLS - Resps=     1, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)= 10000
Thu Aug 31 06:54:22 2023 daemon.err stubby[2897]: [06:54:22.275730] STUBBY: 100.25.249.20                            : Upstream   : TLS - Resps=    36, Timeouts  =     5, Best_auth =Success
Thu Aug 31 06:54:22 2023 daemon.err stubby[2897]: [06:54:22.275744] STUBBY: 100.25.249.20                            : Upstream   : TLS - Conns=    22, Conn_fails=     0, Conn_shuts=     20, Backoffs     =     0
Thu Aug 31 06:54:25 2023 daemon.err stubby[2897]: [06:54:25.286466] STUBBY: 34.195.80.81                             : Conn opened: TLS - Opportunistic Profile
Thu Aug 31 06:54:34 2023 daemon.err stubby[2897]: [06:54:34.220355] STUBBY: 34.195.80.81                             : Conn closed: TLS - Resps=     1, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)= 10000
Thu Aug 31 06:54:34 2023 daemon.err stubby[2897]: [06:54:34.220390] STUBBY: 34.195.80.81                             : Upstream   : TLS - Resps=    28, Timeouts  =     2, Best_auth =Success
Thu Aug 31 06:54:34 2023 daemon.err stubby[2897]: [06:54:34.220403] STUBBY: 34.195.80.81                             : Upstream   : TLS - Conns=    19, Conn_fails=     0, Conn_shuts=     19, Backoffs     =     0
Thu Aug 31 06:54:37 2023 daemon.err stubby[2897]: [06:54:37.233295] STUBBY: 44.194.59.83                             : Conn opened: TLS - Opportunistic Profile
Thu Aug 31 06:54:46 2023 daemon.err stubby[2897]: [06:54:46.224247] STUBBY: 44.194.59.83                             : Conn closed: TLS - Resps=     1, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)= 10000
Thu Aug 31 06:54:46 2023 daemon.err stubby[2897]: [06:54:46.224281] STUBBY: 44.194.59.83                             : Upstream   : TLS - Resps=    34, Timeouts  =     4, Best_auth =Success
Thu Aug 31 06:54:46 2023 daemon.err stubby[2897]: [06:54:46.224294] STUBBY: 44.194.59.83                             : Upstream   : TLS - Conns=    24, Conn_fails=     0, Conn_shuts=     20,
sangs303 commented 1 year ago

I have tried the with the Cloudflare server and observed the same behavior.

root@OpenWrt:~# uci show stubby
stubby.global=stubby
stubby.global.manual='0'
stubby.global.trigger='wan'
stubby.global.tls_query_padding_blocksize='128'
stubby.global.appdata_dir='/var/lib/stubby'
stubby.global.edns_client_subnet_private='1'
stubby.global.idle_timeout='10000'
stubby.global.listen_address='127.0.0.1@5453' '0::1@5453'
stubby.global.round_robin_upstreams='0'
stubby.global.log_level='7'
stubby.global.dns_transport='GETDNS_TRANSPORT_TLS' 'GETDNS_TRANSPORT_UDP' 'GETDNS_TRANSPORT_TCP'
stubby.@resolver[0]=resolver
stubby.@resolver[0].address='1.1.1.1'
stubby.@resolver[0].tls_auth_name='cloudflare-dns.com'
stubby.@resolver[1]=resolver
stubby.@resolver[1].address='1.0.0.1'
stubby.@resolver[1].tls_auth_name='cloudflare-dns.com'
sangs303 commented 1 year ago

As per the document,

_* round_robin_upstreams: Round-robin queries across all the configured upstream servers. Without this option, Stubby will use each upstream server sequentially until it becomes unavailable and then move on to use the next._

But it does not behave like mentioned. why? Please suggest.


root@OpenWrt:~# logread -f | grep stubby
Thu Aug 31 12:46:40 2023 daemon.err stubby[9661]: [12:46:40.746907] STUBBY: 1.0.0.1                                  : Conn closed: TLS - Resps=     1, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)= 10000
Thu Aug 31 12:46:40 2023 daemon.err stubby[9661]: [12:46:40.746941] STUBBY: 1.0.0.1                                  : Upstream   : TLS - Resps=    11, Timeouts  =     0, Best_auth =Success
Thu Aug 31 12:46:40 2023 daemon.err stubby[9661]: [12:46:40.746954] STUBBY: 1.0.0.1                                  : Upstream   : TLS - Conns=    11, Conn_fails=     0, Conn_shuts=      9, Backoffs     =     0
Thu Aug 31 12:46:41 2023 daemon.err stubby[9661]: [12:46:41.757714] STUBBY: 1.1.1.1                                  : Conn opened: TLS - Opportunistic Profile
Thu Aug 31 12:46:41 2023 daemon.err stubby[9661]: [12:46:41.856423] STUBBY: 1.1.1.1                                  : Verify passed : TLS
Thu Aug 31 12:46:51 2023 daemon.err stubby[9661]: [12:46:51.883197] STUBBY: 1.1.1.1                                  : Conn closed: TLS - Resps=     1, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)= 10000
Thu Aug 31 12:46:51 2023 daemon.err stubby[9661]: [12:46:51.883233] STUBBY: 1.1.1.1                                  : Upstream   : TLS - Resps=    10, Timeouts  =     0, Best_auth =Success
Thu Aug 31 12:46:51 2023 daemon.err stubby[9661]: [12:46:51.883246] STUBBY: 1.1.1.1                                  : Upstream   : TLS - Conns=    10, Conn_fails=     0, Conn_shuts=      9, Backoffs     =     0
Thu Aug 31 12:46:52 2023 daemon.err stubby[9661]: [12:46:52.894108] STUBBY: 1.0.0.1                                  : Conn opened: TLS - Opportunistic Profile
Thu Aug 31 12:47:03 2023 daemon.err stubby[9661]: [12:47:03.013683] STUBBY: 1.0.0.1                                  : Conn closed: TLS - Resps=     1, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)= 10000
Thu Aug 31 12:47:03 2023 daemon.err stubby[9661]: [12:47:03.013718] STUBBY: 1.0.0.1                                  : Upstream   : TLS - Resps=    12, Timeouts  =     0, Best_auth =Success
Thu Aug 31 12:47:03 2023 daemon.err stubby[9661]: [12:47:03.013731] STUBBY: 1.0.0.1                                  : Upstream   : TLS - Conns=    12, Conn_fails=     0, Conn_shuts=     10, Backoffs     =     0
Thu Aug 31 12:47:04 2023 daemon.err stubby[9661]: [12:47:04.024454] STUBBY: 1.1.1.1                                  : Conn opened: TLS - Opportunistic Profile
Thu Aug 31 12:47:14 2023 daemon.err stubby[9661]: [12:47:14.189701] STUBBY: 1.1.1.1                                  : Conn closed: TLS - Resps=     1, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)= 10000
Thu Aug 31 12:47:14 2023 daemon.err stubby[9661]: [12:47:14.189735] STUBBY: 1.1.1.1                                  : Upstream   : TLS - Resps=    11, Timeouts  =     0, Best_auth =Success
Thu Aug 31 12:47:14 2023 daemon.err stubby[9661]: [12:47:14.189749] STUBBY: 1.1.1.1                                  : Upstream   : TLS - Conns=    11, Conn_fails=     0, Co
```nn_shuts=     10, Backoffs     =     0
saradickinson commented 1 year ago

I think the issue here is the idle_timeout of 10000, which is long enough that the upstream is actually shutting the connection each time (instead of stubby) - see the Conn_shuts= value in the logs. This triggers the unavailable criteria for stubby and causes it to move to the next upstream. You want this idle_timeout value as high as possible for efficiency but some resolvers apply limits server side e.g. Cloudflare

If you look in the config file you will see this comment: 

## Cloudflare 1.1.1.1 and 1.0.0.1
## (NOTE: recommend reducing idle_timeout to 9000 if using Cloudflare)

Which is because of this behaviour. I see the following log if I do reduce idle_timeout to 9000:

[16:47:32.623206] STUBBY: 1.1.1.1                                  : Conn opened: TLS - Strict Profile
[16:47:32.882675] STUBBY: 1.1.1.1                                  : Verify passed : TLS
[16:47:41.912256] STUBBY: 1.1.1.1                                  : Conn closed: TLS - Resps=     1, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=  9000
[16:47:41.912272] STUBBY: 1.1.1.1                                  : Upstream   : TLS - Resps=     1, Timeouts  =     0, Best_auth =Success
[16:47:41.912275] STUBBY: 1.1.1.1                                  : Upstream   : TLS - Conns=     1, Conn_fails=     0, Conn_shuts=      0, Backoffs     =     0
[16:47:43.924166] STUBBY: 1.1.1.1                                  : Conn opened: TLS - Strict Profile
[16:47:43.990580] STUBBY: 1.1.1.1                                  : Verify passed : TLS
[16:47:53.060844] STUBBY: 1.1.1.1                                  : Conn closed: TLS - Resps=     1, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=  9000
[16:47:53.060860] STUBBY: 1.1.1.1                                  : Upstream   : TLS - Resps=     2, Timeouts  =     0, Best_auth =Success
[16:47:53.060863] STUBBY: 1.1.1.1                                  : Upstream   : TLS - Conns=     2, Conn_fails=     0, Conn_shuts=      0, Backoffs     =     0
[16:47:55.070885] STUBBY: 1.1.1.1                                  : Conn opened: TLS - Strict Profile
[16:47:55.104292] STUBBY: 1.1.1.1                                  : Verify passed : TLS
[16:48:04.174794] STUBBY: 1.1.1.1                                  : Conn closed: TLS - Resps=     1, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=  9000
[16:48:04.174812] STUBBY: 1.1.1.1                                  : Upstream   : TLS - Resps=     3, Timeouts  =     0, Best_auth =Success
[16:48:04.174815] STUBBY: 1.1.1.1                                  : Upstream   : TLS - Conns=     3, Conn_fails=     0, Conn_shuts=      0, Backoffs     =     0
[16:48:06.187998] STUBBY: 1.1.1.1                                  : Conn opened: TLS - Strict Profile

Please try this modification and it should change the behaviour with Cloudflare. You will have to experiment to see what is needed with your other resolvers.

sangs303 commented 1 year ago

Thanks, it working fine. Let me try with all scenerio