Enhance logging (#834)

* Enhance query logging

Add request duration, and forward duration if applicable.

* Also measure requests forwarded based on forwarding_rules

dnscrypt-proxy/plugin_forward.go

@@ -5,6 +5,7 @@ import (
 	"math/rand"
 	"net"
 	"strings"
+	"time"
 	"unicode"
 
 	"github.com/jedisct1/dlog"
@@ -92,7 +93,9 @@ func (plugin *PluginForward) Eval(pluginsState *PluginsState, msg *dns.Msg) erro
 		return nil
 	}
 	server := servers[rand.Intn(len(servers))]
+	reqStart := time.Now()
 	respMsg, err := dns.Exchange(msg, server)
+	pluginsState.forwardDuration = time.Now().Sub(reqStart)
 	if err != nil {
 		return err
 	}

dnscrypt-proxy/plugin_query_log.go

@@ -71,16 +71,22 @@ func (plugin *PluginQueryLog) Eval(pluginsState *PluginsState, msg *dns.Msg) err
 		returnCode = string(returnCode)
 	}
 
+	var requestDuration, forwardDuration time.Duration
+	if !pluginsState.requestStart.IsZero() && !pluginsState.requestEnd.IsZero() {
+		requestDuration = pluginsState.requestEnd.Sub(pluginsState.requestStart)
+	}
+	forwardDuration = pluginsState.forwardDuration
+
 	var line string
 	if plugin.format == "tsv" {
 		now := time.Now()
 		year, month, day := now.Date()
 		hour, minute, second := now.Clock()
 		tsStr := fmt.Sprintf("[%d-%02d-%02d %02d:%02d:%02d]", year, int(month), day, hour, minute, second)
-		line = fmt.Sprintf("%s\t%s\t%s\t%s\t%s\n", tsStr, clientIPStr, StringQuote(qName), qType, returnCode)
+		line = fmt.Sprintf("%s\t%s\t%s\t%s\t%s\t%v\t%v\n", tsStr, clientIPStr, StringQuote(qName), qType, returnCode, requestDuration, forwardDuration)
 	} else if plugin.format == "ltsv" {
-		line = fmt.Sprintf("time:%d\thost:%s\tmessage:%s\ttype:%s\treturn:%s\n",
+		line = fmt.Sprintf("time:%d\thost:%s\tmessage:%s\ttype:%s\treturn:%s\treqDuration:%d\tfwdDuration:%d\n",
-			time.Now().Unix(), clientIPStr, StringQuote(qName), qType, returnCode)
+			time.Now().Unix(), clientIPStr, StringQuote(qName), qType, returnCode, requestDuration.Nanoseconds(), forwardDuration.Nanoseconds())
 	} else {
 		dlog.Fatalf("Unexpected log format: [%s]", plugin.format)
 	}

dnscrypt-proxy/plugins.go

@@ -4,6 +4,7 @@ import (
 	"errors"
 	"net"
 	"sync"
+	"time"
 
 	"github.com/jedisct1/dlog"
 	"github.com/miekg/dns"
@@ -70,6 +71,9 @@ type PluginsState struct {
 	cacheMinTTL            uint32
 	cacheMaxTTL            uint32
 	questionMsg            *dns.Msg
+	requestStart           time.Time
+	requestEnd             time.Time
+	forwardDuration        time.Duration
 	returnCode             PluginsReturnCode
 }
 
@@ -143,7 +147,7 @@ type Plugin interface {
 	Eval(pluginsState *PluginsState, msg *dns.Msg) error
 }
 
-func NewPluginsState(proxy *Proxy, clientProto string, clientAddr *net.Addr) PluginsState {
+func NewPluginsState(proxy *Proxy, clientProto string, clientAddr *net.Addr, start time.Time) PluginsState {
 	return PluginsState{
 		action:         PluginsActionForward,
 		maxPayloadSize: MaxDNSUDPPacketSize - ResponseOverhead,
@@ -155,6 +159,7 @@ func NewPluginsState(proxy *Proxy, clientProto string, clientAddr *net.Addr) Plu
 		cacheMinTTL:    proxy.cacheMinTTL,
 		cacheMaxTTL:    proxy.cacheMaxTTL,
 		questionMsg:    nil,
+		requestStart:   start,
 	}
 }
 
@@ -253,6 +258,7 @@ func (pluginsState *PluginsState) ApplyLoggingPlugins(pluginsGlobals *PluginsGlo
 	if len(*pluginsGlobals.loggingPlugins) == 0 {
 		return nil
 	}
+	pluginsState.requestEnd = time.Now()
 	questionMsg := pluginsState.questionMsg
 	if questionMsg == nil || len(questionMsg.Question) > 1 {
 		return errors.New("Unexpected number of questions")

dnscrypt-proxy/proxy.go

@@ -206,12 +206,13 @@ func (proxy *Proxy) udpListener(clientPc *net.UDPConn) {
 		}
 		packet := buffer[:length]
 		go func() {
+			start := time.Now()
 			if !proxy.clientsCountInc() {
 				dlog.Warnf("Too many connections (max=%d)", proxy.maxClients)
 				return
 			}
 			defer proxy.clientsCountDec()
-			proxy.processIncomingQuery(proxy.serversInfo.getOne(), "udp", proxy.mainProto, packet, &clientAddr, clientPc)
+			proxy.processIncomingQuery(proxy.serversInfo.getOne(), "udp", proxy.mainProto, packet, &clientAddr, clientPc, start)
 		}()
 	}
 }
@@ -234,6 +235,7 @@ func (proxy *Proxy) tcpListener(acceptPc *net.TCPListener) {
 			continue
 		}
 		go func() {
+			start := time.Now()
 			defer clientPc.Close()
 			if !proxy.clientsCountInc() {
 				dlog.Warnf("Too many connections (max=%d)", proxy.maxClients)
@@ -246,7 +248,7 @@ func (proxy *Proxy) tcpListener(acceptPc *net.TCPListener) {
 				return
 			}
 			clientAddr := clientPc.RemoteAddr()
-			proxy.processIncomingQuery(proxy.serversInfo.getOne(), "tcp", "tcp", packet, &clientAddr, clientPc)
+			proxy.processIncomingQuery(proxy.serversInfo.getOne(), "tcp", "tcp", packet, &clientAddr, clientPc, start)
 		}()
 	}
 }
@@ -325,11 +327,11 @@ func (proxy *Proxy) clientsCountDec() {
 	}
 }
 
-func (proxy *Proxy) processIncomingQuery(serverInfo *ServerInfo, clientProto string, serverProto string, query []byte, clientAddr *net.Addr, clientPc net.Conn) {
+func (proxy *Proxy) processIncomingQuery(serverInfo *ServerInfo, clientProto string, serverProto string, query []byte, clientAddr *net.Addr, clientPc net.Conn, start time.Time) {
 	if len(query) < MinDNSPacketSize {
 		return
 	}
-	pluginsState := NewPluginsState(proxy, clientProto, clientAddr)
+	pluginsState := NewPluginsState(proxy, clientProto, clientAddr, start)
 	query, _ = pluginsState.ApplyQueryPlugins(&proxy.pluginsGlobals, query)
 	var response []byte
 	var err error
@@ -360,11 +362,13 @@ func (proxy *Proxy) processIncomingQuery(serverInfo *ServerInfo, clientProto str
 				return
 			}
 			serverInfo.noticeBegin(proxy)
+			reqStart := time.Now()
 			if serverProto == "udp" {
 				response, err = proxy.exchangeWithUDPServer(serverInfo, sharedKey, encryptedQuery, clientNonce)
 			} else {
 				response, err = proxy.exchangeWithTCPServer(serverInfo, sharedKey, encryptedQuery, clientNonce)
 			}
+			pluginsState.forwardDuration = time.Now().Sub(reqStart)
 			if err != nil {
 				pluginsState.returnCode = PluginsReturnCodeServerError
 				pluginsState.ApplyLoggingPlugins(&proxy.pluginsGlobals)
@@ -375,8 +379,9 @@ func (proxy *Proxy) processIncomingQuery(serverInfo *ServerInfo, clientProto str
 			tid := TransactionID(query)
 			SetTransactionID(query, 0)
 			serverInfo.noticeBegin(proxy)
-			resp, _, err := proxy.xTransport.DoHQuery(serverInfo.useGet, serverInfo.URL, query, proxy.timeout)
+			resp, duration, err := proxy.xTransport.DoHQuery(serverInfo.useGet, serverInfo.URL, query, proxy.timeout)
 			SetTransactionID(query, tid)
+			pluginsState.forwardDuration = duration
 			if err != nil {
 				pluginsState.returnCode = PluginsReturnCodeServerError
 				pluginsState.ApplyLoggingPlugins(&proxy.pluginsGlobals)