Pull request 292: 6220-query-duration

Updates AdguardTeam/AdGuardHome#6220.

Squashed commit of the following:

commit 3d437e68f3aae2bb91809a569cf55ddafabfdc12
Author: Stanislav Chzhen <[email protected]>
Date:   Tue Oct 31 14:20:56 2023 +0300

    proxy: imp docs

commit 543a9a9e61f9a969847ce56967a2101f0346343d
Author: Stanislav Chzhen <[email protected]>
Date:   Tue Oct 31 13:22:07 2023 +0300

    proxy: imp log msg

commit 20a0ddae04472827d30797cf5787bbc06ce7f1e2
Author: Stanislav Chzhen <[email protected]>
Date:   Mon Oct 30 15:21:47 2023 +0300

    proxy: imp docs

commit b6c440931eeb69566f218ad27eb70bea43629a03
Author: Stanislav Chzhen <[email protected]>
Date:   Thu Oct 26 16:35:47 2023 +0300

    proxy: add query duration

proxy/dnscontext.go

@@ -14,9 +14,6 @@ import (
 
 // DNSContext represents a DNS request message context
 type DNSContext struct {
-	// StartTime is the moment when request processing started.
-	StartTime time.Time
-
 	// Conn is the underlying client connection.  It is nil if Proto is
 	// ProtoDNSCrypt, ProtoHTTPS, or ProtoQUIC.
 	Conn net.Conn
@@ -66,6 +63,10 @@ type DNSContext struct {
 	// localIP - local IP address (for UDP socket to call udpMakeOOBWithSrc)
 	localIP net.IP
 
+	// QueryDuration is the duration of a successful query to an upstream
+	// server or, if the upstream server is unavailable, to a fallback server.
+	QueryDuration time.Duration
+
 	// DoQVersion is the DoQ protocol version. It can (and should) be read from
 	// ALPN, but in the current version we also use the way DNS messages are
 	// encoded as a signal.

proxy/proxy.go

@@ -508,6 +508,7 @@ func (p *Proxy) replyFromUpstream(d *DNSContext) (ok bool, err error) {
 	}
 
 	start := time.Now()
+	src := "upstream"
 
 	// Perform the DNS request.
 	resp, u, err := p.exchange(req, upstreams)
@@ -518,11 +519,13 @@ func (p *Proxy) replyFromUpstream(d *DNSContext) (ok bool, err error) {
 		resp = p.genWithRCode(req, dns.RcodeNameError)
 	}
 
-	log.Debug("proxy: replying from upstream: rtt is %s", time.Since(start))
-
 	if err != nil && p.Fallbacks != nil {
 		log.Debug("proxy: replying from upstream: using fallback due to %s", err)
 
+		// Reset the timer.
+		start = time.Now()
+		src = "fallback"
+
 		upstreams = p.Fallbacks.getUpstreamsForDomain(req.Question[0].Name)
 		if len(upstreams) == 0 {
 			return false, fmt.Errorf("selecting fallback upstream: %w", upstream.ErrNoUpstreams)
@@ -531,6 +534,17 @@ func (p *Proxy) replyFromUpstream(d *DNSContext) (ok bool, err error) {
 		resp, u, err = upstream.ExchangeParallel(upstreams, req)
 	}
 
+	if err != nil {
+		log.Debug("proxy: replying from %s: %s", src, err)
+	}
+
+	if resp != nil {
+		rtt := time.Since(start)
+		log.Debug("proxy: replying from %s: rtt is %s", src, rtt)
+
+		d.QueryDuration = rtt
+	}
+
 	p.handleExchangeResult(d, req, resp, u)
 
 	return resp != nil, err
@@ -686,9 +700,8 @@ func (dctx *DNSContext) processECS(cliIP net.IP) {
 // newDNSContext returns a new properly initialized *DNSContext.
 func (p *Proxy) newDNSContext(proto Proto, req *dns.Msg) (d *DNSContext) {
 	return &DNSContext{
-		Proto:     proto,
-		Req:       req,
-		StartTime: time.Now(),
+		Proto: proto,
+		Req:   req,
 
 		RequestID: atomic.AddUint64(&p.counter, 1),
 	}

proxy/server.go

@@ -80,7 +80,6 @@ func (p *Proxy) startListeners(ctx context.Context) error {
 
 // handleDNSRequest processes the incoming packet bytes and returns with an optional response packet.
 func (p *Proxy) handleDNSRequest(d *DNSContext) error {
-	d.StartTime = time.Now()
 	p.logDNSMessage(d.Req)
 
 	if d.Req.Response {