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.

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

Adguard DNS name resolution times out with OpenWrt/stubby #150

Closed
Ryan-Goldstein opened this issue Apr 14, 2021 · 37 comments
Closed

Adguard DNS name resolution times out with OpenWrt/stubby #150

Ryan-Goldstein opened this issue Apr 14, 2021 · 37 comments

Comments

@Ryan-Goldstein
Copy link

Ryan-Goldstein commented Apr 14, 2021

I've been using AdGuard DNS for many months by connecting to it via DoT through stubby in my OpenWrt-flashed router, running the latest version of both OpenWrt (19.07.7) and stubby (0.3.0-1).

It had been working well up until about a week ago, when I started seeing resolution timeouts, mostly on Google-related domains, and I understand that that has since been fixed per this blog post.

In the past few days, possibly corresponding to the changes made to fix the aforementioned timeout issue, I have started experiencing a different issue, where after 5-15 minutes, name resolution stops working on all clients and my router itself. Running nslookup on any domain when my router enters this state results in:

;; connection timed out; no servers could be reached

There's nothing indicated in the OpenWrt system logs at the debug log level, but name resolution simply stops working, with name resolution attempts timing out. Restarting stubby with service stubby restart resolves the issue again for approximately 5-15 minutes longer, at which time the same problem occurs.

Keeping all stubby settings the same, but switching from Adguard DNS to Cloudflare DNS, that issue no longer occurs, so it seems attributable specifically to Adguard DNS.

Here is my stubby configuration with Adguard DNS being used:

resolution_type: GETDNS_RESOLUTION_STUB
round_robin_upstreams: 0
appdata_dir: "/var/lib/stubby"
tls_authentication: GETDNS_AUTHENTICATION_REQUIRED
tls_query_padding_blocksize: 128
edns_client_subnet_private: 1
idle_timeout: 10000
listen_addresses:
  - 127.0.0.1@5453
  - 0::1@5453
dns_transport_list:
  - GETDNS_TRANSPORT_TLS
upstream_recursive_servers:
#  - address_data: 1.1.1.1
#    tls_auth_name: "cloudflare-dns.com"
#  - address_data: 1.0.0.1
#    tls_auth_name: "cloudflare-dns.com"
  - address_data: 94.140.14.14
    tls_auth_name: "dns.adguard.com"
  - address_data: 94.140.15.15
    tls_auth_name: "dns.adguard.com"

When switching to Cloudflare DNS by removing the commented lines, and commenting out the Adguard DNS lines, then restarting stubby with service stubby restart, name resolution works and remains working without having to restart the stubby service.

I'd be happy to provide any other requested information and/or follow any suggested troubleshooting steps. Thanks in advance!

@Ryan-Goldstein Ryan-Goldstein changed the title Name resolution stops with OpenWrt/stubby Adguard DNS name resolution times out with OpenWrt/stubby Apr 14, 2021
@ameshkov
Copy link
Member

Interesting! Quick question - is there anything save for stubby in this configuration? dnsmasq or something like that?

@Ryan-Goldstein
Copy link
Author

Thanks for the quick response! Yes, dnsmasq (version 2.80-16.3) is used. Here's that configuration as in /etc/config/dhcp:

config dnsmasq
        option domainneeded '1'
        option localise_queries '1'
        option local '/lan/'
        option domain 'lan'
        option expandhosts '1'
        option authoritative '1'
        option readethers '1'
        option leasefile '/tmp/dhcp.leases'
        option localservice '1'
        option noresolv '1'
        option rebind_protection '0'
        option filterwin2k '1'
        list server '127.0.0.1#5453'
        option ednspacket_max '1280'

@ameshkov
Copy link
Member

There's nothing indicated in the OpenWrt system logs at the debug log level, but name resolution simply stops working, with name resolution attempts timing out

As I understand, there's a way to enable stubby logs if you modify the service file to run stubby with -l -v flags. This way it will write the log to stdout. Could you please try doing it and see if there's anything useful in that log?

@Ryan-Goldstein
Copy link
Author

Sure, good idea. Here's the output:

root@OpenWrt:~# stubby -C /etc/stubby/stubby.yml -l -v 7
[22:23:45.075112] STUBBY: Stubby version: Stubby 0.3.0
[22:23:45.101176] STUBBY: Read config from file /etc/stubby/stubby.yml
[22:23:45.103842] STUBBY: DNSSEC Validation is OFF
[22:23:45.105555] STUBBY: Transport list is:
[22:23:45.106142] STUBBY:   - TLS
[22:23:45.106720] STUBBY: Privacy Usage Profile is Strict (Authentication required)
[22:23:45.107328] STUBBY: (NOTE a Strict Profile only applies when TLS is the ONLY transport!!)
[22:23:45.107922] STUBBY: Starting DAEMON....
[22:23:53.165523] STUBBY: 94.140.14.14                             : Conn opened: TLS - Strict Profile
[22:23:53.371218] STUBBY: 94.140.14.14                             : Verify passed : TLS
[22:24:06.173842] STUBBY: 94.140.14.14                             : Conn closed: TLS - Resps=    10, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)= 10000
[22:24:06.174011] STUBBY: 94.140.14.14                             : Upstream   : TLS - Resps=    10, Timeouts  =     0, Best_auth =Success
[22:24:06.174073] STUBBY: 94.140.14.14                             : Upstream   : TLS - Conns=     1, Conn_fails=     0, Conn_shuts=      1, Backoffs     =     0
[22:24:10.517978] STUBBY: 94.140.14.14                             : Conn opened: TLS - Strict Profile
[22:24:10.688062] STUBBY: 94.140.14.14                             : Verify passed : TLS
[22:24:54.815281] STUBBY: 94.140.14.14                             : Conn closed: TLS - Resps=    62, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)= 10000
[22:24:54.815468] STUBBY: 94.140.14.14                             : Upstream   : TLS - Resps=    72, Timeouts  =     0, Best_auth =Success
[22:24:54.815532] STUBBY: 94.140.14.14                             : Upstream   : TLS - Conns=     2, Conn_fails=     0, Conn_shuts=      2, Backoffs     =     0
[22:24:56.212526] STUBBY: 94.140.14.14                             : Conn opened: TLS - Strict Profile
[22:24:56.571421] STUBBY: 94.140.14.14                             : Verify passed : TLS
[22:25:10.403978] STUBBY: 94.140.14.14                             : Conn closed: TLS - Resps=    28, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)= 10000
[22:25:10.404162] STUBBY: 94.140.14.14                             : Upstream   : TLS - Resps=   100, Timeouts  =     0, Best_auth =Success
[22:25:10.404226] STUBBY: 94.140.14.14                             : Upstream   : TLS - Conns=     3, Conn_fails=     0, Conn_shuts=      3, Backoffs     =     0
[22:25:16.520991] STUBBY: 94.140.14.14                             : Conn opened: TLS - Strict Profile
[22:25:16.692839] STUBBY: 94.140.14.14                             : Verify passed : TLS
[22:25:29.653832] STUBBY: 94.140.14.14                             : Conn closed: TLS - Resps=    12, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)= 10000
[22:25:29.654015] STUBBY: 94.140.14.14                             : Upstream   : TLS - Resps=   112, Timeouts  =     0, Best_auth =Success
[22:25:29.654077] STUBBY: 94.140.14.14                             : Upstream   : TLS - Conns=     4, Conn_fails=     0, Conn_shuts=      4, Backoffs     =     0
[22:25:29.976502] STUBBY: 94.140.14.14                             : Conn opened: TLS - Strict Profile
[22:25:30.163277] STUBBY: 94.140.14.14                             : Verify passed : TLS
[22:26:06.343125] STUBBY: 94.140.14.14                             : Conn closed: TLS - Resps=    33, Timeouts  =    36, Curr_auth =Success, Keepalive(ms)= 10000
[22:26:06.344821] STUBBY: 94.140.14.14                             : Upstream   : TLS - Resps=   145, Timeouts  =    36, Best_auth =Success
[22:26:06.347239] STUBBY: 94.140.14.14                             : Upstream   : TLS - Conns=     5, Conn_fails=     0, Conn_shuts=      5, Backoffs     =     0
[22:26:06.352278] STUBBY: 94.140.14.14                             : Conn opened: TLS - Strict Profile
[22:26:06.547571] STUBBY: 94.140.14.14                             : Verify passed : TLS
[22:26:11.356387] STUBBY: 94.140.14.14                             : Conn closed: TLS - *Failure*
[22:26:11.359613] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[22:26:11.378542] STUBBY: 94.140.14.14                             : Conn closed: TLS - Resps=     0, Timeouts  =     1, Curr_auth =Success, Keepalive(ms)=     0
[22:26:11.380390] STUBBY: 94.140.14.14                             : Upstream   : TLS - Resps=   145, Timeouts  =    37, Best_auth =Success
[22:26:11.383170] STUBBY: 94.140.14.14                             : Upstream   : TLS - Conns=     6, Conn_fails=     0, Conn_shuts=      6, Backoffs     =     0
[22:26:11.603142] STUBBY: 94.140.15.15                             : Verify passed : TLS
[22:26:34.253735] STUBBY: 94.140.15.15                             : Conn closed: TLS - *Failure*
[22:26:34.259023] STUBBY: 94.140.14.14                             : Conn opened: TLS - Strict Profile
[22:26:34.262537] STUBBY: 94.140.15.15                             : Conn closed: TLS - *Failure*
[22:26:34.295235] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=    18, Timeouts  =    38, Curr_auth =Success, Keepalive(ms)= 10000
[22:26:34.297534] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=    18, Timeouts  =    38, Best_auth =Success
[22:26:34.301689] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=     1, Conn_fails=     0, Conn_shuts=      1, Backoffs     =     0
[22:26:34.504156] STUBBY: 94.140.14.14                             : Verify passed : TLS
[22:26:40.080507] STUBBY: 94.140.14.14                             : Conn closed: TLS - *Failure*
[22:26:40.081429] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[22:26:40.087556] STUBBY: 94.140.14.14                             : Conn closed: TLS - Resps=     0, Timeouts  =    13, Curr_auth =Success, Keepalive(ms)=     0
[22:26:40.090748] STUBBY: 94.140.14.14                             : Upstream   : TLS - Resps=   145, Timeouts  =    50, Best_auth =Success
[22:26:40.094060] STUBBY: 94.140.14.14                             : Upstream   : TLS - Conns=     7, Conn_fails=     0, Conn_shuts=      7, Backoffs     =     0
[22:26:40.479164] STUBBY: 94.140.15.15                             : Verify passed : TLS
[22:26:45.091306] STUBBY: 94.140.15.15                             : Conn closed: TLS - *Failure*
[22:26:45.096395] STUBBY: 94.140.14.14                             : Conn opened: TLS - Strict Profile
[22:26:45.103514] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     1, Curr_auth =Success, Keepalive(ms)=     0
[22:26:45.105139] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=    18, Timeouts  =    39, Best_auth =Success
[22:26:45.108374] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=     2, Conn_fails=     0, Conn_shuts=      2, Backoffs     =     0
[22:26:45.278697] STUBBY: 94.140.14.14                             : Verify passed : TLS
[22:26:50.115487] STUBBY: 94.140.14.14                             : Conn closed: TLS - Resps=     0, Timeouts  =     2, Curr_auth =Success, Keepalive(ms)=     0
[22:26:50.118426] STUBBY: 94.140.14.14                             : Upstream   : TLS - Resps=   145, Timeouts  =    52, Best_auth =Success
[22:26:50.121018] STUBBY: 94.140.14.14                             : Upstream   : TLS - Conns=     8, Conn_fails=     0, Conn_shuts=      7, Backoffs     =     0
[22:26:50.945472] STUBBY: 94.140.14.14                             : Conn opened: TLS - Strict Profile
[22:26:51.117342] STUBBY: 94.140.14.14                             : Verify passed : TLS
[22:26:55.949691] STUBBY: 94.140.14.14                             : Conn closed: TLS - *Failure*
[22:26:55.952305] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[22:26:55.966188] STUBBY: 94.140.14.14                             : Conn closed: TLS - Resps=     0, Timeouts  =     1, Curr_auth =Success, Keepalive(ms)=     0
[22:26:55.967705] STUBBY: 94.140.14.14                             : Upstream   : TLS - Resps=   145, Timeouts  =    53, Best_auth =Success
[22:26:55.968591] STUBBY: 94.140.14.14                             : Upstream   : TLS - Conns=     9, Conn_fails=     0, Conn_shuts=      8, Backoffs     =     0
[22:26:56.127278] STUBBY: 94.140.15.15                             : Verify passed : TLS
[22:27:01.149804] STUBBY: 94.140.15.15                             : Conn closed: TLS - *Failure*
[22:27:01.151743] STUBBY: 94.140.14.14                             : Conn opened: TLS - Strict Profile
[22:27:01.158489] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     8, Curr_auth =Success, Keepalive(ms)=     0
[22:27:01.160220] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=    18, Timeouts  =    47, Best_auth =Success
[22:27:01.161663] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=     3, Conn_fails=     0, Conn_shuts=      3, Backoffs     =     0
[22:27:01.330359] STUBBY: 94.140.14.14                             : Verify passed : TLS
[22:27:06.167731] STUBBY: 94.140.14.14                             : Conn closed: TLS - *Failure*
[22:27:06.170416] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[22:27:06.185290] STUBBY: 94.140.14.14                             : Conn closed: TLS - Resps=     0, Timeouts  =     1, Curr_auth =Success, Keepalive(ms)=     0
[22:27:06.190133] STUBBY: 94.140.14.14                             : Upstream   : TLS - Resps=   145, Timeouts  =    54, Best_auth =Success
[22:27:06.192299] STUBBY: 94.140.14.14                             : Upstream   : TLS - Conns=    10, Conn_fails=     0, Conn_shuts=      9, Backoffs     =     0
[22:27:06.354026] STUBBY: 94.140.15.15                             : Verify passed : TLS
[22:27:11.171553] STUBBY: 94.140.15.15                             : Conn closed: TLS - *Failure*
[22:27:11.174164] STUBBY: 94.140.14.14                             : Conn opened: TLS - Strict Profile
[22:27:11.179845] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     1, Curr_auth =Success, Keepalive(ms)=     0
[22:27:11.181387] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=    18, Timeouts  =    48, Best_auth =Success
[22:27:11.183803] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=     4, Conn_fails=     0, Conn_shuts=      4, Backoffs     =     0
[22:27:11.355405] STUBBY: 94.140.14.14                             : Verify passed : TLS
[22:27:16.261095] STUBBY: 94.140.14.14                             : Conn closed: TLS - *Failure*
[22:27:16.262124] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[22:27:16.267266] STUBBY: 94.140.14.14                             : Conn closed: TLS - Resps=     0, Timeouts  =     1, Curr_auth =Success, Keepalive(ms)=     0
[22:27:16.267610] STUBBY: 94.140.14.14                             : Upstream   : TLS - Resps=   145, Timeouts  =    55, Best_auth =Success
[22:27:16.267683] STUBBY: 94.140.14.14                             : Upstream   : TLS - Conns=    11, Conn_fails=     0, Conn_shuts=     10, Backoffs     =     0
[22:27:16.438826] STUBBY: 94.140.15.15                             : Verify passed : TLS

Everything seemed fine at first, and I was running nslookup throughout, and results returned fine. After I started seeing the Conn closed: TLS - *Failure* messages, subsequent nslookup commands started returning ;; connection timed out; no servers could be reached until I restarted the stubby process.

I hope that helps! Any other ideas/thoughts?

@Ryan-Goldstein
Copy link
Author

As a data point, I was running stubby with debug output for a good 15-20 minutes with only my computer connected to my router making occasional DNS queries, and it continued working fine during that time. So I stopped stubby, started it again with debug output enabled, and then connected my phone and my Roku to my router to increase the number of connected devices and DNS queries, and very soon thereafter, within a minute or so, those failures started appearing.

So it appears that the number and/or frequency of DNS queries could be contributing to this issue, and potentially the number of active connected devices on the router.

But again, with Cloudflare DNS as the configured provider and all other settings the same, it continues working, even under high DNS load with many connected devices. I've been running stubby with debug output, using Cloudflare DNS, for the past 30 minutes or so with lots of DNS activity across multiple devices, I didn't see a single Conn closed: TLS - *Failure* message, and name resolution has continued working properly. Here's the most recent stubby debug output while using Cloudflare DNS:

[22:53:46.716253] STUBBY: 1.1.1.1                                  : Conn opened: TLS - Strict Profile
[22:53:46.896398] STUBBY: 1.1.1.1                                  : Verify passed : TLS
[22:55:25.649405] STUBBY: 1.1.1.1                                  : Conn closed: TLS - Resps=    64, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)= 10000
[22:55:25.649721] STUBBY: 1.1.1.1                                  : Upstream   : TLS - Resps=   597, Timeouts  =     4, Best_auth =Success
[22:55:25.649823] STUBBY: 1.1.1.1                                  : Upstream   : TLS - Conns=    40, Conn_fails=     0, Conn_shuts=     34, Backoffs     =     0

@ameshkov
Copy link
Member

My idea is that stubby does not handle remote end closing the connection properly. On our side, we're using an idle_timeout of 8 seconds, and 2 seconds until the first TLS query is received.

Please try setting idle_timeout to 7000, and if it does not help, to 1000.

@ameshkov
Copy link
Member

@saradickinson Sara, could you please take a look? What could be the reason for this stubby behavior?

@saradickinson
Copy link

@ameshkov So the logs are showing that all the connections are shutdown by the far end, but this is not causing stubby to backoff from using the upstream, stubby is continuing to connect and send requests but it would be better to lower the idle_timeout as suggested.

What I do see is that there are a bunch of timeouts on one connection (e.g. the one to 94.140.14.14 closed at 22:26:06.343125 and the connections problems start after that and all are closed after ~5 seconds. I haven't seen this behaviour before but the fact that restarting stubby fixes it does seem to indicate a problem in the failure handling.... I'll try to dig into it!

@Ryan-Goldstein
Copy link
Author

Ryan-Goldstein commented Apr 15, 2021

Thanks for the additional investigation and suggestions. I changed the idle_timeout to 7000 as suggested, and the same issue occurred after about 10 minutes.

I then changed the idle_timeout to 1000 as suggested, and here is the debug output:

root@OpenWrt:~# stubby -C /etc/stubby/stubby.yml -l -v 7
[13:54:17.818169] STUBBY: Stubby version: Stubby 0.3.0
[13:54:17.846276] STUBBY: Read config from file /etc/stubby/stubby.yml
[13:54:17.850738] STUBBY: DNSSEC Validation is OFF
[13:54:17.851970] STUBBY: Transport list is:
[13:54:17.852559] STUBBY:   - TLS
[13:54:17.854131] STUBBY: Privacy Usage Profile is Strict (Authentication required)
[13:54:17.855231] STUBBY: (NOTE a Strict Profile only applies when TLS is the ONLY transport!!)
[13:54:17.855903] STUBBY: Starting DAEMON....
[13:54:30.211429] STUBBY: 94.140.14.14                             : Conn opened: TLS - Strict Profile
[13:54:30.391130] STUBBY: 94.140.14.14                             : Verify passed : TLS
[13:54:31.492446] STUBBY: 94.140.14.14                             : Conn closed: TLS - Resps=     1, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=  1000
[13:54:31.492640] STUBBY: 94.140.14.14                             : Upstream   : TLS - Resps=     1, Timeouts  =     0, Best_auth =Success
[13:54:31.492705] STUBBY: 94.140.14.14                             : Upstream   : TLS - Conns=     1, Conn_fails=     0, Conn_shuts=      0, Backoffs     =     0

...

[14:06:15.776623] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[14:06:15.951955] STUBBY: 94.140.15.15                             : Verify passed : TLS
[14:06:16.046057] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[14:06:16.048784] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   281, Timeouts  =     0, Best_auth =Success
[14:06:16.054303] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=   141, Conn_fails=     0, Conn_shuts=     61, Backoffs     =     0
[14:06:16.059815] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[14:06:16.232333] STUBBY: 94.140.15.15                             : Verify passed : TLS
[14:06:16.326786] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[14:06:16.328369] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   281, Timeouts  =     0, Best_auth =Success
[14:06:16.329950] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=   142, Conn_fails=     0, Conn_shuts=     62, Backoffs     =     0
[14:06:16.336000] STUBBY: 94.140.14.14                             : Conn opened: TLS - Strict Profile
[14:06:16.503546] STUBBY: 94.140.14.14                             : Verify passed : TLS
[14:06:21.344899] STUBBY: 94.140.14.14                             : Conn closed: TLS - *Failure*
[14:06:21.349701] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[14:06:21.359769] STUBBY: 94.140.14.14                             : Conn closed: TLS - Resps=     0, Timeouts  =     2, Curr_auth =Success, Keepalive(ms)=     0
[14:06:21.361304] STUBBY: 94.140.14.14                             : Upstream   : TLS - Resps=    14, Timeouts  =    40, Best_auth =Success
[14:06:21.362769] STUBBY: 94.140.14.14                             : Upstream   : TLS - Conns=     6, Conn_fails=     0, Conn_shuts=      2, Backoffs     =     0
[14:06:21.523953] STUBBY: 94.140.15.15                             : Verify passed : TLS
[14:06:21.619902] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[14:06:21.621999] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   281, Timeouts  =     0, Best_auth =Success
[14:06:21.623601] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=   143, Conn_fails=     0, Conn_shuts=     63, Backoffs     =     0
[14:06:21.629121] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[14:06:21.821793] STUBBY: 94.140.15.15                             : Verify passed : TLS
[14:06:22.022552] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[14:06:22.022742] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   281, Timeouts  =     0, Best_auth =Success
[14:06:22.022806] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=   144, Conn_fails=     0, Conn_shuts=     64, Backoffs     =     0
[14:06:23.222611] STUBBY: 94.140.14.14                             : Conn opened: TLS - Strict Profile
[14:06:23.393655] STUBBY: 94.140.14.14                             : Verify passed : TLS
[14:06:28.843665] STUBBY: 94.140.14.14                             : Conn closed: TLS - *Failure*
[14:06:28.846500] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[14:06:28.847367] STUBBY: 94.140.14.14                             : Conn closed: TLS - *Failure*
[14:06:28.865070] STUBBY: 94.140.14.14                             : Conn closed: TLS - Resps=     0, Timeouts  =     7, Curr_auth =Success, Keepalive(ms)=     0
[14:06:28.867363] STUBBY: 94.140.14.14                             : Upstream   : TLS - Resps=    14, Timeouts  =    47, Best_auth =Success
[14:06:28.870344] STUBBY: 94.140.14.14                             : Upstream   : TLS - Conns=     7, Conn_fails=     0, Conn_shuts=      3, Backoffs     =     0
[14:06:29.026394] STUBBY: 94.140.15.15                             : Verify passed : TLS
[14:06:29.121076] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[14:06:29.122719] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   281, Timeouts  =     0, Best_auth =Success
[14:06:29.125228] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=   145, Conn_fails=     0, Conn_shuts=     65, Backoffs     =     0
[14:06:29.974192] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[14:06:31.199646] STUBBY: 94.140.15.15                             : Verify passed : TLS
[14:06:31.306502] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[14:06:31.309858] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   281, Timeouts  =     0, Best_auth =Success
[14:06:31.310811] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=   146, Conn_fails=     0, Conn_shuts=     66, Backoffs     =     0
[14:06:31.317783] STUBBY: 94.140.14.14                             : Conn opened: TLS - Strict Profile
[14:06:31.504130] STUBBY: 94.140.14.14                             : Verify passed : TLS
[14:06:36.322529] STUBBY: 94.140.14.14                             : Conn closed: TLS - *Failure*
[14:06:36.324976] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[14:06:36.336089] STUBBY: 94.140.14.14                             : Conn closed: TLS - Resps=     0, Timeouts  =     1, Curr_auth =Success, Keepalive(ms)=     0
[14:06:36.337610] STUBBY: 94.140.14.14                             : Upstream   : TLS - Resps=    14, Timeouts  =    48, Best_auth =Success
[14:06:36.338887] STUBBY: 94.140.14.14                             : Upstream   : TLS - Conns=     8, Conn_fails=     0, Conn_shuts=      4, Backoffs     =     0
[14:06:36.493501] STUBBY: 94.140.15.15                             : Verify passed : TLS
[14:06:36.594900] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[14:06:36.597824] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   281, Timeouts  =     0, Best_auth =Success
[14:06:36.600397] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=   147, Conn_fails=     0, Conn_shuts=     67, Backoffs     =     0
[14:06:36.604658] STUBBY: 94.140.14.14                             : Conn opened: TLS - Strict Profile
[14:06:36.791781] STUBBY: 94.140.14.14                             : Verify passed : TLS
[14:06:41.613262] STUBBY: 94.140.14.14                             : Conn closed: TLS - *Failure*

So, with light to moderate DNS traffic, the failures started occurring in about 12 minutes even at an idle_timeout of 1000.

@Ryan-Goldstein
Copy link
Author

As another update, I've been running stubby connected to AdGuard DNS with debug output enabled and an idle_timeout set to 5000. I just encountered a situation where name resolution started timing out again, but instead of showing failures, the debug output showed a large amount of information in a short time, and the Keepalive(ms) value changed from 5000 to 0 unexpectedly:

[17:15:05.264743] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:15:05.436876] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:15:30.949411] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=    25, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=  5000
[17:15:30.949704] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   310, Timeouts  =     0, Best_auth =Success
[17:15:30.949780] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    38, Conn_fails=     0, Conn_shuts=      0, Backoffs     =     0
[17:15:33.767276] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:15:33.963247] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:15:49.605374] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=    14, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=  5000
[17:15:49.605555] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   324, Timeouts  =     0, Best_auth =Success
[17:15:49.605620] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    39, Conn_fails=     0, Conn_shuts=      0, Backoffs     =     0
[17:16:02.891190] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:16:03.056156] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:16:13.409420] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     6, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=  5000
[17:16:13.409590] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   330, Timeouts  =     0, Best_auth =Success
[17:16:13.409656] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    40, Conn_fails=     0, Conn_shuts=      0, Backoffs     =     0
[17:16:32.603154] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:16:32.782331] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:16:41.569404] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     3, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=  5000
[17:16:41.569749] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   333, Timeouts  =     0, Best_auth =Success
[17:16:41.569829] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    41, Conn_fails=     0, Conn_shuts=      0, Backoffs     =     0
[17:16:42.926185] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:16:43.233596] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:16:43.393621] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     1, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=  5000
[17:16:43.395130] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:16:43.396026] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    42, Conn_fails=     0, Conn_shuts=      1, Backoffs     =     0
[17:16:43.404817] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:16:43.664163] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:16:43.895349] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:16:43.898350] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:16:43.900268] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    43, Conn_fails=     0, Conn_shuts=      2, Backoffs     =     0
[17:16:44.247174] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:16:44.499545] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:16:44.702679] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:16:44.702870] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:16:44.702936] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    44, Conn_fails=     0, Conn_shuts=      3, Backoffs     =     0
[17:16:44.709135] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:16:44.996579] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:16:45.233731] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:16:45.238787] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:16:45.239500] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    45, Conn_fails=     0, Conn_shuts=      4, Backoffs     =     0
[17:16:45.245992] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:16:46.470381] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:16:46.567144] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:16:46.570687] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:16:46.573213] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    46, Conn_fails=     0, Conn_shuts=      5, Backoffs     =     0
[17:16:46.578290] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:16:46.749218] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:16:46.839413] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:16:46.840921] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:16:46.842381] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    47, Conn_fails=     0, Conn_shuts=      6, Backoffs     =     0
[17:16:47.918366] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:16:48.223845] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:16:48.322772] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:16:48.322955] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:16:48.323019] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    48, Conn_fails=     0, Conn_shuts=      7, Backoffs     =     0
[17:16:48.328414] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:16:48.505613] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:16:48.604582] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:16:48.609943] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:16:48.611563] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    49, Conn_fails=     0, Conn_shuts=      8, Backoffs     =     0
[17:16:48.614967] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:16:48.786573] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:16:48.887435] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:16:48.888955] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:16:48.890691] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    50, Conn_fails=     0, Conn_shuts=      9, Backoffs     =     0
[17:16:48.894244] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:16:49.063848] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:16:49.155497] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:16:49.157393] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:16:49.158851] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    51, Conn_fails=     0, Conn_shuts=     10, Backoffs     =     0
[17:16:50.072075] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:16:50.253742] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:16:50.342838] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:16:50.344352] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:16:50.345815] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    52, Conn_fails=     0, Conn_shuts=     11, Backoffs     =     0
[17:16:50.350925] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:16:50.527083] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:16:50.622319] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:16:50.627033] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:16:50.629867] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    53, Conn_fails=     0, Conn_shuts=     12, Backoffs     =     0
[17:16:50.634135] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:16:50.815351] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:16:50.916389] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:16:50.918514] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:16:50.921486] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    54, Conn_fails=     0, Conn_shuts=     13, Backoffs     =     0
[17:16:50.927541] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:16:51.161328] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:16:51.254898] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:16:51.256409] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:16:51.257875] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    55, Conn_fails=     0, Conn_shuts=     14, Backoffs     =     0
[17:16:54.888663] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:16:55.064724] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:16:55.164432] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:16:55.166137] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:16:55.167626] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    56, Conn_fails=     0, Conn_shuts=     15, Backoffs     =     0
[17:16:55.172496] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:16:55.350253] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:16:55.452754] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:16:55.457656] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:16:55.460856] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    57, Conn_fails=     0, Conn_shuts=     16, Backoffs     =     0
[17:16:55.466481] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:16:55.650928] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:16:55.754563] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:16:55.757096] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:16:55.759564] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    58, Conn_fails=     0, Conn_shuts=     17, Backoffs     =     0
[17:16:55.764461] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:16:55.938478] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:16:56.035755] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:16:56.037348] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:16:56.039384] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    59, Conn_fails=     0, Conn_shuts=     18, Backoffs     =     0
[17:16:57.748838] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:16:57.930069] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:16:58.018095] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:16:58.021536] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:16:58.023398] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    60, Conn_fails=     0, Conn_shuts=     19, Backoffs     =     0
[17:16:58.027522] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:16:58.194517] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:16:58.288488] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:16:58.290626] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:16:58.293019] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    61, Conn_fails=     0, Conn_shuts=     20, Backoffs     =     0
[17:17:00.274866] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:17:00.444911] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:17:00.533531] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:00.535822] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:17:00.540044] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    62, Conn_fails=     0, Conn_shuts=     21, Backoffs     =     0
[17:17:00.544142] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:17:00.716855] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:17:00.815741] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:00.818700] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:17:00.820855] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    63, Conn_fails=     0, Conn_shuts=     22, Backoffs     =     0
[17:17:00.829437] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:17:01.012401] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:17:01.104554] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:01.106323] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:17:01.107793] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    64, Conn_fails=     0, Conn_shuts=     23, Backoffs     =     0
[17:17:01.113926] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:17:01.373945] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:17:01.475650] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:01.480281] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:17:01.483633] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    65, Conn_fails=     0, Conn_shuts=     24, Backoffs     =     0
[17:17:01.488092] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:17:01.664549] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:17:01.758794] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:01.760453] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:17:01.762357] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    66, Conn_fails=     0, Conn_shuts=     25, Backoffs     =     0
[17:17:01.768257] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:17:01.941167] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:17:02.035940] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:02.038409] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:17:02.039884] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    67, Conn_fails=     0, Conn_shuts=     26, Backoffs     =     0
[17:17:02.134235] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:17:02.312305] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:17:02.403363] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:02.404867] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:17:02.406327] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    68, Conn_fails=     0, Conn_shuts=     27, Backoffs     =     0
[17:17:02.410995] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:17:02.938787] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:17:03.101128] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:03.101319] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:17:03.101384] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    69, Conn_fails=     0, Conn_shuts=     28, Backoffs     =     0
[17:17:03.108741] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:17:03.293214] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:17:03.388437] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:03.390087] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:17:03.391063] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    70, Conn_fails=     0, Conn_shuts=     29, Backoffs     =     0
[17:17:03.398403] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:17:03.581947] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:17:03.691376] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:03.693972] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:17:03.698076] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    71, Conn_fails=     0, Conn_shuts=     30, Backoffs     =     0
[17:17:05.240220] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:17:05.408924] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:17:05.500829] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:05.503499] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:17:05.506499] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    72, Conn_fails=     0, Conn_shuts=     31, Backoffs     =     0
[17:17:05.511616] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:17:05.690371] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:17:05.786909] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:05.788429] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:17:05.791473] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    73, Conn_fails=     0, Conn_shuts=     32, Backoffs     =     0
[17:17:05.797147] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:17:06.010752] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:17:06.112252] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:06.113767] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:17:06.115224] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    74, Conn_fails=     0, Conn_shuts=     33, Backoffs     =     0
[17:17:06.119902] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:17:06.320608] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:17:06.422712] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:06.424262] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:17:06.425151] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    75, Conn_fails=     0, Conn_shuts=     34, Backoffs     =     0
[17:17:08.188826] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:17:08.360683] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:17:08.453685] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:08.455691] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:17:08.459568] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    76, Conn_fails=     0, Conn_shuts=     35, Backoffs     =     0
[17:17:08.465765] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:17:08.648778] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:17:08.745554] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:08.749580] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:17:08.751097] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    77, Conn_fails=     0, Conn_shuts=     36, Backoffs     =     0
[17:17:08.756931] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:17:08.943487] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:17:09.042248] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:09.043965] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:17:09.045855] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    78, Conn_fails=     0, Conn_shuts=     37, Backoffs     =     0
[17:17:09.055259] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:17:09.229220] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:17:09.328825] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:09.330525] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:17:09.332001] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    79, Conn_fails=     0, Conn_shuts=     38, Backoffs     =     0
[17:17:10.888266] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:17:11.064577] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:17:11.155534] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:11.157658] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:17:11.160162] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    80, Conn_fails=     0, Conn_shuts=     39, Backoffs     =     0
[17:17:11.165478] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:17:11.339529] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:17:11.437849] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:11.441521] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:17:11.442803] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    81, Conn_fails=     0, Conn_shuts=     40, Backoffs     =     0
[17:17:11.450233] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:17:11.623720] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:17:11.735458] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:11.737865] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:17:11.738775] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    82, Conn_fails=     0, Conn_shuts=     41, Backoffs     =     0
[17:17:11.748555] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:17:11.962824] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:17:12.074082] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:12.076608] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:17:12.077685] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    83, Conn_fails=     0, Conn_shuts=     42, Backoffs     =     0
[17:17:15.658917] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:17:15.830860] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:17:15.923407] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:15.924936] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:17:15.925822] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    84, Conn_fails=     0, Conn_shuts=     43, Backoffs     =     0
[17:17:15.930538] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:17:16.106713] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:17:16.201074] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:16.202586] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:17:16.203482] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    85, Conn_fails=     0, Conn_shuts=     44, Backoffs     =     0
[17:17:16.212339] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:17:16.420530] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:17:16.519579] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:16.521577] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:17:16.523576] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    86, Conn_fails=     0, Conn_shuts=     45, Backoffs     =     0
[17:17:16.527155] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:17:16.703309] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:17:16.802340] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:16.804605] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:17:16.806155] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    87, Conn_fails=     0, Conn_shuts=     46, Backoffs     =     0
[17:17:21.094973] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:17:21.270958] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:17:21.365910] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:21.368748] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:17:21.370161] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    88, Conn_fails=     0, Conn_shuts=     47, Backoffs     =     0
[17:17:21.374417] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:17:21.586477] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:17:21.691207] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:21.694768] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:17:21.697060] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    89, Conn_fails=     0, Conn_shuts=     48, Backoffs     =     0
[17:17:23.982029] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:17:24.165330] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:17:24.265591] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:24.267572] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:17:24.269032] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    90, Conn_fails=     0, Conn_shuts=     49, Backoffs     =     0
[17:17:24.274741] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:17:24.451024] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:17:24.546126] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:24.547636] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:17:24.549100] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    91, Conn_fails=     0, Conn_shuts=     50, Backoffs     =     0
[17:17:24.554501] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:17:24.740038] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:17:24.836454] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:24.839111] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:17:24.840700] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    92, Conn_fails=     0, Conn_shuts=     51, Backoffs     =     0
[17:17:24.845694] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:17:25.017309] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:17:25.112174] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:25.116656] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:17:25.120962] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    93, Conn_fails=     0, Conn_shuts=     52, Backoffs     =     0
[17:17:25.127588] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:17:25.313256] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:17:25.421069] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:25.423476] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:17:25.424935] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    94, Conn_fails=     0, Conn_shuts=     53, Backoffs     =     0
[17:17:25.430925] STUBBY: 94.140.14.14                             : Conn opened: TLS - Strict Profile
[17:17:25.603312] STUBBY: 94.140.14.14                             : Verify passed : TLS
[17:17:25.712346] STUBBY: 94.140.14.14                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:25.714828] STUBBY: 94.140.14.14                             : Upstream   : TLS - Resps=   223, Timeouts  =    40, Best_auth =Success
[17:17:25.715777] STUBBY: 94.140.14.14                             : Upstream   : TLS - Conns=    42, Conn_fails=     0, Conn_shuts=     23, Backoffs     =     0
[17:17:25.721352] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:17:25.902028] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:17:26.005290] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:26.007037] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:17:26.008559] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    95, Conn_fails=     0, Conn_shuts=     54, Backoffs     =     0
[17:17:26.019993] STUBBY: 94.140.14.14                             : Conn opened: TLS - Strict Profile
[17:17:26.205687] STUBBY: 94.140.14.14                             : Verify passed : TLS
[17:17:26.301989] STUBBY: 94.140.14.14                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:26.304091] STUBBY: 94.140.14.14                             : Upstream   : TLS - Resps=   223, Timeouts  =    40, Best_auth =Success
[17:17:26.306143] STUBBY: 94.140.14.14                             : Upstream   : TLS - Conns=    43, Conn_fails=     0, Conn_shuts=     24, Backoffs     =     0
[17:17:26.890240] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:17:27.063436] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:17:27.157079] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:27.160301] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:17:27.164134] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    96, Conn_fails=     0, Conn_shuts=     55, Backoffs     =     0
[17:17:27.169517] STUBBY: 94.140.14.14                             : Conn opened: TLS - Strict Profile
[17:17:27.342406] STUBBY: 94.140.14.14                             : Verify passed : TLS
[17:17:27.441550] STUBBY: 94.140.14.14                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:27.445575] STUBBY: 94.140.14.14                             : Upstream   : TLS - Resps=   223, Timeouts  =    40, Best_auth =Success
[17:17:27.447803] STUBBY: 94.140.14.14                             : Upstream   : TLS - Conns=    44, Conn_fails=     0, Conn_shuts=     25, Backoffs     =     0
[17:17:27.452954] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:17:27.624244] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:17:27.712715] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:27.715827] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:17:27.718710] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    97, Conn_fails=     0, Conn_shuts=     56, Backoffs     =     0
[17:17:27.722929] STUBBY: 94.140.14.14                             : Conn opened: TLS - Strict Profile
[17:17:27.894989] STUBBY: 94.140.14.14                             : Verify passed : TLS
[17:17:27.992149] STUBBY: 94.140.14.14                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:27.993833] STUBBY: 94.140.14.14                             : Upstream   : TLS - Resps=   223, Timeouts  =    40, Best_auth =Success
[17:17:27.995287] STUBBY: 94.140.14.14                             : Upstream   : TLS - Conns=    45, Conn_fails=     0, Conn_shuts=     26, Backoffs     =     0
[17:17:28.725657] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:17:28.896035] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:17:28.995108] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:28.996962] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:17:28.998470] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    98, Conn_fails=     0, Conn_shuts=     57, Backoffs     =     0
[17:17:29.003566] STUBBY: 94.140.14.14                             : Conn opened: TLS - Strict Profile
[17:17:29.179876] STUBBY: 94.140.14.14                             : Verify passed : TLS
[17:17:29.268897] STUBBY: 94.140.14.14                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:29.270527] STUBBY: 94.140.14.14                             : Upstream   : TLS - Resps=   223, Timeouts  =    40, Best_auth =Success
[17:17:29.271995] STUBBY: 94.140.14.14                             : Upstream   : TLS - Conns=    46, Conn_fails=     0, Conn_shuts=     27, Backoffs     =     0
[17:17:29.376369] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:17:29.545989] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:17:29.645200] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:29.647854] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:17:29.648927] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=    99, Conn_fails=     0, Conn_shuts=     58, Backoffs     =     0
[17:17:29.656066] STUBBY: 94.140.14.14                             : Conn opened: TLS - Strict Profile
[17:17:29.831899] STUBBY: 94.140.14.14                             : Verify passed : TLS
[17:17:29.934157] STUBBY: 94.140.14.14                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:29.936144] STUBBY: 94.140.14.14                             : Upstream   : TLS - Resps=   223, Timeouts  =    40, Best_auth =Success
[17:17:29.939045] STUBBY: 94.140.14.14                             : Upstream   : TLS - Conns=    47, Conn_fails=     0, Conn_shuts=     28, Backoffs     =     0
[17:17:31.214150] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:17:31.393963] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:17:31.584992] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:31.586518] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:17:31.588364] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=   100, Conn_fails=     0, Conn_shuts=     59, Backoffs     =     0
[17:17:31.592869] STUBBY: 94.140.14.14                             : Conn opened: TLS - Strict Profile
[17:17:31.848804] STUBBY: 94.140.14.14                             : Verify passed : TLS
[17:17:31.974360] STUBBY: 94.140.14.14                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:31.978800] STUBBY: 94.140.14.14                             : Upstream   : TLS - Resps=   223, Timeouts  =    40, Best_auth =Success
[17:17:31.979908] STUBBY: 94.140.14.14                             : Upstream   : TLS - Conns=    48, Conn_fails=     0, Conn_shuts=     29, Backoffs     =     0
[17:17:31.986708] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:17:32.170733] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:17:32.263667] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:32.265384] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:17:32.266276] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=   101, Conn_fails=     0, Conn_shuts=     60, Backoffs     =     0
[17:17:32.272337] STUBBY: 94.140.14.14                             : Conn opened: TLS - Strict Profile
[17:17:32.460593] STUBBY: 94.140.14.14                             : Verify passed : TLS
[17:17:32.552204] STUBBY: 94.140.14.14                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:32.554630] STUBBY: 94.140.14.14                             : Upstream   : TLS - Resps=   223, Timeouts  =    40, Best_auth =Success
[17:17:32.557053] STUBBY: 94.140.14.14                             : Upstream   : TLS - Conns=    49, Conn_fails=     0, Conn_shuts=     30, Backoffs     =     0
[17:17:33.050527] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:17:33.228868] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:17:33.327051] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:33.329760] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:17:33.331426] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=   102, Conn_fails=     0, Conn_shuts=     61, Backoffs     =     0
[17:17:33.336413] STUBBY: 94.140.14.14                             : Conn opened: TLS - Strict Profile
[17:17:33.515032] STUBBY: 94.140.14.14                             : Verify passed : TLS
[17:17:33.609187] STUBBY: 94.140.14.14                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:33.611147] STUBBY: 94.140.14.14                             : Upstream   : TLS - Resps=   223, Timeouts  =    40, Best_auth =Success
[17:17:33.615627] STUBBY: 94.140.14.14                             : Upstream   : TLS - Conns=    50, Conn_fails=     0, Conn_shuts=     31, Backoffs     =     0
[17:17:33.620050] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[17:17:33.797165] STUBBY: 94.140.15.15                             : Verify passed : TLS
[17:17:33.892841] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[17:17:33.895640] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   334, Timeouts  =     0, Best_auth =Success
[17:17:33.897365] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=   103, Conn_fails=     0, Conn_shuts=     62, Backoffs     =     0

After killing the stubby process and restarting it, it started working normally again, with the Keepalive(ms) showing 5000 again as expected.

This specifically looks more like a stubby issue than an Adguard DNS issue, so maybe @saradickinson would be best to address this one.

But again, I don't experience any of these issues when using Cloudflare DNS with all the same settings otherwise, so there appears to be some kind of incompatibility between stubby and Adguard DNS, which started at some point in the past week (and no recent OpenWrt or stubby updates/changes).

I'd be happy to try anything else suggested to troubleshoot further.

@ameshkov
Copy link
Member

ameshkov commented Apr 16, 2021

@Ryan-Goldstein could you please try recording a tcpdump for connections to 94.140.14.14? Maybe we'll see something suspicious there at the moment when the issue starts to happen?

@Ryan-Goldstein
Copy link
Author

Sure, here you go: https://pastebin.com/MzCtb72E

Requests started timing out maybe a minute before the end of that recording. Please let me know if you'd like me to do the same with -v or -vv flags.

@Ryan-Goldstein
Copy link
Author

Ryan-Goldstein commented Apr 16, 2021

For fun (haha), I ran it with -vv. The beginning of it was pushed out of the backlog, but I believe I still captured the time before name resolution started timing out. Unfortunately, it's really hard to pinpoint exactly when it stops working. I think it might have been at 16:11:12.947884, but it's hard to say for sure.

Here's that verbose capture: https://pastebin.com/cAURkYwG

@ameshkov
Copy link
Member

Uh, sorry for me being not specific enough.

I wanted a tcpdump with data so that I could analyze it in Wireshark, see what TLS packets are being sent:
https://linuxexplore.com/2012/06/07/use-tcpdump-to-capture-in-a-pcap-file-wireshark-dump/

@Ryan-Goldstein
Copy link
Author

Ryan-Goldstein commented Apr 17, 2021

Sure, I just did that. During this capture, instead of showing the *Failure* message in the stubby debug output, it started doing that thing around 19:19:35 where stubby started sending a bunch of lines per second, and name resolution was timing out during that time. Here's that capture: cap.zip

Here's another one where I started tcpdump, then ran stubby in debug mode, and it resolved a few names, then the *Failure* messages started within a few seconds: cap2.zip

This is a more typical one, where it was working fine for a couple minutes, then I connected my phone and Roku to increase the number of DNS queries, and I started seeing stubby *Failure* messages and name resolution started timing out again: cap3.zip

Hope that helps!

@Ryan-Goldstein
Copy link
Author

In case you want to do a comparison with Cloudflare DNS, which worked fine, I ran the same tcpdump command, except using 'host 1.1.1.1'. I started tcpdump, then started stubby in debug mode. I then followed the same process that I did to cause the error condition during the captures above: opening Google News app on my phone and clicking through a bunch of articles, most of which cause a high number of DNS queries (and many ad domains that are blocked by Adguard DNS). Stubby with Cloudflare DNS continued working fine during this time. Here's that capture: cap4-cloudflare.zip

@ameshkov
Copy link
Member

From the pcaps the only difference I see is how AG DNS and CF DNS close TLS connections:
image

I'll try to patch this soon.

@ameshkov
Copy link
Member

@Ryan-Goldstein the patched version is live, could you please try again?

@ameshkov
Copy link
Member

Okay, to be precise, it's partly live. Should be rolled out to every server in about 15 minutes:)

@Ryan-Goldstein
Copy link
Author

Ryan-Goldstein commented Apr 18, 2021

Unfortunately, the issue persists. I've done another capture: cap5.zip

EDIT: I didn't see your second message until after I started recording, so it might not have been live when I did the capture above. I'll wait a bit and try again.

@ameshkov
Copy link
Member

Well, from the pcap it seems that you were using the new version. First two connections were closed gracefully. Other connections were closed forcibly by Stubby, it's unclear what was the reason.

Tbh, I am out of ideas now so we'll have to wait.

As a temporary solution, you could try use dnsproxy instead of Stubby until the issue is fixed.

@Ryan-Goldstein
Copy link
Author

Thanks for the investigation and suggestion. I'll check out dnsproxy for now.

In the meantime, in case it helps, I wrote this before I saw your most recent comment:

I tried again 25 minutes after your post saying it should be rolled out everywhere in 15 minutes, and I'm still encountering this issue.

I first started tcpdump to listen for connections to/from both AG DNS servers as follows:

root@OpenWrt:~# tcpdump -n -i wlan0 -e "(host 94.140.14.14 or host 94.140.15.15)" -w cap6.pcap
tcpdump: listening on wlan0, link-type EN10MB (Ethernet), capture size 262144 bytes
^C1933 packets captured
1934 packets received by filter
0 packets dropped by kernel
root@OpenWrt:~#

Then I started stubby (and it immediately indicated a *Failure*):

root@OpenWrt:~# stubby -C /etc/stubby/stubby.yml -l -v 7
[22:04:37.045786] STUBBY: Stubby version: Stubby 0.3.0
[22:04:37.072800] STUBBY: Read config from file /etc/stubby/stubby.yml
[22:04:37.075905] STUBBY: DNSSEC Validation is OFF
[22:04:37.076742] STUBBY: Transport list is:
[22:04:37.077330] STUBBY:   - TLS
[22:04:37.078893] STUBBY: Privacy Usage Profile is Strict (Authentication required)
[22:04:37.080555] STUBBY: (NOTE a Strict Profile only applies when TLS is the ONLY transport!!)
[22:04:37.081678] STUBBY: Starting DAEMON....
[22:04:39.793688] STUBBY: 94.140.14.14                             : Conn opened: TLS - Strict Profile
[22:04:40.012384] STUBBY: 94.140.14.14                             : Verify passed : TLS
[22:04:54.730577] STUBBY: 94.140.14.14                             : Conn closed: TLS - *Failure*
[22:04:54.756610] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[22:04:54.928992] STUBBY: 94.140.14.14                             : Conn closed: TLS - Resps=   149, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=  5000
[22:04:54.930549] STUBBY: 94.140.14.14                             : Upstream   : TLS - Resps=   149, Timeouts  =     0, Best_auth =Success
[22:04:54.936329] STUBBY: 94.140.14.14                             : Upstream   : TLS - Conns=     1, Conn_fails=     0, Conn_shuts=      1, Backoffs     =     0
[22:04:55.753198] STUBBY: 94.140.15.15                             : Verify passed : TLS
[22:05:38.535657] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=   185, Timeouts  =    56, Curr_auth =Success, Keepalive(ms)=  5000
[22:05:38.537669] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   185, Timeouts  =    56, Best_auth =Success
[22:05:38.539311] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=     1, Conn_fails=     0, Conn_shuts=      1, Backoffs     =     0
[22:05:38.545245] STUBBY: 94.140.14.14                             : Conn opened: TLS - Strict Profile
[22:05:38.789191] STUBBY: 94.140.14.14                             : Verify passed : TLS
[22:05:38.891476] STUBBY: 94.140.14.14                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[22:05:38.894520] STUBBY: 94.140.14.14                             : Upstream   : TLS - Resps=   149, Timeouts  =     0, Best_auth =Success
[22:05:38.897011] STUBBY: 94.140.14.14                             : Upstream   : TLS - Conns=     2, Conn_fails=     0, Conn_shuts=      2, Backoffs     =     0
[22:05:39.053965] STUBBY: 94.140.14.14                             : Conn opened: TLS - Strict Profile
[22:05:39.231445] STUBBY: 94.140.14.14                             : Verify passed : TLS
[22:05:39.328975] STUBBY: 94.140.14.14                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[22:05:39.331091] STUBBY: 94.140.14.14                             : Upstream   : TLS - Resps=   149, Timeouts  =     0, Best_auth =Success
[22:05:39.333069] STUBBY: 94.140.14.14                             : Upstream   : TLS - Conns=     3, Conn_fails=     0, Conn_shuts=      3, Backoffs     =     0
[22:05:39.337481] STUBBY: 94.140.14.14                             : Conn opened: TLS - Strict Profile
[22:05:39.616553] STUBBY: 94.140.14.14                             : Verify passed : TLS
[22:05:39.711526] STUBBY: 94.140.14.14                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[22:05:39.717111] STUBBY: 94.140.14.14                             : Upstream   : TLS - Resps=   149, Timeouts  =     0, Best_auth =Success
[22:05:39.717319] STUBBY: 94.140.14.14                             : Upstream   : TLS - Conns=     4, Conn_fails=     0, Conn_shuts=      4, Backoffs     =     0
[22:05:39.903923] STUBBY: 94.140.14.14                             : Conn opened: TLS - Strict Profile
[22:05:40.083969] STUBBY: 94.140.14.14                             : Verify passed : TLS
[22:05:40.199622] STUBBY: 94.140.14.14                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[22:05:40.201671] STUBBY: 94.140.14.14                             : Upstream   : TLS - Resps=   149, Timeouts  =     0, Best_auth =Success
[22:05:40.205145] STUBBY: 94.140.14.14                             : Upstream   : TLS - Conns=     5, Conn_fails=     0, Conn_shuts=      5, Backoffs     =     0
[22:05:40.210883] STUBBY: 94.140.14.14                             : Conn opened: TLS - Strict Profile
[22:05:40.382868] STUBBY: 94.140.14.14                             : Verify passed : TLS
[22:05:40.483656] STUBBY: 94.140.14.14                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[22:05:40.483836] STUBBY: 94.140.14.14                             : Upstream   : TLS - Resps=   149, Timeouts  =     0, Best_auth =Success
[22:05:40.483899] STUBBY: 94.140.14.14                             : Upstream   : TLS - Conns=     6, Conn_fails=     0, Conn_shuts=      6, Backoffs     =     0
[22:05:42.934667] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[22:05:43.109103] STUBBY: 94.140.15.15                             : Verify passed : TLS
[22:05:43.217472] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[22:05:43.220255] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   185, Timeouts  =    56, Best_auth =Success
[22:05:43.222797] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=     2, Conn_fails=     0, Conn_shuts=      2, Backoffs     =     0
[22:05:43.440673] STUBBY: 94.140.14.14                             : Conn opened: TLS - Strict Profile
[22:05:43.669807] STUBBY: 94.140.14.14                             : Verify passed : TLS
[22:05:43.764217] STUBBY: 94.140.14.14                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[22:05:43.764392] STUBBY: 94.140.14.14                             : Upstream   : TLS - Resps=   149, Timeouts  =     0, Best_auth =Success
[22:05:43.764454] STUBBY: 94.140.14.14                             : Upstream   : TLS - Conns=     7, Conn_fails=     0, Conn_shuts=      7, Backoffs     =     0
[22:05:46.234006] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[22:05:46.427712] STUBBY: 94.140.15.15                             : Verify passed : TLS
[22:05:46.526398] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[22:05:46.529126] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   185, Timeouts  =    56, Best_auth =Success
[22:05:46.530086] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=     3, Conn_fails=     0, Conn_shuts=      3, Backoffs     =     0
[22:05:46.536883] STUBBY: 94.140.14.14                             : Conn opened: TLS - Strict Profile
[22:05:46.741375] STUBBY: 94.140.14.14                             : Verify passed : TLS
[22:05:46.839893] STUBBY: 94.140.14.14                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[22:05:46.843529] STUBBY: 94.140.14.14                             : Upstream   : TLS - Resps=   149, Timeouts  =     0, Best_auth =Success
[22:05:46.845660] STUBBY: 94.140.14.14                             : Upstream   : TLS - Conns=     8, Conn_fails=     0, Conn_shuts=      8, Backoffs     =     0
[22:05:48.445535] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[22:05:48.628375] STUBBY: 94.140.15.15                             : Verify passed : TLS
[22:05:48.722767] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[22:05:48.724838] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   185, Timeouts  =    56, Best_auth =Success
[22:05:48.728868] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=     4, Conn_fails=     0, Conn_shuts=      4, Backoffs     =     0
[22:05:52.844220] STUBBY: 94.140.14.14                             : Conn opened: TLS - Strict Profile
[22:05:53.100762] STUBBY: 94.140.14.14                             : Verify passed : TLS
[22:05:53.199681] STUBBY: 94.140.14.14                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[22:05:53.199876] STUBBY: 94.140.14.14                             : Upstream   : TLS - Resps=   149, Timeouts  =     0, Best_auth =Success
[22:05:53.199939] STUBBY: 94.140.14.14                             : Upstream   : TLS - Conns=     9, Conn_fails=     0, Conn_shuts=      9, Backoffs     =     0
[22:05:54.656132] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
[22:05:54.829386] STUBBY: 94.140.15.15                             : Verify passed : TLS
[22:05:54.923471] STUBBY: 94.140.15.15                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[22:05:54.925604] STUBBY: 94.140.15.15                             : Upstream   : TLS - Resps=   185, Timeouts  =    56, Best_auth =Success
[22:05:54.927094] STUBBY: 94.140.15.15                             : Upstream   : TLS - Conns=     5, Conn_fails=     0, Conn_shuts=      5, Backoffs     =     0
[22:05:56.433048] STUBBY: 94.140.14.14                             : Conn opened: TLS - Strict Profile
[22:05:56.606974] STUBBY: 94.140.14.14                             : Verify passed : TLS
[22:05:56.710150] STUBBY: 94.140.14.14                             : Conn closed: TLS - Resps=     0, Timeouts  =     0, Curr_auth =Success, Keepalive(ms)=     0
[22:05:56.711695] STUBBY: 94.140.14.14                             : Upstream   : TLS - Resps=   149, Timeouts  =     0, Best_auth =Success
[22:05:56.714050] STUBBY: 94.140.14.14                             : Upstream   : TLS - Conns=    10, Conn_fails=     0, Conn_shuts=     10, Backoffs     =     0
[22:06:01.985237] STUBBY: 94.140.15.15                             : Conn opened: TLS - Strict Profile
^C
root@OpenWrt:~#

And the tcpdump capture is here: cap6.zip

@Ryan-Goldstein
Copy link
Author

@ameshkov Unfortunately, there doesn't appear to be a straightforward way to get dnsproxy installed on my OpenWrt router (which has less than 1 MB free space). I may try checking out Unbound or otherwise in place of stubby, but I'd prefer stubby, as the other options appear to have more overhead.

@saradickinson Please let me know if you want me to do any debugging from the stubby side beyond what I've already done.

@ameshkov
Copy link
Member

The only thing I can add is that in these dumps every connection is closed from the Stubby side, not from AdGuard DNS.

@saradickinson
Copy link

@ameshkov I have some packet captures taken just now that seem to show some malformed packets being sent from 94.140.14.14 which seem to trigger the failure mode in stubby. I'm still investigating, but I'll email you the captures instead of posting here....

@ameshkov
Copy link
Member

Sure, thank you!

@saradickinson
Copy link

Update: Looks like the issue is caused by malformed packets coming from the server (intermingled lengths and packets). Leaving this issue open to address improving the stubby failure handling for this scenario because it should handle it...

@ameshkov
Copy link
Member

Thanks for Sara's help I've been able to identify the issue.

What's especially stupid about this issue is that I've fixed it in the upstream of the library we're using, but simply forgot to migrate that fix to our fork.

@Ryan-Goldstein we're planning to roll out the fix a little later today.

@Ryan-Goldstein
Copy link
Author

Great news! Please let me know when the fix is rolled out, and I'd be happy to test/confirm that it resolves the issue for me.

@ameshkov
Copy link
Member

@Ryan-Goldstein should be okay now.

@Ryan-Goldstein
Copy link
Author

It does appear to be fixed! Try as I might, I haven't been able to cause name resolution failures, and I haven't seen any *Failure* messages in the stubby debug output either.

I'll leave it up to you when/whether to close this issue. I know @saradickinson still wants to improve stubby's error handling, not sure if this issue remaining open will help keep that on the radar, or maybe a new issue should be opened there if one hasn't been already.

Thanks again to both of you for your quick investigation and for ultimately resolving this issue!

@Ryan-Goldstein
Copy link
Author

@ameshkov I do have one quick question: What's the officially recommended idle_timeout? I couldn't find this in any Adguard DNS documentation.

@ameshkov
Copy link
Member

I do have one quick question: What's the officially recommended idle_timeout? I couldn't find this in any Adguard DNS documentation

I guess this depends on stubby's own logic.

AdGuard DNS's own idle timeout is 8 seconds so I guess it should be somewhere close to that.

I'll leave it up to you when/whether to close this issue. I know @saradickinson still wants to improve stubby's error handling, not sure if this issue remaining open will help keep that on the radar, or maybe a new issue should be opened there if one hasn't been already.

I guess it's not that important to keep this issue open so I'd prefer to close it. @saradickinson if you need my assistance, please let me know, I guess I can set up a copy of AG DNS with that bug if you need it.

@saradickinson
Copy link

@ameshkov @Ryan-Goldstein In terms of the idle_timeout parameter - ideally servers would implement EDNS0 Keepalive (RFC7828) so the server can tell directly the client what the timeout is for each connection and the client will then shut the connection before this (since RFC7858 says clients should be the one to close the connection). In the absence of this, the recommendation is to configure stubby to have a slightly shorter timeout than the server to achieve the same behaviour so I would suggest 7s seconds.

I've also opened an issue in the getdns repo to further investigate the problem getdnsapi/getdns#501

@hanvinke
Copy link

May I ask, do I understand this correctly that this failure in Stubby's resolving has to do with the handling of the 'edns_client_subnet_private option=1' being 'on' in the stubby configuration? Google's authoritative servers were serving records for China instead of the records for AdGuard DNS servers location. If stubby fails to respond correctly - by closing the connection - this would not have been a problem?

@ameshkov
Copy link
Member

ameshkov commented Apr 20, 2021

@hanvinke no, this is completely unrelated. This was a bug on AdGuard DNS side, it could randomly send a malformed DNS packet in response, and this triggered a bug in stubby.

@hanvinke
Copy link

Thanks for the info, I was afraid of that. It is just that I myself have issues with edns and dnsmasq.
Systemlog on my router shows a lot of messages like: dnsmasq: reducing DNS packet size for nameserver 127.0.0.1 to 1280
I thought maybe "malformed" might be similar in this case to "truncated".

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants