search

aarond10 / https_dns_proxy

A lightweight DNS-over-HTTPS proxy.
MIT License
779 stars 114 forks source link

https_dns_proxy is very chatty in logs on OpenWrt when WAN cable is disconnected #125

Closed stangri closed 3 years ago

stangri commented 3 years ago

While I was trying to reproduce this: https://github.com/openwrt/packages/issues/16222, I've discovered that with the default verbosity level (as in, non-verbose), once I pull the WAN cable out, the https-dns-proxy is very chatty:

02:55:53 https-dns-proxy[2103]: [E] 1627379753.106147 https_client.c:205 No response
02:55:53 https-dns-proxy[2103]: [E] 1627379753.106183 https_client.c:248 CURLINFO_OS_ERRNO: 101 Network unreachable
02:55:53 https-dns-proxy[2101]: [E] 1627379753.107616 https_client.c:205 No response
02:55:53 https-dns-proxy[2101]: [E] 1627379753.107650 https_client.c:248 CURLINFO_OS_ERRNO: 101 Network unreachable
02:55:53 https-dns-proxy[2101]: [E] 1627379753.144880 https_client.c:205 No response
02:55:53 https-dns-proxy[2101]: [E] 1627379753.144915 https_client.c:248 CURLINFO_OS_ERRNO: 101 Network unreachable
02:55:53 https-dns-proxy[2103]: [E] 1627379753.147628 https_client.c:205 No response
02:55:53 https-dns-proxy[2103]: [E] 1627379753.147660 https_client.c:248 CURLINFO_OS_ERRNO: 101 Network unreachable
02:55:53 https-dns-proxy[2101]: [E] 1627379753.185832 https_client.c:205 No response
02:55:53 https-dns-proxy[2101]: [E] 1627379753.185866 https_client.c:248 CURLINFO_OS_ERRNO: 101 Network unreachable
02:55:53 https-dns-proxy[2103]: [E] 1627379753.187618 https_client.c:205 No response
02:55:53 https-dns-proxy[2103]: [E] 1627379753.187651 https_client.c:248 CURLINFO_OS_ERRNO: 101 Network unreachable
02:55:53 https-dns-proxy[2101]: [E] 1627379753.224453 https_client.c:205 No response
02:55:53 https-dns-proxy[2101]: [E] 1627379753.224486 https_client.c:248 CURLINFO_OS_ERRNO: 101 Network unreachable
02:55:53 https-dns-proxy[2103]: [E] 1627379753.231500 https_client.c:205 No response
02:55:53 https-dns-proxy[2103]: [E] 1627379753.231534 https_client.c:248 CURLINFO_OS_ERRNO: 101 Network unreachable
02:55:53 https-dns-proxy[2101]: [E] 1627379753.264973 https_client.c:205 No response
02:55:53 https-dns-proxy[2101]: [E] 1627379753.265006 https_client.c:248 CURLINFO_OS_ERRNO: 101 Network unreachable
02:55:53 https-dns-proxy[2103]: [E] 1627379753.271109 https_client.c:205 No response
02:55:53 https-dns-proxy[2103]: [E] 1627379753.271142 https_client.c:248 CURLINFO_OS_ERRNO: 101 Network unreachable
02:55:53 vpn-policy-routing [9790]: service waiting for wan gateway...
02:55:53 https-dns-proxy[2103]: [E] 1627379753.739917 https_client.c:205 No response
02:55:53 https-dns-proxy[2101]: [E] 1627379753.740776 https_client.c:205 No response
02:55:53 https-dns-proxy[2101]: [E] 1627379753.740966 https_client.c:248 CURLINFO_OS_ERRNO: 101 Network unreachable
02:55:53 https-dns-proxy[2103]: [E] 1627379753.742566 https_client.c:248 CURLINFO_OS_ERRNO: 101 Network unreachable
02:55:53 https-dns-proxy[2103]: [E] 1627379753.767786 https_client.c:205 No response
02:55:53 https-dns-proxy[2101]: [E] 1627379753.768445 https_client.c:205 No response
02:55:53 https-dns-proxy[2103]: [E] 1627379753.768627 https_client.c:248 CURLINFO_OS_ERRNO: 101 Network unreachable
02:55:53 https-dns-proxy[2101]: [E] 1627379753.770550 https_client.c:248 CURLINFO_OS_ERRNO: 101 Network unreachable
02:55:53 https-dns-proxy[2103]: [E] 1627379753.802103 https_client.c:205 No response
02:55:53 https-dns-proxy[2103]: [E] 1627379753.802316 https_client.c:248 CURLINFO_OS_ERRNO: 101 Network unreachable
02:55:53 https-dns-proxy[2101]: [E] 1627379753.807440 https_client.c:205 No response
02:55:53 https-dns-proxy[2101]: [E] 1627379753.807474 https_client.c:248 CURLINFO_OS_ERRNO: 101 Network unreachable
02:55:53 https-dns-proxy[2103]: [E] 1627379753.858092 https_client.c:205 No response
02:55:53 https-dns-proxy[2103]: [E] 1627379753.858305 https_client.c:248 CURLINFO_OS_ERRNO: 101 Network unreachable
02:55:53 https-dns-proxy[2101]: [E] 1627379753.863202 https_client.c:205 No response
02:55:53 https-dns-proxy[2101]: [E] 1627379753.863236 https_client.c:248 CURLINFO_OS_ERRNO: 101 Network unreachable

And this continues every second until connection is restored. Also, I've only had a limited opportunity to test it with WAN cable pulled out, but I believe it also caused spikes in CPU utilization (wherever it's from dnsmasq or https-dns-proxy I can't recall sadly). I suspect it very well may lock up the router if left in this state for an extended periods of time.

@baranyaib90 @aarond10 can you gentlemen please also try to reproduce the issue and:

  1. ideally cut down on error reporting frequency with the default verbosity level
  2. see if something can be done about CPU utilization

I'll try to update the OpenWrt package to include the restart on wan up asap.

PS. This is with the version 2021-06-03, should I update the OpenWrt package to the commit from June 11th and retest?

stangri commented 3 years ago

Another issue with high CPU utilization when no internet.

baranyaib90 commented 3 years ago

Hi,

1. in scope of #120 the log "No response" was set to warning in commit 40a974 I could lower the level of CURLINFO_OS_ERRNO log as well, but that I need to think through. (From proxys view it's an error, not a warning.) The thing is, that it's logged after every request, not periodically. 2. CPU utilization was fixed in commit 10102f Provided strace shows it perfectly, this commit definitely fixes it.

Updating the package is a great idea, thanks. I would recommend latest commit from master.

stangri commented 3 years ago

@baranyaib90 I believe https://github.com/aarond10/https_dns_proxy/pull/121/commits/10102f166f72668e18079867158f517b7af97394 is included in the OpenWrt package as its date stamp is 2021-06-03 and the commit in question was merged before then.

I'll keep an eye on the update #124 and once it's merged I'll update the binary.

baranyaib90 commented 3 years ago

I don't think, that the commit was included, since in the strace it's visible, that the proxy want's to connect to the bootstrap resolvers: connect(8, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("1.1.1.1")}, 16) And for that, the delay way 0 seconds (= retry immediatelly) and that was changed to 5 sec, so no endless loop should occur. Also I did not see any version info in the ticket, that's just an assumption. You could ask for package version info.

stangri commented 3 years ago

in scope of #120 the log "No response" was set to warning in commit 40a974

Thanks, I've tested the latest commit in your fixes-6 branch on OpenWrt and I can confirm that the "No response" messages are gone from the log.

I could lower the level of CURLINFO_OS_ERRNO log as well, but that I need to think through. (From proxys view it's an error, not a warning.)

Yeah, that's still there and it spams the log. For someone trying to troubleshoot why WAN may have gone down it's supper-annoying.

baranyaib90 commented 3 years ago

Hi @stangri ! My latest pull request has been merged (#126 ) so from now on every HTTP request issues are now logged on warning level. The proxy won't be chatty anymore if you uplift the OpenWRT package to latest master.

stangri commented 3 years ago

Thanks, I've built the updated package for OpenWrt, I'll try to test sometime this weekend, when it won't interfere with WFH situation. ;)

stangri commented 3 years ago

Thank you, confirm fixed, I'll try to merge an update into OpenWrt asap.