Files
matsandClaude Sonnet 5.5 c6c5ca4ff7 Make the resolver pure DNS: JSON access log on stdout instead of a log store
The resolver kept its own query-log store (a bbolt ring, a live ring with SSE
fanout, rolling per-domain counters and dashboard time-series) for the console.
In a multi-node deployment each pod held a different slice of that, so every
view disagreed with itself, and the cost sat on the query path. Charts belong
in Grafana and log search in the log collector, so the store is gone.

internal/accesslog writes one JSON line per notable query to stdout. The default
is what was blocked and what failed (blocked, redirected, SERVFAIL, dropped,
refused); log_cached and sample_rate add ordinary answers for a debugging
session. Lines go through a bounded buffer to a single writer goroutine and are
dropped, and counted in fancydns_access_log_dropped_total, when the stream
cannot keep up, so a stalled log pipe can never stall a query. The config key is
access_log (the old qlog block is ignored, like any unknown key).

The metrics gain what the dashboard used to compute: fancydns_group_queries_total
by ACL group and outcome and fancydns_responses_total by RCODE. Removed with the
store: /api/dashboard, /api/logs, /api/logs/stream, /api/logs/clear,
/api/cache/top, the series rings, and the cache's per-name hit table, which took
a mutex and built a string on every cache hit.

Tests that read the old log now read the access-log lines; the contract test
drops the removed endpoints. The web console still calls them and is changed in
the next commit.

Co-Authored-By: Claude Sonnet 5.5 <noreply@anthropic.com>
2026-10-16 09:53:04 +02:00

177 lines
7.1 KiB
Go

package engine
import (
"encoding/hex"
"net/http"
"net/http/httptest"
"strconv"
"strings"
"testing"
"git.k8s-git-k6n.net/mats/fancy-dns/internal/accesslog"
"git.k8s-git-k6n.net/mats/fancy-dns/internal/config"
"git.k8s-git-k6n.net/mats/fancy-dns/internal/metrics"
"github.com/miekg/dns"
)
// The tests in this file PIN behaviour we know is wrong or known to be
// incomplete. They are not assertions of intent — they are tripwires, so that
// when the behaviour changes (a library bump, a metrics change) the suite says
// so out loud instead of the drift reaching the dashboards or the clients.
// Each one names in its failure message what to do when it goes off.
// outcomeCount sums the _count of fancydns_query_duration_seconds over every
// transport for one outcome label. Zero is a legitimate answer: a histogram
// with no observations publishes no series at all.
func outcomeCount(t *testing.T, outcome string) uint64 {
t.Helper()
rec := httptest.NewRecorder()
metrics.Handler().ServeHTTP(rec, httptest.NewRequest(http.MethodGet, "/metrics", nil))
prefix := metrics.Namespace + "_query_duration_seconds_count{"
want := `outcome="` + outcome + `"`
var total uint64
for _, line := range strings.Split(rec.Body.String(), "\n") {
if !strings.HasPrefix(line, prefix) || !strings.Contains(line, want) {
continue
}
fields := strings.Fields(line)
n, err := strconv.ParseUint(fields[len(fields)-1], 10, 64)
if err != nil {
t.Fatalf("unparseable exposition line %q: %v", line, err)
}
total += n
}
return total
}
// TestPinnedLocalAnswersAreCountedAsUpstream pins the gap STATUS.md called
// "metrics.OutcomeLocal has no producer": a query answered from the local
// zone reports accesslog.ActionAllow, and outcomeFor maps ActionAllow to
// OutcomeUpstream, so every locally answered query was counted as an upstream
// one. The outcome="local" series was therefore never published and the
// dashboard's local column was permanently empty.
//
// DECIDED (round with the console contract): the producer now exists.
// Response.Local is set on the local-zone path and outcomeFor consults it, so
// a local answer is counted as outcome="local" and is NOT counted as upstream.
// This moved published counters, which is why it was a decision and not a
// silent fix. TestLocallyAnsweredQueryIsCountedAsLocal replaces this pin; the
// dashboards and STATUS.md were updated in the same change.
func TestLocallyAnsweredQueryIsCountedAsLocal(t *testing.T) {
h := newHarness(t, hopt{localZone: testZone})
upBefore := outcomeCount(t, metrics.OutcomeUpstream)
localBefore := outcomeCount(t, metrics.OutcomeLocal)
res := h.ask("host.local.", dns.TypeA)
requireAction(t, res, accesslog.ActionAllow)
if got := answerA(res.Msg); got != "192.168.1.5" {
t.Fatalf("answer = %q, want the local zone's 192.168.1.5", got)
}
requireNoUpstreamHit(t, h, "host.local.")
if !res.Local {
t.Error("Response.Local is false for a locally answered query, so the " +
"outcome would be counted as upstream again")
}
if got := outcomeCount(t, metrics.OutcomeLocal) - localBefore; got != 1 {
t.Errorf("a locally answered query moved the local outcome by %d, want 1", got)
}
if got := outcomeCount(t, metrics.OutcomeUpstream) - upBefore; got != 0 {
t.Errorf("a locally answered query moved the upstream outcome by %d, want 0: "+
"it never reached an upstream", got)
}
}
// TestPinnedEDNS0NSIDIsHex pins a contract of the pinned miekg/dns version
// (v1.1.73) that is easy to get wrong and fails silently: EDNS0_NSID.Nsid is
// a HEX STRING, not the opaque bytes RFC 5001 describes. pack() hex-decodes
// it and unpack() hex-encodes it, so:
//
// - a hex string packs, and the bytes on the wire are the decoded value;
// - a plain string such as "fancy-dns" does NOT pack — hex.DecodeString
// rejects the '-' — and the caller gets an error instead of a message.
//
// This is the trap behind the SERVFAIL bug: the engine used to put the literal
// "fancy-dns" in the option, so every query from a client that asked for NSID
// failed to build. If a future miekg/dns changes Nsid to raw bytes, this pin
// fails and the hex.EncodeToString in prepareUpstream has to go with it.
func TestPinnedEDNS0NSIDIsHex(t *testing.T) {
pack := func(nsid string) error {
m := new(dns.Msg)
m.SetQuestion("nsid.example.test.", dns.TypeA)
m.SetEdns0(1232, false)
m.IsEdns0().Option = append(m.IsEdns0().Option, &dns.EDNS0_NSID{Nsid: nsid})
_, err := m.Pack()
return err
}
if err := pack(hex.EncodeToString([]byte(upstreamNSID))); err != nil {
t.Fatalf("a hex-encoded NSID must pack: %v", err)
}
if err := pack(upstreamNSID); err == nil {
t.Fatalf("%q packed as an NSID; dns.EDNS0_NSID.Nsid is no longer hex-encoded, "+
"so drop the hex.EncodeToString in prepareUpstream and update this pin", upstreamNSID)
}
}
// TestClientNSIDIsAnswered pins the user-visible half of that fix: a client
// that asks for NSID gets a real answer, whatever the size of its NSID, and
// the option we forward upstream is our own identifier rather than the
// client's. With dns.hide_identity the option is dropped entirely, which is
// the whole point of the setting.
func TestClientNSIDIsAnswered(t *testing.T) {
t.Run("short NSID", func(t *testing.T) {
h := newHarness(t, hopt{})
req := h.request("nsid.example.test.", dns.TypeA)
req.Msg.SetEdns0(1232, false)
req.Msg.IsEdns0().Option = append(req.Msg.IsEdns0().Option,
&dns.EDNS0_NSID{Nsid: "abc"})
res := h.askWith(req)
requireRcode(t, res, dns.RcodeSuccess)
got := h.up.received()
if len(got) != 1 {
t.Fatalf("upstream saw %d queries, want 1", len(got))
}
opt, ok := findOption(got[0], dns.EDNS0NSID).(*dns.EDNS0_NSID)
if !ok {
t.Fatal("the forwarded query carries no NSID; we do not advertise ourselves upstream")
}
raw, err := hex.DecodeString(opt.Nsid)
if err != nil {
t.Fatalf("forwarded NSID %q is not hex: %v", opt.Nsid, err)
}
if string(raw) != upstreamNSID {
t.Fatalf("forwarded NSID = %q, want our own %q (we forwarded the client's)",
raw, upstreamNSID)
}
})
t.Run("NSID larger than 255 bytes", func(t *testing.T) {
// A character-string over 255 bytes does not pack for TXT, but NSID
// is hex-decoded into a byte slice, so a long NSID is fine here.
// Pinning it keeps the distinction between the two documented.
h := newHarness(t, hopt{})
req := h.request("big-nsid.example.test.", dns.TypeA)
req.Msg.SetEdns0(1232, false)
req.Msg.IsEdns0().Option = append(req.Msg.IsEdns0().Option,
&dns.EDNS0_NSID{Nsid: hex.EncodeToString([]byte(strings.Repeat("a", 300)))})
requireRcode(t, h.askWith(req), dns.RcodeSuccess)
})
t.Run("hide_identity drops the option", func(t *testing.T) {
h := newHarness(t, hopt{
dnsCfg: func(d *config.DNS) { d.HideIdentity = true },
})
req := h.request("hidden-nsid.example.test.", dns.TypeA)
req.Msg.SetEdns0(1232, false)
req.Msg.IsEdns0().Option = append(req.Msg.IsEdns0().Option,
&dns.EDNS0_NSID{Nsid: "abc"})
requireRcode(t, h.askWith(req), dns.RcodeSuccess)
if opt := findOption(h.up.received()[0], dns.EDNS0NSID); opt != nil {
t.Fatal("dns.hide_identity is set but the query still advertises an NSID")
}
})
}