feat: add `queryLog.ignore.sudn` option to ignore SUDN responses

This commit is contained in:
ThinkChaos 2024-04-04 18:31:37 -04:00
parent c56f0f91ca
commit 9d65b9395d
6 changed files with 182 additions and 22 deletions

View File

@ -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 {

View File

@ -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) {

View File

@ -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
}

View File

@ -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),
)
})

View File

@ -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,

View File

@ -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{