upstream: slog

main.go

@@ -507,6 +507,7 @@ func (opts *Options) initUpstreams(
 
 	timeout := opts.Timeout.Duration
 	bootOpts := &upstream.Options{
+		Logger:             l,
 		HTTPVersions:       httpVersions,
 		InsecureSkipVerify: opts.Insecure,
 		Timeout:            timeout,

proxy/lookup_test.go

@@ -6,6 +6,7 @@ import (
 	"testing"
 
 	"github.com/AdguardTeam/dnsproxy/upstream"
+	"github.com/AdguardTeam/golibs/logutil/slogutil"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
 )
@@ -14,7 +15,10 @@ func TestLookupNetIP(t *testing.T) {
 	// Use AdGuard DNS here.
 	dnsUpstream, err := upstream.AddressToUpstream(
 		"94.140.14.14",
-		&upstream.Options{Timeout: defaultTimeout},
+		&upstream.Options{
+			Logger:  slogutil.NewDiscardLogger(),
+			Timeout: defaultTimeout,
+		},
 	)
 	require.NoError(t, err)
 

proxy/proxy_test.go

@@ -220,7 +220,10 @@ func newTestUpstreamConfigWithBoot(
 ) (u *UpstreamConfig) {
 	googleRslv, err := upstream.NewUpstreamResolver(
 		"8.8.8.8:53",
-		&upstream.Options{Timeout: timeout},
+		&upstream.Options{
+			Logger:  slogutil.NewDiscardLogger(),
+			Timeout: timeout,
+		},
 	)
 	require.NoError(t, err)
 
@@ -826,6 +829,7 @@ func TestFallbackFromInvalidBootstrap(t *testing.T) {
 	t.Parallel()
 
 	invalidRslv, err := upstream.NewUpstreamResolver("8.8.8.8:555", &upstream.Options{
+		Logger:  slogutil.NewDiscardLogger(),
 		Timeout: testTimeout,
 	})
 	require.NoError(t, err)

proxy/upstreams.go

@@ -95,7 +95,9 @@ func ParseUpstreamsConfig(
 	opts *upstream.Options,
 ) (conf *UpstreamConfig, err error) {
 	if opts == nil {
-		opts = &upstream.Options{}
+		opts = &upstream.Options{
+			Logger: slog.Default(),
+		}
 	}
 
 	p := &configParser{

upstream/dnscrypt.go

@@ -3,13 +3,13 @@ package upstream
 import (
 	"fmt"
 	"io"
+	"log/slog"
 	"net/url"
 	"os"
 	"sync"
 	"time"
 
 	"github.com/AdguardTeam/golibs/errors"
-	"github.com/AdguardTeam/golibs/log"
 	"github.com/ameshkov/dnscrypt/v2"
 	"github.com/miekg/dns"
 )
@@ -28,6 +28,9 @@ type dnsCrypt struct {
 	// addr is the DNSCrypt server URL.
 	addr *url.URL
 
+	// logger is used for exchange logging.  It is never nil.
+	logger *slog.Logger
+
 	// verifyCert is a callback that verifies the resolver's certificate.
 	verifyCert func(cert *dnscrypt.Cert) (err error)
 
@@ -40,6 +43,7 @@ func newDNSCrypt(addr *url.URL, opts *Options) (u *dnsCrypt) {
 	return &dnsCrypt{
 		mu:         &sync.RWMutex{},
 		addr:       addr,
+		logger:     opts.Logger,
 		verifyCert: opts.VerifyDNSCryptCertificate,
 		timeout:    opts.Timeout,
 	}
@@ -107,7 +111,11 @@ func (p *dnsCrypt) exchangeDNSCrypt(m *dns.Msg) (resp *dns.Msg, err error) {
 	resp, err = client.Exchange(m, resolverInfo)
 	if resp != nil && resp.Truncated {
 		q := &m.Question[0]
-		log.Debug("dnscrypt %s: received truncated, falling back to tcp with %s", p.addr, q)
+		p.logger.Debug(
+			"dnscrypt received truncated, falling back to tcp",
+			"addr", p.addr,
+			"question", q,
+		)
 
 		tcpClient := &dnscrypt.Client{Timeout: p.timeout, Net: networkTCP}
 		resp, err = tcpClient.Exchange(m, resolverInfo)

upstream/dnscrypt_internal_test.go

@@ -10,6 +10,7 @@ import (
 	"time"
 
 	"github.com/AdguardTeam/golibs/errors"
+	"github.com/AdguardTeam/golibs/logutil/slogutil"
 	"github.com/AdguardTeam/golibs/netutil"
 	"github.com/AdguardTeam/golibs/testutil"
 	"github.com/ameshkov/dnscrypt/v2"
@@ -92,7 +93,10 @@ func TestUpstreamDNSCrypt(t *testing.T) {
 
 	// AdGuard DNS (DNSCrypt)
 	address := "sdns://AQMAAAAAAAAAETk0LjE0MC4xNC4xNDo1NDQzINErR_JS3PLCu_iZEIbq95zkSV2LFsigxDIuUso_OQhzIjIuZG5zY3J5cHQuZGVmYXVsdC5uczEuYWRndWFyZC5jb20"
-	u, err := AddressToUpstream(address, &Options{Timeout: dialTimeout})
+	u, err := AddressToUpstream(address, &Options{
+		Logger:  slogutil.NewDiscardLogger(),
+		Timeout: dialTimeout,
+	})
 	require.NoError(t, err)
 	testutil.CleanupAndRequireSuccess(t, u.Close)
 
@@ -135,7 +139,10 @@ func TestDNSCrypt_Exchange_truncated(t *testing.T) {
 	})
 	srvStamp := startTestDNSCryptServer(t, rc, h)
 
-	u, err := AddressToUpstream(srvStamp.String(), &Options{Timeout: timeout})
+	u, err := AddressToUpstream(srvStamp.String(), &Options{
+		Logger:  slogutil.NewDiscardLogger(),
+		Timeout: timeout,
+	})
 	require.NoError(t, err)
 	testutil.CleanupAndRequireSuccess(t, u.Close)
 
@@ -164,7 +171,10 @@ func TestDNSCrypt_Exchange_deadline(t *testing.T) {
 	srvStamp := startTestDNSCryptServer(t, rc, h)
 
 	// Use a shorter timeout to speed up the test.
-	u, err := AddressToUpstream(srvStamp.String(), &Options{Timeout: 100 * time.Millisecond})
+	u, err := AddressToUpstream(srvStamp.String(), &Options{
+		Logger:  slogutil.NewDiscardLogger(),
+		Timeout: 100 * time.Millisecond,
+	})
 	require.NoError(t, err)
 	testutil.CleanupAndRequireSuccess(t, u.Close)
 
@@ -192,7 +202,10 @@ func TestDNSCrypt_Exchange_dialFail(t *testing.T) {
 		srvStamp := startTestDNSCryptServer(t, rc, h)
 
 		// Use a shorter timeout to speed up the test.
-		u, err = AddressToUpstream(srvStamp.String(), &Options{Timeout: 100 * time.Millisecond})
+		u, err = AddressToUpstream(srvStamp.String(), &Options{
+			Logger:  slogutil.NewDiscardLogger(),
+			Timeout: 100 * time.Millisecond,
+		})
 		require.NoError(t, err)
 	}))
 
@@ -213,6 +226,7 @@ func TestDNSCrypt_Exchange_dialFail(t *testing.T) {
 
 		// Use a shorter timeout to speed up the test.
 		u, err = AddressToUpstream(srvStamp.String(), &Options{
+			Logger:  slogutil.NewDiscardLogger(),
 			Timeout: 100 * time.Millisecond,
 			VerifyDNSCryptCertificate: func(cert *dnscrypt.Cert) (err error) {
 				return validationErr

upstream/doh.go

@@ -6,6 +6,7 @@ import (
 	"encoding/base64"
 	"fmt"
 	"io"
+	"log/slog"
 	"net"
 	"net/http"
 	"net/url"
@@ -15,7 +16,7 @@ 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/miekg/dns"
 	"github.com/quic-go/quic-go"
 	"github.com/quic-go/quic-go/http3"
@@ -63,6 +64,9 @@ type dnsOverHTTPS struct {
 	// clientMu protects client.
 	clientMu *sync.Mutex
 
+	// logger is used for exchange logging.  It is never nil.
+	logger *slog.Logger
+
 	// quicConf is the QUIC configuration that is used if HTTP/3 is enabled
 	// for this upstream.
 	quicConf *quic.Config
@@ -115,6 +119,7 @@ func newDoH(addr *url.URL, opts *Options) (u Upstream, err error) {
 			VerifyConnection:      opts.VerifyConnection,
 		},
 		clientMu:     &sync.Mutex{},
+		logger:       opts.Logger,
 		addrRedacted: addr.Redacted(),
 		timeout:      opts.Timeout,
 	}
@@ -268,7 +273,7 @@ func (p *dnsOverHTTPS) exchangeHTTPSClient(
 	if err != nil {
 		return nil, fmt.Errorf("requesting %s: %w", p.addrRedacted, err)
 	}
-	defer log.OnCloserError(httpResp.Body, log.DEBUG)
+	defer slogutil.CloseAndLog(context.TODO(), p.logger, httpResp.Body, slog.LevelDebug)
 
 	body, err := io.ReadAll(httpResp.Body)
 	if err != nil {
@@ -342,11 +347,11 @@ func (p *dnsOverHTTPS) resetClient(resetErr error) (client *http.Client, err err
 	if oldClient != nil {
 		closeErr := p.closeClient(oldClient)
 		if closeErr != nil {
-			log.Info("warning: failed to close the old http client: %v", closeErr)
+			p.logger.Warn("failed to close the old http client", slogutil.KeyError, closeErr)
 		}
 	}
 
-	log.Debug("re-creating the http client due to %v", resetErr)
+	p.logger.Debug("recreating the http client", slogutil.KeyError, resetErr)
 	p.client, err = p.createClient()
 
 	return p.client, err
@@ -390,7 +395,7 @@ func (p *dnsOverHTTPS) getClient() (c *http.Client, isCached bool, err error) {
 		return nil, false, fmt.Errorf("timeout exceeded: %s", elapsed)
 	}
 
-	log.Debug("creating a new http client")
+	p.logger.Debug("creating a new http client")
 	p.client, err = p.createClient()
 
 	return p.client, false, err
@@ -437,11 +442,12 @@ func (p *dnsOverHTTPS) createTransport() (t http.RoundTripper, err error) {
 	tlsConf := p.tlsConf.Clone()
 	transportH3, err := p.createTransportH3(tlsConf, dialContext)
 	if err == nil {
-		log.Debug("using HTTP/3 for this upstream: QUIC was faster")
+		p.logger.Debug("using http/3 for this upstream: quic was faster")
+
 		return transportH3, nil
 	}
 
-	log.Debug("using HTTP/2 for this upstream: %v", err)
+	p.logger.Debug("got error, switching to http/2 for this upstream", slogutil.KeyError, err)
 
 	if !p.supportsHTTP() {
 		return nil, errors.Error("HTTP1/1 and HTTP2 are not supported by this upstream")
@@ -621,7 +627,8 @@ func (p *dnsOverHTTPS) probeH3(
 	case tlsErr := <-chTLS:
 		if tlsErr != nil {
 			// Return immediately, TLS failed.
-			log.Debug("probing TLS: %v", tlsErr)
+			p.logger.Debug("probing tls", slogutil.KeyError, tlsErr)
+
 			return addr, nil
 		}
 
@@ -653,7 +660,7 @@ func (p *dnsOverHTTPS) probeQUIC(addr string, tlsConfig *tls.Config, ch chan err
 	ch <- nil
 
 	elapsed := time.Since(startTime)
-	log.Debug("elapsed on establishing a QUIC connection: %s", elapsed)
+	p.logger.Debug("quic connection established", "elapsed", elapsed)
 }
 
 // probeTLS attempts to establish a TLS connection to the specified address. We
@@ -673,7 +680,7 @@ func (p *dnsOverHTTPS) probeTLS(dialContext bootstrap.DialHandler, tlsConfig *tl
 	ch <- nil
 
 	elapsed := time.Since(startTime)
-	log.Debug("elapsed on establishing a TLS connection: %s", elapsed)
+	p.logger.Debug("tls connection established", "elapsed", elapsed)
 }
 
 // supportsH3 returns true if HTTP/3 is supported by this upstream.

upstream/doh_internal_test.go

@@ -14,6 +14,7 @@ import (
 	"testing"
 	"time"
 
+	"github.com/AdguardTeam/golibs/logutil/slogutil"
 	"github.com/AdguardTeam/golibs/testutil"
 	"github.com/miekg/dns"
 	"github.com/quic-go/quic-go"
@@ -75,6 +76,7 @@ func TestUpstreamDoH(t *testing.T) {
 
 			var lastState tls.ConnectionState
 			opts := &Options{
+				Logger:             slogutil.NewDiscardLogger(),
 				InsecureSkipVerify: true,
 				HTTPVersions:       tc.httpVersions,
 				VerifyConnection: func(state tls.ConnectionState) (err error) {
@@ -183,6 +185,7 @@ func TestUpstreamDoH_raceReconnect(t *testing.T) {
 			// race test.
 			address := fmt.Sprintf("https://%s/dns-query", srv.addr)
 			opts := &Options{
+				Logger:             slogutil.NewDiscardLogger(),
 				InsecureSkipVerify: true,
 				HTTPVersions:       tc.httpVersions,
 				Timeout:            timeout,
@@ -232,6 +235,7 @@ func TestUpstreamDoH_serverRestart(t *testing.T) {
 
 				var err error
 				u, err = AddressToUpstream(upsAddr, &Options{
+					Logger:             slogutil.NewDiscardLogger(),
 					InsecureSkipVerify: true,
 					HTTPVersions:       tc.httpVersions,
 					Timeout:            100 * time.Millisecond,
@@ -280,6 +284,7 @@ func TestUpstreamDoH_0RTT(t *testing.T) {
 	tracer := &quicTracer{}
 	address := fmt.Sprintf("h3://%s/dns-query", srv.addr)
 	u, err := AddressToUpstream(address, &Options{
+		Logger:             slogutil.NewDiscardLogger(),
 		InsecureSkipVerify: true,
 		QUICTracer:         tracer.TracerForConnection,
 	})

upstream/doq.go

@@ -4,6 +4,7 @@ import (
 	"context"
 	"crypto/tls"
 	"fmt"
+	"log/slog"
 	"net"
 	"net/url"
 	"os"
@@ -13,7 +14,7 @@ import (
 
 	"github.com/AdguardTeam/dnsproxy/proxyutil"
 	"github.com/AdguardTeam/golibs/errors"
-	"github.com/AdguardTeam/golibs/log"
+	"github.com/AdguardTeam/golibs/logutil/slogutil"
 	"github.com/miekg/dns"
 	"github.com/quic-go/quic-go"
 	"github.com/quic-go/quic-go/http3"
@@ -87,6 +88,9 @@ type dnsOverQUIC struct {
 	// bytesPoolGuard protects bytesPool.
 	bytesPoolMu *sync.Mutex
 
+	// logger is used for exchange logging.  It is never nil.
+	logger *slog.Logger
+
 	// timeout is the timeout for the upstream connection.
 	timeout time.Duration
 }
@@ -122,6 +126,7 @@ func newDoQ(addr *url.URL, opts *Options) (u Upstream, err error) {
 		quicConfigMu: &sync.Mutex{},
 		connMu:       &sync.Mutex{},
 		bytesPoolMu:  &sync.Mutex{},
+		logger:       opts.Logger,
 		timeout:      opts.Timeout,
 	}
 
@@ -163,7 +168,7 @@ func (p *dnsOverQUIC) Exchange(m *dns.Msg) (resp *dns.Msg, err error) {
 	// connection could have been closed by the server or simply be broken due
 	// to how UDP NAT works.  In this case the connection should be re-created.
 	if cached && err != nil {
-		log.Debug("dnsproxy: re-creating the QUIC connection and retrying due to %v", err)
+		p.logger.Debug("recreating the quic connection and retrying", slogutil.KeyError, err)
 
 		// Close the active connection to make sure the cached connection is
 		// cleaned up.
@@ -239,7 +244,7 @@ func (p *dnsOverQUIC) exchangeQUIC(req *dns.Msg, conn quic.Connection) (resp *dn
 	// of the stream, but does not prevent reading from it.
 	err = stream.Close()
 	if err != nil {
-		log.Debug("dnsproxy: closing quic stream: %s", err)
+		p.logger.Debug("closing quic stream", slogutil.KeyError, err)
 	}
 
 	return p.readMsg(stream)
@@ -334,7 +339,7 @@ func (p *dnsOverQUIC) openConnection() (conn quic.Connection, err error) {
 	// It's never actually used.
 	err = rawConn.Close()
 	if err != nil {
-		log.Debug("dnsproxy: closing raw connection for %s: %s", p.addr, err)
+		p.logger.Debug("closing raw connection", "addr", p.addr, slogutil.KeyError, err)
 	}
 
 	udpConn, ok := rawConn.(*net.UDPConn)
@@ -374,7 +379,7 @@ func (p *dnsOverQUIC) closeConnWithError(conn quic.Connection, err error) {
 
 	err = conn.CloseWithError(code, "")
 	if err != nil {
-		log.Error("dnsproxy: failed to close the conn: %v", err)
+		p.logger.Error("failed to close the conn", slogutil.KeyError, err)
 	}
 
 	// If the connection that's being closed is cached, reset the cache.