plugin/cache: Fix prefetching issues (#1363)

* Improve plugin/cache metrics

* Add coredns_cache_prefetch_total metric to track number of prefetches.
* Remove unnecessary Cache.get() call which would incorrectly increment
  cache counters.
* Initialize all counters and gauges at zero.

* Allow prefetching of a single request per ttl

The original implementation didn't allow prefetching queries which are
only requested once during the duration of a TTL. The minimum amount of
queries which had to be seen was therefore capped at 2.

This change also implements a real prefetch test. The existing test was
a noop and always passed regardless of any prefetch implementation.

* Fix prefetching for items with a short TTL

The default prefetch threshold (percentage) is 10% of the lifetime of a
cache item. With the previous implementation, this disabled prefetching
for all items with a TTL < 10s (the resulting percentage would be 0, at
which point a cached item is already discarded).

This change uses a time based threshold calculation and ensures that
a prefetch is triggered at a TTL of 1 at the latest.

* Fix wrong duration reporting of cached responses

The logging and metrics plugins (among others) included the duration of
a cache prefetch in the request latency of client request. This change
fixes this wrong reporting and executes the prefetch request in a
goroutine in the background.

1 files changed, 134 insertions, 25 deletions

diff --git a/plugin/cache/prefech_test.go b/plugin/cache/prefech_test.go
index 77a8f45ea..1cd0758fb 100644
--- a/plugin/cache/prefech_test.go
+++ b/plugin/cache/prefech_test.go
@@ -6,7 +6,6 @@ import (
 	"time"
 
 	"github.com/coredns/coredns/plugin"
-	"github.com/coredns/coredns/plugin/pkg/cache"
 	"github.com/coredns/coredns/plugin/pkg/dnstest"
 
 	"github.com/coredns/coredns/plugin/test"
@@ -14,41 +13,151 @@ import (
 	"golang.org/x/net/context"
 )
 
-var p = false
-
 func TestPrefetch(t *testing.T) {
-	c := &Cache{Zones: []string{"."}, pcap: defaultCap, ncap: defaultCap, pttl: maxTTL, nttl: maxTTL}
-	c.pcache = cache.New(c.pcap)
-	c.ncache = cache.New(c.ncap)
-	c.prefetch = 1
-	c.duration = 1 * time.Second
-	c.Next = PrefetchHandler(t, dns.RcodeSuccess, nil)
+	tests := []struct {
+		qname         string
+		ttl           int
+		prefetch      int
+		verifications []verification
+	}{
+		{
+			qname:    "hits.reset.example.org.",
+			ttl:      80,
+			prefetch: 1,
+			verifications: []verification{
+				{
+					after:  0 * time.Second,
+					answer: "hits.reset.example.org. 80 IN A 127.0.0.1",
+					fetch:  true,
+				},
+				{
+					after:  73 * time.Second,
+					answer: "hits.reset.example.org.  7 IN A 127.0.0.1",
+					fetch:  true,
+				},
+				{
+					after:  80 * time.Second,
+					answer: "hits.reset.example.org. 73 IN A 127.0.0.2",
+				},
+			},
+		},
+		{
+			qname:    "short.ttl.example.org.",
+			ttl:      5,
+			prefetch: 1,
+			verifications: []verification{
+				{
+					after:  0 * time.Second,
+					answer: "short.ttl.example.org. 5 IN A 127.0.0.1",
+					fetch:  true,
+				},
+				{
+					after:  1 * time.Second,
+					answer: "short.ttl.example.org. 4 IN A 127.0.0.1",
+				},
+				{
+					after:  4 * time.Second,
+					answer: "short.ttl.example.org. 1 IN A 127.0.0.1",
+					fetch:  true,
+				},
+				{
+					after:  5 * time.Second,
+					answer: "short.ttl.example.org. 4 IN A 127.0.0.2",
+				},
+			},
+		},
+		{
+			qname:    "no.prefetch.example.org.",
+			ttl:      30,
+			prefetch: 0,
+			verifications: []verification{
+				{
+					after:  0 * time.Second,
+					answer: "no.prefetch.example.org. 30 IN A 127.0.0.1",
+					fetch:  true,
+				},
+				{
+					after:  15 * time.Second,
+					answer: "no.prefetch.example.org. 15 IN A 127.0.0.1",
+				},
+				{
+					after:  29 * time.Second,
+					answer: "no.prefetch.example.org.  1 IN A 127.0.0.1",
+				},
+				{
+					after:  30 * time.Second,
+					answer: "no.prefetch.example.org. 30 IN A 127.0.0.2",
+					fetch:  true,
+				},
+			},
+		},
+	}
+
+	t0, err := time.Parse(time.RFC3339, "2018-01-01T14:00:00+00:00")
+	if err != nil {
+		t.Fatal(err)
+	}
+	for _, tt := range tests {
+		t.Run(tt.qname, func(t *testing.T) {
+			fetchc := make(chan struct{}, 1)
 
-	ctx := context.TODO()
+			c := New()
+			c.prefetch = tt.prefetch
+			c.Next = prefetchHandler(tt.qname, tt.ttl, fetchc)
 
-	req := new(dns.Msg)
-	req.SetQuestion("lowttl.example.org.", dns.TypeA)
+			req := new(dns.Msg)
+			req.SetQuestion(tt.qname, dns.TypeA)
+			rec := dnstest.NewRecorder(&test.ResponseWriter{})
 
-	rec := dnstest.NewRecorder(&test.ResponseWriter{})
+			for _, v := range tt.verifications {
+				c.now = func() time.Time { return t0.Add(v.after) }
+
+				c.ServeDNS(context.TODO(), rec, req)
+				if v.fetch {
+					select {
+					case <-fetchc:
+						if !v.fetch {
+							t.Fatalf("after %s: want request to trigger a prefetch", v.after)
+						}
+					case <-time.After(time.Second):
+						t.Fatalf("after %s: want request to trigger a prefetch", v.after)
+					}
+				}
+				if want, got := rec.Rcode, dns.RcodeSuccess; want != got {
+					t.Errorf("after %s: want rcode %d, got %d", v.after, want, got)
+				}
+				if want, got := 1, len(rec.Msg.Answer); want != got {
+					t.Errorf("after %s: want %d answer RR, got %d", v.after, want, got)
+				}
+				if want, got := test.A(v.answer).String(), rec.Msg.Answer[0].String(); want != got {
+					t.Errorf("after %s: want answer %s, got %s", v.after, want, got)
+				}
+			}
+		})
+	}
+}
 
-	c.ServeDNS(ctx, rec, req)
-	p = true // prefetch should be true for the 2nd fetch
-	c.ServeDNS(ctx, rec, req)
+type verification struct {
+	after  time.Duration
+	answer string
+	// fetch defines whether a request is sent to the next handler.
+	fetch bool
 }
 
-func PrefetchHandler(t *testing.T, rcode int, err error) plugin.Handler {
+// prefetchHandler is a fake plugin implementation which returns a single A
+// record with the given qname and ttl. The returned IP address starts at
+// 127.0.0.1 and is incremented on every request.
+func prefetchHandler(qname string, ttl int, fetchc chan struct{}) plugin.Handler {
+	i := 0
 	return plugin.HandlerFunc(func(ctx context.Context, w dns.ResponseWriter, r *dns.Msg) (int, error) {
+		i++
 		m := new(dns.Msg)
-		m.SetQuestion("lowttl.example.org.", dns.TypeA)
+		m.SetQuestion(qname, dns.TypeA)
 		m.Response = true
-		m.RecursionAvailable = true
-		m.Answer = append(m.Answer, test.A("lowttl.example.org. 80 IN A 127.0.0.53"))
-		if p != w.(*ResponseWriter).prefetch {
-			err = fmt.Errorf("cache prefetch not equal to p: got %t, want %t", p, w.(*ResponseWriter).prefetch)
-			t.Fatal(err)
-		}
+		m.Answer = append(m.Answer, test.A(fmt.Sprintf("%s %d IN A 127.0.0.%d", qname, ttl, i)))
 
 		w.WriteMsg(m)
-		return rcode, err
+		fetchc <- struct{}{}
+		return dns.RcodeSuccess, nil
 	})
 }