fix(stats): a failed DNS lookup no longer reaches the log as a healthy row

dnstrack.QueryEvent carries Failed and Error; stats.LogEntry carried neither.
A SERVFAIL, a timeout, a loopback or a rejected-cached lookup was therefore
written into the query log with action "pass" — or, when the resolver that
timed out had a detour, with the flow-coloured "proxy" — blocked=false, and
nothing anywhere saying no answer was produced. The daemon already knew, one
event at a time: TotalStats.Failed is counted from that very fact in the same
function. The row threw it away, so the aggregate said "N failed" while every
row said everything was fine.

LogEntry gains two fields:

  Status — closed vocabulary, "answered" | "failed" | "" (NOT RECORDED), same
    discipline as OutboundKind/RuleKind. It is a separate axis rather than a
    fourth Action value because Action says WHICH PATH the lookup took: a query
    that went out through a detour and then timed out is action=proxy AND
    status=failed, and folding the two would erase the one fact that says
    whether the tunnel is what broke. It is also what an old panel would have
    silently mapped back onto "pass" through its own open fallback.
  Error — the producer's own cause text, verbatim, meaningful only when
    Status=="failed". No grading is invented on top: three of the four causes
    are fixed literals ("loopback", "rejected (cached)", "rejected") and the
    fourth is the transport's err.Error(), which cannot be classified without
    guessing. "failed" with an empty Error is honest and reachable — the lookup
    failed and the cause was not recorded. What IS derivable stays derivable:
    Rcode separates "no response at all" (-1) from "the server refused".

queryStatus is a closed POSITIVE list over the sources a producer emits; an
unlisted or zero Source falls to "" (not recorded), never to "answered". The
aggregate is untouched: blocked/failed are computed once in handleEvent and the
row is labelled from those same two values, so the counter and the row can
never disagree and nothing is counted twice.

Cost: LogEntry 152 -> 184 B on 64-bit (+6.4 KB at the default 200-row ring).
Status is a package constant, so its body costs nothing; Error is interned in
its OWN table (maxErrKeys=128, clamped to 160 B) rather than the rule table,
because the transport's error text embeds the queried name and a flood of
distinct causes would otherwise keep clearing the routing-text table.

Tests: every assertion mutation-checked, and the control is three-state — the
same instrument separates answered from blocked from failed, with the
aggregate pinned to identical totals across the change.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01BHw89tdWddzhjUc4bAH4tS
This commit is contained in:
2026-07-27 11:12:59 +03:00
co-authored by Claude Opus 5
parent 735aa5428f
commit a794fbe374
4 changed files with 611 additions and 9 deletions
+11 -7
View File
@@ -126,17 +126,20 @@ func (q LogQuery) normalized() LogQuery {
// matchLog reports whether one query-log row satisfies q's text filter (always true when
// there is no filter). The searched fields are exactly:
//
// domain, qtype, server, action, device, outbound
// domain, qtype, server, action, device, outbound, error
//
// i.e. every TEXTUAL field a row carries about WHAT was asked, WHO asked, WHO answered and
// WHERE it went out. Deliberately NOT searched:
// i.e. every TEXTUAL field a row carries about WHAT was asked, WHO asked, WHO answered,
// WHERE it went out and WHY it failed. Error is searched for the same reason ConnLogEntry
// .Rule is (matchConn): it is free cause text, not vocabulary, so "show me every lookup
// that timed out" is a substring an operator can actually type. Deliberately NOT searched:
//
// seq / unix / time / rcode — numbers and timestamps, where a substring is meaningless
// ("12" matching a clock is noise, not a result);
// blocked — a boolean, already its own filter in the UI;
// outbound_kind — a fixed vocabulary word ("default", "local"), so searching
// it would silently make q=default match every default-egress
// row while the operator was looking for a tag named that.
// outbound_kind / status — fixed vocabulary words ("default", "local", "failed"), so
// searching them would silently make q=default match every
// default-egress row while the operator was looking for a
// tag named that.
//
// The list is POSITIVE and CLOSED: a field added to LogEntry is not searched until it is
// named here, so no field is ever searched by accident.
@@ -149,7 +152,8 @@ func (q LogQuery) matchLog(e LogEntry) bool {
containsFold(e.Server, q.Text) ||
containsFold(e.Action, q.Text) ||
containsFold(e.Device, q.Text) ||
containsFold(e.Outbound, q.Text)
containsFold(e.Outbound, q.Text) ||
containsFold(e.Error, q.Text)
}
// matchConn reports whether one connection-log row satisfies q's text filter (always true
+56 -1
View File
@@ -3,6 +3,7 @@ package stats
import (
"sort"
"strings"
"unicode/utf8"
"github.com/miekg/dns"
@@ -34,10 +35,64 @@ func classifyFailed(ev dnstrack.QueryEvent) bool {
return ev.Failed || ev.Source == dnstrack.SourceFailed
}
// queryStatus maps a resolution to the LogEntry.Status vocabulary — the OUTCOME axis,
// which is not the same question Action answers. blocked and failed are the values
// handleEvent already computed for the totals and are passed IN rather than re-derived,
// so a row can never land in one bucket while its counter lands in another.
//
// # Why the switch is closed and positive
//
// Every Source a producer emits today is listed, and each is listed because that emit
// site has a response in hand (dns/client_log.go: exchanged/cached/optimistic/refreshed
// all carry a *dns.Msg; filtered carries the synthesized answer). An unlisted or zero
// Source falls through to StatusUnrecorded — "we don't know" — which is the recoverable
// side: the panel shows an unknown outcome instead of claiming an answer that no
// producer said was produced. An open `default: return StatusAnswered` would do the
// exact opposite, and is the shape of the defect this field exists to close.
func queryStatus(ev dnstrack.QueryEvent, blocked, failed bool) string {
// Order mirrors handleEvent's totals switch exactly: a filter verdict outranks a
// failure flag, so blocked/failed/answered stay mutually exclusive on the row for
// the same reason Blocked/Failed/Allowed do in TotalStats.
if blocked {
return StatusAnswered // a synthesized block IS an answer; Action/Blocked say whose
}
if failed {
return StatusFailed
}
switch ev.Source {
case dnstrack.SourceExchanged, dnstrack.SourceCached, dnstrack.SourceOptimistic,
dnstrack.SourceRefreshed, dnstrack.SourceFiltered:
return StatusAnswered
}
return StatusUnrecorded
}
// clampErrText bounds one failure cause to maxErrTextLen bytes. A clamped value ends in
// "…" (never a bare cut), and the cut is taken back to a UTF-8 boundary so truncation
// cannot emit half a rune. Returns s unchanged when it already fits — the case every
// real cause takes, at zero allocation.
func clampErrText(s string) string {
if len(s) <= maxErrTextLen {
return s
}
cut := maxErrTextLen - len("…")
for cut > 0 && !utf8.RuneStart(s[cut]) {
cut--
}
return s[:cut] + "…"
}
// action maps a resolution to the panel QueryLog tag vocabulary (block|proxy|pass).
// "block" means blocked by the DNS filter (classifyBlocked); a query that egressed
// via a real proxy outbound is "proxy"; everything else (cached, direct, local
// resolver — including failed lookups, which keep their Rcode) is "pass".
// resolver) is "pass".
//
// It says WHICH PATH the lookup took and nothing about whether it succeeded — a query
// that went out over a detour and then timed out is "proxy" here and StatusFailed in
// LogEntry.Status. That split is deliberate: before Status existed, a failure inherited
// whichever of "pass"/"proxy" its resolver's binding produced and was drawn as a healthy
// row, and folding failure in as a fourth value here would have thrown away the very
// fact that says whether the tunnel is what broke.
func action(blocked bool, outbound []string) string {
if blocked {
return "block"
+419
View File
@@ -0,0 +1,419 @@
package stats
import (
"encoding/json"
"strings"
"testing"
"unicode/utf8"
"unsafe"
"github.com/sagernet/sing-box/common/dnstrack"
)
// unsafeStringData is the address of a string's backing bytes — the only way to tell a
// SHARED copy from an equal one, which is exactly what interning claims to produce.
func unsafeStringData(s string) uintptr {
if s == "" {
return 0
}
return uintptr(unsafe.Pointer(unsafe.StringData(s)))
}
// The defect these tests exist for: a DNS lookup that FAILED (timeout, SERVFAIL,
// resolver refusal) was written into the query log indistinguishable from a
// successful one — action "pass" (or, on a resolver with a detour, "proxy"),
// blocked=false, and no field anywhere saying it produced no answer. The daemon knew:
// dnstrack.QueryEvent carries Failed/Error and TotalStats.Failed was already counted
// from it. The row threw the fact away.
//
// Every test below therefore checks the ROW, not the aggregate, and each one is
// written so that it can distinguish all THREE outcomes — answered, blocked, failed —
// rather than just "not the one I broke".
// failedEvtCause is failedEvt with the cause text the producer really attaches
// (dns/client.go emitFailedQuery), and an optional resolver detour so a failure that
// egressed through the tunnel can be built.
func failedEvtCause(domain, cause string, outbound ...string) dnstrack.QueryEvent {
ev := failedEvt(domain)
ev.Error = cause
if len(outbound) > 0 {
ev.Outbound = outbound
}
return ev
}
// TestQueryStatusClosedPositiveList pins the parse itself: every Source a producer
// emits maps to a NAMED outcome, and anything else falls to StatusUnrecorded rather
// than to "answered". The unknown-source rows are the point — an open default would
// pass every other case in this table and still call an unrecognised event healthy.
func TestQueryStatusClosedPositiveList(t *testing.T) {
cases := []struct {
name string
ev dnstrack.QueryEvent
blocked bool
failed bool
want string
}{
{"exchanged", evt("a.example", 0), false, false, StatusAnswered},
{"cached", dnstrack.QueryEvent{Domain: "a", Source: dnstrack.SourceCached}, false, false, StatusAnswered},
{"optimistic", dnstrack.QueryEvent{Domain: "a", Source: dnstrack.SourceOptimistic}, false, false, StatusAnswered},
{"refreshed", dnstrack.QueryEvent{Domain: "a", Source: dnstrack.SourceRefreshed}, false, false, StatusAnswered},
{"organic-nxdomain-is-an-answer", evt("typo.exmaple", rcodeNXDOMAIN), false, false, StatusAnswered},
{"filtered-block-is-an-answer", filteredEvt("ads.example"), true, false, StatusAnswered},
{"failed", failedEvt("down.example"), false, true, StatusFailed},
{"failed-flag-with-no-source", dnstrack.QueryEvent{Domain: "a", Failed: true}, false, true, StatusFailed},
// The two that an open default would get wrong:
{"unknown-source", dnstrack.QueryEvent{Domain: "a", Source: dnstrack.Source("teleported")}, false, false, StatusUnrecorded},
{"zero-source", dnstrack.QueryEvent{Domain: "a"}, false, false, StatusUnrecorded},
}
for _, c := range cases {
if got := queryStatus(c.ev, c.blocked, c.failed); got != c.want {
t.Errorf("%s: queryStatus = %q, want %q", c.name, got, c.want)
}
}
}
// TestQueryStatusMatchesTotalsExclusivity pins the ordering: a filter verdict outranks
// a failure flag on the ROW exactly as it does in the totals switch, so one event can
// never be counted Blocked while its row reads "failed".
func TestQueryStatusMatchesTotalsExclusivity(t *testing.T) {
ev := filteredEvt("ads.example")
ev.Failed = true // a contradictory producer; handleEvent resolves it blocked-first
if got := queryStatus(ev, true, false); got != StatusAnswered {
t.Fatalf("blocked event with a stray Failed flag: status = %q, want %q", got, StatusAnswered)
}
}
// rowsByDomain reads the whole query-log ring back, keyed by domain.
func rowsByDomain(t *testing.T, a *Aggregator) map[string]LogEntry {
t.Helper()
out := map[string]LogEntry{}
for _, r := range a.Queries(LogQuery{Limit: 100}) {
out[r.Domain] = r
}
return out
}
// TestQueryLogRowTellsThreeStatesApart is THE CONTROL for this whole change: one
// aggregator, one instrument (the query-log row), three genuinely different inputs —
// an allowed lookup, a filter block, and a resolver failure. It asserts each row is
// distinguishable from BOTH others, so an instrument that is blind to failure (the
// defect) and an instrument that calls everything a failure both fail it.
func TestQueryLogRowTellsThreeStatesApart(t *testing.T) {
a := New(nil, nil)
a.handleEvent(evt("ok.example", 0))
a.handleEvent(filteredEvt("ads.example"))
a.handleEvent(failedEvtCause("down.example", "i/o timeout"))
rows := rowsByDomain(t, a)
if len(rows) != 3 {
t.Fatalf("want 3 rows, got %d: %+v", len(rows), rows)
}
want := map[string]struct {
status string
action string
blocked bool
cause string
}{
"ok.example": {StatusAnswered, "pass", false, ""},
"ads.example": {StatusAnswered, "block", true, ""},
"down.example": {StatusFailed, "pass", false, "i/o timeout"},
}
for dom, w := range want {
r := rows[dom]
if r.Status != w.status {
t.Errorf("%s: Status = %q, want %q", dom, r.Status, w.status)
}
if r.Action != w.action {
t.Errorf("%s: Action = %q, want %q", dom, r.Action, w.action)
}
if r.Blocked != w.blocked {
t.Errorf("%s: Blocked = %v, want %v", dom, r.Blocked, w.blocked)
}
if r.Error != w.cause {
t.Errorf("%s: Error = %q, want %q", dom, r.Error, w.cause)
}
}
// The three must be MUTUALLY distinguishable, not merely each equal to a literal:
// before the fix, the failed row and the allowed row were byte-identical on every
// field a reader shows (same action, same blocked, same absence of a cause).
ok, blk, fail := rows["ok.example"], rows["ads.example"], rows["down.example"]
if ok.Status == fail.Status {
t.Errorf("allowed and failed rows carry the SAME status %q — a failure is drawn as a healthy query", ok.Status)
}
if blk.Status == fail.Status {
t.Errorf("blocked and failed rows carry the same status %q", blk.Status)
}
if ok.Action == blk.Action {
t.Errorf("allowed and blocked rows carry the same action %q — the control itself is broken", ok.Action)
}
}
// TestFailedRowCarriesVerbatimCause walks the four causes dns/client.go actually emits
// and pins that each reaches the row UNCHANGED — no classification, no grading, no
// invented vocabulary. It also pins the two facts that ARE derivable: the rcode
// separates "no response at all" (RcodeNoAnswer) from "the server refused", and a
// producer that recorded no cause yields Status=failed with Error="" — an honest
// "failed, cause not recorded" rather than a guess.
func TestFailedRowCarriesVerbatimCause(t *testing.T) {
cases := []struct {
domain string
cause string
rcode int32
}{
{"loop.example", "loopback", dnstrack.RcodeNoAnswer},
{"rdrc.example", "rejected (cached)", dnstrack.RcodeNoAnswer},
{"net.example", "dial udp 1.1.1.1:53: i/o timeout", dnstrack.RcodeNoAnswer},
{"servfail.example", "rejected", 2},
{"nocause.example", "", dnstrack.RcodeNoAnswer},
}
a := New(nil, nil)
for _, c := range cases {
ev := failedEvtCause(c.domain, c.cause)
ev.Rcode = c.rcode
a.handleEvent(ev)
}
rows := rowsByDomain(t, a)
for _, c := range cases {
r, ok := rows[c.domain]
if !ok {
t.Fatalf("%s: no row", c.domain)
}
if r.Status != StatusFailed {
t.Errorf("%s: Status = %q, want %q", c.domain, r.Status, StatusFailed)
}
if r.Error != c.cause {
t.Errorf("%s: Error = %q, want the producer's own text %q", c.domain, r.Error, c.cause)
}
if r.Rcode != c.rcode {
t.Errorf("%s: Rcode = %d, want %d", c.domain, r.Rcode, c.rcode)
}
}
}
// TestAnsweredRowCarriesNoCause pins the other half of the Error contract: a row that
// did not fail has no cause text, by construction. Without it "Error != ”" would be a
// useless test for failure.
func TestAnsweredRowCarriesNoCause(t *testing.T) {
a := New(nil, nil)
// A producer that sets a stray Error on a successful event must not leak it.
ev := evt("ok.example", 0)
ev.Error = "should not appear"
a.handleEvent(ev)
r := rowsByDomain(t, a)["ok.example"]
if r.Status != StatusAnswered {
t.Fatalf("Status = %q, want %q", r.Status, StatusAnswered)
}
if r.Error != "" {
t.Errorf("Error = %q on an answered row, want \"\"", r.Error)
}
}
// TestFailedThroughDetourKeepsBothAxes is why failure is NOT a fourth Action value: a
// lookup that went out over a proxy detour and then timed out must still say it went
// over the proxy. Folding it into Action would erase the one fact that tells the
// operator whether the tunnel is what broke — and, before the fix, that same row was
// drawn as a healthy "proxy".
func TestFailedThroughDetourKeepsBothAxes(t *testing.T) {
a := New(nil, nil)
a.handleEvent(failedEvtCause("via-node.example", "i/o timeout", "us-node-3"))
r := rowsByDomain(t, a)["via-node.example"]
if r.Action != "proxy" {
t.Errorf("Action = %q, want \"proxy\" — the path a failed lookup took is still a fact", r.Action)
}
if r.Status != StatusFailed {
t.Errorf("Status = %q, want %q", r.Status, StatusFailed)
}
if r.OutboundKind != DNSOutDetour || r.Outbound != "us-node-3" {
t.Errorf("outbound = %q/%q, want detour/us-node-3", r.OutboundKind, r.Outbound)
}
}
// TestTotalsFailedUnchangedByRowCapture is the AGGREGATE CONTROL. TotalStats.Failed was
// already computed from QueryEvent.Failed before the row learned about it; this pins
// that the row is labelled from the SAME fact and that nothing is counted twice — the
// three exclusive counters still sum to Queries, and the number of rows reading
// "failed" equals the counter exactly.
func TestTotalsFailedUnchangedByRowCapture(t *testing.T) {
a := New(nil, nil)
// A fixed mixed set: 3 answered, 2 blocked, 4 failed.
a.handleEvent(evt("one.example", 0))
a.handleEvent(evt("two.example", rcodeNXDOMAIN)) // organic NXDOMAIN — an answer
a.handleEvent(dnstrack.QueryEvent{Domain: "three.example", QueryType: 1, Source: dnstrack.SourceCached, Client: lanClient})
a.handleEvent(filteredEvt("ads.example"))
a.handleEvent(filteredEvt("tracker.example"))
a.handleEvent(failedEvtCause("d1.example", "loopback"))
a.handleEvent(failedEvtCause("d2.example", "rejected"))
a.handleEvent(failedEvtCause("d3.example", "i/o timeout", "us-node-3"))
a.handleEvent(dnstrack.QueryEvent{Domain: "d4.example", QueryType: 1, Failed: true, Client: lanClient})
snap := a.Snapshot()
// The pre-change expectation, spelled out as literals so a regression in the
// aggregate is caught here and not explained away by the new field.
if snap.Totals.Queries != 9 || snap.Totals.Blocked != 2 || snap.Totals.Failed != 4 || snap.Totals.Allowed != 3 {
t.Fatalf("totals = %+v, want {Queries:9 Blocked:2 Failed:4 Allowed:3}", snap.Totals)
}
if got := snap.Totals.Blocked + snap.Totals.Failed + snap.Totals.Allowed; got != snap.Totals.Queries {
t.Errorf("the three counters sum to %d, want Queries=%d — a fact is being counted twice or dropped", got, snap.Totals.Queries)
}
var failedRows, answeredRows, unrecordedRows int
for _, r := range a.Queries(LogQuery{Limit: 100}) {
switch r.Status {
case StatusFailed:
failedRows++
case StatusAnswered:
answeredRows++
default:
unrecordedRows++
}
}
if uint64(failedRows) != snap.Totals.Failed {
t.Errorf("%d rows say failed but TotalStats.Failed = %d — the row and the counter disagree about the same events", failedRows, snap.Totals.Failed)
}
if uint64(answeredRows) != snap.Totals.Blocked+snap.Totals.Allowed {
t.Errorf("%d answered rows, want %d (blocked+allowed)", answeredRows, snap.Totals.Blocked+snap.Totals.Allowed)
}
// d4 has Failed=true and no Source: it must be FAILED, not unrecorded. A producer
// that sets the flag is believed.
if unrecordedRows != 0 {
t.Errorf("%d rows landed on the unrecorded outcome; every event in this set has a recorded one", unrecordedRows)
}
}
// TestFailureCauseInternedAndClamped pins the memory contract: identical causes share
// one backing string, the cause is bounded, a clamped one is visibly clamped, and the
// error table is SEPARATE from the rule/outbound table so a flood of distinct causes
// cannot evict routing text.
func TestFailureCauseInternedAndClamped(t *testing.T) {
a := New(nil, nil)
// 1. Interning: two events built from independently allocated (but equal) strings
// must yield rows whose Error shares one backing array.
c1 := strings.Join([]string{"dial", "udp", "1.1.1.1:53:", "i/o", "timeout"}, " ")
c2 := strings.Join([]string{"dial", "udp", "1.1.1.1:53:", "i/o", "timeout"}, " ")
a.handleEvent(failedEvtCause("a.example", c1))
a.handleEvent(failedEvtCause("b.example", c2))
rows := rowsByDomain(t, a)
ra, rb := rows["a.example"], rows["b.example"]
// Guard against a VACUOUS pass: with no cause on the row at all, "equal" and
// "shared" are both trivially true and the two checks below would prove nothing.
if ra.Error == "" {
t.Fatalf("no cause reached the row; the interning check below would be vacuous")
}
if ra.Error != rb.Error {
t.Fatalf("equal causes produced different text: %q vs %q", ra.Error, rb.Error)
}
if unsafeStringData(ra.Error) != unsafeStringData(rb.Error) {
t.Errorf("equal causes are not interned: two copies of %q are stored", ra.Error)
}
// 2. Clamping: an over-long cause is cut to maxErrTextLen, ends in the ellipsis, and
// stays valid UTF-8.
long := strings.Repeat("ы", 500) + "TAIL"
a.handleEvent(failedEvtCause("long.example", long))
rl := rowsByDomain(t, a)["long.example"]
if len(rl.Error) > maxErrTextLen {
t.Errorf("clamped cause is %d bytes, want <= %d", len(rl.Error), maxErrTextLen)
}
if !strings.HasSuffix(rl.Error, "…") {
t.Errorf("clamped cause %q does not end in the truncation marker", rl.Error)
}
if !utf8.ValidString(rl.Error) {
t.Errorf("clamped cause is not valid UTF-8: %q", rl.Error)
}
if strings.Contains(rl.Error, "TAIL") {
t.Errorf("clamp kept the tail of an over-long cause: %q", rl.Error)
}
// A cause that already fits is returned untouched.
if got := clampErrText("i/o timeout"); got != "i/o timeout" {
t.Errorf("clampErrText mangled a short cause: %q", got)
}
// 3. Table separation: flood the error table past its cap and show the rule table
// (which holds the outbound tags of the same rows) is untouched.
a.mu.Lock()
a.ruleText["keep-me"] = "keep-me"
a.mu.Unlock()
// The flood must exceed the RULE table's cap, not just the error table's: at
// maxErrKeys*3 (=384) a shared table would still be under maxRuleKeys (=512) and
// would never clear, so the test would pass on the very mutation it exists to catch.
for i := 0; i < maxRuleKeys*2; i++ {
a.handleEvent(failedEvtCause("flood.example", "unique cause "+strings.Repeat("x", i%50)+string(rune('a'+i%26))+itoaSmall(i), "us-node-3"))
}
a.mu.Lock()
_, kept := a.ruleText["keep-me"]
errKeys := len(a.errText)
a.mu.Unlock()
if !kept {
t.Error("a flood of failure causes cleared the RULE intern table — the two tables are shared")
}
if errKeys > maxErrKeys {
t.Errorf("error intern table holds %d entries, want <= %d", errKeys, maxErrKeys)
}
}
// itoaSmall is a dependency-free small-int formatter for the flood above.
func itoaSmall(n int) string {
if n == 0 {
return "0"
}
var b []byte
for n > 0 {
b = append([]byte{byte('0' + n%10)}, b...)
n /= 10
}
return string(b)
}
// TestOldPersistedRowHasUnrecordedOutcome pins the wire contract the persistent
// (bbolt) backend depends on: a row stored by a build that predates this field decodes
// with Status == StatusUnrecorded — "we don't know" — and never as a successful query.
// The failed row round-trips with its cause; an answered row omits the empty cause.
func TestOldPersistedRowHasUnrecordedOutcome(t *testing.T) {
var old LogEntry
if err := json.Unmarshal([]byte(`{"domain":"legacy.example","action":"pass","rcode":0}`), &old); err != nil {
t.Fatalf("decode: %v", err)
}
if old.Status != StatusUnrecorded {
t.Errorf("a pre-field row decoded to Status %q, want %q (not recorded)", old.Status, StatusUnrecorded)
}
blob, err := json.Marshal(LogEntry{Domain: "d.example", Status: StatusFailed, Error: "i/o timeout"})
if err != nil {
t.Fatalf("encode: %v", err)
}
var back LogEntry
if err := json.Unmarshal(blob, &back); err != nil {
t.Fatalf("decode: %v", err)
}
if back.Status != StatusFailed || back.Error != "i/o timeout" {
t.Errorf("round-trip lost the outcome: %+v", back)
}
if !strings.Contains(string(blob), `"status":"failed"`) {
t.Errorf("wire form lacks the status key: %s", blob)
}
answered, err := json.Marshal(LogEntry{Domain: "d.example", Status: StatusAnswered})
if err != nil {
t.Fatalf("encode: %v", err)
}
if strings.Contains(string(answered), `"error"`) {
t.Errorf("an answered row carries an error key: %s", answered)
}
}
// TestLogFilterMatchesFailureCause pins that `q=timeout` finds the rows that timed out
// — the reason Error is in matchLog's positive list — and that it does not match rows
// that did not.
func TestLogFilterMatchesFailureCause(t *testing.T) {
fail := LogEntry{Domain: "down.example", Status: StatusFailed, Error: "dial udp: i/o TIMEOUT"}
ok := LogEntry{Domain: "up.example", Status: StatusAnswered}
if !(LogQuery{Text: "timeout"}).normalized().matchLog(fail) {
t.Error("q=timeout did not match a row whose cause is a timeout")
}
if (LogQuery{Text: "timeout"}).normalized().matchLog(ok) {
t.Error("q=timeout matched a row that did not fail")
}
}
+125 -1
View File
@@ -121,6 +121,31 @@ const (
// else. That is why it produces no DropStats entry.
maxRuleKeys = 512
// maxErrKeys bounds the intern table behind LogEntry.Error, and it is deliberately
// NOT the rule table (maxRuleKeys).
//
// The rule/outbound vocabulary is written by the config: a few dozen values that
// change only on a regeneration. A failure cause is not. Three of the four producers
// emit a fixed literal ("loopback", "rejected (cached)", "rejected"), but the fourth
// hands over the transport's own err.Error(), which on a real failure embeds the
// QUERIED NAME — so a client resolving junk names against a dead upstream mints a
// distinct string per query. Sharing one table would let that flood clear() the rule
// table over and over, re-allocating routing text on the connection-log hot path for
// no reason. Two tables, and the flood is contained in its own.
//
// Overflow clears, exactly like the rule table: the table holds no statistics, only
// shared copies of strings the rows already carry. At maxErrTextLen per entry the
// full table is ~20 KB.
maxErrKeys = 128
// maxErrTextLen clamps one LogEntry.Error. The cause text is the only row field whose
// length is not bounded by its own grammar (a domain is <=253, a tag is short), and
// part of it can be attacker-chosen — the queried name appears inside the transport's
// error string. 160 bytes fits every literal cause and every real transport error
// ("dial udp 1.1.1.1:53: i/o timeout" is 32); anything longer is truncated with a
// visible "…" so a clamped cause is never mistaken for the whole one.
maxErrTextLen = 160
// dropLogInterval throttles the "aggregate pruned" notices. Every prune is
// counted in Snapshot.Dropped and so is always visible in the API; the log line
// exists for an operator who is watching logread, and once per aggregate per
@@ -205,7 +230,10 @@ const routerDevice = "router"
// both the D15 blocklist and BlockDoH land here).
// Failed — the resolution produced no usable answer (timeout, loopback,
// SERVFAIL-reject — classifyFailed). NOT a block: nothing decided to
// deny it, the lookup just didn't succeed.
// deny it, the lookup just didn't succeed. The SAME fact is carried on
// every row it came from as LogEntry.Status == StatusFailed, computed
// once in handleEvent and shared, so the counter and the log can never
// disagree about one event.
// Allowed — everything else: a real answer from a resolver, including an
// upstream's own organic NXDOMAIN.
type TotalStats struct {
@@ -451,6 +479,11 @@ type NodeHealthStat struct {
// LogEntry is one row of the live query log (also the /api/stats/log element).
//
// Status/Error answer "DID this lookup produce an answer at all" — a question none of
// the other fields answer, and the reason a SERVFAIL or a timeout used to be written
// here indistinguishable from a success. Read Status FIRST: it is what separates a
// failed lookup from an answered one and from a row whose outcome was never recorded.
//
// OutboundKind/Outbound answer "WHERE did this lookup go out" — the same question
// ConnLogEntry.RuleKind/Rule/Chain answer for a connection, and for the same reason: a
// "site does not open" report is resolved by seeing which path the name resolution took,
@@ -476,6 +509,40 @@ type LogEntry struct {
// builds that predate client attribution.
Action string `json:"action"`
Device string `json:"device"`
// Status is the OUTCOME of the resolution: did it produce an answer at all?
// Closed vocabulary — a reader that does not recognise the value must treat it
// as StatusUnrecorded, never as "fine":
//
// StatusAnswered ("answered") — an answer was produced. From an upstream, from
// the cache, or synthesized by the DNS filter (a block is an intended answer,
// not a malfunction — Action/Blocked say which).
// StatusFailed ("failed") — NO usable answer: timeout or network error,
// a resolver rejection (SERVFAIL / the response checker), a loopback, or a
// cached rejection. Same fact TotalStats.Failed counts (classifyFailed),
// carried down to the row it came from.
// StatusUnrecorded ("") — NOT RECORDED. The row was written by a build that
// predates outcome capture (persistent backend, old rows) or by a producer whose
// Source this build does not recognise. It says NOTHING about the outcome.
//
// It is a SEPARATE axis from Action, not a fourth Action value, because the two
// answer different questions and a failure has an answer to both: a lookup that
// went out through a proxy detour and then timed out is Action="proxy" AND
// Status="failed". Folding the failure into Action would erase which path failed —
// the one fact that says whether the tunnel is the problem.
Status string `json:"status"`
// Error is the failure cause EXACTLY as the resolver reported it, with no
// classification applied on top — "loopback", "rejected (cached)", "rejected", or
// the transport's own error text (dns/client.go, the only producer; it is
// QueryEvent.Error verbatim). It is clamped to maxErrTextLen bytes, and a clamped
// value ends in "…" so a truncated cause can never be read as the whole one.
//
// Meaningful ONLY when Status == StatusFailed; "" in every other case. "" WITH
// Status=="failed" is itself honest and possible: the lookup failed and the cause
// was not recorded. Nothing here is ever derived — there is no "timeout" vs
// "servfail" grading, because the producer records free text for the network case
// and only the Rcode separates "no response at all" (dnstrack.RcodeNoAnswer, -1)
// from "the server answered with a refusal" (a real rcode).
Error string `json:"error,omitempty"`
// OutboundKind says HOW TO READ Outbound. Closed vocabulary — a reader that does not
// recognise the value must treat it as DNSOutUnrecorded, never as "no outbound":
//
@@ -526,6 +593,18 @@ const (
DNSOutUnrecorded = ""
)
// The closed vocabulary of LogEntry.Status. See that field's documentation: as with
// RuleKind and OutboundKind, "" is reserved for NOT RECORDED, so a row from a build
// that never captured the outcome can never be read as a successful one.
const (
// StatusAnswered: an answer was produced (upstream, cache, or a filter block).
StatusAnswered = "answered"
// StatusFailed: no usable answer — classifyFailed, the same fact TotalStats.Failed counts.
StatusFailed = "failed"
// StatusUnrecorded: nothing was recorded about this row's outcome.
StatusUnrecorded = ""
)
// Snapshot is the whole aggregated view returned by GET /api/stats.
type Snapshot struct {
// Backend is the EFFECTIVE stats storage backend serving this snapshot:
@@ -711,6 +790,10 @@ type Aggregator struct {
ruleText map[string]string
ruleChains map[string][]string
// errText interns LogEntry.Error the same way, in its own table — see maxErrKeys
// for why it may not share the rule table. Guarded by mu.
errText map[string]string
// nft-derived traffic (refreshed by the poll loop).
devices []DeviceStat
ruleTraffic []RuleStat
@@ -818,6 +901,7 @@ func newAggregatorShared(eng *engine.Engine, logger log.ContextLogger, cfg ...Co
hosts: make(map[string]*hostAgg),
ruleText: make(map[string]string),
ruleChains: make(map[string][]string),
errText: make(map[string]string),
dropLogged: make(map[string]time.Time),
timelineMinutes: tlMin,
timelineUnlimited: tlUnlimited,
@@ -1131,7 +1215,27 @@ func (a *Aggregator) handleEvent(ev dnstrack.QueryEvent) {
// under 50 KB at the cap, and on a real config a handful of resolver detour tags
// (~200 B). On the persistent backend the cost is disk, not RAM: the two JSON keys add
// ~35-45 B to each stored row, which counts against Config.DiskLimitMB.
//
// # And the same accounting for Status/Error
//
// Status and Error are two more string headers: LogEntry 152 -> 184 B on a 64-bit
// target, so +32 B/row again — ring 200 +6.4 KB, ring 5000 +160 KB. Neither ever
// holds a per-row allocation: Status is one of two package-level constants (the
// header points at static data, the body costs nothing at all), and Error is interned
// through errText, bounded at maxErrKeys x maxErrTextLen ~= 20 KB and written only on
// a failed row. On disk the cost is `"status":"answered",` (~20 B) per row plus the
// cause on failures only, since Error is `omitempty`.
outbound, outKind := dnsOutbound(ev)
// Status carries the SAME fact the Failed total above was computed from — `failed`
// is passed in rather than re-derived, so the row and the aggregate can never
// disagree about one event, and nothing is counted twice (the totals switch ran
// once, here we only label). The cause text is written only where it means
// something: a non-failed row's Error is "" by construction, not by convention.
status := queryStatus(ev, blocked, failed)
var cause string
if status == StatusFailed {
cause = a.internErrLocked(ev.Error)
}
entry := LogEntry{
Time: now.Format("15:04:05"),
Unix: now.Unix(),
@@ -1142,6 +1246,8 @@ func (a *Aggregator) handleEvent(ev dnstrack.QueryEvent) {
Server: ev.DNSServer,
Action: action(blocked, ev.Outbound),
Device: a.deviceLabel(ev.Client),
Status: status,
Error: cause,
Outbound: a.internLocked(outbound),
OutboundKind: outKind,
}
@@ -1479,6 +1585,24 @@ func (a *Aggregator) internLocked(s string) string {
return s
}
// internErrLocked returns the shared copy of a failure-cause string, clamping it to
// maxErrTextLen first. Same shape as internLocked but over its OWN bounded table — see
// maxErrKeys for why the two may not be one. Caller holds mu.
func (a *Aggregator) internErrLocked(s string) string {
s = clampErrText(s)
if s == "" {
return ""
}
if got, ok := a.errText[s]; ok {
return got
}
if len(a.errText) >= maxErrKeys {
clear(a.errText)
}
a.errText[s] = s
return s
}
// internChainLocked returns the shared copy of an outbound chain. The tracker owns the
// slice it is given, so a copy is taken on first sight and every later row carrying the
// same chain reuses it. The elements themselves are already shared (each is an