Logs of "context deadline exceeded", broken pipes, and eventual process death

[brainsik]

Context

• nextdns version 1.32.2
• EdgeRouter X v2.0.9-hotfix.2

$ /config/nextdns/nextdns config
log-queries false
cache-max-age 0s
hardened-privacy false
report-client-info true
bogus-priv true
setup-router true
listen localhost:53
max-ttl 0s
timeout 5s
cache-size 10MB
discovery-dns 
detect-captive-portals false
use-hosts true
auto-activate true
control /var/run/nextdns.sock
config 10.11.12.0/24=abc123
config def456

For the past week or so I've been having problems on and off with the client on my router (and Windows host on a separate network, but I'm going to focus on the router). Starting yesterday, things have gotten much worse and the client is now repeatedly dying. The home network is becoming unusable. 😢

These are the sorts of messages filling my logs:

Jun  2 16:07:50 ubnt nextdns[16175]: Starting NextDNS 1.32.2/linux on :53
Jun  2 16:07:50 ubnt nextdns[16175]: Starting mDNS discovery
Jun  2 16:07:50 ubnt nextdns[16175]: Listening on TCP/:53
Jun  2 16:07:50 ubnt nextdns[16175]: Listening on UDP/:53
Jun  2 16:07:54 ubnt nextdns[16175]: Connected 45.90.28.0:443 (con=11ms tls=3941ms, TCP, TLS13)
Jun  2 16:07:55 ubnt nextdns[16175]: Setting up router
Jun  2 16:07:55 ubnt nextdns[16175]: Activating
Jun  2 16:07:56 ubnt nextdns[16175]: Connected [2001:19f0:ac01:170:5400:2ff:fec8:72c8]:443 (con=9ms tls=1474ms, TCP, TLS13)
Jun  2 16:07:56 ubnt nextdns[16175]: Switching endpoint: https://dns.nextdns.io.#104.238.181.28,2001:19f0:ac01:170:5400:2ff:fec8:72c8
Jun  2 16:07:57 ubnt nextdns[16175]: Query 10.19.47.121 UDP A doh.dns.apple.com. (qry=35/res=12) 7264ms : doh resolve: context deadline exceeded
Jun  2 16:07:57 ubnt nextdns[16175]: Query 10.19.47.121 UDP 65 apple.com. (qry=27/res=12) 7270ms : doh resolve: context deadline exceeded
…
Jun  2 16:16:01 ubnt nextdns[16175]: Connected 104.238.181.28:443 (con=0ms tls=0ms, TCP, )
Jun  2 16:16:41 ubnt nextdns[16175]: Connected 104.238.181.28:443 (con=19ms tls=0ms, TCP, )
Jun  2 16:18:19 ubnt nextdns[16175]: Query 10.19.45.95 UDP AAAA www.apple.com. (qry=31/res=12) cached HTTP/2.0: doh resolve: context deadline exceeded
Jun  2 16:18:19 ubnt nextdns[16175]: Query 10.19.45.95 UDP A www.apple.com. (qry=31/res=12) cached HTTP/2.0: doh resolve: context deadline exceeded
…
Jun  2 16:25:04 ubnt nextdns[16175]: Received signal: broken pipe (ignored)
Jun  2 16:25:59 ubnt nextdns[16175]: Received signal: broken pipe (ignored)
Jun  2 16:26:02 ubnt nextdns[16175]: message repeated 5 times: [ Received signal: broken pipe (ignored)]
Jun  2 16:26:03 ubnt nextdns[16175]: Received signal: broken pipe (ignored)
Jun  2 16:26:04 ubnt nextdns[16175]: Received signal: broken pipe (ignored)
Jun  2 16:26:08 ubnt nextdns[16175]: message repeated 21 times: [ Received signal: broken pipe (ignored)]
Jun  2 16:26:09 ubnt nextdns[16175]: Endpoint provider failed: &{dns.nextdns.io. https://dns.nextdns.io#45.90.28.0,2a07:a8c0::,45.90.30.0,2a07:a8c1::}: exchange: roundtrip: write tcp [2001:558:6045:42:15ee:b4d7:5357:f202]:46832->[2a07:a8c0::]:443: write: broken pipe
Jun  2 16:26:09 ubnt nextdns[16175]: Received signal: broken pipe (ignored)
Jun  2 16:26:09 ubnt nextdns[16175]: message repeated 5 times: [ Received signal: broken pipe (ignored)]
Jun  2 16:26:12 ubnt nextdns[16175]: Connected [2001:19f0:ac01:170:5400:2ff:fec8:72c8]:443 (con=11ms tls=1471ms, TCP, TLS13)
Jun  2 16:26:12 ubnt nextdns[16175]: Switching endpoint: https://dns.nextdns.io.#104.238.181.28,2001:19f0:ac01:170:5400:2ff:fec8:72c8
Jun  2 16:26:12 ubnt nextdns[16175]: Query 10.19.45.81 UDP A gateway.icloud.com. (qry=36/res=12) 74721ms : doh resolve: context deadline exceeded

After a while, the client is killed by the oom-killer, which #505 is about.

I've upgraded all the things as a first step. I was running v1.9.4 on EdgeOS v2.0.9 (no hotfix) for many months without issue.

[brainsik]

Upgraded to NextDNS 1.32.3. Issues persist.

[rs]

Please provide a https://nextdns.io/diag

[brainsik]

I tried running it 4 times, but it keeps hanging after the 3rd hop in "Traceroute for ultra low latency primary IPv6". I can run some manual traceroutes to more hosts if it helps.

Here's the output I got:

sh -c 'sh -c "$(curl -s https://nextdns.io/diag)"'

Testing IPv6 connectivity
  available: true
Fetching https://test.nextdns.io
  status: ok
  client: 2001:558:6045:42:XXX
  protocol: DOH
  dest IP: 
  server: do-sfo-1
Fetching PoP name for ultra low latency primary IPv4 (ipv4.dns1.nextdns.io)
  vultr-sjc: 11.44ms
Fetching PoP name for ultra low latency secondary IPv4 (ipv4.dns2.nextdns.io)
  do-sfo: 9.741ms
Fetching PoP name for anycast primary IPv4 (45.90.28.0)
  vultr-sjc: 11.863ms
Fetching PoP name for anycast secondary IPv4 (45.90.30.0)
  virtua-par: 150.032ms
Fetching PoP name for ultra low latency primary IPv6 (ipv6.dns1.nextdns.io)
  vultr-sjc: 10.668ms
Fetching PoP name for ultra low latency secondary IPv6 (ipv6.dns2.nextdns.io)
  do-sfo: 10.623ms
Fetching PoP name for anycast primary IPv6 (2a07:a8c0::)
  vultr-sjc: 10.853ms
Fetching PoP name for anycast secondary IPv6 (2a07:a8c1::)
  virtua-par: 147.713ms
Pinging PoPs
  do-sfo: 9.514ms
  do-sfo (IPv6): 9.829ms
  vultr-sjc: 10.607ms
  anexia-lax: 19.324ms
  anexia-lax (IPv6): 17.486ms
  vultr-lax: 17.643ms
  zepto-lax (IPv6): 17.619ms
  zepto-lax: 17.492ms
  vultr-lax (IPv6): 17.631ms
  vultr-sjc (IPv6): 10.883ms
  smarthost-las (IPv6): 24.458ms
  one-pdx: 28.382ms
  frantech-las: 28.345ms
  bronto-slc: 33ms
  tier-pdx (IPv6): 31.852ms
  tier-pdx: 30.227ms
  frantech-las (IPv6): 31.911ms
  smarthost-las: 29.997ms
  bronto-slc (IPv6): 47ms
Traceroute for ultra low latency primary IPv4 (104.238.181.28)
    1    96.120.89.5   11ms   8ms   7ms
    2  68.86.143.241    8ms   8ms   8ms
    3  162.151.78.89   12ms  35ms  10ms
    4  96.110.41.125   11ms  12ms  10ms
    5   96.110.46.42   10ms  11ms  10ms
    6  96.110.37.182   10ms  12ms  12ms
    7   96.110.33.38   10ms  10ms  10ms
    8 209.120.154.117   11ms  10ms  10ms
    9  89.149.183.10   12ms  10ms  10ms
   10  69.22.143.238   12ms  12ms  12ms
   11                   *     *     *
   12                   *     *     *
   13                   *     *     *
   14                   *     *     *
   15 104.238.181.28   11ms  11ms  10ms
Traceroute for ultra low latency secondary IPv4 (143.110.229.87)
    1    96.120.89.5    8ms  10ms  10ms
    2  68.86.143.241    8ms   8ms  10ms
    3  162.151.78.89    9ms  10ms  10ms
    4   68.86.143.93  100ms  11ms  10ms
    5    4.68.72.105    9ms  13ms  11ms
    6   4.69.202.125   10ms  11ms  10ms
    7     4.14.33.54    9ms  11ms  15ms
    8                   *     *     *
    9                   *     *     *
   10                   *     *     *
   11                   *     *     *
   12 143.110.229.87   12ms   9ms  12ms
Traceroute for anycast primary IPv4 (45.90.28.0)
    1    96.120.89.5    9ms  11ms   8ms
    2  68.86.143.241    7ms   9ms  11ms
    3  162.151.78.89   11ms  11ms  11ms
    4   68.86.143.93   11ms  12ms  11ms
    5    4.68.72.105   11ms  13ms   9ms
    6                   *     *     *
    7     4.7.18.206   10ms  12ms  12ms
    8                   *     *     *
    9                   *     *     *
   10                   *     *     *
   11                   *     *     *
   12     45.90.28.0   14ms  11ms  13ms
Traceroute for anycast secondary IPv4 (45.90.30.0)
    1    96.120.89.5    9ms  12ms  11ms
    2  68.86.143.241   12ms   8ms   8ms
    3  162.151.78.89   10ms  12ms  10ms
    4  96.110.41.121   14ms  12ms  12ms
    5  96.110.41.218   10ms  12ms   9ms
    6 50.248.118.238   12ms  12ms  10ms
    7  154.54.42.157   15ms  14ms  12ms
    8  154.54.44.138   27ms  29ms  30ms
    9  154.54.41.146   53ms  53ms  55ms
   10    154.54.5.90   57ms  53ms  56ms
   11  154.54.42.166   59ms  58ms  58ms
   12   154.54.6.222   65ms  68ms  68ms
   13  154.54.26.130   82ms  83ms  83ms
   14    66.28.4.238   81ms  81ms  82ms
   15   154.54.82.33  144ms 142ms 150ms
   16  130.117.2.110  147ms 152ms 148ms
   17   154.25.3.246  148ms 146ms 148ms
   18  149.6.164.130  146ms 146ms 145ms
   19 188.214.24.188  153ms 149ms 149ms
   20 188.214.24.165  149ms 152ms 152ms
Traceroute for ultra low latency primary IPv6 (2001:19f0:ac01:170:5400:2ff:fec8:72c8)
    1 2001:558:6045:42::1   21ms  12ms  11ms
    2 2001:558:82:5009::1   10ms  12ms   8ms
    3 2001:558:80:41f::1   11ms  12ms  11ms

[rs]

The routing issue should be fixed. Please try a diag again and tell me if the timeouts are still happening.

[brainsik]

I'm getting the same behavior where it hangs after the 3rd hop:

Traceroute for ultra low latency primary IPv6 (2001:19f0:ac01:170:5400:2ff:fec8:72c8)
    1 2001:558:6045:42::1    9ms   9ms   9ms
    2 2001:558:82:5009::1    7ms   8ms   8ms
    3 2001:558:80:41f::1    9ms   9ms  10ms

[rs]

What do you get for curl https://anycast.dns2.nextdns.io/info?

[brainsik]

{"locationName": "🇺🇸 Los Angeles, United States", "pop": "zepto-lax", "rtt": 22675}

[brainsik]

For kicks, I downgraded to NextDNS 1.9.4 as I had been running that for months without issue. It's been about 5 hours and I have a fraction of the errors as before (though I'm am still seeing them) and the memory has grown to only 42M resident so far. I would have had to restart 1.32.3 multiple times by now. Gonna see what happens overnight (I'm UTC-7).

[rs]

Can you also try without the cache enable on the latest version?

[brainsik]

The 1.9.4 run finally ended (about 15' ago) the same way (oom-killer), but it lasted much longer. Hopefully that's useful data.

I'll try running latest without cache now.

[brainsik]

I'm about 2 hours into running 1.32.3 configured with cache-size 0MB and I have had zero error messages. No "context deadline exceeded", no broken pipes, etc. Memory usage has grown a little, but nothing like before. We'll see how the rest of the day goes.

[brainsik]

3 more hours and still not a single error message. Resident memory has only grown by ~4.5 MB.

[rs]

Would you mind running it again with 10M and see if you reproduce the issue then try again with 1M?

[brainsik]

Been running 1.32.3 with 10M cache for about 90' and so far, zero errors and restrained memory growth. Did something change on the backend?

Gonna let it run overnight. Do you still want me to test a 1M cache as well?

[brainsik]

Ran all night without any errors. Memory is still slowly growing (at 28M resident now), but I'm not sure if that's on par with previous behavior and is nothing more than the cache filling up.

Let me know if you still want me to run things with a 1M cache.

[brainsik]

Errors are still gone, however memory continues to grow. Up to 42M resident now.

[varkey]

I've been running into something similar as well, mostly when my internet connection fails-over to backup. My ISP disconnects the PPPoE session every 24 hours so there is usually a failover to backup every 24 hours. When this happens, I see a lot of doh resolve: context deadline exceeded and at times it recovers on its own immediately, but sometimes it goes to a hung state and would either need a restart or it might recover on its own after several minutes.

Mon Jun 14 13:03:31 2021 daemon.notice nextdns[4756]: Query fdf6:a86d:4264:0:e93a:9cb5:96e8:723d UDP PTR db._dns-sd._udp.lan. (qry=37/res=12) 5002ms : doh resolve: context deadline exceeded
Mon Jun 14 13:03:31 2021 daemon.notice nextdns[4756]: Query fdf6:a86d:4264:0:e93a:9cb5:96e8:723d UDP PTR lb._dns-sd._udp.1.0.64.100.in-addr.arpa. (qry=57/res=12) 5002ms : doh resolve: context deadline exceeded
Mon Jun 14 13:03:31 2021 daemon.notice nextdns[4756]: Query fdf6:a86d:4264:0:e93a:9cb5:96e8:723d UDP PTR db._dns-sd._udp.1.0.64.100.in-addr.arpa. (qry=57/res=12) 5002ms : doh resolve: context deadline exceeded
Mon Jun 14 13:03:31 2021 daemon.notice nextdns[4756]: Query fdf6:a86d:4264:0:e93a:9cb5:96e8:723d UDP PTR lb._dns-sd._udp.lan. (qry=37/res=12) 5002ms : doh resolve: context deadline exceeded
Mon Jun 14 13:03:32 2021 daemon.notice nextdns[4756]: Query fdf6:a86d:4264:0:ddcf:8447:e51d:a240 UDP A 0.client-channel.google.com. (qry=45/res=12) cached HTTP/2.0: doh resolve: context deadline exceeded
Mon Jun 14 13:03:32 2021 daemon.notice nextdns[4756]: Query fdf6:a86d:4264:0:ddcf:8447:e51d:a240 UDP AAAA 0.client-channel.google.com. (qry=45/res=12) cached HTTP/2.0: doh resolve: context deadline exceeded
Mon Jun 14 13:03:33 2021 daemon.notice nextdns[4756]: Received signal: broken pipe (ignored)
Mon Jun 14 13:03:41 2021 daemon.notice nextdns[4756]: Received signal: broken pipe (ignored)
Mon Jun 14 13:10:30 2021 daemon.notice nextdns[4756]: Received signal: terminated
Mon Jun 14 13:10:30 2021 daemon.notice nextdns[4756]: Stopping NextDNS 1.32.1/linux
Mon Jun 14 13:10:30 2021 daemon.notice nextdns[4756]: Deactivating
Mon Jun 14 13:10:30 2021 daemon.notice nextdns[4756]: NextDNS 1.32.1/linux stopped
Mon Jun 14 13:10:30 2021 daemon.notice nextdns[5999]: Starting NextDNS 1.32.1/linux on :53
Mon Jun 14 13:10:30 2021 daemon.notice nextdns[5999]: Starting mDNS discovery
Mon Jun 14 13:10:30 2021 daemon.notice nextdns[5999]: Listening on UDP/:53
Mon Jun 14 13:10:30 2021 daemon.notice nextdns[5999]: Listening on TCP/:53
Mon Jun 14 13:10:30 2021 daemon.notice nextdns[5999]: Connected 45.90.28.0:443 (con=37ms tls=137ms, TCP, TLS13)
Mon Jun 14 13:10:30 2021 daemon.notice nextdns[5999]: Connected 68.183.91.243:443 (con=20ms tls=27ms, TCP, TLS13)
Mon Jun 14 13:10:30 2021 daemon.notice nextdns[5999]: Switching endpoint: https://dns.nextdns.io.#68.183.91.243,2400:6180:100:d0::89f:9001
Mon Jun 14 13:10:35 2021 daemon.notice nextdns[5999]: Activating
Mon Jun 14 13:15:37 2021 daemon.notice nextdns[5999]: Connected 68.183.91.243:443 (con=23ms tls=41ms, TCP, TLS13)

[mojo333]

Same just happened to me... loads of "context deadline exceeded" messages before these...

Jun 24 21:34:21 ubnt nextdns[66]: Query 192.168.200.183 UDP A dc.services.visualstudio.com. (qry=46/res=12) 5809ms : doh resolve: context deadline exceeded
Jun 24 21:34:21 ubnt nextdns[66]: Connected 37.252.230.153:443 (con=55ms tls=76ms, TCP, TLS13)
Jun 24 21:34:21 ubnt nextdns[66]: Switching endpoint: https://dns.nextdns.io#209.250.226.191,2001:19f0:7401:85d3:5400:2ff:fec8:749f,37.252.230.153,2a00:11c0:8:4::9
Jun 24 21:34:23 ubnt nextdns[66]: Query 192.168.200.183 UDP A dc.services.visualstudio.com. (qry=46/res=12) 5002ms : doh resolve: context deadline exceeded
Jun 24 21:34:24 ubnt nextdns[66]: Query 192.168.240.107 UDP A embeddedassistant.googleapis.com.home.lan. (qry=59/res=12) 5000ms : doh resolve: context deadline exceeded
Jun 24 21:34:24 ubnt nextdns[66]: Query 192.168.200.183 UDP A login.live.com. (qry=32/res=12) 5000ms : doh resolve: context deadline exceeded
Jun 24 21:34:26 ubnt nextdns[66]: Query 192.168.240.70 UDP A api.amazonalexa.com.home.lan. (qry=46/res=12) 5001ms : doh resolve: context deadline exceeded
Jun 24 21:34:26 ubnt nextdns[66]: Query 192.168.240.70 UDP A api.amazonalexa.com.home.lan. (qry=46/res=12) 5001ms : doh resolve: context deadline exceeded
Jun 24 21:36:04 ubnt nextdns[66]: Received signal: terminated
Jun 24 21:36:04 ubnt nextdns[66]: Stopping NextDNS 1.33.2/linux
Jun 24 21:36:04 ubnt systemd[1]: Stopping NextDNS DNS53 to DoH proxy....
Jun 24 21:36:04 ubnt nextdns[66]: Restore router settings
Jun 24 21:36:04 ubnt nextdns[66]: Restore router settings: exit status 2
Jun 24 21:36:04 ubnt nextdns[66]: NextDNS 1.33.2/linux stopped
Jun 24 21:36:04 ubnt systemd[1]: nextdns.service: Succeeded.
Jun 24 21:36:04 ubnt systemd[1]: Stopped NextDNS DNS53 to DoH proxy..
Jun 24 21:36:04 ubnt systemd[1]: Starting NextDNS DNS53 to DoH proxy....
Jun 24 21:36:04 ubnt nextdns[8586]: Starting NextDNS 1.33.2/linux on localhost:5553
Jun 24 21:36:04 ubnt nextdns[8586]: Listening on TCP/127.0.0.1:5553
Jun 24 21:36:04 ubnt nextdns[8586]: Starting mDNS discovery
Jun 24 21:36:04 ubnt nextdns[8586]: Listening on UDP/127.0.0.1:5553
Jun 24 21:36:05 ubnt ssh[8587]: Welcome to UbiOS
Jun 24 21:36:05 ubnt ssh[8587]: By logging in, accessing, or using the Ubiquiti product, you
Jun 24 21:36:05 ubnt ssh[8587]: acknowledge that you have read and understood the Ubiquiti
Jun 24 21:36:05 ubnt ssh[8587]: License Agreement and agree to be bound by its terms.
Jun 24 21:36:05 ubnt systemd[1]: Started NextDNS DNS53 to DoH proxy..
Jun 24 21:36:07 ubnt nextdns[8586]: Connected 45.90.28.0:443 (con=14ms tls=123ms, TCP, TLS13)
Jun 24 21:36:07 ubnt nextdns[8586]: Connected 209.250.226.191:443 (con=16ms tls=23ms, TCP, TLS13)
Jun 24 21:36:07 ubnt nextdns[8586]: Switching endpoint: https://dns.nextdns.io#209.250.226.191,2001:19f0:7401:85d3:5400:2ff:fec8:749f,37.252.230.153,2a00:11c0:8:4::9
Jun 24 21:36:08 ubnt nextdns[8586]: Connected 37.252.230.153:443 (con=15ms tls=22ms, TCP, TLS13)
Jun 24 21:36:08 ubnt nextdns[8586]: Switching endpoint: https://dns.nextdns.io#37.252.230.153,2a00:11c0:8:4::9,209.250.226.191,2001:19f0:7401:85d3:5400:2ff:fec8:749f
Jun 24 21:36:09 ubnt nextdns[8586]: Setting up router
Jun 24 21:36:10 ubnt nextdns[8586]: Setting up router: exit status 1
Jun 24 21:39:12 ubnt nextdns[8586]: Connected 37.252.230.153:443 (con=0ms tls=0ms, TCP, )
Jun 24 21:39:31 ubnt nextdns[8586]: parse question: parsing/packing of this section has completed
Jun 24 21:39:31 ubnt nextdns[8586]: parse question: parsing/packing of this section has completed
Jun 24 21:39:31 ubnt nextdns[8586]: parse additional: Name: insufficient data for calculated length type
Jun 24 21:41:35 ubnt nextdns[8586]: Connected 37.252.230.153:443 (con=13ms tls=18ms, TCP, TLS13)

I ended up restarting the NextDNS service which restored DNS.

[ralban]

I too have this symptom.
It seems my ISP connection was flapping, and this triggered a chain-reaction from which nextdns was unable to recover.
Cached replies seem to survive a bit, but then I assume all memory is exhausted by the accumulating requests.

[rs]

This will be fixed by d0570f3

[candiesdoodle]

Thanks @rs I was having similar issues on nexdns cli on openwrt. Though have no way of confirming if it's exactly the same issue but conditions seem similar - pppoe tripping every few minutes and nextdns crashing. I have disabled nextdns and it seems to be much stable - no disconnect for past 11 hours.
I hope the fix is applicable to openwrt too
Thanks

[candiesdoodle]

May I ask when will this be pushed out in new version?
Current release is unusable for me on openwrt.
Thanks

[rs]

The new release is currently building, should be ready in a few minutes.

[it-can]

is this now fixed?

[vincentbernat]

There have been multiple commits to attempt to solve such an issue. I think it is likely to be fixed in the current version.

[it-can]

on my synology dsm 7 i am getting this error:
nexdtdns 1.35

Query 192.168.2.172 UDP A ota.awair.is. (qry=30/res=12) cache fallback HTTP/2.0: doh resolve: context deadline exceeded

also on my centos8 machine

Aug 18 17:44:02 server nextdns[1467265]: Switching endpoint: https://dns.nextdns.io#188.172.219.167,2a00:11c0:63:350::3,95.179.134.211,2001:19f0:5001:1faf:5400:2ff:fec8:7d49
Aug 18 18:33:34 server nextdns[1467265]: Query 127.0.0.1 UDP A 1.0.0.127.bl.spameatingmonkey.net. (qry=62/res=12) cache fallback HTTP/2.0: doh resolve: context deadline exceeded

[brainsik]

After a few months of everything being fine, it has struck again. I suspect it's the same thing as #586 (which got opened a few days ago). I've been on nextdns v1.36.0 since August 25 without issue. I just upgraded to the latest (1.37.2).