mats/fancy-dns
1
0 Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Make the resolver pure DNS: JSON access log on stdout instead of a log store

Browse Source 
The resolver kept its own query-log store (a bbolt ring, a live ring with SSE
fanout, rolling per-domain counters and dashboard time-series) for the console.
In a multi-node deployment each pod held a different slice of that, so every
view disagreed with itself, and the cost sat on the query path. Charts belong
in Grafana and log search in the log collector, so the store is gone.

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

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

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

Co-Authored-By: Claude Sonnet 5.5 <noreply@anthropic.com>
This commit is contained in:
matsandClaude Sonnet 5.5 committed 2026-10-16 09:53:04 +02:00
1 parent dd1117fd91
commit c6c5ca4ff7
31 files changed
+818 -3389
Download Patch File Download Diff File Expand all files Collapse all files

No files matched your search

internal/accesslog/accesslog.go
+308
View File
@@ -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):
}
})
}
internal/accesslog/accesslog_test.go
+132
View File
@@ -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()
}
internal/api/api.go
-55
View File
@@ -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))
internal/api/auth_test.go
-1
View File
@@ -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"},
internal/api/errors_test.go
-3
View File
@@ -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) {
internal/api/handlers.go
+2 -144
View File
@@ -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")
internal/api/harness_test.go
-61
View File
@@ -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 {
internal/api/routes_test.go
+2 -10
View File
@@ -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)
}
internal/api/sse_test.go
-243
View File
@@ -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")
}
}
internal/app/accesslog_test.go
+67
View File
@@ -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)
}
}
}
internal/app/app.go
+19 -36
View File
@@ -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
internal/app/contract_test.go
-94
View File
@@ -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.
internal/app/dump_shapes_test.go
+2 -2
View File
@@ -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)
internal/app/harness_test.go
+3 -2
View File
@@ -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)
}
internal/app/hooks.go
+8 -335
View File
@@ -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},
}
internal/app/integration_test.go
+17 -133
View File
@@ -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
internal/cache/cache_test.go
Vendored
-35
View File
@@ -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)
internal/cache/manager.go
Vendored
-103
View File
@@ -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
}
internal/config/config.go
+38 -64
View File
@@ -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 {
internal/engine/engine.go
+47 -33
View File
@@ -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()
internal/engine/engine_test.go
+37 -43
View File
@@ -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)
}
internal/engine/harness_test.go
+77 -19
View File
@@ -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
}
internal/engine/pins_test.go
+3 -3
View File
@@ -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)
}
internal/metrics/metrics.go
+31 -147
View File
@@ -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
}
internal/qlog/counts.go
-148
View File
@@ -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
}
internal/qlog/qlog.go
-784
View File
@@ -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
}
internal/qlog/qlog_test.go
-865
View File
@@ -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()
}