2020-01-12 18:23:35 +01:00
|
|
|
package resolver
|
|
|
|
|
|
|
|
import (
|
|
|
|
"fmt"
|
|
|
|
"time"
|
|
|
|
|
2021-08-25 22:06:34 +02:00
|
|
|
"github.com/0xERR0R/blocky/config"
|
2021-08-29 21:51:24 +02:00
|
|
|
"github.com/0xERR0R/blocky/model"
|
2021-08-30 18:11:06 +02:00
|
|
|
"github.com/0xERR0R/blocky/querylog"
|
2022-11-26 22:12:56 +01:00
|
|
|
"github.com/0xERR0R/blocky/util"
|
2021-12-24 22:40:06 +01:00
|
|
|
"github.com/avast/retry-go/v4"
|
2022-11-26 22:12:56 +01:00
|
|
|
"github.com/miekg/dns"
|
2020-01-12 18:23:35 +01:00
|
|
|
)
|
|
|
|
|
|
|
|
const (
|
|
|
|
cleanUpRunPeriod = 12 * time.Hour
|
|
|
|
queryLoggingResolverPrefix = "query_logging_resolver"
|
|
|
|
logChanCap = 1000
|
2022-05-10 09:09:50 +02:00
|
|
|
defaultFlushPeriod = 30 * time.Second
|
2020-01-12 18:23:35 +01:00
|
|
|
)
|
|
|
|
|
2021-09-12 22:26:07 +02:00
|
|
|
// QueryLoggingResolver writes query information (question, answer, duration, ...)
|
2020-01-12 18:23:35 +01:00
|
|
|
type QueryLoggingResolver struct {
|
|
|
|
NextResolver
|
2021-08-30 18:11:06 +02:00
|
|
|
target string
|
2020-01-12 18:23:35 +01:00
|
|
|
logRetentionDays uint64
|
2022-03-03 11:27:27 +01:00
|
|
|
logChan chan *querylog.LogEntry
|
2021-08-30 18:11:06 +02:00
|
|
|
writer querylog.Writer
|
2021-11-11 08:52:21 +01:00
|
|
|
logType config.QueryLogType
|
2022-11-26 22:12:56 +01:00
|
|
|
fields []config.QueryLogField
|
2020-01-12 18:23:35 +01:00
|
|
|
}
|
|
|
|
|
2021-02-26 13:45:57 +01:00
|
|
|
// NewQueryLoggingResolver returns a new resolver instance
|
2020-01-12 18:23:35 +01:00
|
|
|
func NewQueryLoggingResolver(cfg config.QueryLogConfig) ChainedResolver {
|
2021-08-30 18:11:06 +02:00
|
|
|
var writer querylog.Writer
|
|
|
|
|
2021-11-11 08:52:21 +01:00
|
|
|
logType := cfg.Type
|
2021-12-13 22:00:56 +01:00
|
|
|
err := retry.Do(
|
|
|
|
func() error {
|
|
|
|
var err error
|
|
|
|
switch logType {
|
|
|
|
case config.QueryLogTypeCsv:
|
|
|
|
writer, err = querylog.NewCSVWriter(cfg.Target, false, cfg.LogRetentionDays)
|
|
|
|
case config.QueryLogTypeCsvClient:
|
|
|
|
writer, err = querylog.NewCSVWriter(cfg.Target, true, cfg.LogRetentionDays)
|
|
|
|
case config.QueryLogTypeMysql:
|
2022-05-10 09:09:50 +02:00
|
|
|
writer, err = querylog.NewDatabaseWriter("mysql", cfg.Target, cfg.LogRetentionDays, defaultFlushPeriod)
|
2022-01-07 21:42:06 +01:00
|
|
|
case config.QueryLogTypePostgresql:
|
2022-05-10 09:09:50 +02:00
|
|
|
writer, err = querylog.NewDatabaseWriter("postgresql", cfg.Target, cfg.LogRetentionDays, defaultFlushPeriod)
|
2021-12-13 22:00:56 +01:00
|
|
|
case config.QueryLogTypeConsole:
|
|
|
|
writer = querylog.NewLoggerWriter()
|
|
|
|
case config.QueryLogTypeNone:
|
|
|
|
writer = querylog.NewNoneWriter()
|
|
|
|
}
|
2022-05-10 09:09:50 +02:00
|
|
|
|
2021-12-13 22:00:56 +01:00
|
|
|
return err
|
|
|
|
},
|
2021-12-21 22:03:02 +01:00
|
|
|
retry.Attempts(uint(cfg.CreationAttempts)),
|
|
|
|
retry.Delay(time.Duration(cfg.CreationCooldown)),
|
2021-12-13 22:00:56 +01:00
|
|
|
retry.OnRetry(func(n uint, err error) {
|
|
|
|
logger(queryLoggingResolverPrefix).Warnf("Error occurred on query writer creation, "+
|
2021-12-21 22:03:02 +01:00
|
|
|
"retry attempt %d/%d: %v", n+1, cfg.CreationAttempts, err)
|
2021-12-13 22:00:56 +01:00
|
|
|
}))
|
2020-01-12 18:23:35 +01:00
|
|
|
|
2021-11-11 08:52:21 +01:00
|
|
|
if err != nil {
|
|
|
|
logger(queryLoggingResolverPrefix).Error("can't create query log writer, using console as fallback: ", err)
|
|
|
|
|
|
|
|
writer = querylog.NewLoggerWriter()
|
|
|
|
logType = config.QueryLogTypeConsole
|
|
|
|
}
|
|
|
|
|
2022-03-03 11:27:27 +01:00
|
|
|
logChan := make(chan *querylog.LogEntry, logChanCap)
|
2020-01-12 18:23:35 +01:00
|
|
|
|
|
|
|
resolver := QueryLoggingResolver{
|
2021-08-30 18:11:06 +02:00
|
|
|
target: cfg.Target,
|
2020-01-12 18:23:35 +01:00
|
|
|
logRetentionDays: cfg.LogRetentionDays,
|
|
|
|
logChan: logChan,
|
2021-08-30 18:11:06 +02:00
|
|
|
writer: writer,
|
2021-11-11 08:52:21 +01:00
|
|
|
logType: logType,
|
2022-11-26 22:12:56 +01:00
|
|
|
fields: resolveQueryLogFields(cfg),
|
2020-01-12 18:23:35 +01:00
|
|
|
}
|
|
|
|
|
|
|
|
go resolver.writeLog()
|
|
|
|
|
|
|
|
if cfg.LogRetentionDays > 0 {
|
|
|
|
go resolver.periodicCleanUp()
|
|
|
|
}
|
|
|
|
|
|
|
|
return &resolver
|
|
|
|
}
|
|
|
|
|
2022-11-26 22:12:56 +01:00
|
|
|
func resolveQueryLogFields(cfg config.QueryLogConfig) []config.QueryLogField {
|
|
|
|
var fields []config.QueryLogField
|
|
|
|
|
|
|
|
if len(cfg.Fields) == 0 {
|
|
|
|
// no fields defined, use all fields as fallback
|
|
|
|
for _, v := range config.QueryLogFieldNames() {
|
|
|
|
qlt, err := config.ParseQueryLogField(v)
|
|
|
|
util.LogOnError("ignoring unknown query log field", err)
|
|
|
|
|
|
|
|
fields = append(fields, qlt)
|
|
|
|
}
|
|
|
|
} else {
|
|
|
|
fields = cfg.Fields
|
|
|
|
}
|
|
|
|
|
|
|
|
return fields
|
|
|
|
}
|
|
|
|
|
2020-01-12 18:23:35 +01:00
|
|
|
// triggers periodically cleanup of old log files
|
|
|
|
func (r *QueryLoggingResolver) periodicCleanUp() {
|
|
|
|
ticker := time.NewTicker(cleanUpRunPeriod)
|
|
|
|
defer ticker.Stop()
|
|
|
|
|
|
|
|
for {
|
|
|
|
<-ticker.C
|
|
|
|
r.doCleanUp()
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
func (r *QueryLoggingResolver) doCleanUp() {
|
2021-08-30 18:11:06 +02:00
|
|
|
r.writer.CleanUp()
|
2020-01-12 18:23:35 +01:00
|
|
|
}
|
|
|
|
|
2021-02-26 13:45:57 +01:00
|
|
|
// Resolve logs the query, duration and the result
|
2021-08-29 21:51:24 +02:00
|
|
|
func (r *QueryLoggingResolver) Resolve(request *model.Request) (*model.Response, error) {
|
2020-01-12 18:23:35 +01:00
|
|
|
logger := withPrefix(request.Log, queryLoggingResolverPrefix)
|
|
|
|
|
|
|
|
start := time.Now()
|
|
|
|
|
|
|
|
resp, err := r.next.Resolve(request)
|
|
|
|
|
|
|
|
duration := time.Since(start).Milliseconds()
|
|
|
|
|
|
|
|
if err == nil {
|
|
|
|
select {
|
2022-11-26 22:12:56 +01:00
|
|
|
case r.logChan <- r.createLogEntry(request, resp, start, duration):
|
2020-01-12 18:23:35 +01:00
|
|
|
default:
|
|
|
|
logger.Error("query log writer is too slow, log entry will be dropped")
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
return resp, err
|
|
|
|
}
|
|
|
|
|
2022-11-26 22:12:56 +01:00
|
|
|
func (r *QueryLoggingResolver) createLogEntry(request *model.Request, response *model.Response,
|
|
|
|
start time.Time, durationMs int64) *querylog.LogEntry {
|
|
|
|
entry := querylog.LogEntry{
|
|
|
|
Start: start,
|
|
|
|
ClientIP: "0.0.0.0",
|
|
|
|
ClientNames: []string{"none"},
|
|
|
|
}
|
|
|
|
|
|
|
|
for _, f := range r.fields {
|
|
|
|
switch f {
|
|
|
|
case config.QueryLogFieldClientIP:
|
|
|
|
entry.ClientIP = request.ClientIP.String()
|
|
|
|
|
|
|
|
case config.QueryLogFieldClientName:
|
|
|
|
entry.ClientNames = request.ClientNames
|
|
|
|
|
|
|
|
case config.QueryLogFieldResponseReason:
|
|
|
|
entry.ResponseReason = response.Reason
|
|
|
|
entry.ResponseType = response.RType.String()
|
|
|
|
entry.ResponseCode = dns.RcodeToString[response.Res.Rcode]
|
|
|
|
|
|
|
|
case config.QueryLogFieldResponseAnswer:
|
|
|
|
entry.Answer = util.AnswerToString(response.Res.Answer)
|
|
|
|
|
|
|
|
case config.QueryLogFieldQuestion:
|
|
|
|
entry.QuestionName = request.Req.Question[0].Name
|
|
|
|
entry.QuestionType = dns.TypeToString[request.Req.Question[0].Qtype]
|
|
|
|
|
|
|
|
case config.QueryLogFieldDuration:
|
|
|
|
entry.DurationMs = durationMs
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
return &entry
|
|
|
|
}
|
|
|
|
|
2020-01-12 18:23:35 +01:00
|
|
|
// write entry: if log directory is configured, write to log file
|
|
|
|
func (r *QueryLoggingResolver) writeLog() {
|
|
|
|
for logEntry := range r.logChan {
|
2021-08-30 18:11:06 +02:00
|
|
|
start := time.Now()
|
2020-01-12 18:23:35 +01:00
|
|
|
|
2021-08-30 18:11:06 +02:00
|
|
|
r.writer.Write(logEntry)
|
2020-01-12 18:23:35 +01:00
|
|
|
|
2022-11-29 21:58:26 +01:00
|
|
|
halfCap := cap(r.logChan) / 2 //nolint:gomnd
|
2021-01-19 21:52:24 +01:00
|
|
|
|
2021-08-30 18:11:06 +02:00
|
|
|
// if log channel is > 50% full, this could be a problem with slow writer (external storage over network etc.)
|
|
|
|
if len(r.logChan) > halfCap {
|
|
|
|
logger(queryLoggingResolverPrefix).WithField("channel_len",
|
|
|
|
len(r.logChan)).Warnf("query log writer is too slow, write duration: %d ms", time.Since(start).Milliseconds())
|
2020-01-12 18:23:35 +01:00
|
|
|
}
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2021-02-26 13:45:57 +01:00
|
|
|
// Configuration returns the current resolver configuration
|
2020-01-12 18:23:35 +01:00
|
|
|
func (r *QueryLoggingResolver) Configuration() (result []string) {
|
2021-11-11 08:52:21 +01:00
|
|
|
result = append(result, fmt.Sprintf("type: \"%s\"", r.logType))
|
|
|
|
result = append(result, fmt.Sprintf("target: \"%s\"", r.target))
|
|
|
|
result = append(result, fmt.Sprintf("logRetentionDays: %d", r.logRetentionDays))
|
2022-11-26 22:12:56 +01:00
|
|
|
result = append(result, fmt.Sprintf("fields: %s", r.fields))
|
2020-01-12 18:23:35 +01:00
|
|
|
|
|
|
|
return
|
|
|
|
}
|