package querylog import ( "fmt" "net" "os" "path/filepath" "strconv" "strings" "sync" "time" "github.com/AdguardTeam/AdGuardHome/dnsfilter" "github.com/AdguardTeam/golibs/log" "github.com/miekg/dns" ) const ( logBufferCap = 5000 // maximum capacity of logBuffer before it's flushed to disk queryLogFileName = "querylog.json" // .gz added during compression getDataLimit = 500 // GetData(): maximum log entries to return // maximum data chunks to parse when filtering entries maxFilteringChunks = 10 ) // queryLog is a structure that writes and reads the DNS query log type queryLog struct { conf Config logFile string // path to the log file logBufferLock sync.RWMutex logBuffer []*logEntry fileFlushLock sync.Mutex // synchronize a file-flushing goroutine and main thread flushPending bool // don't start another goroutine while the previous one is still running } // create a new instance of the query log func newQueryLog(conf Config) *queryLog { l := queryLog{} l.logFile = filepath.Join(conf.BaseDir, queryLogFileName) l.conf = conf go l.periodicQueryLogRotate() return &l } func (l *queryLog) Close() { _ = l.flushLogBuffer(true) } func (l *queryLog) Configure(conf Config) { l.conf = conf } func (l *queryLog) Clear() { l.fileFlushLock.Lock() defer l.fileFlushLock.Unlock() l.logBufferLock.Lock() l.logBuffer = nil l.flushPending = false l.logBufferLock.Unlock() err := os.Remove(l.logFile + ".1") if err != nil && !os.IsNotExist(err) { log.Error("file remove: %s: %s", l.logFile+".1", err) } err = os.Remove(l.logFile) if err != nil && !os.IsNotExist(err) { log.Error("file remove: %s: %s", l.logFile, err) } log.Debug("Query log: cleared") } type logEntry struct { Question []byte Answer []byte `json:",omitempty"` // sometimes empty answers happen like binerdunt.top or rev2.globalrootservers.net Result dnsfilter.Result Time time.Time Elapsed time.Duration IP string Upstream string `json:",omitempty"` // if empty, means it was cached } // getIPString is a helper function that extracts IP address from net.Addr func getIPString(addr net.Addr) string { switch addr := addr.(type) { case *net.UDPAddr: return addr.IP.String() case *net.TCPAddr: return addr.IP.String() } return "" } func (l *queryLog) Add(question *dns.Msg, answer *dns.Msg, result *dnsfilter.Result, elapsed time.Duration, addr net.Addr, upstream string) { var q []byte var a []byte var err error ip := getIPString(addr) if question != nil { q, err = question.Pack() if err != nil { log.Printf("failed to pack question for querylog: %s", err) return } } if answer != nil { a, err = answer.Pack() if err != nil { log.Printf("failed to pack answer for querylog: %s", err) return } } if result == nil { result = &dnsfilter.Result{} } now := time.Now() entry := logEntry{ Question: q, Answer: a, Result: *result, Time: now, Elapsed: elapsed, IP: ip, Upstream: upstream, } l.logBufferLock.Lock() l.logBuffer = append(l.logBuffer, &entry) needFlush := false if !l.flushPending { needFlush = len(l.logBuffer) >= logBufferCap if needFlush { l.flushPending = true } } l.logBufferLock.Unlock() // if buffer needs to be flushed to disk, do it now if needFlush { // write to file // do it in separate goroutine -- we are stalling DNS response this whole time go l.flushLogBuffer(false) // nolint } } // Return TRUE if this entry is needed func isNeeded(entry *logEntry, params GetDataParams) bool { if params.ResponseStatus != 0 { if params.ResponseStatus == ResponseStatusFiltered && !entry.Result.IsFiltered { return false } } if len(params.Domain) != 0 || params.QuestionType != 0 { m := dns.Msg{} _ = m.Unpack(entry.Question) if params.QuestionType != 0 { if m.Question[0].Qtype != params.QuestionType { return false } } if len(params.Domain) != 0 && params.StrictMatchDomain { if m.Question[0].Name != params.Domain { return false } } else if len(params.Domain) != 0 { if strings.Index(m.Question[0].Name, params.Domain) == -1 { return false } } } if len(params.Client) != 0 && params.StrictMatchClient { if entry.IP != params.Client { return false } } else if len(params.Client) != 0 { if strings.Index(entry.IP, params.Client) == -1 { return false } } return true } func (l *queryLog) readFromFile(params GetDataParams) ([]*logEntry, int) { entries := []*logEntry{} olderThan := params.OlderThan totalChunks := 0 total := 0 r := l.OpenReader() if r == nil { return entries, 0 } r.BeginRead(olderThan, getDataLimit) for totalChunks < maxFilteringChunks { first := true newEntries := []*logEntry{} for { entry := r.Next() if entry == nil { break } total++ if first { first = false olderThan = entry.Time } if !isNeeded(entry, params) { continue } if len(newEntries) == getDataLimit { newEntries = newEntries[1:] } newEntries = append(newEntries, entry) } log.Debug("entries: +%d (%d) older-than:%s", len(newEntries), len(entries), olderThan) entries = append(newEntries, entries...) if len(entries) > getDataLimit { toremove := len(entries) - getDataLimit entries = entries[toremove:] break } if first || len(entries) == getDataLimit { break } totalChunks++ r.BeginReadPrev(olderThan, getDataLimit) } r.Close() return entries, total } func (l *queryLog) GetData(params GetDataParams) []map[string]interface{} { var data = []map[string]interface{}{} if len(params.Domain) != 0 && params.StrictMatchDomain { params.Domain = params.Domain + "." } now := time.Now() entries := []*logEntry{} total := 0 // add from file entries, total = l.readFromFile(params) if params.OlderThan.IsZero() { params.OlderThan = now } // add from memory buffer l.logBufferLock.Lock() total += len(l.logBuffer) for _, entry := range l.logBuffer { if !isNeeded(entry, params) { continue } if entry.Time.UnixNano() >= params.OlderThan.UnixNano() { break } if len(entries) == getDataLimit { entries = entries[1:] } entries = append(entries, entry) } l.logBufferLock.Unlock() // process the elements from latest to oldest for i := len(entries) - 1; i >= 0; i-- { entry := entries[i] var q *dns.Msg var a *dns.Msg if len(entry.Question) > 0 { q = new(dns.Msg) if err := q.Unpack(entry.Question); err != nil { // ignore, log and move on log.Printf("Failed to unpack dns message question: %s", err) q = nil } } if len(entry.Answer) > 0 { a = new(dns.Msg) if err := a.Unpack(entry.Answer); err != nil { // ignore, log and move on log.Printf("Failed to unpack dns message question: %s", err) a = nil } } jsonEntry := map[string]interface{}{ "reason": entry.Result.Reason.String(), "elapsedMs": strconv.FormatFloat(entry.Elapsed.Seconds()*1000, 'f', -1, 64), "time": entry.Time.Format(time.RFC3339Nano), "client": entry.IP, } if q != nil { jsonEntry["question"] = map[string]interface{}{ "host": strings.ToLower(strings.TrimSuffix(q.Question[0].Name, ".")), "type": dns.Type(q.Question[0].Qtype).String(), "class": dns.Class(q.Question[0].Qclass).String(), } } if a != nil { jsonEntry["status"] = dns.RcodeToString[a.Rcode] } if len(entry.Result.Rule) > 0 { jsonEntry["rule"] = entry.Result.Rule jsonEntry["filterId"] = entry.Result.FilterID } if len(entry.Result.ServiceName) != 0 { jsonEntry["service_name"] = entry.Result.ServiceName } answers := answerToMap(a) if answers != nil { jsonEntry["answer"] = answers } data = append(data, jsonEntry) } log.Debug("QueryLog: prepared data (%d/%d) older than %s in %s", len(entries), total, params.OlderThan, time.Since(now)) return data } func answerToMap(a *dns.Msg) []map[string]interface{} { if a == nil || len(a.Answer) == 0 { return nil } var answers = []map[string]interface{}{} for _, k := range a.Answer { header := k.Header() answer := map[string]interface{}{ "type": dns.TypeToString[header.Rrtype], "ttl": header.Ttl, } // try most common record types switch v := k.(type) { case *dns.A: answer["value"] = v.A case *dns.AAAA: answer["value"] = v.AAAA case *dns.MX: answer["value"] = fmt.Sprintf("%v %v", v.Preference, v.Mx) case *dns.CNAME: answer["value"] = v.Target case *dns.NS: answer["value"] = v.Ns case *dns.SPF: answer["value"] = v.Txt case *dns.TXT: answer["value"] = v.Txt case *dns.PTR: answer["value"] = v.Ptr case *dns.SOA: answer["value"] = fmt.Sprintf("%v %v %v %v %v %v %v", v.Ns, v.Mbox, v.Serial, v.Refresh, v.Retry, v.Expire, v.Minttl) case *dns.CAA: answer["value"] = fmt.Sprintf("%v %v \"%v\"", v.Flag, v.Tag, v.Value) case *dns.HINFO: answer["value"] = fmt.Sprintf("\"%v\" \"%v\"", v.Cpu, v.Os) case *dns.RRSIG: answer["value"] = fmt.Sprintf("%v %v %v %v %v %v %v %v %v", dns.TypeToString[v.TypeCovered], v.Algorithm, v.Labels, v.OrigTtl, v.Expiration, v.Inception, v.KeyTag, v.SignerName, v.Signature) default: // type unknown, marshall it as-is answer["value"] = v } answers = append(answers, answer) } return answers }