diff --git a/dnscrypt-proxy/plugin_forward.go b/dnscrypt-proxy/plugin_forward.go index aa63bb8c..453c6879 100644 --- a/dnscrypt-proxy/plugin_forward.go +++ b/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 } diff --git a/dnscrypt-proxy/plugin_query_log.go b/dnscrypt-proxy/plugin_query_log.go index 6d638866..1d187afa 100644 --- a/dnscrypt-proxy/plugin_query_log.go +++ b/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", - time.Now().Unix(), clientIPStr, StringQuote(qName), qType, returnCode) + 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, requestDuration.Nanoseconds(), forwardDuration.Nanoseconds()) } else { dlog.Fatalf("Unexpected log format: [%s]", plugin.format) } diff --git a/dnscrypt-proxy/plugins.go b/dnscrypt-proxy/plugins.go index e867efb8..a6931328 100644 --- a/dnscrypt-proxy/plugins.go +++ b/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") diff --git a/dnscrypt-proxy/proxy.go b/dnscrypt-proxy/proxy.go index 9e62dbe5..b22d8ced 100644 --- a/dnscrypt-proxy/proxy.go +++ b/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)