diff --git a/CHANGELOG.md b/CHANGELOG.md index a7a6e7e..91104e9 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -8,29 +8,26 @@ All notable changes to Jarl are documented here. The format follows The first version, to be released as 0.1.0. -### Fixed - -- The negative-caching warning now uses the effective negative TTL, which - is the smaller of the SOA minimum and the zone's default TTL (RFC 2308). - It explains the real effect (new names can stay invisible to resolvers - that already asked) and gives the command that fixes it. Before, it - fired on the SOA minimum alone and wrongly blamed BIND's resolver cap. -- Problems printed by `jarld check` show zone names without the trailing dot. -- `jarl` now shows the warnings a change introduces when it is applied or - staged, not only on dry runs. -- `jarl check` and `jarl resync` no longer print named-checkconf's routine - "loaded serial" lines, only its errors and warnings. -- `jarl zone list` showed only primary zones: `zone create`'s default - `--type primary` leaked into the list filter through a shared variable. - Hint, secondary, forward and other zones are listed again. -- named-checkconf and named-checkzone output is classified by the tools' - exit code. Their warnings (e.g. `both "recursion no;" and "allow-recursion" - active`) were shown as errors. They are now shown as warnings in the - CLI, `jarld check` and the web UI. -- The `zone_outside_view` error says how to fix it (`--adopt-zones`). - ### Added +- **Query statistics** (off by default; `stats` in jarl.yaml, docs/stats.md). + When enabled, Jarl adds a loopback statistics channel and a response log to + named's configuration (merged into existing `logging` and + `statistics-channels` statements) and switches response logging with + `rndc responselog`. jarld aggregates named's counters and the log into a + separate SQLite database: per-minute, hourly and daily counters (queries, + result codes, record types, views, zones, cache hits, upstream latency, + DNSSEC) and hourly and daily top lists (names, clients, NXDOMAIN and + SERVFAIL names, refused clients), each with its own retention. Clients can + be anonymized or excluded. It is shown on a new Statistics page in the web + UI (KPI tiles, queries and failed answers over time, a weekday x hour + heatmap, top lists and breakdowns, each chart with a table view), in + `jarl stats status|summary|top|timeline|heatmap|breakdown`, and in the API + under `/api/v1/stats/`, behind the new `stats` permission. Works with the + bind9 packages of Debian 13 and Ubuntu 26.04. +- At startup jarld brings named's configuration up to date with jarl.yaml + settings that affect it (such as statistics), through the usual checked + pipeline. Files changed by hand are never overwritten. - **jarld daemon**: REST API (`/api/v1`) and embedded web UI, with SQLite as the source of truth for the whole BIND configuration. Runs under systemd (`Type=notify`, sandboxed, unprivileged `jarl` user in group `bind`). @@ -101,3 +98,32 @@ The first version, to be released as 0.1.0. - **Documentation**: concepts, install and adoption, configuration, CLI, API, permissions, ACME, validation, operations and development guides, and a split-DNS guide for adding views to a server that has none. + +### Changed + +- `jarl resync` / `jarld resync` refuse to overwrite files that were changed + outside Jarl unless `--force` is given, as documented. Before, they always + overwrote them. + +### Fixed + +- The negative-caching warning now uses the effective negative TTL, which + is the smaller of the SOA minimum and the zone's default TTL (RFC 2308). + It explains the real effect (new names can stay invisible to resolvers + that already asked) and gives the command that fixes it. Before, it + fired on the SOA minimum alone and wrongly blamed BIND's resolver cap. +- Problems printed by `jarld check` show zone names without the trailing dot. +- `jarl` now shows the warnings a change introduces when it is applied or + staged, not only on dry runs. +- `jarl check` and `jarl resync` no longer print named-checkconf's routine + "loaded serial" lines, only its errors and warnings. +- `jarl zone list` showed only primary zones: `zone create`'s default + `--type primary` leaked into the list filter through a shared variable. + Hint, secondary, forward and other zones are listed again. +- named-checkconf and named-checkzone output is classified by the tools' + exit code. Their warnings (e.g. `both "recursion no;" and "allow-recursion" + active`) were shown as errors. They are now shown as warnings in the + CLI, `jarld check` and the web UI. +- The `zone_outside_view` error says how to fix it (`--adopt-zones`). +- The end-to-end test starts named with `-f` like the Debian unit; with `-g`, + named sends all logging to stderr. diff --git a/README.md b/README.md index 4a2e8e9..afda6d8 100644 --- a/README.md +++ b/README.md @@ -39,6 +39,11 @@ error: www.adbraun.lol has a CNAME, so it can't have any other records (found A) argon2id, sessions have CSRF protection, logins are rate limited. * **Audit log** of every login, change and token, with user, token, IP and outcome. +* **Query statistics** (optional, off by default): queries over time, + busiest hours of the week, top names and clients, NXDOMAIN and refused + queries, record types, cache hit rate. Shown in the web UI and the CLI, + and exportable as JSON. Stored as aggregates in a separate database with + retention you set. * **Let's Encrypt DNS-01** built in: `jarl acme` plus certbot and acme.sh hooks, including CNAME delegation to a dedicated ACME zone. * **Adopts an existing server**: imports named.conf and zone files @@ -82,6 +87,7 @@ in `/etc/jarl/jarl.yaml` to reach it from your management network. | [docs/permissions.md](docs/permissions.md) | Users, tokens, grants and roles | | [docs/views.md](docs/views.md) | Split DNS: adding views to a server that has none | | [docs/acme.md](docs/acme.md) | Let's Encrypt DNS-01 with certbot and acme.sh | +| [docs/stats.md](docs/stats.md) | Query statistics: enabling, what is collected, retention | | [docs/validation.md](docs/validation.md) | Every check Jarl makes | | [docs/operations.md](docs/operations.md) | Backups, drift, failures, recovery, monitoring | | [docs/development.md](docs/development.md) | Code layout, tests against real BIND, conventions | @@ -94,6 +100,9 @@ these pages: * **Dashboard**: named status, adoption, drift, recent changes, open problems. +* **Statistics** (when enabled): queries over time, failed answers, a + weekday x hour heatmap, top names and clients, and breakdowns. Every chart + has a table view. * **Zones**: list, create (fields adapt to the zone type), per-zone records with inline editing and type-specific hints, settings (SOA, TTL, serial policy, view), options, the generated zone file, and pasting a zone file diff --git a/cmd/jarl/main.go b/cmd/jarl/main.go index a6e6fb6..4777124 100644 --- a/cmd/jarl/main.go +++ b/cmd/jarl/main.go @@ -172,7 +172,7 @@ Exit codes: 0 ok, 1 error, 3 not authenticated or not allowed, 4 not found, root.AddCommand(c) } } - add("dns", zoneCmd(), recordCmd(), viewCmd(), aclCmd(), tsigCmd(), optionCmd(), settingsCmd(), acmeCmd(), searchCmd()) + add("dns", zoneCmd(), recordCmd(), viewCmd(), aclCmd(), tsigCmd(), optionCmd(), settingsCmd(), acmeCmd(), searchCmd(), statsCmd()) add("changes", applyCmd(), changesetCmd(), historyCmd()) add("admin", statusCmd(), whoamiCmd(), userCmd(), tokenCmd(), auditCmd(), checkCmd(), resyncCmd(), configCmd()) return root diff --git a/cmd/jarl/main_test.go b/cmd/jarl/main_test.go index 501021f..e9eb9f3 100644 --- a/cmd/jarl/main_test.go +++ b/cmd/jarl/main_test.go @@ -6,6 +6,7 @@ import ( "net/http" "net/http/httptest" "path/filepath" + "strings" "testing" "go.yaml.in/yaml/v3" @@ -116,6 +117,10 @@ func TestListQueries(t *testing.T) { srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { got = r.URL.Path + "?" + r.URL.RawQuery w.Header().Set("Content-Type", "application/json") + if strings.Contains(r.URL.Path, "/stats/") && !strings.HasSuffix(r.URL.Path, "/top") && !strings.HasSuffix(r.URL.Path, "/breakdown") { + w.Write([]byte("{}")) + return + } w.Write([]byte("[]")) })) defer srv.Close() @@ -129,6 +134,12 @@ func TestListQueries(t *testing.T) { {[]string{"zone", "list", "--view", "internal"}, "/api/v1/zones?view=internal"}, {[]string{"changeset", "list"}, "/api/v1/changesets?status=open"}, {[]string{"option", "list", "--all"}, "/api/v1/options?"}, + {[]string{"stats", "summary"}, "/api/v1/stats/summary?since=24h&top=10"}, + {[]string{"stats", "heatmap"}, "/api/v1/stats/heatmap?key=queries&since=28d"}, + {[]string{"stats", "breakdown", "rcode"}, "/api/v1/stats/breakdown?group=rcode&since=24h"}, + {[]string{"stats", "top", "clients", "--since", "7d"}, "/api/v1/stats/top?kind=client&limit=20&since=7d"}, + {[]string{"stats", "top", "nxdomain"}, "/api/v1/stats/top?kind=nxdomain&limit=20&since=24h"}, + {[]string{"stats", "timeline", "--key", "queries", "--key", "rcode:*"}, "/api/v1/stats/timeline?key=queries&key=rcode%3A%2A&since=24h&step=auto"}, } { got = "" root := rootCmd() diff --git a/cmd/jarl/stats.go b/cmd/jarl/stats.go new file mode 100644 index 0000000..8cf3bc8 --- /dev/null +++ b/cmd/jarl/stats.go @@ -0,0 +1,378 @@ +package main + +import ( + "fmt" + "io" + "math" + "strconv" + "strings" + "time" + + "github.com/spf13/cobra" + + "jarl/internal/stats" +) + +func statsCmd() *cobra.Command { + cmd := &cobra.Command{ + Use: "stats", + Short: "Query statistics: volume over time, top names and clients, result codes", + Long: `Query statistics collected from named (see docs/stats.md). They must be +enabled in /etc/jarl/jarl.yaml (stats.enabled: true). + +Ranges are given with --since: 90m, 24h, 7d, 2w. Use -o json or -o yaml to +export the data.`, + } + // Each command has its own --since variable: their defaults differ, and + // a shared variable would take the last default for all of them. + var summarySince, topSince, timelineSince, heatmapSince, breakdownSince string + sinceFlag := func(c *cobra.Command, v *string, def, help string) { + c.Flags().StringVar(v, "since", def, help) + } + const sinceHelp = "time range: 90m, 24h, 7d, 2w" + + status := &cobra.Command{ + Use: "status", + Short: "Show whether statistics are collected and any problems", + RunE: func(cmd *cobra.Command, args []string) error { + c, err := newClient() + if err != nil { + return err + } + var st stats.Status + if err := c.Get(ctx(), "/stats/status", nil, &st); err != nil { + return err + } + return output(st, func(w io.Writer) { + if !st.Enabled { + fmt.Fprintln(w, "Statistics:\tdisabled (set stats.enabled: true in /etc/jarl/jarl.yaml and restart jarl)") + return + } + mode := "counters and response log" + if !st.QueryLog { + mode = "counters only" + } + fmt.Fprintf(w, "Statistics:\tenabled (%s)\n", mode) + fmt.Fprintf(w, "Statistics channel:\t%s, last read %s\n", st.StatisticsChannel, fmtTime(st.LastPoll)) + if st.QueryLog { + fmt.Fprintf(w, "Response log:\t%s, %d lines read, last %s\n", st.LogFile, st.LinesRead, fmtTime(st.LastLine)) + } + fmt.Fprintf(w, "Data since:\t%s\n", fmtTime(st.FirstData)) + fmt.Fprintf(w, "Retention:\tminutes %s, hours %s, days %s\n", st.Retention.Minute, st.Retention.Hour, st.Retention.Day) + for _, warn := range st.Warnings { + fmt.Fprintf(w, "Warning:\t%s\n", warn) + } + }) + }, + } + + var topN int + summary := &cobra.Command{ + Use: "summary", + Short: "Totals, result codes, record types and the top names and clients", + RunE: func(cmd *cobra.Command, args []string) error { + c, err := newClient() + if err != nil { + return err + } + var s stats.Summary + if err := c.Get(ctx(), "/stats/summary", q("since", summarySince, "top", strconv.Itoa(topN)), &s); err != nil { + return err + } + return output(s, func(w io.Writer) { + fmt.Fprintf(w, "Range:\t%s to %s\n", s.From.Local().Format("2006-01-02 15:04"), s.To.Local().Format("2006-01-02 15:04")) + fmt.Fprintf(w, "Queries:\t%d (%.2f per second on average)\n", s.Queries, s.AvgQPS) + if s.Peak != nil { + fmt.Fprintf(w, "Busiest %s:\t%s with %d queries\n", s.Peak.Per, s.Peak.Time.Local().Format("2006-01-02 15:04"), s.Peak.Queries) + } + if s.CacheHitRatio != nil { + fmt.Fprintf(w, "Cache hit ratio:\t%.1f%%\n", *s.CacheHitRatio*100) + } + if s.NXDomainRatio != nil { + fmt.Fprintf(w, "NXDOMAIN:\t%.1f%% of queries\n", *s.NXDomainRatio*100) + } + fmt.Fprintf(w, "Result codes:\t%s\n", entryLine(s.RCodes, s.Queries, 6)) + fmt.Fprintf(w, "Record types:\t%s\n", entryLine(s.QTypes, s.Queries, 8)) + if len(s.Answers) > 0 { + fmt.Fprintf(w, "Answers:\t%s\n", entryLine(s.Answers, s.Queries, 2)) + } + if len(s.Views) > 0 { + fmt.Fprintf(w, "Views:\t%s\n", entryLine(s.Views, 0, 10)) + } + if len(s.Zones) > 0 { + fmt.Fprintf(w, "Zones:\t%s\n", strings.ReplaceAll(entryLine(s.Zones, 0, 10), stats.OtherZone+" ", "other ")) + } + for _, k := range []string{stats.KindName, stats.KindClient, stats.KindNXDomain} { + es := s.Tops[k] + if len(es) == 0 { + continue + } + fmt.Fprintf(w, "\n%s\t\n", map[string]string{stats.KindName: "Top names", stats.KindClient: "Top clients", stats.KindNXDomain: "Top NXDOMAIN names"}[k]) + for _, e := range es { + fmt.Fprintf(w, " %s\t%d\n", e.Key, e.Count) + } + } + }) + }, + } + sinceFlag(summary, &summarySince, "24h", sinceHelp) + summary.Flags().IntVar(&topN, "top", 10, "entries per top list") + + var limit int + top := &cobra.Command{ + Use: "top [names|clients|nxdomain|servfail|refused]", + Short: "The most queried names, busiest clients, names with errors, refused clients", + Example: ` jarl stats top names --since 7d + jarl stats top clients --limit 50 + jarl stats top nxdomain # misconfigured hosts and typos + jarl stats top refused # who is asking for what they may not have`, + Args: cobra.MaximumNArgs(1), + RunE: func(cmd *cobra.Command, args []string) error { + kind := stats.KindName + if len(args) == 1 { + kind = strings.TrimSuffix(strings.ToLower(args[0]), "s") + if kind == "nxdomain" || kind == "servfail" { + kind = strings.ToLower(args[0]) + } + } + c, err := newClient() + if err != nil { + return err + } + var es []stats.Entry + if err := c.Get(ctx(), "/stats/top", q("kind", kind, "since", topSince, "limit", strconv.Itoa(limit)), &es); err != nil { + return err + } + return output(es, func(w io.Writer) { + var total int64 + for _, e := range es { + total += e.Count + } + head := map[string]string{stats.KindClient: "CLIENT", stats.KindRefused: "CLIENT"}[kind] + if head == "" { + head = "NAME" + } + fmt.Fprintf(w, "#\t%s\tQUERIES\t\n", head) + for i, e := range es { + fmt.Fprintf(w, "%d\t%s\t%d\t%s\n", i+1, e.Key, e.Count, bar(e.Count, es[0].Count, 20)) + } + }) + }, + } + sinceFlag(top, &topSince, "24h", sinceHelp) + top.Flags().IntVar(&limit, "limit", 20, "how many") + + var step string + var keys []string + var table bool + timeline := &cobra.Command{ + Use: "timeline", + Short: "Counters over time (queries by default)", + Example: ` jarl stats timeline --since 6h + jarl stats timeline --since 7d --key rcode:NXDOMAIN + jarl stats timeline --since 24h --key 'qtype:*' -o json`, + RunE: func(cmd *cobra.Command, args []string) error { + c, err := newClient() + if err != nil { + return err + } + qv := q("since", timelineSince, "step", step) + for _, k := range keys { + qv.Add("key", k) + } + var tl stats.Timeline + if err := c.Get(ctx(), "/stats/timeline", qv, &tl); err != nil { + return err + } + return output(tl, func(w io.Writer) { + for _, s := range tl.Series { + var total, peak int64 + for _, v := range s.Values { + total += v + peak = max(peak, v) + } + fmt.Fprintf(w, "%s\ttotal %d, peak %d per %s\n", s.Key, total, peak, tl.Step) + fmt.Fprintf(w, "\t%s\n", sparkline(s.Values)) + } + if len(tl.Times) > 0 { + fmt.Fprintf(w, "\t%s ... %s\n", time.Unix(tl.Times[0], 0).Local().Format("Jan 2 15:04"), time.Unix(tl.Times[len(tl.Times)-1], 0).Local().Format("Jan 2 15:04")) + } + if !table { + return + } + fmt.Fprint(w, "\nTIME") + for _, s := range tl.Series { + fmt.Fprintf(w, "\t%s", strings.ToUpper(s.Key)) + } + fmt.Fprintln(w) + for i, t := range tl.Times { + fmt.Fprint(w, time.Unix(t, 0).Local().Format("2006-01-02 15:04")) + for _, s := range tl.Series { + fmt.Fprintf(w, "\t%d", s.Values[i]) + } + fmt.Fprintln(w) + } + }) + }, + } + sinceFlag(timeline, &timelineSince, "24h", sinceHelp) + timeline.Flags().StringVar(&step, "step", "auto", "bucket size: auto, 1m, 5m, 15m, 1h, 6h, 1d") + timeline.Flags().BoolVar(&table, "table", false, "also print every bucket (use -o json to export)") + timeline.Flags().StringArrayVar(&keys, "key", nil, `counter (repeatable), e.g. queries, rcode:NXDOMAIN, 'qtype:*' (default queries)`) + + var hmKey string + heatmap := &cobra.Command{ + Use: "heatmap", + Short: "Average queries per hour by weekday and hour of day", + RunE: func(cmd *cobra.Command, args []string) error { + c, err := newClient() + if err != nil { + return err + } + var hm stats.Heatmap + if err := c.Get(ctx(), "/stats/heatmap", q("since", heatmapSince, "key", hmKey), &hm); err != nil { + return err + } + return output(hm, func(w io.Writer) { + peak := 0.0 + for d := range 7 { + for h := range 24 { + peak = math.Max(peak, hm.Avg[d][h]) + } + } + fmt.Fprintf(w, "Average %s per hour since %s (darker = busier, · = no data)\n\n", hm.Key, hm.From.Local().Format("2006-01-02")) + fmt.Fprint(w, " ") + for h := 0; h < 24; h += 3 { + fmt.Fprintf(w, "%-6s", fmt.Sprintf("%02d", h)) + } + fmt.Fprintln(w) + shades := []string{"░░", "▒▒", "▓▓", "██"} + for d, day := range []string{"Mon", "Tue", "Wed", "Thu", "Fri", "Sat", "Sun"} { + fmt.Fprintf(w, "%s ", day) + for h := range 24 { + v := hm.Avg[d][h] + switch { + case v < 0: + fmt.Fprint(w, "· ") + case peak <= 0: + fmt.Fprint(w, shades[0]) + default: + fmt.Fprint(w, shades[min(int(v/peak*float64(len(shades))), len(shades)-1)]) + } + } + fmt.Fprintln(w) + } + fmt.Fprintf(w, "\nBusiest slot: %.0f %s per hour on average\n", peak, hm.Key) + }) + }, + } + sinceFlag(heatmap, &heatmapSince, "28d", "time range (at most the hourly retention)") + heatmap.Flags().StringVar(&hmKey, "key", "queries", "counter to average") + + breakdown := &cobra.Command{ + Use: "breakdown GROUP", + Short: "Totals by " + strings.Join(stats.Groups, ", "), + Example: ` jarl stats breakdown qtype + jarl stats breakdown zone --since 7d + jarl stats breakdown rtt # upstream response times of recursion`, + Args: cobra.ExactArgs(1), + RunE: func(cmd *cobra.Command, args []string) error { + c, err := newClient() + if err != nil { + return err + } + var es []stats.Entry + if err := c.Get(ctx(), "/stats/breakdown", q("group", args[0], "since", breakdownSince), &es); err != nil { + return err + } + return output(es, func(w io.Writer) { + var total int64 + for _, e := range es { + total += e.Count + } + fmt.Fprintf(w, "%s\tCOUNT\tSHARE\t\n", strings.ToUpper(args[0])) + for _, e := range es { + key := e.Key + if args[0] == "zone" && key == stats.OtherZone { + key = "(not a local zone)" + } + fmt.Fprintf(w, "%s\t%d\t%.1f%%\t%s\n", key, e.Count, pct(e.Count, total), bar(e.Count, es[0].Count, 20)) + } + }) + }, + } + sinceFlag(breakdown, &breakdownSince, "24h", sinceHelp) + + cmd.AddCommand(status, summary, top, timeline, heatmap, breakdown) + return cmd +} + +func pct(n, total int64) float64 { + if total == 0 { + return 0 + } + return float64(n) / float64(total) * 100 +} + +// entryLine formats the first n entries as "A 61% · AAAA 30% · ...". +func entryLine(es []stats.Entry, total int64, n int) string { + if total == 0 { + for _, e := range es { + total += e.Count + } + } + var parts []string + for i, e := range es { + if i == n { + parts = append(parts, fmt.Sprintf("+%d more", len(es)-n)) + break + } + parts = append(parts, fmt.Sprintf("%s %.1f%%", e.Key, pct(e.Count, total))) + } + if len(parts) == 0 { + return "-" + } + return strings.Join(parts, " · ") +} + +func bar(v, peak int64, width int) string { + if peak <= 0 { + return "" + } + n := int(math.Round(float64(v) / float64(peak) * float64(width))) + return strings.Repeat("■", max(n, 1)) +} + +// sparkline draws values with block characters, at most 120 wide. +func sparkline(vals []int64) string { + if len(vals) == 0 { + return "" + } + if len(vals) > 120 { + // Combine neighbouring buckets. + per := (len(vals) + 119) / 120 + var merged []int64 + for i := 0; i < len(vals); i += per { + var s int64 + for _, v := range vals[i:min(i+per, len(vals))] { + s += v + } + merged = append(merged, s) + } + vals = merged + } + blocks := []rune("▁▂▃▄▅▆▇█") + var peak int64 + for _, v := range vals { + peak = max(peak, v) + } + var sb strings.Builder + for _, v := range vals { + if peak == 0 { + sb.WriteRune(blocks[0]) + continue + } + sb.WriteRune(blocks[min(int(float64(v)/float64(peak)*float64(len(blocks)-1)+0.5), len(blocks)-1)]) + } + return sb.String() +} diff --git a/cmd/jarld/admin.go b/cmd/jarld/admin.go index fb32014..6f2a0bc 100644 --- a/cmd/jarld/admin.go +++ b/cmd/jarld/admin.go @@ -302,7 +302,7 @@ func renderCmd() *cobra.Command { return err } paths := render.Paths{ConfigDir: filepath.Join(out, "config"), ZoneDir: filepath.Join(out, "zones"), CacheDir: filepath.Join(out, "cache")} - o := render.Render(st, paths) + o := render.Render(st, paths, renderExtras(a.cfg)) for _, f := range o.Files { if err := os.MkdirAll(filepath.Dir(f.Path), 0o750); err != nil { return err diff --git a/cmd/jarld/main.go b/cmd/jarld/main.go index 684b5e7..2085f4e 100644 --- a/cmd/jarld/main.go +++ b/cmd/jarld/main.go @@ -11,6 +11,7 @@ import ( "io" "log/slog" "net" + "net/netip" "os" "os/signal" "path/filepath" @@ -28,6 +29,7 @@ import ( "jarl/internal/model" "jarl/internal/render" "jarl/internal/server" + "jarl/internal/stats" "jarl/internal/store" "jarl/internal/version" "jarl/internal/web" @@ -118,10 +120,72 @@ func openApp(allowMissingConfig bool) (*app, error) { FileGroup: cfg.BIND.FileGroup, ReloadTimeout: time.Duration(cfg.BIND.ReloadTimeout), NoReload: cfg.BIND.NoReload, + Extras: renderExtras(cfg), }, log) return &app{cfg: cfg, log: log, store: st, eng: eng, owner: owner}, nil } +// openStats opens the statistics database (next to, not inside, Jarl's +// configuration database). +func openStats(a *app) (*stats.Store, error) { + path := a.cfg.Stats.Database + if err := os.MkdirAll(filepath.Dir(path), 0o750); err != nil { + return nil, err + } + ss, err := stats.OpenStore(path) + if err != nil { + return nil, err + } + return ss, nil +} + +func statsOptions(cfg *config.Config) stats.Options { + sc := cfg.Stats + o := stats.Options{QueryLog: sc.QueryLog, LogFile: sc.LogFile, StatisticsChannel: sc.StatisticsChannel, TopN: sc.TopN, + RetainMinute: time.Duration(sc.Retention.Minute), RetainHour: time.Duration(sc.Retention.Hour), RetainDay: time.Duration(sc.Retention.Day), + Anonymize: sc.AnonymizeClients} + for _, p := range sc.ExcludeClients { + if pf, err := config.ParsePrefix(p); err == nil { + o.Exclude = append(o.Exclude, pf.Masked()) + } + } + return o +} + +// zoneIndex lists the zones named answers authoritatively, per view, so +// statistics can be broken down by zone. +func zoneIndex(a *app) stats.ZoneIndex { + return func() map[string][]string { + st, err := a.store.LoadState(context.Background()) + if err != nil { + return nil + } + out := map[string][]string{} + for _, z := range st.Zones { + if z.Type != model.ZonePrimary && z.Type != model.ZoneSecondary && z.Type != model.ZoneMirror { + continue + } + v := st.ViewName(z) + out[v] = append(out[v], strings.TrimSuffix(z.Name, ".")) + } + return out + } +} + +// renderExtras turns jarl.yaml settings that change named's configuration +// into render extras. +func renderExtras(cfg *config.Config) render.Extras { + var x render.Extras + if cfg.Stats.Enabled { + h := &render.StatsHooks{Channel: netip.MustParseAddrPort(cfg.Stats.StatisticsChannel)} + if cfg.Stats.QueryLog { + h.LogFile, h.LogVersions, h.LogSize = cfg.Stats.LogFile, cfg.Stats.LogVersions, cfg.Stats.LogSize + } + x.Stats = h + } + return x +} + func (a *app) close() { a.store.Close() // Commands run as root must not leave root-owned files where the @@ -172,14 +236,57 @@ func serveCmd() *cobra.Command { if users, err := a.store.ListUsers(ctx); err == nil && len(users) == 0 { a.log.Warn("there are no users yet; create an administrator with 'jarld init' or 'jarld user add --admin NAME'") } - if ok, err := a.eng.Adopted(); err == nil && !ok { + adopted, aerr := a.eng.Adopted() + if aerr == nil && !adopted { a.log.Warn("named does not load Jarl's configuration yet; changes are written but named is not reloaded until 'jarld adopt' runs", "main_config", a.cfg.BIND.MainConfig) } + if adopted { + // Settings in jarl.yaml (such as stats) can change named's + // configuration; bring it up to date. + if wrote, res, err := a.eng.SyncConfig(ctx); err != nil { + a.log.Warn("could not update named's configuration for the settings in jarl.yaml; fix the problem and restart jarl, or run 'jarl resync'", "err", err) + } else if wrote { + a.log.Info("updated named's configuration for the settings in jarl.yaml", "files", res.Files) + } + // Response logging is switched at runtime (the option only + // counts when named starts). Turn it off again when + // statistics no longer use it, unless the configuration + // asks for it. + if !a.cfg.Stats.Enabled || !a.cfg.Stats.QueryLog { + if st, err := a.store.LoadState(ctx); err == nil && st.FindOption(model.ScopeOptions, 0, "responselog") == nil { + if changed, err := a.eng.SetResponseLogging(ctx, false); err == nil && changed { + a.log.Info("turned off named's response logging, which query statistics no longer use") + } + } + } + } + var collector *stats.Collector + collectorDone := make(chan struct{}) + if a.cfg.Stats.Enabled { + ss, err := openStats(a) + if err != nil { + return err + } + defer ss.Close() + opts := statsOptions(a.cfg) + if adopted { + opts.EnsureLogging = func(ctx context.Context) (bool, error) { return a.eng.SetResponseLogging(ctx, true) } + } + collector = stats.NewCollector(ss, opts, zoneIndex(a), a.log) + cctx, cancel := context.WithCancel(ctx) + go func() { + collector.Run(cctx) + close(collectorDone) + }() + // Stop the collector (it writes what it has) before the + // database closes, however serving ends. + defer func() { cancel(); <-collectorDone }() + } srv := server.New(server.Config{ Listen: a.cfg.Listen, TLSCertFile: a.cfg.TLS.CertFile, TLSKeyFile: a.cfg.TLS.KeyFile, TrustedProxies: a.cfg.Proxies(), SessionLifetime: time.Duration(a.cfg.Session.Lifetime), SessionIdle: time.Duration(a.cfg.Session.IdleTimeout), CookieSecure: a.cfg.Session.CookieSecure, - Version: version.Version, + Version: version.Version, Stats: collector, }, a.eng, a.log, web.FS()) hup := make(chan os.Signal, 1) signal.Notify(hup, syscall.SIGHUP) diff --git a/deploy/tmpfiles.d/jarl.conf b/deploy/tmpfiles.d/jarl.conf index 6dcf587..05e3749 100644 --- a/deploy/tmpfiles.d/jarl.conf +++ b/deploy/tmpfiles.d/jarl.conf @@ -10,3 +10,7 @@ d /etc/bind/jarl 2750 jarl bind d /var/lib/bind/jarl 2770 jarl bind # Files named writes for secondary, stub and mirror zones. d /var/cache/bind/jarl 2770 jarl bind +# Query statistics (stats in jarl.yaml): named writes its response log here +# (Debian's AppArmor profile allows /var/log/named) and jarld reads it as a +# member of group bind. +d /var/log/named 0750 bind bind diff --git a/docs/api.md b/docs/api.md index d2f891e..168210b 100644 --- a/docs/api.md +++ b/docs/api.md @@ -268,6 +268,24 @@ in it and its records. | POST | `/system/resync` | `{"dry_run": false, "force": false}`: rewrite every file from the database and reload (admin) | | GET | `/audit` | `?user=&action=&outcome=&object_type=&changeset=&q=&since=&until=&limit=200&before=ID` | +### Query statistics + +Needs `stats:read`. When statistics are disabled, every endpoint but +`status` answers 404 `stats_disabled`. See [stats.md](stats.md). + +| Method | Path | Query | Returns | +|--------|------|-------|---------| +| GET | `/stats/status` | | `{enabled, query_log, statistics_channel, log_file, last_poll, last_log_line, log_lines_read, first_data, retention, warnings}` | +| GET | `/stats/summary` | `since` (90m, 24h, 7d, 2w; default 24h), `top` (default 10) | totals, `avg_qps`, `peak`, `rcodes`, `qtypes`, `views`, `zones`, `answers`, `transport`, `cache_hit_ratio`, `nxdomain_ratio`, `tops` | +| GET | `/stats/timeline` | `since`, `step` (auto, 1m, 5m, 15m, 1h, 6h, 1d), `key` (repeatable or comma separated; `rcode:*` = every counter of a group; default `queries`) | `{step, times: [unix...], series: [{key, values}]}` | +| GET | `/stats/top` | `kind` (name, client, nxdomain, servfail, refused), `since`, `limit` (default 20) | `[{key, count}]` | +| GET | `/stats/heatmap` | `since` (default 28d), `key` (default queries) | `{key, from, avg[7][24], samples[7][24]}`, Monday first, local time, `-1` = no data | +| GET | `/stats/breakdown` | `group` (qtype, rcode, view, zone, answer, transport, rtt, dnssec, cache, ratelimit), `since` | `[{key, count}]` | + +```sh +curl -sf -H "$AUTH" "$API/stats/top?kind=nxdomain&since=7d&limit=10" | jq -r '.[] | "\(.count)\t\(.key)"' +``` + ### Users and tokens | Method | Path | Body | diff --git a/docs/cli.md b/docs/cli.md index 6d48325..3b6534b 100644 --- a/docs/cli.md +++ b/docs/cli.md @@ -218,6 +218,20 @@ jarl resync [--force] [--dry-run] # rewrite every file from the database Grant syntax and roles are in [permissions.md](permissions.md). +## Query statistics + +```sh +jarl stats status +jarl stats summary --since 7d +jarl stats top names | clients | nxdomain | servfail | refused [--since 24h] [--limit 20] +jarl stats timeline --since 6h [--key rcode:NXDOMAIN] [--table] +jarl stats heatmap --since 28d +jarl stats breakdown qtype | rcode | view | zone | answer | rtt +``` + +Statistics must be enabled in `jarl.yaml`, and `-o json` exports the data. +See [stats.md](stats.md). + ## ACME DNS-01 ```sh diff --git a/docs/configuration.md b/docs/configuration.md index 61c5749..6b24866 100644 --- a/docs/configuration.md +++ b/docs/configuration.md @@ -45,6 +45,12 @@ Durations accept Go syntax (`90s`, `15m`, `12h`) and days (`30d`). Audit events are logged as `msg=audit` lines as well as stored in the database. +### Query statistics + +The `stats:` section turns on query statistics (off by default). See +[stats.md](stats.md) for every setting and what it changes in named's +configuration. Changing it takes effect when jarld restarts. + ### BIND | Key | Default | Meaning | diff --git a/docs/development.md b/docs/development.md index 5f4909d..2b9f90f 100644 --- a/docs/development.md +++ b/docs/development.md @@ -20,6 +20,7 @@ internal/ store/ SQLite (modernc.org/sqlite, no cgo): state, changesets, users, tokens, sessions, audit auth/ argon2id passwords, tokens, sessions, grants and roles server/ HTTP API, authentication, the web UI + stats/ query statistics: statistics-channel poller, response-log tailer, collector, separate SQLite store web/static/ the web UI: plain ES modules, no build step, embedded with go:embed api/, client/ JSON types and the Go client shared by server and CLI config/ jarld's YAML configuration diff --git a/docs/install.md b/docs/install.md index a21b0e7..843ccfe 100644 --- a/docs/install.md +++ b/docs/install.md @@ -201,6 +201,12 @@ The CLI's settings are stored in `~/.config/jarl/config.yaml` (mode 0600). Create more tokens in the web UI (Account → API tokens) or with `jarl token create NAME`. See [cli.md](cli.md). +## Optional: query statistics + +To see query volume, top names and clients in the UI and CLI, set +`stats: {enabled: true}` in `/etc/jarl/jarl.yaml` and restart jarl. See +[stats.md](stats.md). + ## TLS certificate from Let's Encrypt Jarl can publish the DNS-01 challenge for its own certificate. On the DNS diff --git a/docs/operations.md b/docs/operations.md index 6bbdea8..1a822bc 100644 --- a/docs/operations.md +++ b/docs/operations.md @@ -34,6 +34,10 @@ sudo -u jarl jarld backup /var/backups/jarl/jarl-$(date +%F).db find /var/backups/jarl -name 'jarl-*.db' -mtime +30 -delete ``` +Query statistics live in a separate database (`/var/lib/jarl/stats.db`). +It isn't needed to restore DNS, so back it up only if you want to keep the +history. + The database contains password and token *hashes* and the TSIG secrets in the clear, so keep backups private. diff --git a/docs/permissions.md b/docs/permissions.md index 231379c..6ea8295 100644 --- a/docs/permissions.md +++ b/docs/permissions.md @@ -37,6 +37,7 @@ RESOURCE:ACCESS [zones=PATTERNS] [views=PATTERNS] [names=PATTERNS] [types=TYPES] | `tsig` | TSIG keys (`write` is needed to see a secret) | | `options` | server options, top-level statements, the defaults for new zones, `jarl check` | | `audit` | everyone's audit events and changesets (without it, users see only their own) | +| `stats` | query statistics, including client addresses and the names they look up (read only) | | `*` | all of the above | `ACCESS` is `read` or `write` (write includes read). Filters narrow a grant. @@ -69,7 +70,7 @@ you can then edit. | Role | Grants | |------|--------| -| `readonly` | `*:read` | +| `readonly` | `*:read` (includes statistics) | | `dns-editor` | `zones:write`, `records:write`, `views:read`, `acls:read`, `options:read` | | `operator` | `*:write` (everything except user management) | | `acme` | `records:write names=_acme-challenge.* types=TXT` | diff --git a/docs/stats.md b/docs/stats.md new file mode 100644 index 0000000..94c3d66 --- /dev/null +++ b/docs/stats.md @@ -0,0 +1,182 @@ +# Query statistics + +Jarl can show what your DNS server is doing: +- how many queries it answers over time, and the busiest hours of the week, +- the most queried names, and the clients asking the most, +- names that don't exist (NXDOMAIN), names that fail to resolve (SERVFAIL), and clients being refused, +- record types, result codes, views and zones, +- cache hit rate, and how fast upstream servers answer recursive queries. + +All of it is in the web UI (**Statistics**), the CLI (`jarl stats`) and the +API (`/api/v1/stats/...`). + +Statistics are **off by default**. They are kept apart from your +configuration in a database of their own, as aggregates only (never +individual queries), and old data is removed automatically. + +## Turning it on + +Add to `/etc/jarl/jarl.yaml`, then restart jarl: + +```yaml +stats: + enabled: true +``` + +```sh +sudo systemctl restart jarl +jarl stats status +``` + +When jarld starts with statistics enabled, it: + +1. adds a **statistics channel** to named's configuration, listening on + `127.0.0.1:8058` only, so named publishes its counters as JSON, +2. adds a **response log**: a logging channel writing one line per answered + query to `/var/log/named/jarl-responses.log` (rotated by named itself at + 20 MB, 2 old files kept), plus `responselog yes;`, +3. applies this through the usual checked pipeline (named-checkconf, + reconfig, verification) and turns response logging on with + `rndc responselog on` (the option alone only counts when named starts), +4. reads both every minute and writes aggregates to `/var/lib/jarl/stats.db`. + +If you already have a `logging` or `statistics-channels` statement, Jarl +adds its channel to yours instead of replacing it. A `responselog` you set +yourself is respected. + +The tmpfiles.d entry creates `/var/log/named` (owned by bind, readable by +group bind, which the `jarl` user belongs to). Debian's and Ubuntu's AppArmor +profile for named allows writing there. If you installed Jarl before this +version, run `sudo systemd-tmpfiles --create jarl.conf` once. + +**Turning it off**: set `enabled: false` and restart jarl. Jarl removes +the channel and log from named's configuration and turns response logging +off again. The statistics database stays until you delete it +(`/var/lib/jarl/stats.db`). Deleting it is always safe. + +## Settings + +```yaml +stats: + enabled: false + query_log: true # per-query data; false = named's counters only + database: /var/lib/jarl/stats.db + statistics_channel: 127.0.0.1:8058 # must be a loopback address + log_file: /var/log/named/jarl-responses.log + log_size: 20m + log_versions: 2 + retention: + minute: 7d # per-minute counters + hour: 90d # hourly counters and top lists + day: 730d # daily counters and top lists + top_n: 100 # names and clients kept per hour and per day + anonymize_clients: false # store 10.10.0.0/24 instead of 10.10.0.37 (IPv6: /48) + exclude_clients: [] # e.g. [10.10.0.250] to ignore a monitoring probe +``` + +`query_log: false` keeps only what named counts itself: totals, record +types, result codes, cache and recursion figures. It costs nothing on +named's side. The per-name, per-client, per-view and per-zone figures need +the response log. Logging every answer costs named some CPU and disk I/O, +which is negligible at homelab volumes. At tens of thousands of queries per +second, consider counters only. + +`exclude_clients` drops those clients from the log-derived figures (top +lists, views, zones). named's own counters can't be filtered. + +## What is collected + +**Counters** (every minute, summed into hours and days): + +| Counter | Source | Meaning | +|---------|--------|---------| +| `queries` | named | queries received | +| `rcode:NOERROR`, `rcode:NXDOMAIN`, ... | named | answers by result code | +| `qtype:A`, `qtype:AAAA`, ... | named | queries by record type | +| `answer:authoritative`, `answer:recursive` | named | answered from your zones, or by recursion/cache | +| `recursion` | named | queries that needed recursion (cache misses) | +| `cache:hits`, `cache:misses` | named | client queries answered from the cache or not | +| `rtt:<10ms` ... `rtt:>1600ms` | named | how long other servers took to answer named | +| `dnssec:valid`, `dnssec:failed` | named | DNSSEC validation results | +| `transport:udp`, `transport:tcp`, `dropped`, `ratelimit:*` | named | | +| `view:NAME` | response log | answers per view (`_default` without views) | +| `zone:NAME` | response log | answers per local zone; `zone:-` for names in none of your zones | +| `responses` | response log | lines read (a health check) | + +**Top lists** (per hour and per day, the `top_n` largest): `name` (most +queried names), `client`, `nxdomain` (names answered NXDOMAIN), `servfail` +(names answered SERVFAIL), `refused` (clients that were refused). + +Nothing else is stored. In particular there's no per-query record, so you +can't look up "who asked for X at 14:02". That is deliberate, both for size +and privacy. + +## Using it + +**Web UI**: Statistics. Pick a range (1 hour to 90 days); everything on the +page follows it. Charts have a hover readout (or focus them and use the +arrow keys) and a **Table** button showing the same data as a table. The +heatmap shows the average queries per hour for each weekday and hour over at +least the last 7 days. The page refreshes every minute. + +**CLI**: + +```sh +jarl stats status # collecting? any problems? +jarl stats summary --since 7d # totals, ratios, top lists +jarl stats top names --since 24h --limit 50 +jarl stats top clients +jarl stats top nxdomain # misconfigured hosts, typos, malware +jarl stats top refused # who asks for what they may not have +jarl stats timeline --since 6h # sparkline; --table for every bucket +jarl stats timeline --since 7d --key rcode:NXDOMAIN --key rcode:SERVFAIL +jarl stats heatmap --since 28d +jarl stats breakdown qtype | rcode | view | zone | answer | rtt | dnssec | cache | transport | ratelimit +jarl stats summary --since 30d -o json # export (also -o yaml) +``` + +**API**: see [api.md](api.md#query-statistics). + +**Permissions**: the `stats` resource (`stats:read`). The `readonly` and +`operator` roles include it, `dns-editor` doesn't. Statistics show client +addresses and what they look up, so grant it with care. + +## How data is kept + +- Minute counters are kept for `retention.minute`, hourly counters and top + lists for `retention.hour`, daily ones for `retention.day`. Older data is + deleted every hour. +- Charts use the finest resolution that covers the range: minutes up to 48 + hours, hours up to 90 days, days beyond. +- Top lists are exact within an hour (up to 200,000 distinct names or + clients per hour, beyond which the rarest are dropped). Daily lists are + built from the hourly top lists, so for very long tails they are + approximate. +- After a restart, jarld continues the log where it stopped, including a + rotation that happened in the meantime. named's counters are read again + from scratch, so the minutes jarld was down count no queries. +- Days follow the server's local time zone. Hours are UTC hours, which is + the same as local hours except in time zones with a half-hour offset. + +## Troubleshooting + +`jarl stats status` (and the top of the Statistics page) lists problems: + +- **named's statistics channel is not reachable**: named isn't running, or + doesn't have Jarl's configuration with statistics yet. Check + `journalctl -u jarl` for the line about updating named's configuration + at startup. If the files were changed by hand (drift), jarld refuses to + rewrite them; run `jarl resync --force` after checking them. +- **named answered N queries but Jarl read no response log lines**: + `/var/log/named` is missing or not writable by named + (`sudo systemd-tmpfiles --create jarl.conf`), or response logging was + turned off. Jarl tries `rndc responselog on` again by itself every 5 + minutes. Check with `sudo rndc status | grep logging`. +- **No top lists, only totals**: `query_log` is false. + +## Debian 13 and Ubuntu + +This works with the `bind9` packages of Debian 13 (BIND 9.20.26) and Ubuntu +26.04 (9.20.24). Both are built with JSON statistics support (`json-c`), and +their AppArmor profile allows `/var/log/named`. Debian also builds in dnstap, +but Jarl doesn't need or use it, so the same setup works on both. diff --git a/internal/auth/grants.go b/internal/auth/grants.go index ec4036c..12df0f1 100644 --- a/internal/auth/grants.go +++ b/internal/auth/grants.go @@ -19,11 +19,12 @@ const ( ResTSIG = "tsig" // TSIG keys ResOptions = "options" // server options, top-level statements, settings ResAudit = "audit" // audit log and everyone's changesets + ResStats = "stats" // query statistics ResAll = "*" ) // Resources lists the resources in display order. -var Resources = []string{ResZones, ResRecords, ResViews, ResACLs, ResTSIG, ResOptions, ResAudit} +var Resources = []string{ResZones, ResRecords, ResViews, ResACLs, ResTSIG, ResOptions, ResAudit, ResStats} // Access levels. const ( diff --git a/internal/config/config.go b/internal/config/config.go index f913204..2094b3e 100644 --- a/internal/config/config.go +++ b/internal/config/config.go @@ -7,6 +7,7 @@ import ( "net/netip" "os" "path/filepath" + "regexp" "strings" "time" @@ -27,6 +28,7 @@ type Config struct { Session Session `yaml:"session"` BIND BIND `yaml:"bind"` Audit Audit `yaml:"audit"` + Stats Stats `yaml:"stats"` } // TLS configures HTTPS. @@ -69,6 +71,44 @@ type Audit struct { RetentionDays int `yaml:"retention_days"` } +// Stats configures query statistics. When enabled, Jarl makes named publish +// its counters on a local statistics channel and log every response to a +// file, and jarld aggregates both into a separate database. +type Stats struct { + Enabled bool `yaml:"enabled"` + // QueryLog enables per-query data (top names and clients, per-view and + // per-zone counts) from named's response log. Without it only named's + // own counters are collected. + QueryLog bool `yaml:"query_log"` + // Database is the statistics database, kept apart from Jarl's + // configuration database. + Database string `yaml:"database"` + // StatisticsChannel is the address named serves its counters on + // (only reachable from this host). + StatisticsChannel string `yaml:"statistics_channel"` + // LogFile is where named logs responses. named's AppArmor profile + // allows writing under /var/log/named. + LogFile string `yaml:"log_file"` + LogSize string `yaml:"log_size"` + LogVersions int `yaml:"log_versions"` + Retention StatsRetention `yaml:"retention"` + // TopN is how many names and clients are kept per hour and per day. + TopN int `yaml:"top_n"` + // AnonymizeClients stores client networks (IPv4 /24, IPv6 /48) + // instead of addresses. + AnonymizeClients bool `yaml:"anonymize_clients"` + // ExcludeClients are addresses or prefixes whose queries are not + // counted per name or client (e.g. monitoring probes). + ExcludeClients []string `yaml:"exclude_clients"` +} + +// StatsRetention says how long each resolution of the statistics is kept. +type StatsRetention struct { + Minute Duration `yaml:"minute"` + Hour Duration `yaml:"hour"` + Day Duration `yaml:"day"` +} + // Duration is a time.Duration written as "15s" or "12h" in YAML. Days // ("30d") are accepted too. type Duration time.Duration @@ -122,6 +162,16 @@ func Default() *Config { RNDC: "/usr/sbin/rndc", ReloadTimeout: Duration(15 * time.Second), }, + Stats: Stats{ + QueryLog: true, + Database: "/var/lib/jarl/stats.db", + StatisticsChannel: "127.0.0.1:8058", + LogFile: "/var/log/named/jarl-responses.log", + LogSize: "20m", + LogVersions: 2, + Retention: StatsRetention{Minute: Duration(7 * 24 * time.Hour), Hour: Duration(90 * 24 * time.Hour), Day: Duration(730 * 24 * time.Hour)}, + TopN: 100, + }, } } @@ -166,6 +216,9 @@ func (c *Config) check() error { default: return fmt.Errorf("session.cookie_secure must be auto, always or never") } + if err := c.Stats.check(); err != nil { + return fmt.Errorf("stats: %w", err) + } switch c.Log.Format { case "text", "json": default: @@ -174,6 +227,51 @@ func (c *Config) check() error { return nil } +func (s *Stats) check() error { + if !s.Enabled { + return nil + } + if s.Database == "" || !filepath.IsAbs(s.Database) { + return fmt.Errorf("database must be an absolute path") + } + ap, err := netip.ParseAddrPort(s.StatisticsChannel) + if err != nil { + return fmt.Errorf("statistics_channel %q must be ADDRESS:PORT, e.g. 127.0.0.1:8058", s.StatisticsChannel) + } + if !ap.Addr().IsLoopback() { + return fmt.Errorf("statistics_channel must be a loopback address (named's counters must not be reachable from the network)") + } + if s.QueryLog { + if !filepath.IsAbs(s.LogFile) { + return fmt.Errorf("log_file must be an absolute path") + } + if strings.ContainsAny(s.LogFile, "\"\n") { + return fmt.Errorf("log_file contains invalid characters") + } + if !logSizeRe.MatchString(s.LogSize) { + return fmt.Errorf("log_size %q must be a size such as 20m or 1g", s.LogSize) + } + if s.LogVersions < 1 || s.LogVersions > 100 { + return fmt.Errorf("log_versions must be between 1 and 100") + } + } + r := s.Retention + if r.Minute < Duration(time.Hour) || r.Hour < Duration(24*time.Hour) || r.Day < Duration(24*time.Hour) { + return fmt.Errorf("retention must keep minutes for at least 1h, hours and days for at least 1d") + } + if s.TopN < 10 || s.TopN > 10000 { + return fmt.Errorf("top_n must be between 10 and 10000") + } + for _, p := range s.ExcludeClients { + if _, err := ParsePrefix(p); err != nil { + return fmt.Errorf("exclude_clients: %v", err) + } + } + return nil +} + +var logSizeRe = regexp.MustCompile(`^[0-9]+[kKmMgG]?$`) + // ParsePrefix parses an address or prefix. func ParsePrefix(s string) (netip.Prefix, error) { if strings.Contains(s, "/") { @@ -254,4 +352,26 @@ bind: audit: # Delete audit events older than this many days (0 keeps them forever). retention_days: 0 + +# Query statistics (docs/stats.md). Off by default. When enabled, Jarl makes +# named publish its counters on a local statistics channel and log every +# response, and jarld aggregates both into a separate database. Changing +# this section takes effect when jarld restarts (it rewrites named.conf). +stats: + enabled: false + # Per-query data (top names and clients, per view and zone). false + # collects only named's own counters, with no logging overhead. + query_log: true + database: /var/lib/jarl/stats.db + statistics_channel: 127.0.0.1:8058 + log_file: /var/log/named/jarl-responses.log + log_size: 20m + log_versions: 2 + retention: + minute: 7d # per-minute counters + hour: 90d # hourly counters and top lists + day: 730d # daily counters and top lists + top_n: 100 # names and clients kept per hour and per day + anonymize_clients: false # store 10.10.0.0/24 instead of 10.10.0.37 + exclude_clients: [] # e.g. [127.0.0.1] to ignore local monitoring ` diff --git a/internal/config/config_test.go b/internal/config/config_test.go index 160dfd8..92d2196 100644 --- a/internal/config/config_test.go +++ b/internal/config/config_test.go @@ -43,3 +43,31 @@ func TestLoad(t *testing.T) { t.Errorf("missing file with allowMissing: %v", err) } } + +func TestStatsConfig(t *testing.T) { + d := Default() + if d.Stats.Enabled || !d.Stats.QueryLog || d.Stats.TopN != 100 || time.Duration(d.Stats.Retention.Hour) != 90*24*time.Hour { + t.Errorf("defaults = %+v", d.Stats) + } + dir := t.TempDir() + path := filepath.Join(dir, "jarl.yaml") + for _, tc := range []struct { + yaml string + ok bool + }{ + {"stats: {enabled: true}", true}, + {"stats: {enabled: true, query_log: false, retention: {minute: 2d}}", true}, + {"stats: {enabled: true, statistics_channel: 0.0.0.0:8058}", false}, // must be loopback + {"stats: {enabled: true, statistics_channel: localhost}", false}, + {"stats: {enabled: true, log_size: lots}", false}, + {"stats: {enabled: true, retention: {minute: 10m}}", false}, + {"stats: {enabled: true, exclude_clients: [not-an-ip]}", false}, + {"stats: {enabled: false, statistics_channel: nonsense}", true}, // only checked when enabled + } { + os.WriteFile(path, []byte(tc.yaml+"\n"), 0o644) + _, err := Load(path, false) + if (err == nil) != tc.ok { + t.Errorf("%s: err = %v, want ok=%v", tc.yaml, err, tc.ok) + } + } +} diff --git a/internal/engine/engine.go b/internal/engine/engine.go index b3b9cfe..6fb6ffa 100644 --- a/internal/engine/engine.go +++ b/internal/engine/engine.go @@ -34,6 +34,9 @@ import ( // Config configures the engine. type Config struct { Paths render.Paths + // Extras are statements added from jarld's configuration, such as the + // statistics channel and response log for query statistics. + Extras render.Extras // MainConfig is the configuration file named loads (on Debian // /etc/bind/named.conf). Jarl is "adopted" once it includes Jarl's // named.conf. If it is Jarl's named.conf itself, Jarl is always @@ -412,7 +415,7 @@ func (e *Engine) makePlan(ctx context.Context, base, work *model.State, user str return pl, nil } pl.serials = bumpSerials(base, work, e.Now(), user) - pl.out = render.Render(work, e.cfg.Paths) + pl.out = render.Render(work, e.cfg.Paths, e.cfg.Extras) deployed, err := e.store.DeployedFiles(ctx) if err != nil { return nil, err @@ -448,7 +451,7 @@ func (e *Engine) makePlan(ctx context.Context, base, work *model.State, user str pl.diff = diff.String() // Which zones named must reload, and which serials to verify. - baseOut := render.Render(base, e.cfg.Paths) + baseOut := render.Render(base, e.cfg.Paths, e.cfg.Extras) changedPaths := map[string]bool{} for _, f := range pl.changed { changedPaths[f.Path] = true @@ -494,7 +497,7 @@ func (e *Engine) stagingCheck(ctx context.Context, pl *plan) error { } defer os.RemoveAll(dir) sp := render.Paths{ConfigDir: filepath.Join(dir, "config"), ZoneDir: filepath.Join(dir, "zones"), CacheDir: filepath.Join(dir, "cache")} - sout := render.Render(pl.work, sp) + sout := render.Render(pl.work, sp, e.cfg.Extras) for _, f := range sout.Files { if err := os.MkdirAll(filepath.Dir(f.Path), 0o750); err != nil { return err @@ -969,6 +972,13 @@ func (e *Engine) Resync(ctx context.Context, p *auth.Principal, opts ApplyOption if opts.DryRun { return res, nil } + if len(pl.drift) > 0 && !opts.Force { + var paths []string + for _, d := range pl.drift { + paths = append(paths, d.Path+" ("+d.Reason+")") + } + return res, &Error{Kind: KindDrift, Message: "files managed by Jarl were changed outside Jarl: " + strings.Join(paths, ", ") + "; resync with force to overwrite them"} + } // Verify every primary zone and reload them all. pl.configChanged = true pl.reloadZones = nil @@ -1000,6 +1010,47 @@ func (e *Engine) Resync(ctx context.Context, p *auth.Principal, opts ApplyOption return res, nil } +// SyncConfig rewrites named's configuration when it differs from what the +// database and jarld's own configuration produce, for example after query +// statistics were switched on or off in jarl.yaml. Files changed by hand +// are never overwritten. It reports whether anything was written. +func (e *Engine) SyncConfig(ctx context.Context) (bool, *Result, error) { + dry, err := e.Resync(ctx, auth.System, ApplyOptions{DryRun: true}) + if err != nil || len(dry.Files) == 0 { + return false, dry, err + } + res, err := e.Resync(ctx, auth.System, ApplyOptions{}) + return err == nil, res, err +} + +// SetResponseLogging turns named's response logging on or off with rndc. +// The responselog option only takes effect when named starts, so query +// statistics switch it at runtime. It reports whether it changed. +func (e *Engine) SetResponseLogging(ctx context.Context, on bool) (bool, error) { + if e.cfg.NoReload || e.tools == nil { + return false, nil + } + out, err := e.tools.RNDCRun(ctx, "status") + if err != nil { + return false, err + } + want := "response logging is OFF" + if !on { + want = "response logging is ON" + } + if !strings.Contains(out, want) { + return false, nil // already as wanted (or too old a named to say) + } + arg := "on" + if !on { + arg = "off" + } + if _, err := e.tools.RNDCRun(ctx, "responselog", arg); err != nil { + return false, err + } + return true, nil +} + // CheckCurrent validates the stored configuration and runs named-checkconf // on it without changing anything. func (e *Engine) CheckCurrent(ctx context.Context) (*Result, error) { diff --git a/internal/render/render.go b/internal/render/render.go index b0a0193..35a261a 100644 --- a/internal/render/render.go +++ b/internal/render/render.go @@ -123,12 +123,13 @@ func ZoneFilePath(s *model.State, z *model.Zone, p Paths) string { // Header is placed at the top of every generated file. const headerText = "Generated by Jarl. DO NOT EDIT: changes made here are overwritten the next time\nchanges are applied. Manage this server through the Jarl web UI, API or CLI." -// Render renders the complete configuration. -func Render(s *model.State, p Paths) *Output { +// Render renders the complete configuration. x adds statements that come +// from jarld's configuration (e.g. for query statistics). +func Render(s *model.State, p Paths, x Extras) *Output { out := &Output{Spans: map[string][]Span{}, ZoneFiles: map[int64]string{}} keys := renderKeys(s) out.Files = append(out.Files, &File{Path: p.KeysConfig(), Content: []byte(keys), Mode: 0o640, Kind: KindKeys, Secret: true}) - conf, spans := renderConfig(s, p, out) + conf, spans := renderConfig(s, p, x, out) out.Files = append(out.Files, &File{Path: p.MainConfig(), Content: []byte(conf), Mode: 0o640, Kind: KindConfig}) out.Spans[p.MainConfig()] = spans for _, z := range s.SortedZones() { @@ -238,20 +239,43 @@ func normalizeElement(e string) string { return strings.TrimSuffix(strings.TrimSpace(e), ";") } -func renderConfig(s *model.State, p Paths, out *Output) (string, []Span) { +func renderConfig(s *model.State, p Paths, x Extras, out *Output) (string, []Span) { w := newConfWriter() w.write(commentBlock("//", headerText)) w.write("\n") w.write(fmt.Sprintf("include %s;\n", namedconf.QuoteString(p.KeysConfig()))) + st := x.Stats + logResponses := st != nil && st.LogFile != "" + sawStats, sawLogging := false, false if top := s.ScopedOptions(model.ScopeTopLevel, 0); len(top) > 0 { w.write("\n") for _, o := range top { w.begin("option", o.ID, "top-level statement "+o.Name) - w.write(optionText(o, 0)) + switch { + case st != nil && o.Name == "statistics-channels" && !sawStats: + w.write(st.statsStatement(o)) + sawStats = true + case logResponses && o.Name == "logging" && !sawLogging: + w.write(st.loggingStatement(o)) + sawLogging = true + default: + w.write(optionText(o, 0)) + } w.end() } } + if st != nil && (!sawStats || logResponses && !sawLogging) { + w.write("\n") + w.begin("settings", 0, "query statistics settings (stats in jarl.yaml)") + if !sawStats { + w.write(st.statsStatement(nil)) + } + if logResponses && !sawLogging { + w.write(st.loggingStatement(nil)) + } + w.end() + } if acls := s.SortedACLs(); len(acls) > 0 { w.write("\n") @@ -276,6 +300,11 @@ func renderConfig(s *model.State, p Paths, out *Output) (string, []Span) { w.write(optionText(o, 1)) w.end() } + if logResponses && s.FindOption(model.ScopeOptions, 0, "responselog") == nil { + w.begin("settings", 0, "query statistics settings (stats in jarl.yaml)") + w.write("\t// " + statsComment + "\n\tresponselog yes;\n") + w.end() + } w.write("};\n") views := s.OrderedViews() diff --git a/internal/render/render_test.go b/internal/render/render_test.go index 9eec789..899d49c 100644 --- a/internal/render/render_test.go +++ b/internal/render/render_test.go @@ -90,8 +90,8 @@ func TestRenderDeterministicAndValid(t *testing.T) { } dir := t.TempDir() p := Paths{ConfigDir: filepath.Join(dir, "etc"), ZoneDir: filepath.Join(dir, "zones"), CacheDir: filepath.Join(dir, "cache")} - out1 := Render(s, p) - out2 := Render(s.Clone(), p) + out1 := Render(s, p, Extras{}) + out2 := Render(s.Clone(), p, Extras{}) if len(out1.Files) != len(out2.Files) { t.Fatal("file count differs") } @@ -143,8 +143,14 @@ func TestRenderDeterministicAndValid(t *testing.T) { } func TestRenderWithNamedCheckconf(t *testing.T) { + checkWithNamed(t, sampleState(t), Extras{}) +} + +// checkWithNamed renders s and checks the result with named-checkconf -z +// and named-checkzone. +func checkWithNamed(t *testing.T, s *model.State, x Extras) *Output { + t.Helper() tools := testutil.BindTools(t) - s := sampleState(t) dir := t.TempDir() p := Paths{ConfigDir: filepath.Join(dir, "etc"), ZoneDir: filepath.Join(dir, "zones"), CacheDir: filepath.Join(dir, "cache")} // named-checkconf changes into the directory option, so it must exist. @@ -159,7 +165,7 @@ func TestRenderWithNamedCheckconf(t *testing.T) { z.File = hints } } - out := Render(s, p) + out := Render(s, p, x) for _, f := range out.Files { if err := os.MkdirAll(filepath.Dir(f.Path), 0o755); err != nil { t.Fatal(err) @@ -185,6 +191,7 @@ func TestRenderWithNamedCheckconf(t *testing.T) { t.Errorf("named-checkzone %s: %v\n%s", z.Name, err, r.Output) } } + return out } func TestZoneContentHash(t *testing.T) { diff --git a/internal/render/stats.go b/internal/render/stats.go new file mode 100644 index 0000000..769aa8f --- /dev/null +++ b/internal/render/stats.go @@ -0,0 +1,109 @@ +package render + +import ( + "net/netip" + "strconv" + "strings" + + "jarl/internal/model" + "jarl/internal/namedconf" +) + +// Extras are additions to named's configuration that come from jarld's +// own configuration (jarl.yaml) rather than from the database. +type Extras struct { + // Stats, when set, makes named publish what Jarl's statistics + // collector reads. + Stats *StatsHooks +} + +// StatsHooks describe the statistics channel and response log Jarl needs. +type StatsHooks struct { + Channel netip.AddrPort // statistics-channels address (loopback) + LogFile string // response log; "" disables response logging + LogVersions int + LogSize string +} + +// StatsChannelName is the logging channel Jarl adds for responses. +const StatsChannelName = "jarl_responses" + +const statsComment = "Added by Jarl for query statistics (stats in /etc/jarl/jarl.yaml)." + +// statsInet is the statistics-channels clause for the collector. +func (h *StatsHooks) statsInet() *namedconf.Stmt { + addr := h.Channel.Addr().String() + return namedconf.NewStmt("inet", addr, "port", strconv.Itoa(int(h.Channel.Port())), + "allow", namedconf.NewBlock(namedconf.NewStmt(addr))) +} + +// logChannel is the logging channel the response log is written to. +func (h *StatsHooks) logChannel() *namedconf.Stmt { + return namedconf.NewStmt("channel", StatsChannelName, namedconf.NewBlock( + namedconf.NewStmt("file", namedconf.Quoted(h.LogFile), "versions", strconv.Itoa(h.LogVersions), "size", h.LogSize), + namedconf.NewStmt("print-time", "yes"), + namedconf.NewStmt("severity", "info"), + )) +} + +// statsStatement returns the statistics-channels statement, merged into the +// user's own if there is one. +func (h *StatsHooks) statsStatement(user *model.Option) string { + if user != nil { + if st, err := namedconf.ParseOptionValue(user.Name, user.Value); err == nil && st.FirstBlock() != nil { + b := st.FirstBlock() + want := namedconf.CompactStmt(h.statsInet()) + for _, s := range b.Stmts { + if namedconf.CompactStmt(s) == want { + return optionText(user, 0) + } + } + b.Stmts = append(b.Stmts, h.statsInet()) + return commentLines(user.Comment) + commentBlock("//", statsComment) + namedconf.FormatStmt(st, 0) + } + // Unparsable: validation reports it; leave it alone. + return optionText(user, 0) + } + st := namedconf.NewStmt("statistics-channels", namedconf.NewBlock(h.statsInet())) + return commentBlock("//", statsComment) + namedconf.FormatStmt(st, 0) +} + +// loggingStatement returns the logging statement with Jarl's channel and +// the responses category, merged into the user's own if there is one. +func (h *StatsHooks) loggingStatement(user *model.Option) string { + var st *namedconf.Stmt + if user != nil { + var err error + st, err = namedconf.ParseOptionValue(user.Name, user.Value) + if err != nil || st.FirstBlock() == nil { + return optionText(user, 0) + } + } else { + st = namedconf.NewStmt("logging", namedconf.NewBlock()) + } + b := st.FirstBlock() + // Channels must be defined before the categories that use them. + b.Stmts = append([]*namedconf.Stmt{h.logChannel()}, b.Stmts...) + merged := false + for _, s := range b.Stmts { + if s.Keyword() == "category" && strings.EqualFold(s.Arg(0), "responses") && s.FirstBlock() != nil { + s.FirstBlock().Stmts = append(s.FirstBlock().Stmts, namedconf.NewStmt(StatsChannelName)) + merged = true + } + } + if !merged { + b.Stmts = append(b.Stmts, namedconf.NewStmt("category", "responses", namedconf.NewBlock(namedconf.NewStmt(StatsChannelName)))) + } + prefix := "" + if user != nil { + prefix = commentLines(user.Comment) + } + return prefix + commentBlock("//", statsComment) + namedconf.FormatStmt(st, 0) +} + +func commentLines(c string) string { + if c == "" { + return "" + } + return commentBlock("//", c) +} diff --git a/internal/render/stats_test.go b/internal/render/stats_test.go new file mode 100644 index 0000000..0e68d0e --- /dev/null +++ b/internal/render/stats_test.go @@ -0,0 +1,84 @@ +package render + +import ( + "net/netip" + "strings" + "testing" + + "jarl/internal/model" +) + +func statsHooks() *StatsHooks { + return &StatsHooks{Channel: netip.MustParseAddrPort("127.0.0.1:8058"), LogFile: "/var/log/named/jarl-responses.log", LogVersions: 2, LogSize: "20m"} +} + +func TestStatsHooksAdded(t *testing.T) { + s := sampleState(t) + // Without a logging statement of its own, Jarl adds one. + for id, o := range s.Options { + if o.Name == "logging" { + delete(s.Options, id) + } + } + p := Paths{ConfigDir: "/etc/bind/jarl", ZoneDir: "/var/lib/bind/jarl", CacheDir: "/var/cache/bind/jarl"} + conf := string(Render(s, p, Extras{Stats: statsHooks()}).File(p.MainConfig()).Content) + for _, want := range []string{ + "statistics-channels {\n\tinet 127.0.0.1 port 8058 allow { 127.0.0.1; };\n};", + `file "/var/log/named/jarl-responses.log" versions 2 size 20m;`, + "\tcategory responses { jarl_responses; };", + "\tresponselog yes;\n", + } { + if !strings.Contains(conf, want) { + t.Errorf("named.conf lacks %q:\n%s", want, conf) + } + } + // Counters only: no logging, no responselog. + h := statsHooks() + h.LogFile = "" + conf = string(Render(s, p, Extras{Stats: h}).File(p.MainConfig()).Content) + if !strings.Contains(conf, "statistics-channels") || strings.Contains(conf, "responselog") || strings.Contains(conf, "jarl_responses") { + t.Errorf("counters-only config:\n%s", conf) + } + // Disabled: nothing. + conf = string(Render(s, p, Extras{}).File(p.MainConfig()).Content) + if strings.Contains(conf, "statistics-channels") || strings.Contains(conf, "responselog") { + t.Errorf("stats disabled but present:\n%s", conf) + } +} + +func TestStatsHooksMerged(t *testing.T) { + s := sampleState(t) + add := func(scope, name, value string) { + id := int64(10000 + len(s.Options)) + s.Options[id] = &model.Option{ID: id, Scope: scope, Name: name, Value: value, Position: int(id)} + } + for _, o := range s.Options { + if o.Name == "logging" { + o.Value = `{ channel default_log { stderr; severity info; }; category default { default_log; }; category responses { default_log; }; }` + } + } + add(model.ScopeTopLevel, "statistics-channels", `{ inet 127.0.0.1 port 8080 allow { 127.0.0.1; }; }`) + add(model.ScopeOptions, "responselog", "no") + out := checkWithNamed(t, s, Extras{Stats: statsHooks()}) + var conf string + for _, f := range out.Files { + if f.Kind == KindConfig { + conf = string(f.Content) + } + } + if strings.Count(conf, "logging {") != 1 || strings.Count(conf, "statistics-channels {") != 1 { + t.Errorf("statements duplicated instead of merged:\n%s", conf) + } + for _, want := range []string{"port 8080", "port 8058", "category responses { default_log; jarl_responses; };", "responselog no;"} { + if !strings.Contains(conf, want) { + t.Errorf("named.conf lacks %q:\n%s", want, conf) + } + } + if strings.Contains(conf, "responselog yes") { + t.Errorf("Jarl overrode the user's responselog:\n%s", conf) + } +} + +func TestStatsHooksWithNamed(t *testing.T) { + checkWithNamed(t, sampleState(t), Extras{Stats: statsHooks()}) +} diff --git a/internal/server/h_stats.go b/internal/server/h_stats.go new file mode 100644 index 0000000..7a95029 --- /dev/null +++ b/internal/server/h_stats.go @@ -0,0 +1,147 @@ +package server + +import ( + "net/http" + "strings" + "time" + + "jarl/internal/auth" + "jarl/internal/stats" +) + +// statsQuerier checks permission and that statistics are enabled. +func (s *Server) statsQuerier(p *auth.Principal) (*stats.Querier, error) { + if err := require(p, auth.Action{Resource: auth.ResStats}); err != nil { + return nil, err + } + if s.statsQ == nil { + return nil, &httpError{http.StatusNotFound, "stats_disabled", "query statistics are disabled; set stats.enabled: true in /etc/jarl/jarl.yaml and restart jarl (see docs/stats.md)"} + } + return s.statsQ, nil +} + +func statsSince(r *http.Request) (time.Duration, error) { + d, err := stats.ParseSince(r.URL.Query().Get("since")) + if err != nil { + return 0, badRequest("%v", err) + } + return d, nil +} + +func (s *Server) statsStatus(w http.ResponseWriter, r *http.Request, p *auth.Principal) error { + if err := require(p, auth.Action{Resource: auth.ResStats}); err != nil { + return err + } + if s.cfg.Stats == nil { + writeJSON(w, http.StatusOK, stats.Status{Enabled: false, Warnings: []string{}}) + return nil + } + writeJSON(w, http.StatusOK, s.cfg.Stats.Status()) + return nil +} + +func (s *Server) statsSummary(w http.ResponseWriter, r *http.Request, p *auth.Principal) error { + q, err := s.statsQuerier(p) + if err != nil { + return err + } + since, err := statsSince(r) + if err != nil { + return err + } + sum, err := q.Summary(r.Context(), since, queryInt(r, "top", 10)) + if err != nil { + return err + } + writeJSON(w, http.StatusOK, sum) + return nil +} + +func (s *Server) statsTop(w http.ResponseWriter, r *http.Request, p *auth.Principal) error { + q, err := s.statsQuerier(p) + if err != nil { + return err + } + since, err := statsSince(r) + if err != nil { + return err + } + kind := r.URL.Query().Get("kind") + if kind == "" { + kind = stats.KindName + } + limit := min(max(queryInt(r, "limit", 20), 1), 10000) + es, err := q.Top(r.Context(), kind, since, limit) + if err != nil { + return badRequest("%v", err) + } + writeJSON(w, http.StatusOK, es) + return nil +} + +func (s *Server) statsTimeline(w http.ResponseWriter, r *http.Request, p *auth.Principal) error { + q, err := s.statsQuerier(p) + if err != nil { + return err + } + since, err := statsSince(r) + if err != nil { + return err + } + var keys []string + for _, k := range r.URL.Query()["key"] { + for _, part := range strings.Split(k, ",") { + if part = strings.TrimSpace(part); part != "" { + keys = append(keys, part) + } + } + } + if len(keys) == 0 { + keys = []string{"queries"} + } + if len(keys) > 50 { + return badRequest("at most 50 series") + } + tl, err := q.Timeline(r.Context(), since, r.URL.Query().Get("step"), keys) + if err != nil { + return badRequest("%v", err) + } + writeJSON(w, http.StatusOK, tl) + return nil +} + +func (s *Server) statsHeatmap(w http.ResponseWriter, r *http.Request, p *auth.Principal) error { + q, err := s.statsQuerier(p) + if err != nil { + return err + } + since := 28 * 24 * time.Hour + if r.URL.Query().Get("since") != "" { + if since, err = statsSince(r); err != nil { + return err + } + } + hm, err := q.Heatmap(r.Context(), r.URL.Query().Get("key"), since) + if err != nil { + return err + } + writeJSON(w, http.StatusOK, hm) + return nil +} + +func (s *Server) statsBreakdown(w http.ResponseWriter, r *http.Request, p *auth.Principal) error { + q, err := s.statsQuerier(p) + if err != nil { + return err + } + since, err := statsSince(r) + if err != nil { + return err + } + es, err := q.Breakdown(r.Context(), r.URL.Query().Get("group"), since) + if err != nil { + return badRequest("%v", err) + } + writeJSON(w, http.StatusOK, es) + return nil +} diff --git a/internal/server/routes.go b/internal/server/routes.go index e6d24ac..21d52da 100644 --- a/internal/server/routes.go +++ b/internal/server/routes.go @@ -100,6 +100,13 @@ func (s *Server) routes() { m.HandleFunc("POST "+p+"/system/check", s.authed(s.systemCheck)) m.HandleFunc("POST "+p+"/system/resync", s.authed(s.systemResync)) m.HandleFunc("GET "+p+"/audit", s.authed(s.listAudit)) + // Query statistics + m.HandleFunc("GET "+p+"/stats/status", s.authed(s.statsStatus)) + m.HandleFunc("GET "+p+"/stats/summary", s.authed(s.statsSummary)) + m.HandleFunc("GET "+p+"/stats/top", s.authed(s.statsTop)) + m.HandleFunc("GET "+p+"/stats/timeline", s.authed(s.statsTimeline)) + m.HandleFunc("GET "+p+"/stats/heatmap", s.authed(s.statsHeatmap)) + m.HandleFunc("GET "+p+"/stats/breakdown", s.authed(s.statsBreakdown)) m.HandleFunc(p+"/", func(w http.ResponseWriter, r *http.Request) { writeError(w, http.StatusNotFound, "not_found", "no such API endpoint: "+r.Method+" "+r.URL.Path) }) diff --git a/internal/server/server.go b/internal/server/server.go index 53cc9ed..db509b4 100644 --- a/internal/server/server.go +++ b/internal/server/server.go @@ -18,6 +18,7 @@ import ( "jarl/internal/auth" "jarl/internal/engine" + "jarl/internal/stats" "jarl/internal/store" ) @@ -34,6 +35,8 @@ type Config struct { CookieSecure string MaxBodyBytes int64 Version string + // Stats is the query statistics collector (nil when disabled). + Stats *stats.Collector } // Server is the HTTP server. @@ -46,6 +49,7 @@ type Server struct { limiter *rateLimiter web fs.FS certs *certReloader + statsQ *stats.Querier mu sync.Mutex srvs []*http.Server @@ -69,6 +73,9 @@ func New(cfg Config, eng *engine.Engine, log *slog.Logger, web fs.FS) *Server { log = slog.Default() } s := &Server{cfg: cfg, eng: eng, store: eng.Store(), log: log, mux: http.NewServeMux(), limiter: newRateLimiter(), web: web} + if cfg.Stats != nil { + s.statsQ = stats.NewQuerier(cfg.Stats) + } s.routes() return s } diff --git a/internal/server/server_test.go b/internal/server/server_test.go index b1dce7d..c44f09a 100644 --- a/internal/server/server_test.go +++ b/internal/server/server_test.go @@ -19,6 +19,7 @@ import ( "jarl/internal/engine" "jarl/internal/model" "jarl/internal/render" + "jarl/internal/stats" "jarl/internal/store" ) @@ -29,7 +30,8 @@ type apiEnv struct { token string // admin token } -func newAPIEnv(t *testing.T) *apiEnv { +// newAPIEnv starts an API server; a statistics collector may be given. +func newAPIEnv(t *testing.T, collector ...*stats.Collector) *apiEnv { t.Helper() dir := t.TempDir() st, err := store.Open(filepath.Join(dir, "jarl.db")) @@ -42,7 +44,11 @@ func newAPIEnv(t *testing.T) *apiEnv { Paths: render.Paths{ConfigDir: filepath.Join(dir, "etc"), ZoneDir: filepath.Join(dir, "zones"), CacheDir: filepath.Join(dir, "cache")}, StagingDir: filepath.Join(dir, "staging"), NoReload: true, SkipCheck: true, }, quiet) - srv := New(Config{Version: "test"}, eng, quiet, nil) + cfg := Config{Version: "test"} + if len(collector) > 0 { + cfg.Stats = collector[0] + } + srv := New(cfg, eng, quiet, nil) ts := httptest.NewServer(srv.Handler()) t.Cleanup(ts.Close) hash, _ := auth.HashPassword("correct horse battery") diff --git a/internal/server/stats_test.go b/internal/server/stats_test.go new file mode 100644 index 0000000..8f59366 --- /dev/null +++ b/internal/server/stats_test.go @@ -0,0 +1,99 @@ +package server + +import ( + "context" + "encoding/json" + "io" + "log/slog" + "strings" + "testing" + "time" + + "jarl/internal/stats" +) + +func TestStatsAPIDisabled(t *testing.T) { + e := newAPIEnv(t) + st := e.do("GET", "/stats/status", e.token, nil, 200) + if st["enabled"] != false { + t.Errorf("status = %v", st) + } + out, status := e.req("GET", "/stats/summary", e.token, nil) + if status != 404 || !json.Valid(out) || !strings.Contains(string(out), "stats_disabled") { + t.Errorf("summary while disabled = %d %s", status, out) + } +} + +func TestStatsAPI(t *testing.T) { + ctx := context.Background() + ss, err := stats.OpenStore(":memory:") + if err != nil { + t.Fatal(err) + } + defer ss.Close() + now := time.Now() + minute := now.Unix() - now.Unix()%60 - 120 + hour := minute - minute%3600 + b := &stats.Batch{} + vals := map[string]int64{"queries": 50, "rcode:NOERROR": 45, "rcode:NXDOMAIN": 5, "qtype:A": 30, "qtype:AAAA": 20, "zone:example.com": 40, "zone:-": 10} + b.AddCounters(stats.ResMinute, minute, vals) + b.AddCounters(stats.ResHour, hour, vals) + b.SetTops(stats.ResHour, hour, stats.KindName, []stats.Entry{{Key: "www.example.com", Count: 30}, {Key: "mail.example.com", Count: 10}}) + b.SetTops(stats.ResHour, hour, stats.KindClient, []stats.Entry{{Key: "10.0.0.7", Count: 50}}) + if err := ss.Commit(ctx, b); err != nil { + t.Fatal(err) + } + opts := stats.Options{StatisticsChannel: "127.0.0.1:1", TopN: 10, RetainMinute: 7 * 24 * time.Hour, RetainHour: 90 * 24 * time.Hour, RetainDay: 730 * 24 * time.Hour} + c := stats.NewCollector(ss, opts, nil, slog.New(slog.NewTextHandler(io.Discard, nil))) + e := newAPIEnv(t, c) + + if st := e.do("GET", "/stats/status", e.token, nil, 200); st["enabled"] != true { + t.Errorf("status = %v", st) + } + sum := e.do("GET", "/stats/summary?since=1h", e.token, nil, 200) + if sum["queries"].(float64) != 50 || sum["resolution"] != "m" { + t.Errorf("summary = %v", sum) + } + tops := e.list("/stats/top?kind=name&since=2h", e.token) + if len(tops) != 2 || tops[0]["key"] != "www.example.com" { + t.Errorf("top names = %v", tops) + } + if b := e.list("/stats/breakdown?group=zone&since=1h", e.token); len(b) != 2 || b[0]["key"] != "example.com" { + t.Errorf("zones = %v", b) + } + tl := e.do("GET", "/stats/timeline?since=1h&key=queries,rcode:*", e.token, nil, 200) + if tl["step"] != "1m" || len(tl["series"].([]any)) != 3 { + t.Errorf("timeline = %v", tl) + } + if hm := e.do("GET", "/stats/heatmap", e.token, nil, 200); hm["key"] != "queries" { + t.Errorf("heatmap = %v", hm) + } + for _, bad := range []string{"/stats/summary?since=forever", "/stats/top?kind=nope", "/stats/breakdown?group=nope", "/stats/timeline?step=3m"} { + if _, status := e.req("GET", bad, e.token, nil); status != 400 { + t.Errorf("%s = %d, want 400", bad, status) + } + } + // Statistics show client addresses: they need the stats grant. + e.do("POST", "/users", e.token, map[string]any{"username": "editor", "password": "editor-password-1", "role": "dns-editor"}, 201) + var editorID int64 + for _, u := range e.list("/users", e.token) { + if u["username"] == "editor" { + editorID = int64(u["id"].(float64)) + } + } + tok := e.do("POST", "/users/"+itoa(editorID)+"/tokens", e.token, map[string]any{"name": "t"}, 201)["token"].(string) + for _, path := range []string{"/stats/status", "/stats/summary", "/stats/top"} { + if _, status := e.req("GET", path, tok, nil); status != 403 { + t.Errorf("dns-editor %s = %d, want 403", path, status) + } + } + e.do("POST", "/users", e.token, map[string]any{"username": "viewer", "password": "viewer-password-1", "role": "readonly"}, 201) + var viewerID int64 + for _, u := range e.list("/users", e.token) { + if u["username"] == "viewer" { + viewerID = int64(u["id"].(float64)) + } + } + vtok := e.do("POST", "/users/"+itoa(viewerID)+"/tokens", e.token, map[string]any{"name": "t"}, 201)["token"].(string) + e.do("GET", "/stats/summary", vtok, nil, 200) +} diff --git a/internal/stats/collector.go b/internal/stats/collector.go new file mode 100644 index 0000000..a3f52f4 --- /dev/null +++ b/internal/stats/collector.go @@ -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() +} diff --git a/internal/stats/collector_test.go b/internal/stats/collector_test.go new file mode 100644 index 0000000..0f7e36f --- /dev/null +++ b/internal/stats/collector_test.go @@ -0,0 +1,235 @@ +package stats + +import ( + "context" + "fmt" + "io" + "log/slog" + "net/http" + "net/http/httptest" + "net/netip" + "os" + "path/filepath" + "sync" + "testing" + "time" +) + +// fakeNamed serves a statistics channel whose counters the test sets. +type fakeNamed struct { + mu sync.Mutex + queries int64 + nx int64 + srv *httptest.Server +} + +func newFakeNamed(t *testing.T) *fakeNamed { + f := &fakeNamed{} + f.srv = httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + f.mu.Lock() + defer f.mu.Unlock() + fmt.Fprintf(w, `{"boot-time":"2026-10-05T08:00:00Z","opcodes":{"QUERY":%d},"rcodes":{"NOERROR":%d,"NXDOMAIN":%d},"qtypes":{"A":%d},"nsstats":{},"views":{}}`, + f.queries, f.queries-f.nx, f.nx, f.queries) + })) + t.Cleanup(f.srv.Close) + return f +} + +func (f *fakeNamed) add(q, nx int64) { + f.mu.Lock() + f.queries += q + f.nx += nx + f.mu.Unlock() +} + +type clock struct{ t time.Time } + +func (c *clock) now() time.Time { return c.t } + +func logLine(t time.Time, client, view, name, typ, rcode string) string { + v := "" + if view != "" { + v = "view " + view + ": " + } + return fmt.Sprintf("%s client @0x7f0000000000 %s#5353 (%s): %sresponse: %s IN %s %s 1 0 1 +E(0)K (10.10.0.2)\n", + t.Format(logTimeLayout), client, name, v, name, typ, rcode) +} + +func TestCollector(t *testing.T) { + ctx := context.Background() + loc := time.FixedZone("test", 2*3600) + dir := t.TempDir() + logFile := filepath.Join(dir, "responses.log") + store, err := OpenStore(filepath.Join(dir, "stats.db")) + if err != nil { + t.Fatal(err) + } + defer store.Close() + named := newFakeNamed(t) + clk := &clock{time.Date(2026, 10, 5, 10, 0, 30, 0, loc)} // a Monday + zones := func() map[string][]string { + return map[string][]string{"internal": {"adbraun.lol", "0.10.10.in-addr.arpa"}} + } + opts := Options{QueryLog: true, LogFile: logFile, StatisticsChannel: "unused", TopN: 3, + RetainMinute: 7 * 24 * time.Hour, RetainHour: 90 * 24 * time.Hour, RetainDay: 730 * 24 * time.Hour, + Exclude: []netip.Prefix{netip.MustParsePrefix("10.10.0.250/32")}, Location: loc} + log := slog.New(slog.NewTextHandler(io.Discard, nil)) + newCollector := func() *Collector { + c := NewCollector(store, opts, zones, log) + c.poller.URL = named.srv.URL + c.now = clk.now + c.start(ctx) + return c + } + write := func(lines ...string) { + f, err := os.OpenFile(logFile, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0o644) + if err != nil { + t.Fatal(err) + } + for _, l := range lines { + f.WriteString(l) + } + f.Close() + } + c := newCollector() + + // Minute 10:00: four responses (one from an excluded monitor). + base := time.Date(2026, 10, 5, 10, 0, 40, 0, loc) + write(logLine(base, "10.10.0.37", "internal", "nas.adbraun.lol", "A", "NOERROR"), + logLine(base, "10.10.0.37", "internal", "nas.adbraun.lol", "AAAA", "NOERROR"), + logLine(base, "10.10.0.42", "internal", "nope.adbraun.lol", "A", "NXDOMAIN"), + logLine(base, "10.10.0.42", "internal", "debian.org", "A", "NOERROR"), + logLine(base, "10.10.0.250", "internal", "nas.adbraun.lol", "A", "NOERROR")) + c.readLog() + named.add(5, 1) + clk.t = time.Date(2026, 10, 5, 10, 1, 2, 0, loc) + c.flush(ctx, false) + + m := time.Date(2026, 10, 5, 10, 0, 0, 0, loc).Unix() + got, err := store.sums(ctx, ResMinute, m, m+60, "") + if err != nil { + t.Fatal(err) + } + want := map[string]int64{"queries": 5, "rcode:NOERROR": 4, "rcode:NXDOMAIN": 1, "qtype:A": 5, "responses": 4, + "view:internal": 4, "zone:adbraun.lol": 3, "zone:-": 1} + for k, v := range want { + if got[k] != v { + t.Errorf("minute %s = %d, want %d (all: %v)", k, got[k], v, got) + } + } + names, _ := store.TopsAt(ctx, ResHour, m, KindName) + if len(names) != 3 || names[0] != (Entry{"nas.adbraun.lol", 2}) { + t.Errorf("hour names = %v", names) + } + if nx, _ := store.TopsAt(ctx, ResHour, m, KindNXDomain); len(nx) != 1 || nx[0].Key != "nope.adbraun.lol" { + t.Errorf("hour nxdomain = %v", nx) + } + + // Into the next hour: the 10:00 hour is finished and added to the day. + write(logLine(time.Date(2026, 10, 5, 10, 59, 50, 0, loc), "10.10.0.37", "internal", "nas.adbraun.lol", "A", "NOERROR"), + logLine(time.Date(2026, 10, 5, 11, 0, 1, 0, loc), "10.10.0.99", "internal", "printer.adbraun.lol", "A", "NOERROR")) + c.readLog() + named.add(2, 0) + clk.t = time.Date(2026, 10, 5, 11, 0, 2, 0, loc) + c.flush(ctx, false) + day := time.Date(2026, 10, 5, 0, 0, 0, 0, loc).Unix() + if d, _ := store.TopsAt(ctx, ResDay, day, KindName); len(d) == 0 || d[0] != (Entry{"nas.adbraun.lol", 3}) { + t.Errorf("day names after the hour = %v", d) + } + if v, _ := store.sums(ctx, ResDay, day, day+1, "queries"); v["queries"] != 7 { + t.Errorf("day queries = %v", v) + } + + // Restart in the middle of hour 11. Lines from hour 10 that were + // still unread are added to hour 10 and the day, not replacing them. + c.flush(ctx, true) + c2 := newCollector() + write(logLine(time.Date(2026, 10, 5, 10, 59, 59, 0, loc), "10.10.0.37", "internal", "nas.adbraun.lol", "A", "NOERROR"), + logLine(time.Date(2026, 10, 5, 11, 2, 0, 0, loc), "10.10.0.99", "internal", "printer.adbraun.lol", "A", "NOERROR")) + c2.readLog() + clk.t = time.Date(2026, 10, 5, 11, 3, 2, 0, loc) + c2.flush(ctx, false) + if h, _ := store.TopsAt(ctx, ResHour, m, KindName); len(h) == 0 || h[0] != (Entry{"nas.adbraun.lol", 4}) { + t.Errorf("hour 10 after late line = %v", h) + } + if d, _ := store.TopsAt(ctx, ResDay, day, KindName); d[0] != (Entry{"nas.adbraun.lol", 4}) { + t.Errorf("day after late line = %v", d) + } + h11 := time.Date(2026, 10, 5, 11, 0, 0, 0, loc).Unix() + if h, _ := store.TopsAt(ctx, ResHour, h11, KindName); len(h) != 1 || h[0] != (Entry{"printer.adbraun.lol", 2}) { + t.Errorf("hour 11 continued after restart = %v", h) + } + + // The read side. + q := &Querier{Store: store, Opts: opts, Now: clk.now} + s, err := q.Summary(ctx, 24*time.Hour, 5) + if err != nil { + t.Fatal(err) + } + if s.Queries != 7 || s.Resolution != ResMinute || s.Tops[KindName][0].Key != "nas.adbraun.lol" || s.Peak == nil || s.Peak.Queries != 5 { + t.Errorf("summary = %+v", s) + } + if s.NXDomainRatio == nil || *s.NXDomainRatio != 1.0/7 { + t.Errorf("nxdomain ratio = %v", s.NXDomainRatio) + } + tl, err := q.Timeline(ctx, 2*time.Hour, "auto", []string{"queries", "rcode:*"}) + if err != nil { + t.Fatal(err) + } + if tl.Step != "1m" || len(tl.Series) != 3 { + t.Fatalf("timeline step %s series %d", tl.Step, len(tl.Series)) + } + var total int64 + for _, v := range tl.Series[0].Values { + total += v + } + if tl.Series[0].Key != "queries" || total != 7 { + t.Errorf("timeline queries = %v", tl.Series[0]) + } + if tl, _ := q.Timeline(ctx, 30*24*time.Hour, "auto", []string{"queries"}); tl.Step != "6h" { + t.Errorf("30d step = %s", tl.Step) + } + hm, err := q.Heatmap(ctx, "", 7*24*time.Hour) + if err != nil { + t.Fatal(err) + } + // The counters polled at 11:00:02 belong to the minute before. + if hm.Avg[0][10] != 7 || hm.Avg[0][11] != 0 || hm.Samples[0][11] != 1 || hm.Avg[3][3] != -1 { + t.Errorf("heatmap Monday 10h=%v 11h=%v Thu 3h=%v", hm.Avg[0][10], hm.Avg[0][11], hm.Avg[3][3]) + } + b, _ := q.Breakdown(ctx, "zone", 24*time.Hour) + if len(b) != 2 || b[0] != (Entry{"adbraun.lol", 7}) || b[1] != (Entry{OtherZone, 1}) { + t.Errorf("zone breakdown = %v", b) + } + + // Retention: minute data older than the retention disappears. + opts.RetainMinute = time.Hour + c3 := NewCollector(store, opts, zones, log) + c3.now = func() time.Time { return clk.t.Add(2 * time.Hour) } + c3.prune(ctx) + if v, _ := store.sums(ctx, ResMinute, 0, 1<<40, "queries"); v["queries"] != 0 { + t.Errorf("minute data survived pruning: %v", v) + } + if v, _ := store.sums(ctx, ResHour, 0, 1<<40, "queries"); v["queries"] != 7 { + t.Errorf("hour data was pruned: %v", v) + } +} + +func TestAnonymizeAndParseSince(t *testing.T) { + if k := clientKey(netip.MustParseAddr("10.10.0.37"), true); k != "10.10.0.0/24" { + t.Errorf("v4 = %s", k) + } + if k := clientKey(netip.MustParseAddr("2001:db8:1:2::7"), true); k != "2001:db8:1::/48" { + t.Errorf("v6 = %s", k) + } + for in, want := range map[string]time.Duration{"": 24 * time.Hour, "90m": 90 * time.Minute, "7d": 7 * 24 * time.Hour, "2w": 14 * 24 * time.Hour} { + if d, err := ParseSince(in); err != nil || d != want { + t.Errorf("ParseSince(%q) = %v, %v", in, d, err) + } + } + for _, bad := range []string{"x", "-1h", "0d", "1.5d"} { + if _, err := ParseSince(bad); err == nil { + t.Errorf("ParseSince(%q) accepted", bad) + } + } +} diff --git a/internal/stats/parse.go b/internal/stats/parse.go new file mode 100644 index 0000000..1041182 --- /dev/null +++ b/internal/stats/parse.go @@ -0,0 +1,60 @@ +package stats + +import ( + "net/netip" + "regexp" + "strings" + "time" +) + +// Event is one response named logged. +type Event struct { + Time time.Time + Client netip.Addr + View string // "" without views + Name string // lowercase, without the final dot ("." for the root) + Type string // e.g. A, AAAA, PTR + RCode string // e.g. NOERROR, NXDOMAIN +} + +// responseRe matches named's response log lines (BIND 9.20, print-time): +// +// 07-Oct-2026 19:46:22.195 client @0x7135... 10.10.0.37#51709 (nas.adbraun.lol): view internal: response: nas.adbraun.lol IN A NOERROR 1 0 1 +E(0)K (10.10.0.2) +// +// The "view NAME: " part is missing when no views are configured. +var responseRe = regexp.MustCompile(`^(\d{2}-[A-Za-z]{3}-\d{4} \d{2}:\d{2}:\d{2}\.\d{3}) client @0x[0-9a-fA-F]+ (\S+)#\d+ \(.*?\): (?:view (.+?): )?response: (\S+) (\S+) (\S+) ([A-Z0-9]+) `) + +const logTimeLayout = "02-Jan-2006 15:04:05.000" + +// ParseResponse parses a response log line. ok is false for other lines +// (named also logs to the channel when it starts and rotates files). +func ParseResponse(line string, loc *time.Location) (ev Event, ok bool) { + m := responseRe.FindStringSubmatch(line) + if m == nil { + return ev, false + } + t, err := time.ParseInLocation(logTimeLayout, m[1], loc) + if err != nil { + return ev, false + } + client, err := netip.ParseAddr(m[2]) + if err != nil { + return ev, false + } + return Event{ + Time: t, + Client: client.Unmap(), + View: m[3], + Name: normalizeName(m[4]), + Type: m[6], + RCode: m[7], + }, true +} + +func normalizeName(n string) string { + n = strings.ToLower(n) + if n == "." { + return n + } + return strings.TrimSuffix(n, ".") +} diff --git a/internal/stats/parse_test.go b/internal/stats/parse_test.go new file mode 100644 index 0000000..f8271aa --- /dev/null +++ b/internal/stats/parse_test.go @@ -0,0 +1,44 @@ +package stats + +import ( + "testing" + "time" +) + +func TestParseResponse(t *testing.T) { + loc := time.FixedZone("test", 3600) + for _, tc := range []struct { + line string + ok bool + client, view, name, typ, rc string + }{ + // Real lines from named 9.20.24 (with and without views). + {`07-Oct-2026 19:46:22.184 client @0x71358b8ff000 127.0.0.1#53937 (www.example.test): view internal: response: www.example.test IN A NOERROR 1 0 1 +E(0)K (127.0.0.1)`, + true, "127.0.0.1", "internal", "www.example.test", "A", "NOERROR"}, + {`07-Oct-2026 19:46:22.195 client @0x71358b8ff000 10.10.0.37#51709 (nope.example.test): response: Nope.Example.Test IN AAAA NXDOMAIN 0 1 1 +E(0)K (127.0.0.1)`, + true, "10.10.0.37", "", "nope.example.test", "AAAA", "NXDOMAIN"}, + {`07-Oct-2026 19:46:22.217 client @0x71358b8ff000 2001:db8::7#55006 (other.zone): view external net: response: other.zone. IN MX REFUSED 0 0 1 +E(0)K (2001:db8::1)`, + true, "2001:db8::7", "external net", "other.zone", "MX", "REFUSED"}, + {`07-Oct-2026 19:46:22.217 client @0x71358b8ff000 ::ffff:10.0.0.1#55006 (.): response: . IN NS NOERROR 13 0 27 + (10.0.0.2)`, + true, "10.0.0.1", "", ".", "NS", "NOERROR"}, + // Query lines and other messages are not responses. + {`07-Oct-2026 19:46:22.184 client @0x71358b8ff000 127.0.0.1#53937 (www.example.test): view internal: query: www.example.test IN A +E(0)K (127.0.0.1)`, false, "", "", "", "", ""}, + {`07-Oct-2026 19:46:20.000 logging channel 'jarl_responses' file '/var/log/named/jarl-responses.log': rolled`, false, "", "", "", "", ""}, + {``, false, "", "", "", "", ""}, + } { + ev, ok := ParseResponse(tc.line, loc) + if ok != tc.ok { + t.Errorf("%q: ok = %v", tc.line, ok) + continue + } + if !ok { + continue + } + if ev.Client.String() != tc.client || ev.View != tc.view || ev.Name != tc.name || ev.Type != tc.typ || ev.RCode != tc.rc { + t.Errorf("%q: got %+v", tc.line, ev) + } + if want := time.Date(2026, 10, 7, 19, 46, 22, 0, loc); ev.Time.Truncate(time.Second) != want { + t.Errorf("%q: time %v, want %v", tc.line, ev.Time, want) + } + } +} diff --git a/internal/stats/poll.go b/internal/stats/poll.go new file mode 100644 index 0000000..1a7c460 --- /dev/null +++ b/internal/stats/poll.go @@ -0,0 +1,154 @@ +package stats + +import ( + "context" + "encoding/json" + "fmt" + "io" + "net/http" + "strings" + "time" +) + +// Snapshot is named's cumulative counters at one moment, flattened to the +// keys Jarl stores (see Counters in docs/stats.md). +type Snapshot struct { + BootTime string + Values map[string]int64 +} + +// serverJSON is the part of /json/v1/server Jarl uses. +type serverJSON struct { + BootTime string `json:"boot-time"` + Opcodes map[string]int64 `json:"opcodes"` + RCodes map[string]int64 `json:"rcodes"` + QTypes map[string]int64 `json:"qtypes"` + NSStats map[string]int64 `json:"nsstats"` + Views map[string]struct { + Resolver struct { + Stats map[string]int64 `json:"stats"` + CacheStats map[string]int64 `json:"cachestats"` + } `json:"resolver"` + } `json:"views"` +} + +// nsstatsKeys maps named's server counters to Jarl's counter names. +var nsstatsKeys = map[string]string{ + "QryAuthAns": "answer:authoritative", + "QryNoauthAns": "answer:recursive", + "QryRecursion": "recursion", + "QryDropped": "dropped", + "RateDropped": "ratelimit:dropped", + "RateSlipped": "ratelimit:slipped", + "QryTCP": "transport:tcp", + "QryUDP": "transport:udp", + "QryDuplicate": "duplicate", +} + +// rttKeys maps named's upstream round-trip buckets to readable names. +var rttKeys = map[string]string{ + "QryRTT10": "rtt:<10ms", + "QryRTT100": "rtt:10-100ms", + "QryRTT500": "rtt:100-500ms", + "QryRTT800": "rtt:500-800ms", + "QryRTT1600": "rtt:800-1600ms", + "QryRTT1600+": "rtt:>1600ms", +} + +var dnssecKeys = map[string]string{"ValOk": "dnssec:valid", "ValNegOk": "dnssec:valid-negative", "ValFail": "dnssec:failed"} + +// Flatten turns the statistics channel's JSON into a snapshot. +func Flatten(body []byte) (*Snapshot, error) { + var j serverJSON + if err := json.Unmarshal(body, &j); err != nil { + return nil, fmt.Errorf("unexpected statistics data: %w", err) + } + v := map[string]int64{"queries": j.Opcodes["QUERY"]} + for k, n := range j.RCodes { + if n != 0 && !strings.HasPrefix(k, "RESERVED") && (k[0] < '0' || k[0] > '9') { + v["rcode:"+k] = n + } + } + for k, n := range j.QTypes { + v["qtype:"+k] = n + } + for k, name := range nsstatsKeys { + if n := j.NSStats[k]; n != 0 { + v[name] = n + } + } + for _, view := range j.Views { + for k, name := range rttKeys { + v[name] += view.Resolver.Stats[k] + } + for k, name := range dnssecKeys { + v[name] += view.Resolver.Stats[k] + } + v["cache:hits"] += view.Resolver.CacheStats["QueryHits"] + v["cache:misses"] += view.Resolver.CacheStats["QueryMisses"] + } + for k, n := range v { + if n == 0 && k != "queries" { + delete(v, k) + } + } + return &Snapshot{BootTime: j.BootTime, Values: v}, nil +} + +// Delta returns the change from prev to cur. When named restarted (its +// boot time changed or a counter went down), the counters started again +// from zero, so the current values are the change. +func Delta(prev, cur *Snapshot) map[string]int64 { + out := map[string]int64{} + restarted := prev.BootTime != cur.BootTime + if !restarted { + for k, n := range cur.Values { + if n < prev.Values[k] { + restarted = true + break + } + } + } + for k, n := range cur.Values { + d := n + if !restarted { + d = n - prev.Values[k] + } + if d != 0 || k == "queries" { + out[k] = d + } + } + return out +} + +// Poller reads named's statistics channel. +type Poller struct { + URL string // e.g. http://127.0.0.1:8058/json/v1/server + Client *http.Client +} + +// NewPoller returns a poller for a statistics channel address. +func NewPoller(addr string) *Poller { + return &Poller{URL: "http://" + addr + "/json/v1/server", Client: &http.Client{Timeout: 10 * time.Second}} +} + +// Poll fetches a snapshot. +func (p *Poller) Poll(ctx context.Context) (*Snapshot, error) { + req, err := http.NewRequestWithContext(ctx, http.MethodGet, p.URL, nil) + if err != nil { + return nil, err + } + resp, err := p.Client.Do(req) + if err != nil { + return nil, fmt.Errorf("named's statistics channel is not reachable (%v); is the configuration with statistics applied and named running?", err) + } + defer resp.Body.Close() + body, err := io.ReadAll(io.LimitReader(resp.Body, 64<<20)) + if err != nil { + return nil, err + } + if resp.StatusCode != http.StatusOK { + return nil, fmt.Errorf("named's statistics channel answered %s", resp.Status) + } + return Flatten(body) +} diff --git a/internal/stats/poll_test.go b/internal/stats/poll_test.go new file mode 100644 index 0000000..6e41a26 --- /dev/null +++ b/internal/stats/poll_test.go @@ -0,0 +1,55 @@ +package stats + +import "testing" + +// A trimmed /json/v1/server answer from named 9.20.24. +const sampleJSON = `{"json-stats-version":"1.8","boot-time":"2026-10-07T19:46:51.322Z", + "opcodes":{"QUERY":10,"IQUERY":0,"NOTIFY":0}, + "rcodes":{"NOERROR":7,"NXDOMAIN":2,"SERVFAIL":1,"RESERVED11":0,"17":0}, + "qtypes":{"A":6,"AAAA":3,"MX":1}, + "nsstats":{"Requestv4":10,"QryAuthAns":4,"QryNoauthAns":6,"QryRecursion":2,"QryUDP":9,"QryTCP":1}, + "views":{"internal":{"resolver":{"stats":{"QryRTT100":3,"QryRTT500":1,"ValOk":2},"cachestats":{"QueryHits":4,"QueryMisses":2,"CacheHits":345}}}, + "_bind":{"resolver":{"stats":{},"cachestats":{}}}}}` + +func TestFlattenAndDelta(t *testing.T) { + s1, err := Flatten([]byte(sampleJSON)) + if err != nil { + t.Fatal(err) + } + want := map[string]int64{"queries": 10, "rcode:NOERROR": 7, "rcode:NXDOMAIN": 2, "rcode:SERVFAIL": 1, "qtype:A": 6, "qtype:AAAA": 3, "qtype:MX": 1, + "answer:authoritative": 4, "answer:recursive": 6, "recursion": 2, "transport:udp": 9, "transport:tcp": 1, + "rtt:10-100ms": 3, "rtt:100-500ms": 1, "dnssec:valid": 2, "cache:hits": 4, "cache:misses": 2} + for k, v := range want { + if s1.Values[k] != v { + t.Errorf("%s = %d, want %d", k, s1.Values[k], v) + } + } + if len(s1.Values) != len(want) { + t.Errorf("unexpected keys: %v", s1.Values) + } + // Normal change. + s2 := &Snapshot{BootTime: s1.BootTime, Values: map[string]int64{}} + for k, v := range s1.Values { + s2.Values[k] = v + } + s2.Values["queries"] += 5 + s2.Values["qtype:A"] += 5 + d := Delta(s1, s2) + if d["queries"] != 5 || d["qtype:A"] != 5 || d["qtype:AAAA"] != 0 || len(d) != 2 { + t.Errorf("delta = %v", d) + } + // Quiet minute: queries is still recorded (as 0) so coverage is visible. + if d := Delta(s2, s2); len(d) != 1 || d["queries"] != 0 { + t.Errorf("quiet delta = %v", d) + } + // named restarted: counters start again from zero. + s3 := &Snapshot{BootTime: "2026-10-07T20:00:00.000Z", Values: map[string]int64{"queries": 3, "qtype:A": 3}} + if d := Delta(s2, s3); d["queries"] != 3 || d["qtype:A"] != 3 { + t.Errorf("restart delta = %v", d) + } + // A counter going down also means a restart. + s4 := &Snapshot{BootTime: s2.BootTime, Values: map[string]int64{"queries": 2}} + if d := Delta(s2, s4); d["queries"] != 2 { + t.Errorf("reset delta = %v", d) + } +} diff --git a/internal/stats/query.go b/internal/stats/query.go new file mode 100644 index 0000000..adf6c40 --- /dev/null +++ b/internal/stats/query.go @@ -0,0 +1,422 @@ +package stats + +import ( + "cmp" + "context" + "fmt" + "slices" + "strings" + "time" +) + +// Querier answers questions about stored statistics. +type Querier struct { + Store *Store + Opts Options + Now func() time.Time +} + +// NewQuerier returns a querier for a collector's data. +func NewQuerier(c *Collector) *Querier { + return &Querier{Store: c.store, Opts: c.opts, Now: time.Now} +} + +func (q *Querier) loc() *time.Location { + if q.Opts.Location != nil { + return q.Opts.Location + } + return time.Local +} + +// Resolution picks the finest stored resolution that covers a time range +// starting since ago. +func (q *Querier) Resolution(since time.Duration) string { + switch { + case since <= 48*time.Hour && since <= q.Opts.RetainMinute: + return ResMinute + case since <= q.Opts.RetainHour: + return ResHour + } + return ResDay +} + +// topsResolution picks the resolution for top lists, which exist per hour +// and per day. +func (q *Querier) topsResolution(since time.Duration) string { + if since <= 7*24*time.Hour && since <= q.Opts.RetainHour { + return ResHour + } + return ResDay +} + +// bucketStart returns the start of the bucket containing t at a resolution. +func (q *Querier) bucketStart(res string, t time.Time) int64 { + switch res { + case ResMinute: + return t.Unix() - t.Unix()%60 + case ResHour: + return t.Unix() - t.Unix()%3600 + } + l := t.In(q.loc()) + return time.Date(l.Year(), l.Month(), l.Day(), 0, 0, 0, 0, q.loc()).Unix() +} + +// sums returns the totals of counters (optionally with a key prefix) in +// [from, to). +func (s *Store) sums(ctx context.Context, res string, from, to int64, prefix string) (map[string]int64, error) { + rows, err := s.db.QueryContext(ctx, `SELECT key, SUM(value) FROM counters WHERE res = ? AND ts >= ? AND ts < ? AND key LIKE ? ESCAPE '\' GROUP BY key`, + res, from, to, likePrefix(prefix)) + if err != nil { + return nil, err + } + defer rows.Close() + out := map[string]int64{} + for rows.Next() { + var k string + var v int64 + if err := rows.Scan(&k, &v); err != nil { + return nil, err + } + out[k] = v + } + return out, rows.Err() +} + +func likePrefix(p string) string { + r := strings.NewReplacer(`\`, `\\`, `%`, `\%`, `_`, `\_`) + return r.Replace(p) + "%" +} + +// series returns the values of a counter per bucket in [from, to). +func (s *Store) series(ctx context.Context, res string, from, to int64, key string) (map[int64]int64, error) { + rows, err := s.db.QueryContext(ctx, `SELECT ts, value FROM counters WHERE res = ? AND key = ? AND ts >= ? AND ts < ?`, res, key, from, to) + if err != nil { + return nil, err + } + defer rows.Close() + out := map[int64]int64{} + for rows.Next() { + var ts, v int64 + if err := rows.Scan(&ts, &v); err != nil { + return nil, err + } + out[ts] = v + } + return out, rows.Err() +} + +// tops sums top lists in [from, to). +func (s *Store) tops(ctx context.Context, res, kind string, from, to int64, limit int) ([]Entry, error) { + rows, err := s.db.QueryContext(ctx, `SELECT key, SUM(count) AS n FROM tops WHERE res = ? AND kind = ? AND ts >= ? AND ts < ? + GROUP BY key ORDER BY n DESC, key LIMIT ?`, res, kind, from, to, limit) + if err != nil { + return nil, err + } + defer rows.Close() + out := []Entry{} + for rows.Next() { + var e Entry + if err := rows.Scan(&e.Key, &e.Count); err != nil { + return nil, err + } + out = append(out, e) + } + return out, rows.Err() +} + +func sorted(m map[string]int64, prefix string) []Entry { + out := []Entry{} + for k, v := range m { + if strings.HasPrefix(k, prefix) && v != 0 { + out = append(out, Entry{strings.TrimPrefix(k, prefix), 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) + }) + return out +} + +// Summary is an overview of a time range. +type Summary struct { + From time.Time `json:"from"` + To time.Time `json:"to"` + Resolution string `json:"resolution"` + Queries int64 `json:"queries"` + // AvgQPS is queries per second over the part of the range with data. + AvgQPS float64 `json:"avg_qps"` + Peak *struct { + Time time.Time `json:"time"` + Queries int64 `json:"queries"` + Per string `json:"per"` // minute, hour or day + } `json:"peak,omitempty"` + RCodes []Entry `json:"rcodes"` + QTypes []Entry `json:"qtypes"` + Views []Entry `json:"views"` + Zones []Entry `json:"zones"` + Answers []Entry `json:"answers"` // authoritative, recursive + Transport []Entry `json:"transport"` // udp, tcp + CacheHitRatio *float64 `json:"cache_hit_ratio,omitempty"` + NXDomainRatio *float64 `json:"nxdomain_ratio,omitempty"` + Tops map[string][]Entry `json:"tops,omitempty"` +} + +// Summary summarizes the last since. +func (q *Querier) Summary(ctx context.Context, since time.Duration, topLimit int) (*Summary, error) { + now := q.Now() + res := q.Resolution(since) + from := q.bucketStart(res, now.Add(-since)) + to := now.Unix() + 1 + all, err := q.Store.sums(ctx, res, from, to, "") + if err != nil { + return nil, err + } + s := &Summary{From: time.Unix(from, 0), To: now, Resolution: res, Queries: all["queries"], + RCodes: sorted(all, "rcode:"), QTypes: sorted(all, "qtype:"), Views: sorted(all, "view:"), Zones: sorted(all, "zone:"), + Answers: sorted(all, "answer:"), Transport: sorted(all, "transport:")} + if h, m := all["cache:hits"], all["cache:misses"]; h+m > 0 { + r := float64(h) / float64(h+m) + s.CacheHitRatio = &r + } + if s.Queries > 0 { + r := float64(all["rcode:NXDOMAIN"]) / float64(s.Queries) + s.NXDomainRatio = &r + } + per, err := q.Store.series(ctx, res, from, to, "queries") + if err != nil { + return nil, err + } + if len(per) > 0 { + first, peakTS := int64(1<<62), int64(0) + var peak int64 = -1 + for ts, v := range per { + first = min(first, ts) + if v > peak || v == peak && ts < peakTS { + peak, peakTS = v, ts + } + } + if secs := float64(to - first); secs > 0 { + s.AvgQPS = float64(s.Queries) / secs + } + s.Peak = &struct { + Time time.Time `json:"time"` + Queries int64 `json:"queries"` + Per string `json:"per"` + }{time.Unix(peakTS, 0), peak, map[string]string{ResMinute: "minute", ResHour: "hour", ResDay: "day"}[res]} + } + if topLimit > 0 { + s.Tops = map[string][]Entry{} + for _, k := range []string{KindName, KindClient, KindNXDomain} { + es, err := q.Top(ctx, k, since, topLimit) + if err != nil { + return nil, err + } + s.Tops[k] = es + } + } + return s, nil +} + +// Top returns the largest entries of a top list over the last since. +func (q *Querier) Top(ctx context.Context, kind string, since time.Duration, limit int) ([]Entry, error) { + if !slices.Contains(Kinds, kind) { + return nil, fmt.Errorf("unknown list %q (use %s)", kind, strings.Join(Kinds, ", ")) + } + now := q.Now() + res := q.topsResolution(since) + return q.Store.tops(ctx, res, kind, q.bucketStart(res, now.Add(-since)), now.Unix()+1, limit) +} + +// Breakdown returns the totals of a counter group (qtype, rcode, view, +// zone, answer, transport, rtt, dnssec, cache, ratelimit) over the last since. +func (q *Querier) Breakdown(ctx context.Context, group string, since time.Duration) ([]Entry, error) { + if !slices.Contains(Groups, group) { + return nil, fmt.Errorf("unknown group %q (use %s)", group, strings.Join(Groups, ", ")) + } + now := q.Now() + res := q.Resolution(since) + m, err := q.Store.sums(ctx, res, q.bucketStart(res, now.Add(-since)), now.Unix()+1, group+":") + if err != nil { + return nil, err + } + return sorted(m, group+":"), nil +} + +// Groups are the counter groups Breakdown accepts. +var Groups = []string{"qtype", "rcode", "view", "zone", "answer", "transport", "rtt", "dnssec", "cache", "ratelimit"} + +// Timeline is a set of series over time. +type Timeline struct { + Step string `json:"step"` + Times []int64 `json:"times"` // bucket starts (Unix seconds) + Series []*Series `json:"series"` +} + +// Series is one counter over time. +type Series struct { + Key string `json:"key"` + Values []int64 `json:"values"` +} + +var steps = []struct { + name string + d time.Duration + res string +}{ + {"1m", time.Minute, ResMinute}, {"5m", 5 * time.Minute, ResMinute}, {"15m", 15 * time.Minute, ResMinute}, + {"1h", time.Hour, ResHour}, {"6h", 6 * time.Hour, ResHour}, {"1d", 24 * time.Hour, ResDay}, +} + +// Timeline returns counters over the last since. keys are counter names; +// a key ending in ":*" means every counter of that group. step is "auto" +// or one of 1m, 5m, 15m, 1h, 6h, 1d. +func (q *Querier) Timeline(ctx context.Context, since time.Duration, step string, keys []string) (*Timeline, error) { + idx := -1 + for i, st := range steps { + ok := st.res == ResMinute && since <= q.Opts.RetainMinute || st.res == ResHour && since <= q.Opts.RetainHour || st.res == ResDay + if step == st.name { + if !ok { + return nil, fmt.Errorf("step %s needs %s data, which is only kept for %s", st.name, map[string]string{ResMinute: "per-minute", ResHour: "hourly"}[st.res], humanDuration(map[string]time.Duration{ResMinute: q.Opts.RetainMinute, ResHour: q.Opts.RetainHour}[st.res])) + } + idx = i + break + } + if step == "auto" || step == "" { + if ok && since/st.d <= 300 { + idx = i + break + } + } + } + if idx < 0 { + if step != "auto" && step != "" { + return nil, fmt.Errorf("unknown step %q (use auto, 1m, 5m, 15m, 1h, 6h or 1d)", step) + } + idx = len(steps) - 1 + } + st := steps[idx] + now := q.Now() + // Buckets aligned to the step (days to local midnight). + var starts []int64 + if st.res == ResDay { + for t := time.Unix(q.bucketStart(ResDay, now.Add(-since)), 0).In(q.loc()); !t.After(now); t = t.AddDate(0, 0, 1) { + starts = append(starts, t.Unix()) + } + } else { + sd := int64(st.d.Seconds()) + first := now.Add(-since).Unix() + first -= first % sd + for t := first; t <= now.Unix(); t += sd { + starts = append(starts, t) + } + } + from, to := starts[0], now.Unix()+1 + // Expand group keys. + var expanded []string + for _, k := range keys { + if g, ok := strings.CutSuffix(k, ":*"); ok { + m, err := q.Store.sums(ctx, st.res, from, to, g+":") + if err != nil { + return nil, err + } + for _, e := range sorted(m, "") { + expanded = append(expanded, e.Key) + } + continue + } + expanded = append(expanded, k) + } + tl := &Timeline{Step: st.name, Times: starts, Series: []*Series{}} + for _, k := range expanded { + raw, err := q.Store.series(ctx, st.res, from, to, k) + if err != nil { + return nil, err + } + vals := make([]int64, len(starts)) + for ts, v := range raw { + // The bucket is the last start <= ts. + i, found := slices.BinarySearch(starts, ts) + if !found { + i-- + } + if i >= 0 && i < len(vals) { + vals[i] += v + } + } + tl.Series = append(tl.Series, &Series{Key: k, Values: vals}) + } + return tl, nil +} + +// Heatmap is average activity per weekday and hour of day (local time). +type Heatmap struct { + Key string `json:"key"` + // Avg[d][h] is the average per hour on weekday d (0 = Monday) at + // hour h; -1 where there is no data. + Avg [7][24]float64 `json:"avg"` + // Samples[d][h] is how many hours the average is based on. + Samples [7][24]int `json:"samples"` + From time.Time `json:"from"` +} + +// Heatmap averages a counter (default "queries") by weekday and hour over +// the last since (at most the hourly retention). +func (q *Querier) Heatmap(ctx context.Context, key string, since time.Duration) (*Heatmap, error) { + if key == "" { + key = "queries" + } + since = min(since, q.Opts.RetainHour) + now := q.Now() + from := q.bucketStart(ResHour, now.Add(-since)) + raw, err := q.Store.series(ctx, ResHour, from, now.Unix()+1, key) + if err != nil { + return nil, err + } + hm := &Heatmap{Key: key, From: time.Unix(from, 0)} + var sum [7][24]int64 + for ts, v := range raw { + t := time.Unix(ts, 0).In(q.loc()) + d := (int(t.Weekday()) + 6) % 7 + sum[d][t.Hour()] += v + hm.Samples[d][t.Hour()]++ + } + for d := range 7 { + for h := range 24 { + if n := hm.Samples[d][h]; n > 0 { + hm.Avg[d][h] = float64(sum[d][h]) / float64(n) + } else { + hm.Avg[d][h] = -1 + } + } + } + return hm, nil +} + +// ParseSince parses a range such as 90m, 24h, 7d or 2w. +func ParseSince(s string) (time.Duration, error) { + if s == "" { + return 24 * time.Hour, nil + } + mult := time.Duration(0) + switch { + case strings.HasSuffix(s, "d"): + mult = 24 * time.Hour + case strings.HasSuffix(s, "w"): + mult = 7 * 24 * time.Hour + } + if mult > 0 { + var n int + if _, err := fmt.Sscanf(s[:len(s)-1], "%d", &n); err != nil || n <= 0 || fmt.Sprint(n) != s[:len(s)-1] { + return 0, fmt.Errorf("invalid range %q (use e.g. 90m, 24h, 7d, 2w)", s) + } + return time.Duration(n) * mult, nil + } + d, err := time.ParseDuration(s) + if err != nil || d <= 0 { + return 0, fmt.Errorf("invalid range %q (use e.g. 90m, 24h, 7d, 2w)", s) + } + return d, nil +} diff --git a/internal/stats/store.go b/internal/stats/store.go new file mode 100644 index 0000000..3436806 --- /dev/null +++ b/internal/stats/store.go @@ -0,0 +1,254 @@ +// Package stats collects query statistics from named: counters from its +// statistics channel and per-query data from its response log. It stores +// aggregates (never individual queries) in a SQLite database of its own, +// separate from Jarl's configuration database, so it can be deleted at any +// time without losing anything important. +package stats + +import ( + "context" + "database/sql" + "errors" + "fmt" + + _ "modernc.org/sqlite" // registers the "sqlite" driver +) + +// Resolutions of stored data. +const ( + ResMinute = "m" + ResHour = "h" + ResDay = "d" +) + +// Store is the statistics database. +type Store struct { + db *sql.DB +} + +var schema = []string{ + `CREATE TABLE counters ( + res TEXT NOT NULL, + ts INTEGER NOT NULL, + key TEXT NOT NULL, + value INTEGER NOT NULL, + PRIMARY KEY (res, ts, key) + ) WITHOUT ROWID; + CREATE INDEX counters_by_key ON counters (res, key, ts); + CREATE TABLE tops ( + res TEXT NOT NULL, + ts INTEGER NOT NULL, + kind TEXT NOT NULL, + key TEXT NOT NULL, + count INTEGER NOT NULL, + PRIMARY KEY (res, ts, kind, key) + ) WITHOUT ROWID; + CREATE TABLE meta (key TEXT PRIMARY KEY, value TEXT NOT NULL);`, +} + +// OpenStore opens (creating if needed) the statistics database. Use +// ":memory:" for tests. +func OpenStore(path string) (*Store, error) { + dsn := "file:" + path + "?_pragma=busy_timeout(10000)&_pragma=synchronous(NORMAL)&_txlock=immediate" + if path == ":memory:" { + dsn = "file::memory:?_txlock=immediate" + } else { + dsn += "&_pragma=journal_mode(WAL)" + } + db, err := sql.Open("sqlite", dsn) + if err != nil { + return nil, err + } + if path == ":memory:" { + db.SetMaxOpenConns(1) + } + s := &Store{db: db} + if err := s.migrate(); err != nil { + db.Close() + return nil, fmt.Errorf("statistics database %s: %w", path, err) + } + return s, nil +} + +// Close closes the database. +func (s *Store) Close() error { return s.db.Close() } + +func (s *Store) migrate() error { + if _, err := s.db.Exec(`CREATE TABLE IF NOT EXISTS schema_version (version INTEGER NOT NULL)`); err != nil { + return err + } + var v int + err := s.db.QueryRow(`SELECT version FROM schema_version`).Scan(&v) + if errors.Is(err, sql.ErrNoRows) { + if _, err := s.db.Exec(`INSERT INTO schema_version (version) VALUES (0)`); err != nil { + return err + } + } else if err != nil { + return err + } + if v > len(schema) { + return fmt.Errorf("schema version %d is newer than this Jarl; upgrade Jarl or delete the statistics database", v) + } + for i := v; i < len(schema); i++ { + tx, err := s.db.Begin() + if err != nil { + return err + } + if _, err := tx.Exec(schema[i]); err != nil { + tx.Rollback() + return err + } + if _, err := tx.Exec(`UPDATE schema_version SET version = ?`, i+1); err != nil { + tx.Rollback() + return err + } + if err := tx.Commit(); err != nil { + return err + } + } + return nil +} + +// Batch collects writes that are committed together. +type Batch struct { + counters []counterRow + tops []topsWrite + meta map[string]string +} + +type counterRow struct { + res string + ts int64 + key string + value int64 +} + +type topsWrite struct { + res, kind string + ts int64 + entries []Entry + replace bool // replace the (res, ts, kind) rows instead of adding + keep int // after adding, keep only the largest entries (0: all) +} + +// Entry is a key and its count. +type Entry struct { + Key string `json:"key"` + Count int64 `json:"count"` +} + +// AddCounters adds values to the counters of a bucket. +func (b *Batch) AddCounters(res string, ts int64, values map[string]int64) { + for k, v := range values { + b.counters = append(b.counters, counterRow{res, ts, k, v}) + } +} + +// SetTops replaces a bucket's top list of a kind. +func (b *Batch) SetTops(res string, ts int64, kind string, entries []Entry) { + b.tops = append(b.tops, topsWrite{res: res, ts: ts, kind: kind, entries: entries, replace: true}) +} + +// AddTops adds counts to a bucket's top list and keeps the keep largest. +func (b *Batch) AddTops(res string, ts int64, kind string, entries []Entry, keep int) { + b.tops = append(b.tops, topsWrite{res: res, ts: ts, kind: kind, entries: entries, keep: keep}) +} + +// SetMeta stores a value that survives restarts. +func (b *Batch) SetMeta(key, value string) { + if b.meta == nil { + b.meta = map[string]string{} + } + b.meta[key] = value +} + +// Commit writes the batch in one transaction. +func (s *Store) Commit(ctx context.Context, b *Batch) error { + tx, err := s.db.BeginTx(ctx, nil) + if err != nil { + return err + } + defer tx.Rollback() + if len(b.counters) > 0 { + st, err := tx.PrepareContext(ctx, `INSERT INTO counters (res, ts, key, value) VALUES (?, ?, ?, ?) + ON CONFLICT (res, ts, key) DO UPDATE SET value = value + excluded.value`) + if err != nil { + return err + } + for _, c := range b.counters { + if _, err := st.ExecContext(ctx, c.res, c.ts, c.key, c.value); err != nil { + st.Close() + return err + } + } + st.Close() + } + for _, t := range b.tops { + if t.replace { + if _, err := tx.ExecContext(ctx, `DELETE FROM tops WHERE res = ? AND ts = ? AND kind = ?`, t.res, t.ts, t.kind); err != nil { + return err + } + } + for _, e := range t.entries { + if _, err := tx.ExecContext(ctx, `INSERT INTO tops (res, ts, kind, key, count) VALUES (?, ?, ?, ?, ?) + ON CONFLICT (res, ts, kind, key) DO UPDATE SET count = count + excluded.count`, t.res, t.ts, t.kind, e.Key, e.Count); err != nil { + return err + } + } + if t.keep > 0 { + if _, err := tx.ExecContext(ctx, `DELETE FROM tops WHERE res = ? AND ts = ? AND kind = ? AND key NOT IN ( + SELECT key FROM tops WHERE res = ? AND ts = ? AND kind = ? ORDER BY count DESC, key LIMIT ?)`, + t.res, t.ts, t.kind, t.res, t.ts, t.kind, t.keep); err != nil { + return err + } + } + } + for k, v := range b.meta { + if _, err := tx.ExecContext(ctx, `INSERT INTO meta (key, value) VALUES (?, ?) ON CONFLICT (key) DO UPDATE SET value = excluded.value`, k, v); err != nil { + return err + } + } + return tx.Commit() +} + +// Meta returns a stored value ("" if unset). +func (s *Store) Meta(ctx context.Context, key string) (string, error) { + var v string + err := s.db.QueryRowContext(ctx, `SELECT value FROM meta WHERE key = ?`, key).Scan(&v) + if errors.Is(err, sql.ErrNoRows) { + return "", nil + } + return v, err +} + +// Prune deletes data of a resolution older than before (a Unix time). +func (s *Store) Prune(ctx context.Context, res string, before int64) (int64, error) { + var n int64 + for _, table := range []string{"counters", "tops"} { + r, err := s.db.ExecContext(ctx, `DELETE FROM `+table+` WHERE res = ? AND ts < ?`, res, before) + if err != nil { + return n, err + } + c, _ := r.RowsAffected() + n += c + } + return n, nil +} + +// TopsAt returns a bucket's top list of a kind. +func (s *Store) TopsAt(ctx context.Context, res string, ts int64, kind string) ([]Entry, error) { + rows, err := s.db.QueryContext(ctx, `SELECT key, count FROM tops WHERE res = ? AND ts = ? AND kind = ? ORDER BY count DESC, key`, res, ts, kind) + if err != nil { + return nil, err + } + defer rows.Close() + var out []Entry + for rows.Next() { + var e Entry + if err := rows.Scan(&e.Key, &e.Count); err != nil { + return nil, err + } + out = append(out, e) + } + return out, rows.Err() +} diff --git a/internal/stats/tail.go b/internal/stats/tail.go new file mode 100644 index 0000000..48d512e --- /dev/null +++ b/internal/stats/tail.go @@ -0,0 +1,159 @@ +package stats + +import ( + "bytes" + "errors" + "io" + "io/fs" + "os" + "syscall" +) + +// Tailer follows a log file that named rotates (renaming it to FILE.0, +// FILE.1, ... and starting a new FILE). It remembers its position as +// (inode, offset) so reading resumes after a restart. +type Tailer struct { + Path string + + f *os.File + ino uint64 + offset int64 + partial []byte + // draining is set while finishing a rotated file before switching + // to the current one. + draining bool +} + +// Position is where the tailer is, for persisting. +type Position struct { + Inode uint64 `json:"inode"` + Offset int64 `json:"offset"` +} + +func inode(fi fs.FileInfo) uint64 { + if st, ok := fi.Sys().(*syscall.Stat_t); ok { + return st.Ino + } + return 0 +} + +// Position returns the current position (of complete lines). +func (t *Tailer) Position() Position { + return Position{Inode: t.ino, Offset: t.offset - int64(len(t.partial))} +} + +// Resume continues from a saved position: in the current file, or in the +// newest rotated file if named rotated it in the meantime. Without a +// usable position, reading starts at the beginning of the current file. +func (t *Tailer) Resume(p Position) { + if p.Inode == 0 { + return + } + for _, path := range []string{t.Path, t.Path + ".0"} { + fi, err := os.Stat(path) + if err != nil || inode(fi) != p.Inode || fi.Size() < p.Offset { + continue + } + f, err := os.Open(path) + if err != nil { + return + } + if _, err := f.Seek(p.Offset, io.SeekStart); err != nil { + f.Close() + return + } + t.f, t.ino, t.offset, t.draining = f, p.Inode, p.Offset, path != t.Path + return + } +} + +// open opens the current file from the start. A missing file is not an +// error: named creates it when it logs the first response. +func (t *Tailer) open() (bool, error) { + f, err := os.Open(t.Path) + if errors.Is(err, fs.ErrNotExist) { + return false, nil + } + if err != nil { + return false, err + } + fi, err := f.Stat() + if err != nil { + f.Close() + return false, err + } + t.f, t.ino, t.offset, t.partial, t.draining = f, inode(fi), 0, nil, false + return true, nil +} + +// Read calls fn for every complete new line and returns how many lines it +// read. Call it periodically. +func (t *Tailer) Read(fn func(line string)) (int, error) { + if t.f == nil { + ok, err := t.open() + if !ok || err != nil { + return 0, err + } + } + n := 0 + buf := make([]byte, 64<<10) + for { + k, err := t.f.Read(buf) + if k > 0 { + t.offset += int64(k) + data := append(t.partial, buf[:k]...) + for { + i := bytes.IndexByte(data, '\n') + if i < 0 { + break + } + fn(string(data[:i])) + n++ + data = data[i+1:] + } + t.partial = append([]byte(nil), data...) + if len(t.partial) > 1<<20 { // not a log line; drop it + t.partial = nil + } + } + if err == io.EOF || k == 0 { + break + } + if err != nil { + return n, err + } + } + // At the end of the file: has named rotated or truncated it? + fi, err := os.Stat(t.Path) + switch { + case errors.Is(err, fs.ErrNotExist): + return n, nil // rotated and not recreated yet + case err != nil: + return n, err + case t.draining || inode(fi) != t.ino: + t.f.Close() + t.f = nil + if _, err := t.open(); err != nil { + return n, err + } + if t.f != nil { + m, err := t.Read(fn) + return n + m, err + } + case fi.Size() < t.offset: + // Truncated (e.g. by hand): start again from the top. + if _, err := t.f.Seek(0, io.SeekStart); err != nil { + return n, err + } + t.offset, t.partial = 0, nil + } + return n, nil +} + +// Close closes the file. +func (t *Tailer) Close() { + if t.f != nil { + t.f.Close() + t.f = nil + } +} diff --git a/internal/stats/tail_test.go b/internal/stats/tail_test.go new file mode 100644 index 0000000..7e1f933 --- /dev/null +++ b/internal/stats/tail_test.go @@ -0,0 +1,77 @@ +package stats + +import ( + "os" + "path/filepath" + "reflect" + "testing" +) + +func TestTailer(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, "r.log") + var got []string + collect := func(l string) { got = append(got, l) } + appendTo := func(p, s string) { + f, err := os.OpenFile(p, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0o644) + if err != nil { + t.Fatal(err) + } + f.WriteString(s) + f.Close() + } + tl := &Tailer{Path: path} + // The file doesn't exist yet. + if n, err := tl.Read(collect); n != 0 || err != nil { + t.Fatalf("missing file: %d, %v", n, err) + } + appendTo(path, "one\ntwo\nthr") + tl.Read(collect) + appendTo(path, "ee\n") + tl.Read(collect) + if !reflect.DeepEqual(got, []string{"one", "two", "three"}) { + t.Fatalf("got %q", got) + } + // named rotates: renames the file and starts a new one. Lines written + // to the old file before the rename are not lost. + appendTo(path, "four\n") + os.Rename(path, path+".0") + appendTo(path, "five\n") + tl.Read(collect) + if !reflect.DeepEqual(got[3:], []string{"four", "five"}) { + t.Fatalf("after rotation got %q", got) + } + // Restart: resume from the saved position. + pos := tl.Position() + tl.Close() + appendTo(path, "six\n") + tl2 := &Tailer{Path: path} + tl2.Resume(pos) + got = nil + tl2.Read(collect) + if !reflect.DeepEqual(got, []string{"six"}) { + t.Fatalf("after resume got %q", got) + } + // Rotation while jarld was down: finish the rotated file first. + pos = tl2.Position() + tl2.Close() + appendTo(path, "seven\n") + os.Rename(path, path+".0") + appendTo(path, "eight\n") + tl3 := &Tailer{Path: path} + tl3.Resume(pos) + got = nil + tl3.Read(collect) + if !reflect.DeepEqual(got, []string{"seven", "eight"}) { + t.Fatalf("after offline rotation got %q", got) + } + // Truncation: start over. + os.WriteFile(path, []byte("x\n"), 0o644) + got = nil + tl3.Read(collect) + tl3.Read(collect) + if !reflect.DeepEqual(got, []string{"x"}) { + t.Fatalf("after truncation got %q", got) + } + tl3.Close() +} diff --git a/internal/web/static/assets/app.js b/internal/web/static/assets/app.js index 0aec259..cc61398 100644 --- a/internal/web/static/assets/app.js +++ b/internal/web/static/assets/app.js @@ -14,6 +14,7 @@ import * as audit from "./pages/audit.js"; import * as users from "./pages/users.js"; import * as account from "./pages/account.js"; import * as search from "./pages/search.js"; +import * as stats from "./pages/stats.js"; const routes = [ { pattern: /^$/, page: dashboard, nav: "dashboard" }, @@ -30,10 +31,12 @@ const routes = [ { pattern: /^users$/, page: users, nav: "users" }, { pattern: /^account$/, page: account, nav: "account" }, { pattern: /^search$/, page: search, nav: "" }, + { pattern: /^stats$/, page: stats, nav: "stats" }, ]; const navItems = [ ["dashboard", "#/", "Dashboard"], + ["stats", "#/stats", "Statistics"], ["zones", "#/zones", "Zones"], ["views", "#/views", "Views"], ["acls", "#/acls", "ACLs"], diff --git a/internal/web/static/assets/charts.js b/internal/web/static/assets/charts.js new file mode 100644 index 0000000..41643ed --- /dev/null +++ b/internal/web/static/assets/charts.js @@ -0,0 +1,333 @@ +// Small SVG charts for the statistics page: a line/area chart with a +// crosshair tooltip, a weekday x hour heatmap, and bar lists. No library; +// colors come from CSS custom properties (--series-N, --heat-N) so light +// and dark themes are handled in style.css. All text is inserted as text, +// never as markup. +import { h } from "./ui.js"; + +const NS = "http://www.w3.org/2000/svg"; + +function svg(tag, attrs, ...children) { + const el = document.createElementNS(NS, tag); + for (const [k, v] of Object.entries(attrs || {})) { + if (v !== undefined && v !== null && v !== false) el.setAttribute(k, v); + } + for (const c of children.flat(Infinity)) { + if (c === null || c === undefined || c === false) continue; + el.append(c instanceof Node ? c : document.createTextNode(String(c))); + } + return el; +} + +// compact formats a count: 1,234 / 12.9K / 4.2M. +export function compact(n) { + const a = Math.abs(n); + if (a >= 1e9) return (n / 1e9).toFixed(a >= 1e10 ? 0 : 1).replace(/\.0$/, "") + "B"; + if (a >= 1e6) return (n / 1e6).toFixed(a >= 1e7 ? 0 : 1).replace(/\.0$/, "") + "M"; + if (a >= 1e4) return (n / 1e3).toFixed(a >= 1e5 ? 0 : 1).replace(/\.0$/, "") + "K"; + return Math.round(n).toLocaleString(); +} + +// niceTicks returns 0..max in clean steps (1, 2 or 5 x 10^k), at most n+1 ticks. +export function niceTicks(max, n = 4) { + if (max <= 0) return [0, 1]; + const raw = max / n; + const mag = Math.pow(10, Math.floor(Math.log10(raw))); + const step = [1, 2, 5, 10].map((m) => m * mag).find((s) => s >= raw); + const ticks = []; + for (let v = 0; v < max + step * 0.999; v += step) ticks.push(Math.round(v * 1e6) / 1e6); + return ticks; +} + +const MIN = 60, HOUR = 3600, DAY = 86400; +const tickSteps = [5 * MIN, 10 * MIN, 15 * MIN, 30 * MIN, HOUR, 2 * HOUR, 3 * HOUR, 6 * HOUR, 12 * HOUR, DAY, 2 * DAY, 7 * DAY, 14 * DAY, 30 * DAY]; + +// timeTicks picks local-time-aligned ticks between t0 and t1 (Unix seconds). +function timeTicks(t0, t1, maxTicks) { + const span = t1 - t0; + const step = tickSteps.find((s) => span / s <= maxTicks) || 30 * DAY; + const out = []; + const d = new Date(t0 * 1000); + if (step >= DAY) { + d.setHours(0, 0, 0, 0); + } else { + d.setSeconds(0, 0); + const mins = d.getHours() * 60 + d.getMinutes(); + const stepMin = step / 60; + d.setHours(0, Math.floor(mins / stepMin) * stepMin, 0, 0); + } + for (let t = d.getTime() / 1000; t <= t1; ) { + if (t >= t0) out.push(t); + if (step >= DAY) { + const nd = new Date(t * 1000); + nd.setDate(nd.getDate() + step / DAY); + t = nd.getTime() / 1000; + } else t += step; + } + return { ticks: out, step }; +} + +const weekdays = ["Sun", "Mon", "Tue", "Wed", "Thu", "Fri", "Sat"]; +const months = ["Jan", "Feb", "Mar", "Apr", "May", "Jun", "Jul", "Aug", "Sep", "Oct", "Nov", "Dec"]; +const pad = (n) => String(n).padStart(2, "0"); + +function tickLabel(t, step) { + const d = new Date(t * 1000); + if (step >= DAY) return step >= 7 * DAY ? months[d.getMonth()] + " " + d.getDate() : weekdays[d.getDay()] + " " + d.getDate(); + const hm = pad(d.getHours()) + ":" + pad(d.getMinutes()); + return d.getHours() === 0 && d.getMinutes() === 0 ? weekdays[d.getDay()] + " " + d.getDate() : hm; +} + +// longTime describes a bucket for tooltips and tables. +export function bucketLabel(t, stepSecs) { + const d = new Date(t * 1000); + const day = weekdays[d.getDay()] + " " + d.getDate() + " " + months[d.getMonth()]; + if (stepSecs >= DAY) return day; + const end = new Date((t + stepSecs) * 1000); + const hm = (x) => pad(x.getHours()) + ":" + pad(x.getMinutes()); + return day + ", " + hm(d) + (stepSecs > MIN ? "–" + hm(end) : ""); +} + +export const stepSeconds = { "1m": MIN, "5m": 5 * MIN, "15m": 15 * MIN, "1h": HOUR, "6h": 6 * HOUR, "1d": DAY }; + +// tooltip is one floating readout per chart. +function tooltip() { + const el = h("div", { class: "chart-tip", role: "status" }); + el.hidden = true; + return el; +} + +// chartCard wraps a chart with its title and a table-view toggle (the +// accessible twin of every chart). +export function chartCard(title, subtitle, chart, tableView, opts = {}) { + const body = h("div", { class: "chart-body" }, chart); + const tableBox = h("div", { class: "chart-table" }, tableView); + tableBox.hidden = true; + const toggle = h("button", { class: "small link", type: "button", "aria-pressed": "false" }, "Table"); + toggle.addEventListener("click", () => { + const showTable = tableBox.hidden; + tableBox.hidden = !showTable; + body.hidden = showTable; + toggle.textContent = showTable ? "Chart" : "Table"; + toggle.setAttribute("aria-pressed", String(showTable)); + }); + return h("figure", { class: "panel chart-card" + (opts.wide ? " wide" : "") }, + h("figcaption", { class: "chart-head" }, + h("div", { class: "grow" }, h("h2", null, title), subtitle ? h("div", { class: "muted small" }, subtitle) : null), + opts.legend || null, + tableView ? toggle : null), + body, tableBox); +} + +// legend lists series with a short line key (the mark the series uses). +export function legend(series) { + return h("ul", { class: "chart-legend" }, series.map((s) => + h("li", null, h("span", { class: "key line s" + s.slot }), s.label))); +} + +// lineChart draws series over time. series: [{label, values, slot}] (slot +// = categorical color 1..3); times: bucket starts (Unix seconds); step in +// seconds. With area, the first series gets a 10% wash under its line. +export function lineChart({ series, times, step, area = false, height = 220, endLabels = true }) { + const root = h("div", { class: "chart", tabindex: "0", "aria-label": series.map((s) => s.label).join(", ") + " over time" }); + const tip = tooltip(); + root.append(tip); + let width = 0, focusIdx = -1, geom = null; + + function draw() { + const w = root.clientWidth; + if (!w || w === width) return; + width = w; + root.querySelector("svg")?.remove(); + const max = Math.max(1, ...series.flatMap((s) => s.values)); + const yTicks = niceTicks(max, 4); + const yMax = yTicks[yTicks.length - 1]; + const labelW = Math.max(...yTicks.map((t) => compact(t).length)) * 7 + 10; + const endW = endLabels && series.length > 1 && series.length <= 4 ? Math.max(...series.map((s) => s.label.length)) * 7 + 12 : 8; + const m = { top: 10, right: endW, bottom: 24, left: labelW }; + const pw = Math.max(40, w - m.left - m.right), ph = height - m.top - m.bottom; + const t0 = times[0], t1 = times[times.length - 1] + step; + const x = (t) => m.left + ((t - t0) / Math.max(1, t1 - t0)) * pw; + const cx = (i) => x(times[i] + step / 2); // the middle of a bucket + const y = (v) => m.top + ph - (v / yMax) * ph; + const s = svg("svg", { width: w, height, viewBox: `0 0 ${w} ${height}`, role: "img", "aria-hidden": "true" }); + // Grid and axes. + for (const t of yTicks) { + s.append(svg("line", { class: t === 0 ? "axis" : "grid", x1: m.left, x2: m.left + pw, y1: y(t), y2: y(t) })); + s.append(svg("text", { class: "tick", x: m.left - 6, y: y(t) + 4, "text-anchor": "end" }, compact(t))); + } + const { ticks, step: tstep } = timeTicks(t0, t1, Math.max(2, Math.floor(pw / 90))); + for (const t of ticks) { + s.append(svg("text", { class: "tick", x: x(t), y: height - 6, "text-anchor": "middle" }, tickLabel(t, tstep))); + } + // Series. + series.forEach((sr, k) => { + const pts = sr.values.map((v, i) => [cx(i), y(v)]); + const d = pts.map((p, i) => (i ? "L" : "M") + p[0].toFixed(1) + " " + p[1].toFixed(1)).join(""); + if (area && k === 0 && pts.length) { + s.append(svg("path", { class: "area s" + sr.slot, d: d + `L${pts[pts.length - 1][0].toFixed(1)} ${y(0)}L${pts[0][0].toFixed(1)} ${y(0)}Z` })); + } + s.append(svg("path", { class: "line s" + sr.slot, d })); + if (pts.length === 1) s.append(svg("circle", { class: "dot s" + sr.slot, cx: pts[0][0], cy: pts[0][1], r: 4 })); + }); + // Direct end labels when there is room and they don't collide. + if (m.right > 8) { + const ends = series.map((sr) => ({ label: sr.label, y: y(sr.values[sr.values.length - 1] || 0) })).sort((a, b) => a.y - b.y); + if (ends.every((e, i) => i === 0 || e.y - ends[i - 1].y >= 13)) { + for (const e of ends) s.append(svg("text", { class: "end-label", x: m.left + pw + 6, y: e.y + 4 }, e.label)); + } + } + // Crosshair (drawn on hover/focus). + const cross = svg("line", { class: "crosshair", y1: m.top, y2: m.top + ph, visibility: "hidden" }); + const dots = series.map((sr) => svg("circle", { class: "dot s" + sr.slot, r: 4, visibility: "hidden" })); + s.append(cross, ...dots); + // The hit area is the whole plot: readers aim at a time, not a line. + const hit = svg("rect", { class: "hit", x: m.left, y: m.top, width: pw, height: ph }); + s.append(hit); + root.prepend(s); + geom = { cx, y, m, pw, ph, cross, dots, hit }; + hit.addEventListener("pointermove", (e) => { + const r = s.getBoundingClientRect(); + const px = e.clientX - r.left; + const i = Math.round(((px - m.left) / pw) * (times.length) - 0.5); + show(Math.max(0, Math.min(times.length - 1, i))); + }); + hit.addEventListener("pointerleave", hide); + if (focusIdx >= 0) show(focusIdx); + } + + function show(i) { + if (!geom) return; + focusIdx = i; + const xpos = geom.cx(i); + geom.cross.setAttribute("x1", xpos); + geom.cross.setAttribute("x2", xpos); + geom.cross.setAttribute("visibility", "visible"); + series.forEach((sr, k) => { + geom.dots[k].setAttribute("cx", xpos); + geom.dots[k].setAttribute("cy", geom.y(sr.values[i])); + geom.dots[k].setAttribute("visibility", "visible"); + }); + tip.replaceChildren( + h("div", { class: "tip-head" }, bucketLabel(times[i], step)), + ...series.map((sr) => h("div", { class: "tip-row" }, + h("span", { class: "key line s" + sr.slot }), h("strong", null, sr.values[i].toLocaleString()), " ", h("span", { class: "muted" }, sr.label)))); + tip.hidden = false; + // Keep the readout inside the chart, on the far side of the pointer. + const left = xpos > root.clientWidth / 2 ? xpos - tip.offsetWidth - 12 : xpos + 12; + tip.style.left = Math.max(0, left) + "px"; + tip.style.top = geom.m.top + "px"; + } + + function hide() { + if (!geom) return; + geom.cross.setAttribute("visibility", "hidden"); + geom.dots.forEach((d) => d.setAttribute("visibility", "hidden")); + tip.hidden = true; + focusIdx = -1; + } + + // Keyboard: arrows move the crosshair, as hover does. + root.addEventListener("focus", () => show(focusIdx >= 0 ? focusIdx : times.length - 1)); + root.addEventListener("blur", hide); + root.addEventListener("keydown", (e) => { + if (e.key === "ArrowLeft" || e.key === "ArrowRight") { + e.preventDefault(); + show(Math.max(0, Math.min(times.length - 1, (focusIdx < 0 ? times.length - 1 : focusIdx) + (e.key === "ArrowLeft" ? -1 : 1)))); + } + }); + new ResizeObserver(draw).observe(root); + return root; +} + +// timeTable is the table view of a line chart (busiest buckets first is +// not useful here: keep time order, newest first). +export function timeTable(series, times, step) { + const rows = times.map((t, i) => ({ t, i })).reverse(); + return h("div", { class: "table-wrap scroll" }, h("table", null, + h("thead", null, h("tr", null, h("th", null, "Time"), series.map((s) => h("th", { class: "num" }, s.label)))), + h("tbody", null, rows.map((r) => h("tr", null, h("td", null, bucketLabel(r.t, step)), + series.map((s) => h("td", { class: "num" }, s.values[r.i].toLocaleString()))))))); +} + +// heatmap draws average activity by weekday (rows, Monday first) and hour +// (columns) with a sequential one-hue ramp; cells without data stay empty. +export function heatmap(hm, unit) { + const days = ["Mon", "Tue", "Wed", "Thu", "Fri", "Sat", "Sun"]; + let peak = 0; + hm.avg.forEach((row) => row.forEach((v) => { peak = Math.max(peak, v); })); + const steps = 7; + const level = (v) => (peak <= 0 ? 0 : Math.min(steps - 1, Math.floor((v / peak) * steps))); + const tip = tooltip(); + const grid = h("div", { class: "heatmap", role: "grid", "aria-label": "Average " + unit + " per hour by weekday and hour of day" }); + grid.append(h("div", { class: "hm-corner" })); + for (let hr = 0; hr < 24; hr++) grid.append(h("div", { class: "hm-col" }, hr % 3 === 0 ? pad(hr) : "")); + days.forEach((day, d) => { + grid.append(h("div", { class: "hm-row" }, day)); + for (let hr = 0; hr < 24; hr++) { + const v = hm.avg[d][hr]; + const n = hm.samples[d][hr]; + const text = v < 0 ? day + " " + pad(hr) + ":00 – no data" : + day + " " + pad(hr) + ":00 – " + Math.round(v).toLocaleString() + " " + unit + " per hour (average of " + n + (n === 1 ? " hour)" : " hours)"); + const cell = h("div", { class: "hm-cell " + (v < 0 ? "empty" : "heat-" + level(v)), tabindex: "-1", "aria-label": text }); + const showTip = () => { + tip.textContent = text; + tip.hidden = false; + const r = cell.getBoundingClientRect(), pr = grid.getBoundingClientRect(); + tip.style.left = Math.max(0, Math.min(pr.width - tip.offsetWidth, r.left - pr.left - tip.offsetWidth / 2 + r.width / 2)) + "px"; + tip.style.top = (r.bottom - pr.top + 6) + "px"; + }; + cell.addEventListener("pointerenter", showTip); + cell.addEventListener("focus", showTip); + cell.addEventListener("pointerleave", () => { tip.hidden = true; }); + cell.addEventListener("blur", () => { tip.hidden = true; }); + grid.append(cell); + } + }); + // Arrow keys move between cells. + grid.tabIndex = 0; + let cur = -1; + const cells = () => [...grid.querySelectorAll(".hm-cell")]; + grid.addEventListener("keydown", (e) => { + const delta = { ArrowLeft: -1, ArrowRight: 1, ArrowUp: -24, ArrowDown: 24 }[e.key]; + if (delta === undefined) return; + e.preventDefault(); + cur = Math.max(0, Math.min(7 * 24 - 1, (cur < 0 ? 0 : cur) + delta)); + cells()[cur].focus(); + }); + const scale = h("div", { class: "hm-scale" }, + h("span", { class: "muted small" }, "0"), + Array.from({ length: steps }, (_, i) => h("span", { class: "hm-swatch heat-" + i })), + h("span", { class: "muted small" }, compact(peak) + " " + unit + "/hour"), + h("span", { class: "hm-swatch empty" }), h("span", { class: "muted small" }, "no data")); + return h("div", { class: "heatmap-wrap" }, grid, tip, scale); +} + +export function heatmapTable(hm, unit) { + const days = ["Monday", "Tuesday", "Wednesday", "Thursday", "Friday", "Saturday", "Sunday"]; + return h("div", { class: "table-wrap scroll" }, h("table", null, + h("thead", null, h("tr", null, h("th", null, "Hour"), days.map((d) => h("th", { class: "num" }, d)))), + h("tbody", null, Array.from({ length: 24 }, (_, hr) => h("tr", null, h("td", null, pad(hr) + ":00"), + days.map((_, d) => h("td", { class: "num" }, hm.avg[d][hr] < 0 ? "–" : Math.round(hm.avg[d][hr]).toLocaleString())))))), + h("div", { class: "muted small" }, "Average " + unit + " per hour.")); +} + +// barList shows ranked entries as labelled horizontal bars in one hue +// (one series: no legend, the title names it). Values are always printed, +// so the list is its own table view. +export function barList(entries, { total, label = (k) => k, empty = "No data yet.", href } = {}) { + if (!entries.length) return h("div", { class: "empty" }, empty); + // Entries may be in a natural order (e.g. latency buckets), not by size. + const peak = Math.max(1, ...entries.map((e) => e.count)); + const sum = total || entries.reduce((a, e) => a + e.count, 0); + return h("ol", { class: "bar-list" }, entries.map((e) => { + const share = sum ? (e.count / sum) * 100 : 0; + const name = label(e.key); + const link = href ? href(e.key) : null; + return h("li", { title: name + ": " + e.count.toLocaleString() + " (" + share.toFixed(1) + "%)" }, + h("div", { class: "bar-text" }, + link ? h("a", { href: link, class: "bar-label" }, name) : h("span", { class: "bar-label" }, name), + h("span", { class: "bar-value" }, compact(e.count), h("span", { class: "muted" }, " · " + share.toFixed(share < 10 ? 1 : 0) + "%"))), + h("div", { class: "bar-track" }, h("div", { class: "bar-fill", style: { width: Math.max(0.5, (e.count / peak) * 100) + "%" } }))); + })); +} diff --git a/internal/web/static/assets/pages/stats.js b/internal/web/static/assets/pages/stats.js new file mode 100644 index 0000000..1cc84b4 --- /dev/null +++ b/internal/web/static/assets/pages/stats.js @@ -0,0 +1,186 @@ +import { h, mount, fmtTime, errorBox } from "../ui.js"; +import { get } from "../api.js"; +import { lineChart, chartCard, legend, timeTable, heatmap, heatmapTable, barList, compact, stepSeconds } from "../charts.js"; + +const ranges = [["1h", "1 hour"], ["6h", "6 hours"], ["24h", "24 hours"], ["7d", "7 days"], ["30d", "30 days"], ["90d", "90 days"]]; +const rangeSecs = { "1h": 3600, "6h": 6 * 3600, "24h": 86400, "7d": 7 * 86400, "30d": 30 * 86400, "90d": 90 * 86400 }; + +// Failed answers keep the same color whatever the range: color follows +// the result code, never its rank. +const failures = [ + { key: "rcode:NXDOMAIN", label: "NXDOMAIN", slot: 1 }, + { key: "rcode:SERVFAIL", label: "SERVFAIL", slot: 2 }, + { key: "rcode:REFUSED", label: "REFUSED", slot: 3 }, +]; + +const rttOrder = ["<10ms", "10-100ms", "100-500ms", "500-800ms", "800-1600ms", ">1600ms"]; + +let generation = 0; + +export async function render(el, params, query) { + const gen = ++generation; + const want = query && query.get ? query.get("since") : null; + const since = rangeSecs[want] ? want : "24h"; + const status = await get("/stats/status"); + const head = h("div", { class: "page-head" }, + h("div", { class: "grow" }, h("h1", null, "Statistics"), + h("div", { class: "muted" }, status.enabled + ? "From named's counters" + (status.query_log ? " and response log" : "") + " · data since " + (status.first_data ? fmtTime(status.first_data) : "–") + + " · kept: minutes " + status.retention.minute + ", hours " + status.retention.hour + ", days " + status.retention.day + : "Query statistics are off"))); + if (!status.enabled) { + mount(el, head, disabledPanel()); + return; + } + const heatSince = rangeSecs[since] < 7 * 86400 ? "7d" : since; + let data; + try { + data = await loadAll(since, heatSince, status.query_log); + } catch (e) { + mount(el, head, errorBox(e)); + return; + } + if (gen !== generation) return; // the user moved on + const { summary: s, heat } = data; + // The newest bucket is still filling up; drawing it would look like a + // sudden drop in traffic. + const timeline = complete(data.timeline), errors = complete(data.errors); + const step = stepSeconds[timeline.step]; + const parts = [head, filterRow(since)]; + for (const w of status.warnings || []) parts.push(h("div", { class: "msg warn" }, w)); + + // Headline numbers. + const rangeLabel = "in the last " + ranges.find((r) => r[0] === since)[1]; + parts.push(h("div", { class: "cards" }, + tile("Queries", compact(s.queries), rangeLabel), + tile("Per second", s.avg_qps < 10 ? s.avg_qps.toFixed(2) : Math.round(s.avg_qps).toLocaleString(), "on average"), + s.peak ? tile("Busiest " + s.peak.per, compact(s.peak.queries), fmtTime(s.peak.time)) : null, + s.nxdomain_ratio != null ? tile("NXDOMAIN", pct(s.nxdomain_ratio), "of queries named no existing name") : null, + s.cache_hit_ratio != null ? tile("Cache hits", pct(s.cache_hit_ratio), "of recursive queries answered from cache") : null)); + + // Volume over time: one series, so no legend box; the title names it. + const q = timeline.series.find((x) => x.key === "queries") || { values: timeline.times.map(() => 0) }; + const qSeries = [{ label: "Queries", values: q.values, slot: 1 }]; + parts.push(chartCard("Queries", "per " + stepName(timeline.step) + ", " + rangeLabel, + lineChart({ series: qSeries, times: timeline.times, step, area: true }), timeTable(qSeries, timeline.times, step), { wide: true })); + + // Failed answers: three fixed series, legend plus end labels. + const fSeries = failures.map((f) => ({ ...f, values: (errors.series.find((x) => x.key === f.key) || { values: errors.times.map(() => 0) }).values })); + const anyFailures = fSeries.some((f) => f.values.some((v) => v > 0)); + parts.push(chartCard("Failed answers", "NXDOMAIN: the name doesn't exist · SERVFAIL: resolution failed · REFUSED: not allowed", + anyFailures ? lineChart({ series: fSeries, times: errors.times, step: stepSeconds[errors.step] }) : h("div", { class: "empty" }, "No failed answers " + rangeLabel + "."), + anyFailures ? timeTable(fSeries, errors.times, stepSeconds[errors.step]) : null, + { wide: true, legend: anyFailures ? legend(fSeries) : null })); + + // When is the server busy? + parts.push(chartCard("Busiest times", "average queries per hour by weekday and hour of day (local time), last " + ranges.find((r) => r[0] === heatSince)[1], + heatmap(heat, "queries"), heatmapTable(heat, "queries"), { wide: true })); + + // Who asks for what. + if (status.query_log) { + const t = data.tops; + parts.push(h("div", { class: "chart-grid" }, + listCard("Most queried names", "", barList(t.name, { href: (k) => "#/search?q=" + encodeURIComponent(k) })), + listCard("Busiest clients", "", barList(t.client)), + listCard("Names that don't exist", "NXDOMAIN answers: typos, removed hosts, misconfigured clients, malware", barList(t.nxdomain, { empty: "None " + rangeLabel + "." })), + listCard("Refused clients", "clients asking for something they may not have (often internet scanners)", barList(t.refused, { empty: "None " + rangeLabel + "." })), + t.servfail.length ? listCard("Names that failed to resolve", "SERVFAIL answers", barList(t.servfail)) : null)); + } else { + parts.push(h("div", { class: "msg info" }, "Top names and clients need the response log: set stats.query_log: true in /etc/jarl/jarl.yaml and restart jarl.")); + } + + // Breakdowns. + const b = data.breakdowns; + const rtt = rttOrder.map((k) => b.rtt.find((e) => e.key === k)).filter(Boolean); + parts.push(h("div", { class: "chart-grid" }, + listCard("Record types", "", barList(b.qtype, { total: s.queries })), + listCard("Result codes", "", barList(b.rcode, { total: s.queries })), + b.view.length > 1 || (b.view.length === 1 && b.view[0].key !== "_default") ? listCard("Views", "", barList(b.view, { label: viewLabel })) : null, + b.zone.length ? listCard("Zones", "queries per local zone; other = names in no local zone (recursion)", barList(b.zone, { label: (k) => (k === "-" ? "other" : k), href: (k) => (k === "-" ? null : "#/search?q=" + encodeURIComponent(k)) })) : null, + b.answer.length ? listCard("Answers", "authoritative (your zones) or recursive (from the cache or the internet)", barList(b.answer)) : null, + rtt.length ? listCard("Upstream response time", "how long other servers took to answer named's recursive queries", barList(rtt)) : null)); + el.classList.remove("refreshing"); + mount(el, parts); + scheduleRefresh(el, params, query, gen); +} + +async function loadAll(since, heatSince, queryLog) { + const p = { + summary: get("/stats/summary", { since, top: 0 }), + timeline: get("/stats/timeline", { since, key: "queries" }), + errors: get("/stats/timeline", { since, key: failures.map((f) => f.key).join(",") }), + heat: get("/stats/heatmap", { since: heatSince }), + }; + const groups = ["qtype", "rcode", "view", "zone", "answer", "rtt"]; + groups.forEach((g) => { p["b_" + g] = get("/stats/breakdown", { group: g, since }); }); + if (queryLog) { + for (const k of ["name", "client", "nxdomain", "refused", "servfail"]) p["t_" + k] = get("/stats/top", { kind: k, since, limit: 15 }); + } + const keys = Object.keys(p); + const vals = await Promise.all(Object.values(p)); + const out = { breakdowns: {}, tops: {} }; + keys.forEach((k, i) => { + if (k.startsWith("b_")) out.breakdowns[k.slice(2)] = vals[i]; + else if (k.startsWith("t_")) out.tops[k.slice(2)] = vals[i]; + else out[k] = vals[i]; + }); + return out; +} + +// scheduleRefresh reloads the page's data every minute while it is shown, +// keeping the current render (dimmed) until the new one is ready. +function scheduleRefresh(el, params, query, gen) { + setTimeout(() => { + if (gen !== generation || !location.hash.startsWith("#/stats") || !el.isConnected) return; + el.classList.add("refreshing"); + render(el, params, query).catch(() => el.classList.remove("refreshing")); + }, 60_000); +} + +// complete drops the last bucket of a timeline if it hasn't ended yet. +function complete(tl) { + const step = stepSeconds[tl.step]; + const n = tl.times.length; + if (n > 1 && tl.times[n - 1] + step > Date.now() / 1000) { + return { ...tl, times: tl.times.slice(0, -1), series: tl.series.map((x) => ({ ...x, values: x.values.slice(0, -1) })) }; + } + return tl; +} + +function filterRow(since) { + return h("div", { class: "filter-row", role: "group", "aria-label": "Time range" }, + h("span", { class: "muted" }, "Range"), + h("div", { class: "segmented" }, ranges.map(([k, label]) => + h("a", { href: "#/stats?since=" + k, class: k === since ? "active" : "", "aria-current": k === since ? "true" : null, title: "last " + label }, k)))); +} + +function tile(label, value, sub) { + return h("div", { class: "card stat" }, h("div", { class: "label" }, label), h("div", { class: "value big" }, value), h("div", { class: "sub" }, sub)); +} + +function listCard(title, subtitle, body) { + return h("section", { class: "panel" }, h("h2", null, title), subtitle ? h("div", { class: "muted small list-sub" }, subtitle) : null, body); +} + +function pct(r) { + const p = r * 100; + return (p < 10 ? p.toFixed(1) : Math.round(p)) + "%"; +} + +function stepName(step) { + return { "1m": "minute", "5m": "5 minutes", "15m": "15 minutes", "1h": "hour", "6h": "6 hours", "1d": "day" }[step] || step; +} + +function viewLabel(k) { + return k === "_default" ? "(no view)" : k; +} + +function disabledPanel() { + return h("div", { class: "panel" }, + h("h2", null, "Turn on query statistics"), + h("p", null, "Jarl can show how many queries named answers over time, the busiest hours, the most queried names and the clients asking most. " + + "It is off by default. To turn it on, add this to /etc/jarl/jarl.yaml on the server and restart jarl (sudo systemctl restart jarl):"), + h("pre", { class: "code" }, "stats:\n enabled: true"), + h("p", { class: "muted" }, "Jarl then makes named publish its counters on a local statistics channel and log responses to /var/log/named, and keeps aggregates " + + "(never individual queries) in a separate database, by default for 7 days per minute, 90 days per hour and 2 years per day. See docs/stats.md.")); +} diff --git a/internal/web/static/assets/style.css b/internal/web/static/assets/style.css index 1cf9587..6fd502e 100644 --- a/internal/web/static/assets/style.css +++ b/internal/web/static/assets/style.css @@ -232,3 +232,114 @@ button:disabled { opacity: 0.5; cursor: not-allowed; } .form-grid .help { grid-column: 1; } header.top form.search input { width: 140px; } } + +/* ---- Statistics charts. Colors from the validated reference palette + (categorical slots 1-3, sequential blue), checked against this UI's + panel surfaces in both themes. */ +:root { + --series-1: #2a78d6; + --series-2: #eb6834; + --series-3: #1baf7a; + --chart-grid: #eceef2; + --chart-axis: #c9cfd8; + /* Sequential ramp, low to high (blue 100 -> 700). */ + --heat-0: #cde2fb; --heat-1: #9ec5f4; --heat-2: #6da7ec; --heat-3: #3987e5; + --heat-4: #256abf; --heat-5: #184f95; --heat-6: #0d366b; +} +@media (prefers-color-scheme: dark) { + :root:not([data-theme="light"]) { + --series-1: #3987e5; + --series-2: #d95926; + --series-3: #199e70; + --chart-grid: #272c34; + --chart-axis: #3a414d; + /* In dark, low values recede into the surface: the ramp runs dark -> light. */ + --heat-0: #0d366b; --heat-1: #184f95; --heat-2: #256abf; --heat-3: #3987e5; + --heat-4: #6da7ec; --heat-5: #9ec5f4; --heat-6: #cde2fb; + } +} +:root[data-theme="dark"] { + --series-1: #3987e5; + --series-2: #d95926; + --series-3: #199e70; + --chart-grid: #272c34; + --chart-axis: #3a414d; + --heat-0: #0d366b; --heat-1: #184f95; --heat-2: #256abf; --heat-3: #3987e5; + --heat-4: #6da7ec; --heat-5: #9ec5f4; --heat-6: #cde2fb; +} + +.refreshing { opacity: 0.6; transition: opacity 0.2s; } +.filter-row { display: flex; align-items: center; gap: 10px; flex-wrap: wrap; margin-bottom: 12px; } +.segmented { display: inline-flex; border: 1px solid var(--border); border-radius: var(--radius); overflow: hidden; background: var(--panel); } +.segmented a { padding: 4px 12px; color: var(--text); border-right: 1px solid var(--border); text-decoration: none; font-variant-numeric: tabular-nums; } +.segmented a:last-child { border-right: none; } +.segmented a:hover { background: var(--info-soft); } +.segmented a.active { background: var(--accent); color: var(--accent-text); font-weight: 600; } +.card.stat .value.big { font-size: 26px; font-weight: 600; line-height: 1.2; } + +.chart-card { margin: 0 0 14px; } +.chart-head { display: flex; align-items: flex-start; gap: 12px; flex-wrap: wrap; margin-bottom: 8px; } +.chart-head .grow { flex: 1; min-width: 200px; } +.chart-head h2 { margin: 0; font-size: 16px; } +.chart-grid { display: grid; grid-template-columns: repeat(auto-fill, minmax(320px, 1fr)); gap: 0 14px; } +.chart-grid > .panel h2 { margin: 0; font-size: 16px; } +.list-sub { margin: 2px 0 8px; } + +.chart { position: relative; outline: none; } +.chart:focus-visible { box-shadow: 0 0 0 2px var(--accent); border-radius: var(--radius); } +.chart svg { display: block; overflow: visible; } +.chart .grid { stroke: var(--chart-grid); stroke-width: 1; } +.chart .axis { stroke: var(--chart-axis); stroke-width: 1; } +.chart .tick, .chart .end-label { fill: var(--muted); font-size: 11px; font-variant-numeric: tabular-nums; } +.chart .end-label { fill: var(--text); } +.chart .line { fill: none; stroke-width: 2; stroke-linejoin: round; stroke-linecap: round; } +.chart .area { stroke: none; fill-opacity: 0.1; } +.chart .dot { stroke: var(--panel); stroke-width: 2; } +.chart .crosshair { stroke: var(--muted); stroke-width: 1; } +.chart .hit { fill: transparent; cursor: crosshair; } +.chart .s1, .key.s1 { stroke: var(--series-1); } +.chart .s2, .key.s2 { stroke: var(--series-2); } +.chart .s3, .key.s3 { stroke: var(--series-3); } +.chart .area.s1, .chart .dot.s1 { fill: var(--series-1); } +.chart .area.s2, .chart .dot.s2 { fill: var(--series-2); } +.chart .area.s3, .chart .dot.s3 { fill: var(--series-3); } +.key.line { display: inline-block; width: 14px; height: 0; border-top: 2px solid; vertical-align: middle; margin-right: 6px; } +.key.line.s1 { border-color: var(--series-1); } +.key.line.s2 { border-color: var(--series-2); } +.key.line.s3 { border-color: var(--series-3); } +.chart-legend { list-style: none; display: flex; gap: 14px; margin: 2px 0 0; padding: 0; font-size: 13px; color: var(--text); flex-wrap: wrap; } + +.chart-tip { position: absolute; z-index: 5; pointer-events: none; background: var(--panel); border: 1px solid var(--border); border-radius: var(--radius); + box-shadow: 0 4px 16px rgba(0, 0, 0, 0.16); padding: 6px 10px; font-size: 13px; white-space: nowrap; } +.chart-tip .tip-head { color: var(--muted); font-size: 12px; margin-bottom: 2px; } +.chart-tip .tip-row strong { font-variant-numeric: tabular-nums; } +.chart-table .scroll, .chart-table .table-wrap { max-height: 360px; overflow: auto; } +td.num, th.num { text-align: right; font-variant-numeric: tabular-nums; } + +.heatmap-wrap { position: relative; } +.heatmap { display: grid; grid-template-columns: 36px repeat(24, minmax(10px, 1fr)); gap: 2px; outline: none; } +.heatmap:focus-visible { box-shadow: 0 0 0 2px var(--accent); } +.hm-corner, .hm-col, .hm-row { font-size: 11px; color: var(--muted); font-variant-numeric: tabular-nums; } +.hm-row { display: flex; align-items: center; } +.hm-cell { height: 22px; border-radius: 3px; } +.hm-cell:hover, .hm-cell:focus { outline: 2px solid var(--text); outline-offset: -1px; } +.hm-cell.empty, .hm-swatch.empty { background: transparent; box-shadow: inset 0 0 0 1px var(--chart-grid); } +.heat-0 { background: var(--heat-0); } .heat-1 { background: var(--heat-1); } .heat-2 { background: var(--heat-2); } +.heat-3 { background: var(--heat-3); } .heat-4 { background: var(--heat-4); } .heat-5 { background: var(--heat-5); } +.heat-6 { background: var(--heat-6); } +.hm-scale { display: flex; align-items: center; gap: 2px; margin-top: 10px; flex-wrap: wrap; } +.hm-scale .muted { margin: 0 6px; } +.hm-swatch { display: inline-block; width: 18px; height: 10px; border-radius: 2px; } + +.bar-list { list-style: none; margin: 0; padding: 0; } +.bar-list li { padding: 4px 0; } +.bar-text { display: flex; gap: 8px; justify-content: space-between; font-size: 13px; } +.bar-label { overflow: hidden; text-overflow: ellipsis; white-space: nowrap; font-family: var(--mono); font-size: 12.5px; min-width: 0; } +.bar-value { white-space: nowrap; font-variant-numeric: tabular-nums; } +.bar-track { height: 6px; margin-top: 3px; } +.bar-fill { height: 6px; background: var(--series-1); border-radius: 0 3px 3px 0; min-width: 2px; } +@media (max-width: 700px) { + .heatmap { grid-template-columns: 30px repeat(24, minmax(6px, 1fr)); gap: 1px; } + .hm-cell { height: 16px; } + .chart-grid { grid-template-columns: 1fr; } +} diff --git a/scripts/e2e.sh b/scripts/e2e.sh index ef65f82..064865f 100755 --- a/scripts/e2e.sh +++ b/scripts/e2e.sh @@ -80,7 +80,9 @@ $TTL 86400 @ IN NS ns1.adbraun.test. 20 IN PTR nas.adbraun.test. EOF -$NAMED -c $E/legacy/named.conf -g -n 1 > $E/named.log 2>&1 & +# -f like the Debian unit (-g would send all logging, including the +# statistics response log, to stderr). +$NAMED -c $E/legacy/named.conf -f -n 1 > $E/named.log 2>&1 & NAMED_PID=$! for i in $(seq 50); do $RNDC -k $E/legacy/rndc.key -s 127.0.0.1 -p $CTL status >/dev/null 2>&1 && break; sleep 0.2; done