diff --git a/plugin/cache/README.md b/plugin/cache/README.md index 119f5290f..487b5392c 100644 --- a/plugin/cache/README.md +++ b/plugin/cache/README.md @@ -40,7 +40,7 @@ cache [TTL] [ZONES...] { success CAPACITY [TTL] [MINTTL] denial CAPACITY [TTL] [MINTTL] prefetch AMOUNT [[DURATION] [PERCENTAGE%]] - serve_stale [DURATION] [REFRESH_MODE [VERIFY_TIMEOUT]] + serve_stale [DURATION] [immediate [RESPONSE_TTL [FAILURE_RECHECK]] | verify [VERIFY_TIMEOUT [RESPONSE_TTL [FAILURE_RECHECK]]]] servfail DURATION disable success|denial [ZONES...] keepttl @@ -66,7 +66,7 @@ cache [TTL] [ZONES...] { * `serve_stale`, when serve\_stale is set, cache will always serve an expired entry to a client if there is one available as long as it has not been expired for longer than **DURATION** (default 1 hour). By default, the _cache_ plugin will attempt to refresh the cache entry after sending the expired cache entry to the client. The - responses have a TTL of 0. **REFRESH_MODE** controls the timing of the expired cache entry refresh. + responses have a TTL of 0 by default for backward compatibility. **REFRESH_MODE** controls the timing of the expired cache entry refresh. `verify` will first verify that an entry is still unavailable from the source before sending the expired entry to the client. `immediate` will immediately send the expired entry to the client before checking to see if the entry is available from the source. **REFRESH_MODE** defaults to `immediate`. Setting this @@ -78,6 +78,17 @@ cache [TTL] [ZONES...] { verify before falling back to the stale entry. The verify continues in the background and refreshes the cache when it eventually succeeds, so subsequent queries see the fresh entry. The default of `0` means wait until the upstream's own timeout (the original `verify` behavior). Example: `serve_stale 1h verify 100ms`. + **RESPONSE_TTL** sets the TTL returned with expired entries and defaults to `0`. RFC 8767 requires stale + responses to use a TTL greater than zero and recommends `30s`. In `immediate` mode it follows the mode, + for example `serve_stale 1h immediate 30s`. In `verify` mode it follows **VERIFY_TIMEOUT**, for example + `serve_stale 1h verify 100ms 30s`; use `0` as the timeout to wait for the upstream while setting a response + TTL, as in `serve_stale 1h verify 0 30s`. The response TTL must be a whole number of seconds. + **FAILURE_RECHECK** follows **RESPONSE_TTL** and limits how frequently a failed refresh is attempted again + for the same cache entry. While a refresh is in flight or its failure recheck period is active, the stale + entry is served immediately without another upstream request. A failed refresh leaves the stale cache entry + intact. The default of `0` preserves the existing retry behavior. RFC 8767 recommends `30s` and says this + value should not exceed 5 minutes. Examples: `serve_stale 1h immediate 30s 30s` and + `serve_stale 1h verify 100ms 30s 30s`. * `servfail` cache SERVFAIL responses for **DURATION**. Setting **DURATION** to 0 will disable caching of SERVFAIL responses. If this option is not set, SERVFAIL responses will be cached for 5 seconds. **DURATION** may not be greater than 5 minutes. diff --git a/plugin/cache/cache.go b/plugin/cache/cache.go index 76a73ff40..19bb13d44 100644 --- a/plugin/cache/cache.go +++ b/plugin/cache/cache.go @@ -46,6 +46,8 @@ type Cache struct { staleUpTo time.Duration verifyStale bool verifyStaleTimeout time.Duration // 0 means wait for upstream until its own timeout (current default). + staleTTL time.Duration // TTL returned with stale responses; 0 preserves the legacy behavior. + staleRecheck time.Duration // Delay after a failed refresh before another attempt; 0 preserves the legacy behavior. // Positive/negative zone exceptions pexcept []string @@ -468,8 +470,8 @@ type verifyStaleResponseWriter struct { } // newVerifyStaleResponseWriter returns a ResponseWriter to be used when verifying stale cache -// entries. It only forward writes if an entry was successfully refreshed according to RFC8767, -// section 4 (response is NoError or NXDomain), and ignores any other response. +// entries. It only forwards matching, complete responses that successfully refresh the data +// according to RFC8767, section 4 (response is NoError or NXDomain), and ignores other responses. func newVerifyStaleResponseWriter(w *ResponseWriter) *verifyStaleResponseWriter { return &verifyStaleResponseWriter{ w, @@ -480,11 +482,18 @@ func newVerifyStaleResponseWriter(w *ResponseWriter) *verifyStaleResponseWriter // WriteMsg implements the dns.ResponseWriter interface. func (w *verifyStaleResponseWriter) WriteMsg(res *dns.Msg) error { w.refreshed = false - if res.Rcode == dns.RcodeSuccess || res.Rcode == dns.RcodeNameError { - w.refreshed = true - return w.ResponseWriter.WriteMsg(res) // stores to the cache and send to client + if res == nil || res.Truncated || !w.state.Match(res) { + return nil } - return nil // else discard + responseType, _ := response.Typify(res, w.now().UTC()) + if responseType == response.OtherError || responseType == response.Meta || responseType == response.Update { + return nil + } + if res.Rcode != dns.RcodeSuccess && res.Rcode != dns.RcodeNameError { + return nil + } + w.refreshed = true + return w.ResponseWriter.WriteMsg(res) // stores to the cache and sends to the client } const ( diff --git a/plugin/cache/cache_test.go b/plugin/cache/cache_test.go index a15fc804d..7be23a46b 100644 --- a/plugin/cache/cache_test.go +++ b/plugin/cache/cache_test.go @@ -6,6 +6,7 @@ import ( "testing" "time" + "github.com/coredns/caddy" "github.com/coredns/coredns/plugin" "github.com/coredns/coredns/plugin/metadata" "github.com/coredns/coredns/plugin/pkg/dnstest" @@ -693,6 +694,121 @@ func TestServeFromStaleCache(t *testing.T) { } } +func TestServeFromStaleCacheResponseTTL(t *testing.T) { + tests := []struct { + name string + config string + primeRcode int + advance time.Duration + expectedTTL uint32 + }{ + { + name: "legacy default", + config: "serve_stale 1h immediate", + primeRcode: dns.RcodeSuccess, + advance: 2 * time.Minute, + expectedTTL: 0, + }, + { + name: "immediate positive", + config: "serve_stale 1h immediate 30s", + primeRcode: dns.RcodeSuccess, + advance: 2 * time.Minute, + expectedTTL: 30, + }, + { + name: "exact expiry", + config: "serve_stale 1h immediate 30s", + primeRcode: dns.RcodeSuccess, + advance: time.Minute, + expectedTTL: 30, + }, + { + name: "immediate negative", + config: "serve_stale 1h immediate 25s", + primeRcode: dns.RcodeNameError, + advance: 2 * time.Minute, + expectedTTL: 25, + }, + { + name: "verify failure", + config: "serve_stale 1h verify 0 45s", + primeRcode: dns.RcodeSuccess, + advance: 2 * time.Minute, + expectedTTL: 45, + }, + { + name: "stale ttl overrides keepttl", + config: "serve_stale 1h immediate 17s\nkeepttl", + primeRcode: dns.RcodeSuccess, + advance: 2 * time.Minute, + expectedTTL: 17, + }, + { + name: "fresh response is unchanged", + config: "serve_stale 1h immediate 30s", + primeRcode: dns.RcodeSuccess, + advance: 10 * time.Second, + expectedTTL: 50, + }, + } + + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + controller := caddy.NewTestController("dns", fmt.Sprintf("cache {\n%s\n}", tc.config)) + c, err := cacheParse(controller) + if err != nil { + t.Fatalf("unexpected parse error: %v", err) + } + c.Zones = []string{"."} + + switch tc.primeRcode { + case dns.RcodeSuccess: + c.Next = ttlBackend(60) + case dns.RcodeNameError: + c.Next = nxDomainBackend(60) + default: + t.Fatalf("unsupported prime rcode %d", tc.primeRcode) + } + + req := new(dns.Msg) + req.SetQuestion("cached.org.", dns.TypeA) + ctx := context.Background() + stored := time.Now() + c.now = func() time.Time { return stored } + if ret, err := c.ServeDNS(ctx, dnstest.NewRecorder(&test.ResponseWriter{}), req); err != nil || ret != tc.primeRcode { + t.Fatalf("failed to prime cache: rcode=%d, err=%v", ret, err) + } + + c.now = func() time.Time { return stored.Add(tc.advance) } + c.Next = servFailBackend(60) + rec := dnstest.NewRecorder(&test.ResponseWriter{}) + if ret, err := c.ServeDNS(ctx, rec, req.Copy()); err != nil || ret != dns.RcodeSuccess { + t.Fatalf("unexpected cached response: rcode=%d, err=%v", ret, err) + } + if rec.Msg == nil || rec.Msg.Rcode != tc.primeRcode { + t.Fatalf("expected response rcode %d, got %v", tc.primeRcode, rec.Msg) + } + + var got uint32 + if tc.primeRcode == dns.RcodeNameError { + if len(rec.Msg.Ns) == 0 { + t.Fatalf("expected authority record, got %v", rec.Msg) + } + got = rec.Msg.Ns[0].Header().Ttl + } else { + if len(rec.Msg.Answer) == 0 { + t.Fatalf("expected answer record, got %v", rec.Msg) + } + got = rec.Msg.Answer[0].Header().Ttl + } + if got != tc.expectedTTL { + t.Fatalf("expected TTL %d, got %d", tc.expectedTTL, got) + } + }) + } +} + func TestServeFromStaleCacheFetchVerify(t *testing.T) { c := New() c.Next = ttlBackend(120) @@ -777,6 +893,7 @@ func TestServeFromStaleCacheFetchVerifyTimeout(t *testing.T) { c.staleUpTo = 1 * time.Hour c.verifyStale = true c.verifyStaleTimeout = 50 * time.Millisecond + c.staleTTL = 30 * time.Second c.Next = ttlBackend(120) req := new(dns.Msg) @@ -814,9 +931,8 @@ func TestServeFromStaleCacheFetchVerifyTimeout(t *testing.T) { if rec.Msg == nil || len(rec.Msg.Answer) == 0 { t.Fatalf("expected an answer, got %+v", rec.Msg) } - // Stale serve sets TTL to 0. - if got := rec.Msg.Answer[0].Header().Ttl; got != 0 { - t.Errorf("expected stale TTL=0, got %d", got) + if got := rec.Msg.Answer[0].Header().Ttl; got != 30 { + t.Errorf("expected stale TTL=30, got %d", got) } // Wait for the background verify to complete. diff --git a/plugin/cache/handler.go b/plugin/cache/handler.go index 845ab82c7..7d1b6e64b 100644 --- a/plugin/cache/handler.go +++ b/plugin/cache/handler.go @@ -41,34 +41,43 @@ func (c *Cache) ServeDNS(ctx context.Context, w dns.ResponseWriter, r *dns.Msg) return c.doRefresh(ctx, state, crr) } ttl := i.ttl(now) - if ttl < 0 { + stale := ttl <= 0 + if stale { // serve stale behavior if c.verifyStale { - crr := &ResponseWriter{ResponseWriter: w, Cache: c, state: state, server: server, do: do, cd: cd} - if c.verifyStaleTimeout > 0 { - // Background verify: cache the response but do not write to the wire. - // On timeout, we serve the stale entry below and let the goroutine continue. - crr.prefetch = true - } - cw := newVerifyStaleResponseWriter(crr) - if c.verifyStaleTimeout == 0 { - ret, err := c.doRefresh(ctx, state, cw) - if cw.refreshed { + failureRecheck := c.staleRecheck + nowFunc := c.now + trackRefresh := failureRecheck > 0 + if !trackRefresh || i.beginRefresh(now, failureRecheck) { + crr := &ResponseWriter{ResponseWriter: w, Cache: c, state: state, server: server, do: do, cd: cd} + if c.verifyStaleTimeout > 0 { + // Background verify: cache the response but do not write to the wire. + // On timeout, we serve the stale entry below and let the goroutine continue. + crr.prefetch = true + } + cw := newVerifyStaleResponseWriter(crr) + if c.verifyStaleTimeout == 0 { + ret, err := c.doRefresh(ctx, state, cw) + if trackRefresh { + i.endRefresh(nowFunc(), failureRecheck, cw.refreshed) + } + if cw.refreshed { + return ret, err + } + } else if served, ret, err := c.verifyWithTimeout(ctx, state, w, cw, r, do, ad, i, failureRecheck, nowFunc); served { return ret, err } - } else if served, ret, err := c.verifyWithTimeout(ctx, state, w, cw, r, do, ad); served { - return ret, err } } // Adjust the time to get a 0 TTL in the reply built from a stale item. now = now.Add(time.Duration(ttl) * time.Second) if !c.verifyStale { - c.tryPrefetch(ctx, i, server, rc, do, cd, now) + c.tryPrefetch(ctx, i, server, rc, do, cd, now, true) } servedStale.WithLabelValues(server, c.zonesMetricLabel, c.viewMetricLabel).Inc() } else if c.shouldPrefetch(i, now) { - c.tryPrefetch(ctx, i, server, rc, do, cd, now) + c.tryPrefetch(ctx, i, server, rc, do, cd, now, false) } if i.wildcard != "" { @@ -83,7 +92,13 @@ func (c *Cache) ServeDNS(ctx context.Context, w dns.ResponseWriter, r *dns.Msg) // one so that we always get the original TTL now = i.stored } - resp := i.toMsg(r, now, do, ad) + var resp *dns.Msg + if stale && c.staleTTL > 0 { + staleTTL := uint32(c.staleTTL / time.Second) // #nosec G115 -- configuration parsing bounds this to the DNS TTL range. + resp = i.toMsgWithTTL(r, staleTTL, do, ad) + } else { + resp = i.toMsg(r, now, do, ad) + } w.WriteMsg(resp) return dns.RcodeSuccess, nil } @@ -101,22 +116,37 @@ func wildcardFunc(ctx context.Context) func() string { // tryPrefetch dispatches a background prefetch for i if one is not already in // flight. The CAS on i.refreshing ensures at most one prefetch goroutine per // item, so prefetch load scales with distinct stale keys rather than QPS. -func (c *Cache) tryPrefetch(ctx context.Context, i *item, server string, req *dns.Msg, do, cd bool, now time.Time) { - if !i.refreshing.CompareAndSwap(false, true) { +func (c *Cache) tryPrefetch(ctx context.Context, i *item, server string, req *dns.Msg, do, cd bool, now time.Time, stale bool) { + failureRecheck := time.Duration(0) + if stale { + failureRecheck = c.staleRecheck + } + nowFunc := c.now + if !i.beginRefresh(nowFunc(), failureRecheck) { return } cw := newPrefetchResponseWriter(server, req, do, cd, c) go func() { - defer i.refreshing.Store(false) - c.doPrefetch(ctx, cw, i, now) + refreshed := c.doPrefetch(ctx, cw, i, now, stale) + i.endRefresh(nowFunc(), failureRecheck, refreshed) }() } -func (c *Cache) doPrefetch(ctx context.Context, cw *ResponseWriter, i *item, now time.Time) { +func (c *Cache) doPrefetch(ctx context.Context, cw *ResponseWriter, i *item, now time.Time, stale bool) bool { // Use a fresh metadata map to avoid concurrent writes to the original request's metadata. ctx = metadata.ContextWithMetadata(ctx) cachePrefetches.WithLabelValues(cw.server, c.zonesMetricLabel, c.viewMetricLabel).Inc() - c.doRefresh(ctx, cw.state, cw) + refreshed := true + if stale { + refreshWriter := newVerifyStaleResponseWriter(cw) + c.doRefresh(ctx, cw.state, refreshWriter) + refreshed = refreshWriter.refreshed + } else { + c.doRefresh(ctx, cw.state, cw) + } + if !refreshed { + return false + } // When prefetching we loose the item i, and with it the frequency // that we've gathered sofar. See we copy the frequencies info back @@ -124,6 +154,7 @@ func (c *Cache) doPrefetch(ctx context.Context, cw *ResponseWriter, i *item, now if i1 := c.exists(cw.state.Name(), cw.state.QType(), cw.state.QClass(), cw.do, cw.cd); i1 != nil { i1.Reset(now, i.Hits()) } + return true } func (c *Cache) doRefresh(ctx context.Context, state request.Request, cw dns.ResponseWriter) (int, error) { @@ -136,7 +167,7 @@ func (c *Cache) doRefresh(ctx context.Context, state request.Request, cw dns.Res // to the client and served is true. Otherwise served is false and the caller falls // through to serve stale; the goroutine continues to run and any successful response // will update the cache without writing to the (now-detached) client connection. -func (c *Cache) verifyWithTimeout(ctx context.Context, state request.Request, w dns.ResponseWriter, cw *verifyStaleResponseWriter, r *dns.Msg, do, ad bool) (served bool, code int, err error) { +func (c *Cache) verifyWithTimeout(ctx context.Context, state request.Request, w dns.ResponseWriter, cw *verifyStaleResponseWriter, r *dns.Msg, do, ad bool, i *item, failureRecheck time.Duration, now func() time.Time) (served bool, code int, err error) { type result struct { code int err error @@ -148,6 +179,9 @@ func (c *Cache) verifyWithTimeout(ctx context.Context, state request.Request, w } go func() { rc, re := c.doRefresh(refreshCtx, state, cw) + if failureRecheck > 0 { + i.endRefresh(now(), failureRecheck, cw.refreshed) + } done <- result{rc, re} }() timer := time.NewTimer(c.verifyStaleTimeout) diff --git a/plugin/cache/item.go b/plugin/cache/item.go index 17f68a04e..cf135fc38 100644 --- a/plugin/cache/item.go +++ b/plugin/cache/item.go @@ -28,13 +28,12 @@ type item struct { *freq.Freq - // refreshing is set via CAS when a prefetch goroutine is dispatched for - // this item and cleared when it returns, bounding in-flight prefetches - // per item to one. A successful prefetch replaces this item in the cache - // with a new one (zero-valued refreshing); the deferred clear matters - // only when the prefetch fails and this item remains cached, so the next - // hit can retry. + // refreshing bounds in-flight refreshes for this item to one. retryAfter + // suppresses another attempt after a failed refresh when failure recheck + // is configured. A successful refresh normally replaces this item with a + // new one whose refresh state is zero-valued. refreshing atomic.Bool + retryAfter atomic.Pointer[time.Time] } func newItem(m *dns.Msg, now time.Time, d time.Duration) *item { @@ -79,6 +78,12 @@ func newItem(m *dns.Msg, now time.Time, d time.Duration) *item { // On newer systems(e.g. ubuntu 16.04 with glib version 2.23), this issue is resolved. // So we may set this bit back to 0 in the future ? func (i *item) toMsg(m *dns.Msg, now time.Time, do bool, ad bool) *dns.Msg { + ttl := uint32(i.ttl(now)) // #nosec G115 -- ttl is bounded by DNS TTL limits + return i.toMsgWithTTL(m, ttl, do, ad) +} + +// toMsgWithTTL returns the cached item with an explicit TTL on every RR. +func (i *item) toMsgWithTTL(m *dns.Msg, ttl uint32, do bool, ad bool) *dns.Msg { m1 := new(dns.Msg) m1.SetReply(m) @@ -95,7 +100,6 @@ func (i *item) toMsg(m *dns.Msg, now time.Time, do bool, ad bool) *dns.Msg { m1.RecursionAvailable = i.RecursionAvailable m1.Rcode = i.Rcode - ttl := uint32(i.ttl(now)) // #nosec G115 -- ttl is bounded by DNS TTL limits m1.Answer = filterRRSlice(i.Answer, ttl, true) m1.Ns = filterRRSlice(i.Ns, ttl, true) m1.Extra = filterRRSlice(i.Extra, ttl, true) @@ -114,3 +118,23 @@ func (i *item) matches(state request.Request) bool { } return false } + +func (i *item) beginRefresh(now time.Time, failureRecheck time.Duration) bool { + if failureRecheck > 0 { + if retryAfter := i.retryAfter.Load(); retryAfter != nil && now.Before(*retryAfter) { + return false + } + } + return i.refreshing.CompareAndSwap(false, true) +} + +func (i *item) endRefresh(now time.Time, failureRecheck time.Duration, refreshed bool) { + if failureRecheck > 0 && !refreshed { + retryAfter := now.Add(failureRecheck) + i.retryAfter.Store(&retryAfter) + } else { + i.retryAfter.Store(nil) + } + // Publish the retry deadline before allowing another refresh to start. + i.refreshing.Store(false) +} diff --git a/plugin/cache/serve_stale_recheck_test.go b/plugin/cache/serve_stale_recheck_test.go new file mode 100644 index 000000000..5e39c51f6 --- /dev/null +++ b/plugin/cache/serve_stale_recheck_test.go @@ -0,0 +1,376 @@ +package cache + +import ( + "context" + "sync/atomic" + "testing" + "time" + + "github.com/coredns/coredns/plugin" + "github.com/coredns/coredns/plugin/pkg/dnstest" + "github.com/coredns/coredns/plugin/test" + + "github.com/miekg/dns" +) + +type staleRecheckClock struct { + base time.Time + offset atomic.Int64 +} + +func newStaleRecheckClock() *staleRecheckClock { + return &staleRecheckClock{base: time.Now()} +} + +func (c *staleRecheckClock) Now() time.Time { + return c.base.Add(time.Duration(c.offset.Load())) +} + +func (c *staleRecheckClock) Set(offset time.Duration) { + c.offset.Store(int64(offset)) +} + +func TestServeStaleFailureRecheckImmediate(t *testing.T) { + tests := []struct { + name string + prime plugin.Handler + expectedRcode int + }{ + {name: "positive", prime: ttlBackend(1), expectedRcode: dns.RcodeSuccess}, + {name: "negative", prime: nxDomainBackend(1), expectedRcode: dns.RcodeNameError}, + } + + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + clock := newStaleRecheckClock() + c := New() + c.now = clock.Now + c.minpttl = 0 + c.minnttl = 0 + c.staleUpTo = time.Hour + c.staleTTL = 30 * time.Second + c.staleRecheck = 30 * time.Second + c.Next = tc.prime + + req := new(dns.Msg) + req.SetQuestion("cached.org.", dns.TypeA) + serveStaleRecheckRequest(t, c, req) + item := c.exists("cached.org.", dns.TypeA, dns.ClassINET, false, false) + if item == nil { + t.Fatal("expected primed cache item") + } + + clock.Set(2 * time.Second) + var calls atomic.Int32 + started := make(chan struct{}, 2) + completed := make(chan struct{}, 2) + release := make(chan struct{}, 2) + defer close(release) + failure := servFailBackend(30) + c.Next = plugin.HandlerFunc(func(ctx context.Context, w dns.ResponseWriter, r *dns.Msg) (int, error) { + calls.Add(1) + started <- struct{}{} + <-release + rcode, err := failure.ServeDNS(ctx, w, r) + completed <- struct{}{} + return rcode, err + }) + + msg := serveStaleRecheckRequest(t, c, req) + if msg.Rcode != tc.expectedRcode { + t.Fatalf("expected stale rcode %d, got %d", tc.expectedRcode, msg.Rcode) + } + waitForStaleSignal(t, started, "background refresh did not start") + release <- struct{}{} + waitForStaleRefresh(t, completed, item) + if got := calls.Load(); got != 1 { + t.Fatalf("expected one refresh attempt, got %d", got) + } + + msg = serveStaleRecheckRequest(t, c, req) + if msg.Rcode != tc.expectedRcode { + t.Fatalf("expected stale rcode %d during recheck, got %d", tc.expectedRcode, msg.Rcode) + } + if item.refreshing.Load() { + t.Fatal("failure recheck did not suppress a new refresh") + } + if got := calls.Load(); got != 1 { + t.Fatalf("expected refresh to be suppressed during recheck, got %d attempts", got) + } + + clock.Set(33 * time.Second) + serveStaleRecheckRequest(t, c, req) + waitForStaleSignal(t, started, "refresh did not restart after recheck elapsed") + release <- struct{}{} + waitForStaleRefresh(t, completed, item) + if got := calls.Load(); got != 2 { + t.Fatalf("expected refresh after recheck elapsed, got %d attempts", got) + } + if got := c.exists("cached.org.", dns.TypeA, dns.ClassINET, false, false).Rcode; got != tc.expectedRcode { + t.Fatalf("failed refresh replaced stale state: expected rcode %d, got %d", tc.expectedRcode, got) + } + }) + } +} + +func TestServeStaleFailureRecheckVerify(t *testing.T) { + clock := newStaleRecheckClock() + c := New() + c.now = clock.Now + c.minpttl = 0 + c.minnttl = 0 + c.staleUpTo = time.Hour + c.verifyStale = true + c.staleRecheck = 30 * time.Second + c.Next = ttlBackend(1) + + req := new(dns.Msg) + req.SetQuestion("cached.org.", dns.TypeA) + serveStaleRecheckRequest(t, c, req) + clock.Set(2 * time.Second) + + var calls atomic.Int32 + failure := servFailBackend(30) + c.Next = plugin.HandlerFunc(func(ctx context.Context, w dns.ResponseWriter, r *dns.Msg) (int, error) { + calls.Add(1) + return failure.ServeDNS(ctx, w, r) + }) + + serveStaleRecheckRequest(t, c, req) + serveStaleRecheckRequest(t, c, req) + if got := calls.Load(); got != 1 { + t.Fatalf("expected one verify during failure recheck, got %d", got) + } + + clock.Set(33 * time.Second) + serveStaleRecheckRequest(t, c, req) + if got := calls.Load(); got != 2 { + t.Fatalf("expected verify after failure recheck elapsed, got %d", got) + } +} + +func TestServeStaleFailureRecheckRejectsInvalidRefresh(t *testing.T) { + modes := []struct { + name string + verify bool + }{ + {name: "immediate"}, + {name: "verify", verify: true}, + } + invalidResponses := []struct { + name string + build func(*dns.Msg) *dns.Msg + }{ + { + name: "truncated", + build: func(req *dns.Msg) *dns.Msg { + m := new(dns.Msg) + m.SetReply(req) + m.Truncated = true + m.Answer = []dns.RR{test.A("cached.org. 60 IN A 192.0.2.20")} + return m + }, + }, + { + name: "mismatched question", + build: func(req *dns.Msg) *dns.Msg { + m := new(dns.Msg) + m.SetReply(req) + m.Question[0].Name = "other.org." + m.Answer = []dns.RR{test.A("other.org. 60 IN A 192.0.2.20")} + return m + }, + }, + { + name: "expired RRSIG", + build: func(req *dns.Msg) *dns.Msg { + m := new(dns.Msg) + m.SetReply(req) + m.SetEdns0(4096, true) + m.Answer = []dns.RR{ + test.A("cached.org. 60 IN A 192.0.2.20"), + test.RRSIG("cached.org. 60 IN RRSIG A 8 2 60 20160521031301 20160421031301 12051 cached.org. lAaEzB5teQLLKyDenatmyhca7blLRg9DoGNrhe3NReBZN5C5/pMQk8Jc u25hv2fW23/SLm5IC2zaDpp2Fzgm6Jf7e90/yLcwQPuE7JjS55WMF+HE LEh7Z6AEb+Iq4BWmNhUz6gPxD4d9eRMs7EAzk13o1NYi5/JhfL6IlaYy qkc="), + } + return m + }, + }, + } + + for _, mode := range modes { + for _, invalid := range invalidResponses { + t.Run(mode.name+"/"+invalid.name, func(t *testing.T) { + clock := newStaleRecheckClock() + c := New() + c.now = clock.Now + c.minpttl = 0 + c.staleUpTo = time.Hour + c.verifyStale = mode.verify + c.staleTTL = 30 * time.Second + c.staleRecheck = 30 * time.Second + c.Next = ttlBackend(1) + + req := new(dns.Msg) + req.SetQuestion("cached.org.", dns.TypeA) + req.SetEdns0(4096, true) + serveStaleRecheckRequest(t, c, req) + item := c.exists("cached.org.", dns.TypeA, dns.ClassINET, true, false) + if item == nil { + t.Fatal("expected primed cache item") + } + clock.Set(2 * time.Second) + + var calls atomic.Int32 + completed := make(chan struct{}, 1) + c.Next = plugin.HandlerFunc(func(_ context.Context, w dns.ResponseWriter, req *dns.Msg) (int, error) { + calls.Add(1) + err := w.WriteMsg(invalid.build(req)) + completed <- struct{}{} + return dns.RcodeSuccess, err + }) + + msg := serveStaleRecheckRequest(t, c, req) + assertStaleRecheckAddress(t, msg) + waitForStaleRefresh(t, completed, item) + if retryAfter := item.retryAfter.Load(); retryAfter == nil || !retryAfter.After(clock.Now()) { + t.Fatal("invalid refresh did not start the failure recheck interval") + } + + msg = serveStaleRecheckRequest(t, c, req) + assertStaleRecheckAddress(t, msg) + if got := calls.Load(); got != 1 { + t.Fatalf("expected invalid refresh to be suppressed during recheck, got %d attempts", got) + } + }) + } + } +} + +func TestServeStaleFailureRecheckVerifyTimeoutCoalesces(t *testing.T) { + clock := newStaleRecheckClock() + c := New() + c.now = clock.Now + c.minpttl = 0 + c.minnttl = 0 + c.staleUpTo = time.Hour + c.verifyStale = true + c.verifyStaleTimeout = 10 * time.Millisecond + c.staleRecheck = 30 * time.Second + c.Next = ttlBackend(1) + + req := new(dns.Msg) + req.SetQuestion("cached.org.", dns.TypeA) + serveStaleRecheckRequest(t, c, req) + item := c.exists("cached.org.", dns.TypeA, dns.ClassINET, false, false) + clock.Set(2 * time.Second) + + var calls atomic.Int32 + started := make(chan struct{}, 2) + completed := make(chan struct{}, 2) + release := make(chan struct{}) + failure := servFailBackend(30) + c.Next = plugin.HandlerFunc(func(ctx context.Context, w dns.ResponseWriter, r *dns.Msg) (int, error) { + calls.Add(1) + started <- struct{}{} + <-release + rcode, err := failure.ServeDNS(ctx, w, r) + completed <- struct{}{} + return rcode, err + }) + + serveStaleRecheckRequest(t, c, req) + waitForStaleSignal(t, started, "background verify did not start") + serveStaleRecheckRequest(t, c, req) + if got := calls.Load(); got != 1 { + t.Fatalf("expected concurrent stale request to share the in-flight verify, got %d attempts", got) + } + + close(release) + waitForStaleRefresh(t, completed, item) + serveStaleRecheckRequest(t, c, req) + if got := calls.Load(); got != 1 { + t.Fatalf("expected failed background verify to start recheck delay, got %d attempts", got) + } + + clock.Set(33 * time.Second) + serveStaleRecheckRequest(t, c, req) + waitForStaleRefresh(t, completed, item) + if got := calls.Load(); got != 2 { + t.Fatalf("expected a new verify after recheck elapsed, got %d attempts", got) + } +} + +func TestServeStaleFailureRecheckDisabledPreservesVerifyBehavior(t *testing.T) { + clock := newStaleRecheckClock() + c := New() + c.now = clock.Now + c.minpttl = 0 + c.minnttl = 0 + c.staleUpTo = time.Hour + c.verifyStale = true + c.Next = ttlBackend(1) + + req := new(dns.Msg) + req.SetQuestion("cached.org.", dns.TypeA) + serveStaleRecheckRequest(t, c, req) + clock.Set(2 * time.Second) + + var calls atomic.Int32 + failure := servFailBackend(30) + c.Next = plugin.HandlerFunc(func(ctx context.Context, w dns.ResponseWriter, r *dns.Msg) (int, error) { + calls.Add(1) + return failure.ServeDNS(ctx, w, r) + }) + + serveStaleRecheckRequest(t, c, req) + serveStaleRecheckRequest(t, c, req) + if got := calls.Load(); got != 2 { + t.Fatalf("expected disabled failure recheck to preserve per-request verify, got %d attempts", got) + } +} + +func serveStaleRecheckRequest(t *testing.T, c *Cache, req *dns.Msg) *dns.Msg { + t.Helper() + recorder := dnstest.NewRecorder(&test.ResponseWriter{}) + if _, err := c.ServeDNS(context.Background(), recorder, req.Copy()); err != nil { + t.Fatalf("ServeDNS failed: %v", err) + } + if recorder.Msg == nil { + t.Fatal("ServeDNS did not write a response") + } + return recorder.Msg +} + +func assertStaleRecheckAddress(t *testing.T, msg *dns.Msg) { + t.Helper() + if msg.Truncated || len(msg.Answer) != 1 { + t.Fatalf("expected one complete stale answer, got %#v", msg) + } + a, ok := msg.Answer[0].(*dns.A) + if !ok || a.A.String() != "127.0.0.53" { + t.Fatalf("expected stale address 127.0.0.53, got %v", msg.Answer) + } + if a.Hdr.Ttl != 30 { + t.Fatalf("expected stale TTL 30, got %d", a.Hdr.Ttl) + } +} + +func waitForStaleRefresh(t *testing.T, completed <-chan struct{}, item *item) { + t.Helper() + waitForStaleSignal(t, completed, "background refresh did not complete") + deadline := time.Now().Add(2 * time.Second) + for item.refreshing.Load() { + if time.Now().After(deadline) { + t.Fatal("background refresh did not release the cache item") + } + time.Sleep(time.Millisecond) + } +} + +func waitForStaleSignal(t *testing.T, signal <-chan struct{}, failure string) { + t.Helper() + select { + case <-signal: + case <-time.After(2 * time.Second): + t.Fatal(failure) + } +} diff --git a/plugin/cache/setup.go b/plugin/cache/setup.go index 611fce1c4..1a33183f4 100644 --- a/plugin/cache/setup.go +++ b/plugin/cache/setup.go @@ -172,10 +172,12 @@ func cacheParse(c *caddy.Controller) (*Cache, error) { case "serve_stale": args := c.RemainingArgs() - if len(args) > 3 { + if len(args) > 5 { return nil, c.ArgErr() } ca.staleUpTo = 1 * time.Hour + ca.staleTTL = 0 + ca.staleRecheck = 0 if len(args) > 0 { d, err := time.ParseDuration(args[0]) if err != nil { @@ -196,17 +198,43 @@ func cacheParse(c *caddy.Controller) (*Cache, error) { ca.verifyStale = mode == "verify" } if len(args) > 2 { - if !ca.verifyStale { - return nil, errors.New("serve_stale timeout is only valid with the verify refresh mode") + if ca.verifyStale { + t, err := time.ParseDuration(args[2]) + if err != nil { + return nil, fmt.Errorf("invalid serve_stale verify timeout: %w", err) + } + if t < 0 { + return nil, errors.New("invalid negative timeout for serve_stale verify") + } + ca.verifyStaleTimeout = t + if len(args) > 3 { + ca.staleTTL, err = parseServeStaleTTL(args[3]) + if err != nil { + return nil, err + } + } + if len(args) > 4 { + ca.staleRecheck, err = parseServeStaleRecheck(args[4]) + if err != nil { + return nil, err + } + } + } else { + if len(args) > 4 { + return nil, c.ArgErr() + } + var err error + ca.staleTTL, err = parseServeStaleTTL(args[2]) + if err != nil { + return nil, err + } + if len(args) > 3 { + ca.staleRecheck, err = parseServeStaleRecheck(args[3]) + if err != nil { + return nil, err + } + } } - t, err := time.ParseDuration(args[2]) - if err != nil { - return nil, fmt.Errorf("invalid serve_stale verify timeout: %w", err) - } - if t < 0 { - return nil, errors.New("invalid negative timeout for serve_stale verify") - } - ca.verifyStaleTimeout = t } case "servfail": args := c.RemainingArgs() @@ -273,3 +301,34 @@ func cacheParse(c *caddy.Controller) (*Cache, error) { return ca, nil } + +func parseServeStaleTTL(value string) (time.Duration, error) { + ttl, err := time.ParseDuration(value) + if err != nil { + return 0, fmt.Errorf("invalid serve_stale response TTL: %w", err) + } + if ttl < 0 { + return 0, errors.New("invalid negative response TTL for serve_stale") + } + if ttl%time.Second != 0 { + return 0, errors.New("serve_stale response TTL must be a whole number of seconds") + } + if ttl/time.Second > time.Duration(^uint32(0)) { + return 0, errors.New("serve_stale response TTL exceeds the DNS TTL range") + } + return ttl, nil +} + +func parseServeStaleRecheck(value string) (time.Duration, error) { + recheck, err := time.ParseDuration(value) + if err != nil { + return 0, fmt.Errorf("invalid serve_stale failure recheck: %w", err) + } + if recheck < 0 { + return 0, errors.New("invalid negative failure recheck for serve_stale") + } + if recheck > 5*time.Minute { + return 0, errors.New("serve_stale failure recheck cannot exceed 5 minutes") + } + return recheck, nil +} diff --git a/plugin/cache/setup_test.go b/plugin/cache/setup_test.go index 3aaa42921..7ac411d1f 100644 --- a/plugin/cache/setup_test.go +++ b/plugin/cache/setup_test.go @@ -122,28 +122,43 @@ func TestServeStale(t *testing.T) { staleUpTo time.Duration verifyStale bool verifyStaleTimeout time.Duration + staleTTL time.Duration }{ - {"serve_stale", false, 1 * time.Hour, false, 0}, - {"serve_stale 20m", false, 20 * time.Minute, false, 0}, - {"serve_stale 1h20m", false, 80 * time.Minute, false, 0}, - {"serve_stale 0m", false, 0, false, 0}, - {"serve_stale 0", false, 0, false, 0}, - {"serve_stale 0 verify", false, 0, true, 0}, - {"serve_stale 0 immediate", false, 0, false, 0}, - {"serve_stale 0 VERIFY", false, 0, true, 0}, - {"serve_stale 1h verify 100ms", false, 1 * time.Hour, true, 100 * time.Millisecond}, - {"serve_stale 1h verify 0", false, 1 * time.Hour, true, 0}, - {"serve_stale 1h VERIFY 250ms", false, 1 * time.Hour, true, 250 * time.Millisecond}, + {"serve_stale", false, 1 * time.Hour, false, 0, 0}, + {"serve_stale 20m", false, 20 * time.Minute, false, 0, 0}, + {"serve_stale 1h20m", false, 80 * time.Minute, false, 0, 0}, + {"serve_stale 0m", false, 0, false, 0, 0}, + {"serve_stale 0", false, 0, false, 0, 0}, + {"serve_stale 0 verify", false, 0, true, 0, 0}, + {"serve_stale 0 immediate", false, 0, false, 0, 0}, + {"serve_stale 0 VERIFY", false, 0, true, 0, 0}, + {"serve_stale 1h immediate 30s", false, 1 * time.Hour, false, 0, 30 * time.Second}, + {"serve_stale 1h immediate 30s 30s", false, 1 * time.Hour, false, 0, 30 * time.Second}, + {"serve_stale 1h immediate 4294967295s", false, 1 * time.Hour, false, 0, time.Duration(^uint32(0)) * time.Second}, + {"serve_stale 1h immediate 0", false, 1 * time.Hour, false, 0, 0}, + {"serve_stale 1h verify 100ms", false, 1 * time.Hour, true, 100 * time.Millisecond, 0}, + {"serve_stale 1h verify 100ms 30s", false, 1 * time.Hour, true, 100 * time.Millisecond, 30 * time.Second}, + {"serve_stale 1h verify 100ms 30s 30s", false, 1 * time.Hour, true, 100 * time.Millisecond, 30 * time.Second}, + {"serve_stale 1h verify 0", false, 1 * time.Hour, true, 0, 0}, + {"serve_stale 1h verify 0 1m", false, 1 * time.Hour, true, 0, time.Minute}, + {"serve_stale 1h VERIFY 250ms", false, 1 * time.Hour, true, 250 * time.Millisecond, 0}, // fails - {"serve_stale 20", true, 0, false, 0}, - {"serve_stale -20m", true, 0, false, 0}, - {"serve_stale aa", true, 0, false, 0}, - {"serve_stale 1m nono", true, 0, false, 0}, - {"serve_stale 0 after nono", true, 0, false, 0}, - {"serve_stale 1h immediate 100ms", true, 0, false, 0}, - {"serve_stale 1h verify -1ms", true, 0, false, 0}, - {"serve_stale 1h verify garbage", true, 0, false, 0}, - {"serve_stale 1h verify 100ms extra", true, 0, false, 0}, + {"serve_stale 20", true, 0, false, 0, 0}, + {"serve_stale -20m", true, 0, false, 0, 0}, + {"serve_stale aa", true, 0, false, 0, 0}, + {"serve_stale 1m nono", true, 0, false, 0, 0}, + {"serve_stale 0 after nono", true, 0, false, 0, 0}, + {"serve_stale 1h immediate 100ms", true, 0, false, 0, 0}, + {"serve_stale 1h immediate 4294967296s", true, 0, false, 0, 0}, + {"serve_stale 1h immediate -1s", true, 0, false, 0, 0}, + {"serve_stale 1h immediate garbage", true, 0, false, 0, 0}, + {"serve_stale 1h immediate 30s extra", true, 0, false, 0, 0}, + {"serve_stale 1h verify -1ms", true, 0, false, 0, 0}, + {"serve_stale 1h verify garbage", true, 0, false, 0, 0}, + {"serve_stale 1h verify 100ms 500ms", true, 0, false, 0, 0}, + {"serve_stale 1h verify 100ms -1s", true, 0, false, 0, 0}, + {"serve_stale 1h verify 100ms garbage", true, 0, false, 0, 0}, + {"serve_stale 1h verify 100ms 30s extra", true, 0, false, 0, 0}, } for i, test := range tests { c := caddy.NewTestController("dns", fmt.Sprintf("cache {\n%s\n}", test.input)) @@ -167,6 +182,47 @@ func TestServeStale(t *testing.T) { if ca.verifyStaleTimeout != test.verifyStaleTimeout { t.Errorf("Test %v: Expected verifyStaleTimeout %v but found: %v", i, test.verifyStaleTimeout, ca.verifyStaleTimeout) } + if ca.staleTTL != test.staleTTL { + t.Errorf("Test %v: Expected staleTTL %v but found: %v", i, test.staleTTL, ca.staleTTL) + } + } +} + +func TestServeStaleFailureRecheck(t *testing.T) { + tests := []struct { + input string + wantRecheck time.Duration + shouldErr bool + }{ + {input: "serve_stale 1h immediate 30s 30s", wantRecheck: 30 * time.Second}, + {input: "serve_stale 1h immediate 0 0"}, + {input: "serve_stale 1h verify 100ms 30s 250ms", wantRecheck: 250 * time.Millisecond}, + {input: "serve_stale 1h verify 0 0 5m", wantRecheck: 5 * time.Minute}, + {input: "serve_stale 1h immediate 30s -1s", shouldErr: true}, + {input: "serve_stale 1h immediate 30s 5m1s", shouldErr: true}, + {input: "serve_stale 1h immediate 30s invalid", shouldErr: true}, + {input: "serve_stale 1h immediate 30s 30s extra", shouldErr: true}, + {input: "serve_stale 1h verify 100ms 30s -1s", shouldErr: true}, + {input: "serve_stale 1h verify 100ms 30s 30s extra", shouldErr: true}, + } + + for _, test := range tests { + t.Run(test.input, func(t *testing.T) { + controller := caddy.NewTestController("dns", fmt.Sprintf("cache {\n%s\n}", test.input)) + ca, err := cacheParse(controller) + if test.shouldErr { + if err == nil { + t.Fatal("expected an error") + } + return + } + if err != nil { + t.Fatalf("unexpected error: %v", err) + } + if ca.staleRecheck != test.wantRecheck { + t.Fatalf("expected failure recheck %v, got %v", test.wantRecheck, ca.staleRecheck) + } + }) } }