Keep list copies on disk, start from them, and stop logging address overrides

Found by rolling the resolver out to the real cluster.

BlockList objects have no path, deliberately, so the first rollout downloaded
the list at every start. The cluster DNS that the download needs is this very
resolver, which was not up yet, so the first compile failed after 14 seconds,
held the DNS listeners closed for that long, and left the pod with no ad
blocking at all. Three changes:

* Lists from cluster objects get a copy under the runtime's own data directory
  (data/lists/<name>), chosen by the runtime from the object's name, never by the
  object.
* The copy is used as the answer only while it is younger than the list's
  refresh interval, and otherwise the list is downloaded again, with the old copy
  as the fallback if that fails. Before, any copy on disk was treated as current
  for ever, so a list with a path was frozen at its first download. A source now
  ages from its file, an operator's "refresh now" forces a download, and a
  failed download keeps the stale copy.
* Startup loads only what is on disk (RefreshOffline), opens the listeners, and
  fetches stale or missing lists in the background. The resolver answers at once
  and the network is never on its critical path.

An address override answered as a redirect and so counted as a policy action:
with the access log logging redirects, every lookup of an internal name wrote a
line. Overrides from the managed source are local answers now; a redirect a list
imposes is still logged.

Co-Authored-By: Claude Sonnet 5.5 <noreply@anthropic.com>

internal/app/app.go

@@ -314,11 +314,19 @@ func (a *App) startBlocklist() {
 	if snap := a.kubeSnap.Load(); snap != nil {
 		a.blocks.SetManagedRPZ(kubesource.RenderRPZ(snap.Overrides))
 	}
-	// Compile once before serving so the first queries are not unprotected.
-	if _, err := a.blocks.RefreshAll(context.Background()); err != nil {
-		a.markDegraded("blocklist: " + err.Error())
-		a.log.Warn("initial blocklist compile failed", "error", err)
+	// Compile once before serving, from what is on disk, so the first queries
+	// are not unprotected and the listeners do not wait for the network. Lists
+	// that are stale or have never been downloaded are then fetched in the
+	// background and swapped in when they arrive.
+	if st, err := a.blocks.RefreshOffline(context.Background()); err != nil || len(st.Errors) > 0 {
+		a.log.Info("some blocklists are not on disk yet; fetching them in the background", "lists", len(st.Errors), "error", err)
 	}
+	go func() {
+		if _, err := a.blocks.RefreshAll(context.Background()); err != nil {
+			a.markDegraded("blocklist: " + err.Error())
+			a.log.Warn("blocklist download failed", "error", err)
+		}
+	}()
 }
 
 // startLocalZones compiles the local master files.

internal/app/hooks.go

@@ -240,14 +240,14 @@ func (a *App) refreshBlocklists(ctx context.Context, names []string) error {
 	a.invalidateBlocklistCache()
 	go func() {
 		if len(names) == 0 {
-			if _, err := a.blocks.RefreshAll(ctx); err != nil {
+			if _, err := a.blocks.ForceRefresh(ctx); err != nil {
 				a.log.Warn("blocklist refresh failed", "error", err)
 			}
 			return
 		}
 		// The manager compiles everything in one pass, which is cheaper than
 		// a pass per name and keeps the compiled set internally consistent.
-		if _, err := a.blocks.RefreshAll(ctx); err != nil {
+		if _, err := a.blocks.ForceRefresh(ctx); err != nil {
 			a.log.Warn("blocklist refresh failed", "error", err, "names", names)
 		}
 	}()

internal/blocklist/manager.go

@@ -60,6 +60,10 @@ type Manager struct {
 	running    map[string]bool // in-flight refreshes, by source name
 	managedMu  sync.RWMutex
 	managedRPZ string
+	// forceFetch makes loadOne download even a fresh on-disk copy.
+	forceFetch atomic.Bool
+	// offline makes loadOne use only what is on disk.
+	offline atomic.Bool
 
 	// trigger lets the cluster ask one instance to refresh (leader election).
 	trigger chan string
@@ -135,6 +139,30 @@ func (m *Manager) SetManagedRPZ(content string) {
 	m.managedMu.Unlock()
 }
 
+// errNotOnDisk is why an offline pass skips a list that has never been downloaded.
+var errNotOnDisk = errors.New("not downloaded yet")
+
+// RefreshOffline is RefreshAll that never touches the network: lists load from
+// their copy on disk, however old, and a list with no copy is skipped. It is
+// for starting up. The resolver can then answer at once, instead of holding its
+// listeners closed while a download finishes (or times out, when the network
+// is the cluster DNS that this very resolver provides), and a following
+// RefreshAll brings stale or missing lists up to date.
+func (m *Manager) RefreshOffline(ctx context.Context) (State, error) {
+	m.offline.Store(true)
+	defer m.offline.Store(false)
+	return m.RefreshAll(ctx)
+}
+
+// ForceRefresh is RefreshAll that downloads every list again, even one whose
+// copy on disk is still within its refresh interval. It is what an operator's
+// "refresh now" means.
+func (m *Manager) ForceRefresh(ctx context.Context) (State, error) {
+	m.forceFetch.Store(true)
+	defer m.forceFetch.Store(false)
+	return m.RefreshAll(ctx)
+}
+
 // RefreshAll compiles every enabled source plus the local zones. The previous
 // set is kept if every source fails, so a bad deploy never leaves the
 // resolver with no blocklists at all.
@@ -334,16 +362,31 @@ func (m *Manager) loadOne(ctx context.Context, cfg *config.Config, l config.List
 		httpStatus int
 	)
 
+	// The copy on disk is what a restart without network sees, and what stands
+	// in when a fetch fails. It is used as the answer, with no fetch at all,
+	// only while it is younger than the list's refresh interval (a list with
+	// no interval is refreshed by hand, so any copy will do) and nobody asked
+	// for a fresh download. Past that the list is fetched again: treating any
+	// copy as current froze a list at its first download for good.
 	needFetch := true
+	loadedAt := start
 	if path != "" {
-		// Prefer the local copy: it is what a restart without network sees.
-		if fi, err := os.Stat(path); err == nil {
-			if fi.Size() < l.MaxBytes {
-				data, _ = os.ReadFile(path)
+		if fi, err := os.Stat(path); err == nil && fi.Size() < l.MaxBytes {
+			data, _ = os.ReadFile(path)
+			fresh := l.Refresh <= 0 || time.Since(fi.ModTime()) < l.Refresh.D()
+			// Offline, any copy will do: the point is to serve now and let a
+			// later pass bring it up to date.
+			if m.offline.Load() || (fresh && !m.forceFetch.Load()) {
 				needFetch = false
+				// Age the source from its file, so the scheduled refresh
+				// falls due when the copy does, not a full interval later.
+				loadedAt = fi.ModTime()
 			}
 		}
 	}
+	if m.offline.Load() && len(data) == 0 {
+		return rawSource{}, errNotOnDisk
+	}
 	if l.URL != "" && needFetch {
 		fetched, status, newETag, newLM, err := m.fetch(ctx, l)
 		if err != nil {
@@ -393,7 +436,7 @@ func (m *Manager) loadOne(ctx context.Context, cfg *config.Config, l config.List
 		Bytes:      int64(len(data)),
 		ETag:       etag,
 		LastMod:    lastMod,
-		UpdatedAt:  start,
+		UpdatedAt:  loadedAt,
 		Duration:   config.Duration(time.Since(start)),
 		Enabled:    true,
 		URL:        l.URL,

internal/blocklist/manager_fetch_test.go

@@ -0,0 +1,209 @@
+package blocklist
+
+import (
+	"context"
+	"fmt"
+	"log/slog"
+	"net/http"
+	"net/http/httptest"
+	"os"
+	"path/filepath"
+	"sync/atomic"
+	"testing"
+	"time"
+
+	"git.k8s-git-k6n.net/mats/fancy-dns/internal/config"
+)
+
+type listFixture struct {
+	t      *testing.T
+	srv    *httptest.Server
+	hits   atomic.Int32
+	fail   atomic.Bool
+	body   atomic.Value // string
+	path   string
+	mgr    *Manager
+	cfgSrc *config.Store
+}
+
+func newListFixture(t *testing.T, refresh time.Duration) *listFixture {
+	t.Helper()
+	f := &listFixture{t: t, path: filepath.Join(t.TempDir(), "lists", "ads")}
+	f.body.Store("0.0.0.0 first.example\n")
+	f.srv = httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		f.hits.Add(1)
+		if f.fail.Load() {
+			http.Error(w, "down", http.StatusServiceUnavailable)
+			return
+		}
+		fmt.Fprint(w, f.body.Load().(string))
+	}))
+	t.Cleanup(f.srv.Close)
+
+	cfg := config.Default()
+	cfg.Block.Enabled = true
+	cfg.Block.Lists = []config.ListSource{{
+		Name: "ads", Format: "hosts", URL: f.srv.URL, Path: f.path, Enabled: true,
+		Refresh: config.Duration(refresh), MaxBytes: 1 << 20, Timeout: config.Duration(2 * time.Second),
+	}}
+	f.cfgSrc = config.NewStore(cfg, "")
+	f.mgr = NewManager(ManagerOptions{Config: f.cfgSrc, Logger: slog.New(slog.NewTextHandler(os.Stderr, &slog.HandlerOptions{Level: slog.LevelError}))})
+	return f
+}
+
+func (f *listFixture) blocks(name string) bool {
+	set := f.mgr.Holder().Get()
+	return set != nil && set.Match(name) != nil
+}
+
+func (f *listFixture) age(d time.Duration) {
+	f.t.Helper()
+	old := time.Now().Add(-d)
+	if err := os.Chtimes(f.path, old, old); err != nil {
+		f.t.Fatal(err)
+	}
+}
+
+// A restart should come up with the list from disk, not wait for the network:
+// the network may be this resolver's own cluster DNS, which is not up yet.
+func TestFreshCopyStartsWithoutTheNetwork(t *testing.T) {
+	f := newListFixture(t, 24*time.Hour)
+	if _, err := f.mgr.RefreshAll(context.Background()); err != nil { // first start: downloads and keeps a copy
+		t.Fatal(err)
+	}
+	if f.hits.Load() != 1 || !f.blocks("first.example") {
+		t.Fatalf("setup: hits=%d", f.hits.Load())
+	}
+	f.fail.Store(true)
+	again := NewManager(ManagerOptions{Config: f.cfgSrc, Logger: slog.Default()})
+	if _, err := again.RefreshAll(context.Background()); err != nil {
+		t.Fatal(err)
+	}
+	if f.hits.Load() != 1 {
+		t.Errorf("a fresh copy still went to the network (%d requests)", f.hits.Load())
+	}
+	if set := again.Holder().Get(); set == nil || set.Match("first.example") == nil {
+		t.Error("the restarted manager did not load the copy from disk")
+	}
+}
+
+// A copy past its refresh interval must be replaced; treating any copy as
+// current froze a list at its first download for good.
+func TestStaleCopyIsDownloadedAgain(t *testing.T) {
+	f := newListFixture(t, time.Hour)
+	if _, err := f.mgr.RefreshAll(context.Background()); err != nil {
+		t.Fatal(err)
+	}
+	f.body.Store("0.0.0.0 second.example\n")
+	f.age(2 * time.Hour)
+	if _, err := f.mgr.RefreshAll(context.Background()); err != nil {
+		t.Fatal(err)
+	}
+	if f.hits.Load() != 2 || !f.blocks("second.example") || f.blocks("first.example") {
+		t.Errorf("hits=%d second=%v first=%v: the stale copy was not replaced", f.hits.Load(), f.blocks("second.example"), f.blocks("first.example"))
+	}
+	if b, _ := os.ReadFile(f.path); string(b) != "0.0.0.0 second.example\n" {
+		t.Errorf("the copy on disk was not updated: %q", b)
+	}
+}
+
+// And when the download fails, the stale copy still stands in: a stale list
+// beats no list.
+func TestStaleCopyStandsInWhenTheDownloadFails(t *testing.T) {
+	f := newListFixture(t, time.Hour)
+	if _, err := f.mgr.RefreshAll(context.Background()); err != nil {
+		t.Fatal(err)
+	}
+	f.age(2 * time.Hour)
+	f.fail.Store(true)
+	again := NewManager(ManagerOptions{Config: f.cfgSrc, Logger: slog.Default()})
+	if _, err := again.RefreshAll(context.Background()); err != nil {
+		t.Fatalf("refresh with a stale copy and a dead server: %v", err)
+	}
+	if set := again.Holder().Get(); set == nil || set.Match("first.example") == nil {
+		t.Error("the stale copy was not used")
+	}
+}
+
+func TestForceRefreshDownloadsAFreshCopy(t *testing.T) {
+	f := newListFixture(t, 24*time.Hour)
+	if _, err := f.mgr.RefreshAll(context.Background()); err != nil {
+		t.Fatal(err)
+	}
+	f.body.Store("0.0.0.0 second.example\n")
+	if _, err := f.mgr.RefreshAll(context.Background()); err != nil || f.hits.Load() != 1 {
+		t.Fatalf("a plain refresh of a fresh copy should not download: hits=%d err=%v", f.hits.Load(), err)
+	}
+	if _, err := f.mgr.ForceRefresh(context.Background()); err != nil {
+		t.Fatal(err)
+	}
+	if f.hits.Load() != 2 || !f.blocks("second.example") {
+		t.Errorf("a forced refresh did not download: hits=%d", f.hits.Load())
+	}
+}
+
+func TestNoCopyAndNoNetworkIsAnError(t *testing.T) {
+	f := newListFixture(t, time.Hour)
+	f.fail.Store(true)
+	if _, err := f.mgr.RefreshAll(context.Background()); err == nil && f.blocks("first.example") {
+		t.Fatal("blocked a name with no list data")
+	}
+}
+
+// The source ages from its file, so the scheduled refresh is due when the copy
+// is, not a whole interval after a restart.
+func TestSourceAgeFollowsTheCopy(t *testing.T) {
+	f := newListFixture(t, 10*time.Hour)
+	if _, err := f.mgr.RefreshAll(context.Background()); err != nil {
+		t.Fatal(err)
+	}
+	f.age(9 * time.Hour)
+	again := NewManager(ManagerOptions{Config: f.cfgSrc, Logger: slog.Default()})
+	if _, err := again.RefreshAll(context.Background()); err != nil {
+		t.Fatal(err)
+	}
+	src, ok := again.previous("ads")
+	if !ok {
+		t.Fatal("no source")
+	}
+	if age := time.Since(src.Meta.UpdatedAt); age < 8*time.Hour || age > 10*time.Hour {
+		t.Errorf("source age = %v, want about 9h (the copy's)", age)
+	}
+}
+
+// Startup must not wait for the network: the offline pass serves what is on
+// disk, however old, and skips what was never downloaded; a normal pass then
+// updates it.
+func TestOfflinePassNeverTouchesTheNetwork(t *testing.T) {
+	f := newListFixture(t, time.Hour)
+	st, _ := f.mgr.RefreshOffline(context.Background())
+	if st.Errors["ads"] == "" {
+		t.Errorf("a list with no copy should be reported as not downloaded yet: %+v", st.Errors)
+	}
+	if f.hits.Load() != 0 || f.blocks("first.example") {
+		t.Fatalf("hits=%d: an offline pass reached for the network", f.hits.Load())
+	}
+
+	if _, err := f.mgr.RefreshAll(context.Background()); err != nil { // the background pass
+		t.Fatal(err)
+	}
+	f.body.Store("0.0.0.0 second.example\n")
+	f.age(5 * time.Hour) // stale
+	again := NewManager(ManagerOptions{Config: f.cfgSrc, Logger: slog.Default()})
+	if _, err := again.RefreshOffline(context.Background()); err != nil {
+		t.Fatal(err)
+	}
+	if f.hits.Load() != 1 {
+		t.Errorf("hits=%d: the offline pass downloaded a stale copy", f.hits.Load())
+	}
+	if set := again.Holder().Get(); set == nil || set.Match("first.example") == nil {
+		t.Error("the stale copy was not served while offline")
+	}
+	// ...and the pass that follows brings it up to date.
+	if _, err := again.RefreshAll(context.Background()); err != nil {
+		t.Fatal(err)
+	}
+	if f.hits.Load() != 2 || again.Holder().Get().Match("second.example") == nil {
+		t.Errorf("hits=%d: the follow-up pass did not refresh the stale copy", f.hits.Load())
+	}
+}

internal/engine/blockttl_test.go

@@ -6,6 +6,7 @@ import (
 
 	"github.com/miekg/dns"
 
+	"git.k8s-git-k6n.net/mats/fancy-dns/internal/accesslog"
 	"git.k8s-git-k6n.net/mats/fancy-dns/internal/blocklist"
 	"git.k8s-git-k6n.net/mats/fancy-dns/internal/config"
 )
@@ -74,3 +75,26 @@ func TestTTLSecondsClamps(t *testing.T) {
 		}
 	}
 }
+
+// An address override is the answer the operator wants for a name, not a policy
+// action. With the access log logging redirects by default, logging each one
+// would fill it with every lookup of an internal name.
+func TestAddressOverridesAreLocalAnswersNotLoggedRedirects(t *testing.T) {
+	h := newHarness(t, hopt{})
+	b := blocklist.NewBuilder()
+	b.Add(blocklist.Rule{Name: "**.pinned.test", Action: blocklist.ActionRedirect, Response: "10.9.9.9"}, "managed:address-overrides", nil)
+	b.Add(blocklist.Rule{Name: "**.sinkholed.test", Action: blocklist.ActionRedirect, Response: "10.8.8.8"}, "somelist", nil)
+	h.blocks.Set(b.Build())
+
+	res := h.ask("www.pinned.test.", dns.TypeA)
+	if res.Action != accesslog.ActionAllow || !res.Local {
+		t.Errorf("override: action=%q local=%v, want allow/local", res.Action, res.Local)
+	}
+	if len(res.Msg.Answer) != 1 {
+		t.Errorf("override answer = %v", res.Msg.Answer)
+	}
+	// A redirect that a list imposes is still a policy action.
+	if res := h.ask("www.sinkholed.test.", dns.TypeA); res.Action != accesslog.ActionRedirect {
+		t.Errorf("list redirect: action=%q, want redirect", res.Action)
+	}
+}

internal/engine/engine.go

@@ -386,6 +386,14 @@ func (e *Engine) Handle(ctx context.Context, req Request) Response {
 			res.Action = accesslog.ActionRedirect
 			res.BlockSource = blocked.Source
 			res.CacheHit = false
+			if strings.HasPrefix(blocked.Source, "managed:") {
+				// An address override is the answer the operator wants for that
+				// name (split-horizon DNS), not a policy action: it is local
+				// data, and logging every query for it would make the
+				// access log mostly noise.
+				res.Action = accesslog.ActionAllow
+				res.Local = true
+			}
 			e.finish(req, res, start, decision)
 			return res
 		default:

internal/kubesource/listpath_test.go

@@ -0,0 +1,30 @@
+package kubesource
+
+import (
+	"path/filepath"
+	"testing"
+
+	"git.k8s-git-k6n.net/mats/fancy-dns/internal/config"
+)
+
+// A BlockList cannot name a file, so the runtime keeps each list's copy under
+// its own data directory. The name comes from the object, so it must never be
+// able to leave that directory.
+func TestClusterListsGetAPathUnderTheDataDirectory(t *testing.T) {
+	base := config.Default()
+	base.Cache.Persist.Path = "/var/lib/fancy-dns/cache.db"
+	merged, _ := Merge(base, &Snapshot{Lists: []config.ListSource{
+		{Name: "haas", URL: "https://a/x", Enabled: true},
+		{Name: "../escape", URL: "https://a/y", Enabled: true},
+	}})
+	got := map[string]string{}
+	for _, l := range merged.Block.Lists {
+		got[l.Name] = l.Path
+	}
+	if want := filepath.Join("/var/lib/fancy-dns", "lists", "haas"); got["haas"] != want {
+		t.Errorf("path = %q, want %q", got["haas"], want)
+	}
+	if got["../escape"] != "" {
+		t.Errorf("a name that is not a plain file name got the path %q", got["../escape"])
+	}
+}

internal/kubesource/merge.go

@@ -66,6 +66,14 @@ func Merge(base *config.Config, snap *Snapshot) (*config.Config, []string) {
 			dropped = append(dropped, "BlockList "+l.Name+" (name used in the YAML)")
 			continue
 		}
+		// A cluster object cannot name a file, so the runtime picks one: a copy
+		// of the list under its own data directory. It is what lets a restart
+		// start with the list when the network (or the cluster DNS, which may
+		// be this very resolver) is not up yet.
+		if filepath.Base(l.Name) == l.Name && l.Name != "." && l.Name != ".." {
+			l.Path = filepath.Join("lists", l.Name)
+			l.Path = filepath.Join(filepath.Dir(base.CachePath()), l.Path)
+		}
 		// The same defaults config.applyDefaults gives a YAML list.
 		if l.Format == "" {
 			l.Format = "auto"