From 9d65b9395dc94e5243a9c792382c4d97acddf42a Mon Sep 17 00:00:00 2001 From: ThinkChaos Date: Thu, 4 Apr 2024 18:31:37 -0400 Subject: [PATCH] feat: add `queryLog.ignore.sudn` option to ignore SUDN responses --- config/query_log.go | 11 ++++ config/query_log_test.go | 1 + querylog/logger_writer.go | 43 ++++++++++----- querylog/logger_writer_test.go | 47 ++++++++++++++++ resolver/query_logging_resolver.go | 30 +++++++++-- resolver/query_logging_resolver_test.go | 72 +++++++++++++++++++++++-- 6 files changed, 182 insertions(+), 22 deletions(-) diff --git a/config/query_log.go b/config/query_log.go index 55fa7965..687fbd94 100644 --- a/config/query_log.go +++ b/config/query_log.go @@ -4,6 +4,7 @@ import ( "net/url" "strings" + "github.com/0xERR0R/blocky/log" "github.com/sirupsen/logrus" ) @@ -16,6 +17,11 @@ type QueryLog struct { CreationCooldown Duration `yaml:"creationCooldown" default:"2s"` Fields []QueryLogField `yaml:"fields"` FlushInterval Duration `yaml:"flushInterval" default:"30s"` + Ignore QueryLogIgnore `yaml:"ignore"` +} + +type QueryLogIgnore struct { + SUDN bool `yaml:"sudn" default:"false"` } // SetDefaults implements `defaults.Setter`. @@ -43,6 +49,11 @@ func (c *QueryLog) LogConfig(logger *logrus.Entry) { logger.Debugf("creationCooldown: %s", c.CreationCooldown) logger.Infof("flushInterval: %s", c.FlushInterval) logger.Infof("fields: %s", c.Fields) + + logger.Infof("ignore:") + log.WithIndent(logger, " ", func(e *logrus.Entry) { + logger.Infof("sudn: %t", c.Ignore.SUDN) + }) } func (c *QueryLog) censoredTarget() string { diff --git a/config/query_log_test.go b/config/query_log_test.go index 6eee153a..cedab381 100644 --- a/config/query_log_test.go +++ b/config/query_log_test.go @@ -54,6 +54,7 @@ var _ = Describe("QueryLogConfig", func() { Expect(hook.Calls).ShouldNot(BeEmpty()) Expect(hook.Messages).Should(ContainElement(ContainSubstring("logRetentionDays:"))) + Expect(hook.Messages).Should(ContainElement(ContainSubstring("sudn:"))) }) DescribeTable("secret censoring", func(target string) { diff --git a/querylog/logger_writer.go b/querylog/logger_writer.go index ed10874e..786bc6bc 100644 --- a/querylog/logger_writer.go +++ b/querylog/logger_writer.go @@ -1,6 +1,7 @@ package querylog import ( + "reflect" "strings" "github.com/0xERR0R/blocky/log" @@ -19,22 +20,36 @@ func NewLoggerWriter() *LoggerWriter { } func (d *LoggerWriter) Write(entry *LogEntry) { - d.logger.WithFields( - logrus.Fields{ - "client_ip": entry.ClientIP, - "client_names": strings.Join(entry.ClientNames, "; "), - "response_reason": entry.ResponseReason, - "response_type": entry.ResponseType, - "response_code": entry.ResponseCode, - "question_name": entry.QuestionName, - "question_type": entry.QuestionType, - "answer": entry.Answer, - "duration_ms": entry.DurationMs, - "hostname": util.HostnameString(), - }, - ).Infof("query resolved") + fields := LogEntryFields(entry) + + d.logger.WithFields(fields).Infof("query resolved") } func (d *LoggerWriter) CleanUp() { // Nothing to do } + +func LogEntryFields(entry *LogEntry) logrus.Fields { + return withoutZeroes(logrus.Fields{ + "client_ip": entry.ClientIP, + "client_names": strings.Join(entry.ClientNames, "; "), + "response_reason": entry.ResponseReason, + "response_type": entry.ResponseType, + "response_code": entry.ResponseCode, + "question_name": entry.QuestionName, + "question_type": entry.QuestionType, + "answer": entry.Answer, + "duration_ms": entry.DurationMs, + "hostname": util.HostnameString(), + }) +} + +func withoutZeroes(fields logrus.Fields) logrus.Fields { + for k, v := range fields { + if reflect.ValueOf(v).IsZero() { + delete(fields, k) + } + } + + return fields +} diff --git a/querylog/logger_writer_test.go b/querylog/logger_writer_test.go index f238e228..38b136c5 100644 --- a/querylog/logger_writer_test.go +++ b/querylog/logger_writer_test.go @@ -3,6 +3,7 @@ package querylog import ( "time" + "github.com/sirupsen/logrus" "github.com/sirupsen/logrus/hooks/test" . "github.com/onsi/gomega" @@ -34,4 +35,50 @@ var _ = Describe("LoggerWriter", func() { }) }) }) + + Describe("LogEntryFields", func() { + It("should return log fields", func() { + entry := LogEntry{ + ClientIP: "ip", + DurationMs: 100, + QuestionType: "qtype", + ResponseCode: "rcode", + } + + fields := LogEntryFields(&entry) + + Expect(fields).Should(HaveKeyWithValue("client_ip", entry.ClientIP)) + Expect(fields).Should(HaveKeyWithValue("duration_ms", entry.DurationMs)) + Expect(fields).Should(HaveKeyWithValue("question_type", entry.QuestionType)) + Expect(fields).Should(HaveKeyWithValue("response_code", entry.ResponseCode)) + Expect(fields).Should(HaveKey("hostname")) + + Expect(fields).ShouldNot(HaveKey("client_names")) + Expect(fields).ShouldNot(HaveKey("question_name")) + }) + }) + + DescribeTable("withoutZeroes", + func(value any, isZero bool) { + fields := withoutZeroes(logrus.Fields{"a": value}) + + if isZero { + Expect(fields).Should(BeEmpty()) + } else { + Expect(fields).ShouldNot(BeEmpty()) + } + }, + Entry("empty string", + "", + true), + Entry("non-empty string", + "something", + false), + Entry("zero int", + 0, + true), + Entry("non-zero int", + 1, + false), + ) }) diff --git a/resolver/query_logging_resolver.go b/resolver/query_logging_resolver.go index ea549327..02fc9086 100644 --- a/resolver/query_logging_resolver.go +++ b/resolver/query_logging_resolver.go @@ -115,20 +115,40 @@ func (r *QueryLoggingResolver) Resolve(ctx context.Context, request *model.Reque ctx, logger := r.log(ctx) start := time.Now() - resp, err := r.next.Resolve(ctx, request) - duration := time.Since(start).Milliseconds() - if err == nil { + if err != nil { + return nil, err + } + + entry := r.createLogEntry(request, resp, start, duration) + + if r.ignore(resp) { + // Log to the console for debugging purposes + logger.WithFields(querylog.LogEntryFields(entry)).Debug("ignored querylog entry") + } else { select { - case r.logChan <- r.createLogEntry(request, resp, start, duration): + case r.logChan <- entry: default: logger.Error("query log writer is too slow, log entry will be dropped") } } - return resp, err + return resp, nil +} + +func (r *QueryLoggingResolver) ignore(response *model.Response) bool { + cfg := r.cfg.Ignore + + if cfg.SUDN && response.RType == model.ResponseTypeSPECIAL { + return true + } + + // If we add more ways to ignore entries, it would be nice to log why it's ignored in the debug log + // Probably make this func return a (string, bool). + + return false } func (r *QueryLoggingResolver) createLogEntry(request *model.Request, response *model.Response, diff --git a/resolver/query_logging_resolver_test.go b/resolver/query_logging_resolver_test.go index 4e7968a3..f6cec856 100644 --- a/resolver/query_logging_resolver_test.go +++ b/resolver/query_logging_resolver_test.go @@ -13,6 +13,8 @@ import ( . "github.com/0xERR0R/blocky/helpertest" "github.com/0xERR0R/blocky/log" "github.com/0xERR0R/blocky/querylog" + "github.com/sirupsen/logrus" + "github.com/stretchr/testify/mock" "github.com/0xERR0R/blocky/config" . "github.com/0xERR0R/blocky/model" @@ -21,7 +23,6 @@ import ( "github.com/miekg/dns" . "github.com/onsi/ginkgo/v2" . "github.com/onsi/gomega" - "github.com/stretchr/testify/mock" ) type SlowMockWriter struct { @@ -43,6 +44,7 @@ var _ = Describe("QueryLoggingResolver", func() { sutConfig config.QueryLog m *mockResolver tmpDir *TmpFolder + mockRType ResponseType mockAnswer *dns.Msg ctx context.Context @@ -59,6 +61,12 @@ var _ = Describe("QueryLoggingResolver", func() { ctx, cancelFn = context.WithCancel(context.Background()) DeferCleanup(cancelFn) + var err error + + sutConfig, err = config.WithDefaults[config.QueryLog]() + Expect(err).Should(Succeed()) + + mockRType = ResponseTypeRESOLVED mockAnswer = new(dns.Msg) tmpDir = NewTmpFolder("queryLoggingResolver") }) @@ -69,8 +77,15 @@ var _ = Describe("QueryLoggingResolver", func() { } sut = NewQueryLoggingResolver(ctx, sutConfig) - m = &mockResolver{} - m.On("Resolve", mock.Anything).Return(&Response{Res: mockAnswer, Reason: "reason"}, nil) + + m = &mockResolver{ + ResolveFn: func(context.Context, *Request) (*Response, error) { + return &Response{RType: mockRType, Res: mockAnswer, Reason: "reason"}, nil + }, + } + + m.On("Resolve", mock.Anything).Return(autoAnswer, nil) + sut.Next(m) }) @@ -109,6 +124,57 @@ var _ = Describe("QueryLoggingResolver", func() { m.AssertExpectations(GinkgoT()) }) }) + + Describe("ignore", func() { + var ignored *log.MockLoggerHook + + JustBeforeEach(func() { + // Stop background goroutines + cancelFn() + + ctx, cancelFn = context.WithCancel(context.Background()) + DeferCleanup(cancelFn) + + // Capture written logs + sut.logChan = make(chan *querylog.LogEntry, 16) + + // Capture ignored logs + { + var logger *logrus.Entry + + logger, ignored = log.NewMockEntry() + ctx, _ = log.NewCtx(ctx, logger) + } + }) + + Describe("SUDN", func() { + JustBeforeEach(func() { + sut.cfg.Ignore.SUDN = true + }) + + It("should not log SUDN responses", func() { + mockRType = ResponseTypeSPECIAL + + _, err := sut.Resolve(ctx, newRequestWithClient("example.com.", A, "192.168.178.25", "client1")) + Expect(err).Should(Succeed()) + + Expect(sut.logChan).Should(BeEmpty()) + Expect(ignored.Calls).Should(HaveLen(1)) + Expect(ignored.Messages).Should(ContainElement(ContainSubstring("ignored querylog entry"))) + }) + + It("should log other responses", func() { + mockRType = ResponseTypeBLOCKED + + _, err := sut.Resolve(ctx, newRequestWithClient("example.com.", A, "192.168.178.25", "client1")) + Expect(err).Should(Succeed()) + + Expect(sut.logChan).ShouldNot(BeEmpty()) + Expect(ignored.Calls).Should(BeEmpty()) + }) + }) + }) + When("Configuration with logging per client", func() { BeforeEach(func() { sutConfig = config.QueryLog{