Log workarounds only if verbose logging is enabled

[pfactum]

Hello.

Currently dns-over-https works around some dnscrypt-proxy and old Firefox bugs/features, and each time that happens, a message is printed in the log.

If dns-over-https is used as a public DNS resolver, that hurts logs a lot:

$ jctl -u doh-server --grep 'DNSCrypt-Proxy detected. Patching response.' | wc -l
67964

Could you please make that printout depend on s.conf.Verbose?

Thanks.

[pfactum]

The same applies to the received server failure from upstream messages. servfail is pretty common in production, there's no need to log it by default, or at least there should be a separate option to disable those messages.

[m13253]

Thank you for your response.

There doesn't suppose to be so much logging. The excessive logging was mixed in through the contributions from all over the world. A large portion of them are not needed (even if in verbose mode). Since I almost always run the software in verbose mode, I haven't noticed the problem until you told me.

I hope I can fix it soon but currently I am just too busy. Would you (or anyone else) help me clean up the logging and send a pull request?

The task mainly consists of:

1. Removing useless logging messages
2. Reformat / rephrase some logging messages to look consistent
3. Set some logging messages to verbose only

[m13253]

The same applies to the received server failure from upstream messages. servfail is pretty common in production, there's no need to log it by default, or at least there should be a separate option to disable those messages.

git blame shows it was introduced in #58. I am personally against this change. Feel free to just delete it (as well as some others).

[pfactum]

I won't guarantee I'll revamp logging sooner than you, but who knows ☺. For now I ended up with this:

diff --git a/doh-server/ietf.go b/doh-server/ietf.go
index 497ff27..e0ec98a 100644
--- a/doh-server/ietf.go
+++ b/doh-server/ietf.go
@@ -194,7 +194,9 @@ func (s *Server) generateResponseIETF(ctx context.Context, w http.ResponseWriter
 	}
 
 	if respJSON.Status == dns.RcodeServerFailure {
-		log.Printf("received server failure from upstream %s: %v\n", req.currentUpstream, req.response)
+		if s.conf.Verbose {
+			log.Printf("received server failure from upstream %s: %v\n", req.currentUpstream, req.response)
+		}
 		w.WriteHeader(503)
 	}
 	_, err = w.Write(respBytes)
@@ -206,7 +208,9 @@ func (s *Server) generateResponseIETF(ctx context.Context, w http.ResponseWriter
 // Workaround a bug causing DNSCrypt-Proxy to expect a response with TransactionID = 0xcafe
 func (s *Server) patchDNSCryptProxyReqID(w http.ResponseWriter, r *http.Request, requestBinary []byte) bool {
 	if strings.Contains(r.UserAgent(), "dnscrypt-proxy") && bytes.Equal(requestBinary, []byte("\xca\xfe\x01\x00\x00\x01\x00\x00\x00\x00\x00\x01\x00\x00\x02\x00\x01\x00\x00\x29\x10\x00\x00\x00\x80\x00\x00\x00")) {
-		log.Println("DNSCrypt-Proxy detected. Patching response.")
+		if s.conf.Verbose {
+			log.Println("DNSCrypt-Proxy detected. Patching response.")
+		}
 		w.Header().Set("Content-Type", "application/dns-message")
 		w.Header().Set("Vary", "Accept, User-Agent")
 		now := time.Now().UTC().Format(http.TimeFormat)
@@ -220,7 +224,9 @@ func (s *Server) patchDNSCryptProxyReqID(w http.ResponseWriter, r *http.Request,
 // Workaround a bug causing Firefox 61-62 to reject responses with Content-Type = application/dns-message
 func (s *Server) patchFirefoxContentType(w http.ResponseWriter, r *http.Request, req *DNSRequest) bool {
 	if strings.Contains(r.UserAgent(), "Firefox") && strings.Contains(r.Header.Get("Accept"), "application/dns-udpwireformat") && !strings.Contains(r.Header.Get("Accept"), "application/dns-message") {
-		log.Println("Firefox 61-62 detected. Patching response.")
+		if s.conf.Verbose {
+			log.Println("Firefox 61-62 detected. Patching response.")
+		}
 		w.Header().Set("Content-Type", "application/dns-udpwireformat")
 		w.Header().Set("Vary", "Accept, User-Agent")
 		req.isTailored = true

[gdm85]

@pfactum it was not introduced in that PR, it was already there as a bare err printed to the log; I merely added some context to the existing log line.

@m13253 each and every log line that is reported here to be noisy was present before my changes, so please do not blame me for them. The only new log line introduced in that PR is failed to write to client which happens on bad network connections.

[pfactum]

Personally /me is here not to find who to blame but to improve a code a little bit.

Do you think my small correction from above can be applied as it is without major logging revamp?

[m13253]

I am really sorry. I apologize for my rudeness. I was studying for an exam and suddenly received the update from this repo, so I didn't spend too much time thinking before posting.

It should be my responsibility for not checking the code before merging. I will clean up the logging before next release.

[gdm85]

No worries @m13253, I can contribute a patch for that if you like :) although I would expect some feedback to decide exactly what needs to be logged verbosely or not. Edit: PR created: #107

@pfactum quoting you:

Personally /me is here not to find who to blame but to improve a code a little bit. git blame shows it was introduced in #58. I am personally against this change.

Your reading was insufficient, next time I suggest to read the actual PR you link to.

[pfactum]

Eh? I didn't link that PR.

[m13253]

I guess it's now fixed? Please reopen if you disagree.