Pull request: AGDNS-2202-slog-upstream

Squashed commit of the following: commit 472b63a Author: Dimitry Kolyshev <dkolyshev@adguard.com> Date: Fri Jun 28 16:11:18 2024 +0300 dnsproxytest: rm tslog commit efea125 Author: Dimitry Kolyshev <dkolyshev@adguard.com> Date: Fri Jun 28 14:27:52 2024 +0300 dnsproxytest: imp code commit 1b58095 Author: Dimitry Kolyshev <dkolyshev@adguard.com> Date: Fri Jun 28 13:58:10 2024 +0300 dnsproxytest: imp code commit 22b4035 Author: Dimitry Kolyshev <dkolyshev@adguard.com> Date: Fri Jun 28 08:46:07 2024 +0300 dnsproxytest: imp tlog commit 9b36995 Author: Dimitry Kolyshev <dkolyshev@adguard.com> Date: Thu Jun 27 08:59:10 2024 +0300 all: tslog commit 216df13 Author: Dimitry Kolyshev <dkolyshev@adguard.com> Date: Wed Jun 26 16:01:23 2024 +0300 upstream: imp code commit 6a755d9 Author: Dimitry Kolyshev <dkolyshev@adguard.com> Date: Wed Jun 26 15:41:15 2024 +0300 upstream: imp code commit 01629f6 Author: Dimitry Kolyshev <dkolyshev@adguard.com> Date: Tue Jun 25 13:37:02 2024 +0300 upstream: imp code commit 1305183 Author: Dimitry Kolyshev <dkolyshev@adguard.com> Date: Tue Jun 25 12:16:44 2024 +0300 upstream: slog commit 0596984 Author: Dimitry Kolyshev <dkolyshev@adguard.com> Date: Tue Jun 25 11:12:34 2024 +0300 upstream: slog
AdguardTeam · Jul 1, 2024 · 7f77a34 · 7f77a34
1 parent 74dfff2
commit 7f77a34
Show file tree

Hide file tree

Showing 19 changed files with 188 additions and 63 deletions.
diff --git a/main.go b/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,

diff --git a/proxy/lookup_test.go b/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)
 

diff --git a/proxy/proxy_test.go b/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)

diff --git a/proxy/upstreams.go b/proxy/upstreams.go
@@ -1,7 +1,6 @@
 package proxy
 
 import (
-	"cmp"
 	"fmt"
 	"io"
 	"log/slog"
@@ -98,9 +97,13 @@ func ParseUpstreamsConfig(
 		opts = &upstream.Options{}
 	}
 
+	if opts.Logger == nil {
+		opts.Logger = slog.Default()
+	}
+
 	p := &configParser{
 		options:                  opts,
-		logger:                   cmp.Or(opts.Logger, slog.Default()),
+		logger:                   opts.Logger,
 		upstreamsIndex:           map[string]upstream.Upstream{},
 		domainReservedUpstreams:  map[string][]upstream.Upstream{},
 		specifiedDomainUpstreams: map[string][]upstream.Upstream{},

diff --git a/upstream/dnscrypt.go b/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)

diff --git a/upstream/dnscrypt_internal_test.go b/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

diff --git a/upstream/doh.go b/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(httpReq.Context(), 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.

diff --git a/upstream/doh_internal_test.go b/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,
@@ -197,8 +200,6 @@ func TestUpstreamDoH_raceReconnect(t *testing.T) {
 }
 
 func TestUpstreamDoH_serverRestart(t *testing.T) {
-	t.Parallel()
-
 	testCases := []struct {
 		name         string
 		httpVersions []HTTPVersion
@@ -212,8 +213,6 @@ func TestUpstreamDoH_serverRestart(t *testing.T) {
 
 	for _, tc := range testCases {
 		t.Run(tc.name, func(t *testing.T) {
-			t.Parallel()
-
 			var addr netip.AddrPort
 			var upsAddr string
 			var u Upstream
@@ -232,6 +231,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 +280,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,
 	})