2018-08-30 15:25:33 +01:00
|
|
|
package dnsfilter
|
|
|
|
|
|
|
|
import (
|
|
|
|
"encoding/json"
|
|
|
|
"fmt"
|
|
|
|
"log"
|
|
|
|
"net/http"
|
2018-10-06 22:51:44 +01:00
|
|
|
"os"
|
|
|
|
"path"
|
2018-08-30 15:25:33 +01:00
|
|
|
"runtime"
|
|
|
|
"strconv"
|
|
|
|
"strings"
|
2018-10-06 22:58:59 +01:00
|
|
|
"sync"
|
2018-08-30 15:25:33 +01:00
|
|
|
"time"
|
|
|
|
|
2018-10-15 14:02:19 +01:00
|
|
|
"github.com/AdguardTeam/AdGuardHome/dnsfilter"
|
2018-08-30 15:25:33 +01:00
|
|
|
"github.com/coredns/coredns/plugin/pkg/response"
|
|
|
|
"github.com/miekg/dns"
|
|
|
|
)
|
|
|
|
|
2018-10-06 22:51:44 +01:00
|
|
|
const (
|
2018-10-08 18:02:09 +01:00
|
|
|
logBufferCap = 5000 // maximum capacity of logBuffer before it's flushed to disk
|
|
|
|
queryLogTimeLimit = time.Hour * 24 // how far in the past we care about querylogs
|
|
|
|
queryLogRotationPeriod = time.Hour * 24 // rotate the log every 24 hours
|
|
|
|
queryLogFileName = "querylog.json" // .gz added during compression
|
2018-10-09 20:53:19 +01:00
|
|
|
queryLogSize = 5000 // maximum API response for /querylog
|
2018-10-08 18:02:09 +01:00
|
|
|
queryLogTopSize = 500 // Keep in memory only top N values
|
|
|
|
queryLogAPIPort = "8618" // 8618 is sha512sum of "querylog" then each byte summed
|
2018-10-06 22:51:44 +01:00
|
|
|
)
|
2018-10-03 20:25:55 +01:00
|
|
|
|
2018-10-06 22:51:44 +01:00
|
|
|
var (
|
2018-10-06 22:58:59 +01:00
|
|
|
logBufferLock sync.RWMutex
|
2018-10-10 17:44:07 +01:00
|
|
|
logBuffer []*logEntry
|
2018-10-08 17:51:43 +01:00
|
|
|
|
2018-10-10 17:44:07 +01:00
|
|
|
queryLogCache []*logEntry
|
2018-10-08 17:51:43 +01:00
|
|
|
queryLogLock sync.RWMutex
|
|
|
|
queryLogTime time.Time
|
2018-10-06 22:51:44 +01:00
|
|
|
)
|
2018-08-30 15:25:33 +01:00
|
|
|
|
|
|
|
type logEntry struct {
|
2018-10-06 22:51:44 +01:00
|
|
|
Question []byte
|
2018-10-07 00:17:57 +01:00
|
|
|
Answer []byte `json:",omitempty"` // sometimes empty answers happen like binerdunt.top or rev2.globalrootservers.net
|
2018-09-05 19:25:11 +01:00
|
|
|
Result dnsfilter.Result
|
|
|
|
Time time.Time
|
|
|
|
Elapsed time.Duration
|
|
|
|
IP string
|
2018-08-30 15:25:33 +01:00
|
|
|
}
|
|
|
|
|
2018-09-05 19:25:11 +01:00
|
|
|
func logRequest(question *dns.Msg, answer *dns.Msg, result dnsfilter.Result, elapsed time.Duration, ip string) {
|
2018-10-06 22:51:44 +01:00
|
|
|
var q []byte
|
|
|
|
var a []byte
|
|
|
|
var err error
|
|
|
|
|
|
|
|
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
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2018-10-07 21:24:04 +01:00
|
|
|
now := time.Now()
|
2018-08-30 15:25:33 +01:00
|
|
|
entry := logEntry{
|
2018-10-06 22:51:44 +01:00
|
|
|
Question: q,
|
|
|
|
Answer: a,
|
2018-09-05 19:25:11 +01:00
|
|
|
Result: result,
|
2018-10-07 21:24:04 +01:00
|
|
|
Time: now,
|
2018-09-05 19:25:11 +01:00
|
|
|
Elapsed: elapsed,
|
|
|
|
IP: ip,
|
2018-08-30 15:25:33 +01:00
|
|
|
}
|
2018-10-10 17:44:07 +01:00
|
|
|
var flushBuffer []*logEntry
|
2018-10-06 22:51:44 +01:00
|
|
|
|
2018-10-06 22:58:59 +01:00
|
|
|
logBufferLock.Lock()
|
2018-10-10 17:44:07 +01:00
|
|
|
logBuffer = append(logBuffer, &entry)
|
2018-10-06 22:51:44 +01:00
|
|
|
if len(logBuffer) >= logBufferCap {
|
|
|
|
flushBuffer = logBuffer
|
|
|
|
logBuffer = nil
|
|
|
|
}
|
2018-10-06 22:58:59 +01:00
|
|
|
logBufferLock.Unlock()
|
2018-10-10 17:44:07 +01:00
|
|
|
queryLogLock.Lock()
|
|
|
|
queryLogCache = append(queryLogCache, &entry)
|
|
|
|
if len(queryLogCache) > queryLogSize {
|
|
|
|
toremove := len(queryLogCache) - queryLogSize
|
|
|
|
queryLogCache = queryLogCache[toremove:]
|
|
|
|
}
|
|
|
|
queryLogLock.Unlock()
|
2018-10-07 21:24:04 +01:00
|
|
|
|
|
|
|
// add it to running top
|
2018-10-09 02:45:05 +01:00
|
|
|
err = runningTop.addEntry(&entry, question, now)
|
2018-10-07 21:24:04 +01:00
|
|
|
if err != nil {
|
|
|
|
log.Printf("Failed to add entry to running top: %s", err)
|
|
|
|
// don't do failure, just log
|
|
|
|
}
|
|
|
|
|
|
|
|
// if buffer needs to be flushed to disk, do it now
|
2018-10-06 22:51:44 +01:00
|
|
|
if len(flushBuffer) > 0 {
|
|
|
|
// write to file
|
|
|
|
// do it in separate goroutine -- we are stalling DNS response this whole time
|
|
|
|
go flushToFile(flushBuffer)
|
|
|
|
}
|
2018-08-30 15:25:33 +01:00
|
|
|
}
|
|
|
|
|
2018-10-17 16:55:27 +01:00
|
|
|
func HandleQueryLog(w http.ResponseWriter, r *http.Request) {
|
2018-10-08 17:51:43 +01:00
|
|
|
queryLogLock.RLock()
|
2018-10-10 17:44:07 +01:00
|
|
|
values := make([]*logEntry, len(queryLogCache))
|
|
|
|
copy(values, queryLogCache)
|
2018-10-08 17:51:43 +01:00
|
|
|
queryLogLock.RUnlock()
|
|
|
|
|
2018-10-10 17:44:07 +01:00
|
|
|
// reverse it so that newest is first
|
|
|
|
for left, right := 0, len(values)-1; left < right; left, right = left+1, right-1 {
|
|
|
|
values[left], values[right] = values[right], values[left]
|
2018-10-07 00:17:22 +01:00
|
|
|
}
|
|
|
|
|
2018-08-30 15:25:33 +01:00
|
|
|
var data = []map[string]interface{}{}
|
2018-10-06 22:51:44 +01:00
|
|
|
for _, entry := range values {
|
|
|
|
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
|
|
|
|
}
|
2018-08-30 15:25:33 +01:00
|
|
|
}
|
|
|
|
|
|
|
|
jsonentry := map[string]interface{}{
|
|
|
|
"reason": entry.Result.Reason.String(),
|
|
|
|
"elapsed_ms": strconv.FormatFloat(entry.Elapsed.Seconds()*1000, 'f', -1, 64),
|
|
|
|
"time": entry.Time.Format(time.RFC3339),
|
2018-08-31 17:59:04 +01:00
|
|
|
"client": entry.IP,
|
2018-08-30 15:25:33 +01:00
|
|
|
}
|
2018-10-06 22:51:44 +01:00
|
|
|
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(),
|
|
|
|
}
|
2018-08-30 15:25:33 +01:00
|
|
|
}
|
|
|
|
|
2018-10-06 22:51:44 +01:00
|
|
|
if a != nil {
|
|
|
|
status, _ := response.Typify(a, time.Now().UTC())
|
|
|
|
jsonentry["status"] = status.String()
|
|
|
|
}
|
2018-08-30 15:25:33 +01:00
|
|
|
if len(entry.Result.Rule) > 0 {
|
|
|
|
jsonentry["rule"] = entry.Result.Rule
|
|
|
|
}
|
|
|
|
|
2018-10-06 22:51:44 +01:00
|
|
|
if a != nil && len(a.Answer) > 0 {
|
2018-08-30 15:25:33 +01:00
|
|
|
var answers = []map[string]interface{}{}
|
2018-10-06 22:51:44 +01:00
|
|
|
for _, k := range a.Answer {
|
2018-08-30 15:25:33 +01:00
|
|
|
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)
|
|
|
|
}
|
|
|
|
jsonentry["answer"] = answers
|
|
|
|
}
|
|
|
|
|
|
|
|
data = append(data, jsonentry)
|
|
|
|
}
|
|
|
|
|
2018-10-20 17:58:39 +01:00
|
|
|
jsonVal, err := json.Marshal(data)
|
2018-08-30 15:25:33 +01:00
|
|
|
if err != nil {
|
|
|
|
errortext := fmt.Sprintf("Couldn't marshal data into json: %s", err)
|
|
|
|
log.Println(errortext)
|
|
|
|
http.Error(w, errortext, http.StatusInternalServerError)
|
|
|
|
return
|
|
|
|
}
|
|
|
|
|
|
|
|
w.Header().Set("Content-Type", "application/json")
|
2018-10-20 17:58:39 +01:00
|
|
|
_, err = w.Write(jsonVal)
|
2018-08-30 15:25:33 +01:00
|
|
|
if err != nil {
|
|
|
|
errortext := fmt.Sprintf("Unable to write response json: %s", err)
|
|
|
|
log.Println(errortext)
|
2018-10-08 18:02:09 +01:00
|
|
|
http.Error(w, errortext, http.StatusInternalServerError)
|
2018-08-30 15:25:33 +01:00
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2018-10-06 22:51:44 +01:00
|
|
|
func trace(format string, args ...interface{}) {
|
2018-08-30 15:25:33 +01:00
|
|
|
pc := make([]uintptr, 10) // at least 1 entry needed
|
|
|
|
runtime.Callers(2, pc)
|
|
|
|
f := runtime.FuncForPC(pc[0])
|
2018-10-06 22:51:44 +01:00
|
|
|
var buf strings.Builder
|
|
|
|
buf.WriteString(fmt.Sprintf("%s(): ", path.Base(f.Name())))
|
|
|
|
text := fmt.Sprintf(format, args...)
|
|
|
|
buf.WriteString(text)
|
|
|
|
if len(text) == 0 || text[len(text)-1] != '\n' {
|
|
|
|
buf.WriteRune('\n')
|
|
|
|
}
|
|
|
|
fmt.Fprint(os.Stderr, buf.String())
|
2018-08-30 15:25:33 +01:00
|
|
|
}
|