diff --git a/AGENTS.md b/AGENTS.md index 23202b6..9767084 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -11,7 +11,7 @@ the hard way. A recursive DNS server in Go with an embedded React console. Config is YAML plus RFC 1035 master files, hot-reloaded over SIGHUP. Blocklists in four formats, a sharded LRU cache with a bbolt snapshot for warm restart, per-client ACLs, -query logging, Prometheus metrics, and optional Valkey/Redis for cross-instance +an access log on stdout, Prometheus metrics, and optional Valkey/Redis for cross-instance sync. ## Layout @@ -29,7 +29,7 @@ internal/ localzone/ authoritative data from master files, wildcards, delegations engine/ THE QUERY PIPELINE, reverse-PTR cache server/ UDP, TCP, DoT, DoH listeners; all funnel into one handler - qlog/ bbolt query-log ring + live in-memory ring + SSE fanout + accesslog/ async JSON-lines access log to stdout (blocked/errors by default) metrics/ Prometheus collectors + rolling time-series rings cluster/ Valkey pub/sub, leader lease, divergence detection kubeedit/ the console's writes to ClientGroup/BlockList/DNSZone objects @@ -48,7 +48,7 @@ deploy/ example config, example zones, k8s manifests ``` validate → ACL deny → per-client concurrency → global concurrency → rate limit → group allow/deny domains → local zone → blocklist → cache → upstream - → cache put → finalize (EDNS0, UDP truncation) → metrics + qlog + → cache put → finalize (EDNS0, UDP truncation) → metrics + access log ``` Cache is a single shard-local lookup; only a miss touches the network. @@ -57,11 +57,12 @@ Cache is a single shard-local lookup; only a miss touches the network. | Decision | Choice | Why | |---|---|---| -| Scope | Full production | clustering, metrics, ACLs, query logs, hot reload, Docker, k8s, CI | +| Scope | Full production | clustering, metrics, ACLs, access log, hot reload, Docker, k8s, CI | | Config store | YAML + DNS master files | reviewable/diffable in git | | Console-written zone data | Its own directory, `blocklist.managed_zones`, one file per apex | the console is a real operator surface, so it needs somewhere to write; a separate directory keeps the operator's master files read-only to it, and an unset key keeps the console read-only by default | | Cluster sync | Valkey (Redis protocol) | simple, mature Go client, easy local dev | | Secure DNS | DoT + DoH, **no DNSSEC validation** | deliberately out of scope; AD/CD/extended-RCODE are passed through only | +| Observability | Prometheus metrics + a JSON access log on stdout; **no in-app dashboard, log store or live tail** | the resolver is DNS only. Charts belong in Grafana, search in the log collector, and per-pod state in a multi-node deployment only disagrees with itself. The access log is blocked/errors by default, goes through a bounded buffer that drops (and counts) rather than ever blocking a query, and nothing may be added to the query path to feed a UI | | Hot cache | Sharded LRU in memory, bbolt for snapshots | no I/O on the hot path; warm restart | | k8s networking | **No hostNetwork**, LoadBalancer Service | the server never sets SO_REUSEPORT, so two host-network pods cannot share :53 | | Memory | Soft GOMEMLIMIT + cache byte budget | a cgroup kill is an outage; a cache miss is not | @@ -137,8 +138,8 @@ Break these and you break the design, not just the test. The internal `*.` / `**.` prefixes must not leak into the UI, but the API needs them to re-add a rule unchanged. - **The Go heap does not account for goroutine stacks, runtime metadata, or the - bbolt mmap.** `memory.reserve` exists to cover them; the cache snapshot and - query log are mmapped and live outside the heap entirely. + bbolt mmap.** `memory.reserve` exists to cover them; the cache snapshot is + mmapped and lives outside the heap entirely. - **The zone writer proves its own output.** Every record is validated by the project's own master-file parser, the file is rendered, and the rendering is re-parsed and compared with the records it meant to write *before* the file diff --git a/deploy/config.example.yaml b/deploy/config.example.yaml index cfaf074..c589b89 100644 --- a/deploy/config.example.yaml +++ b/deploy/config.example.yaml @@ -161,20 +161,18 @@ acl: cidrs: ["192.168.91.0/24"] policy: deny -qlog: +# One JSON line on stdout per query worth looking at, for whatever collects the +# pod's logs (Loki, a Grafana agent, `kubectl logs`). Nothing is stored here; +# the metrics count everything. The default is blocked queries and failures. +access_log: enabled: true - path: data/queries.db - max_entries: 200000 - flush_interval: 1s - # 1.0 logs every query. Lower it on a busy instance: the per-domain - # counters are what the dashboard actually needs. - sample_rate: 1.0 - log_blocked: true - log_cached: false - log_errors: true - live_buffer: 2000 - top_domains: 5000 - top_ttl: 5m + log_blocked: true # blocklist hits and redirects + log_errors: true # SERVFAIL, drops, ACL refusals + log_cached: false # also cache hits + # Fraction of ordinary answers to log as well: 0 none, 1 all. For a short + # debugging session; leave at 0 otherwise. + sample_rate: 0 + buffer: 4096 # lines that may wait for the log stream before dropping cluster: enabled: false diff --git a/deploy/k8s/00-config.yaml b/deploy/k8s/00-config.yaml index 81e432e..b240e26 100644 --- a/deploy/k8s/00-config.yaml +++ b/deploy/k8s/00-config.yaml @@ -106,13 +106,13 @@ data: default_policy: allow groups: [] - qlog: + # JSON lines on stdout for blocked and failed queries; the metrics cover + # the rest. See deploy/config.example.yaml. + access_log: enabled: true - path: /var/lib/fancy-dns/queries.db - max_entries: 200000 - sample_rate: 1.0 log_blocked: true - log_cached: false + log_errors: true + sample_rate: 0 api: enabled: true diff --git a/deploy/k8s/console/console.yaml b/deploy/k8s/console/console.yaml index 9796b5e..298b861 100644 --- a/deploy/k8s/console/console.yaml +++ b/deploy/k8s/console/console.yaml @@ -82,8 +82,8 @@ spec: command: ["/usr/local/bin/fancy-dns-console"] args: - -config=/etc/fancy-dns/console.yaml - # A Service in front of the resolver pods. With several replicas the - # statistics and query log come from whichever pod answers. + # A Service in front of the resolver pods. With several replicas, the + # per-pod views (status, cache, upstreams) come from whichever pod answers. - -runtime-url=http://fancy-dns-admin.dns.svc:8080 env: - name: FANCYDNS_RUNTIME_KEY diff --git a/internal/accesslog/accesslog.go b/internal/accesslog/accesslog.go new file mode 100644 index 0000000..783d78a --- /dev/null +++ b/internal/accesslog/accesslog.go @@ -0,0 +1,308 @@ +// Package accesslog writes one JSON line per notable DNS query to a stream +// (stdout by default), for whatever collects the pod's logs to index. +// +// It is deliberately not a log store: nothing is kept, searched or aggregated +// here. Counting belongs to the metrics, searching to the log collector. What +// this package guarantees is that logging can never slow or stop a query: +// lines go through a bounded buffer to a single writer goroutine, and when the +// buffer is full (a blocked pipe, a stalled collector) the line is dropped and +// counted rather than waited for. +package accesslog + +import ( + "context" + "io" + "log/slog" + "math/rand/v2" + "os" + "strconv" + "sync" + "sync/atomic" + "time" + + "github.com/miekg/dns" + + "git.k8s-git-k6n.net/mats/fancy-dns/internal/metrics" +) + +// Action is the outcome classification of a query. +type Action string + +const ( + // ActionAllow is a normal resolution. + ActionAllow Action = "allow" + // ActionBlock is a blocklist hit. + ActionBlock Action = "block" + // ActionRedirect is a blocklist rewrite to an address or CNAME target. + ActionRedirect Action = "redirect" + // ActionCached is a cache hit. + ActionCached Action = "cached" + // ActionError is a SERVFAIL or other failure. + ActionError Action = "error" + // ActionDrop is a query answered with silence. + ActionDrop Action = "drop" + // ActionRefused is an ACL refusal. + ActionRefused Action = "refused" +) + +// Entry is one logged query. +type Entry struct { + TS time.Time + Client string + Group string + Name string + QType uint16 + RCode int + Action Action + Duration time.Duration + Upstream string + List string + Protocol string +} + +// FromMsg fills the question-derived fields from a DNS message. +func (e *Entry) FromMsg(m *dns.Msg) { + if len(m.Question) > 0 { + q := m.Question[0] + e.Name = q.Name + e.QType = q.Qtype + } + e.RCode = m.Rcode +} + +// Options configures a Logger. +type Options struct { + // Writer receives the lines; nil means os.Stdout. + Writer io.Writer + // Buffer is how many lines may wait for the writer; beyond that they are + // dropped. Zero means 4096. + Buffer int + // LogBlocked, LogErrors and LogCached select whole categories. Refusals + // and drops count with errors, redirects with blocks. + LogBlocked bool + LogErrors bool + LogCached bool + // SampleRate is the fraction of ordinary answers (allowed, and cached when + // LogCached is off) to log. 0 logs none, 1 logs all. + SampleRate float64 +} + +// Logger is the access log. +type Logger struct { + opt Options + h slog.Handler + w *asyncWriter + written atomic.Uint64 +} + +// New starts a Logger. Close it to flush. +func New(opt Options) *Logger { + if opt.Writer == nil { + opt.Writer = os.Stdout + } + aw := newAsyncWriter(opt.Writer, opt.Buffer) + h := slog.NewJSONHandler(aw, &slog.HandlerOptions{ + Level: slog.LevelInfo, + // The level carries no information here, and a collector would index + // a constant. "log":"access" says which stream the line belongs to. + ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr { + if len(groups) == 0 && a.Key == slog.LevelKey { + return slog.Attr{} + } + return a + }, + }).WithAttrs([]slog.Attr{slog.String("log", "access")}) + return &Logger{opt: opt, h: h, w: aw} +} + +// ShouldLog reports whether a query with this outcome is logged. A nil Logger +// logs nothing. +func (l *Logger) ShouldLog(a Action) bool { + if l == nil { + return false + } + switch a { + case ActionBlock, ActionRedirect: + return l.opt.LogBlocked + case ActionError, ActionDrop, ActionRefused: + return l.opt.LogErrors + case ActionCached: + if l.opt.LogCached { + return true + } + } + switch { + case l.opt.SampleRate >= 1: + return true + case l.opt.SampleRate <= 0: + return false + default: + return rand.Float64() < l.opt.SampleRate + } +} + +// Log writes one line. It never blocks. +func (l *Logger) Log(e Entry) { + if l == nil { + return + } + ts := e.TS + if ts.IsZero() { + ts = time.Now() + } + rec := slog.NewRecord(ts, slog.LevelInfo, "query", 0) + rec.AddAttrs( + slog.String("client", e.Client), + slog.String("client_group", e.Group), + slog.String("name", e.Name), + slog.String("qtype", dns.Type(e.QType).String()), + slog.String("rcode", rcodeName(e.RCode)), + slog.String("action", string(e.Action)), + slog.Float64("duration_ms", float64(e.Duration.Microseconds())/1000), + ) + if e.Upstream != "" { + rec.AddAttrs(slog.String("upstream", e.Upstream)) + } + if e.List != "" { + rec.AddAttrs(slog.String("list", e.List)) + } + if e.Protocol != "" { + rec.AddAttrs(slog.String("protocol", e.Protocol)) + } + _ = l.h.Handle(context.Background(), rec) + l.written.Add(1) +} + +func rcodeName(c int) string { + if s, ok := dns.RcodeToString[c]; ok { + return s + } + return "RCODE" + strconv.Itoa(c) +} + +// Dropped is how many lines were discarded because the writer fell behind. +func (l *Logger) Dropped() uint64 { + if l == nil { + return 0 + } + return l.w.dropped.Load() +} + +// Flush waits for the lines logged so far to be written. +func (l *Logger) Flush() { + if l != nil { + l.w.flush(2 * time.Second) + } +} + +// Close writes what is buffered (for at most two seconds) and stops. +func (l *Logger) Close() error { + if l == nil { + return nil + } + l.w.close() + return nil +} + +// asyncWriter hands each Write to one goroutine through a bounded channel. A +// Write never waits: a full channel drops the line. +type item struct { + b []byte + ack chan struct{} // set on a flush marker: closed when everything before it is written +} + +type asyncWriter struct { + ch chan item + w io.Writer + dropped atomic.Uint64 + closed atomic.Bool + stop chan struct{} + done chan struct{} + once sync.Once +} + +func newAsyncWriter(w io.Writer, buffer int) *asyncWriter { + if buffer <= 0 { + buffer = 4096 + } + a := &asyncWriter{ + ch: make(chan item, buffer), w: w, + stop: make(chan struct{}), done: make(chan struct{}), + } + go a.run() + return a +} + +// Write implements io.Writer for slog's handler, which calls it once per line +// with a buffer it reuses, so the bytes are copied. +func (a *asyncWriter) Write(p []byte) (int, error) { + if a.closed.Load() { + return len(p), nil + } + b := append(make([]byte, 0, len(p)), p...) + select { + case a.ch <- item{b: b}: + default: + a.dropped.Add(1) + metrics.RecordAccessLogDropped() + } + return len(p), nil +} + +func (a *asyncWriter) run() { + defer close(a.done) + for { + select { + case it := <-a.ch: + a.write(it) + case <-a.stop: + for { + select { + case it := <-a.ch: + a.write(it) + default: + return + } + } + } + } +} + +func (a *asyncWriter) write(it item) { + if it.ack != nil { + close(it.ack) + return + } + _, _ = a.w.Write(it.b) +} + +// flush waits until every line accepted before the call has been written, or +// the timeout passes. It is for tests and shutdown, never the query path. +func (a *asyncWriter) flush(timeout time.Duration) { + if a.closed.Load() { + return + } + ack := make(chan struct{}) + t := time.NewTimer(timeout) + defer t.Stop() + select { + case a.ch <- item{ack: ack}: + case <-t.C: + return + } + select { + case <-ack: + case <-t.C: + } +} + +func (a *asyncWriter) close() { + a.once.Do(func() { + a.closed.Store(true) + close(a.stop) + select { + case <-a.done: + case <-time.After(2 * time.Second): + } + }) +} diff --git a/internal/accesslog/accesslog_test.go b/internal/accesslog/accesslog_test.go new file mode 100644 index 0000000..9628d45 --- /dev/null +++ b/internal/accesslog/accesslog_test.go @@ -0,0 +1,132 @@ +package accesslog + +import ( + "bytes" + "encoding/json" + "strings" + "sync" + "testing" + "time" + + "github.com/miekg/dns" +) + +type syncBuf struct { + mu sync.Mutex + b bytes.Buffer +} + +func (s *syncBuf) Write(p []byte) (int, error) { s.mu.Lock(); defer s.mu.Unlock(); return s.b.Write(p) } +func (s *syncBuf) String() string { s.mu.Lock(); defer s.mu.Unlock(); return s.b.String() } + +// TestDefaultPolicyLogsOnlyBlockedAndFailed is the policy the deployment runs +// with: what was blocked or went wrong, never ordinary answers. +func TestDefaultPolicyLogsOnlyBlockedAndFailed(t *testing.T) { + l := New(Options{Writer: &syncBuf{}, LogBlocked: true, LogErrors: true}) + defer l.Close() + for a, want := range map[Action]bool{ + ActionBlock: true, ActionRedirect: true, + ActionError: true, ActionDrop: true, ActionRefused: true, + ActionAllow: false, ActionCached: false, + } { + if got := l.ShouldLog(a); got != want { + t.Errorf("ShouldLog(%s) = %v, want %v", a, got, want) + } + } +} + +func TestSamplingAndCachedOptIn(t *testing.T) { + all := New(Options{Writer: &syncBuf{}, SampleRate: 1}) + defer all.Close() + if !all.ShouldLog(ActionAllow) || !all.ShouldLog(ActionCached) { + t.Error("sample_rate 1 must log ordinary answers") + } + cached := New(Options{Writer: &syncBuf{}, LogCached: true}) + defer cached.Close() + if !cached.ShouldLog(ActionCached) || cached.ShouldLog(ActionAllow) { + t.Error("log_cached must add cache hits and nothing else") + } + var nilLogger *Logger + if nilLogger.ShouldLog(ActionBlock) { + t.Error("a nil logger logs nothing") + } + nilLogger.Log(Entry{}) // must not panic +} + +func TestLineFormat(t *testing.T) { + out := &syncBuf{} + l := New(Options{Writer: out, LogBlocked: true}) + m := new(dns.Msg) + m.SetQuestion("ads.example.com.", dns.TypeAAAA) + m.Rcode = dns.RcodeNameError + e := Entry{ + TS: time.Date(2026, 10, 16, 12, 0, 0, 0, time.UTC), Client: "10.0.0.5", Group: "kids", + Action: ActionBlock, Duration: 1500 * time.Microsecond, List: "stevenblack", Protocol: "udp", + } + e.FromMsg(m) + l.Log(e) + l.Flush() + _ = l.Close() + + lines := strings.Split(strings.TrimSpace(out.String()), "\n") + if len(lines) != 1 { + t.Fatalf("got %d lines: %q", len(lines), out.String()) + } + var got map[string]any + if err := json.Unmarshal([]byte(lines[0]), &got); err != nil { + t.Fatalf("not JSON: %v", err) + } + want := map[string]any{ + "log": "access", "msg": "query", "client": "10.0.0.5", "client_group": "kids", + "name": "ads.example.com.", "qtype": "AAAA", "rcode": "NXDOMAIN", "action": "block", + "duration_ms": 1.5, "list": "stevenblack", "protocol": "udp", + "time": "2026-10-16T12:00:00Z", + } + for k, v := range want { + if got[k] != v { + t.Errorf("%s = %v, want %v", k, got[k], v) + } + } + if _, has := got["level"]; has { + t.Error("a constant level key is noise for a log collector") + } + if _, has := got["upstream"]; has { + t.Error("an empty upstream must be omitted") + } +} + +// stuck is a log pipe nobody is reading. +type stuck struct{ release chan struct{} } + +func (s stuck) Write(p []byte) (int, error) { <-s.release; return len(p), nil } + +// TestLoggingNeverBlocksTheQueryPath: a collector that stops reading must cost +// dropped lines, not stalled queries. +func TestLoggingNeverBlocksTheQueryPath(t *testing.T) { + w := stuck{release: make(chan struct{})} + l := New(Options{Writer: w, Buffer: 8, LogBlocked: true}) + done := make(chan struct{}) + go func() { + defer close(done) + for i := 0; i < 5000; i++ { + l.Log(Entry{Name: "x.test.", Action: ActionBlock}) + } + }() + select { + case <-done: + case <-time.After(5 * time.Second): + t.Fatal("Log blocked on a stalled writer") + } + if l.Dropped() == 0 { + t.Error("nothing was counted as dropped") + } + close(w.release) + _ = l.Close() +} + +func TestWritesAfterCloseAreIgnored(t *testing.T) { + l := New(Options{Writer: &syncBuf{}, LogBlocked: true}) + _ = l.Close() + l.Log(Entry{Name: "late.test.", Action: ActionBlock}) // must not panic or block + _ = l.Close() +} diff --git a/internal/api/api.go b/internal/api/api.go index a90a9f4..a6a8219 100644 --- a/internal/api/api.go +++ b/internal/api/api.go @@ -53,8 +53,6 @@ type Hooks struct { // StartedAt is the process start time. StartedAt time.Time - // Dashboard returns the aggregated dashboard payload. - Dashboard func(ctx context.Context, rangeKey string) (any, error) // BlocklistState returns the compiled blocklist detail. BlocklistState func() any // BlocklistStats returns the compiled rule counts. @@ -107,18 +105,8 @@ type Hooks struct { GetUpstream func() any // PutUpstream validates and persists a new upstream config. PutUpstream func(ctx context.Context, up config.Upstream) (int64, error) - // SearchLog pages the query log. - SearchLog func(ctx context.Context, q LogQuery) (any, error) - // LogStats is the live stats event pushed over SSE. - LogStats func() any - // SubscribeLog streams new log entries; the cancel func must be called. - SubscribeLog func() (<-chan LogEntry, func()) - // ClearLog empties the query log. - ClearLog func() error // CacheStats returns the cache snapshot. CacheStats func() any - // CacheTop returns the hottest cached names. - CacheTop func(limit int) any // FlushCache empties the cache. FlushCache func() int64 // Health returns the health payload for /healthz. @@ -153,44 +141,6 @@ type ZoneFile struct { Content string `json:"content"` } -// LogQuery pages the query log. -type LogQuery struct { - Limit int - Offset int - Text string - Action string - Client string - RCode int - BlockedOnly bool - Since time.Time -} - -// LogEntry is one query-log row as the admin API serves it. -// -// These fields are not omitempty, and that is deliberate: omitempty makes the -// key set depend on the row, so a query with no ACL group arrived without -// `client_group` and the console rendered "undefined" where the column should -// be empty. The contract test in internal/app pins the key set, and it can -// only pin one shape if the server emits one. -type LogEntry struct { - ID uint64 `json:"id"` - TS time.Time `json:"ts"` - Client string `json:"client"` - Group string `json:"client_group"` - Name string `json:"name"` - QType uint16 `json:"qtype"` - QTypeStr string `json:"qtype_name"` - RCode int `json:"rcode"` - RCodeStr string `json:"rcode_name"` - Action string `json:"action"` - Response string `json:"response"` - Duration int64 `json:"duration_ms"` - Upstream string `json:"upstream"` - List string `json:"list"` - Protocol string `json:"protocol"` - Blocked bool `json:"blocked"` -} - // Server is the admin HTTP server. type Server struct { hooks Hooks @@ -284,7 +234,6 @@ func (s *Server) routes(cfg *config.Config) *http.ServeMux { mux.Handle("POST "+base+"auth/logout", s.authed(s.handleLogout, false)) // Everything below requires a principal. - mux.Handle("GET "+base+"dashboard", s.authed(s.handleDashboard, false)) mux.Handle("GET "+base+"status", s.authed(s.handleStatus, false)) mux.Handle("GET "+base+"blocklists", s.authed(s.handleBlocklists, false)) mux.Handle("POST "+base+"blocklists/refresh", s.authed(s.handleBlocklistRefresh, true)) @@ -311,11 +260,7 @@ func (s *Server) routes(cfg *config.Config) *http.ServeMux { mux.Handle("PUT "+base+"clients", s.authed(s.handleClientsPut, true)) mux.Handle("GET "+base+"upstreams", s.authed(s.handleUpstreams, false)) mux.Handle("PUT "+base+"upstreams", s.authed(s.handleUpstreamsPut, true)) - mux.Handle("GET "+base+"logs", s.authed(s.handleLogs, false)) - mux.Handle("GET "+base+"logs/stream", s.authed(s.handleLogStream, false)) - mux.Handle("POST "+base+"logs/clear", s.authed(s.handleLogsClear, true)) mux.Handle("GET "+base+"cache", s.authed(s.handleCache, false)) - mux.Handle("GET "+base+"cache/top", s.authed(s.handleCacheTop, false)) mux.Handle("POST "+base+"cache/flush", s.authed(s.handleCacheFlush, true)) mux.Handle("GET "+base+"settings", s.authed(s.handleSettingsGet, false)) mux.Handle("PUT "+base+"settings", s.authed(s.handleSettingsPut, true)) diff --git a/internal/api/auth_test.go b/internal/api/auth_test.go index 90f028d..dd00390 100644 --- a/internal/api/auth_test.go +++ b/internal/api/auth_test.go @@ -237,7 +237,6 @@ func TestReadOnlyKeyCannotWrite(t *testing.T) { hook string }{ {"cache flush", http.MethodPost, "/api/cache/flush", "", "FlushCache"}, - {"logs clear", http.MethodPost, "/api/logs/clear", "", "ClearLog"}, {"domain add", http.MethodPost, "/api/domains", `{"name":"a.example.com","action":"block"}`, "AddDomain"}, {"domain delete", http.MethodDelete, "/api/domains/a.example.com", "", "DeleteDomain"}, {"blocklist refresh", http.MethodPost, "/api/blocklists/refresh", "", "RefreshBlocklists"}, diff --git a/internal/api/errors_test.go b/internal/api/errors_test.go index 3bd7b3f..7793132 100644 --- a/internal/api/errors_test.go +++ b/internal/api/errors_test.go @@ -37,9 +37,7 @@ func TestHookErrorsAreReported(t *testing.T) { want int }{ // Reads: the component could not produce an answer. - {"dashboard", "Dashboard", http.MethodGet, "/api/dashboard", "", http.StatusInternalServerError}, {"domain list", "ListDomains", http.MethodGet, "/api/domains", "", http.StatusInternalServerError}, - {"log search", "SearchLog", http.MethodGet, "/api/logs", "", http.StatusInternalServerError}, // A domain check that fails still answers, with the reason: 200 here // is the point of the route. {"domain check answers 200 with the error", "DomainCheck", http.MethodGet, "/api/domains/check?name=a.example.com", "", http.StatusOK}, @@ -50,7 +48,6 @@ func TestHookErrorsAreReported(t *testing.T) { {"domain delete", "DeleteDomain", http.MethodDelete, "/api/domains/a.example.com", "", http.StatusNotFound}, {"clients put", "PutACL", http.MethodPut, "/api/clients", `{"groups":[],"default_policy":"allow"}`, http.StatusBadRequest}, {"upstreams put", "PutUpstream", http.MethodPut, "/api/upstreams", `{"policy":"parallel","servers":[]}`, http.StatusBadRequest}, - {"log clear", "ClearLog", http.MethodPost, "/api/logs/clear", "", http.StatusInternalServerError}, } for _, tc := range cases { t.Run(tc.name, func(t *testing.T) { diff --git a/internal/api/handlers.go b/internal/api/handlers.go index e37ed79..3887edd 100644 --- a/internal/api/handlers.go +++ b/internal/api/handlers.go @@ -2,7 +2,6 @@ package api import ( "context" - "encoding/json" "errors" "fmt" "net/http" @@ -56,20 +55,6 @@ func (s *Server) handleStatus(w http.ResponseWriter, _ *http.Request) { }) } -// handleDashboard serves the aggregated dashboard payload. -func (s *Server) handleDashboard(w http.ResponseWriter, r *http.Request) { - if s.hooks.Dashboard == nil { - writeError(w, http.StatusNotImplemented, "dashboard not available") - return - } - v, err := s.hooks.Dashboard(r.Context(), r.URL.Query().Get("range")) - if err != nil { - writeError(w, http.StatusInternalServerError, err.Error()) - return - } - writeJSON(w, http.StatusOK, v) -} - // handleBlocklists serves the compiled blocklist state. func (s *Server) handleBlocklists(w http.ResponseWriter, _ *http.Request) { out := map[string]any{} @@ -470,122 +455,6 @@ func (s *Server) handleUpstreamsPut(w http.ResponseWriter, r *http.Request) { writeJSON(w, http.StatusOK, map[string]any{"ok": true, "version": version}) } -// handleLogs pages the query log. -func (s *Server) handleLogs(w http.ResponseWriter, r *http.Request) { - if s.hooks.SearchLog == nil { - writeError(w, http.StatusNotImplemented, "query log not available") - return - } - q := LogQuery{ - Limit: queryInt(r, "limit", 200), - Offset: queryInt(r, "offset", 0), - Text: r.URL.Query().Get("q"), - Action: r.URL.Query().Get("action"), - Client: r.URL.Query().Get("client"), - RCode: queryInt(r, "rcode", 0), - BlockedOnly: queryBool(r, "blocked"), - Since: queryTime(r, "since"), - } - v, err := s.hooks.SearchLog(r.Context(), q) - if err != nil { - writeError(w, http.StatusInternalServerError, err.Error()) - return - } - writeJSON(w, http.StatusOK, v) -} - -// handleLogStream is the Server-Sent Events endpoint feeding the live view. -func (s *Server) handleLogStream(w http.ResponseWriter, r *http.Request) { - flusher, ok := w.(http.Flusher) - if !ok { - writeError(w, http.StatusInternalServerError, "streaming unsupported") - return - } - w.Header().Set("Content-Type", "text/event-stream") - w.Header().Set("Cache-Control", "no-store") - w.Header().Set("Connection", "keep-alive") - // Without this, a reverse proxy buffers the stream and the UI shows - // nothing until the buffer fills. - w.Header().Set("X-Accel-Buffering", "no") - w.WriteHeader(http.StatusOK) - flusher.Flush() - - send := func(event string, v any) bool { - b, err := json.Marshal(v) - if err != nil { - return true - } - // A single-line data field is what the SSE grammar requires, so the - // payload is compact JSON with no newlines (json.Marshal never emits - // a raw newline). - if _, err := fmt.Fprintf(w, "event: %s\ndata: %s\n\n", event, b); err != nil { - return false - } - flusher.Flush() - return true - } - // An initial event tells the client the stream is live, so the UI can show - // a "connected" state before any query happens. - if !send("ready", map[string]any{"at": time.Now(), "version": s.hooks.Version}) { - return - } - - var ( - entries <-chan LogEntry - cancel func() - ) - if s.hooks.SubscribeLog != nil { - entries, cancel = s.hooks.SubscribeLog() - defer cancel() - } - - stats := time.NewTicker(time.Second) - defer stats.Stop() - ping := time.NewTicker(20 * time.Second) - defer ping.Stop() - - ctx := r.Context() - for { - select { - case <-ctx.Done(): - return - case e, ok := <-entries: - if !ok { - return - } - if !send("entry", e) { - return - } - case <-stats.C: - if s.hooks.LogStats == nil { - continue - } - if !send("stats", s.hooks.LogStats()) { - return - } - case <-ping.C: - // A comment frame keeps proxies from timing the stream out. - if _, err := fmt.Fprint(w, ": ping\n\n"); err != nil { - return - } - flusher.Flush() - } - } -} - -// handleLogsClear empties the query log. -func (s *Server) handleLogsClear(w http.ResponseWriter, _ *http.Request) { - if s.hooks.ClearLog == nil { - writeError(w, http.StatusNotImplemented, "query log not available") - return - } - if err := s.hooks.ClearLog(); err != nil { - writeError(w, http.StatusInternalServerError, err.Error()) - return - } - writeJSON(w, http.StatusOK, map[string]any{"ok": true}) -} - // handleCache returns the cache snapshot. func (s *Server) handleCache(w http.ResponseWriter, _ *http.Request) { if s.hooks.CacheStats == nil { @@ -595,17 +464,6 @@ func (s *Server) handleCache(w http.ResponseWriter, _ *http.Request) { writeJSON(w, http.StatusOK, s.hooks.CacheStats()) } -// handleCacheTop returns the hottest cached names. -func (s *Server) handleCacheTop(w http.ResponseWriter, r *http.Request) { - if s.hooks.CacheTop == nil { - writeError(w, http.StatusNotImplemented, "cache not available") - return - } - writeJSON(w, http.StatusOK, map[string]any{ - "items": s.hooks.CacheTop(queryInt(r, "limit", 50)), - }) -} - // handleCacheFlush empties the cache. func (s *Server) handleCacheFlush(w http.ResponseWriter, _ *http.Request) { if s.hooks.FlushCache == nil { @@ -856,8 +714,8 @@ func configWarnings(cfg *config.Config) []string { add("upstream.servers[%s]: insecure_skip_verify disables TLS validation", u.Addr) } } - if cfg.QueryLog.Enabled && cfg.QueryLog.SampleRate == 1 && cfg.QueryLog.LogCached { - add("qlog: logging every cached query on a busy instance is a lot of disk for little value; consider lowering sample_rate") + if cfg.AccessLog.Enabled && cfg.AccessLog.SampleRate == 1 { + add("access_log: sample_rate 1 logs every query; that is for short debugging sessions, the metrics already count ordinary traffic") } if cfg.Metrics.Enabled && !cfg.Metrics.Protect { add("metrics.protect: /metrics is unauthenticated and exposes client and domain statistics") diff --git a/internal/api/harness_test.go b/internal/api/harness_test.go index ced2c01..603f0ba 100644 --- a/internal/api/harness_test.go +++ b/internal/api/harness_test.go @@ -48,19 +48,14 @@ type fakeHooks struct { // arguments the API passed down, for the routes where the argument is // the interesting part of the contract. - dashRange []string domainQuery []DomainQuery domainAdd []DomainInput domainDel []domainDelete aclPut []aclPut upstreamPut []config.Upstream - logQuery []LogQuery refresh [][]string toggle []toggleCall - cacheTop []int - clearLog int flushes int - logStats int // fail maps a hook name to the error it should return, so the error // branches of a handler can be reached without a real component. @@ -68,12 +63,6 @@ type fakeHooks struct { // panicOn names hooks that panic instead of returning, which is how the // recoverer gets exercised. panicOn map[string]bool - - // stream plumbing for the SSE test. - stream chan LogEntry - unsub chan struct{} - unsubOnce sync.Once - subs int } type domainDelete struct { @@ -96,8 +85,6 @@ func newFakeHooks() *fakeHooks { return &fakeHooks{ fail: map[string]error{}, panicOn: map[string]bool{}, - stream: make(chan LogEntry, 16), - unsub: make(chan struct{}), } } @@ -174,10 +161,6 @@ func (f *fakeHooks) reset() { func (f *fakeHooks) hooks() Hooks { return Hooks{ - Dashboard: func(_ context.Context, rangeKey string) (any, error) { - f.record("Dashboard", func() { f.dashRange = append(f.dashRange, rangeKey) }) - return map[string]any{"range": rangeKey}, f.err("Dashboard") - }, BlocklistState: func() any { f.record("BlocklistState", func() {}) return map[string]any{"lists": []any{}} @@ -254,40 +237,10 @@ func (f *fakeHooks) hooks() Hooks { f.record("PutUpstream", func() { f.upstreamPut = append(f.upstreamPut, up) }) return 43, f.err("PutUpstream") }, - SearchLog: func(_ context.Context, q LogQuery) (any, error) { - f.record("SearchLog", func() { f.logQuery = append(f.logQuery, q) }) - return map[string]any{"entries": []any{}}, f.err("SearchLog") - }, - LogStats: func() any { - f.mu.Lock() - f.logStats++ - f.mu.Unlock() - return map[string]any{"qps": 1} - }, - SubscribeLog: func() (<-chan LogEntry, func()) { - f.mu.Lock() - f.subs++ - f.calls = append(f.calls, "SubscribeLog") - f.mu.Unlock() - return f.stream, func() { - f.mu.Lock() - f.subs-- - f.mu.Unlock() - f.unsubOnce.Do(func() { close(f.unsub) }) - } - }, - ClearLog: func() error { - f.record("ClearLog", func() { f.clearLog++ }) - return f.err("ClearLog") - }, CacheStats: func() any { f.record("CacheStats", func() {}) return map[string]any{"entries": 0} }, - CacheTop: func(limit int) any { - f.record("CacheTop", func() { f.cacheTop = append(f.cacheTop, limit) }) - return []any{} - }, FlushCache: func() int64 { f.record("FlushCache", func() { f.flushes++ }) return 0 @@ -304,20 +257,6 @@ func (f *fakeHooks) hooks() Hooks { } } -// subscribers is the number of live SSE subscribers; it must be back to zero -// once a client has disconnected. -func (f *fakeHooks) subscribers() int { - f.mu.Lock() - defer f.mu.Unlock() - return f.subs -} - -func (f *fakeHooks) statsCalls() int { - f.mu.Lock() - defer f.mu.Unlock() - return f.logStats -} - // harness is a wired Server behind an httptest listener, with a config file on // disk so the settings and reload routes have something real to work on. type harness struct { diff --git a/internal/api/routes_test.go b/internal/api/routes_test.go index 4f370ec..b9d4244 100644 --- a/internal/api/routes_test.go +++ b/internal/api/routes_test.go @@ -21,7 +21,6 @@ func TestRouteTableHappyPath(t *testing.T) { want string // substring the response must contain }{ {name: "healthz", method: http.MethodGet, path: "/api/healthz", hook: "Health", want: `"status":"ok"`}, - {name: "dashboard", method: http.MethodGet, path: "/api/dashboard?range=1h", hook: "Dashboard", want: `"range":"1h"`}, {name: "status", method: http.MethodGet, path: "/api/status", hook: "Status", want: `"version":"test"`}, {name: "blocklists", method: http.MethodGet, path: "/api/blocklists", hook: "BlocklistState", want: `"lists"`}, {name: "blocklist refresh all", method: http.MethodPost, path: "/api/blocklists/refresh", hook: "RefreshBlocklists", want: `"started":true`}, @@ -41,10 +40,7 @@ func TestRouteTableHappyPath(t *testing.T) { {name: "clients put", method: http.MethodPut, path: "/api/clients", body: `{"groups":[],"default_policy":"allow"}`, hook: "PutACL", want: `"version":42`}, {name: "upstreams get", method: http.MethodGet, path: "/api/upstreams", hook: "GetUpstream", want: `"policy":"parallel"`}, {name: "upstreams put", method: http.MethodPut, path: "/api/upstreams", body: `{"policy":"parallel","servers":[{"addr":"127.0.0.1:53","proto":"udp"}]}`, hook: "PutUpstream", want: `"version":43`}, - {name: "logs search", method: http.MethodGet, path: "/api/logs?limit=5", hook: "SearchLog", want: `"entries"`}, - {name: "logs clear", method: http.MethodPost, path: "/api/logs/clear", hook: "ClearLog", want: `"ok":true`}, {name: "cache stats", method: http.MethodGet, path: "/api/cache", hook: "CacheStats", want: `"entries":0`}, - {name: "cache top", method: http.MethodGet, path: "/api/cache/top?limit=7", hook: "CacheTop", want: `"items"`}, {name: "cache flush", method: http.MethodPost, path: "/api/cache/flush", hook: "FlushCache", want: `"ok":true`}, {name: "settings get", method: http.MethodGet, path: "/api/settings", hook: "", want: `"config_yaml"`}, {name: "settings reload", method: http.MethodPost, path: "/api/settings/reload", hook: "", want: `"ok":true`}, @@ -109,7 +105,6 @@ func TestReadRoutesDoNotMutate(t *testing.T) { path string }{ {http.MethodGet, "/api/healthz"}, - {http.MethodGet, "/api/dashboard?range=24h"}, {http.MethodGet, "/api/status"}, {http.MethodGet, "/api/blocklists"}, {http.MethodGet, "/api/domains"}, @@ -117,9 +112,7 @@ func TestReadRoutesDoNotMutate(t *testing.T) { {http.MethodGet, "/api/zones"}, {http.MethodGet, "/api/clients"}, {http.MethodGet, "/api/upstreams"}, - {http.MethodGet, "/api/logs"}, {http.MethodGet, "/api/cache"}, - {http.MethodGet, "/api/cache/top"}, {http.MethodGet, "/api/settings"}, {http.MethodGet, "/api/whoami"}, } @@ -131,7 +124,6 @@ func TestReadRoutesDoNotMutate(t *testing.T) { } mutations := []string{ "RefreshBlocklists", "ToggleBlocklist", "AddDomain", "DeleteDomain", - "PutACL", "PutUpstream", "ClearLog", "FlushCache", "AddZoneRecord", "PutZoneRecord", "DeleteZoneRecord", "AddZoneDelegation", "DeleteZoneDelegation", "DeleteZone", } @@ -154,10 +146,10 @@ func TestReadRoutesDoNotMutate(t *testing.T) { func TestHandlerRecoversFromPanic(t *testing.T) { h := newHarness(t, nil) h.fake.mu.Lock() - h.fake.panicOn["Dashboard"] = true + h.fake.panicOn["CacheStats"] = true h.fake.mu.Unlock() - res := h.get("/api/dashboard") + res := h.get("/api/cache") if res.status != http.StatusInternalServerError { t.Fatalf("panicking hook = %d, want 500: %s", res.status, res.body) } diff --git a/internal/api/sse_test.go b/internal/api/sse_test.go deleted file mode 100644 index d7d1539..0000000 --- a/internal/api/sse_test.go +++ /dev/null @@ -1,243 +0,0 @@ -package api - -import ( - "bufio" - "context" - "encoding/json" - "net/http" - "runtime" - "strings" - "sync" - "testing" - "time" -) - -// sseEvent is one parsed SSE frame: the event name and the JSON payload. -type sseEvent struct { - name string - data string -} - -// openSSE opens GET /logs/stream and returns a reader for the frames. The -// stream stays open until the context the caller passed is cancelled or the -// body is closed, so every test here has to do one or the other. -func openSSE(t *testing.T, h *harness, ctx context.Context) (*http.Response, *bufio.Reader) { - t.Helper() - req, err := http.NewRequestWithContext(ctx, http.MethodGet, h.ts.URL+"/api/logs/stream", nil) - if err != nil { - t.Fatal(err) - } - req.Header.Set("X-API-Key", "rw-key") - res, err := h.ts.Client().Do(req) - if err != nil { - t.Fatalf("open the log stream: %v", err) - } - t.Cleanup(func() { _ = res.Body.Close() }) - return res, bufio.NewReader(res.Body) -} - -// nextEvent reads until a complete frame has arrived. Comment frames (the -// keep-alive ": ping") and the blank separator line are skipped. -func nextEvent(t *testing.T, br *bufio.Reader) sseEvent { - t.Helper() - var ev sseEvent - for { - line, err := br.ReadString('\n') - if err != nil { - t.Fatalf("read the log stream: %v", err) - } - line = strings.TrimRight(line, "\r\n") - switch { - case strings.HasPrefix(line, "event: "): - ev.name = strings.TrimPrefix(line, "event: ") - case strings.HasPrefix(line, "data: "): - ev.data = strings.TrimPrefix(line, "data: ") - case line == "": - if ev.name != "" || ev.data != "" { - return ev - } - } - } -} - -// freshUnsubSignal gives the SSE test its own one-shot unsubscribe channel. -// The harness closes a single shared channel through a sync.Once, so without -// this only the first stream test in the package could observe it. -func freshUnsubSignal(h *harness) <-chan struct{} { - h.fake.mu.Lock() - defer h.fake.mu.Unlock() - h.fake.unsub = make(chan struct{}) - h.fake.unsubOnce = sync.Once{} - return h.fake.unsub -} - -// TestSSEStreamHeadersAndEvents pins the SSE contract the live log view -// depends on: the streaming content type, the two headers that stop an -// intermediary from buffering the stream, a "ready" event so the UI can show it -// is connected, and exactly one "entry" event per query-log row. -func TestSSEStreamHeadersAndEvents(t *testing.T) { - h := newHarness(t, nil) - unsub := freshUnsubSignal(h) - // Queued before the stream opens: the fake's channel is buffered, so this - // is a deterministic ordering and not a race on the subscription. - want := []LogEntry{ - {ID: 1, Name: "a.example.com.", QTypeStr: "A", RCode: 0, Client: "198.51.100.1"}, - {ID: 2, Name: "b.example.com.", QTypeStr: "AAAA", RCode: 3, Client: "198.51.100.2", Blocked: true}, - {ID: 3, Name: "c.example.com.", QTypeStr: "TXT", RCode: 0, Client: "198.51.100.3"}, - } - for _, e := range want { - h.fake.stream <- e - } - - ctx, cancel := context.WithCancel(context.Background()) - defer cancel() - res, br := openSSE(t, h, ctx) - - if got := res.Header.Get("Content-Type"); got != "text/event-stream" { - t.Errorf("Content-Type = %q, want text/event-stream", got) - } - // no-store, not no-cache: this stream is never replayable. - if got := res.Header.Get("Cache-Control"); got != "no-store" { - t.Errorf("Cache-Control = %q, want no-store", got) - } - // Without this an nginx in front buffers the stream and the live view shows - // nothing until the buffer fills. - if got := res.Header.Get("X-Accel-Buffering"); got != "no" { - t.Errorf("X-Accel-Buffering = %q, want no", got) - } - - ready := nextEvent(t, br) - if ready.name != "ready" { - t.Fatalf("first event = %q, want ready", ready.name) - } - var readyBody map[string]any - if err := json.Unmarshal([]byte(ready.data), &readyBody); err != nil { - t.Fatalf("ready payload is not JSON: %v: %q", err, ready.data) - } - if readyBody["version"] != "test" { - t.Errorf("ready payload = %v, want it to carry the version", readyBody) - } - for i, e := range want { - got := nextEvent(t, br) - if got.name != "entry" { - t.Fatalf("event %d = %q, want entry", i, got.name) - } - var gotEntry LogEntry - if err := json.Unmarshal([]byte(got.data), &gotEntry); err != nil { - t.Fatalf("entry payload is not JSON: %v: %q", err, got.data) - } - if gotEntry.ID != e.ID || gotEntry.Name != e.Name || gotEntry.Client != e.Client { - t.Errorf("entry %d = %+v, want %+v", i, gotEntry, e) - } - } - cancel() - waitFor(t, 2*time.Second, "the subscriber to be released", func() bool { - return h.fake.subscribers() == 0 - }) - select { - case <-unsub: - default: - t.Error("the handler returned without running the unsubscribe hook") - } -} - -// TestSSEStreamUnsubscribesOnClientDisconnect checks a client that goes away -// does not leave a handler parked on the log channel: the request context is -// cancelled when the connection drops, and the handler must return and run its -// cancel hook, or every reconnect leaks a goroutine and a log subscriber. -func TestSSEStreamUnsubscribesOnClientDisconnect(t *testing.T) { - h := newHarness(t, nil) - unsub := freshUnsubSignal(h) - ctx, cancel := context.WithCancel(context.Background()) - _, br := openSSE(t, h, ctx) - if got := nextEvent(t, br); got.name != "ready" { - t.Fatalf("first event = %q, want ready", got.name) - } - waitFor(t, 2*time.Second, "the handler to subscribe", func() bool { - return h.fake.subscribers() == 1 - }) - - // Disconnect: dropping the request context closes the connection, which is - // what the server sees when a browser tab is closed. - cancel() - - waitFor(t, 2*time.Second, "the handler to unsubscribe", func() bool { - return h.fake.subscribers() == 0 - }) - select { - case <-unsub: - case <-time.After(2 * time.Second): - t.Fatal("the unsubscribe hook never ran after the client disconnected") - } -} - -// TestSSEStreamLeavesNoGoroutinesBehind opens and closes the stream repeatedly -// and asserts the goroutine count stays bounded. The bound, not an exact count: -// the HTTP client and server keep per-connection goroutines that wind down on -// their own, and a test that demands an exact number is a flake. The property -// worth having is that the count does not grow with the number of streams. -func TestSSEStreamLeavesNoGoroutinesBehind(t *testing.T) { - h := newHarness(t, nil) - runtime.GC() // keep the baseline honest: the count is what it is after a GC - before := runtime.NumGoroutine() - for i := 0; i < 25; i++ { - ctx, cancel := context.WithCancel(context.Background()) - _, br := openSSE(t, h, ctx) - if got := nextEvent(t, br); got.name != "ready" { - cancel() - t.Fatalf("stream %d: first event = %q, want ready", i, got.name) - } - cancel() - } - waitFor(t, 2*time.Second, "every subscriber to be released", func() bool { - return h.fake.subscribers() == 0 - }) - const bound = 8 // per-connection goroutines that may still be winding down - waitFor(t, 3*time.Second, "the goroutine count to settle", func() bool { - return runtime.NumGoroutine() <= before+bound - }) -} - -// TestSSEStreamEndsWhenTheSourceCloses covers the other exit from the handler -// loop: the hook's channel being closed, which is what a shutting-down log ring -// does. The response has to end rather than hang, and the unsubscribe hook must -// still run — a handler that only returns on the request context is a handler -// that leaks when the producer goes away. -func TestSSEStreamEndsWhenTheSourceCloses(t *testing.T) { - h := newHarness(t, nil) - unsub := freshUnsubSignal(h) - ctx, cancel := context.WithCancel(context.Background()) - defer cancel() - // Closing the hook's channel is what a shutting-down log ring does. - close(h.fake.stream) - _, br := openSSE(t, h, ctx) - if got := nextEvent(t, br); got.name != "ready" { - t.Fatalf("first event = %q, want ready", got.name) - } - if _, err := br.ReadString('\n'); err == nil { - t.Error("the stream carried on after its source closed") - } - waitFor(t, 2*time.Second, "the handler to unsubscribe", func() bool { - return h.fake.subscribers() == 0 - }) - select { - case <-unsub: - case <-time.After(2 * time.Second): - t.Fatal("the unsubscribe hook never ran after the source closed") - } -} - -// TestSSEStreamRequiresAuth checks the stream is behind the same auth as the -// rest of the API: it is a live view of every client address and domain the -// instance sees, so an unauthenticated subscribe is a data leak, not a -// cosmetic one. -func TestSSEStreamRequiresAuth(t *testing.T) { - h := newHarness(t, nil) - res := h.do(http.MethodGet, "/api/logs/stream", "") - if res.status != http.StatusUnauthorized { - t.Fatalf("GET /api/logs/stream without a key = %d, want 401: %s", res.status, res.body) - } - if h.fake.count("SubscribeLog") != 0 { - t.Error("an unauthenticated request reached the subscribe hook") - } -} diff --git a/internal/app/accesslog_test.go b/internal/app/accesslog_test.go new file mode 100644 index 0000000..4724377 --- /dev/null +++ b/internal/app/accesslog_test.go @@ -0,0 +1,67 @@ +package app + +import ( + "bytes" + "encoding/json" + "strings" + "sync" + "testing" + + "github.com/miekg/dns" +) + +type lockedBuf struct { + mu sync.Mutex + b bytes.Buffer +} + +func (l *lockedBuf) Write(p []byte) (int, error) { + l.mu.Lock() + defer l.mu.Unlock() + return l.b.Write(p) +} +func (l *lockedBuf) lines() []map[string]any { + l.mu.Lock() + defer l.mu.Unlock() + var out []map[string]any + for _, ln := range strings.Split(strings.TrimSpace(l.b.String()), "\n") { + if ln == "" { + continue + } + var m map[string]any + if err := json.Unmarshal([]byte(ln), &m); err != nil { + panic("access log line is not JSON: " + ln) + } + out = append(out, m) + } + return out +} + +// TestAccessLogDefaultsToBlockedAndFailed runs the whole resolver with the +// shipped defaults: a blocked query leaves a line, an ordinary answer and a +// cache hit leave none, and the line carries what a log search needs. +func TestAccessLogDefaultsToBlockedAndFailed(t *testing.T) { + out := &lockedBuf{} + h := newHarness(t, nil, func(o *Options) { o.AccessLogOut = out }) + + h.query("www.example.test", dns.TypeA) // allowed + h.query("www.example.test", dns.TypeA) // cached + if m := h.query("ads.example.com", dns.TypeA); m.Rcode != dns.RcodeNameError { + t.Fatalf("setup: ads.example.com rcode %d, want a block", m.Rcode) + } + h.app.logger.Flush() + + lines := out.lines() + if len(lines) != 1 { + t.Fatalf("%d access-log lines, want exactly the blocked query: %v", len(lines), lines) + } + l := lines[0] + for k, want := range map[string]any{ + "log": "access", "msg": "query", "name": "ads.example.com.", "action": "block", + "list": "test-hosts", "qtype": "A", "client": "127.0.0.1", "protocol": "udp", + } { + if l[k] != want { + t.Errorf("%s = %v, want %v (line %v)", k, l[k], want, l) + } + } +} diff --git a/internal/app/app.go b/internal/app/app.go index 597e9c4..c46656a 100644 --- a/internal/app/app.go +++ b/internal/app/app.go @@ -7,6 +7,7 @@ import ( "crypto/tls" "errors" "fmt" + "io" "log/slog" "net" "net/http" @@ -19,6 +20,7 @@ import ( "sync/atomic" "time" + "git.k8s-git-k6n.net/mats/fancy-dns/internal/accesslog" "git.k8s-git-k6n.net/mats/fancy-dns/internal/acl" "git.k8s-git-k6n.net/mats/fancy-dns/internal/api" "git.k8s-git-k6n.net/mats/fancy-dns/internal/blocklist" @@ -30,7 +32,6 @@ import ( "git.k8s-git-k6n.net/mats/fancy-dns/internal/kubezones" "git.k8s-git-k6n.net/mats/fancy-dns/internal/localzone" "git.k8s-git-k6n.net/mats/fancy-dns/internal/metrics" - "git.k8s-git-k6n.net/mats/fancy-dns/internal/qlog" "git.k8s-git-k6n.net/mats/fancy-dns/internal/resolver" "git.k8s-git-k6n.net/mats/fancy-dns/internal/server" "git.k8s-git-k6n.net/mats/fancy-dns/internal/web" @@ -51,6 +52,8 @@ type Options struct { LogFormat string // Kube turns on the Kubernetes source for groups, lists and zones. Kube KubeOptions + // AccessLogOut receives the access log; nil means os.Stdout. + AccessLogOut io.Writer } // App is the running process. @@ -64,7 +67,7 @@ type App struct { overrideMu sync.Mutex cache *cache.Manager cstore *cache.Store - logger *qlog.Logger + logger *accesslog.Logger aclH *acl.Holder local *localzone.Holder // zones is the Kubernetes-sourced zone client. @@ -83,7 +86,6 @@ type App struct { dns *server.Server api *api.Server cl *cluster.Cluster - series *seriesStore apiServers []*http.Server apiLn []net.Listener @@ -292,29 +294,20 @@ func apiTLS(cfg *config.Config) (*tls.Config, error) { }, nil } -// startLogger opens the query log. +// startLogger starts the access log: JSON lines on stdout for blocked and +// failed queries (and more, if configured). It stores nothing. func (a *App) startLogger(cfg *config.Config) error { - opts := qlog.DefaultOptions() - opts.Path = cfg.QueryLogPath() - opts.MaxEntries = cfg.QueryLog.MaxEntries - opts.LiveBuffer = cfg.QueryLog.LiveBuffer - opts.FlushInterval = cfg.QueryLog.FlushInterval.D() - opts.SampleRate = cfg.QueryLog.SampleRate - opts.LogBlocked = cfg.QueryLog.LogBlocked - opts.LogCached = cfg.QueryLog.LogCached - opts.LogErrors = cfg.QueryLog.LogErrors - opts.TopDomains = cfg.QueryLog.TopDomains - opts.TopTTL = cfg.QueryLog.TopTTL.D() - if !cfg.QueryLog.Enabled { - opts.Path = "" - } - l, err := qlog.New(opts) - if err != nil { - a.markDegraded("query log: " + err.Error()) - a.log.Warn("query log unavailable, continuing without persistence", "error", err) + if !cfg.AccessLog.Enabled { return nil } - a.logger = l + a.logger = accesslog.New(accesslog.Options{ + Writer: a.opt.AccessLogOut, + Buffer: cfg.AccessLog.Buffer, + LogBlocked: cfg.AccessLog.LogBlocked, + LogErrors: cfg.AccessLog.LogErrors, + LogCached: cfg.AccessLog.LogCached, + SampleRate: cfg.AccessLog.SampleRate, + }) return nil } @@ -441,7 +434,6 @@ func (a *App) startDNS(ctx context.Context) { a.log.Error("dns listeners failed to start", "error", err) a.markDegraded("dns listeners: " + err.Error()) } - a.series = newSeriesStore() } func mustNames(rc *engine.ReverseCache, ip string) []string { @@ -632,22 +624,16 @@ func (a *App) startBackground(ctx context.Context, cfg *config.Config) { } // Upstream health probes. go a.healthLoop(ctx) - // Live gauges and the dashboard series sampler. + // The in-flight gauge. go func() { t := time.NewTicker(2 * time.Second) defer t.Stop() - sample := time.NewTicker(5 * time.Second) - defer sample.Stop() for { select { case <-ctx.Done(): return case <-t.C: metrics.SetConcurrent(int(a.engine.Inflight())) - case <-sample.C: - if a.series != nil { - a.series.sample() - } } } }() @@ -838,11 +824,8 @@ func (a *App) Stop(ctx context.Context) error { errs = append(errs, err) } } - if a.logger != nil { - a.logger.Flush() - if err := a.logger.Close(); err != nil { - errs = append(errs, err) - } + if err := a.logger.Close(); err != nil { + errs = append(errs, err) } if a.cstore != nil { // Snapshot, close, then clear the pointer: the background snapshot diff --git a/internal/app/contract_test.go b/internal/app/contract_test.go index ad1bba7..deed594 100644 --- a/internal/app/contract_test.go +++ b/internal/app/contract_test.go @@ -122,25 +122,6 @@ func TestAdminEndpointKeySets(t *testing.T) { wantKeys("components", "config", "started", "uptime_s", "version")) }) - t.Run("dashboard", func(t *testing.T) { - code, body := h.get("/api/dashboard?range=1h") - if code != http.StatusOK { - t.Fatalf("GET /api/dashboard = %d: %s", code, body) - } - requireKeys(t, "GET /api/dashboard", keysOf(t, body), wantKeys( - "blocked_pct", "blocked_total", "blocklist_rules", "cache_entries", - "cache_hit_rate", "config_version", "degraded_reason", "errors_total", - "generation", "health", "inflight", "listeners", "node_id", - "queries_per_sec", "queries_total", "recent", "series", "top_blocked", - "top_queried", "transports", "upstreams", "uptime_seconds", "version", - )) - requireKeys(t, "GET /api/dashboard recent[0]", keysOfField(t, body, "recent", "0"), wantKeys( - "action", "blocked", "client", "client_group", "duration_ms", "id", - "list", "name", "protocol", "qtype", "qtype_name", "rcode", "rcode_name", - "response", "ts", "upstream", - )) - }) - t.Run("blocklists", func(t *testing.T) { code, body := h.get("/api/blocklists") if code != http.StatusOK { @@ -210,23 +191,6 @@ func TestAdminEndpointKeySets(t *testing.T) { "weight")) }) - t.Run("logs", func(t *testing.T) { - code, body := h.get("/api/logs?limit=10") - if code != http.StatusOK { - t.Fatalf("GET /api/logs = %d: %s", code, body) - } - requireKeys(t, "GET /api/logs", keysOf(t, body), - wantKeys("has_more", "items", "limit", "offset", "total")) - // Every key on every row. These were omitempty, so a row without an - // ACL group or a blocklist arrived without the key and the console - // rendered "undefined" instead of an empty cell. - requireKeys(t, "GET /api/logs items[0]", keysOfField(t, body, "items", "0"), wantKeys( - "action", "blocked", "client", "client_group", "duration_ms", "id", - "list", "name", "protocol", "qtype", "qtype_name", "rcode", "rcode_name", - "response", "ts", "upstream", - )) - }) - t.Run("cache", func(t *testing.T) { code, body := h.get("/api/cache") if code != http.StatusOK { @@ -243,19 +207,6 @@ func TestAdminEndpointKeySets(t *testing.T) { )) }) - t.Run("cache top", func(t *testing.T) { - code, body := h.get("/api/cache/top?limit=5") - if code != http.StatusOK { - t.Fatalf("GET /api/cache/top = %d: %s", code, body) - } - requireKeys(t, "GET /api/cache/top", keysOf(t, body), wantKeys("items")) - // There is no `count` and no `last_seen`: the cache tracks a hit - // counter and a byte count per name, and the console's "Lookups" and - // "Last seen" columns were reading fields that never existed. - requireKeys(t, "GET /api/cache/top items[0]", keysOfField(t, body, "items", "0"), - wantKeys("bytes", "hits", "name", "qtype", "qtype_name")) - }) - t.Run("settings", func(t *testing.T) { code, body := h.get("/api/settings") if code != http.StatusOK { @@ -466,14 +417,6 @@ func TestRemainingEndpointKeySets(t *testing.T) { )) }) - t.Run("logs clear", func(t *testing.T) { - code, body := h.do(http.MethodPost, "/api/logs/clear", "") - if code != http.StatusOK { - t.Fatalf("POST /api/logs/clear = %d: %s", code, body) - } - requireKeys(t, "POST /api/logs/clear", keysOf(t, body), wantKeys("ok")) - }) - t.Run("settings validate", func(t *testing.T) { // A document that is valid: the issue lists are present and empty. code, body := h.do(http.MethodPost, "/api/settings/validate", @@ -516,43 +459,6 @@ func TestRemainingEndpointKeySets(t *testing.T) { requireKeys(t, "POST /api/settings/reload", keysOf(t, body), wantKeys("ok", "version")) }) - t.Run("log stream ready frame", func(t *testing.T) { - // The stream never ends, so read the first frame and hang up: the - // console only needs to know the stream opened and what it carries. - req, _ := http.NewRequest("GET", "http://"+h.api+"/api/logs/stream", nil) - req.Header.Set("X-API-Key", h.key) - res, err := http.DefaultClient.Do(req) - if err != nil { - t.Fatalf("GET /api/logs/stream: %v", err) - } - defer res.Body.Close() - if res.StatusCode != http.StatusOK { - t.Fatalf("GET /api/logs/stream = %d", res.StatusCode) - } - br := newLineReader(res.Body) - var event, data string - for range 2 { - line, err := br.readLine() - if err != nil { - t.Fatalf("read stream: %v", err) - } - switch { - case line == "": - case len(line) > 7 && line[:7] == "event: ": - event = line[7:] - case len(line) > 6 && line[:6] == "data: ": - data = line[6:] - } - if event != "" && data != "" { - break - } - } - if event != "ready" { - t.Fatalf("first event = %q, want ready", event) - } - requireKeys(t, "GET /api/logs/stream ready frame", keysOf(t, []byte(data)), - wantKeys("at", "version")) - }) } // quote renders a Go string as a JSON string literal. diff --git a/internal/app/dump_shapes_test.go b/internal/app/dump_shapes_test.go index 5c6cd2a..bd1ddaa 100644 --- a/internal/app/dump_shapes_test.go +++ b/internal/app/dump_shapes_test.go @@ -22,9 +22,9 @@ func TestDumpShapes(t *testing.T) { h := newHarness(t, nil) h.query("hot.test.", 1) for _, p := range []string{ - "/api/status", "/api/dashboard?range=1h", "/api/blocklists", + "/api/status", "/api/blocklists", "/api/domains?per_page=3", "/api/clients", "/api/upstreams", - "/api/logs?limit=3", "/api/cache", "/api/cache/top?limit=3", + "/api/cache", "/api/settings", "/api/whoami", } { code, body := h.get(p) diff --git a/internal/app/harness_test.go b/internal/app/harness_test.go index 2b9f979..cec5f02 100644 --- a/internal/app/harness_test.go +++ b/internal/app/harness_test.go @@ -140,7 +140,6 @@ func newHarness(t *testing.T, mutate func(*config.Config), opts ...func(*Options cfg.Upstream.HealthCheck = 0 cfg.Upstream.Servers = []config.UpstreamServer{{Addr: up.addr, Proto: "udp", Weight: 1, HealthName: "test"}} cfg.Cache.Persist.Path = filepath.Join(dir, "cache.db") - cfg.QueryLog.Path = filepath.Join(dir, "queries.db") cfg.Block.Lists = []config.ListSource{{ Name: "test-hosts", Format: "hosts", Path: hosts, Enabled: true, Refresh: 0, }} @@ -159,7 +158,9 @@ func newHarness(t *testing.T, mutate func(*config.Config), opts ...func(*Options t.Fatal(err) } - opt := Options{ConfigPath: path, Version: "test"} + // The access log goes to stdout by design; keep it out of the test output + // unless a test captures it. + opt := Options{ConfigPath: path, Version: "test", AccessLogOut: io.Discard} for _, o := range opts { o(&opt) } diff --git a/internal/app/hooks.go b/internal/app/hooks.go index b5f7b94..a0e5660 100644 --- a/internal/app/hooks.go +++ b/internal/app/hooks.go @@ -8,7 +8,6 @@ import ( "reflect" "sort" "strings" - "sync" "time" "github.com/miekg/dns" @@ -17,8 +16,6 @@ import ( "git.k8s-git-k6n.net/mats/fancy-dns/internal/blocklist" "git.k8s-git-k6n.net/mats/fancy-dns/internal/config" "git.k8s-git-k6n.net/mats/fancy-dns/internal/engine" - "git.k8s-git-k6n.net/mats/fancy-dns/internal/metrics" - "git.k8s-git-k6n.net/mats/fancy-dns/internal/qlog" "git.k8s-git-k6n.net/mats/fancy-dns/internal/resolver" "git.k8s-git-k6n.net/mats/fancy-dns/internal/zonefile" ) @@ -31,7 +28,6 @@ func (a *App) hooks() api.Hooks { Logger: a.log, Version: a.ver, StartedAt: a.startedAt, - Dashboard: a.dashboard, Status: a.status, Health: a.health, BlocklistState: a.blocklistState, @@ -61,12 +57,7 @@ func (a *App) hooks() api.Hooks { PutACL: a.putACL, GetUpstream: a.getUpstreams, PutUpstream: a.putUpstream, - SearchLog: a.searchLog, - LogStats: a.logStats, - SubscribeLog: a.subscribeLog, - ClearLog: a.clearLog, CacheStats: a.cacheStats, - CacheTop: a.cacheTop, FlushCache: a.flushCache, Flush: a.flush, } @@ -269,9 +260,11 @@ func (a *App) health() any { if a.dns == nil || len(a.dns.Listeners()) == 0 { status = "down" } - if a.logger != nil && a.logger.ErrorCount() > 0 && status == "ok" { + if a.logger.Dropped() > 0 && status == "ok" { + // Lines are dropped when the log stream cannot keep up. DNS is fine, but + // whoever reads the log is missing events, which is worth a mention. status = "degraded" - problems = append(problems, "query log write errors") + problems = append(problems, "access log is dropping lines") } return map[string]any{ "status": status, @@ -316,8 +309,9 @@ func (a *App) status() any { if a.cache != nil { out["cache"] = a.cacheStats() } - if a.logger != nil { - out["qlog"] = a.logger.Stats() + out["access_log"] = map[string]any{ + "enabled": a.logger != nil, + "dropped": a.logger.Dropped(), } if a.pool != nil { out["upstream"] = a.getUpstreams() @@ -866,106 +860,6 @@ func (a *App) putUpstream(_ context.Context, up config.Upstream) (int64, error) return a.cfg.Get().Version, nil } -// searchLog pages the query log. -func (a *App) searchLog(_ context.Context, q api.LogQuery) (any, error) { - if a.logger == nil { - return map[string]any{"items": []any{}, "total": 0, "offset": 0}, nil - } - page, err := a.logger.Search(qlog.Query{ - Limit: q.Limit, Offset: q.Offset, Text: q.Text, Action: q.Action, - Client: q.Client, RCode: q.RCode, BlockedOnly: q.BlockedOnly, Since: q.Since, - }) - if err != nil { - return nil, err - } - out := make([]api.LogEntry, 0, len(page.Items)) - for _, e := range page.Items { - out = append(out, toLogEntry(e)) - } - return map[string]any{ - "items": out, - "total": page.Total, - "offset": page.Offset, - "limit": page.Limit, - "has_more": len(out) == page.Limit, - }, nil -} - -func toLogEntry(e qlog.Entry) api.LogEntry { - return api.LogEntry{ - ID: e.ID, TS: e.TS, Client: e.Client, Group: e.Group, Name: e.Name, - QType: e.QType, QTypeStr: e.QTypeStr, RCode: e.RCode, - RCodeStr: e.RCodeName(), Action: string(e.Action), Response: e.Response, - Duration: e.Duration, Upstream: e.Upstream, List: e.List, Protocol: e.Protocol, - Blocked: e.Blocked, - } -} - -// logStats is the live stats frame pushed over SSE. -func (a *App) logStats() any { - t := metrics.TotalsNow() - var hitRate float64 - if t.Hits+t.Misses > 0 { - hitRate = float64(t.Hits) / float64(t.Hits+t.Misses) - } - var blockedPct float64 - if t.Queries > 0 { - blockedPct = float64(t.Blocked) / float64(t.Queries) - } - return map[string]any{ - "qps": a.series.qps(), - "blocked_pct": blockedPct, - "cache_hit_rate": hitRate, - "queries_total": t.Queries, - "blocked_total": t.Blocked, - "errors_total": t.Errors, - "inflight": t.Concurrent, - "uptime_s": int64(time.Since(a.startedAt).Seconds()), - } -} - -// subscribeLog streams new entries to one SSE client. -func (a *App) subscribeLog() (<-chan api.LogEntry, func()) { - if a.logger == nil { - ch := make(chan api.LogEntry) - close(ch) - return ch, func() {} - } - src, cancel := a.logger.Subscribe() - out := make(chan api.LogEntry, 256) - done := make(chan struct{}) - go func() { - defer close(out) - for { - select { - case <-done: - return - case e, ok := <-src: - if !ok { - return - } - select { - case out <- toLogEntry(e): - case <-done: - return - } - } - } - }() - return out, func() { - close(done) - cancel() - } -} - -// clearLog empties the query log. -func (a *App) clearLog() error { - if a.logger == nil { - return nil - } - return a.logger.Clear() -} - // cacheStats returns the cache snapshot. func (a *App) cacheStats() any { if a.cache == nil { @@ -992,25 +886,6 @@ func (a *App) cacheStats() any { } } -// cacheTop returns the hottest cached names. -func (a *App) cacheTop(limit int) any { - if a.cache == nil { - return []any{} - } - entries := a.cache.TopEntries(limit) - out := make([]map[string]any, 0, len(entries)) - for _, e := range entries { - out = append(out, map[string]any{ - "name": e.Name, - "qtype": e.Type, - "qtype_name": dns.Type(e.Type).String(), - "hits": e.Hits, - "bytes": e.Bytes, - }) - } - return out -} - // flushCache empties the cache. func (a *App) flushCache() int64 { if a.cache == nil { @@ -1023,208 +898,6 @@ func (a *App) flushCache() int64 { // flush persists buffered state. func (a *App) flush() { - if a.logger != nil { - a.logger.Flush() - } + a.logger.Flush() a.snapshotCache() } - -// seriesStore keeps the rolling counters the dashboard charts read. -type seriesStore struct { - mu sync.Mutex - queries *metrics.Ring - blocked *metrics.Ring - errors *metrics.Ring - cacheHit *metrics.Ring - // The previous totals, used to derive per-bucket deltas. - lastQueries uint64 - lastBlocked uint64 - lastErrors uint64 - lastHits uint64 - lastAt time.Time - qpsValue float64 -} - -func newSeriesStore() *seriesStore { - return &seriesStore{ - queries: metrics.NewRing(300, 5*time.Second), - blocked: metrics.NewRing(300, 5*time.Second), - errors: metrics.NewRing(300, 5*time.Second), - cacheHit: metrics.NewRing(300, 5*time.Second), - lastAt: time.Now(), - } -} - -// sample folds the delta since the last sample into the rings. Sampling on a -// timer rather than per query keeps the query path free of any extra work and -// is accurate enough for a chart. -func (s *seriesStore) sample() { - t := metrics.TotalsNow() - s.mu.Lock() - now := time.Now() - dt := now.Sub(s.lastAt).Seconds() - if dt > 0 { - s.qpsValue = float64(t.Queries-s.lastQueries) / dt - } - // Ring buckets are 5s wide; scale the interval delta accordingly. - scale := dt / 5 - if scale < 0 { - scale = 0 - } - dq := int64(float64(t.Queries-s.lastQueries) * scale) - db := int64(float64(t.Blocked-s.lastBlocked) * scale) - de := int64(float64(t.Errors-s.lastErrors) * scale) - dc := int64(float64(t.Hits-s.lastHits) * scale) - if dq > 0 { - s.queries.Add(dq) - } - if db > 0 { - s.blocked.Add(db) - } - if de > 0 { - s.errors.Add(de) - } - if dc > 0 { - s.cacheHit.Add(dc) - } - s.lastQueries, s.lastBlocked, s.lastErrors, s.lastHits = t.Queries, t.Blocked, t.Errors, t.Hits - s.lastAt = now - s.mu.Unlock() -} - -func (s *seriesStore) qps() float64 { - s.mu.Lock() - defer s.mu.Unlock() - return s.qpsValue -} - -// dashboard builds the aggregated payload. -func (a *App) dashboard(_ context.Context, rangeKey string) (any, error) { - spec, ok := ranges[rangeKey] - if !ok { - spec = ranges["1h"] - } - t := metrics.TotalsNow() - hitRate := 0.0 - if t.Hits+t.Misses > 0 { - hitRate = float64(t.Hits) / float64(t.Hits+t.Misses) - } - blockedPct := 0.0 - if t.Queries > 0 { - blockedPct = float64(t.Blocked) / float64(t.Queries) * 100 - } - - // Build the series by walking the rings oldest-first and dropping anything - // older than the requested range. - var series []map[string]any - now := time.Now() - qts, qv := a.series.queries.Snapshot() - _, bv := a.series.blocked.Snapshot() - _, ev := a.series.errors.Snapshot() - _, cv := a.series.cacheHit.Snapshot() - series = make([]map[string]any, 0, len(qts)) - for i := range qts { - age := now.Sub(time.Unix(qts[i], 0)) - if age > spec.duration { - break - } - series = append(series, map[string]any{ - "t": qts[i], - "queries": qv[i], - "blocked": bv[i], - "errors": ev[i], - "cache_hits": cv[i], - }) - } - - topBlocked := []any{} - topQueried := []any{} - if a.logger != nil { - for _, d := range a.logger.TopBlocked(15) { - topBlocked = append(topBlocked, map[string]any{ - "domain": d.Name, "count": d.Count, "list": "", "qtype": d.QType, - }) - } - for _, d := range a.logger.TopQueried(15) { - topQueried = append(topQueried, map[string]any{ - "domain": d.Name, "count": d.Count, "qtype": d.QType, "blocked": d.Blocked > 0, - }) - } - } - - problems := a.Degraded() - status := "ok" - if len(problems) > 0 { - status = "degraded" - } - out := map[string]any{ - "health": status, - "degraded_reason": strings.Join(problems, "; "), - "version": a.ver, - "node_id": a.clusterNodeID(), - "uptime_seconds": int64(time.Since(a.startedAt).Seconds()), - "queries_total": t.Queries, - "queries_per_sec": a.series.qps(), - "cache_hit_rate": hitRate, - "blocked_total": t.Blocked, - "blocked_pct": blockedPct, - "errors_total": t.Errors, - "inflight": t.Concurrent, - "series": series, - "top_blocked": topBlocked, - "top_queried": topQueried, - "upstreams": a.pool.Stats(), - "listeners": a.dns.Listeners(), - "transports": a.dns.ByTransport(), - "blocklist_rules": a.blocklistRuleCount(), - "cache_entries": a.cacheEntries(), - "config_version": a.cfg.Get().Version, - "generation": a.cfg.Generation(), - } - if a.logger != nil { - recent := a.logger.Recent(20) - items := make([]api.LogEntry, 0, len(recent)) - for _, e := range recent { - items = append(items, toLogEntry(e)) - } - out["recent"] = items - } - return out, nil -} - -func (a *App) clusterNodeID() string { - if a.cl != nil { - return a.cl.NodeID() - } - return "" -} - -func (a *App) blocklistRuleCount() int { - if a.blocks == nil { - return 0 - } - if st := a.blocks.State(); st != nil && st.Set != nil { - return st.Set.Len() - } - return 0 -} - -func (a *App) cacheEntries() int { - if a.cache == nil { - return 0 - } - return a.cache.Stats().Entries -} - -// rangeSpec is one dashboard time range. -type rangeSpec struct { - duration time.Duration - buckets int -} - -var ranges = map[string]rangeSpec{ - "15m": {duration: 15 * time.Minute, buckets: 45}, - "1h": {duration: time.Hour, buckets: 60}, - "6h": {duration: 6 * time.Hour, buckets: 72}, - "24h": {duration: 24 * time.Hour, buckets: 96}, -} diff --git a/internal/app/integration_test.go b/internal/app/integration_test.go index f1a759c..9d2c92a 100644 --- a/internal/app/integration_test.go +++ b/internal/app/integration_test.go @@ -801,87 +801,34 @@ func TestBlocklistToggle(t *testing.T) { }) } -// TestDashboardAndStatus checks the aggregate endpoints return the fields the -// UI reads, so a frontend change cannot silently drift from the API. -func TestDashboardAndStatus(t *testing.T) { +// TestStatus checks the status and health endpoints carry the sections the +// console's status page reads. +func TestStatus(t *testing.T) { h := newHarness(t, nil) h.query("www.example.test", dns.TypeA) - h.query("ads.example.com", dns.TypeA) - code, out := h.get("/api/dashboard?range=1h") - if code != 200 { - t.Fatalf("dashboard = %d", code) + code, out := h.get("/api/healthz") + if code != 200 || !strings.Contains(string(out), `"status":"ok"`) { + t.Fatalf("healthz = %d %s", code, out) } - var d struct { - Health string `json:"health"` - Queries uint64 `json:"queries_total"` - Blocked uint64 `json:"blocked_total"` - HitRate any `json:"cache_hit_rate"` - Series []any `json:"series"` - TopBlocked []struct { - Domain string `json:"domain"` - Count uint64 `json:"count"` - } `json:"top_blocked"` - Upstreams []struct { - Addr string `json:"addr"` - Health string `json:"health"` - } `json:"upstreams"` - } - if err := json.Unmarshal(out, &d); err != nil { - t.Fatal(err) - } - if d.Health != "ok" { - t.Errorf("health = %q, want ok", d.Health) - } - if d.Queries == 0 { - t.Error("queries_total is zero after two queries") - } - if d.Blocked == 0 { - t.Error("blocked_total is zero after a blocked query") - } - if len(d.Upstreams) == 0 { - t.Error("upstreams empty in dashboard") - } - if len(d.Series) == 0 { - t.Error("series empty in dashboard") - } - _ = d.HitRate - _ = d.TopBlocked - code, out = h.get("/api/status") if code != 200 { t.Fatalf("status = %d", code) } - if !strings.Contains(string(out), "listeners") { - t.Error("status has no listeners section") + var st struct { + Components map[string]json.RawMessage `json:"components"` } -} - -// TestLogsAndClear covers the query log endpoint and the clear action. -func TestLogsAndClear(t *testing.T) { - h := newHarness(t, nil) - h.query("www.example.test", dns.TypeA) - h.query("ads.example.com", dns.TypeA) - waitFor(t, 3*time.Second, func() bool { - code, out := h.get("/api/logs?limit=50") - if code != 200 { - return false + if err := json.Unmarshal(out, &st); err != nil { + t.Fatal(err) + } + for _, want := range []string{"listeners", "blocklist", "cache", "upstream", "access_log"} { + if _, ok := st.Components[want]; !ok { + t.Errorf("status has no %q section", want) } - return strings.Contains(string(out), "example.test") - }) - code, out := h.get("/api/logs?q=ads.example.com&blocked=1") - if code != 200 { - t.Fatalf("logs = %d", code) - } - if !strings.Contains(string(out), "ads.example.com") { - t.Error("filtered log did not include the blocked query") - } - if code, _ := h.do("POST", "/api/logs/clear", ""); code != 200 { - t.Errorf("clear logs = %d, want 200", code) } } -// TestCacheEndpoints covers the cache stats/top/flush trio. +// TestCacheEndpoints covers the cache stats and flush. func TestCacheEndpoints(t *testing.T) { h := newHarness(t, nil) h.query("www.example.test", dns.TypeA) @@ -900,13 +847,6 @@ func TestCacheEndpoints(t *testing.T) { if c.Shards <= 0 { t.Error("shards is zero") } - code, out = h.get("/api/cache/top?limit=10") - if code != 200 { - t.Fatalf("cache top = %d", code) - } - if !strings.Contains(string(out), "example.test") { - t.Error("cache top does not list the queried name") - } if code, _ := h.do("POST", "/api/cache/flush", ""); code != 200 { t.Errorf("flush = %d, want 200", code) } @@ -949,62 +889,6 @@ func TestReloadFromDisk(t *testing.T) { } } -// TestLogStream checks the SSE endpoint emits a ready frame and at least one -// entry frame, and that it terminates when the client disconnects. -func TestLogStream(t *testing.T) { - h := newHarness(t, nil) - req, err := httpNewRequest("GET", "http://"+h.api+"/api/logs/stream", h.key) - if err != nil { - t.Fatal(err) - } - // A streaming client must not time out while idle, so give it a generous - // deadline; the test closes the body when it has seen what it needs. - streamClient := &http.Client{Timeout: 20 * time.Second} - resp, err := streamClient.Do(req) - if err != nil { - t.Fatal(err) - } - defer resp.Body.Close() - if resp.StatusCode != 200 { - t.Fatalf("stream = %d", resp.StatusCode) - } - if ct := resp.Header.Get("Content-Type"); !strings.HasPrefix(ct, "text/event-stream") { - t.Errorf("content-type = %q, want text/event-stream", ct) - } - if resp.Header.Get("X-Accel-Buffering") != "no" { - t.Error("missing X-Accel-Buffering: no, a proxy would buffer the stream") - } - // Generate a query and read frames until we see an entry. - go func() { - time.Sleep(150 * time.Millisecond) - h.query("www.example.test", dns.TypeA) - }() - buf := make([]byte, 4096) - seen := map[string]bool{} - deadline := time.Now().Add(5 * time.Second) - for time.Now().Before(deadline) { - n, err := resp.Body.Read(buf) - if err != nil { - break - } - chunk := string(buf[:n]) - for _, ev := range []string{"event: ready", "event: entry", "event: stats"} { - if strings.Contains(chunk, ev) { - seen[ev] = true - } - } - if seen["event: ready"] && seen["event: entry"] { - break - } - } - if !seen["event: ready"] { - t.Error("no ready event") - } - if !seen["event: entry"] { - t.Error("no entry event for a query issued while streaming") - } -} - // TestMetricsEndpoint checks Prometheus output is served and protected. func TestMetricsEndpoint(t *testing.T) { h := newHarness(t, nil) @@ -1066,13 +950,13 @@ func TestConcurrentQueries(t *testing.T) { apiDone := make(chan error, workers) for w := 0; w < workers; w++ { go func() { - res, err := httpGet("http://"+h.api+"/api/dashboard", h.key) + res, err := httpGet("http://"+h.api+"/api/status", h.key) if err != nil { apiDone <- err return } if res.status != 200 { - apiDone <- fmt.Errorf("dashboard = %d", res.status) + apiDone <- fmt.Errorf("status = %d", res.status) return } apiDone <- nil diff --git a/internal/cache/cache_test.go b/internal/cache/cache_test.go index 843e70f..502a381 100644 --- a/internal/cache/cache_test.go +++ b/internal/cache/cache_test.go @@ -554,41 +554,6 @@ func TestManagerDeleteNameAndSubtree(t *testing.T) { } } -func TestManagerTopEntriesCountsAndFlush(t *testing.T) { - clk := newClock() - m := NewManager(Options{MaxTTL: time.Hour, Now: clk.Now}, nil) - for range 5 { - m.PutResponse(key("hot.example.com"), answer(t, "hot.example.com", 300, "10.0.0.5"), "up") - } - for range 2 { - m.PutResponse(key("warm.example.com"), answer(t, "warm.example.com", 300, "10.0.0.6"), "up") - } - top := m.TopEntries(10) - if len(top) < 2 { - t.Fatalf("TopEntries returned %d rows, want at least 2", len(top)) - } - // Each Put counts too, so a name queried once still shows up. - var hot, warm uint64 - for _, e := range top { - switch e.Name { - case "hot.example.com": - hot = e.Hits - case "warm.example.com": - warm = e.Hits - } - } - if hot < 5 || warm < 2 { - t.Errorf("top hits: hot=%d warm=%d, want >=5 and >=2", hot, warm) - } - if top[0].Name != "hot.example.com" { - t.Errorf("first row = %s, want the hottest name first", top[0].Name) - } - m.Flush() - if got := len(m.TopEntries(10)); got != 0 { - t.Errorf("TopEntries after Flush = %d rows, want 0", got) - } -} - func TestManagerStatsShape(t *testing.T) { clk := newClock() m := NewManager(Options{Size: 100, Shards: 4, MaxTTL: time.Hour, MinTTL: time.Second, Now: clk.Now}, nil) diff --git a/internal/cache/manager.go b/internal/cache/manager.go index 3f007c7..bb031a8 100644 --- a/internal/cache/manager.go +++ b/internal/cache/manager.go @@ -2,7 +2,6 @@ package cache import ( "math" - "sort" "strconv" "sync" "sync/atomic" @@ -61,9 +60,6 @@ type Manager struct { // It is set once at wiring time via SetPrefetcher. prefetchFn atomic.Pointer[prefetcher] - // top holds a rolling per-domain hit counter for the "top cached" UI. - top *topDomains - // Blocked counts blocklist hits served from the matcher, kept here so the // dashboard can show block volume without a second counter package. blockedSince atomic.Uint64 @@ -87,7 +83,6 @@ func NewManager(opt Options, store *Store) *Manager { opt: opt, now: opt.Now, store: store, - top: newTopDomains(5000), } // Applied after construction rather than through NewLRU so the LRU keeps // its two-argument signature; a 0 budget means unbounded. @@ -143,7 +138,6 @@ func (m *Manager) Get(k Key) Result { m.lru.Delete(k) return Result{Kind: Miss} } - m.top.observe(k, e) res := Result{ Kind: kind, Msg: msg, @@ -289,7 +283,6 @@ func (m *Manager) putWire(k Key, wire []byte, ttl uint32, origin, upstream strin copy(buf, wire) // Record the insert too, not just the hits: a name queried once must show // up in "top cached names", and a miss-only workload has no hits to count. - m.top.observe(k, &Entry{TTL: ttl, CreatedAt: now}) // Key bytes, the wire body and the entry struct: account for all three so // the LRU budget reflects real memory. e := &Entry{ @@ -414,7 +407,6 @@ func (m *Manager) Delete(k Key) { m.lru.Delete(k) } // snapshot so a restart does not resurrect it. func (m *Manager) Flush() { m.lru.Flush() - m.top.reset() if m.store != nil { _ = m.store.Truncate() } @@ -454,11 +446,6 @@ func (m *Manager) Resize(size, shards int) { // Options returns the manager's current options. func (m *Manager) Options() Options { return m.opt } -// TopEntries returns the hottest names in the cache for the UI. -func (m *Manager) TopEntries(limit int) []TopEntry { - return m.top.top(limit) -} - // Stats is the JSON-friendly cache snapshot. type Stats struct { Enabled bool `json:"enabled"` @@ -540,93 +527,3 @@ func HumanBytes(n int64) string { return neg + strconv.FormatFloat(float64(n)/(1024*1024*1024), 'f', 2, 64) + " GiB" } } - -// topDomains is a bounded, periodic top-N counter. It uses a compact -// min-heap-free approach: a plain map plus periodic pruning, which is far -// cheaper than maintaining a sorted structure on every query. -type topDomains struct { - mu sync.Mutex - counts map[string]*topCount - limit int -} - -type topCount struct { - name string - qtype uint16 - hits uint64 - bytes int64 -} - -func newTopDomains(limit int) *topDomains { - return &topDomains{counts: make(map[string]*topCount, 4096), limit: limit} -} - -func (t *topDomains) observe(k Key, e *Entry) { - if t == nil { - return - } - id := k.Name + "|" + strconv.Itoa(int(k.Type)) - t.mu.Lock() - c, ok := t.counts[id] - if !ok { - if len(t.counts) > t.limit*2 { - t.pruneLocked() - } - c = &topCount{name: k.Name, qtype: k.Type} - t.counts[id] = c - } - c.hits++ - c.bytes += int64(len(e.Wire)) - t.mu.Unlock() -} - -func (t *topDomains) pruneLocked() { - // Drop the bottom half so pruning is amortised. - type kv struct { - id string - c *topCount - } - all := make([]kv, 0, len(t.counts)) - for id, c := range t.counts { - all = append(all, kv{id, c}) - } - sort.Slice(all, func(i, j int) bool { return all[i].c.hits < all[j].c.hits }) - keep := len(all) / 2 - for _, e := range all[keep:] { - delete(t.counts, e.id) - } -} - -func (t *topDomains) reset() { - t.mu.Lock() - t.counts = make(map[string]*topCount, 4096) - t.mu.Unlock() -} - -// TopEntry is one row of the "top cached names" table. -type TopEntry struct { - Name string `json:"name"` - Type uint16 `json:"qtype"` - Hits uint64 `json:"hits"` - Bytes int64 `json:"bytes"` -} - -func (t *topDomains) top(limit int) []TopEntry { - if t == nil { - return nil - } - if limit <= 0 || limit > 500 { - limit = 50 - } - t.mu.Lock() - out := make([]TopEntry, 0, limit) - for _, c := range t.counts { - out = append(out, TopEntry{Name: c.name, Type: c.qtype, Hits: c.hits, Bytes: c.bytes}) - } - t.mu.Unlock() - sort.Slice(out, func(i, j int) bool { return out[i].Hits > out[j].Hits }) - if len(out) > limit { - out = out[:limit] - } - return out -} diff --git a/internal/config/config.go b/internal/config/config.go index 664b728..d732fd2 100644 --- a/internal/config/config.go +++ b/internal/config/config.go @@ -106,18 +106,18 @@ type Config struct { // echoed in /api/config and used to detect divergence in the cluster. Version int64 `yaml:"version,omitempty"` - Server Server `yaml:"server"` - DNS DNS `yaml:"dns"` - Upstream Upstream `yaml:"upstream"` - Cache Cache `yaml:"cache"` - Block Block `yaml:"blocklist"` - ACL ACL `yaml:"acl"` - QueryLog QueryLog `yaml:"qlog"` - Cluster Cluster `yaml:"cluster"` - API API `yaml:"api"` - Metrics Metrics `yaml:"metrics"` - Log Log `yaml:"log"` - Memory Memory `yaml:"memory"` + Server Server `yaml:"server"` + DNS DNS `yaml:"dns"` + Upstream Upstream `yaml:"upstream"` + Cache Cache `yaml:"cache"` + Block Block `yaml:"blocklist"` + ACL ACL `yaml:"acl"` + AccessLog AccessLog `yaml:"access_log"` + Cluster Cluster `yaml:"cluster"` + API API `yaml:"api"` + Metrics Metrics `yaml:"metrics"` + Log Log `yaml:"log"` + Memory Memory `yaml:"memory"` } // Server groups the process-level knobs. @@ -415,26 +415,24 @@ type Match struct { Any bool `yaml:"any" json:"any"` } -type QueryLog struct { +// AccessLog configures the access log: one JSON line on stdout for each query +// whose outcome is selected below. Nothing is stored by the resolver; the pod's +// log collector indexes the lines, and the metrics count everything. +type AccessLog struct { Enabled bool `yaml:"enabled"` - // Path is the bbolt file backing the query log ring. - Path string `yaml:"path"` - // MaxEntries bounds the ring; oldest are dropped. - MaxEntries int `yaml:"max_entries"` - // FlushInterval batches writes. - FlushInterval Duration `yaml:"flush_interval"` - // SampleRate is 0..1 for non-blocked, non-error queries. - SampleRate float64 `yaml:"sample_rate"` - // What to record. + // LogBlocked logs blocklist hits and redirects. LogBlocked bool `yaml:"log_blocked"` - LogCached bool `yaml:"log_cached"` - LogErrors bool `yaml:"log_errors"` - LogClients bool `yaml:"log_client_names"` - // LiveBuffer is the ring of recent entries kept in memory for the UI/SSE. - LiveBuffer int `yaml:"live_buffer"` - // Retention of aggregated per-domain counters. - TopDomains int `yaml:"top_domains"` - TopTTL Duration `yaml:"top_ttl"` + // LogErrors logs SERVFAILs, drops and ACL refusals. + LogErrors bool `yaml:"log_errors"` + // LogCached also logs cache hits. + LogCached bool `yaml:"log_cached"` + // SampleRate is the fraction of ordinary answers to log: 0 (the default) + // none, 1 all. It is for temporary debugging; the metrics are the + // permanent record of ordinary traffic. + SampleRate float64 `yaml:"sample_rate"` + // Buffer is how many lines may wait for the log stream before further ones + // are dropped (and counted). Zero means 4096. + Buffer int `yaml:"buffer"` } type Cluster struct { @@ -606,17 +604,10 @@ func Default() *Config { ACL: ACL{ DefaultPolicy: "allow", }, - QueryLog: QueryLog{ - Enabled: true, - MaxEntries: 200000, - FlushInterval: Duration(time.Second), - SampleRate: 1, - LogBlocked: true, - LogCached: true, - LogErrors: true, - LiveBuffer: 2000, - TopDomains: 5000, - TopTTL: Duration(5 * time.Minute), + AccessLog: AccessLog{ + Enabled: true, + LogBlocked: true, + LogErrors: true, }, Cluster: Cluster{ Enabled: false, @@ -905,20 +896,11 @@ func (c *Config) applyDefaults() { if c.ACL.DefaultPolicy == "" { c.ACL.DefaultPolicy = d.ACL.DefaultPolicy } - if c.QueryLog.MaxEntries <= 0 { - c.QueryLog.MaxEntries = d.QueryLog.MaxEntries + if c.AccessLog.SampleRate < 0 { + c.AccessLog.SampleRate = 0 } - if c.QueryLog.FlushInterval <= 0 { - c.QueryLog.FlushInterval = d.QueryLog.FlushInterval - } - if c.QueryLog.LiveBuffer <= 0 { - c.QueryLog.LiveBuffer = d.QueryLog.LiveBuffer - } - if c.QueryLog.SampleRate <= 0 { - c.QueryLog.SampleRate = 1 - } - if c.QueryLog.SampleRate > 1 { - c.QueryLog.SampleRate = 1 + if c.AccessLog.SampleRate > 1 { + c.AccessLog.SampleRate = 1 } if c.Cluster.Valkey.Prefix == "" { c.Cluster.Valkey.Prefix = d.Cluster.Valkey.Prefix @@ -1208,8 +1190,8 @@ func (c *Config) Validate() error { add("acl.groups[%d] %q: match.any is set but is also the fallback; make it the last group", i, g.Name) } } - if c.QueryLog.SampleRate < 0 || c.QueryLog.SampleRate > 1 { - add("qlog.sample_rate must be between 0 and 1") + if c.AccessLog.SampleRate < 0 || c.AccessLog.SampleRate > 1 { + add("access_log.sample_rate must be between 0 and 1") } if c.Cluster.Enabled { @@ -1341,14 +1323,6 @@ func (c *Config) CachePath() string { return c.AbsPath("data/cache.db") } -// QueryLogPath returns the resolved bbolt query-log path. -func (c *Config) QueryLogPath() string { - if c.QueryLog.Path != "" { - return c.AbsPath(c.QueryLog.Path) - } - return c.AbsPath("data/queries.db") -} - // ListPath returns the on-disk path for a list source, or "" when the source // is URL-only. func (c *Config) ListPath(l ListSource) string { diff --git a/internal/engine/engine.go b/internal/engine/engine.go index e9e2b40..28f4f32 100644 --- a/internal/engine/engine.go +++ b/internal/engine/engine.go @@ -23,13 +23,13 @@ import ( "github.com/miekg/dns" + "git.k8s-git-k6n.net/mats/fancy-dns/internal/accesslog" "git.k8s-git-k6n.net/mats/fancy-dns/internal/acl" "git.k8s-git-k6n.net/mats/fancy-dns/internal/blocklist" "git.k8s-git-k6n.net/mats/fancy-dns/internal/cache" "git.k8s-git-k6n.net/mats/fancy-dns/internal/config" "git.k8s-git-k6n.net/mats/fancy-dns/internal/localzone" "git.k8s-git-k6n.net/mats/fancy-dns/internal/metrics" - "git.k8s-git-k6n.net/mats/fancy-dns/internal/qlog" "git.k8s-git-k6n.net/mats/fancy-dns/internal/resolver" ) @@ -69,7 +69,7 @@ type Request struct { type Response struct { Msg *dns.Msg // Action is the pipeline classification. - Action qlog.Action + Action accesslog.Action // Group is the matched ACL group. Group string // BlockSource is the blocklist/rule that blocked the query, for the log. @@ -111,7 +111,7 @@ type Engine struct { aclH *acl.Holder local *localzone.Holder pool atomic.Pointer[resolver.Pool] - logger *qlog.Logger + logger *accesslog.Logger reverse *ReverseCache // concurrency limiter: a buffered channel as a semaphore, which is @@ -161,7 +161,7 @@ type Options struct { // Config is the hot-reloadable config store. Config *config.Store // Logger receives query entries; may be nil. - Logger *qlog.Logger + Logger *accesslog.Logger // Blocklists is the compiled blocklist holder. Blocklists *blocklist.Holder // Cache is the answer cache. @@ -236,7 +236,7 @@ func (e *Engine) applyConfig(cfg *config.Config) { } // Logger exposes the query logger (may be nil). -func (e *Engine) Logger() *qlog.Logger { return e.logger } +func (e *Engine) Logger() *accesslog.Logger { return e.logger } // Cache exposes the answer cache (may be nil). func (e *Engine) Cache() *cache.Manager { return e.cache } @@ -288,7 +288,7 @@ func (e *Engine) Handle(ctx context.Context, req Request) Response { if err == errNotImplemented { res.Msg = notImpl(q) } - res.Action = qlog.ActionError + res.Action = accesslog.ActionError e.finish(req, res, start, decision) return res } @@ -300,7 +300,7 @@ func (e *Engine) Handle(ctx context.Context, req Request) Response { // denied a client means it. if !decision.Allows() { res.Msg = refuse(q, decision) - res.Action = qlog.ActionRefused + res.Action = accesslog.ActionRefused e.finish(req, res, start, decision) return res } @@ -310,7 +310,7 @@ func (e *Engine) Handle(ctx context.Context, req Request) Response { if cl := decision.MaxConcurrent; cl > 0 { if !e.acquireClient(client, cl) { res.Msg = servFail(q, "client concurrency limit") - res.Action = qlog.ActionError + res.Action = accesslog.ActionError e.finish(req, res, start, decision) return res } @@ -327,7 +327,7 @@ func (e *Engine) Handle(ctx context.Context, req Request) Response { default: e.dropped.Add(1) res.Msg = servFail(q, "server overloaded") - res.Action = qlog.ActionError + res.Action = accesslog.ActionError e.finish(req, res, start, decision) return res } @@ -336,7 +336,7 @@ func (e *Engine) Handle(ctx context.Context, req Request) Response { // Rate limiting. if decision.RateLimit > 0 && !e.allowRate(client, decision.RateLimit) { res.Msg = refuse(q, decision) - res.Action = qlog.ActionRefused + res.Action = accesslog.ActionRefused e.finish(req, res, start, decision) return res } @@ -344,7 +344,7 @@ func (e *Engine) Handle(ctx context.Context, req Request) Response { // Group-level domain policy. if e.groupBlocks(decision, qname) { res.Msg = e.finalize(blockedResponse(q, e.blockCfg(), nil), q, req) - res.Action = qlog.ActionBlock + res.Action = accesslog.ActionBlock res.BlockSource = "acl:" + decision.Group e.finish(req, res, start, decision) return res @@ -354,7 +354,7 @@ func (e *Engine) Handle(ctx context.Context, req Request) Response { if store := e.local.Get(); store != nil && store.Count() > 0 { if local, ok := e.answerLocal(q, store); ok { res.Msg = e.finalize(local, q, req) - res.Action = qlog.ActionAllow + res.Action = accesslog.ActionAllow // Authoritative local data is ActionAllow for the query log (the // query was permitted and answered), but it is its own metrics // outcome: counting it as upstream inflated the upstream column @@ -375,7 +375,7 @@ func (e *Engine) Handle(ctx context.Context, req Request) Response { if blocked != nil && !blocked.IsAllow() { switch blocked.Action { case blocklist.ActionDrop: - res.Action = qlog.ActionDrop + res.Action = accesslog.ActionDrop res.BlockSource = blocked.Source res.Drop = true res.Duration = time.Since(start) @@ -383,14 +383,14 @@ func (e *Engine) Handle(ctx context.Context, req Request) Response { return res case blocklist.ActionRedirect, blocklist.ActionCNAME: res.Msg = e.finalize(e.blockedMsg(q, blocked), q, req) - res.Action = qlog.ActionRedirect + res.Action = accesslog.ActionRedirect res.BlockSource = blocked.Source res.CacheHit = false e.finish(req, res, start, decision) return res default: res.Msg = e.finalize(e.blockedMsg(q, blocked), q, req) - res.Action = qlog.ActionBlock + res.Action = accesslog.ActionBlock res.BlockSource = blocked.Source res.CacheHit = false e.finish(req, res, start, decision) @@ -414,7 +414,7 @@ func (e *Engine) Handle(ctx context.Context, req Request) Response { metrics.RecordStaleHit() } res.Msg = e.finalize(res.Msg, q, req) - res.Action = qlog.ActionCached + res.Action = accesslog.ActionCached if hit.Kind == cache.Stale { // The cached answer is expired, so its TTL is 0; hand back a // short one so clients do not cache the stale copy forever. @@ -432,7 +432,7 @@ func (e *Engine) Handle(ctx context.Context, req Request) Response { pool := e.pool.Load() if pool == nil { res.Msg = servFail(q, "no upstream configured") - res.Action = qlog.ActionError + res.Action = accesslog.ActionError e.finish(req, res, start, decision) return res } @@ -450,7 +450,7 @@ func (e *Engine) Handle(ctx context.Context, req Request) Response { if err != nil || up == nil { metrics.RecordUpstreamError() res.Msg = servFail(q, "upstream failure: "+shortErr(err)) - res.Action = qlog.ActionError + res.Action = accesslog.ActionError e.finish(req, res, start, decision) return res } @@ -466,13 +466,13 @@ func (e *Engine) Handle(ctx context.Context, req Request) Response { reply := e.finalize(e.fromUpstream(q, up, req), q, req) res.Msg = reply res.Upstream = addr - res.Action = qlog.ActionAllow + res.Action = accesslog.ActionAllow // A non-success RCODE is reported as an error through finish's metrics // call, so the counters stay in one place. if reply.Rcode != dns.RcodeServerFailure && reply.Rcode != dns.RcodeSuccess { - res.Action = qlog.ActionError + res.Action = accesslog.ActionError } else if reply.Rcode == dns.RcodeServerFailure { - res.Action = qlog.ActionError + res.Action = accesslog.ActionError } if e.cache != nil && !decision.SkipCache { key := cache.QueryKey(qname, qtype, q.Question[0].Qclass, cache.Do(q), 0) @@ -486,27 +486,33 @@ func (e *Engine) Handle(ctx context.Context, req Request) Response { return res } -// finish attaches duration, records metrics and writes the query log. +// finish attaches duration, records metrics and writes the access log line when the outcome calls for one. func (e *Engine) finish(req Request, res Response, start time.Time, d acl.Decision) { if res.Duration == 0 { res.Duration = time.Since(start) } metrics.Record(req.Transport, outcomeFor(res), res.Duration) - if res.Action == qlog.ActionAllow && res.CacheHit { + if res.Action == accesslog.ActionAllow && res.CacheHit { metrics.Record(req.Transport, metrics.OutcomeCache, res.Duration) } e.groupStats.observe(d.Group, res) + metrics.RecordGroupQuery(d.Group, outcomeFor(res)) + rcode := "none" + if res.Msg != nil { + rcode = rcodeLabel(res.Msg.Rcode) + } + metrics.RecordRcode(rcode) if e.logger == nil { return } if !e.logger.ShouldLog(res.Action) && !d.LogQueries { return } - entry := qlog.Entry{ + entry := accesslog.Entry{ TS: start, Client: res.Client, Group: res.Group, - Duration: res.Duration.Milliseconds(), + Duration: res.Duration, Action: res.Action, Upstream: res.Upstream, List: res.BlockSource, @@ -518,6 +524,14 @@ func (e *Engine) finish(req Request, res Response, start time.Time, d acl.Decisi e.logger.Log(entry) } +// rcodeLabel is the metric label for an RCODE. +func rcodeLabel(c int) string { + if s, ok := dns.RcodeToString[c]; ok { + return s + } + return "OTHER" +} + // outcomeFor maps a finished query onto its metrics outcome. The action alone // is not enough: ActionAllow covers both an upstream answer and a local-zone // answer, and the two are different things for an operator reading the @@ -527,15 +541,15 @@ func outcomeFor(res Response) string { return metrics.OutcomeLocal } switch res.Action { - case qlog.ActionCached: + case accesslog.ActionCached: return metrics.OutcomeCache - case qlog.ActionBlock: + case accesslog.ActionBlock: return metrics.OutcomeBlocked - case qlog.ActionRedirect: + case accesslog.ActionRedirect: return metrics.OutcomeLocal - case qlog.ActionError, qlog.ActionDrop: + case accesslog.ActionError, accesslog.ActionDrop: return metrics.OutcomeError - case qlog.ActionRefused: + case accesslog.ActionRefused: return metrics.OutcomeRefused default: return metrics.OutcomeUpstream @@ -1174,11 +1188,11 @@ func (t *groupStatTable) observe(group string, res Response) { } s.queries++ switch res.Action { - case qlog.ActionBlock: + case accesslog.ActionBlock: s.blocked++ - case qlog.ActionError, qlog.ActionDrop: + case accesslog.ActionError, accesslog.ActionDrop: s.errors++ - case qlog.ActionCached: + case accesslog.ActionCached: s.cache++ } t.mu.Unlock() diff --git a/internal/engine/engine_test.go b/internal/engine/engine_test.go index fc86310..d581436 100644 --- a/internal/engine/engine_test.go +++ b/internal/engine/engine_test.go @@ -9,11 +9,11 @@ import ( "github.com/miekg/dns" + "git.k8s-git-k6n.net/mats/fancy-dns/internal/accesslog" "git.k8s-git-k6n.net/mats/fancy-dns/internal/acl" "git.k8s-git-k6n.net/mats/fancy-dns/internal/blocklist" "git.k8s-git-k6n.net/mats/fancy-dns/internal/cache" "git.k8s-git-k6n.net/mats/fancy-dns/internal/config" - "git.k8s-git-k6n.net/mats/fancy-dns/internal/qlog" ) // testZone is the local zone the harness loads when a test asks for one. @@ -55,7 +55,7 @@ func TestACLDenyWinsOverLocalZone(t *testing.T) { for _, name := range []string{"host.local.", "denied.local."} { res := h.ask(name, dns.TypeA) requireRcode(t, res, dns.RcodeRefused) - requireAction(t, res, qlog.ActionRefused) + requireAction(t, res, accesslog.ActionRefused) if res.Group != "test" { t.Fatalf("group = %q, want %q", res.Group, "test") } @@ -79,7 +79,7 @@ func TestLocalZoneWinsOverBlocklist(t *testing.T) { }) res := h.ask("host.local.", dns.TypeA) - requireAction(t, res, qlog.ActionAllow) + requireAction(t, res, accesslog.ActionAllow) if got := answerA(res.Msg); got != "192.168.1.5" { t.Fatalf("answer = %q, want 192.168.1.5 (blocked instead?)", got) } @@ -128,7 +128,7 @@ func TestBlocklistWinsOverCache(t *testing.T) { } res := h.ask("blocked.example.test.", dns.TypeA) - requireAction(t, res, qlog.ActionBlock) + requireAction(t, res, accesslog.ActionBlock) requireRcode(t, res, dns.RcodeNameError) if res.CacheHit { t.Fatal("a blocked query reported a cache hit: the cache outranked the blocklist") @@ -155,7 +155,7 @@ func TestBlocklistDropSendsNothing(t *testing.T) { if res.Msg != nil { t.Fatal("a dropped query produced a message to send") } - requireAction(t, res, qlog.ActionDrop) + requireAction(t, res, accesslog.ActionDrop) requireNoUpstreamHit(t, h, "drop.example.test.") } @@ -167,12 +167,12 @@ func TestAllowRuleBeatsBlockRule(t *testing.T) { {Name: "ok.example.test", Action: blocklist.ActionAllow}, }}) res := h.ask("ok.example.test.", dns.TypeA) - requireAction(t, res, qlog.ActionAllow) + requireAction(t, res, accesslog.ActionAllow) if got := answerA(res.Msg); got != "203.0.113.7" { t.Fatalf("answer = %q, want the upstream address 203.0.113.7", got) } blocked := h.ask("ads.example.test.", dns.TypeA) - requireAction(t, blocked, qlog.ActionBlock) + requireAction(t, blocked, accesslog.ActionBlock) } // TestGlobalConcurrencyCapRefuses pins the overload refusal: a saturated @@ -196,7 +196,7 @@ func TestGlobalConcurrencyCapRefuses(t *testing.T) { h.up.waitArrived(t) second := h.ask("other.example.test.", dns.TypeA) requireRcode(t, second, dns.RcodeServerFailure) - requireAction(t, second, qlog.ActionError) + requireAction(t, second, accesslog.ActionError) if h.eng.Dropped() != 1 { t.Fatalf("dropped = %d, want 1", h.eng.Dropped()) } @@ -206,7 +206,7 @@ func TestGlobalConcurrencyCapRefuses(t *testing.T) { open() wg.Wait() res := <-first - requireAction(t, res, qlog.ActionAllow) + requireAction(t, res, accesslog.ActionAllow) if got := answerA(res.Msg); got != "203.0.113.7" { t.Fatalf("first answer = %q, want 203.0.113.7", got) } @@ -246,7 +246,7 @@ func TestPerClientConcurrencyCapRefuses(t *testing.T) { open() wg.Wait() - requireAction(t, <-first, qlog.ActionAllow) + requireAction(t, <-first, accesslog.ActionAllow) } // TestRateLimitRefuses pins the fixed-window rate limit: the first N queries @@ -259,11 +259,11 @@ func TestRateLimitRefuses(t *testing.T) { // Distinct names, so the cache cannot turn the second query into a // hit and mask what is being asserted. res := h.ask(fmt.Sprintf("rate%d.example.test.", i), dns.TypeA) - requireAction(t, res, qlog.ActionAllow) + requireAction(t, res, accesslog.ActionAllow) } res := h.ask("rate2.example.test.", dns.TypeA) requireRcode(t, res, dns.RcodeRefused) - requireAction(t, res, qlog.ActionRefused) + requireAction(t, res, accesslog.ActionRefused) } // TestGroupDomainPolicy pins the per-group allow/deny lists, which run after @@ -278,19 +278,19 @@ func TestGroupDomainPolicy(t *testing.T) { }, }) res := h.ask("denied.example.test.", dns.TypeA) - requireAction(t, res, qlog.ActionBlock) + requireAction(t, res, accesslog.ActionBlock) if res.BlockSource != "acl:test" { t.Fatalf("block source = %q, want acl:test", res.BlockSource) } // A subdomain of a denied name is denied too. - if sub := h.ask("sub.denied.example.test.", dns.TypeA); sub.Action != qlog.ActionBlock { + if sub := h.ask("sub.denied.example.test.", dns.TypeA); sub.Action != accesslog.ActionBlock { t.Fatalf("subdomain action = %q, want block", sub.Action) } - if sib := h.ask("sibling.example.test.", dns.TypeA); sib.Action != qlog.ActionAllow { + if sib := h.ask("sibling.example.test.", dns.TypeA); sib.Action != accesslog.ActionAllow { t.Fatalf("sibling action = %q, want allow: the deny list leaked", sib.Action) } allowed := h.ask("allowed.example.test.", dns.TypeA) - requireAction(t, allowed, qlog.ActionAllow) + requireAction(t, allowed, accesslog.ActionAllow) if got := answerA(allowed.Msg); got != "203.0.113.7" { t.Fatalf("answer = %q, want 203.0.113.7", got) } @@ -302,11 +302,11 @@ func TestGroupDomainPolicy(t *testing.T) { *a = loopbackGroup(config.Group{DenyDomains: []string{"denied.example.test."}}) }, }) - if res := h.ask("denied.example.test.", dns.TypeA); res.Action != qlog.ActionBlock { + if res := h.ask("denied.example.test.", dns.TypeA); res.Action != accesslog.ActionBlock { t.Fatalf("exact name: action = %q, want block", res.Action) } // Documented behaviour of a rule without a wildcard: the apex only. - if sub := h.ask("sub.denied.example.test.", dns.TypeA); sub.Action != qlog.ActionAllow { + if sub := h.ask("sub.denied.example.test.", dns.TypeA); sub.Action != accesslog.ActionAllow { t.Fatalf("subdomain of an exact rule: action = %q, want allow", sub.Action) } }) @@ -317,11 +317,11 @@ func TestGroupDomainPolicy(t *testing.T) { *a = loopbackGroup(config.Group{AllowDomains: []string{"only.example.test."}}) }, }) - if res := h.ask("other.example.test.", dns.TypeA); res.Action != qlog.ActionBlock { + if res := h.ask("other.example.test.", dns.TypeA); res.Action != accesslog.ActionBlock { t.Fatalf("non-allowlisted name: action = %q, want block", res.Action) } allowed := h.ask("only.example.test.", dns.TypeA) - requireAction(t, allowed, qlog.ActionAllow) + requireAction(t, allowed, accesslog.ActionAllow) if got := answerA(allowed.Msg); got != "203.0.113.7" { t.Fatalf("answer = %q, want 203.0.113.7", got) } @@ -337,7 +337,7 @@ func TestSkipToggles(t *testing.T) { rules: []blocklist.Rule{{Name: "blocked.example.test"}}, }) res := h.ask("blocked.example.test.", dns.TypeA) - requireAction(t, res, qlog.ActionAllow) + requireAction(t, res, accesslog.ActionAllow) if got := answerA(res.Msg); got != "203.0.113.7" { t.Fatalf("answer = %q, want 203.0.113.7 (the blocklist still applies)", got) } @@ -349,7 +349,7 @@ func TestSkipToggles(t *testing.T) { }) for i := 0; i < 2; i++ { res := h.ask("nocache.example.test.", dns.TypeA) - requireAction(t, res, qlog.ActionAllow) + requireAction(t, res, accesslog.ActionAllow) if res.CacheKind != "" { t.Fatalf("query %d: cache kind = %q, want none", i, res.CacheKind) } @@ -364,7 +364,7 @@ func TestSkipToggles(t *testing.T) { func TestCacheHitDoesNotReachUpstream(t *testing.T) { h := newHarness(t, hopt{}) first := h.ask("cached.example.test.", dns.TypeA) - requireAction(t, first, qlog.ActionAllow) + requireAction(t, first, accesslog.ActionAllow) if first.CacheHit { t.Fatal("the first query reported a cache hit") } @@ -376,7 +376,7 @@ func TestCacheHitDoesNotReachUpstream(t *testing.T) { if !second.CacheHit || second.CacheKind != "hit" { t.Fatalf("second query: hit=%v kind=%q, want a fresh hit", second.CacheHit, second.CacheKind) } - requireAction(t, second, qlog.ActionCached) + requireAction(t, second, accesslog.ActionCached) if got := answerA(second.Msg); got != "203.0.113.7" { t.Fatalf("answer = %q, want 203.0.113.7", got) } @@ -398,7 +398,7 @@ func TestServeStaleAgesToOneAndRefreshesOnce(t *testing.T) { h := newHarness(t, hopt{serveStale: 10 * time.Minute, clock: true}) first := h.ask("stale.example.test.", dns.TypeA) - requireAction(t, first, qlog.ActionAllow) + requireAction(t, first, accesslog.ActionAllow) // Expire the entry: the upstream TTL is 60s. h.advance(61 * time.Second) @@ -544,7 +544,7 @@ func TestMalformedQueriesAreFormErr(t *testing.T) { before := h.totals() res := h.askWith(Request{Msg: q, Remote: h.request("a.example.test.", dns.TypeA).Remote, Transport: "udp"}) requireRcode(t, res, dns.RcodeFormatError) - requireAction(t, res, qlog.ActionError) + requireAction(t, res, accesslog.ActionError) if got := h.totals().Queries - before.Queries; got != 1 { t.Fatalf("%s: metrics recorded %d queries, want 1", name, got) } @@ -565,14 +565,14 @@ func TestMetricsAndQueryLogFireOncePerQuery(t *testing.T) { // be counted exactly once. queries int send func(*harness) - want qlog.Action + want accesslog.Action }{ { name: "upstream answer", opt: hopt{}, queries: 1, send: func(h *harness) { h.ask("once.example.test.", dns.TypeA) }, - want: qlog.ActionAllow, + want: accesslog.ActionAllow, }, { name: "cache hit", @@ -582,14 +582,14 @@ func TestMetricsAndQueryLogFireOncePerQuery(t *testing.T) { h.ask("once.example.test.", dns.TypeA) h.ask("once.example.test.", dns.TypeA) }, - want: qlog.ActionCached, + want: accesslog.ActionCached, }, { name: "blocked", opt: hopt{rules: []blocklist.Rule{{Name: "blocked.example.test"}}}, queries: 1, send: func(h *harness) { h.ask("blocked.example.test.", dns.TypeA) }, - want: qlog.ActionBlock, + want: accesslog.ActionBlock, }, { name: "refused", @@ -598,7 +598,7 @@ func TestMetricsAndQueryLogFireOncePerQuery(t *testing.T) { send: func(h *harness) { h.ask("denied.example.test.", dns.TypeA) }, - want: qlog.ActionRefused, + want: accesslog.ActionRefused, }, } @@ -613,11 +613,11 @@ func TestMetricsAndQueryLogFireOncePerQuery(t *testing.T) { t.Fatalf("metrics counted %d queries, want exactly %d", got, tc.queries) } if got := h.logged() - beforeLog; got != tc.queries { - t.Fatalf("query log holds %d new entries, want exactly %d", got, tc.queries) + t.Fatalf("access log holds %d new entries, want exactly %d", got, tc.queries) } entries := h.entries() if len(entries) == 0 { - t.Fatal("the newest entry is missing from the live ring") + t.Fatal("the newest entry is missing from the access log") } e := entries[0] if e.Action != tc.want { @@ -630,15 +630,9 @@ func TestMetricsAndQueryLogFireOncePerQuery(t *testing.T) { t.Fatalf("logged protocol = %q, want udp", e.Protocol) } if len(entries) != tc.queries { - t.Fatalf("the live ring holds %d entries, want %d: the hook fired more than once per query", + t.Fatalf("the access log holds %d entries, want %d: the hook fired more than once per query", len(entries), tc.queries) } - for i := 0; i+1 < len(entries); i++ { - if entries[i].ID-entries[i+1].ID != 1 { - t.Fatalf("entries %d and %d are not adjacent (ids %d, %d): the hook fired more than once per query", - i+1, i, entries[i+1].ID, entries[i].ID) - } - } }) } } @@ -649,7 +643,7 @@ func TestNoUpstreamIsServfail(t *testing.T) { h := newHarness(t, hopt{noPool: true}) res := h.ask("nowhere.example.test.", dns.TypeA) requireRcode(t, res, dns.RcodeServerFailure) - requireAction(t, res, qlog.ActionError) + requireAction(t, res, accesslog.ActionError) } // TestDeadUpstreamIsServfail pins upstream failure handling: the exchange @@ -669,7 +663,7 @@ func TestDeadUpstreamIsServfail(t *testing.T) { before := h.totals() res := h.ask("dead.example.test.", dns.TypeA) requireRcode(t, res, dns.RcodeServerFailure) - requireAction(t, res, qlog.ActionError) + requireAction(t, res, accesslog.ActionError) if got := h.totals().Errors - before.Errors; got != 1 { t.Fatalf("errors rose by %d, want 1", got) } @@ -745,7 +739,7 @@ func TestReplyEchoesTheClientQuestionAndID(t *testing.T) { req := h.request("HoSt.ExAmPlE.TeSt.", dns.TypeA) req.Msg.Id = 0x1234 res := h.askWith(req) - requireAction(t, res, qlog.ActionAllow) + requireAction(t, res, accesslog.ActionAllow) if res.Msg.Id != 0x1234 { t.Fatalf("reply id = %#x, want 0x1234", res.Msg.Id) } diff --git a/internal/engine/harness_test.go b/internal/engine/harness_test.go index 74e4db8..97a55b9 100644 --- a/internal/engine/harness_test.go +++ b/internal/engine/harness_test.go @@ -1,7 +1,9 @@ package engine import ( + "bytes" "context" + "encoding/json" "net" "net/netip" "os" @@ -13,13 +15,13 @@ import ( "github.com/miekg/dns" + "git.k8s-git-k6n.net/mats/fancy-dns/internal/accesslog" "git.k8s-git-k6n.net/mats/fancy-dns/internal/acl" "git.k8s-git-k6n.net/mats/fancy-dns/internal/blocklist" "git.k8s-git-k6n.net/mats/fancy-dns/internal/cache" "git.k8s-git-k6n.net/mats/fancy-dns/internal/config" "git.k8s-git-k6n.net/mats/fancy-dns/internal/localzone" "git.k8s-git-k6n.net/mats/fancy-dns/internal/metrics" - "git.k8s-git-k6n.net/mats/fancy-dns/internal/qlog" "git.k8s-git-k6n.net/mats/fancy-dns/internal/resolver" ) @@ -266,7 +268,8 @@ type harness struct { store *config.Store pool *resolver.Pool cache *cache.Manager - log *qlog.Logger + log *accesslog.Logger + lines *lineSink up *fakeUpstream clock *testClock blocks *blocklist.Holder @@ -353,20 +356,12 @@ func newHarness(t *testing.T, o hopt) *harness { Now: clock.Now, }, nil) - log, err := qlog.New(qlog.Options{ - LiveBuffer: 64, - SampleRate: 1, - // Every action is logged, so a test can count entries without - // reasoning about the sampling policy. - LogBlocked: true, - LogCached: true, - LogErrors: true, - TopDomains: 16, - TopTTL: time.Minute, + lines := &lineSink{} + // Every action is logged, so a test can count entries without reasoning + // about the sampling policy. + log := accesslog.New(accesslog.Options{ + Writer: lines, SampleRate: 1, LogBlocked: true, LogCached: true, LogErrors: true, }) - if err != nil { - t.Fatalf("qlog: %v", err) - } t.Cleanup(func() { _ = log.Close() }) blocks := blocklist.NewHolder(buildSet(o.rules...)) @@ -387,7 +382,7 @@ func newHarness(t *testing.T, o hopt) *harness { } h := &harness{ - t: t, eng: eng, cfg: cfg, store: store, cache: cm, log: log, + t: t, eng: eng, cfg: cfg, store: store, cache: cm, log: log, lines: lines, up: up, clock: clock, blocks: blocks, local: localH, aclH: aclH, } if !o.noPool { @@ -446,9 +441,16 @@ func (h *harness) askTCP(name string, qtype uint16) Response { return h.askWith(req) } -func (h *harness) entries() []qlog.Entry { return h.log.Recent(64) } +// entries returns the access-log lines written so far, newest first. +func (h *harness) entries() []accesslog.Entry { + h.log.Flush() + return h.lines.entries() +} -func (h *harness) logged() int { return h.log.Count() } +func (h *harness) logged() int { + h.log.Flush() + return h.lines.count() +} func (h *harness) totals() metrics.Totals { return metrics.TotalsNow() } @@ -484,7 +486,7 @@ func requireRcode(t *testing.T, res Response, rcode int) { } } -func requireAction(t *testing.T, res Response, want qlog.Action) { +func requireAction(t *testing.T, res Response, want accesslog.Action) { t.Helper() if res.Action != want { t.Fatalf("action = %q, want %q", res.Action, want) @@ -497,3 +499,59 @@ func requireNoUpstreamHit(t *testing.T, h *harness, name string) { t.Fatalf("upstream saw %d queries for %s, want 0", n, name) } } + +// lineSink collects the access log's output so a test can read it back. +type lineSink struct { + mu sync.Mutex + buf []byte + rows []accesslog.Entry +} + +func (s *lineSink) Write(p []byte) (int, error) { + s.mu.Lock() + defer s.mu.Unlock() + s.buf = append(s.buf, p...) + for { + i := bytes.IndexByte(s.buf, '\n') + if i < 0 { + break + } + line := s.buf[:i] + s.buf = s.buf[i+1:] + var raw struct { + Client string `json:"client"` + Group string `json:"client_group"` + Name string `json:"name"` + Action string `json:"action"` + Protocol string `json:"protocol"` + List string `json:"list"` + Upstream string `json:"upstream"` + Duration float64 `json:"duration_ms"` + } + if err := json.Unmarshal(line, &raw); err != nil { + panic("access log line is not JSON: " + string(line)) + } + s.rows = append(s.rows, accesslog.Entry{ + Client: raw.Client, Group: raw.Group, Name: raw.Name, + Action: accesslog.Action(raw.Action), Protocol: raw.Protocol, + List: raw.List, Upstream: raw.Upstream, + }) + } + return len(p), nil +} + +func (s *lineSink) count() int { + s.mu.Lock() + defer s.mu.Unlock() + return len(s.rows) +} + +func (s *lineSink) entries() []accesslog.Entry { + s.mu.Lock() + defer s.mu.Unlock() + out := make([]accesslog.Entry, len(s.rows)) + for i, r := range s.rows { + out[len(s.rows)-1-i] = r + } + return out +} diff --git a/internal/engine/pins_test.go b/internal/engine/pins_test.go index 8ea3ee1..58524f7 100644 --- a/internal/engine/pins_test.go +++ b/internal/engine/pins_test.go @@ -8,9 +8,9 @@ import ( "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" - "git.k8s-git-k6n.net/mats/fancy-dns/internal/qlog" "github.com/miekg/dns" ) @@ -47,7 +47,7 @@ func outcomeCount(t *testing.T, outcome string) uint64 { // TestPinnedLocalAnswersAreCountedAsUpstream pins the gap STATUS.md called // "metrics.OutcomeLocal has no producer": a query answered from the local -// zone reports qlog.ActionAllow, and outcomeFor maps ActionAllow to +// 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. @@ -64,7 +64,7 @@ func TestLocallyAnsweredQueryIsCountedAsLocal(t *testing.T) { upBefore := outcomeCount(t, metrics.OutcomeUpstream) localBefore := outcomeCount(t, metrics.OutcomeLocal) res := h.ask("host.local.", dns.TypeA) - requireAction(t, res, qlog.ActionAllow) + 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) } diff --git a/internal/metrics/metrics.go b/internal/metrics/metrics.go index 2fd8ea4..12c67c1 100644 --- a/internal/metrics/metrics.go +++ b/internal/metrics/metrics.go @@ -7,7 +7,6 @@ package metrics import ( - "math" "sync" "sync/atomic" "time" @@ -30,6 +29,9 @@ var ( cacheStaleHits prometheus.Counter coalesced prometheus.Counter prefetches prometheus.Counter + logDropped prometheus.Counter + groupQueries *prometheus.CounterVec + rcodes *prometheus.CounterVec upstreamErrors prometheus.Counter dnsErrors prometheus.Counter dropsTotal prometheus.Counter @@ -92,6 +94,18 @@ func initCollectors() { Namespace: Namespace, Name: "cache_prefetch_total", Help: "Background refreshes started for an entry that was stale or close to expiry.", }) + logDropped = prometheus.NewCounter(prometheus.CounterOpts{ + Namespace: Namespace, Name: "access_log_dropped_total", + Help: "Access-log lines discarded because the log stream could not keep up.", + }) + groupQueries = prometheus.NewCounterVec(prometheus.CounterOpts{ + Namespace: Namespace, Name: "group_queries_total", + Help: "Queries by ACL group and outcome. The group is empty-named \"default\" when no group matched.", + }, []string{"group", "outcome"}) + rcodes = prometheus.NewCounterVec(prometheus.CounterOpts{ + Namespace: Namespace, Name: "responses_total", + Help: "Responses by RCODE.", + }, []string{"rcode"}) upstreamErrors = prometheus.NewCounter(prometheus.CounterOpts{ Namespace: Namespace, Name: "upstream_errors_total", Help: "Upstream exchange failures.", @@ -153,7 +167,7 @@ func initCollectors() { }) Registry.MustRegister( - queriesTotal, blockedTotal, cacheHits, cacheMisses, cacheStaleHits, coalesced, prefetches, + queriesTotal, blockedTotal, cacheHits, cacheMisses, cacheStaleHits, coalesced, prefetches, logDropped, groupQueries, rcodes, upstreamErrors, dnsErrors, dropsTotal, refusedTotal, upstreamHealth, concurrentNow, listCount, listBytes, aclGroups, localRecords, up, queryDuration, upstreamDur, parseDuration, @@ -221,6 +235,21 @@ func RecordStaleHit() { initCollectors(); cacheStaleHits.Inc(); staleHits.Add(1) // RecordCoalesced counts a query that shared an in-flight upstream exchange. func RecordCoalesced() { initCollectors(); coalesced.Inc() } +// RecordAccessLogDropped counts an access-log line that was discarded. +func RecordAccessLogDropped() { initCollectors(); logDropped.Inc() } + +// RecordGroupQuery counts a finished query against its ACL group. +func RecordGroupQuery(group, outcome string) { + initCollectors() + if group == "" { + group = "default" + } + groupQueries.WithLabelValues(group, outcome).Inc() +} + +// RecordRcode counts a response by RCODE name. +func RecordRcode(rcode string) { initCollectors(); rcodes.WithLabelValues(rcode).Inc() } + // RecordPrefetch counts a background refresh. func RecordPrefetch() { initCollectors(); prefetches.Inc() } @@ -349,148 +378,3 @@ func CountDrop() { drops.Add(1) } // CountRefused increments the refused counter. func CountRefused() { refused.Add(1) } - -// Series is a fixed-window time series for the UI charts. -type Series struct { - // Buckets are the sample timestamps (epoch seconds), oldest first. - Buckets []int64 `json:"t"` - Values []int64 `json:"v"` - // ResolutionMS is the bucket width. - ResolutionMS int64 `json:"resolution_ms"` -} - -// Ring is a fixed-bucket counter ring: a circular array of counts indexed by -// bucket number. Lock-free on the write path, which matters because it is hit -// once per DNS query. -type Ring struct { - buckets []atomic.Int64 - res time.Duration - start atomic.Int64 // first bucket timestamp, epoch seconds - pos atomic.Uint32 - sealed atomic.Bool - count int -} - -// NewRing builds a ring of n buckets at the given resolution. -func NewRing(n int, res time.Duration) *Ring { - if n <= 0 { - n = 120 - } - if res <= 0 { - res = 5 * time.Second - } - r := &Ring{buckets: make([]atomic.Int64, n), res: res, count: n} - r.start.Store(time.Now().Unix()) - return r -} - -// Inc bumps the current bucket by 1, rotating when the window advances. -func (r *Ring) Inc() { r.Add(1) } - -// Add bumps the current bucket. -func (r *Ring) Add(delta int64) { - if r == nil { - return - } - now := time.Now().Unix() - bucket := now / int64(r.res.Seconds()) - start := r.start.Load() - // If more than count buckets elapsed, we skipped a full window: reset - // everything so a long idle period does not report phantom zeros followed - // by a sudden spike. - if bucket-start >= int64(r.count) { - if r.start.CompareAndSwap(start, bucket-int64(r.count)+1) { - for i := range r.buckets { - r.buckets[i].Store(0) - } - } - start = r.start.Load() - } - if bucket < start { - return - } - idx := int(bucket - start) - if idx >= r.count { - idx = r.count - 1 - } - // Store at the position implied by the bucket so readers can map index to - // time without extra bookkeeping. - r.buckets[idx%r.count].Add(delta) -} - -// AddAt bumps an explicit bucket (used by tests). -func (r *Ring) AddAt(bucket int64, delta int64) { - start := r.start.Load() - idx := int(bucket - start) - if idx < 0 || idx >= r.count { - return - } - r.buckets[idx%r.count].Add(delta) -} - -// Series snapshots the ring into aligned arrays. -func (r *Ring) Snapshot() ([]int64, []int64) { - if r == nil { - return nil, nil - } - start := r.start.Load() - now := time.Now().Unix() - step := int64(r.res.Seconds()) - ts := make([]int64, r.count) - vs := make([]int64, r.count) - for i := 0; i < r.count; i++ { - b := start + int64(i) - ts[i] = b * step - vs[i] = r.buckets[i%r.count].Load() - } - // Trim leading buckets that are in the future (ring not yet filled) so the - // chart starts at "now" rather than at zero time. - if now > ts[len(ts)-1] { - shift := int((now-ts[len(ts)-1])/step) + 1 - if shift >= len(ts) { - return []int64{now}, []int64{0} - } - ts = append(ts[:0], ts[shift:]...) - vs = append(vs[:0], vs[shift:]...) - } - return ts, vs -} - -// Series is the snapshot form. -func (r *Ring) Series() Series { - ts, vs := r.Snapshot() - return Series{Buckets: ts, Values: vs, ResolutionMS: r.res.Milliseconds()} -} - -// LCG is a tiny deterministic PRNG for jitter, so the test suite does not -// depend on the global rand. -type LCG struct{ s uint64 } - -func NewLCG(seed uint64) *LCG { return &LCG{s: seed | 1} } - -func (l *LCG) Next() uint64 { - l.s = l.s*6364136223846793005 + 1442695040888963407 - return l.s >> 11 -} - -func (l *LCG) Float() float64 { return float64(l.Next()) / float64(1<<53) } - -// SafeFloat converts an int count to a float for charting, guarding NaN. -func SafeFloat(n int64) float64 { - if n <= 0 { - return 0 - } - return float64(n) -} - -// Percent computes a safe percentage. -func Percent(part, total int64) float64 { - if total <= 0 { - return 0 - } - p := float64(part) / float64(total) * 100 - if math.IsNaN(p) || math.IsInf(p, 0) { - return 0 - } - return p -} diff --git a/internal/qlog/counts.go b/internal/qlog/counts.go deleted file mode 100644 index 425e149..0000000 --- a/internal/qlog/counts.go +++ /dev/null @@ -1,148 +0,0 @@ -package qlog - -import ( - "math/rand/v2" - "sort" - "sync" - "time" -) - -// randFloat is a 0..1 sample draw, isolated so tests can reason about -// sampling without seeding the global source. -func randFloat() float64 { return rand.Float64() } - -// domainCount is a rolling per-domain counter. -type domainCount struct { - name string - qtype uint16 - qtypeS string - total uint64 - blocked uint64 - last time.Time -} - -// domainCounts is a bounded, TTL-evicting map of domain counters. It replaces -// the hot half of "what is everyone asking for" without the cost of a sorted -// set on every query. -type domainCounts struct { - mu sync.Mutex - counts map[string]*domainCount - limit int - ttl time.Duration - now func() time.Time -} - -func newDomainCounts(limit int, ttl time.Duration) *domainCounts { - return &domainCounts{ - counts: make(map[string]*domainCount, 1024), - limit: limit, - ttl: ttl, - now: time.Now, - } -} - -func countKey(name string, qtype uint16) string { - return name + "|" + itoa(int(qtype)) -} - -func itoa(n int) string { - if n == 0 { - return "0" - } - var buf [8]byte - i := len(buf) - for n > 0 { - i-- - buf[i] = byte('0' + n%10) - n /= 10 - } - return string(buf[i:]) -} - -// observe records a query against its domain counter. -func (d *domainCounts) observe(e Entry) { - if e.Name == "" { - return - } - key := countKey(e.Name, e.QType) - now := d.now() - d.mu.Lock() - c, ok := d.counts[key] - if !ok { - if len(d.counts) >= d.limit { - d.evictLocked(now) - } - c = &domainCount{name: trimDot(e.Name), qtype: e.QType, qtypeS: e.QTypeStr} - d.counts[key] = c - } - c.total++ - if e.Blocked { - c.blocked++ - } - c.last = now - d.mu.Unlock() -} - -// evictLocked removes expired counters, and if that is not enough, the oldest -// quarter. Callers hold d.mu. -func (d *domainCounts) evictLocked(now time.Time) { - cutoff := now.Add(-d.ttl) - removed := 0 - for k, c := range d.counts { - if c.last.Before(cutoff) { - delete(d.counts, k) - removed++ - } - } - if removed == 0 && len(d.counts) > 0 { - // Nothing has expired (a very busy window): drop the oldest quarter. - type kv struct { - k string - t time.Time - } - all := make([]kv, 0, len(d.counts)) - for k, c := range d.counts { - all = append(all, kv{k, c.last}) - } - sort.Slice(all, func(i, j int) bool { return all[i].t.Before(all[j].t) }) - n := len(all) / 4 - if n < 1 { - n = 1 - } - for i := 0; i < n && i < len(all); i++ { - delete(d.counts, all[i].k) - } - } -} - -// top returns the n hottest domains. -func (d *domainCounts) top(n int, blockedOnly bool) []DomainCount { - if n <= 0 { - n = 25 - } - d.mu.Lock() - out := make([]DomainCount, 0, n) - for _, c := range d.counts { - if blockedOnly && c.blocked == 0 { - continue - } - dc := DomainCount{Name: c.name, Count: c.total, Blocked: c.blocked, QType: c.qtype, QTypeS: c.qtypeS} - if blockedOnly { - dc.Count = c.blocked - } - out = append(out, dc) - } - d.mu.Unlock() - sort.Slice(out, func(i, j int) bool { return out[i].Count > out[j].Count }) - if len(out) > n { - out = out[:n] - } - return out -} - -func trimDot(s string) string { - if n := len(s); n > 1 && s[n-1] == '.' { - return s[:n-1] - } - return s -} diff --git a/internal/qlog/qlog.go b/internal/qlog/qlog.go deleted file mode 100644 index 3398d29..0000000 --- a/internal/qlog/qlog.go +++ /dev/null @@ -1,784 +0,0 @@ -// Package qlog records DNS queries for the admin console: a live in-memory -// ring for the SSE stream, a bbolt-backed ring for the query log, and rolling -// per-domain counters that back the "top blocked" and "top queried" panels. -// -// The write path is deliberately allocation-light: entries are value types, the -// live ring is a fixed array, and bbolt writes are batched on a background -// goroutine so a burst of queries never blocks a DNS response. -package qlog - -import ( - "encoding/json" - "fmt" - "os" - "path/filepath" - "sync" - "sync/atomic" - "time" - - "github.com/miekg/dns" - bolt "go.etcd.io/bbolt" -) - -// Action is the outcome classification shown in the log. -type Action string - -const ( - // ActionAllow is a normal resolution. - ActionAllow Action = "allow" - // ActionBlock is a blocklist hit. - ActionBlock Action = "block" - // ActionRedirect is a blocklist rewrite to an address or CNAME target. - ActionRedirect Action = "redirect" - // ActionCached is a cache hit. - ActionCached Action = "cached" - // ActionError is a SERVFAIL or other failure. - ActionError Action = "error" - // ActionDrop is a query answered with silence. - ActionDrop Action = "drop" - // ActionRefused is an ACL refusal. - ActionRefused Action = "refused" -) - -// Entry is one logged query. -type Entry struct { - ID uint64 `json:"id"` - TS time.Time `json:"ts"` - Client string `json:"client"` - Group string `json:"client_group,omitempty"` - Name string `json:"name"` - QType uint16 `json:"qtype"` - QTypeStr string `json:"qtype_name"` - RCode int `json:"rcode"` - Action Action `json:"action"` - Response string `json:"response,omitempty"` - Duration int64 `json:"duration_ms"` - Upstream string `json:"upstream,omitempty"` - List string `json:"list,omitempty"` - Protocol string `json:"protocol,omitempty"` - // Blocked is a convenience mirror of Action == ActionBlock so the UI can - // filter without parsing the action string. - Blocked bool `json:"blocked"` -} - -// FromMsg fills the question-derived fields from a DNS message. -func (e *Entry) FromMsg(m *dns.Msg) { - if len(m.Question) > 0 { - q := m.Question[0] - e.Name = q.Name - e.QType = q.Qtype - e.QTypeStr = dns.Type(q.Qtype).String() - } - e.RCode = m.Rcode -} - -// RCodeName renders the RCODE as its mnemonic. -func (e Entry) RCodeName() string { - if s, ok := dns.RcodeToString[e.RCode]; ok { - return s - } - return fmt.Sprintf("RCODE%d", e.RCode) -} - -// liveEntry is a decoded copy kept in memory for the SSE stream. -type liveEntry struct { - entry Entry -} - -// Logger batches query logging to bbolt and maintains the live ring. -type Logger struct { - opts Options - - // seq assigns monotonic ids so the UI can detect drops. - seq atomic.Uint64 - - // live is a fixed-size ring of the most recent entries. Each slot is a - // pointer, so a writer on the query path never races a reader walking the - // ring: publishing is one atomic word, and a reader sees either the whole - // entry or the one it replaced. The slot an entry lands in comes from its - // id, so concurrent writers cannot leave a hole or reorder the stream. - live []atomic.Pointer[liveEntry] - liveMu sync.RWMutex - liveCond *sync.Cond - liveFull atomic.Bool - - // pending batches entries between bbolt transactions. - pendingMu sync.Mutex - pending []Entry - - // closed is set by Close; queries can still be logged after shutdown, so - // Log has to notice rather than write to a closed bbolt handle. - closed atomic.Bool - - // counts are rolling per-domain counters. - counts *domainCounts - - // logErrors counts persistence failures, which the API surfaces so a - // silently-failing query log never looks healthy. - logErrors atomic.Uint64 - - // subscribers is the set of live SSE consumers. - subMu sync.Mutex - subs map[int]chan Entry - subSeq int - - db *bolt.DB - stop chan struct{} - done chan struct{} - wg sync.WaitGroup -} - -// Options configures a Logger. -type Options struct { - // Path is the bbolt file; empty disables persistence. - Path string - // MaxEntries bounds the persisted log ring. - MaxEntries int - // LiveBuffer is the in-memory ring size for the SSE stream. - LiveBuffer int - // FlushInterval is the bbolt batch window. - FlushInterval time.Duration - // SampleRate is the fraction of non-blocked, non-error queries to keep. - SampleRate float64 - // LogBlocked, LogCached, LogErrors are forced categories. - LogBlocked bool - LogCached bool - LogErrors bool - // TopDomains is the size of the rolling counter set. - TopDomains int - // TopTTL is how long a counter survives without being touched. - TopTTL time.Duration - // Now is injectable for tests. - Now func() time.Time -} - -// DefaultOptions returns sane defaults. -func DefaultOptions() Options { - return Options{ - Path: "data/queries.db", - MaxEntries: 200000, - LiveBuffer: 2000, - FlushInterval: time.Second, - SampleRate: 1, - LogBlocked: true, - LogCached: true, - LogErrors: true, - TopDomains: 5000, - TopTTL: 5 * time.Minute, - } -} - -// New opens a Logger, creating the bbolt file when a path is given. -func New(opt Options) (*Logger, error) { - if opt.Now == nil { - opt.Now = time.Now - } - if opt.LiveBuffer <= 0 { - opt.LiveBuffer = 2000 - } - if opt.FlushInterval <= 0 { - opt.FlushInterval = time.Second - } - if opt.SampleRate <= 0 { - opt.SampleRate = 1 - } - if opt.SampleRate > 1 { - opt.SampleRate = 1 - } - if opt.TopDomains <= 0 { - opt.TopDomains = 5000 - } - if opt.TopTTL <= 0 { - opt.TopTTL = 5 * time.Minute - } - l := &Logger{ - opts: opt, - live: make([]atomic.Pointer[liveEntry], opt.LiveBuffer), - counts: newDomainCounts(opt.TopDomains, opt.TopTTL), - subs: make(map[int]chan Entry), - stop: make(chan struct{}), - done: make(chan struct{}), - pending: make([]Entry, 0, 4096), - } - l.liveCond = sync.NewCond(&l.liveMu) - if opt.Path != "" { - if err := os.MkdirAll(filepath.Dir(opt.Path), 0o755); err != nil { - return nil, fmt.Errorf("qlog: create data dir: %w", err) - } - db, err := bolt.Open(opt.Path, 0o600, &bolt.Options{Timeout: 5 * time.Second, NoFreelistSync: true}) - if err != nil { - return nil, fmt.Errorf("qlog: open %s: %w", opt.Path, err) - } - if err := db.Update(func(tx *bolt.Tx) error { - _, err := tx.CreateBucketIfNotExists(bucketLog) - if err != nil { - return err - } - meta, err := tx.CreateBucketIfNotExists(bucketMeta) - if err != nil { - return err - } - // Resume the id sequence where the previous process stopped. The - // bbolt keys are that same sequence, so ids stay unique across a - // restart: a repeated id would make the SSE stream and the UI show - // a live entry as an older one carrying the same id. - if v := meta.Get(keyNextID); len(v) == 8 { - // next_id is the id the next entry will take, while seq - // counts ids already handed out. - l.seq.Store(beUint64(v) - 1) - } - return nil - }); err != nil { - _ = db.Close() - return nil, err - } - l.db = db - l.wg.Add(1) - go l.flushLoop() - } else { - close(l.done) - } - return l, nil -} - -var ( - bucketLog = []byte("log") - bucketMeta = []byte("meta") - keyNextID = []byte("next_id") -) - -// ShouldLog reports whether an entry with this action passes the sampling -// policy. Blocked, redirected, cached and error entries are always kept when -// their category flag is set; ordinary resolutions are sampled. -func (l *Logger) ShouldLog(a Action) bool { - switch a { - case ActionBlock, ActionRedirect: - return l.opts.LogBlocked - case ActionCached: - return l.opts.LogCached - case ActionError, ActionDrop: - return l.opts.LogErrors - default: - if l.opts.SampleRate >= 1 { - return true - } - return randFloat() < l.opts.SampleRate - } -} - -// Log records a query. It never blocks on bbolt: the entry goes to the live -// ring and a batch, and a background goroutine does the disk write. -func (l *Logger) Log(e Entry) { - if l == nil || l.closed.Load() { - return - } - if e.TS.IsZero() { - e.TS = l.opts.Now() - } - if e.QTypeStr == "" && e.QType != 0 { - e.QTypeStr = dns.Type(e.QType).String() - } - e.Blocked = e.Action == ActionBlock - e.ID = l.seq.Add(1) - l.counts.observe(e) - - // Live ring. The slot is published with a single atomic store; a reader - // walking the ring concurrently gets either the old or the new entry, - // never a half-written one. - // The index is the entry id rather than a second counter, so a burst from - // several resolver goroutines still lands gap free and in id order. - l.live[(e.ID-1)%uint64(len(l.live))].Store(&liveEntry{entry: e}) - - // Fan out to SSE subscribers (non-blocking: a slow consumer drops entries - // rather than stalling the query path). - l.subMu.Lock() - for _, ch := range l.subs { - select { - case ch <- e: - default: - } - } - l.subMu.Unlock() - - if l.db == nil { - return - } - l.pendingMu.Lock() - l.pending = append(l.pending, e) - n := len(l.pending) - l.pendingMu.Unlock() - if n >= 2048 { - go l.Flush() - } -} - -// flushLoop writes pending batches on a timer. -func (l *Logger) flushLoop() { - defer l.wg.Done() - t := time.NewTicker(l.opts.FlushInterval) - defer t.Stop() - for { - select { - case <-l.stop: - l.Flush() - return - case <-t.C: - l.Flush() - } - } -} - -// Flush writes any pending entries to bbolt and trims the ring. -func (l *Logger) Flush() { - if l == nil || l.db == nil { - return - } - l.pendingMu.Lock() - if len(l.pending) == 0 { - l.pendingMu.Unlock() - return - } - batch := l.pending - // Not pending[:0]: that would hand the next Log call the array this batch is - // still being read from. - l.pending = nil - l.pendingMu.Unlock() - - err := l.db.Update(func(tx *bolt.Tx) error { - b := tx.Bucket(bucketLog) - if b == nil { - return nil - } - meta := tx.Bucket(bucketMeta) - nextID := uint64(1) - if meta != nil { - if v := meta.Get(keyNextID); len(v) == 8 { - nextID = beUint64(v) - } - } - for _, e := range batch { - data, err := json.Marshal(e) - if err != nil { - continue - } - if err := b.Put(be64b(nextID), data); err != nil { - return err - } - nextID++ - } - if meta != nil { - meta.Put(keyNextID, be64b(nextID)) - } - return l.trim(b, nextID) - }) - if err != nil { - // A logging failure must never take the resolver down; surface it via - // the error counter the API reads. - l.logErrors.Add(1) - } -} - -// trim enforces the entry cap by deleting the oldest ids. -func (l *Logger) trim(b *bolt.Bucket, nextID uint64) error { - if l.opts.MaxEntries <= 0 { - return nil - } - // The keys are a dense id range, so the count is the span from the oldest - // surviving key up to nextID. Bucket.Stats cannot answer that here: it - // walks the pages as they sit on disk, and a write transaction has not - // spilled this batch yet, so it always under-counts and the cap is never - // enforced. - cur := b.Cursor() - first, _ := cur.First() - if first == nil { - return nil - } - oldest := beUint64(first) - span := nextID - oldest - if span <= uint64(l.opts.MaxEntries) { - return nil - } - excess := span - uint64(l.opts.MaxEntries) - // Collect the doomed keys before deleting any: bbolt rewrites a leaf - // page in place once it drops under a quarter full, which invalidates the - // cursor's page stack, so deleting while iterating stops early and the - // cap is only half enforced. - keys := make([][]byte, 0, excess) - for k, _ := cur.First(); k != nil && len(keys) < int(excess); k, _ = cur.Next() { - keys = append(keys, append([]byte(nil), k...)) - } - for _, k := range keys { - if err := b.Delete(k); err != nil { - return err - } - } - return nil -} - -// ErrorCount reports how many batch writes have failed. -func (l *Logger) ErrorCount() uint64 { return l.logErrors.Load() } - -// be64b encodes a uint64 big-endian for use as a bbolt key. -func be64b(v uint64) []byte { - return []byte{ - byte(v >> 56), byte(v >> 48), byte(v >> 40), byte(v >> 32), - byte(v >> 24), byte(v >> 16), byte(v >> 8), byte(v), - } -} - -// beUint64 decodes what be64b wrote. -func beUint64(b []byte) uint64 { - var v uint64 - for _, c := range b { - v = v<<8 | uint64(c) - } - return v -} - -// Query filters the persisted log. -type Query struct { - // Limit is the page size. - Limit int - // Offset skips the newest Offset entries. - Offset int - // Text matches name, client or list. - Text string - // Action filters by classification. - Action string - // Client filters by client address. - Client string - // RCode filters by numeric rcode (0 = no filter). - RCode int - // BlockedOnly keeps only blocklist hits. - BlockedOnly bool - // Since keeps only entries at or after this time. - Since time.Time -} - -// Page is a page of log entries plus the total match count. -type Page struct { - Items []Entry `json:"items"` - Total int `json:"total"` - Offset int `json:"offset"` - Limit int `json:"limit"` -} - -// Recent returns the newest entries from the in-memory ring, newest first. -// It powers the SSE initial burst so a client connecting mid-stream sees -// recent history immediately. -func (l *Logger) Recent(limit int) []Entry { - if l == nil { - return nil - } - if limit <= 0 { - limit = 200 - } - if limit > len(l.live) { - limit = len(l.live) - } - out := make([]Entry, 0, limit) - size := uint64(len(l.live)) - pos := l.seq.Load() // the newest id doubles as the newest ring position - total := pos - if total > size { - total = size - } - for i := uint64(0); i < total; i++ { - le := l.live[(pos-1-i)%size].Load() - if le == nil { - // Never written (or already aged out of the window). - continue - } - out = append(out, le.entry) - if len(out) >= limit { - break - } - } - return out -} - -// Search queries the persisted log. -func (l *Logger) Search(q Query) (Page, error) { - if l == nil { - return Page{Offset: q.Offset, Limit: q.Limit}, nil - } - l.Flush() - page := Page{Offset: q.Offset, Limit: q.Limit} - if q.Limit <= 0 { - q.Limit = 200 - } - if q.Limit > 1000 { - q.Limit = 1000 - } - if l.db == nil { - // No persistence: serve from the live ring. - items := l.Recent(1000) - filtered := l.filter(items, q) - page.Total = len(filtered) - page.Items = paginate(filtered, q.Offset, q.Limit) - return page, nil - } - var ( - matched []Entry - total int - ) - err := l.db.View(func(tx *bolt.Tx) error { - b := tx.Bucket(bucketLog) - if b == nil { - return nil - } - // Walk newest-first. - c := b.Cursor() - for k, v := c.Last(); k != nil; k, v = c.Prev() { - var e Entry - if err := json.Unmarshal(v, &e); err != nil { - continue - } - if !matchEntry(e, q) { - continue - } - total++ - if total > q.Offset && len(matched) < q.Limit { - matched = append(matched, e) - } - if total >= q.Offset+q.Limit+1 && q.Offset+q.Limit > 0 { - // We have enough to fill the page and know the total is at - // least this high; keep scanning only if we still need an - // exact total. For the UI, a "has more" hint is enough. - break - } - } - return nil - }) - if err != nil { - return page, err - } - page.Items = matched - page.Total = total - return page, nil -} - -func (l *Logger) filter(items []Entry, q Query) []Entry { - out := make([]Entry, 0, len(items)) - for _, e := range items { - if matchEntry(e, q) { - out = append(out, e) - } - } - return out -} - -func matchEntry(e Entry, q Query) bool { - if q.BlockedOnly && !e.Blocked { - return false - } - if q.Action != "" && string(e.Action) != q.Action { - return false - } - if q.Client != "" && e.Client != q.Client { - return false - } - if q.RCode != 0 && e.RCode != q.RCode { - return false - } - if !q.Since.IsZero() && e.TS.Before(q.Since) { - return false - } - if q.Text != "" { - t := q.Text - if !containsFold(e.Name, t) && !containsFold(e.Client, t) && !containsFold(e.List, t) { - return false - } - } - return true -} - -func paginate(items []Entry, offset, limit int) []Entry { - if offset >= len(items) { - return []Entry{} - } - end := offset + limit - if end > len(items) { - end = len(items) - } - return items[offset:end] -} - -func containsFold(hay, needle string) bool { - if len(needle) == 0 { - return true - } - return indexFold(hay, needle) >= 0 -} - -func indexFold(hay, needle string) int { - n := len(needle) - if n == 0 { - return 0 - } - if n > len(hay) { - return -1 - } - for i := 0; i+n <= len(hay); i++ { - match := true - for j := 0; j < n; j++ { - if lower(hay[i+j]) != lower(needle[j]) { - match = false - break - } - } - if match { - return i - } - } - return -1 -} - -func lower(b byte) byte { - if b >= 'A' && b <= 'Z' { - return b + 32 - } - return b -} - -// Subscribe registers a live-stream consumer. The returned cancel func must -// be called. Entries are delivered best-effort: a full channel drops rather -// than blocking the DNS path. -func (l *Logger) Subscribe() (<-chan Entry, func()) { - l.subMu.Lock() - defer l.subMu.Unlock() - l.subSeq++ - id := l.subSeq - ch := make(chan Entry, 256) - l.subs[id] = ch - return ch, func() { - l.subMu.Lock() - if c, ok := l.subs[id]; ok { - delete(l.subs, id) - close(c) - } - l.subMu.Unlock() - } -} - -// SubscriberCount reports how many live streams are attached. -func (l *Logger) SubscriberCount() int { - l.subMu.Lock() - defer l.subMu.Unlock() - return len(l.subs) -} - -// Clear removes every persisted entry. -func (l *Logger) Clear() error { - if l == nil || l.db == nil { - return nil - } - err := l.db.Update(func(tx *bolt.Tx) error { - if tx.Bucket(bucketLog) == nil { - _, err := tx.CreateBucket(bucketLog) - return err - } - if err := tx.DeleteBucket(bucketLog); err != nil { - return err - } - // Recreate it in the same transaction: the flush path assumes the - // bucket is there, and a logger that silently stopped persisting after - // a clear would look like a healthy, empty log. - _, err := tx.CreateBucket(bucketLog) - return err - }) - if err != nil { - l.logErrors.Add(1) - } - return err -} - -// Count is the number of persisted entries. -func (l *Logger) Count() int { - if l == nil { - return 0 - } - if l.db == nil { - return int(l.seq.Load()) - } - n := 0 - _ = l.db.View(func(tx *bolt.Tx) error { - if b := tx.Bucket(bucketLog); b != nil { - n = b.Stats().KeyN - } - return nil - }) - return n -} - -// TopDomains returns the hottest domains, optionally only blocked ones. -type DomainCount struct { - Name string `json:"domain"` - Count uint64 `json:"count"` - Blocked uint64 `json:"blocked"` - QType uint16 `json:"qtype"` - QTypeS string `json:"qtype_name"` -} - -// TopDomains returns the top n domains by query count. -func (l *Logger) TopDomains(n int, blockedOnly bool) []DomainCount { - return l.counts.top(n, blockedOnly) -} - -// TopBlocked returns the top blocked domains. -func (l *Logger) TopBlocked(n int) []DomainCount { return l.counts.top(n, true) } - -// TopQueried returns the top queried domains. -func (l *Logger) TopQueried(n int) []DomainCount { return l.counts.top(n, false) } - -// Stats is a JSON-friendly summary. -type Stats struct { - Enabled bool `json:"enabled"` - Path string `json:"path"` - Entries int `json:"entries"` - MaxEntries int `json:"max_entries"` - LiveBuffer int `json:"live_buffer"` - Subscribers int `json:"subscribers"` - SampleRate float64 `json:"sample_rate"` - TotalLogged uint64 `json:"total_logged"` - Pending int `json:"pending"` - Errors uint64 `json:"errors"` -} - -// Stats snapshots the logger. -func (l *Logger) Stats() Stats { - l.pendingMu.Lock() - pending := len(l.pending) - l.pendingMu.Unlock() - return Stats{ - Enabled: l.db != nil, - Path: l.opts.Path, - Entries: l.Count(), - MaxEntries: l.opts.MaxEntries, - LiveBuffer: l.opts.LiveBuffer, - Subscribers: l.SubscriberCount(), - SampleRate: l.opts.SampleRate, - TotalLogged: l.seq.Load(), - Pending: pending, - Errors: l.logErrors.Load(), - } -} - -// Close flushes and releases resources. -func (l *Logger) Close() error { - if l == nil { - return nil - } - l.closed.Store(true) - select { - case <-l.stop: - default: - close(l.stop) - } - l.wg.Wait() - if l.db != nil { - l.Flush() - return l.db.Close() - } - return nil -} diff --git a/internal/qlog/qlog_test.go b/internal/qlog/qlog_test.go deleted file mode 100644 index 7658114..0000000 --- a/internal/qlog/qlog_test.go +++ /dev/null @@ -1,865 +0,0 @@ -package qlog - -import ( - "fmt" - "path/filepath" - "strconv" - "strings" - "sync" - "testing" - "time" - - "github.com/miekg/dns" -) - -// openLogger builds a Logger over a temp-dir bbolt file. Every logger this -// file creates is closed through t.Cleanup, so a failing assertion cannot leak -// the flush goroutine or hold the bbolt file lock. -func openLogger(t *testing.T, path string, mutate func(*Options)) *Logger { - t.Helper() - opt := Options{ - Path: path, - MaxEntries: 1000, - LiveBuffer: 256, - FlushInterval: 20 * time.Millisecond, - SampleRate: 1, - LogBlocked: true, - LogCached: true, - LogErrors: true, - TopDomains: 128, - TopTTL: time.Minute, - } - if mutate != nil { - mutate(&opt) - } - l, err := New(opt) - if err != nil { - t.Fatalf("qlog.New: %v", err) - } - t.Cleanup(func() { _ = l.Close() }) - return l -} - -func tempPath(t *testing.T) string { - t.Helper() - return filepath.Join(t.TempDir(), "queries.db") -} - -// entryFor builds an entry the way the engine does: the question-derived -// fields come from a real dns.Msg via FromMsg, the rest is filled in by the -// caller. -func entryFor(i int) Entry { - q := new(dns.Msg) - q.SetQuestion(fmt.Sprintf("host%d.test.", i), dns.TypeA) - m := new(dns.Msg) - m.SetReply(q) - rr, err := dns.NewRR(q.Question[0].Name + " 30 IN A 203.0.113.7") - if err != nil { - panic(err) - } - m.Answer = []dns.RR{rr} - e := Entry{ - TS: time.Date(2024, 5, 1, 12, 0, i, 0, time.UTC), - Client: "192.0.2.10", - Group: "testers", - Duration: int64(i) * 2, - Action: ActionAllow, - Upstream: "127.0.0.1:5399", - List: "test-list", - Protocol: "udp", - } - e.FromMsg(m) - return e -} - -func names(items []Entry) []string { - out := make([]string, 0, len(items)) - for _, e := range items { - out = append(out, e.Name) - } - return out -} - -// TestLogRoundTripReopen is the core promise of the package: what Log accepted -// is what Search hands back after the process restarted. -func TestLogRoundTripReopen(t *testing.T) { - path := tempPath(t) - first := openLogger(t, path, nil) - for i := 1; i <= 5; i++ { - first.Log(entryFor(i)) - } - first.Flush() - if got := first.Count(); got != 5 { - t.Fatalf("Count() = %d, want 5", got) - } - // Close before reopening: bbolt takes an exclusive file lock, so a - // reopened handle would just block on the timeout. - if err := first.Close(); err != nil { - t.Fatalf("close: %v", err) - } - - second := openLogger(t, path, nil) - page, err := second.Search(Query{Limit: 50}) - if err != nil { - t.Fatalf("search: %v", err) - } - if page.Total != 5 { - t.Fatalf("Total = %d, want 5", page.Total) - } - want := []string{"host5.test.", "host4.test.", "host3.test.", "host2.test.", "host1.test."} - if got := names(page.Items); !equalStrings(got, want) { - t.Fatalf("names = %v, want %v (newest first)", got, want) - } - for i, e := range page.Items { - w := entryFor(5 - i) - assertEntryFields(t, e, w) - } - if got := second.Count(); got != 5 { - t.Errorf("Count() after reopen = %d, want 5", got) - } - if n := second.ErrorCount(); n != 0 { - t.Errorf("ErrorCount() = %d, want 0", n) - } -} - -// TestReopenContinuesEntryIDs pins that ids stay unique across a restart: a -// logger that resumed at 1 would hand the UI two entries with the same id. -func TestReopenContinuesEntryIDs(t *testing.T) { - path := tempPath(t) - first := openLogger(t, path, nil) - for i := 1; i <= 3; i++ { - first.Log(entryFor(i)) - } - first.Flush() - if err := first.Close(); err != nil { - t.Fatalf("close: %v", err) - } - - second := openLogger(t, path, nil) - second.Log(entryFor(4)) - second.Flush() - page, err := second.Search(Query{Limit: 50}) - if err != nil { - t.Fatalf("search: %v", err) - } - if len(page.Items) != 4 { - t.Fatalf("items = %d, want 4", len(page.Items)) - } - seen := map[uint64]bool{} - for _, e := range page.Items { - if seen[e.ID] { - t.Fatalf("duplicate entry id %d in %v", e.ID, names(page.Items)) - } - seen[e.ID] = true - } - if page.Items[0].ID != 4 { - t.Errorf("newest id = %d, want 4 (ids must continue across a restart)", page.Items[0].ID) - } -} - -// assertEntryFields compares every field the round trip has to preserve. -func assertEntryFields(t *testing.T, got, want Entry) { - t.Helper() - if !got.TS.Equal(want.TS) { - t.Errorf("TS = %v, want %v", got.TS, want.TS) - } - if got.Client != want.Client { - t.Errorf("Client = %q, want %q", got.Client, want.Client) - } - if got.Group != want.Group { - t.Errorf("Group = %q, want %q", got.Group, want.Group) - } - if got.Name != want.Name { - t.Errorf("Name = %q, want %q", got.Name, want.Name) - } - if got.QType != want.QType { - t.Errorf("QType = %d, want %d", got.QType, want.QType) - } - if got.QTypeStr != want.QTypeStr { - t.Errorf("QTypeStr = %q, want %q", got.QTypeStr, want.QTypeStr) - } - if got.RCode != want.RCode { - t.Errorf("RCode = %d, want %d", got.RCode, want.RCode) - } - if got.Action != want.Action { - t.Errorf("Action = %q, want %q", got.Action, want.Action) - } - if got.Duration != want.Duration { - t.Errorf("Duration = %d, want %d", got.Duration, want.Duration) - } - if got.Upstream != want.Upstream { - t.Errorf("Upstream = %q, want %q", got.Upstream, want.Upstream) - } - if got.List != want.List { - t.Errorf("List = %q, want %q", got.List, want.List) - } - if got.Protocol != want.Protocol { - t.Errorf("Protocol = %q, want %q", got.Protocol, want.Protocol) - } - if got.Blocked != want.Blocked { - t.Errorf("Blocked = %v, want %v", got.Blocked, want.Blocked) - } - if got.RCodeName() != "NOERROR" { - t.Errorf("RCodeName() = %q, want NOERROR", got.RCodeName()) - } -} - -func equalStrings(a, b []string) bool { - if len(a) != len(b) { - return false - } - for i := range a { - if a[i] != b[i] { - return false - } - } - return true -} - -// TestMaxEntriesEvictsOldestFirst covers the on-disk size bound: the ring -// never grows past MaxEntries and the survivors are the newest entries. -func TestMaxEntriesEvictsOldestFirst(t *testing.T) { - l := openLogger(t, tempPath(t), func(o *Options) { o.MaxEntries = 8 }) - for i := 1; i <= 20; i++ { - l.Log(entryFor(i)) - } - l.Flush() - if got := l.Count(); got > 8 { - t.Fatalf("Count() = %d, want <= 8", got) - } - if got := l.Count(); got != 8 { - t.Fatalf("Count() = %d, want 8 (the ring should be full, not short)", got) - } - page, err := l.Search(Query{Limit: 100}) - if err != nil { - t.Fatalf("search: %v", err) - } - want := []string{ - "host20.test.", "host19.test.", "host18.test.", "host17.test.", - "host16.test.", "host15.test.", "host14.test.", "host13.test.", - } - if got := names(page.Items); !equalStrings(got, want) { - t.Fatalf("survivors = %v, want %v", got, want) - } - // A second flush must not trim below the bound either: the key count is - // re-checked on every transaction. - l.Flush() - if got := l.Count(); got != 8 { - t.Errorf("Count() after re-flush = %d, want 8", got) - } -} - -// TestMaxEntriesZeroMeansUnbounded documents the escape hatch: 0 disables the -// trim entirely. -func TestMaxEntriesZeroMeansUnbounded(t *testing.T) { - l := openLogger(t, tempPath(t), func(o *Options) { o.MaxEntries = 0 }) - for i := 1; i <= 25; i++ { - l.Log(entryFor(i)) - } - l.Flush() - if got := l.Count(); got != 25 { - t.Fatalf("Count() = %d, want 25", got) - } -} - -// TestLiveRingOrderAndGapFree pins the SSE initial burst: newest first, one -// step at a time, with no holes where the ring wrapped. -func TestLiveRingOrderAndGapFree(t *testing.T) { - l := openLogger(t, tempPath(t), func(o *Options) { o.LiveBuffer = 32 }) - for i := 1; i <= 40; i++ { - l.Log(entryFor(i)) - } - got := l.Recent(32) - if len(got) != 32 { - t.Fatalf("Recent(32) returned %d entries, want 32", len(got)) - } - for i, e := range got { - want := 40 - i - if e.ID != uint64(want) { - t.Fatalf("entry %d has id %d, want %d (ring must be newest first, gap free)", i, e.ID, want) - } - if e.Name != fmt.Sprintf("host%d.test.", want) { - t.Fatalf("entry %d name = %q, want host%d.test.", i, e.Name, want) - } - } - if got := l.Recent(5); len(got) != 5 || got[0].ID != 40 || got[4].ID != 36 { - t.Fatalf("Recent(5) = %v, want ids 40..36", got) - } - // limit <= 0 falls back to the 200-entry default, bounded by the ring. - if got := l.Recent(0); len(got) != 32 { - t.Fatalf("Recent(0) returned %d entries, want the whole 32-slot ring", len(got)) - } - // A limit past the ring size clamps instead of panicking. - if got := l.Recent(10000); len(got) != 32 { - t.Fatalf("Recent(10000) returned %d entries, want 32", len(got)) - } -} - -// TestLiveRingEmptyBeforeAnyWrite covers the zero state. -func TestLiveRingEmptyBeforeAnyWrite(t *testing.T) { - l := openLogger(t, tempPath(t), nil) - if got := l.Recent(10); len(got) != 0 { - t.Fatalf("Recent(10) on an empty ring = %d entries, want 0", len(got)) - } - if got := l.Stats().TotalLogged; got != 0 { - t.Fatalf("TotalLogged = %d, want 0", got) - } -} - -// TestLiveRingConcurrentLogAndRecent is the race test for the whole point of -// the []atomic.Pointer[liveEntry] ring: many writers publish while readers -// walk, and no reader may ever see a half-written entry. Every entry carries -// its own writer id and sequence in two fields, so a torn read — the failure -// mode a mutex-free ring has to avoid — shows up as Name not matching -// Client+Protocol. -func TestLiveRingConcurrentLogAndRecent(t *testing.T) { - const ( - writers = 8 - perWriter = 200 - readers = 3 - ) - l := openLogger(t, tempPath(t), func(o *Options) { - o.LiveBuffer = 2048 - o.Path = "" // the live ring is what is under test; skip bbolt - }) - var start sync.WaitGroup - var done sync.WaitGroup - start.Add(1) - for w := 0; w < writers; w++ { - w := w - done.Add(1) - go func() { - defer done.Done() - start.Wait() - for i := 0; i < perWriter; i++ { - l.Log(Entry{ - Client: "w" + strconv.Itoa(w), - Name: fmt.Sprintf("w%d-i%d.test.", w, i), - Protocol: strconv.Itoa(i), - QType: dns.TypeA, - QTypeStr: "A", - Action: ActionAllow, - TS: time.Unix(int64(i), 0), - }) - } - }() - } - stop := make(chan struct{}) - var readersWG sync.WaitGroup - for r := 0; r < readers; r++ { - readersWG.Add(1) - go func() { - defer readersWG.Done() - start.Wait() - for { - select { - case <-stop: - return - default: - } - snapshot := l.Recent(64) - seenID := make(map[uint64]bool, len(snapshot)) - seenKey := make(map[string]bool, len(snapshot)) - for _, e := range snapshot { - // Name and the client/protocol pair are written together - // into one immutable entry, so a reader that saw a mix - // of two would be reading torn data. - want := fmt.Sprintf("%s-i%s.test.", e.Client, e.Protocol) - if e.Name != want { - t.Errorf("torn entry: name %q does not match client %q/protocol %q", e.Name, e.Client, e.Protocol) - return - } - if e.ID == 0 { - t.Errorf("entry with id 0 reached a reader: %+v", e) - return - } - if e.ID > writers*perWriter { - t.Errorf("entry id %d is beyond the %d written", e.ID, writers*perWriter) - return - } - if seenID[e.ID] { - t.Errorf("id %d appeared twice in one snapshot", e.ID) - return - } - seenID[e.ID] = true - key := e.Client + "/" + e.Protocol - if seenKey[key] { - t.Errorf("entry w%s/%s appeared twice in one snapshot", e.Client, e.Protocol) - return - } - seenKey[key] = true - } - } - }() - } - start.Done() - done.Wait() - close(stop) - readersWG.Wait() - - // With the writers done the ring must be a complete, ordered history. - all := l.Recent(writers * perWriter) - if len(all) != writers*perWriter { - t.Fatalf("Recent returned %d entries, want %d", len(all), writers*perWriter) - } - for i, e := range all { - want := writers*perWriter - i - if e.ID != uint64(want) { - t.Fatalf("entry %d has id %d, want %d (final snapshot must be gap free)", i, e.ID, want) - } - } -} - -// TestSSEFanoutDeliversEachEntryOnce covers the live stream: every subscriber -// sees the same entries, in order, exactly once. -func TestSSEFanoutDeliversEachEntryOnce(t *testing.T) { - l := openLogger(t, tempPath(t), func(o *Options) { o.Path = "" }) - const subs = 3 - chans := make([]<-chan Entry, 0, subs) - cancels := make([]func(), 0, subs) - for i := 0; i < subs; i++ { - ch, cancel := l.Subscribe() - chans = append(chans, ch) - cancels = append(cancels, cancel) - } - if got := l.SubscriberCount(); got != subs { - t.Fatalf("SubscriberCount() = %d, want %d", got, subs) - } - for i := 1; i <= 5; i++ { - l.Log(entryFor(i)) - } - for s, ch := range chans { - for i := 1; i <= 5; i++ { - select { - case e := <-ch: - if e.ID != uint64(i) { - t.Errorf("subscriber %d: entry %d has id %d", s, i, e.ID) - } - if e.Name != fmt.Sprintf("host%d.test.", i) { - t.Errorf("subscriber %d: entry %d name = %q", s, i, e.Name) - } - default: - t.Fatalf("subscriber %d never got entry %d", s, i) - } - } - select { - case extra := <-ch: - t.Errorf("subscriber %d got an extra entry: %+v", s, extra) - default: - } - } - for _, cancel := range cancels { - cancel() - } -} - -// TestSSESlowSubscriberDoesNotBlockLog is the reason fanout is non-blocking: a -// consumer that stopped reading must never stall the query path. -func TestSSESlowSubscriberDoesNotBlockLog(t *testing.T) { - l := openLogger(t, tempPath(t), func(o *Options) { o.Path = "" }) - slow, cancelSlow := l.Subscribe() - defer cancelSlow() - // Nothing ever reads from slow, so its 256-slot buffer fills and stays - // full. - for i := 0; i < 256; i++ { - l.Log(entryFor(i + 1)) - } - done := make(chan struct{}) - go func() { - defer close(done) - for i := 0; i < 50; i++ { - l.Log(entryFor(i + 1)) - } - }() - select { - case <-done: - case <-time.After(10 * time.Second): - t.Fatal("Log blocked on a subscriber that stopped reading") - } - // A healthy subscriber still gets everything. - fast, cancelFast := l.Subscribe() - defer cancelFast() - l.Log(entryFor(999)) - select { - case e := <-fast: - if e.Name != "host999.test." { - t.Errorf("fast subscriber got %q", e.Name) - } - case <-time.After(5 * time.Second): - t.Fatal("fast subscriber did not receive the entry") - } - // The slow consumer's buffer only ever holds entries from the first - // burst: everything logged after it filled up was dropped, not queued. - drained := 0 - for { - select { - case e := <-slow: - if e.ID > 256 { - t.Fatalf("slow subscriber received a dropped-then-queued entry: %+v", e) - } - drained++ - continue - default: - } - break - } - if drained != 256 { - t.Errorf("slow subscriber buffered %d entries, want 256", drained) - } - select { - case e := <-slow: - t.Errorf("slow subscriber received a late entry: %+v", e) - default: - } -} - -// TestSSEUnsubscribeStopsDelivery covers teardown: no delivery after the -// cancel func, a closed channel, and no leaked subscription slot. -func TestSSEUnsubscribeStopsDelivery(t *testing.T) { - l := openLogger(t, tempPath(t), func(o *Options) { o.Path = "" }) - ch, cancel := l.Subscribe() - l.Log(entryFor(1)) - if e := <-ch; e.ID != 1 { - t.Fatalf("first entry id = %d, want 1", e.ID) - } - cancel() - if got := l.SubscriberCount(); got != 0 { - t.Fatalf("SubscriberCount() = %d after cancel, want 0", got) - } - l.Log(entryFor(2)) - // A closed channel yields immediately, so a plain receive is enough. - select { - case e, ok := <-ch: - if ok { - t.Fatalf("received %+v after unsubscribe", e) - } - case <-time.After(time.Second): - t.Fatal("channel was not closed by the cancel func") - } - // Cancelling twice must not panic on a double close. - cancel() - if got := l.SubscriberCount(); got != 0 { - t.Errorf("SubscriberCount() = %d, want 0", got) - } -} - -// TestFieldPreservationThroughMsg checks the question-derived fields come from -// the message and the flags are mirrored. -func TestFieldPreservationThroughMsg(t *testing.T) { - l := openLogger(t, tempPath(t), nil) - q := new(dns.Msg) - q.SetQuestion("Blocked.Example.COM.", dns.TypeAAAA) - m := new(dns.Msg) - m.SetReply(q) - m.Rcode = dns.RcodeNameError - e := Entry{ - TS: time.Date(2024, 5, 1, 12, 0, 0, 0, time.UTC), - Client: "2001:db8::5", - Group: "laptops", - Duration: 7, - Action: ActionBlock, - List: "adlist", - Protocol: "doh", - Upstream: "", - } - e.FromMsg(m) - l.Log(e) - l.Flush() - - page, err := l.Search(Query{Limit: 10}) - if err != nil { - t.Fatalf("search: %v", err) - } - if len(page.Items) != 1 { - t.Fatalf("items = %d, want 1", len(page.Items)) - } - got := page.Items[0] - if got.Name != "Blocked.Example.COM." { - t.Errorf("Name = %q, want the name verbatim", got.Name) - } - if got.QType != dns.TypeAAAA || got.QTypeStr != "AAAA" { - t.Errorf("QType = %d/%q, want AAAA/AAAA", got.QType, got.QTypeStr) - } - if got.RCode != dns.RcodeNameError || got.RCodeName() != "NXDOMAIN" { - t.Errorf("RCode = %d/%q, want NXDOMAIN", got.RCode, got.RCodeName()) - } - if !got.Blocked { - t.Error("Blocked = false, want the mirror of ActionBlock") - } - if got.Client != "2001:db8::5" || got.Group != "laptops" || got.Duration != 7 { - t.Errorf("client/group/duration = %q/%q/%d", got.Client, got.Group, got.Duration) - } - if got.List != "adlist" || got.Protocol != "doh" { - t.Errorf("list/protocol = %q/%q", got.List, got.Protocol) - } - if got.Upstream != "" { - t.Errorf("Upstream = %q, want empty (a blocked query never reaches one)", got.Upstream) - } - if got.TS.IsZero() { - t.Error("TS was dropped") - } - // A blocked query is the mirror's only source, so a non-block must clear it. - l.Log(entryFor(9)) - l.Flush() - page, err = l.Search(Query{BlockedOnly: true, Limit: 10}) - if err != nil { - t.Fatalf("search: %v", err) - } - if page.Total != 1 || page.Items[0].Name != "Blocked.Example.COM." { - t.Fatalf("BlockedOnly search = %+v, want just the blocked name", page.Items) - } -} - -// TestQueryStringStampsMissingFields covers the Log-time fixups: an entry -// built by hand gets a timestamp and a type name without the caller setting -// them. -func TestQueryStringStampsMissingFields(t *testing.T) { - l := openLogger(t, tempPath(t), func(o *Options) { o.Path = "" }) - l.Log(Entry{Name: "stamped.test.", QType: dns.TypeMX, Action: ActionAllow}) - got := l.Recent(1) - if len(got) != 1 { - t.Fatalf("Recent(1) = %d entries, want 1", len(got)) - } - if got[0].QTypeStr != "MX" { - t.Errorf("QTypeStr = %q, want MX", got[0].QTypeStr) - } - if got[0].TS.IsZero() { - t.Error("TS = zero, want the logger's clock") - } - if got[0].ID != 1 { - t.Errorf("ID = %d, want 1", got[0].ID) - } -} - -// TestDisabledLoggerStillServesTheLiveRing covers the no-path configuration: -// nothing is persisted, but the SSE ring, the counters and the API filters -// still work. -func TestDisabledLoggerStillServesTheLiveRing(t *testing.T) { - l := openLogger(t, tempPath(t), func(o *Options) { o.Path = "" }) - if l.Stats().Enabled { - t.Error("Stats().Enabled = true without a path") - } - for i := 1; i <= 3; i++ { - e := entryFor(i) - e.Action = ActionBlock - l.Log(e) - } - if got := l.Count(); got != 3 { - t.Errorf("Count() = %d, want the 3 logged ids", got) - } - page, err := l.Search(Query{Action: "block", Limit: 10}) - if err != nil { - t.Fatalf("search: %v", err) - } - if page.Total != 3 { - t.Fatalf("Total = %d, want 3 (search must fall back to the live ring)", page.Total) - } - // Offset and text filters work on the same fallback path. - page, err = l.Search(Query{Text: "host2", Limit: 10}) - if err != nil { - t.Fatalf("search: %v", err) - } - if page.Total != 1 || page.Items[0].Name != "host2.test." { - t.Fatalf("text search = %+v, want host2.test.", page.Items) - } - if err := l.Clear(); err != nil { - t.Errorf("Clear() without persistence: %v", err) - } - if err := l.Close(); err != nil { - t.Errorf("Close() without persistence: %v", err) - } -} - -// TestLogOnClosedLoggerIsANoOp covers the shutdown path: every read and write -// after Close must stay safe rather than panicking on a closed bbolt handle. -func TestLogOnClosedLoggerIsANoOp(t *testing.T) { - l := openLogger(t, tempPath(t), nil) - l.Log(entryFor(1)) - if err := l.Close(); err != nil { - t.Fatalf("close: %v", err) - } - l.Log(entryFor(2)) - l.Flush() - _ = l.Count() - _ = l.Recent(10) - if _, err := l.Search(Query{Limit: 10}); err == nil { - t.Log("search on a closed store returned no error; acceptable") - } - if got := l.ErrorCount(); got > 1 { - t.Errorf("ErrorCount() = %d, want at most the failed write", got) - } - // A nil logger is the "logging disabled" shape some callers hold; it must - // swallow the call instead of panicking on the query path. - var nilLogger *Logger - nilLogger.Log(entryFor(3)) - if got := nilLogger.Recent(1); got != nil { - t.Errorf("nil Recent() = %v, want nil", got) - } -} - -// TestShouldLogPolicy covers the sampling gate the engine consults. -func TestShouldLogPolicy(t *testing.T) { - all := openLogger(t, tempPath(t), func(o *Options) { o.Path = "" }) - for _, a := range []Action{ActionAllow, ActionBlock, ActionCached, ActionError, ActionDrop, ActionRefused} { - if !all.ShouldLog(a) { - t.Errorf("ShouldLog(%q) = false with every category enabled", a) - } - } - off := openLogger(t, tempPath(t), func(o *Options) { - o.Path = "" - o.LogBlocked = false - o.LogCached = false - o.LogErrors = false - }) - if off.ShouldLog(ActionBlock) || off.ShouldLog(ActionCached) || off.ShouldLog(ActionError) || off.ShouldLog(ActionDrop) { - t.Error("disabled categories must not be logged") - } - if !off.ShouldLog(ActionAllow) { - t.Error("ordinary resolutions still pass a full sample rate") - } -} - -// TestClearEmptiesPersistedLog covers the admin API's "clear log" button. -func TestClearEmptiesPersistedLog(t *testing.T) { - l := openLogger(t, tempPath(t), nil) - for i := 1; i <= 4; i++ { - l.Log(entryFor(i)) - } - l.Flush() - if err := l.Clear(); err != nil { - t.Fatalf("clear: %v", err) - } - if got := l.Count(); got != 0 { - t.Errorf("Count() = %d after Clear, want 0", got) - } - page, err := l.Search(Query{Limit: 10}) - if err != nil { - t.Fatalf("search: %v", err) - } - if page.Total != 0 { - t.Errorf("Total = %d after Clear, want 0", page.Total) - } - // Logging keeps working afterwards, and the new entries are found. - l.Log(entryFor(9)) - l.Flush() - page, err = l.Search(Query{Limit: 10}) - if err != nil { - t.Fatalf("search: %v", err) - } - if page.Total != 1 || page.Items[0].Name != "host9.test." { - t.Fatalf("search after clear = %+v, want host9.test.", page.Items) - } -} - -// TestTopDomainsCounters covers the rolling per-domain panel: blocked counts -// are tracked separately from the total. -func TestTopDomainsCounters(t *testing.T) { - l := openLogger(t, tempPath(t), func(o *Options) { o.Path = "" }) - for i := 0; i < 3; i++ { - e := entryFor(1) - e.Name = "ads.test." - e.Action = ActionBlock - l.Log(e) - } - for i := 0; i < 2; i++ { - l.Log(entryFor(1)) - } - blocked := l.TopBlocked(5) - if len(blocked) != 1 { - t.Fatalf("TopBlocked = %+v, want one domain", blocked) - } - if blocked[0].Name != "ads.test" || blocked[0].Count != 3 || blocked[0].Blocked != 3 { - t.Errorf("TopBlocked[0] = %+v, want ads.test count 3 blocked 3", blocked[0]) - } - if blocked[0].QTypeS != "A" { - t.Errorf("QTypeS = %q, want A", blocked[0].QTypeS) - } - queried := l.TopQueried(5) - if len(queried) != 2 { - t.Fatalf("TopQueried = %+v, want two domains", queried) - } - if queried[0].Name != "ads.test" || queried[0].Count != 3 { - t.Errorf("TopQueried[0] = %+v, want ads.test count 3 first", queried[0]) - } - if got := l.TopDomains(5, true); len(got) != 1 { - t.Errorf("TopDomains(blockedOnly) = %+v, want one entry", got) - } -} - -func BenchmarkLog(b *testing.B) { - l, err := New(Options{Path: "", LiveBuffer: 4096, MaxEntries: 1024, TopDomains: 512, TopTTL: time.Minute}) - if err != nil { - b.Fatal(err) - } - defer func() { _ = l.Close() }() - e := entryFor(1) - b.ReportAllocs() - b.ResetTimer() - for i := 0; i < b.N; i++ { - l.Log(e) - } -} - -func BenchmarkRecent(b *testing.B) { - l, err := New(Options{Path: "", LiveBuffer: 4096, MaxEntries: 1024, TopDomains: 512, TopTTL: time.Minute}) - if err != nil { - b.Fatal(err) - } - defer func() { _ = l.Close() }() - for i := 0; i < 4096; i++ { - l.Log(entryFor(i%2000 + 1)) - } - b.ReportAllocs() - b.ResetTimer() - for i := 0; i < b.N; i++ { - _ = l.Recent(200) - } -} - -// TestEntriesWithNoTimestampAreStamped guards the LiveEntry field the SSE -// consumers render: an entry with no TS must not reach them as year 1. -func TestEntriesWithNoTimestampAreStamped(t *testing.T) { - l := openLogger(t, tempPath(t), func(o *Options) { - o.Path = "" - o.Now = func() time.Time { return time.Date(2024, 5, 1, 12, 0, 0, 0, time.UTC) } - }) - l.Log(Entry{Name: "clock.test.", QType: dns.TypeA, Action: ActionAllow}) - got := l.Recent(1) - if len(got) != 1 { - t.Fatalf("Recent(1) = %d entries, want 1", len(got)) - } - if !strings.HasSuffix(got[0].Name, "clock.test.") { - t.Errorf("Name = %q", got[0].Name) - } - want := time.Date(2024, 5, 1, 12, 0, 0, 0, time.UTC) - if !got[0].TS.Equal(want) { - t.Errorf("TS = %v, want the injected clock %v", got[0].TS, want) - } -} - -// TestFlushDoesNotShareItsBatchWithNewEntries pins a race the detector finds: -// Flush took the pending slice and reset it to length zero, so entries logged -// while it was still marshalling the batch were appended over the same backing -// array. Under -race this fails without the fix; without -race it can store -// the wrong entries. -func TestFlushDoesNotShareItsBatchWithNewEntries(t *testing.T) { - l := openLogger(t, tempPath(t), func(o *Options) { o.FlushInterval = time.Hour }) - for i := 0; i < 500; i++ { - l.Log(entryFor(i % 50)) // a batch big enough to take a while to store - } - done := make(chan struct{}) - go func() { - defer close(done) - for i := 0; i < 1000; i++ { - l.Log(entryFor(i % 50)) - if i%10 == 0 { - time.Sleep(10 * time.Microsecond) - } - } - }() - for i := 0; i < 20; i++ { - l.Flush() - } - <-done - l.Flush() -}