Start using slog in library code, closes #26

Author: ameshkov

.github/workflows/lint.yaml

@@ -23,4 +23,4 @@ jobs:
         with:
           # This field is required.  Dont set the patch version to always use
           # the latest patch version.
-          version: v1.56.2
+          version: 1.64.7

client.go

@@ -4,12 +4,13 @@ import (
 	"crypto/ed25519"
 	"encoding/binary"
 	"fmt"
+	"log/slog"
 	"net"
 	"strings"
 	"time"
 
 	"github.com/AdguardTeam/golibs/errors"
-	"github.com/AdguardTeam/golibs/log"
+	"github.com/AdguardTeam/golibs/logutil/slogutil"
 	"github.com/ameshkov/dnsstamps"
 	"github.com/miekg/dns"
 )
@@ -19,8 +20,12 @@ type Client struct {
 	Net     string        // protocol (can be "udp" or "tcp", by default - "udp")
 	Timeout time.Duration // read/write timeout
 
+	// Logger is a logger instance for Client. If not set, slog.Default() will
+	// be used.
+	Logger *slog.Logger
+
 	// UDPSize is the maximum size of a DNS response (or query) this client can
-	// sent or receive. If not set, we use dns.MinMsgSize by default.
+	// send or receive. If not set, we use dns.MinMsgSize by default.
 	UDPSize int
 }
 
@@ -250,9 +255,9 @@ func (c *Client) fetchCert(stamp dnsstamps.ServerStamp) (cert *Cert, err error)
 			continue
 		}
 
-		cert, err = parseCert(stamp, currentCert, providerName, strings.Join(txt.Txt, ""))
+		cert, err = c.parseCert(stamp, currentCert, providerName, strings.Join(txt.Txt, ""))
 		if err != nil {
-			log.Debug("[%s] bad cert: %s", providerName, err)
+			c.logger().Debug("bad cert", "provider", providerName, slogutil.KeyError, err)
 
 			continue
 		} else if cert == nil {
@@ -275,7 +280,7 @@ func (c *Client) fetchCert(stamp dnsstamps.ServerStamp) (cert *Cert, err error)
 
 // parseCert parses a certificate from its string form and returns it if it has
 // priority over currentCert.
-func parseCert(
+func (c *Client) parseCert(
 	stamp dnsstamps.ServerStamp,
 	currentCert *Cert,
 	providerName string,
@@ -292,7 +297,13 @@ func parseCert(
 		return nil, fmt.Errorf("deserializing cert for: %w", err)
 	}
 
-	log.Debug("[%s] fetched certificate %d", providerName, cert.Serial)
+	c.logger().Debug(
+		"fetched certificate",
+		"provider",
+		providerName,
+		"cert_serial",
+		cert.Serial,
+	)
 
 	if !cert.VerifyDate() {
 		return nil, ErrInvalidDate
@@ -303,7 +314,13 @@ func parseCert(
 	}
 
 	if cert.Serial < currentCert.Serial {
-		log.Debug("[%v] cert %d superseded by a previous certificate", providerName, cert.Serial)
+		c.logger().Debug(
+			"cert superseded by a previous certificate",
+			"provider",
+			providerName,
+			"cert_serial",
+			cert.Serial,
+		)
 
 		return nil, nil
 	}
@@ -313,15 +330,22 @@ func parseCert(
 	}
 
 	if cert.EsVersion <= currentCert.EsVersion {
-		log.Debug("[%v] keeping the previous, preferred crypto construction", providerName)
+		c.logger().Debug(
+			"keeping the current cert es version",
+			"provider",
+			providerName,
+		)
 
 		return nil, nil
 	}
 
-	log.Debug(
-		"[%v] upgrading the construction from %v to %v",
+	c.logger().Debug(
+		"upgrading the construction",
+		"provider",
 		providerName,
+		"es_version",
 		currentCert.EsVersion,
+		"new_es_version",
 		cert.EsVersion,
 	)
 
@@ -339,3 +363,11 @@ func (c *Client) maxQuerySize() int {
 
 	return dns.MinMsgSize
 }
+
+func (c *Client) logger() (l *slog.Logger) {
+	if c.Logger == nil {
+		return slog.Default()
+	}
+
+	return c.Logger
+}

cmd/convert_dnscrypt_wrapper.go

@@ -23,7 +23,6 @@ type ConvertWrapperArgs struct {
 
 // convertWrapper generates DNSCrypt configuration from both dnscrypt and server private keys
 func convertWrapper(args ConvertWrapperArgs) {
-
 	log.Info("Generating configuration for %s", args.ProviderName)
 
 	var rc = dnscrypt.ResolverConfig{

generate.go

@@ -7,7 +7,6 @@ import (
 	"strings"
 	"time"
 
-	"github.com/AdguardTeam/golibs/log"
 	"github.com/ameshkov/dnsstamps"
 	"golang.org/x/crypto/curve25519"
 )
@@ -46,8 +45,6 @@ type ResolverConfig struct {
 
 // CreateCert generates a signed Cert to be used by Server
 func (rc *ResolverConfig) CreateCert() (*Cert, error) {
-	log.Printf("Creating signed DNSCrypt certificate")
-
 	notAfter := time.Now()
 	if rc.CertificateTTL > 0 {
 		notAfter = notAfter.Add(rc.CertificateTTL)
@@ -75,7 +72,6 @@ func (rc *ResolverConfig) CreateCert() (*Cert, error) {
 	}
 
 	if len(resolverPk) != keySize || len(resolverSk) != keySize {
-		log.Printf("Short-term keys are not set, generating random ones")
 		sk, pk := generateRandomKeyPair()
 		resolverSk = sk[:]
 		resolverPk = pk[:]
@@ -93,8 +89,6 @@ func (rc *ResolverConfig) CreateCert() (*Cert, error) {
 	// sign the data
 	cert.Sign(privateKey)
 
-	log.Info("Signed cert: %s", cert.String())
-
 	// done
 	return cert, nil
 }

go.mod

@@ -18,6 +18,7 @@ require (
 require (
 	github.com/davecgh/go-spew v1.1.1 // indirect
 	github.com/pmezard/go-difflib v1.0.0 // indirect
+	golang.org/x/exp v0.0.0-20240205201215-2c58cdc269a3 // indirect
 	golang.org/x/mod v0.16.0 // indirect
 	golang.org/x/sys v0.18.0 // indirect
 	golang.org/x/tools v0.19.0 // indirect

go.sum

@@ -14,6 +14,8 @@ github.com/stretchr/testify v1.9.0 h1:HtqpIVDClZ4nwg75+f6Lvsy/wHu+3BoSGCbBAcpTsT
 github.com/stretchr/testify v1.9.0/go.mod h1:r2ic/lqez/lEtzL7wO/rwa5dbSLXVDPFyf8C91i36aY=
 golang.org/x/crypto v0.21.0 h1:X31++rzVUdKhX5sWmSOFZxx8UW/ldWx55cbf08iNAMA=
 golang.org/x/crypto v0.21.0/go.mod h1:0BP7YvVV9gBbVKyeTG0Gyn+gZm94bibOW5BjDEYAOMs=
+golang.org/x/exp v0.0.0-20240205201215-2c58cdc269a3 h1:/RIbNt/Zr7rVhIkQhooTxCxFcdWLGIKnZA4IXNFSrvo=
+golang.org/x/exp v0.0.0-20240205201215-2c58cdc269a3/go.mod h1:idGWGoKP1toJGkd5/ig9ZLuPcZBC3ewk7SzmH0uou08=
 golang.org/x/mod v0.16.0 h1:QX4fJ0Rr5cPQCF7O9lh9Se4pmwfwskqZfq5moyldzic=
 golang.org/x/mod v0.16.0/go.mod h1:hTbmBsO62+eylJbnUtE2MGJUyE7QWk4xUqPFrRgJ+7c=
 golang.org/x/net v0.22.0 h1:9sGLhx7iRIHEiX0oAJ3MRZMUCElJgy7Br1nO+AMN3Tc=

server.go

@@ -2,12 +2,14 @@ package dnscrypt
 
 import (
 	"context"
+	"log/slog"
 	"net"
 	"strings"
 	"sync"
 	"time"
 
-	"github.com/AdguardTeam/golibs/log"
+	"github.com/AdguardTeam/golibs/errors"
+	"github.com/AdguardTeam/golibs/logutil/slogutil"
 	"github.com/miekg/dns"
 )
 
@@ -63,6 +65,10 @@ type Server struct {
 	// Handler to invoke. If nil, uses DefaultHandler.
 	Handler Handler
 
+	// Logger is a logger instance for Server. If not set, slog.Default() will
+	// be used.
+	Logger *slog.Logger
+
 	// make sure init is called only once
 	initOnce sync.Once
 
@@ -88,7 +94,8 @@ func (s *Server) prepareShutdown() error {
 	defer s.lock.Unlock()
 
 	if !s.started {
-		log.Info("Server is not started")
+		s.Logger.Info("server is not started")
+
 		return ErrServerNotStarted
 	}
 
@@ -126,7 +133,7 @@ func (s *Server) prepareShutdown() error {
 // connections are processed and only after that it leaves the method.
 // If context deadline is specified, it will exit earlier.
 func (s *Server) Shutdown(ctx context.Context) error {
-	log.Info("Shutting down the DNSCrypt server")
+	s.Logger.Info("shutting down the DNSCrypt server")
 
 	err := s.prepareShutdown()
 	if err != nil {
@@ -137,17 +144,17 @@ func (s *Server) Shutdown(ctx context.Context) error {
 	closed := make(chan struct{})
 	go func() {
 		s.wg.Wait()
-		log.Info("Serve goroutines finished their work")
+		s.Logger.Info("serve goroutines finished their work")
 		close(closed)
 	}()
 
 	// Wait for either all goroutines finish their work
 	// Or for the context deadline
 	select {
 	case <-closed:
-		log.Info("DNSCrypt server has been stopped")
+		s.Logger.Info("DNSCrypt server has been stopped")
 	case <-ctx.Done():
-		log.Info("DNSCrypt server shutdown has timed out")
+		s.Logger.Info("DNSCrypt server shutdown has timed out")
 		err = ctx.Err()
 	}
 
@@ -164,6 +171,10 @@ func (s *Server) init() {
 	if s.UDPSize == 0 {
 		s.UDPSize = defaultUDPSize
 	}
+
+	if s.Logger == nil {
+		s.Logger = slog.Default()
+	}
 }
 
 // isStarted returns true if the server is processing queries right now
@@ -181,7 +192,7 @@ func (s *Server) serveDNS(rw ResponseWriter, r *dns.Msg) error {
 		return ErrInvalidQuery
 	}
 
-	log.Tracef("Handling a DNS query: %s", r.Question[0].Name)
+	s.Logger.Debug("handling a DNS query", "question", r.Question[0].Name)
 
 	handler := s.Handler
 	if handler == nil {
@@ -190,7 +201,7 @@ func (s *Server) serveDNS(rw ResponseWriter, r *dns.Msg) error {
 
 	err := handler.ServeDNS(rw, r)
 	if err != nil {
-		log.Tracef("Error while handing a DNS query: %v", err)
+		s.Logger.Debug("error while handling a DNS query", slogutil.KeyError, err)
 
 		reply := &dns.Msg{}
 		reply.SetRcode(r, dns.RcodeServerFailure)
@@ -285,23 +296,20 @@ func (s *Server) handleHandshake(b []byte, certTxt string) ([]byte, error) {
 }
 
 // validate checks if the Server config is properly set
-func (s *Server) validate() bool {
+func (s *Server) validate() (err error) {
 	if s.ResolverCert == nil {
-		log.Error("ResolverCert must be set")
-		return false
+		return errors.Annotate(ErrServerConfig, "ResolverCert is required")
 	}
 
 	if !s.ResolverCert.VerifyDate() {
-		log.Error("ResolverCert date is not valid")
-		return false
+		return errors.Annotate(ErrServerConfig, "ResolverCert date is not valid")
 	}
 
 	if s.ProviderName == "" {
-		log.Error("ProviderName must be set")
-		return false
+		return errors.Annotate(ErrServerConfig, "ProviderName must be set")
 	}
 
-	return true
+	return nil
 }
 
 // getCertTXT serializes the cert TXT record that are to be sent to the client

server_tcp.go

@@ -4,11 +4,12 @@ import (
 	"bytes"
 	"errors"
 	"fmt"
+	"log/slog"
 	"net"
 	"sync"
 	"time"
 
-	"github.com/AdguardTeam/golibs/log"
+	"github.com/AdguardTeam/golibs/logutil/slogutil"
 	"github.com/miekg/dns"
 )
 
@@ -18,6 +19,7 @@ type TCPResponseWriter struct {
 	encrypt encryptionFunc
 	req     *dns.Msg
 	query   EncryptedQuery
+	logger  *slog.Logger
 }
 
 // type check
@@ -39,7 +41,8 @@ func (w *TCPResponseWriter) WriteMsg(m *dns.Msg) error {
 
 	res, err := w.encrypt(m, w.query)
 	if err != nil {
-		log.Tracef("Failed to encrypt the DNS query: %v", err)
+		w.logger.Debug("failed to encrypt the DNS query", slogutil.KeyError, err)
+
 		return err
 	}
 
@@ -55,7 +58,7 @@ func (s *Server) ServeTCP(l net.Listener) error {
 		return err
 	}
 
-	log.Info("Entering DNSCrypt TCP listening loop tcp://%s", l.Addr())
+	s.Logger.Info("entering DNSCrypt TCP listening loop", "listenAddr", l.Addr())
 
 	// Tracks TCP connection handling goroutines
 	tcpWg := &sync.WaitGroup{}
@@ -85,9 +88,9 @@ func (s *Server) ServeTCP(l net.Listener) error {
 				continue
 			}
 			if isConnClosed(err) {
-				log.Info("udpListen.ReadFrom() returned because we're reading from a closed connection, exiting loop")
+				s.Logger.Info("TCP listener closed, exiting loop")
 			} else {
-				log.Info("got error when reading from UDP listen: %s", err)
+				s.Logger.Info("got error when reading from UDP listen", slogutil.KeyError, err)
 			}
 			break
 		}
@@ -117,10 +120,11 @@ func (s *Server) ServeTCP(l net.Listener) error {
 }
 
 // prepareServeTCP prepares the server and listener to serving DNSCrypt
-func (s *Server) prepareServeTCP(l net.Listener) error {
+func (s *Server) prepareServeTCP(l net.Listener) (err error) {
 	// Check that server is properly configured
-	if !s.validate() {
-		return ErrServerConfig
+	err = s.validate()
+	if err != nil {
+		return err
 	}
 
 	// Protect shutdown-related fields
@@ -184,6 +188,7 @@ func (s *Server) handleTCPMsg(b []byte, conn net.Conn, certTxt string) error {
 		encrypt: s.encrypt,
 		req:     m,
 		query:   q,
+		logger:  s.Logger,
 	}
 	err = s.serveDNS(rw, m)
 	if err != nil {
@@ -208,7 +213,8 @@ func (s *Server) handleTCPConnection(conn net.Conn, certTxt string) error {
 
 		err = s.handleTCPMsg(b, conn, certTxt)
 		if err != nil {
-			log.Debug("failed to process DNS query: %v", err)
+			s.Logger.Debug("failed to process a DNS query", slogutil.KeyError, err)
+
 			return err
 		}