a
/
badguardhome
1
0
Fork 0
Code Issues Pull Requests Projects Releases Wiki Activity

Use new log wrapper and add more functions to it.

This commit is contained in:
Eugene Bujak 2018-12-29 17:23:42 +03:00
parent 7463e54258
commit d8802a9709
22 changed files with 96 additions and 123 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

4
app.go
View File

@ -3,7 +3,6 @@ package main
import ( import (
"bufio" "bufio"
"fmt" "fmt"
"log"
"net" "net"
"net/http" "net/http"
"os" "os"
@ -13,6 +12,7 @@ import (
"syscall" "syscall"
"time" "time"
"github.com/AdguardTeam/AdGuardHome/log"
"github.com/gobuffalo/packr" "github.com/gobuffalo/packr"
"golang.org/x/crypto/ssh/terminal" "golang.org/x/crypto/ssh/terminal"
) )
@ -64,7 +64,7 @@ func main() {
} }
bindPort = &v bindPort = &v
}, nil}, }, nil},
// {"verbose", "v", "enable verbose output", nil, func() { log.SetLevel(log.TraceLevel) }}, {"verbose", "v", "enable verbose output", nil, func() { log.Verbose = true }},
{"help", "h", "print this help", nil, func() { printHelp(); os.Exit(64) }}, {"help", "h", "print this help", nil, func() { printHelp(); os.Exit(64) }},
} }
printHelp = func() { printHelp = func() {

2
config.go
View File

@ -2,7 +2,6 @@ package main
import ( import (
"io/ioutil" "io/ioutil"
"log"
"os" "os"
"path/filepath" "path/filepath"
"sync" "sync"
@ -10,6 +9,7 @@ import (
"github.com/AdguardTeam/AdGuardHome/dhcpd" "github.com/AdguardTeam/AdGuardHome/dhcpd"
"github.com/AdguardTeam/AdGuardHome/dnsfilter" "github.com/AdguardTeam/AdGuardHome/dnsfilter"
"github.com/AdguardTeam/AdGuardHome/dnsforward" "github.com/AdguardTeam/AdGuardHome/dnsforward"
"github.com/AdguardTeam/AdGuardHome/log"
"gopkg.in/yaml.v2" "gopkg.in/yaml.v2"
) )

6
control.go
View File

@ -4,7 +4,6 @@ import (
"encoding/json" "encoding/json"
"fmt" "fmt"
"io/ioutil" "io/ioutil"
"log"
"net" "net"
"net/http" "net/http"
"os" "os"
@ -12,11 +11,10 @@ import (
"strings" "strings"
"time" "time"
"github.com/AdguardTeam/dnsproxy/upstream"
"github.com/AdguardTeam/AdGuardHome/dnsforward" "github.com/AdguardTeam/AdGuardHome/dnsforward"
"github.com/AdguardTeam/AdGuardHome/log"
"github.com/AdguardTeam/dnsproxy/upstream"
"github.com/miekg/dns" "github.com/miekg/dns"
"gopkg.in/asaskevich/govalidator.v4" "gopkg.in/asaskevich/govalidator.v4"
) )

2
dhcp.go
View File

@ -4,13 +4,13 @@ import (
"encoding/json" "encoding/json"
"fmt" "fmt"
"io/ioutil" "io/ioutil"
"log"
"net" "net"
"net/http" "net/http"
"strings" "strings"
"time" "time"
"github.com/AdguardTeam/AdGuardHome/dhcpd" "github.com/AdguardTeam/AdGuardHome/dhcpd"
"github.com/AdguardTeam/AdGuardHome/log"
"github.com/joomcode/errorx" "github.com/joomcode/errorx"
) )

5
dhcpd/check_other_dhcp.go
View File

@ -9,6 +9,7 @@ import (
"os" "os"
"time" "time"
"github.com/AdguardTeam/AdGuardHome/log"
"github.com/krolaw/dhcp4" "github.com/krolaw/dhcp4"
) )
@ -85,7 +86,7 @@ func CheckIfOtherDHCPServersPresent(ifaceName string) (bool, error) {
} }
// bind to 0.0.0.0:68 // bind to 0.0.0.0:68
trace("Listening to udp4 %+v", udpAddr) log.Tracef("Listening to udp4 %+v", udpAddr)
c, err := net.ListenPacket("udp4", src) c, err := net.ListenPacket("udp4", src)
if c != nil { if c != nil {
defer c.Close() defer c.Close()
@ -104,7 +105,7 @@ func CheckIfOtherDHCPServersPresent(ifaceName string) (bool, error) {
} }
// wait for answer // wait for answer
trace("Waiting %v for an answer", defaultDiscoverTime) log.Tracef("Waiting %v for an answer", defaultDiscoverTime)
// TODO: replicate dhclient's behaviour of retrying several times with progressively bigger timeouts // TODO: replicate dhclient's behaviour of retrying several times with progressively bigger timeouts
b := make([]byte, 1500) b := make([]byte, 1500)
c.SetReadDeadline(time.Now().Add(defaultDiscoverTime)) c.SetReadDeadline(time.Now().Add(defaultDiscoverTime))

60
dhcpd/dhcpd.go
View File

@ -3,10 +3,10 @@ package dhcpd
import ( import (
"bytes" "bytes"
"fmt" "fmt"
"log"
"net" "net"
"time" "time"
"github.com/AdguardTeam/AdGuardHome/log"
"github.com/krolaw/dhcp4" "github.com/krolaw/dhcp4"
) )
@ -167,16 +167,16 @@ func (s *Server) reserveLease(p dhcp4.Packet) (*Lease, error) {
copy(hwaddr, hwaddrCOW) copy(hwaddr, hwaddrCOW)
foundLease := s.locateLease(p) foundLease := s.locateLease(p)
if foundLease != nil { if foundLease != nil {
// trace("found lease for %s: %+v", hwaddr, foundLease) // log.Tracef("found lease for %s: %+v", hwaddr, foundLease)
return foundLease, nil return foundLease, nil
} }
// not assigned a lease, create new one, find IP from LRU // not assigned a lease, create new one, find IP from LRU
trace("Lease not found for %s: creating new one", hwaddr) log.Tracef("Lease not found for %s: creating new one", hwaddr)
ip, err := s.findFreeIP(p, hwaddr) ip, err := s.findFreeIP(p, hwaddr)
if err != nil { if err != nil {
return nil, wrapErrPrint(err, "Couldn't find free IP for the lease %s", hwaddr.String()) return nil, wrapErrPrint(err, "Couldn't find free IP for the lease %s", hwaddr.String())
} }
trace("Assigning to %s IP address %s", hwaddr, ip.String()) log.Tracef("Assigning to %s IP address %s", hwaddr, ip.String())
hostname := p.ParseOptions()[dhcp4.OptionHostName] hostname := p.ParseOptions()[dhcp4.OptionHostName]
lease := &Lease{HWAddr: hwaddr, IP: ip, Hostname: string(hostname)} lease := &Lease{HWAddr: hwaddr, IP: ip, Hostname: string(hostname)}
s.leases = append(s.leases, lease) s.leases = append(s.leases, lease)
@ -187,7 +187,7 @@ func (s *Server) locateLease(p dhcp4.Packet) *Lease {
hwaddr := p.CHAddr() hwaddr := p.CHAddr()
for i := range s.leases { for i := range s.leases {
if bytes.Equal([]byte(hwaddr), []byte(s.leases[i].HWAddr)) { if bytes.Equal([]byte(hwaddr), []byte(s.leases[i].HWAddr)) {
// trace("bytes.Equal(%s, %s) returned true", hwaddr, s.leases[i].hwaddr) // log.Tracef("bytes.Equal(%s, %s) returned true", hwaddr, s.leases[i].hwaddr)
return s.leases[i] return s.leases[i]
} }
} }
@ -205,12 +205,12 @@ func (s *Server) findFreeIP(p dhcp4.Packet, hwaddr net.HardwareAddr) (net.IP, er
for i := 0; i < dhcp4.IPRange(s.leaseStart, s.leaseStop); i++ { for i := 0; i < dhcp4.IPRange(s.leaseStart, s.leaseStop); i++ {
newIP := dhcp4.IPAdd(s.leaseStart, i) newIP := dhcp4.IPAdd(s.leaseStart, i)
foundHWaddr := s.getIPpool(newIP) foundHWaddr := s.getIPpool(newIP)
trace("tried IP %v, got hwaddr %v", newIP, foundHWaddr) log.Tracef("tried IP %v, got hwaddr %v", newIP, foundHWaddr)
if foundHWaddr != nil && len(foundHWaddr) != 0 { if foundHWaddr != nil && len(foundHWaddr) != 0 {
// if !bytes.Equal(foundHWaddr, hwaddr) { // if !bytes.Equal(foundHWaddr, hwaddr) {
// trace("SHOULD NOT HAPPEN: hwaddr in IP pool %s is not equal to hwaddr in lease %s", foundHWaddr, hwaddr) // log.Tracef("SHOULD NOT HAPPEN: hwaddr in IP pool %s is not equal to hwaddr in lease %s", foundHWaddr, hwaddr)
// } // }
trace("will try again") log.Tracef("will try again")
continue continue
} }
foundIP = newIP foundIP = newIP
@ -246,14 +246,14 @@ func (s *Server) unreserveIP(ip net.IP) {
} }
func (s *Server) ServeDHCP(p dhcp4.Packet, msgType dhcp4.MessageType, options dhcp4.Options) dhcp4.Packet { func (s *Server) ServeDHCP(p dhcp4.Packet, msgType dhcp4.MessageType, options dhcp4.Options) dhcp4.Packet {
trace("Got %v message", msgType) log.Tracef("Got %v message", msgType)
trace("Leases:") log.Tracef("Leases:")
for i, lease := range s.leases { for i, lease := range s.leases {
trace("Lease #%d: hwaddr %s, ip %s, expiry %s", i, lease.HWAddr, lease.IP, lease.Expiry) log.Tracef("Lease #%d: hwaddr %s, ip %s, expiry %s", i, lease.HWAddr, lease.IP, lease.Expiry)
} }
trace("IP pool:") log.Tracef("IP pool:")
for ip, hwaddr := range s.IPpool { for ip, hwaddr := range s.IPpool {
trace("IP pool entry %s -> %s", net.IPv4(ip[0], ip[1], ip[2], ip[3]), hwaddr) log.Tracef("IP pool entry %s -> %s", net.IPv4(ip[0], ip[1], ip[2], ip[3]), hwaddr)
} }
// spew.Dump(s.leases, s.IPpool) // spew.Dump(s.leases, s.IPpool)
// log.Printf("Called with msgType = %v, options = %+v", msgType, options) // log.Printf("Called with msgType = %v, options = %+v", msgType, options)
@ -280,22 +280,22 @@ func (s *Server) ServeDHCP(p dhcp4.Packet, msgType dhcp4.MessageType, options dh
switch msgType { switch msgType {
case dhcp4.Discover: // Broadcast Packet From Client - Can I have an IP? case dhcp4.Discover: // Broadcast Packet From Client - Can I have an IP?
// find a lease, but don't update lease time // find a lease, but don't update lease time
trace("Got from client: Discover") log.Tracef("Got from client: Discover")
lease, err := s.reserveLease(p) lease, err := s.reserveLease(p)
if err != nil { if err != nil {
trace("Couldn't find free lease: %s", err) log.Tracef("Couldn't find free lease: %s", err)
// couldn't find lease, don't respond // couldn't find lease, don't respond
return nil return nil
} }
reply := dhcp4.ReplyPacket(p, dhcp4.Offer, s.ipnet.IP, lease.IP, s.leaseTime, s.leaseOptions.SelectOrderOrAll(options[dhcp4.OptionParameterRequestList])) reply := dhcp4.ReplyPacket(p, dhcp4.Offer, s.ipnet.IP, lease.IP, s.leaseTime, s.leaseOptions.SelectOrderOrAll(options[dhcp4.OptionParameterRequestList]))
trace("Replying with offer: offered IP %v for %v with options %+v", lease.IP, s.leaseTime, reply.ParseOptions()) log.Tracef("Replying with offer: offered IP %v for %v with options %+v", lease.IP, s.leaseTime, reply.ParseOptions())
return reply return reply
case dhcp4.Request: // Broadcast From Client - I'll take that IP (Also start for renewals) case dhcp4.Request: // Broadcast From Client - I'll take that IP (Also start for renewals)
// start/renew a lease -- update lease time // start/renew a lease -- update lease time
// some clients (OSX) just go right ahead and do Request first from previously known IP, if they get NAK, they restart full cycle with Discover then Request // some clients (OSX) just go right ahead and do Request first from previously known IP, if they get NAK, they restart full cycle with Discover then Request
trace("Got from client: Request") log.Tracef("Got from client: Request")
if server, ok := options[dhcp4.OptionServerIdentifier]; ok && !net.IP(server).Equal(s.ipnet.IP) { if server, ok := options[dhcp4.OptionServerIdentifier]; ok && !net.IP(server).Equal(s.ipnet.IP) {
trace("Request message not for this DHCP server (%v vs %v)", p, server, s.ipnet.IP) log.Tracef("Request message not for this DHCP server (%v vs %v)", server, s.ipnet.IP)
return nil // Message not for this dhcp server return nil // Message not for this dhcp server
} }
@ -305,19 +305,19 @@ func (s *Server) ServeDHCP(p dhcp4.Packet, msgType dhcp4.MessageType, options dh
} }
if reqIP.To4() == nil { if reqIP.To4() == nil {
trace("Replying with NAK: request IP isn't valid IPv4: %s", reqIP) log.Tracef("Replying with NAK: request IP isn't valid IPv4: %s", reqIP)
return dhcp4.ReplyPacket(p, dhcp4.NAK, s.ipnet.IP, nil, 0, nil) return dhcp4.ReplyPacket(p, dhcp4.NAK, s.ipnet.IP, nil, 0, nil)
} }
if reqIP.Equal(net.IPv4zero) { if reqIP.Equal(net.IPv4zero) {
trace("Replying with NAK: request IP is 0.0.0.0") log.Tracef("Replying with NAK: request IP is 0.0.0.0")
return dhcp4.ReplyPacket(p, dhcp4.NAK, s.ipnet.IP, nil, 0, nil) return dhcp4.ReplyPacket(p, dhcp4.NAK, s.ipnet.IP, nil, 0, nil)
} }
trace("requested IP is %s", reqIP) log.Tracef("requested IP is %s", reqIP)
lease, err := s.reserveLease(p) lease, err := s.reserveLease(p)
if err != nil { if err != nil {
trace("Couldn't find free lease: %s", err) log.Tracef("Couldn't find free lease: %s", err)
// couldn't find lease, don't respond // couldn't find lease, don't respond
return nil return nil
} }
@ -325,7 +325,7 @@ func (s *Server) ServeDHCP(p dhcp4.Packet, msgType dhcp4.MessageType, options dh
if lease.IP.Equal(reqIP) { if lease.IP.Equal(reqIP) {
// IP matches lease IP, nothing else to do // IP matches lease IP, nothing else to do
lease.Expiry = time.Now().Add(s.leaseTime) lease.Expiry = time.Now().Add(s.leaseTime)
trace("Replying with ACK: request IP matches lease IP, nothing else to do. IP %v for %v", lease.IP, p.CHAddr()) log.Tracef("Replying with ACK: request IP matches lease IP, nothing else to do. IP %v for %v", lease.IP, p.CHAddr())
return dhcp4.ReplyPacket(p, dhcp4.ACK, s.ipnet.IP, lease.IP, s.leaseTime, s.leaseOptions.SelectOrderOrAll(options[dhcp4.OptionParameterRequestList])) return dhcp4.ReplyPacket(p, dhcp4.ACK, s.ipnet.IP, lease.IP, s.leaseTime, s.leaseOptions.SelectOrderOrAll(options[dhcp4.OptionParameterRequestList]))
} }
@ -333,14 +333,14 @@ func (s *Server) ServeDHCP(p dhcp4.Packet, msgType dhcp4.MessageType, options dh
// requested IP different from lease // requested IP different from lease
// //
trace("lease IP is different from requested IP: %s vs %s", lease.IP, reqIP) log.Tracef("lease IP is different from requested IP: %s vs %s", lease.IP, reqIP)
hwaddr := s.getIPpool(reqIP) hwaddr := s.getIPpool(reqIP)
if hwaddr == nil { if hwaddr == nil {
// not in pool, check if it's in DHCP range // not in pool, check if it's in DHCP range
if dhcp4.IPInRange(s.leaseStart, s.leaseStop, reqIP) { if dhcp4.IPInRange(s.leaseStart, s.leaseStop, reqIP) {
// okay, we can give it to our client -- it's in our DHCP range and not taken, so let them use their IP // okay, we can give it to our client -- it's in our DHCP range and not taken, so let them use their IP
trace("Replying with ACK: request IP %v is not taken, so assigning lease IP %v to it, for %v", reqIP, lease.IP, p.CHAddr()) log.Tracef("Replying with ACK: request IP %v is not taken, so assigning lease IP %v to it, for %v", reqIP, lease.IP, p.CHAddr())
s.unreserveIP(lease.IP) s.unreserveIP(lease.IP)
lease.IP = reqIP lease.IP = reqIP
s.reserveIP(reqIP, p.CHAddr()) s.reserveIP(reqIP, p.CHAddr())
@ -355,21 +355,21 @@ func (s *Server) ServeDHCP(p dhcp4.Packet, msgType dhcp4.MessageType, options dh
// requsted IP is not sufficient, reply with NAK // requsted IP is not sufficient, reply with NAK
if hwaddr != nil { if hwaddr != nil {
trace("Replying with NAK: request IP %s is taken, asked by %v", reqIP, p.CHAddr()) log.Tracef("Replying with NAK: request IP %s is taken, asked by %v", reqIP, p.CHAddr())
return dhcp4.ReplyPacket(p, dhcp4.NAK, s.ipnet.IP, nil, 0, nil) return dhcp4.ReplyPacket(p, dhcp4.NAK, s.ipnet.IP, nil, 0, nil)
} }
// requested IP is outside of DHCP range // requested IP is outside of DHCP range
trace("Replying with NAK: request IP %s is outside of DHCP range [%s, %s], asked by %v", reqIP, s.leaseStart, s.leaseStop, p.CHAddr()) log.Tracef("Replying with NAK: request IP %s is outside of DHCP range [%s, %s], asked by %v", reqIP, s.leaseStart, s.leaseStop, p.CHAddr())
return dhcp4.ReplyPacket(p, dhcp4.NAK, s.ipnet.IP, nil, 0, nil) return dhcp4.ReplyPacket(p, dhcp4.NAK, s.ipnet.IP, nil, 0, nil)
case dhcp4.Decline: // Broadcast From Client - Sorry I can't use that IP case dhcp4.Decline: // Broadcast From Client - Sorry I can't use that IP
trace("Got from client: Decline") log.Tracef("Got from client: Decline")
case dhcp4.Release: // From Client, I don't need that IP anymore case dhcp4.Release: // From Client, I don't need that IP anymore
trace("Got from client: Release") log.Tracef("Got from client: Release")
case dhcp4.Inform: // From Client, I have this IP and there's nothing you can do about it case dhcp4.Inform: // From Client, I have this IP and there's nothing you can do about it
trace("Got from client: Inform") log.Tracef("Got from client: Inform")
// do nothing // do nothing
// from server -- ignore those but enumerate just in case // from server -- ignore those but enumerate just in case

19
dhcpd/helpers.go
View File

@ -2,30 +2,13 @@ package dhcpd
import ( import (
"fmt" "fmt"
"log"
"net" "net"
"os"
"path"
"runtime"
"strings" "strings"
"github.com/AdguardTeam/AdGuardHome/log"
"github.com/joomcode/errorx" "github.com/joomcode/errorx"
) )
func trace(format string, args ...interface{}) {
pc := make([]uintptr, 10) // at least 1 entry needed
runtime.Callers(2, pc)
f := runtime.FuncForPC(pc[0])
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())
}
func isTimeout(err error) bool { func isTimeout(err error) bool {
operr, ok := err.(*net.OpError) operr, ok := err.(*net.OpError)
if !ok { if !ok {

2
dhcpd/standalone/main.go
View File

@ -1,7 +1,6 @@
package main package main
import ( import (
"log"
"net" "net"
"os" "os"
"os/signal" "os/signal"
@ -9,6 +8,7 @@ import (
"time" "time"
"github.com/AdguardTeam/AdGuardHome/dhcpd" "github.com/AdguardTeam/AdGuardHome/dhcpd"
"github.com/AdguardTeam/AdGuardHome/log"
"github.com/krolaw/dhcp4" "github.com/krolaw/dhcp4"
) )

2
dns.go
View File

@ -2,11 +2,11 @@ package main
import ( import (
"fmt" "fmt"
"log"
"net" "net"
"github.com/AdguardTeam/AdGuardHome/dnsfilter" "github.com/AdguardTeam/AdGuardHome/dnsfilter"
"github.com/AdguardTeam/AdGuardHome/dnsforward" "github.com/AdguardTeam/AdGuardHome/dnsforward"
"github.com/AdguardTeam/AdGuardHome/log"
"github.com/AdguardTeam/dnsproxy/upstream" "github.com/AdguardTeam/dnsproxy/upstream"
"github.com/joomcode/errorx" "github.com/joomcode/errorx"
) )

2
dnsfilter/dnsfilter.go
View File

@ -8,7 +8,6 @@ import (
"errors" "errors"
"fmt" "fmt"
"io/ioutil" "io/ioutil"
"log"
"net" "net"
"net/http" "net/http"
"regexp" "regexp"
@ -17,6 +16,7 @@ import (
"sync/atomic" "sync/atomic"
"time" "time"
"github.com/AdguardTeam/AdGuardHome/log"
"github.com/bluele/gcache" "github.com/bluele/gcache"
"golang.org/x/net/publicsuffix" "golang.org/x/net/publicsuffix"
) )

31
dnsfilter/dnsfilter_test.go
View File

@ -17,6 +17,7 @@ import (
"os" "os"
"runtime" "runtime"
"github.com/AdguardTeam/AdGuardHome/log"
"github.com/shirou/gopsutil/process" "github.com/shirou/gopsutil/process"
"go.uber.org/goleak" "go.uber.org/goleak"
) )
@ -24,7 +25,7 @@ import (
// first in file because it must be run first // first in file because it must be run first
func TestLotsOfRulesMemoryUsage(t *testing.T) { func TestLotsOfRulesMemoryUsage(t *testing.T) {
start := getRSS() start := getRSS()
trace("RSS before loading rules - %d kB\n", start/1024) log.Tracef("RSS before loading rules - %d kB\n", start/1024)
dumpMemProfile(_Func() + "1.pprof") dumpMemProfile(_Func() + "1.pprof")
d := NewForTest() d := NewForTest()
@ -35,7 +36,7 @@ func TestLotsOfRulesMemoryUsage(t *testing.T) {
} }
afterLoad := getRSS() afterLoad := getRSS()
trace("RSS after loading rules - %d kB (%d kB diff)\n", afterLoad/1024, (afterLoad-start)/1024) log.Tracef("RSS after loading rules - %d kB (%d kB diff)\n", afterLoad/1024, (afterLoad-start)/1024)
dumpMemProfile(_Func() + "2.pprof") dumpMemProfile(_Func() + "2.pprof")
tests := []struct { tests := []struct {
@ -58,7 +59,7 @@ func TestLotsOfRulesMemoryUsage(t *testing.T) {
} }
} }
afterMatch := getRSS() afterMatch := getRSS()
trace("RSS after matching - %d kB (%d kB diff)\n", afterMatch/1024, (afterMatch-afterLoad)/1024) log.Tracef("RSS after matching - %d kB (%d kB diff)\n", afterMatch/1024, (afterMatch-afterLoad)/1024)
dumpMemProfile(_Func() + "3.pprof") dumpMemProfile(_Func() + "3.pprof")
} }
@ -88,20 +89,20 @@ func dumpMemProfile(name string) {
const topHostsFilename = "../tests/top-1m.csv" const topHostsFilename = "../tests/top-1m.csv"
func fetchTopHostsFromNet() { func fetchTopHostsFromNet() {
trace("Fetching top hosts from network") log.Tracef("Fetching top hosts from network")
resp, err := http.Get("http://s3-us-west-1.amazonaws.com/umbrella-static/top-1m.csv.zip") resp, err := http.Get("http://s3-us-west-1.amazonaws.com/umbrella-static/top-1m.csv.zip")
if err != nil { if err != nil {
panic(err) panic(err)
} }
defer resp.Body.Close() defer resp.Body.Close()
trace("Reading zipfile body") log.Tracef("Reading zipfile body")
zipfile, err := ioutil.ReadAll(resp.Body) zipfile, err := ioutil.ReadAll(resp.Body)
if err != nil { if err != nil {
panic(err) panic(err)
} }
trace("Opening zipfile") log.Tracef("Opening zipfile")
r, err := zip.NewReader(bytes.NewReader(zipfile), int64(len(zipfile))) r, err := zip.NewReader(bytes.NewReader(zipfile), int64(len(zipfile)))
if err != nil { if err != nil {
panic(err) panic(err)
@ -111,19 +112,19 @@ func fetchTopHostsFromNet() {
panic(fmt.Errorf("zipfile must have only one entry: %+v", r)) panic(fmt.Errorf("zipfile must have only one entry: %+v", r))
} }
f := r.File[0] f := r.File[0]
trace("Unpacking file %s from zipfile", f.Name) log.Tracef("Unpacking file %s from zipfile", f.Name)
rc, err := f.Open() rc, err := f.Open()
if err != nil { if err != nil {
panic(err) panic(err)
} }
trace("Reading file %s contents", f.Name) log.Tracef("Reading file %s contents", f.Name)
body, err := ioutil.ReadAll(rc) body, err := ioutil.ReadAll(rc)
if err != nil { if err != nil {
panic(err) panic(err)
} }
rc.Close() rc.Close()
trace("Writing file %s contents to disk", f.Name) log.Tracef("Writing file %s contents to disk", f.Name)
err = ioutil.WriteFile(topHostsFilename+".tmp", body, 0644) err = ioutil.WriteFile(topHostsFilename+".tmp", body, 0644)
if err != nil { if err != nil {
panic(err) panic(err)
@ -144,16 +145,16 @@ func getTopHosts() {
func TestLotsOfRulesLotsOfHostsMemoryUsage(t *testing.T) { func TestLotsOfRulesLotsOfHostsMemoryUsage(t *testing.T) {
start := getRSS() start := getRSS()
trace("RSS before loading rules - %d kB\n", start/1024) log.Tracef("RSS before loading rules - %d kB\n", start/1024)
dumpMemProfile(_Func() + "1.pprof") dumpMemProfile(_Func() + "1.pprof")
d := NewForTest() d := NewForTest()
defer d.Destroy() defer d.Destroy()
mustLoadTestRules(d) mustLoadTestRules(d)
trace("Have %d rules", d.Count()) log.Tracef("Have %d rules", d.Count())
afterLoad := getRSS() afterLoad := getRSS()
trace("RSS after loading rules - %d kB (%d kB diff)\n", afterLoad/1024, (afterLoad-start)/1024) log.Tracef("RSS after loading rules - %d kB (%d kB diff)\n", afterLoad/1024, (afterLoad-start)/1024)
dumpMemProfile(_Func() + "2.pprof") dumpMemProfile(_Func() + "2.pprof")
getTopHosts() getTopHosts()
@ -163,7 +164,7 @@ func TestLotsOfRulesLotsOfHostsMemoryUsage(t *testing.T) {
} }
defer hostnames.Close() defer hostnames.Close()
afterHosts := getRSS() afterHosts := getRSS()
trace("RSS after loading hosts - %d kB (%d kB diff)\n", afterHosts/1024, (afterHosts-afterLoad)/1024) log.Tracef("RSS after loading hosts - %d kB (%d kB diff)\n", afterHosts/1024, (afterHosts-afterLoad)/1024)
dumpMemProfile(_Func() + "2.pprof") dumpMemProfile(_Func() + "2.pprof")
{ {
@ -182,7 +183,7 @@ func TestLotsOfRulesLotsOfHostsMemoryUsage(t *testing.T) {
} }
afterMatch := getRSS() afterMatch := getRSS()
trace("RSS after matching - %d kB (%d kB diff)\n", afterMatch/1024, (afterMatch-afterLoad)/1024) log.Tracef("RSS after matching - %d kB (%d kB diff)\n", afterMatch/1024, (afterMatch-afterLoad)/1024)
dumpMemProfile(_Func() + "3.pprof") dumpMemProfile(_Func() + "3.pprof")
} }
@ -236,7 +237,7 @@ func TestSuffixRule(t *testing.T) {
t.Errorf("Result suffix does not match for \"%s\": got \"%s\" expected \"%s\"", testcase.rule, suffix, testcase.suffix) t.Errorf("Result suffix does not match for \"%s\": got \"%s\" expected \"%s\"", testcase.rule, suffix, testcase.suffix)
continue continue
} }
// trace("\"%s\": %v: %s", testcase.rule, isSuffix, suffix) // log.Tracef("\"%s\": %v: %s", testcase.rule, isSuffix, suffix)
} }
} }

18
dnsfilter/helpers.go
View File

@ -1,10 +1,6 @@
package dnsfilter package dnsfilter
import ( import (
"fmt"
"os"
"path"
"runtime"
"strings" "strings"
"sync/atomic" "sync/atomic"
) )
@ -62,17 +58,3 @@ func updateMax(valuePtr *int64, maxPtr *int64) {
// swapping failed because value has changed after reading, try again // swapping failed because value has changed after reading, try again
} }
} }
func trace(format string, args ...interface{}) {
pc := make([]uintptr, 10) // at least 1 entry needed
runtime.Callers(2, pc)
f := runtime.FuncForPC(pc[0])
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())
}

4
dnsforward/dnsforward.go
View File

@ -3,13 +3,13 @@ package dnsforward
import ( import (
"errors" "errors"
"fmt" "fmt"
"log"
"net" "net"
"strings" "strings"
"sync" "sync"
"time" "time"
"github.com/AdguardTeam/AdGuardHome/dnsfilter" "github.com/AdguardTeam/AdGuardHome/dnsfilter"
"github.com/AdguardTeam/AdGuardHome/log"
"github.com/AdguardTeam/dnsproxy/proxy" "github.com/AdguardTeam/dnsproxy/proxy"
"github.com/AdguardTeam/dnsproxy/upstream" "github.com/AdguardTeam/dnsproxy/upstream"
"github.com/joomcode/errorx" "github.com/joomcode/errorx"
@ -283,7 +283,7 @@ func (s *Server) filterDNSRequest(d *proxy.DNSContext) (*dnsfilter.Result, error
// Return immediately if there's an error // Return immediately if there's an error
return nil, errorx.Decorate(err, "dnsfilter failed to check host '%s'", host) return nil, errorx.Decorate(err, "dnsfilter failed to check host '%s'", host)
} else if res.IsFiltered { } else if res.IsFiltered {
// trace("Host %s is filtered, reason - '%s', matched rule: '%s'", host, res.Reason, res.Rule) // log.Tracef("Host %s is filtered, reason - '%s', matched rule: '%s'", host, res.Reason, res.Rule)
d.Res = s.genDNSFilterMessage(d, &res) d.Res = s.genDNSFilterMessage(d, &res)
} }

2
dnsforward/querylog.go
View File

@ -3,7 +3,6 @@ package dnsforward
import ( import (
"encoding/json" "encoding/json"
"fmt" "fmt"
"log"
"net" "net"
"net/http" "net/http"
"strconv" "strconv"
@ -12,6 +11,7 @@ import (
"time" "time"
"github.com/AdguardTeam/AdGuardHome/dnsfilter" "github.com/AdguardTeam/AdGuardHome/dnsfilter"
"github.com/AdguardTeam/AdGuardHome/log"
"github.com/miekg/dns" "github.com/miekg/dns"
) )

4
dnsforward/querylog_file.go
View File

@ -5,11 +5,11 @@ import (
"compress/gzip" "compress/gzip"
"encoding/json" "encoding/json"
"fmt" "fmt"
"log"
"os" "os"
"sync" "sync"
"time" "time"
"github.com/AdguardTeam/AdGuardHome/log"
"github.com/go-test/deep" "github.com/go-test/deep"
) )
@ -221,7 +221,7 @@ func genericLoader(onEntry func(entry *logEntry) error, needMore func() bool, ti
} }
if now.Sub(entry.Time) > timeWindow { if now.Sub(entry.Time) > timeWindow {
// trace("skipping entry") // debug logging // log.Tracef("skipping entry") // debug logging
continue continue
} }

2
dnsforward/querylog_top.go
View File

@ -3,7 +3,6 @@ package dnsforward
import ( import (
"bytes" "bytes"
"fmt" "fmt"
"log"
"net/http" "net/http"
"os" "os"
"path" "path"
@ -14,6 +13,7 @@ import (
"sync" "sync"
"time" "time"
"github.com/AdguardTeam/AdGuardHome/log"
"github.com/bluele/gcache" "github.com/bluele/gcache"
"github.com/miekg/dns" "github.com/miekg/dns"
) )

10
dnsforward/stats.go
View File

@ -3,12 +3,12 @@ package dnsforward
import ( import (
"encoding/json" "encoding/json"
"fmt" "fmt"
"log"
"net/http" "net/http"
"sync" "sync"
"time" "time"
"github.com/AdguardTeam/AdGuardHome/dnsfilter" "github.com/AdguardTeam/AdGuardHome/dnsfilter"
"github.com/AdguardTeam/AdGuardHome/log"
) )
var ( var (
@ -69,7 +69,7 @@ func purgeStats() {
func (p *periodicStats) Inc(name string, when time.Time) { func (p *periodicStats) Inc(name string, when time.Time) {
// calculate how many periods ago this happened // calculate how many periods ago this happened
elapsed := int64(time.Since(when) / p.period) elapsed := int64(time.Since(when) / p.period)
// trace("%s: %v as %v -> [%v]", name, time.Since(when), p.period, elapsed) // log.Tracef("%s: %v as %v -> [%v]", name, time.Since(when), p.period, elapsed)
if elapsed >= statsHistoryElements { if elapsed >= statsHistoryElements {
return // outside of our timeframe return // outside of our timeframe
} }
@ -83,7 +83,7 @@ func (p *periodicStats) Inc(name string, when time.Time) {
func (p *periodicStats) Observe(name string, when time.Time, value float64) { func (p *periodicStats) Observe(name string, when time.Time, value float64) {
// calculate how many periods ago this happened // calculate how many periods ago this happened
elapsed := int64(time.Since(when) / p.period) elapsed := int64(time.Since(when) / p.period)
// trace("%s: %v as %v -> [%v]", name, time.Since(when), p.period, elapsed) // log.Tracef("%s: %v as %v -> [%v]", name, time.Since(when), p.period, elapsed)
if elapsed >= statsHistoryElements { if elapsed >= statsHistoryElements {
return // outside of our timeframe return // outside of our timeframe
} }
@ -92,7 +92,7 @@ func (p *periodicStats) Observe(name string, when time.Time, value float64) {
countname := name + "_count" countname := name + "_count"
currentValues := p.Entries[countname] currentValues := p.Entries[countname]
value := currentValues[elapsed] value := currentValues[elapsed]
// trace("Will change p.Entries[%s][%d] from %v to %v", countname, elapsed, value, value+1) // log.Tracef("Will change p.Entries[%s][%d] from %v to %v", countname, elapsed, value, value+1)
value += 1 value += 1
currentValues[elapsed] = value currentValues[elapsed] = value
p.Entries[countname] = currentValues p.Entries[countname] = currentValues
@ -145,7 +145,7 @@ type counter struct {
} }
func newDNSCounter(name string) *counter { func newDNSCounter(name string) *counter {
// trace("called") // log.Tracef("called")
return &counter{ return &counter{
name: name, name: name,
} }

2
filter.go
View File

@ -3,7 +3,6 @@ package main
import ( import (
"fmt" "fmt"
"io/ioutil" "io/ioutil"
"log"
"os" "os"
"path/filepath" "path/filepath"
"reflect" "reflect"
@ -13,6 +12,7 @@ import (
"time" "time"
"github.com/AdguardTeam/AdGuardHome/dnsfilter" "github.com/AdguardTeam/AdGuardHome/dnsfilter"
"github.com/AdguardTeam/AdGuardHome/log"
) )
var ( var (

15
helpers.go
View File

@ -3,7 +3,6 @@ package main
import ( import (
"bufio" "bufio"
"errors" "errors"
"fmt"
"io" "io"
"io/ioutil" "io/ioutil"
"net/http" "net/http"
@ -135,17 +134,3 @@ func _Func() string {
f := runtime.FuncForPC(pc[0]) f := runtime.FuncForPC(pc[0])
return path.Base(f.Name()) return path.Base(f.Name())
} }
func trace(format string, args ...interface{}) {
pc := make([]uintptr, 10) // at least 1 entry needed
runtime.Callers(2, pc)
f := runtime.FuncForPC(pc[0])
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())
}

3
i18n.go
View File

@ -3,9 +3,10 @@ package main
import ( import (
"fmt" "fmt"
"io/ioutil" "io/ioutil"
"log"
"net/http" "net/http"
"strings" "strings"
"github.com/AdguardTeam/AdGuardHome/log"
) )
// -------------------- // --------------------

22
log/log.go
View File

@ -12,12 +12,34 @@ import (
var Verbose = false var Verbose = false
// Print calls Output to print to the standard logger.
// Arguments are handled in the manner of fmt.Print.
func Print(v ...interface{}) {
log.Print(v...)
}
// Printf calls Output to print to the standard logger. // Printf calls Output to print to the standard logger.
// Arguments are handled in the manner of fmt.Printf. // Arguments are handled in the manner of fmt.Printf.
func Printf(format string, v ...interface{}) { func Printf(format string, v ...interface{}) {
log.Printf(format, v...) log.Printf(format, v...)
} }
// Println calls Output to print to the standard logger.
// Arguments are handled in the manner of fmt.Println.
func Println(v ...interface{}) {
log.Println(v...)
}
// Fatal is equivalent to Print() followed by a call to os.Exit(1).
func Fatal(v ...interface{}) {
log.Fatal(v...)
}
// Fatalf is equivalent to Printf() followed by a call to os.Exit(1).
func Fatalf(format string, v ...interface{}) {
log.Fatalf(format, v...)
}
func Tracef(format string, v ...interface{}) { func Tracef(format string, v ...interface{}) {
if Verbose { if Verbose {
pc := make([]uintptr, 10) // at least 1 entry needed pc := make([]uintptr, 10) // at least 1 entry needed

2
upgrade.go
View File

@ -3,10 +3,10 @@ package main
import ( import (
"fmt" "fmt"
"io/ioutil" "io/ioutil"
"log"
"os" "os"
"path/filepath" "path/filepath"
"github.com/AdguardTeam/AdGuardHome/log"
"gopkg.in/yaml.v2" "gopkg.in/yaml.v2"
) )