package accesslog import ( "bytes" "encoding/json" "strings" "sync" "testing" "time" "github.com/miekg/dns" ) type syncBuf struct { mu sync.Mutex b bytes.Buffer } func (s *syncBuf) Write(p []byte) (int, error) { s.mu.Lock(); defer s.mu.Unlock(); return s.b.Write(p) } func (s *syncBuf) String() string { s.mu.Lock(); defer s.mu.Unlock(); return s.b.String() } // TestDefaultPolicyLogsOnlyBlockedAndFailed is the policy the deployment runs // with: what was blocked or went wrong, never ordinary answers. func TestDefaultPolicyLogsOnlyBlockedAndFailed(t *testing.T) { l := New(Options{Writer: &syncBuf{}, LogBlocked: true, LogErrors: true}) defer l.Close() for a, want := range map[Action]bool{ ActionBlock: true, ActionRedirect: true, ActionError: true, ActionDrop: true, ActionRefused: true, ActionAllow: false, ActionCached: false, } { if got := l.ShouldLog(a); got != want { t.Errorf("ShouldLog(%s) = %v, want %v", a, got, want) } } } func TestSamplingAndCachedOptIn(t *testing.T) { all := New(Options{Writer: &syncBuf{}, SampleRate: 1}) defer all.Close() if !all.ShouldLog(ActionAllow) || !all.ShouldLog(ActionCached) { t.Error("sample_rate 1 must log ordinary answers") } cached := New(Options{Writer: &syncBuf{}, LogCached: true}) defer cached.Close() if !cached.ShouldLog(ActionCached) || cached.ShouldLog(ActionAllow) { t.Error("log_cached must add cache hits and nothing else") } var nilLogger *Logger if nilLogger.ShouldLog(ActionBlock) { t.Error("a nil logger logs nothing") } nilLogger.Log(Entry{}) // must not panic } func TestLineFormat(t *testing.T) { out := &syncBuf{} l := New(Options{Writer: out, LogBlocked: true}) m := new(dns.Msg) m.SetQuestion("ads.example.com.", dns.TypeAAAA) m.Rcode = dns.RcodeNameError e := Entry{ TS: time.Date(2026, 10, 16, 12, 0, 0, 0, time.UTC), Client: "10.0.0.5", Group: "kids", Action: ActionBlock, Duration: 1500 * time.Microsecond, List: "stevenblack", Protocol: "udp", } e.FromMsg(m) l.Log(e) l.Flush() _ = l.Close() lines := strings.Split(strings.TrimSpace(out.String()), "\n") if len(lines) != 1 { t.Fatalf("got %d lines: %q", len(lines), out.String()) } var got map[string]any if err := json.Unmarshal([]byte(lines[0]), &got); err != nil { t.Fatalf("not JSON: %v", err) } want := map[string]any{ "log": "access", "msg": "query", "client": "10.0.0.5", "client_group": "kids", "name": "ads.example.com.", "qtype": "AAAA", "rcode": "NXDOMAIN", "action": "block", "duration_ms": 1.5, "list": "stevenblack", "protocol": "udp", "time": "2026-10-16T12:00:00Z", } for k, v := range want { if got[k] != v { t.Errorf("%s = %v, want %v", k, got[k], v) } } if _, has := got["level"]; has { t.Error("a constant level key is noise for a log collector") } if _, has := got["upstream"]; has { t.Error("an empty upstream must be omitted") } } // stuck is a log pipe nobody is reading. type stuck struct{ release chan struct{} } func (s stuck) Write(p []byte) (int, error) { <-s.release; return len(p), nil } // TestLoggingNeverBlocksTheQueryPath: a collector that stops reading must cost // dropped lines, not stalled queries. func TestLoggingNeverBlocksTheQueryPath(t *testing.T) { w := stuck{release: make(chan struct{})} l := New(Options{Writer: w, Buffer: 8, LogBlocked: true}) done := make(chan struct{}) go func() { defer close(done) for i := 0; i < 5000; i++ { l.Log(Entry{Name: "x.test.", Action: ActionBlock}) } }() select { case <-done: case <-time.After(5 * time.Second): t.Fatal("Log blocked on a stalled writer") } if l.Dropped() == 0 { t.Error("nothing was counted as dropped") } close(w.release) _ = l.Close() } func TestWritesAfterCloseAreIgnored(t *testing.T) { l := New(Options{Writer: &syncBuf{}, LogBlocked: true}) _ = l.Close() l.Log(Entry{Name: "late.test.", Action: ActionBlock}) // must not panic or block _ = l.Close() }