Fix logging prefixes in resolver package

This commit is contained in:
Daniel 2020-04-02 17:08:43 +02:00
parent dc32e72b3a
commit 180f27307c
9 changed files with 58 additions and 53 deletions

View file

@ -8,6 +8,7 @@ import (
"github.com/safing/portmaster/status"
)
// Configuration Keys
var (
defaultNameServers = []string{
// Collection of default DNS Servers

View file

@ -1,5 +1,5 @@
/*
package resolver is responsible for fetching intelligence data, including DNS, on remote entities.
Package resolver is responsible for querying DNS.
DNS Servers
@ -25,6 +25,5 @@ Reverse lookups on local address ranges (10/8, 172.16/12, 192.168/16, fe80::/7)
Special domains ("example.", "example.com.", "example.net.", "example.org.", "invalid.", "test.", "onion.") are resolved using search scopes and local resolvers.
All other domains are resolved using search scopes and all available resolvers.
*/
package resolver

View file

@ -17,7 +17,7 @@ var (
)
func init() {
module = modules.Register("resolver", prep, start, nil, "core", "network")
module = modules.Register("resolver", prep, start, nil, "core", "netenv")
}
func prep() error {
@ -31,12 +31,12 @@ func start() error {
loadResolvers()
err := module.RegisterEventHook(
"network",
"netenv",
"network changed",
"update nameservers",
func(_ context.Context, _ interface{}) error {
loadResolvers()
log.Debug("intel: reloaded nameservers due to network change")
log.Debug("resolver: reloaded nameservers due to network change")
return nil
},
)

View file

@ -1,6 +1,11 @@
package resolver
import (
// portmaster tests helper
_ "github.com/safing/portmaster/core/pmtesting"
"testing"
"github.com/safing/portmaster/core/pmtesting"
)
func TestMain(m *testing.M) {
pmtesting.TestMain(m, module)
}

View file

@ -132,7 +132,7 @@ func handleMDNSMessages(ctx context.Context, messages chan *dns.Msg) error {
case <-ctx.Done():
return nil
case message := <-messages:
// log.Tracef("intel: got net mdns message: %s", message)
// log.Tracef("resolver: got net mdns message: %s", message)
var err error
var question *dns.Question
@ -146,19 +146,19 @@ func handleMDNSMessages(ctx context.Context, messages chan *dns.Msg) error {
// continue if not response
if !message.Response {
// log.Tracef("intel: mdns message has no response, ignoring")
// log.Tracef("resolver: mdns message has no response, ignoring")
continue
}
// continue if rcode is not success
if message.Rcode != dns.RcodeSuccess {
// log.Tracef("intel: mdns message has error, ignoring")
// log.Tracef("resolver: mdns message has error, ignoring")
continue
}
// continue if answer section is empty
if len(message.Answer) == 0 {
// log.Tracef("intel: mdns message has no answers, ignoring")
// log.Tracef("resolver: mdns message has no answers, ignoring")
continue
}
@ -270,7 +270,7 @@ func handleMDNSMessages(ctx context.Context, messages chan *dns.Msg) error {
rrCache.Clean(60)
err := rrCache.Save()
if err != nil {
log.Warningf("intel: failed to cache RR %s: %s", rrCache.Domain, err)
log.Warningf("resolver: failed to cache RR %s: %s", rrCache.Domain, err)
}
// return finished response
@ -296,9 +296,9 @@ func handleMDNSMessages(ctx context.Context, messages chan *dns.Msg) error {
rrCache.Clean(60)
err := rrCache.Save()
if err != nil {
log.Warningf("intel: failed to cache RR %s: %s", rrCache.Domain, err)
log.Warningf("resolver: failed to cache RR %s: %s", rrCache.Domain, err)
}
// log.Tracef("intel: mdns scavenged %s", k)
// log.Tracef("resolver: mdns scavenged %s", k)
}
}
@ -316,12 +316,12 @@ func listenForDNSPackets(conn *net.UDPConn, messages chan *dns.Msg) error {
if module.IsStopping() {
return nil
}
log.Debugf("intel: failed to read packet: %s", err)
log.Debugf("resolver: failed to read packet: %s", err)
return err
}
message := new(dns.Msg)
if err = message.Unpack(buf[:n]); err != nil {
log.Debugf("intel: failed to unpack message: %s", err)
log.Debugf("resolver: failed to unpack message: %s", err)
continue
}
messages <- message
@ -335,7 +335,7 @@ func queryMulticastDNS(ctx context.Context, q *Query) (*RRCache, error) {
}
// trace log
log.Tracer(ctx).Trace("intel: resolving with mDNS")
log.Tracer(ctx).Trace("resolver: resolving with mDNS")
// create query
dnsQuery := new(dns.Msg)

View file

@ -75,7 +75,7 @@ func Resolve(ctx context.Context, q *Query) (rrCache *RRCache, err error) {
}
// log
log.Tracer(ctx).Tracef("intel: resolving %s%s", q.FQDN, q.QType)
log.Tracer(ctx).Tracef("resolver: resolving %s%s", q.FQDN, q.QType)
// check query compliance
if err = q.checkCompliance(); err != nil {
@ -116,8 +116,8 @@ func checkCache(ctx context.Context, q *Query) *RRCache {
// failed to get from cache
if err != nil {
if err != database.ErrNotFound {
log.Tracer(ctx).Warningf("intel: getting RRCache %s%s from database failed: %s", q.FQDN, q.QType.String(), err)
log.Warningf("intel: getting RRCache %s%s from database failed: %s", q.FQDN, q.QType.String(), err)
log.Tracer(ctx).Warningf("resolver: getting RRCache %s%s from database failed: %s", q.FQDN, q.QType.String(), err)
log.Warningf("resolver: getting RRCache %s%s from database failed: %s", q.FQDN, q.QType.String(), err)
}
return nil
}
@ -131,7 +131,7 @@ func checkCache(ctx context.Context, q *Query) *RRCache {
// check compliance of resolver
err = resolver.checkCompliance(ctx, q)
if err != nil {
log.Tracer(ctx).Debugf("intel: cached entry for %s%s does not comply to query parameters: %s", q.FQDN, q.QType.String(), err)
log.Tracer(ctx).Debugf("resolver: cached entry for %s%s does not comply to query parameters: %s", q.FQDN, q.QType.String(), err)
return nil
}
@ -141,7 +141,7 @@ func checkCache(ctx context.Context, q *Query) *RRCache {
rrCache.requestingNew = true
rrCache.Unlock()
log.Tracer(ctx).Trace("intel: serving from cache, requesting new")
log.Tracer(ctx).Trace("resolver: serving from cache, requesting new")
// resolve async
module.StartMediumPriorityMicroTask(&mtAsyncResolve, func(ctx context.Context) error {
@ -167,7 +167,7 @@ func deduplicateRequest(ctx context.Context, q *Query) (finishRequest func()) {
dupReqLock.Unlock()
// log that we are waiting
log.Tracer(ctx).Tracef("intel: waiting for duplicate query for %s to complete", dupKey)
log.Tracer(ctx).Tracef("resolver: waiting for duplicate query for %s to complete", dupKey)
// wait
wg.Wait()
// done!
@ -217,7 +217,7 @@ resolveLoop:
for _, resolver := range resolvers {
// check if resolver failed recently (on first run)
if i == 0 && resolver.Conn.LastFail().After(lastFailBoundary) {
log.Tracer(ctx).Tracef("intel: skipping resolver %s, because it failed recently", resolver)
log.Tracer(ctx).Tracef("resolver: skipping resolver %s, because it failed recently", resolver)
continue
}
@ -267,7 +267,7 @@ resolveLoop:
rrCache.Clean(600)
err = rrCache.Save()
if err != nil {
log.Warningf("intel: failed to cache RR for %s%s: %s", q.FQDN, q.QType.String(), err)
log.Warningf("resolver: failed to cache RR for %s%s: %s", q.FQDN, q.QType.String(), err)
}
}

View file

@ -8,7 +8,7 @@ import (
"github.com/miekg/dns"
"github.com/safing/portbase/log"
"github.com/safing/portmaster/network/environment"
"github.com/safing/portmaster/netenv"
)
// DNS Resolver Attributes
@ -69,7 +69,7 @@ type BasicResolverConn struct {
// MarkFailed marks the resolver as failed.
func (brc *BasicResolverConn) MarkFailed() {
if !environment.Online() {
if !netenv.Online() {
// don't mark failed if we are offline
return
}
@ -103,22 +103,22 @@ func (brc *BasicResolverConn) Query(ctx context.Context, q *Query) (*RRCache, er
// log query time
// qStart := time.Now()
reply, _, err = brc.clientManager.getDNSClient().Exchange(dnsQuery, resolver.ServerAddress)
// log.Tracef("intel: query to %s took %s", resolver.Server, time.Now().Sub(qStart))
// log.Tracef("resolver: query to %s took %s", resolver.Server, time.Now().Sub(qStart))
// error handling
if err != nil {
log.Tracer(ctx).Tracef("intel: query to %s encountered error: %s", resolver.Server, err)
log.Tracer(ctx).Tracef("resolver: query to %s encountered error: %s", resolver.Server, err)
// TODO: handle special cases
// 1. connect: network is unreachable
// 2. timeout
// hint network environment at failed connection
environment.ReportFailedConnection()
netenv.ReportFailedConnection()
// temporary error
if nerr, ok := err.(net.Error); ok && nerr.Timeout() {
log.Tracer(ctx).Tracef("intel: retrying to resolve %s%s with %s, error is temporary", q.FQDN, q.QType, resolver.Server)
log.Tracer(ctx).Tracef("resolver: retrying to resolve %s%s with %s, error is temporary", q.FQDN, q.QType, resolver.Server)
continue
}
@ -132,11 +132,11 @@ func (brc *BasicResolverConn) Query(ctx context.Context, q *Query) (*RRCache, er
if err != nil {
return nil, err
// FIXME: mark as failed
// TODO: mark as failed
}
// hint network environment at successful connection
environment.ReportSuccessfulConnection()
netenv.ReportSuccessfulConnection()
new := &RRCache{
Domain: q.FQDN,

View file

@ -13,7 +13,7 @@ import (
"github.com/miekg/dns"
"github.com/safing/portbase/log"
"github.com/safing/portmaster/network/environment"
"github.com/safing/portmaster/netenv"
"github.com/safing/portmaster/network/netutils"
)
@ -108,7 +108,7 @@ configuredServersLoop:
parts := strings.Split(server, "|")
if len(parts) < 2 {
log.Warningf("intel: nameserver format invalid: %s", server)
log.Warningf("resolver: nameserver format invalid: %s", server)
continue configuredServersLoop
}
@ -117,14 +117,14 @@ configuredServersLoop:
if err == nil {
ipScope = netutils.ClassifyIP(ip)
if ipScope == netutils.HostLocal {
log.Warningf(`intel: cannot use configured localhost nameserver "%s"`, server)
log.Warningf(`resolver: cannot use configured localhost nameserver "%s"`, server)
continue configuredServersLoop
}
} else {
if strings.ToLower(parts[0]) == "doh" {
ipScope = netutils.Global
} else {
log.Warningf("intel: nameserver (%s) address invalid: %s", server, err)
log.Warningf("resolver: nameserver (%s) address invalid: %s", server, err)
continue configuredServersLoop
}
}
@ -152,7 +152,7 @@ configuredServersLoop:
newConn.clientManager = newTCPClientManager(new)
case "dot":
if len(parts) < 3 {
log.Warningf("intel: nameserver missing verification domain as third parameter: %s", server)
log.Warningf("resolver: nameserver missing verification domain as third parameter: %s", server)
continue configuredServersLoop
}
new.VerifyDomain = parts[2]
@ -164,7 +164,7 @@ configuredServersLoop:
}
newConn.clientManager = newHTTPSClientManager(new)
default:
log.Warningf("intel: nameserver (%s) type invalid: %s", server, parts[0])
log.Warningf("resolver: nameserver (%s) type invalid: %s", server, parts[0])
continue configuredServersLoop
}
newResolvers = append(newResolvers, new)
@ -174,7 +174,7 @@ configuredServersLoop:
}
// add local resolvers
assignedNameservers := environment.Nameservers()
assignedNameservers := netenv.Nameservers()
assignedServersLoop:
for _, nameserver := range assignedNameservers {
server := fmt.Sprintf("dns|%s", urlFormatAddress(nameserver.IP, 53))
@ -187,7 +187,7 @@ assignedServersLoop:
ipScope := netutils.ClassifyIP(nameserver.IP)
if ipScope == netutils.HostLocal {
log.Infof(`intel: cannot use assigned localhost nameserver at %s`, nameserver.IP)
log.Infof(`resolver: cannot use assigned localhost nameserver at %s`, nameserver.IP)
continue assignedServersLoop
}
@ -232,7 +232,7 @@ assignedServersLoop:
// save resolvers
globalResolvers = newResolvers
if len(globalResolvers) == 0 {
log.Criticalf("intel: no (valid) dns servers found in configuration and system")
log.Criticalf("resolver: no (valid) dns servers found in configuration and system")
}
// make list with local resolvers
@ -276,41 +276,41 @@ assignedServersLoop:
// log global resolvers
if len(globalResolvers) > 0 {
log.Trace("intel: loaded global resolvers:")
log.Trace("resolver: loaded global resolvers:")
for _, resolver := range globalResolvers {
log.Tracef("intel: %s", resolver.Server)
log.Tracef("resolver: %s", resolver.Server)
}
} else {
log.Warning("intel: no global resolvers loaded")
log.Warning("resolver: no global resolvers loaded")
}
// log local resolvers
if len(localResolvers) > 0 {
log.Trace("intel: loaded local resolvers:")
log.Trace("resolver: loaded local resolvers:")
for _, resolver := range localResolvers {
log.Tracef("intel: %s", resolver.Server)
log.Tracef("resolver: %s", resolver.Server)
}
} else {
log.Info("intel: no local resolvers loaded")
log.Info("resolver: no local resolvers loaded")
}
// log scopes
if len(localScopes) > 0 {
log.Trace("intel: loaded scopes:")
log.Trace("resolver: loaded scopes:")
for _, scope := range localScopes {
var scopeServers []string
for _, resolver := range scope.Resolvers {
scopeServers = append(scopeServers, resolver.Server)
}
log.Tracef("intel: %s: %s", scope.Domain, strings.Join(scopeServers, ", "))
log.Tracef("resolver: %s: %s", scope.Domain, strings.Join(scopeServers, ", "))
}
} else {
log.Info("intel: no scopes loaded")
log.Info("resolver: no scopes loaded")
}
// alert if no resolvers are loaded
if len(globalResolvers) == 0 && len(localResolvers) == 0 {
log.Critical("intel: no resolvers loaded!")
log.Critical("resolver: no resolvers loaded!")
}
}

View file

@ -14,7 +14,7 @@ func ResolveIPAndValidate(ctx context.Context, ip string, securityLevel uint8) (
// get reversed DNS address
reverseIP, err := dns.ReverseAddr(ip)
if err != nil {
log.Tracef("intel: failed to get reverse address of %s: %s", ip, err)
log.Tracef("resolver: failed to get reverse address of %s: %s", ip, err)
return "", ErrInvalid
}