Pull request: AGDNS-2202-slog-vol-5

Squashed commit of the following:

commit 15bc993
Merge: 8bc8e4d 2a1c257
Author: Dimitry Kolyshev <[email protected]>
Date:   Thu Jul 4 15:46:14 2024 +0300

    Merge remote-tracking branch 'origin/master' into AGDNS-2202-slog-vol-5

commit 8bc8e4d
Author: Dimitry Kolyshev <[email protected]>
Date:   Thu Jul 4 14:09:42 2024 +0300

    upstream: imp code

commit eef7afb
Merge: 3bd3f90 2847564
Author: Dimitry Kolyshev <[email protected]>
Date:   Wed Jul 3 16:09:53 2024 +0300

    Merge remote-tracking branch 'origin/master' into AGDNS-2202-slog-vol-5

commit 3bd3f90
Author: Dimitry Kolyshev <[email protected]>
Date:   Wed Jul 3 16:05:46 2024 +0300

    main: imp code

commit 262e0e4
Author: Dimitry Kolyshev <[email protected]>
Date:   Wed Jul 3 11:32:37 2024 +0300

    main: fix aglog

commit 27c1858
Author: Dimitry Kolyshev <[email protected]>
Date:   Wed Jul 3 08:34:16 2024 +0300

    upstream: imp code

commit cf84c5f
Author: Dimitry Kolyshev <[email protected]>
Date:   Tue Jul 2 12:32:44 2024 +0300

    scripts: blocklist log

commit 9e8fdd6
Author: Dimitry Kolyshev <[email protected]>
Date:   Tue Jul 2 12:27:36 2024 +0300

    upstream: slog

commit 5f1ebe9
Author: Dimitry Kolyshev <[email protected]>
Date:   Tue Jul 2 11:58:27 2024 +0300

    upstream: slog

main.go

@@ -235,7 +235,7 @@ func main() {
 
 	l := slogutil.New(&slogutil.Config{
 		Output: logOutput,
-		Format: slogutil.FormatAdGuardLegacy,
+		Format: slogutil.FormatDefault,
 		// TODO(d.kolyshev): Consider making configurable.
 		AddTimestamp: true,
 		Verbose:      opts.Verbose,
@@ -587,7 +587,7 @@ func initBootstrap(
 
 	switch len(resolvers) {
 	case 0:
-		etcHosts, hostsErr := upstream.NewDefaultHostsResolver(osutil.RootDirFS())
+		etcHosts, hostsErr := upstream.NewDefaultHostsResolver(osutil.RootDirFS(), l)
 		if hostsErr != nil {
 			l.ErrorContext(ctx, "creating default hosts resolver", slogutil.KeyError, hostsErr)
 

scripts/make/go-lint.sh

@@ -63,12 +63,12 @@ set -f -u
 # schemas, which use package reflect.  If your project needs more exceptions,
 # add and document them.
 #
-# TODO(a.garipov): Add golibs/log.
 # TODO(a.garipov): Add deprecated package golang.org/x/exp/maps once all
 # projects switch to Go 1.23.
 blocklist_imports() {
 	git grep\
 		-e '[[:space:]]"errors"$'\
+		-e '[[:space:]]"github.com/AdguardTeam/golibs/log"$'\
 		-e '[[:space:]]"golang.org/x/exp/slices"$'\
 		-e '[[:space:]]"golang.org/x/net/context"$'\
 		-e '[[:space:]]"io/ioutil"$'\

upstream/doh.go

@@ -224,8 +224,8 @@ func (p *dnsOverHTTPS) exchangeHTTPS(client *http.Client, req *dns.Msg) (resp *d
 		n = networkUDP
 	}
 
-	logBegin(p.addrRedacted, n, req)
-	defer func() { logFinish(p.addrRedacted, n, err) }()
+	logBegin(p.logger, p.addrRedacted, n, req)
+	defer func() { logFinish(p.logger, p.addrRedacted, n, err) }()
 
 	return p.exchangeHTTPSClient(client, req)
 }

upstream/doq.go

@@ -213,8 +213,8 @@ func (p *dnsOverQUIC) Close() (err error) {
 func (p *dnsOverQUIC) exchangeQUIC(req *dns.Msg, conn quic.Connection) (resp *dns.Msg, err error) {
 	addr := p.Address()
 
-	logBegin(addr, networkUDP, req)
-	defer func() { logFinish(addr, networkUDP, err) }()
+	logBegin(p.logger, addr, networkUDP, req)
+	defer func() { logFinish(p.logger, addr, networkUDP, err) }()
 
 	buf, err := req.Pack()
 	if err != nil {

upstream/dot.go

@@ -195,8 +195,8 @@ func (p *dnsOverTLS) putBack(conn net.Conn) {
 func (p *dnsOverTLS) exchangeWithConn(conn net.Conn, m *dns.Msg) (reply *dns.Msg, err error) {
 	addr := p.Address()
 
-	logBegin(addr, networkTCP, m)
-	defer func() { logFinish(addr, networkTCP, err) }()
+	logBegin(p.logger, addr, networkTCP, m)
+	defer func() { logFinish(p.logger, addr, networkTCP, err) }()
 
 	dnsConn := dns.Conn{Conn: conn}
 

upstream/hostsresolver.go

@@ -4,12 +4,12 @@ import (
 	"context"
 	"fmt"
 	"io/fs"
+	"log/slog"
 	"net/netip"
 	"slices"
 
 	"github.com/AdguardTeam/golibs/errors"
 	"github.com/AdguardTeam/golibs/hostsfile"
-	"github.com/AdguardTeam/golibs/log"
 )
 
 // HostsResolver is a [Resolver] that looks into system hosts files, see
@@ -27,8 +27,14 @@ func NewHostsResolver(hosts hostsfile.Storage) (hr *HostsResolver) {
 }
 
 // NewDefaultHostsResolver returns a resolver based on system hosts files
-// provided by the [hostsfile.DefaultHostsPaths] and read from rootFSys.
-func NewDefaultHostsResolver(rootFSys fs.FS) (hr *HostsResolver, err error) {
+// provided by the [hostsfile.DefaultHostsPaths] and read from rootFSys.  In
+// case the file by any default path doesn't exist it adds a log debug record.
+// If l is nil, [slog.Default] is used.
+func NewDefaultHostsResolver(rootFSys fs.FS, l *slog.Logger) (hr *HostsResolver, err error) {
+	if l == nil {
+		l = slog.Default()
+	}
+
 	paths, err := hostsfile.DefaultHostsPaths()
 	if err != nil {
 		return nil, fmt.Errorf("getting default hosts paths: %w", err)
@@ -37,7 +43,7 @@ func NewDefaultHostsResolver(rootFSys fs.FS) (hr *HostsResolver, err error) {
 	// The error is always nil here since no readers passed.
 	strg, _ := hostsfile.NewDefaultStorage()
 	for _, filename := range paths {
-		err = parseHostsFile(rootFSys, strg, filename)
+		err = parseHostsFile(rootFSys, strg, filename, l)
 		if err != nil {
 			// Don't wrap the error since it's already informative enough as is.
 			return nil, err
@@ -48,11 +54,11 @@ func NewDefaultHostsResolver(rootFSys fs.FS) (hr *HostsResolver, err error) {
 }
 
 // parseHostsFile reads a single hosts file from fsys and parses it into hosts.
-func parseHostsFile(fsys fs.FS, hosts hostsfile.Set, filename string) (err error) {
+func parseHostsFile(fsys fs.FS, hosts hostsfile.Set, filename string, l *slog.Logger) (err error) {
 	f, err := fsys.Open(filename)
 	if err != nil {
 		if errors.Is(err, fs.ErrNotExist) {
-			log.Debug("hosts file %q doesn't exist", filename)
+			l.Debug("hosts file does not exist", "filename", filename)
 
 			return nil
 		}

upstream/hostsresolver_test.go

@@ -8,6 +8,7 @@ import (
 
 	"github.com/AdguardTeam/dnsproxy/upstream"
 	"github.com/AdguardTeam/golibs/hostsfile"
+	"github.com/AdguardTeam/golibs/logutil/slogutil"
 	"github.com/AdguardTeam/golibs/testutil"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
@@ -34,7 +35,7 @@ func TestHostsResolver_LookupNetIP(t *testing.T) {
 		},
 	}
 
-	hr, err := upstream.NewDefaultHostsResolver(fsys)
+	hr, err := upstream.NewDefaultHostsResolver(fsys, slogutil.NewDiscardLogger())
 	require.NoError(t, err)
 
 	testCases := []struct {

upstream/parallel.go

@@ -3,10 +3,8 @@ package upstream
 import (
 	"fmt"
 	"slices"
-	"time"
 
 	"github.com/AdguardTeam/golibs/errors"
-	"github.com/AdguardTeam/golibs/log"
 	"github.com/miekg/dns"
 )
 
@@ -19,15 +17,15 @@ const (
 	ErrNoReply errors.Error = "no reply"
 )
 
-// ExchangeParallel returns the dirst successful response from one of u.  It
+// ExchangeParallel returns the first successful response from one of u.  It
 // returns an error if all upstreams failed to exchange the request.
 func ExchangeParallel(ups []Upstream, req *dns.Msg) (reply *dns.Msg, resolved Upstream, err error) {
 	upsNum := len(ups)
 	switch upsNum {
 	case 0:
 		return nil, nil, ErrNoUpstreams
 	case 1:
-		reply, err = exchangeAndLog(ups[0], req)
+		reply, err = ups[0].Exchange(req)
 
 		return reply, ups[0], err
 	default:
@@ -81,7 +79,7 @@ func ExchangeAll(ups []Upstream, req *dns.Msg) (res []ExchangeAllResult, err err
 		return nil, ErrNoUpstreams
 	case 1:
 		var reply *dns.Msg
-		reply, err = exchangeAndLog(ups[0], req)
+		reply, err = ups[0].Exchange(req)
 		if err != nil {
 			return nil, err
 		} else if reply == nil {
@@ -141,30 +139,10 @@ func receiveAsyncResult(resCh chan any) (res *ExchangeAllResult, err error) {
 // exchangeAsync tries to resolve DNS request with one upstream and sends the
 // result to respCh.
 func exchangeAsync(u Upstream, req *dns.Msg, resCh chan any) {
-	reply, err := exchangeAndLog(u, req)
+	reply, err := u.Exchange(req)
 	if err != nil {
 		resCh <- err
 	} else {
 		resCh <- &ExchangeAllResult{Resp: reply, Upstream: u}
 	}
 }
-
-// exchangeAndLog wraps the [Upstream.Exchange] method with logging.
-func exchangeAndLog(u Upstream, req *dns.Msg) (resp *dns.Msg, err error) {
-	addr := u.Address()
-	req = req.Copy()
-
-	start := time.Now()
-	reply, err := u.Exchange(req)
-	dur := time.Since(start)
-
-	if len(req.Question) > 0 {
-		if q := &req.Question[0]; err == nil {
-			log.Debug("dnsproxy: upstream %s exchanged %s successfully in %s", addr, q, dur)
-		} else {
-			log.Debug("dnsproxy: upstream %s failed to exchange %s in %s: %s", addr, q, dur, err)
-		}
-	}
-
-	return reply, err
-}

upstream/plain.go

@@ -99,8 +99,8 @@ func (p *plainDNS) dialExchange(
 		conn.UDPSize = dns.MinMsgSize
 	}
 
-	logBegin(addr, network, req)
-	defer func() { logFinish(addr, network, err) }()
+	logBegin(p.logger, addr, network, req)
+	defer func() { logFinish(p.logger, addr, network, err) }()
 
 	ctx := context.Background()
 	conn.Conn, err = dial(ctx, network, "")

upstream/upstream.go

@@ -19,7 +19,6 @@ import (
 
 	"github.com/AdguardTeam/dnsproxy/internal/bootstrap"
 	"github.com/AdguardTeam/golibs/errors"
-	"github.com/AdguardTeam/golibs/log"
 	"github.com/AdguardTeam/golibs/logutil/slogutil"
 	"github.com/AdguardTeam/golibs/netutil"
 	"github.com/ameshkov/dnscrypt/v2"
@@ -321,33 +320,33 @@ func addPort(u *url.URL, port uint16) {
 // logBegin logs the start of DNS request resolution.  It should be called right
 // before dialing the connection to the upstream.  n is the [network] that will
 // be used to send the request.
-func logBegin(addr string, n network, req *dns.Msg) {
+func logBegin(l *slog.Logger, addr string, n network, req *dns.Msg) {
 	var qtype dns.Type
 	var qname string
 	if len(req.Question) != 0 {
 		qtype = dns.Type(req.Question[0].Qtype)
 		qname = req.Question[0].Name
 	}
 
-	log.Debug("dnsproxy: sending request to %s over %s: %s %q", addr, n, qtype, qname)
+	l.Debug("sending request", "addr", addr, "proto", n, "qtype", qtype, "qname", qname)
 }
 
 // logFinish logs the end of DNS request resolution.  It should be called right
 // after receiving the response from the upstream or the failing action.  n is
 // the [network] that was used to send the request.
-func logFinish(addr string, n network, err error) {
-	logRoutine := log.Debug
-
+func logFinish(l *slog.Logger, addr string, n network, err error) {
+	lvl := slog.LevelDebug
 	status := "ok"
+
 	if err != nil {
 		status = err.Error()
 		if isTimeout(err) {
 			// Notify user about the timeout.
-			logRoutine = log.Error
+			lvl = slog.LevelError
 		}
 	}
 
-	logRoutine("dnsproxy: %s: response received over %s: %q", addr, n, status)
+	l.Log(context.TODO(), lvl, "response received", "addr", addr, "proto", n, "status", status)
 }
 
 // isTimeout returns true if err is a timeout error.