Pull request: 3772 cache upstreams

Merge in DNS/adguard-home from 3772-cache-upstreams to master

Updates #3772.

Squashed commit of the following:

commit 809e874fe8847fdbd7f8a7221f18393509f41339
Merge: 5774798c 2d328ea8
Author: Eugene Burkov <E.Burkov@AdGuard.COM>
Date:   Tue Dec 7 17:15:59 2021 +0300

    Merge branch 'master' into 3772-cache-upstreams

commit 5774798ce1897bf292be49410794ce06cd084f93
Author: Ildar Kamalov <ik@adguard.com>
Date:   Tue Dec 7 16:48:38 2021 +0300

    client: fix formatting

commit 4b4bb668c762c9b4d47cf40a007f34fe47a6e260
Author: Ildar Kamalov <ik@adguard.com>
Date:   Tue Dec 7 16:47:18 2021 +0300

    client: remove comment

commit a2a9f904a6ab52194bb811a2a83967660a25f2cc
Author: Ildar Kamalov <ik@adguard.com>
Date:   Tue Dec 7 16:45:31 2021 +0300

    client: handle cached upstream

commit a56804c4910da838cb10c8ef0af2a525e9722b1c
Author: Eugene Burkov <E.Burkov@AdGuard.COM>
Date:   Fri Nov 26 15:33:43 2021 +0300

    querylog: rm todo

commit 16c0a62ad2dfc7fcb5a6adbc868b296b7840fd27
Author: Eugene Burkov <E.Burkov@AdGuard.COM>
Date:   Fri Nov 26 15:31:53 2021 +0300

    all: revise log of changes

commit 9f4b793205f17b6e85d74e83126093ed09eb24e3
Author: Eugene Burkov <E.Burkov@AdGuard.COM>
Date:   Thu Nov 25 17:23:42 2021 +0300

    WIP

commit 7fbc6d596295570d2c61c3e507160f65c9adccb8
Author: Eugene Burkov <E.Burkov@AdGuard.COM>
Date:   Thu Nov 25 17:03:42 2021 +0300

    all: imp upstream info in querylog

internal/querylog/decode.go

@@ -44,8 +44,10 @@ var logEntryHandlers = map[string]logEntryHandler{
 		if !ok {
 			return nil
 		}
+
 		var err error
 		ent.Time, err = time.Parse(time.RFC3339, v)
+
 		return err
 	},
 	"QH": func(t json.Token, ent *logEntry) error {
@@ -69,7 +71,9 @@ var logEntryHandlers = map[string]logEntryHandler{
 		if !ok {
 			return nil
 		}
+
 		ent.QClass = v
+
 		return nil
 	},
 	"CP": func(t json.Token, ent *logEntry) error {
@@ -77,8 +81,10 @@ var logEntryHandlers = map[string]logEntryHandler{
 		if !ok {
 			return nil
 		}
+
 		var err error
 		ent.ClientProto, err = NewClientProto(v)
+
 		return err
 	},
 	"Answer": func(t json.Token, ent *logEntry) error {
@@ -86,8 +92,10 @@ var logEntryHandlers = map[string]logEntryHandler{
 		if !ok {
 			return nil
 		}
+
 		var err error
 		ent.Answer, err = base64.StdEncoding.DecodeString(v)
+
 		return err
 	},
 	"OrigAnswer": func(t json.Token, ent *logEntry) error {
@@ -95,16 +103,30 @@ var logEntryHandlers = map[string]logEntryHandler{
 		if !ok {
 			return nil
 		}
+
 		var err error
 		ent.OrigAnswer, err = base64.StdEncoding.DecodeString(v)
+
 		return err
 	},
+	"Cached": func(t json.Token, ent *logEntry) error {
+		v, ok := t.(bool)
+		if !ok {
+			return nil
+		}
+
+		ent.Cached = v
+
+		return nil
+	},
 	"Upstream": func(t json.Token, ent *logEntry) error {
 		v, ok := t.(string)
 		if !ok {
 			return nil
 		}
+
 		ent.Upstream = v
+
 		return nil
 	},
 	"Elapsed": func(t json.Token, ent *logEntry) error {
@@ -112,11 +134,14 @@ var logEntryHandlers = map[string]logEntryHandler{
 		if !ok {
 			return nil
 		}
+
 		i, err := v.Int64()
 		if err != nil {
 			return err
 		}
+
 		ent.Elapsed = time.Duration(i)
+
 		return nil
 	},
 }

internal/querylog/decode_test.go

@@ -33,6 +33,7 @@ func TestDecodeLogEntry(t *testing.T) {
 			`"QC":"IN",` +
 			`"CP":"",` +
 			`"Answer":"` + ansStr + `",` +
+			`"Cached":true,` +
 			`"Result":{` +
 			`"IsFiltered":true,` +
 			`"Reason":3,` +
@@ -42,6 +43,7 @@ func TestDecodeLogEntry(t *testing.T) {
 			`"CanonName":"example.com",` +
 			`"ServiceName":"example.org",` +
 			`"DNSRewriteResult":{"RCode":0,"Response":{"1":["127.0.0.2"]}}},` +
+			`"Upstream":"https://some.upstream",` +
 			`"Elapsed":837429}`
 
 		ans, err := base64.StdEncoding.DecodeString(ansStr)
@@ -56,6 +58,7 @@ func TestDecodeLogEntry(t *testing.T) {
 			ClientID:    "cli42",
 			ClientProto: "",
 			Answer:      ans,
+			Cached:      true,
 			Result: filtering.Result{
 				IsFiltered: true,
 				Reason:     filtering.FilteredBlockList,
@@ -78,7 +81,8 @@ func TestDecodeLogEntry(t *testing.T) {
 					},
 				},
 			},
-			Elapsed: 837429,
+			Upstream: "https://some.upstream",
+			Elapsed:  837429,
 		}
 
 		got := &logEntry{}

internal/querylog/json.go

@@ -74,6 +74,7 @@ func (l *queryLog) entryToJSON(entry *logEntry, anonFunc aghnet.IPMutFunc) (json
 		"time":         entry.Time.Format(time.RFC3339Nano),
 		"client":       eip,
 		"client_proto": entry.ClientProto,
+		"cached":       entry.Cached,
 		"upstream":     entry.Upstream,
 		"question":     question,
 	}

internal/querylog/qlog.go

@@ -87,10 +87,11 @@ type logEntry struct {
 
 	Answer     []byte `json:",omitempty"` // sometimes empty answers happen like binerdunt.top or rev2.globalrootservers.net
 	OrigAnswer []byte `json:",omitempty"`
+	Cached     bool   `json:",omitempty"`
 
 	Result   filtering.Result
 	Elapsed  time.Duration
-	Upstream string `json:",omitempty"` // if empty, means it was cached
+	Upstream string `json:",omitempty"`
 }
 
 func (l *queryLog) Start() {
@@ -171,6 +172,7 @@ func (l *queryLog) Add(params AddParams) {
 		Result:      *params.Result,
 		Elapsed:     params.Elapsed,
 		Upstream:    params.Upstream,
+		Cached:      params.Cached,
 		ClientID:    params.ClientID,
 		ClientProto: params.ClientProto,
 	}

internal/querylog/querylog.go

@@ -73,16 +73,24 @@ type Config struct {
 	Anonymizer *aghnet.IPMut
 }
 
-// AddParams - parameters for Add()
+// AddParams is the parameters for adding an entry.
 type AddParams struct {
-	Question    *dns.Msg
-	Answer      *dns.Msg          // The response we sent to the client (optional)
-	OrigAnswer  *dns.Msg          // The response from an upstream server (optional)
-	Result      *filtering.Result // Filtering result (optional)
-	Elapsed     time.Duration     // Time spent for processing the request
-	ClientID    string
-	ClientIP    net.IP
-	Upstream    string // Upstream server URL
+	Question *dns.Msg
+	// Answer is the response which is sent to the client, if any.
+	Answer *dns.Msg
+	// OrigAnswer is the response from an upstream server.  It's only set if the
+	// answer has been modified by filtering.
+	OrigAnswer *dns.Msg
+	// Cached indicates if the response is served from cache.
+	Cached bool
+	// Result is the filtering result (optional).
+	Result *filtering.Result
+	// Elapsed is the time spent for processing the request.
+	Elapsed  time.Duration
+	ClientID string
+	ClientIP net.IP
+	// Upstream is the URL of the upstream DNS server.
+	Upstream    string
 	ClientProto ClientProto
 }