Tweaks to logging, calculating some basic stats

.better-dns.yaml

@@ -15,3 +15,6 @@ dns_servers:
   - dns+tls://1.0.0.1
 
 listen_host: 127.0.0.1
+
+# One of: panic, fatal, error, warn, info, debug, trace
+log_level: info

README.md

@@ -20,7 +20,7 @@ What it can do:
  - Proxy any non-blacklisted DNS requests to a proper DNS server
  - Caches results (minimum 30s, otherwise respects TTL in responses, using a fixed-size LRU) - leads to a minor performance enhancement in some scenarios
  - Override your active DNS servers while it's running and return them to normal on exit
- - Show all the DNS requests your software is doing - maybe you'll find it enlightening
+ - Show all the DNS requests your software is doing (if you increase log level to debug) - maybe you'll find it enlightening
  - Supports Windows, Mac, and Linux (at least based on limited testing)
 
 Current version is quite preliminary still, however it seems to very much work (on Windows 10, Mac OS High Sierra, and Fedora 31 armhfp on Raspberry Pi 2).
@@ -89,7 +89,7 @@ listen_host: 0.0.0.0
  - Cached block lists in case your network isn't working perfectly when you launch the software
  - Periodically checking the lists for updates (e.g. hourly / daily)
  - Monitor for new networks (e.g. WiFi) and update their DNS settings as well
- - Reporting interface similar to Pi-hole
+ - Reporting interface similar to Pi-hole (but probably not as detailed due to privacy issues)
 
 
 # License

better-dns.go

@@ -4,6 +4,7 @@ import (
 	"flag"
 	"github.com/lietu/better-dns/server"
 	"github.com/lietu/better-dns/shared"
+	"github.com/lietu/better-dns/stats"
 	"github.com/mattn/go-colorable"
 	"github.com/miekg/dns"
 	log "github.com/sirupsen/logrus"
@@ -15,6 +16,7 @@ import (
 	"strings"
 	"sync"
 	"syscall"
+	"time"
 )
 
 const PORT = 53
@@ -87,13 +89,50 @@ func main() {
 		}
 	}()
 
+	go func() {
+		duration := time.Minute
+		start := time.Now()
+		previous := stats.Stats{}
+		for {
+			time.Sleep(duration)
+			total := stats.GetStats()
+			successes := total.Successes - previous.Successes
+			diff := stats.Stats{
+				Blocked:   total.Blocked - previous.Blocked,
+				Cached:    total.Cached - previous.Cached,
+				Errors:    total.Errors - previous.Errors,
+				Successes: successes,
+				Rtt:       total.Rtt / time.Duration(successes),
+			}
+
+			saved := (time.Duration(diff.Cached) * diff.Rtt).Truncate(time.Millisecond)
+			log.Infof("")
+			log.Infof("------------------------------")
+			log.Infof("Stats for last %s:", duration)
+			log.Infof(" - Blocked: %d", diff.Blocked)
+			log.Infof(" - Successes: %d (%s avg)", diff.Successes, diff.Rtt.Truncate(time.Millisecond))
+			log.Infof(" - Cache hits: %d (~%s saved)", diff.Cached, saved)
+			log.Infof(" - Errors: %d", diff.Errors)
+
+			totalSaved := (time.Duration(total.Cached) * diff.Rtt).Truncate(time.Millisecond)
+			log.Infof("")
+			log.Infof("Stats since start (%s):", time.Since(start).Truncate(duration))
+			log.Infof(" - Blocked: %d", total.Blocked)
+			log.Infof(" - Successes: %d (%s avg)", total.Successes, diff.Rtt.Truncate(time.Millisecond))
+			log.Infof(" - Cache hits: %d (~%s saved)", total.Cached, totalSaved)
+			log.Infof(" - Errors: %d", total.Errors)
+			log.Infof("------------------------------")
+			previous = total
+		}
+	}()
+
 	shared.UpdateDnsServers()
 
 	sig := make(chan os.Signal, 10)
 	signal.Notify(sig, syscall.SIGINT, syscall.SIGTERM)
 	s := <-sig
 
 	shared.RestoreDnsServers()
-
-	log.Fatalf("Signal (%v) received, stopping", s)
+	log.Debugf("Signal (%v) received, stopping", s)
+	log.Info("Exiting...")
 }

client/client.go

@@ -4,7 +4,7 @@ import (
 	"bytes"
 	"crypto/tls"
 	"errors"
-	"github.com/lietu/better-dns/shared"
+	"github.com/lietu/better-dns/stats"
 	"github.com/miekg/dns"
 	log "github.com/sirupsen/logrus"
 	"io/ioutil"
@@ -43,7 +43,7 @@ func queryDnsOverTls(req *dns.Msg, host string, serverName string) queryResult {
 		res, rtt, err := tlsClient.Exchange(req, server)
 
 		if err != nil {
-			go shared.ReportError(req, res, rtt, err)
+			go stats.ReportError(req, res, rtt, err)
 
 			if err.Error() == "tls: DialWithDialer timed out" {
 				log.Debug("TLS connection timed out.")
@@ -78,7 +78,7 @@ func queryDns(req *dns.Msg, server string) queryResult {
 		res, rtt, err := client.Exchange(req, server)
 
 		if err != nil {
-			go shared.ReportError(req, res, rtt, err)
+			go stats.ReportError(req, res, rtt, err)
 			log.Debugf("Caught error while querying: %s", err)
 		} else {
 			return queryResult{
@@ -134,7 +134,7 @@ func queryDnsOverHttps(req *dns.Msg, serverUrl string) queryResult {
 		rtt := time.Since(start)
 
 		if err != nil {
-			go shared.ReportError(req, res, rtt, err)
+			go stats.ReportError(req, res, rtt, err)
 			log.Errorf("Caught error while querying: %s", err)
 			if httpRes != nil {
 				if err = httpRes.Body.Close(); err != nil {
@@ -145,7 +145,7 @@ func queryDnsOverHttps(req *dns.Msg, serverUrl string) queryResult {
 			if httpRes.StatusCode == 200 {
 				udpPayload, err := ioutil.ReadAll(httpRes.Body)
 				if err != nil {
-					go shared.ReportError(req, res, rtt, err)
+					go stats.ReportError(req, res, rtt, err)
 					if err = httpRes.Body.Close(); err != nil {
 						log.Errorf("Error closing HTTP client body: %s", err)
 					}
@@ -159,7 +159,7 @@ func queryDnsOverHttps(req *dns.Msg, serverUrl string) queryResult {
 				res := &dns.Msg{}
 				err = res.Unpack(udpPayload)
 				if err != nil {
-					go shared.ReportError(req, res, rtt, err)
+					go stats.ReportError(req, res, rtt, err)
 					continue
 				}
 
@@ -171,7 +171,7 @@ func queryDnsOverHttps(req *dns.Msg, serverUrl string) queryResult {
 				msg, _ := ioutil.ReadAll(httpRes.Body)
 				log.Errorf("HTTP response %d %s: %s", httpRes.StatusCode, httpRes.Status, string(msg[:]))
 				err = ErrDnsOverHttpsRequest
-				go shared.ReportError(req, res, rtt, err)
+				go stats.ReportError(req, res, rtt, err)
 				continue
 			}
 		}
@@ -246,7 +246,7 @@ func Query(req *dns.Msg, dnsServers []string) *dns.Msg {
 
 		if qr.res != nil {
 			// Just return first success
-			go shared.ReportSuccess(req, qr.res, qr.rtt, qr.server)
+			go stats.ReportSuccess(req, qr.res, qr.rtt, qr.server)
 			return qr.res
 		} else if received == count {
 			// All servers failed

server/filter.go

@@ -3,6 +3,7 @@ package server
 import (
 	"bufio"
 	"github.com/lietu/better-dns/shared"
+	"github.com/lietu/better-dns/stats"
 	"github.com/miekg/dns"
 	"github.com/ryanuber/go-glob"
 	log "github.com/sirupsen/logrus"
@@ -148,7 +149,7 @@ func BlockFromURL(listURL string) {
 		log.Errorf("Error while processing list %s: %s", listURL, err)
 	}
 
-	log.Infof("✔ Parsed %s list in %s", listURL, shared.CleanDuration(time.Since(start)))
+	log.Debugf("✔ Parsed %s list in %s", listURL, stats.CleanDuration(time.Since(start)))
 }
 
 // Show current log lists

server/handler.go

@@ -3,6 +3,7 @@ package server
 import (
 	"github.com/lietu/better-dns/client"
 	"github.com/lietu/better-dns/shared"
+	"github.com/lietu/better-dns/stats"
 	"github.com/miekg/dns"
 	log "github.com/sirupsen/logrus"
 )
@@ -26,13 +27,13 @@ func writeResponse(w dns.ResponseWriter, res *dns.Msg) {
 
 func (h *RequestHandler) getResult(req *dns.Msg) *dns.Msg {
 	if cached := getCache(req); cached != nil {
-		go shared.ReportCached(req, cached)
+		go stats.ReportCached(req, cached)
 		return cached
 	}
 
 	var res *dns.Msg
 	if filtered := filter(req, h.Config.GetBlacklist()); filtered != nil {
-		go shared.ReportFiltered(req, filtered)
+		go stats.ReportBlocked(req, filtered)
 		res = newFilteredResponse(req)
 	} else {
 		res = client.Query(req, h.Config.GetDnsServers())

shared/config.go

@@ -91,7 +91,7 @@ func NewConfig(src string, usingDefault bool) *Config {
 	if _, err := os.Stat(src); os.IsNotExist(err) {
 		if usingDefault {
 			// Default config path not overridden, file does not exist, just use defaults
-			log.Info("Using built-in default configuration.")
+			log.Debug("Using built-in default configuration.")
 			return &c
 		}
 
@@ -108,7 +108,7 @@ func NewConfig(src string, usingDefault bool) *Config {
 		log.Panicf("Error parsing config file %s: %s", src, err)
 	}
 
-	log.Infof("Using configuration from %s", src)
+	log.Debugf("Using configuration from %s", src)
 
 	validate(c)
 

shared/report.go → stats/report.go

@@ -1,13 +1,24 @@
-package shared
+package stats
 
 import (
 	"fmt"
+	"github.com/lietu/better-dns/shared"
 	"github.com/miekg/dns"
 	log "github.com/sirupsen/logrus"
 	"sort"
 	"time"
 )
 
+type Stats struct {
+	Blocked   uint64
+	Cached	  uint64
+	Errors    uint64
+	Successes uint64
+	Rtt		  time.Duration
+}
+
+var stats = Stats{0, 0, 0, 0, 0}
+
 func answerResult(a dns.RR) string {
 	if a, ok := a.(*dns.A); ok {
 		return a.A.String()
@@ -51,6 +62,7 @@ func ReportError(req *dns.Msg, res *dns.Msg, rtt time.Duration, err error) {
 		c = fmt.Sprintf("error: %s", err)
 	}
 	log.Debugf("❌ %s (%s) not resolved (%s) %s", CleanName(q.Name), dns.TypeToString[q.Qtype], CleanDuration(rtt), c)
+	stats.Errors++
 }
 
 func ReportSuccess(req *dns.Msg, res *dns.Msg, rtt time.Duration, server string) {
@@ -67,6 +79,7 @@ func ReportSuccess(req *dns.Msg, res *dns.Msg, rtt time.Duration, server string)
 
 	answers := len(res.Answer)
 	if answers == 0 {
+		// No matches
 		return
 	}
 
@@ -109,6 +122,8 @@ func ReportSuccess(req *dns.Msg, res *dns.Msg, rtt time.Duration, server string)
 	result := answerResult(ans)
 
 	log.Debugf("✔ %s (%s) is %s%s for %s (%s)", CleanName(name), t, result, extra, CleanDuration(ttl), CleanDuration(rtt))
+	stats.Successes++
+	stats.Rtt += rtt
 }
 
 func ReportCached(req *dns.Msg, res *dns.Msg) {
@@ -134,17 +149,25 @@ func ReportCached(req *dns.Msg, res *dns.Msg) {
 	}
 
 	log.Debugf("✔ %s (%s) is %s%s (cached)", CleanName(name), t, result, extra)
+	stats.Cached++
 }
 
-func ReportFiltered(req *dns.Msg, be *BlockEntry) {
+func ReportBlocked(req *dns.Msg, be *shared.BlockEntry) {
 	defer func() {
 		if err := recover(); err != nil {
-			log.Errorf("Suppressing panic during ReportFiltered: %s", err)
+			log.Errorf("Suppressing panic during ReportBlocked: %s", err)
 		}
 	}()
 
 	name := req.Question[0].Name
 	log.Debugf("⛔ %s blocked by %s", CleanName(name), be.Src)
+	stats.Blocked++
+}
+
+func GetStats() Stats {
+	latest := stats
+	stats.Rtt = 0  // Reset Rtt calculation
+	return latest
 }
 
 func CleanDuration(d time.Duration) time.Duration {