Add optional query statistics

Off by default (stats in jarl.yaml). When enabled, Jarl adds a loopback
statistics channel and a response log to named's configuration (merged
into existing logging/statistics-channels statements) and switches
response logging with rndc responselog, because the responselog option
only counts when named starts. jarld polls named's counters every minute
and tails the response log (resuming after restarts and across
rotation). It stores aggregates, never individual queries, in a separate
SQLite database: per-minute, hourly and daily counters (queries, result
codes, record types, views, zones, cache hits, upstream latency, DNSSEC)
and hourly/daily top lists (names, clients, NXDOMAIN and SERVFAIL names,
refused clients), each with its own retention. Clients can be anonymized
or excluded.

- Web UI: Statistics page with KPI tiles, queries and failed answers over
  time, a weekday x hour heatmap, top lists and breakdowns; SVG charts
  with hover/keyboard readouts, a table view and light/dark palettes
  validated for colour-vision deficiency.
- CLI: jarl stats status|summary|top|timeline|heatmap|breakdown.
- API: /api/v1/stats/*, behind a new "stats" permission resource.
- jarld brings named's configuration up to date with jarl.yaml at
  startup (engine.SyncConfig), never overwriting hand-edited files.
- resync now refuses to overwrite drifted files without force, as
  documented.
- tmpfiles.d creates /var/log/named (allowed by named's AppArmor profile
  on Debian 13 and Ubuntu).
- The e2e harness runs named with -f like the Debian unit.
- docs/stats.md, plus API, CLI, configuration, permissions and README
  updates.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
This commit is contained in:
abrown38andClaude Opus 5.5 committed 2026-10-07 20:21:34 +00:00
1 parent 0795a1001e
commit 3b7bee67f8
44 files changed
+4163 -42

No files matched your search

+564
View File
@@ -0,0 +1,564 @@
package stats
import (
"cmp"
"context"
"encoding/json"
"fmt"
"log/slog"
"net/netip"
"slices"
"strconv"
"strings"
"sync"
"time"
)
// Kinds of top lists.
const (
KindName = "name" // most queried names
KindClient = "client" // clients sending the most queries
KindNXDomain = "nxdomain" // names answered with NXDOMAIN
KindServFail = "servfail" // names answered with SERVFAIL
KindRefused = "refused" // clients that were refused
)
// Kinds lists the top-list kinds.
var Kinds = []string{KindName, KindClient, KindNXDomain, KindServFail, KindRefused}
// OtherZone is the zone key for names outside every local zone (answered
// by recursion, or refused).
const OtherZone = "-"
// Options configure a Collector.
type Options struct {
QueryLog bool
LogFile string
StatisticsChannel string // ADDRESS:PORT
TopN int
RetainMinute time.Duration
RetainHour time.Duration
RetainDay time.Duration
Anonymize bool
Exclude []netip.Prefix
Location *time.Location // for days and log timestamps (default: local time)
// EnsureLogging turns named's response logging on (rndc responselog
// on). It is called at start and when named answers queries but no
// log lines arrive.
EnsureLogging func(context.Context) (bool, error)
}
// ZoneIndex returns, per view name ("" when no views are used), the names
// of the zones this server is authoritative for (lowercase, without the
// final dot).
type ZoneIndex func() map[string][]string
// Status describes the collector's health.
type Status struct {
Enabled bool `json:"enabled"`
QueryLog bool `json:"query_log"`
LogFile string `json:"log_file,omitempty"`
StatisticsChannel string `json:"statistics_channel"`
LastPoll *time.Time `json:"last_poll,omitempty"`
PollError string `json:"poll_error,omitempty"`
LastLine *time.Time `json:"last_log_line,omitempty"`
LinesRead int64 `json:"log_lines_read"`
LogError string `json:"log_error,omitempty"`
Warnings []string `json:"warnings"`
FirstData *time.Time `json:"first_data,omitempty"`
Retention struct {
Minute string `json:"minute"`
Hour string `json:"hour"`
Day string `json:"day"`
} `json:"retention"`
}
// Collector gathers statistics into a Store.
type Collector struct {
opts Options
store *Store
zones ZoneIndex
log *slog.Logger
poller *Poller
tail *Tailer
now func() time.Time
mu sync.Mutex
minutes map[int64]map[string]int64 // minute -> counter -> value
hours map[int64]map[string]map[string]int64 // live hours: hour -> kind -> key -> count
// late holds counts for hours that were already written and added to
// their day (lines read after a restart); they are added, not
// replaced.
late map[int64]map[string]map[string]int64
liveHour int64
prev *Snapshot
zoneIdx map[string][]string
zoneAt time.Time
status Status
recentQ []int64 // queries per minute from the counters, last 10 minutes
recentL []int64 // response log lines per minute, last 10 minutes
linesMin int64
ensureAt time.Time
}
// maxKeys bounds the per-hour maps; rarely seen keys are dropped first.
const maxKeys = 200_000
// NewCollector creates a collector. Run starts it.
func NewCollector(store *Store, opts Options, zones ZoneIndex, log *slog.Logger) *Collector {
if opts.Location == nil {
opts.Location = time.Local
}
c := &Collector{opts: opts, store: store, zones: zones, log: log, poller: NewPoller(opts.StatisticsChannel), now: time.Now,
minutes: map[int64]map[string]int64{}, hours: map[int64]map[string]map[string]int64{}, late: map[int64]map[string]map[string]int64{}}
if opts.QueryLog {
c.tail = &Tailer{Path: opts.LogFile}
}
c.status = Status{Enabled: true, QueryLog: opts.QueryLog, StatisticsChannel: opts.StatisticsChannel, Warnings: []string{}}
if opts.QueryLog {
c.status.LogFile = opts.LogFile
}
c.status.Retention.Minute = humanDuration(opts.RetainMinute)
c.status.Retention.Hour = humanDuration(opts.RetainHour)
c.status.Retention.Day = humanDuration(opts.RetainDay)
return c
}
// Store returns the collector's store.
func (c *Collector) Store() *Store { return c.store }
// Options returns the collector's options.
func (c *Collector) Options() Options { return c.opts }
// Status returns the current status.
func (c *Collector) Status() Status {
c.mu.Lock()
defer c.mu.Unlock()
s := c.status
s.Warnings = append([]string{}, c.status.Warnings...)
return s
}
func (c *Collector) minuteOf(t time.Time) int64 { return t.Unix() - t.Unix()%60 }
func (c *Collector) hourOf(t time.Time) int64 { return t.Unix() - t.Unix()%3600 }
// dayOf returns the start of the local day containing t.
func (c *Collector) dayOf(t time.Time) int64 {
t = t.In(c.opts.Location)
return time.Date(t.Year(), t.Month(), t.Day(), 0, 0, 0, 0, c.opts.Location).Unix()
}
// Run collects until ctx is done.
func (c *Collector) Run(ctx context.Context) {
c.start(ctx)
tick := time.NewTicker(time.Second)
defer tick.Stop()
next := c.nextFlush()
for {
select {
case <-ctx.Done():
// Write what was collected; a restart continues the minute.
c.readLog()
c.flush(context.Background(), true)
if c.tail != nil {
c.tail.Close()
}
return
case <-tick.C:
c.readLog()
if !c.now().Before(next) {
c.flush(ctx, false)
next = c.nextFlush()
}
}
}
}
// nextFlush is two seconds into the next minute, so the minute that just
// ended is complete.
func (c *Collector) nextFlush() time.Time {
return time.Unix(c.minuteOf(c.now())+62, 0)
}
func (c *Collector) start(ctx context.Context) {
if c.tail != nil {
if v, _ := c.store.Meta(ctx, "tail"); v != "" {
var p Position
if json.Unmarshal([]byte(v), &p) == nil {
c.tail.Resume(p)
}
}
}
if v, _ := c.store.Meta(ctx, "first_data"); v != "" {
if n, err := strconv.ParseInt(v, 10, 64); err == nil {
t := time.Unix(n, 0)
c.status.FirstData = &t
}
}
// Continue the current hour's top lists, and fold hours that ended
// while jarld was not running into their days.
cur := c.hourOf(c.now())
c.liveHour = cur
b := &Batch{}
merged, _ := c.store.Meta(ctx, "merged_through")
if last, err := strconv.ParseInt(merged, 10, 64); err == nil {
from := max(last+3600, cur-48*3600)
for h := from; h < cur; h += 3600 {
for _, k := range Kinds {
if es, err := c.store.TopsAt(ctx, ResHour, h, k); err == nil && len(es) > 0 {
b.AddTops(ResDay, c.dayOf(time.Unix(h, 0)), k, es, 3*c.opts.TopN)
}
}
}
}
b.SetMeta("merged_through", strconv.FormatInt(cur-3600, 10))
for _, k := range Kinds {
es, err := c.store.TopsAt(ctx, ResHour, cur, k)
if err != nil || len(es) == 0 {
continue
}
m := c.topsMap(c.hours, cur, k)
for _, e := range es {
m[e.Key] = e.Count
}
}
if err := c.store.Commit(ctx, b); err != nil {
c.log.Warn("statistics: catching up failed", "err", err)
}
c.ensureLogging(ctx)
// The first poll is the baseline for the counters.
if snap, err := c.poller.Poll(ctx); err == nil {
c.prev = snap
t := c.now()
c.status.LastPoll = &t
} else {
c.status.PollError = err.Error()
}
c.prune(ctx)
c.log.Info("statistics collector started", "query_log", c.opts.QueryLog, "statistics_channel", c.opts.StatisticsChannel)
}
func (c *Collector) topsMap(hours map[int64]map[string]map[string]int64, hour int64, kind string) map[string]int64 {
h := hours[hour]
if h == nil {
h = map[string]map[string]int64{}
hours[hour] = h
}
m := h[kind]
if m == nil {
m = map[string]int64{}
h[kind] = m
}
return m
}
// hourMaps returns the per-kind maps of an hour, creating them.
func (c *Collector) hourMaps(hours map[int64]map[string]map[string]int64, hour int64) map[string]map[string]int64 {
for _, k := range Kinds {
c.topsMap(hours, hour, k)
}
return hours[hour]
}
func (c *Collector) count(minute int64, key string, n int64) {
m := c.minutes[minute]
if m == nil {
m = map[string]int64{}
c.minutes[minute] = m
}
m[key] += n
}
// readLog reads new response log lines.
func (c *Collector) readLog() {
if c.tail == nil {
return
}
c.mu.Lock()
defer c.mu.Unlock()
c.refreshZones()
_, err := c.tail.Read(c.handleLine)
if err != nil {
c.status.LogError = err.Error()
} else {
c.status.LogError = ""
}
}
// HandleLine processes one log line (exported for tests).
func (c *Collector) HandleLine(line string) {
c.mu.Lock()
defer c.mu.Unlock()
c.refreshZones()
c.handleLine(line)
}
func (c *Collector) handleLine(line string) {
ev, ok := ParseResponse(line, c.opts.Location)
if !ok {
return
}
c.status.LinesRead++
c.linesMin++
t := ev.Time
c.status.LastLine = &t
for _, p := range c.opts.Exclude {
if p.Contains(ev.Client) {
return
}
}
minute, hour := c.minuteOf(ev.Time), c.hourOf(ev.Time)
view := ev.View
if view == "" {
view = "_default"
}
c.count(minute, "responses", 1)
c.count(minute, "view:"+view, 1)
c.count(minute, "zone:"+c.zoneOf(ev.Name, ev.View), 1)
client := clientKey(ev.Client, c.opts.Anonymize)
hours := c.hours
if hour < c.liveHour {
hours = c.late
}
hours[hour] = c.hourMaps(hours, hour)
tops := hours[hour]
tops[KindName][ev.Name]++
tops[KindClient][client]++
switch ev.RCode {
case "NXDOMAIN":
tops[KindNXDomain][ev.Name]++
case "SERVFAIL":
tops[KindServFail][ev.Name]++
case "REFUSED":
tops[KindRefused][client]++
}
for _, m := range tops {
if len(m) > maxKeys {
shrink(m)
}
}
}
// shrink drops the rarest keys until the map is well under maxKeys.
func shrink(m map[string]int64) {
for limit := int64(1); len(m) > maxKeys*8/10; limit++ {
for k, v := range m {
if v <= limit {
delete(m, k)
}
}
}
}
// clientKey is how a client is recorded: its address, or its network
// when anonymizing.
func clientKey(a netip.Addr, anonymize bool) string {
if !anonymize {
return a.String()
}
bits := 24
if a.Is6() {
bits = 48
}
p, _ := a.Prefix(bits)
return p.String()
}
func (c *Collector) refreshZones() {
if c.zones == nil || c.zoneIdx != nil && c.now().Sub(c.zoneAt) < 5*time.Minute {
return
}
idx := c.zones()
for v, zs := range idx {
// Longest first, so the most specific zone matches.
slices.SortFunc(zs, func(a, b string) int { return cmp.Compare(len(b), len(a)) })
idx[v] = zs
}
c.zoneIdx, c.zoneAt = idx, c.now()
}
// zoneOf returns the local zone a name belongs to in a view, or OtherZone.
func (c *Collector) zoneOf(name, view string) string {
for _, z := range c.zoneIdx[view] {
if name == z || z == "." || strings.HasSuffix(name, "."+z) {
return z
}
}
return OtherZone
}
// flush polls named's counters and writes everything collected for
// finished minutes (all minutes when final).
func (c *Collector) flush(ctx context.Context, final bool) {
now := c.now()
cur := c.minuteOf(now)
snap, perr := c.poller.Poll(ctx)
c.mu.Lock()
if perr != nil {
c.status.PollError = perr.Error()
} else {
c.status.PollError = ""
c.status.LastPoll = &now
if c.prev != nil {
d := Delta(c.prev, snap)
// The change happened during the minute that just ended.
for k, v := range d {
c.count(cur-60, k, v)
}
c.noteRecent(d["queries"])
}
c.prev = snap
}
b := &Batch{}
first := c.status.FirstData == nil
for m, vals := range c.minutes {
if m >= cur && !final {
continue
}
t := time.Unix(m, 0)
b.AddCounters(ResMinute, m, vals)
b.AddCounters(ResHour, c.hourOf(t), vals)
b.AddCounters(ResDay, c.dayOf(t), vals)
delete(c.minutes, m)
if first && len(vals) > 0 {
ft := t
c.status.FirstData = &ft
first = false
b.SetMeta("first_data", strconv.FormatInt(m, 10))
}
}
curHour := c.hourOf(now)
for h, kinds := range c.late {
for k, m := range kinds {
if len(m) > 0 {
b.AddTops(ResHour, h, k, top(m, c.opts.TopN), c.opts.TopN)
b.AddTops(ResDay, c.dayOf(time.Unix(h, 0)), k, top(m, c.opts.TopN), 3*c.opts.TopN)
}
}
delete(c.late, h)
}
for h, kinds := range c.hours {
for k, m := range kinds {
b.SetTops(ResHour, h, k, top(m, c.opts.TopN))
}
if h < curHour {
// The hour is over: add it to its day.
for k, m := range kinds {
b.AddTops(ResDay, c.dayOf(time.Unix(h, 0)), k, top(m, c.opts.TopN), 3*c.opts.TopN)
}
delete(c.hours, h)
b.SetMeta("merged_through", strconv.FormatInt(h, 10))
}
}
c.liveHour = curHour
if c.tail != nil {
pos, _ := json.Marshal(c.tail.Position())
b.SetMeta("tail", string(pos))
}
c.updateWarnings()
c.mu.Unlock()
if err := c.store.Commit(ctx, b); err != nil {
c.log.Error("statistics: writing failed", "err", err)
}
// Queries but no log lines for a while: named's response logging may
// have been turned off (or named restarted without it).
c.mu.Lock()
quiet := len(c.recentL) >= 2 && c.recentL[len(c.recentL)-1] == 0 && c.recentL[len(c.recentL)-2] == 0 &&
c.recentQ[len(c.recentQ)-1] > 0 && c.recentQ[len(c.recentQ)-2] > 0
c.mu.Unlock()
if quiet && !final {
c.ensureLogging(ctx)
}
// Prune once an hour.
if now.Minute() == 0 || final {
c.prune(ctx)
}
}
// ensureLogging makes sure named logs responses (at most every 5 minutes).
func (c *Collector) ensureLogging(ctx context.Context) {
if !c.opts.QueryLog || c.opts.EnsureLogging == nil || c.now().Sub(c.ensureAt) < 5*time.Minute {
return
}
c.ensureAt = c.now()
changed, err := c.opts.EnsureLogging(ctx)
switch {
case err != nil:
c.log.Warn("statistics: could not turn on named's response logging (rndc responselog on)", "err", err)
case changed:
c.log.Info("statistics: turned on named's response logging (rndc responselog on)")
}
}
// noteRecent records the last ten minutes of query counts and log lines
// for the health warnings.
func (c *Collector) noteRecent(queries int64) {
c.recentQ = append(c.recentQ, queries)
c.recentL = append(c.recentL, c.linesMin)
c.linesMin = 0
if len(c.recentQ) > 10 {
c.recentQ, c.recentL = c.recentQ[1:], c.recentL[1:]
}
}
func (c *Collector) updateWarnings() {
w := []string{}
if c.status.PollError != "" {
w = append(w, c.status.PollError)
}
if c.opts.QueryLog {
var q, l int64
for i := range c.recentQ {
q += c.recentQ[i]
l += c.recentL[i]
}
if len(c.recentQ) >= 5 && q > 0 && l == 0 {
w = append(w, fmt.Sprintf("named answered %d queries in the last %d minutes, but Jarl read no response log lines from %s: check that /var/log/named exists and is writable by named, and that responselog is not turned off", q, len(c.recentQ), c.opts.LogFile))
}
if c.status.LogError != "" {
w = append(w, "reading the response log failed: "+c.status.LogError)
}
}
c.status.Warnings = w
}
// top returns the n largest entries of m.
func top(m map[string]int64, n int) []Entry {
out := make([]Entry, 0, len(m))
for k, v := range m {
out = append(out, Entry{k, v})
}
slices.SortFunc(out, func(a, b Entry) int {
if a.Count != b.Count {
return cmp.Compare(b.Count, a.Count)
}
return cmp.Compare(a.Key, b.Key)
})
if len(out) > n {
out = out[:n]
}
return out
}
func (c *Collector) prune(ctx context.Context) {
now := c.now().Unix()
for res, keep := range map[string]time.Duration{ResMinute: c.opts.RetainMinute, ResHour: c.opts.RetainHour, ResDay: c.opts.RetainDay} {
if keep <= 0 {
continue
}
if n, err := c.store.Prune(ctx, res, now-int64(keep.Seconds())); err != nil {
c.log.Warn("statistics: pruning failed", "err", err)
} else if n > 0 {
c.log.Debug("statistics: pruned", "resolution", res, "rows", n)
}
}
}
func humanDuration(d time.Duration) string {
if d%(24*time.Hour) == 0 && d > 0 {
return strconv.Itoa(int(d/(24*time.Hour))) + "d"
}
return d.String()
}