refactor(log): store log in context so it's automatically propagated

cmd/serve.go

@@ -63,7 +63,7 @@ func startServer(_ *cobra.Command, _ []string) error {
 		select {
 		case <-signals:
 			log.Log().Infof("Terminating...")
-			util.LogOnError("can't stop server: ", srv.Stop(ctx))
+			util.LogOnError(ctx, "can't stop server: ", srv.Stop(ctx))
 			done <- true
 
 		case err := <-errChan:

config/config.go

@@ -240,7 +240,7 @@ type Config struct {
 		Upstream            *UpstreamGroups `yaml:"upstream"`
 		UpstreamTimeout     *Duration       `yaml:"upstreamTimeout"`
 		DisableIPv6         *bool           `yaml:"disableIPv6"`
-		LogLevel            *log.Level      `yaml:"logLevel"`
+		LogLevel            *logrus.Level   `yaml:"logLevel"`
 		LogFormat           *log.FormatType `yaml:"logFormat"`
 		LogPrivacy          *bool           `yaml:"logPrivacy"`
 		LogTimestamp        *bool           `yaml:"logTimestamp"`

config/config_test.go

@@ -69,10 +69,10 @@ var _ = Describe("Config", func() {
 
 		When("parameter 'logLevel' is set", func() {
 			It("should convert to log.level", func() {
-				c.Deprecated.LogLevel = ptrOf(log.LevelDebug)
+				c.Deprecated.LogLevel = ptrOf(logrus.DebugLevel)
 				c.migrate(logger)
 				Expect(hook.Messages).Should(ContainElement(ContainSubstring("log.level")))
-				Expect(c.Log.Level).Should(Equal(log.LevelDebug))
+				Expect(c.Log.Level).Should(Equal(logrus.DebugLevel))
 			})
 		})
 
@@ -434,7 +434,7 @@ bootstrapDns:
 				c, err = LoadConfig(tmpDir.JoinPath("config.yml"), false)
 
 				Expect(err).Should(Succeed())
-				Expect(c.Log.Level).Should(Equal(log.LevelInfo))
+				Expect(c.Log.Level).Should(Equal(logrus.InfoLevel))
 			})
 		})
 	})

docs/config.yml

@@ -316,7 +316,7 @@ ports:
 
 # optional: logging configuration
 log:
-  # optional: Log level (one from debug, info, warn, error). Default: info
+  # optional: Log level (one from trace, debug, info, warn, error). Default: info
   level: info
   # optional: Log format (text or json). Default: text
   format: text

docs/configuration.md

@@ -49,12 +49,12 @@ All logging port are optional.
 
 All logging options are optional.
 
-| Parameter     | Type                            | Default value | Description                                                                                                                                      |
-| ------------- | ------------------------------- | ------------- | ------------------------------------------------------------------------------------------------------------------------------------------------ |
-| log.level     | enum (debug, info, warn, error) | info          | Log level                                                                                                                                        |
-| log.format    | enum (text, json)               | text          | Log format (text or json).                                                                                                                       |
-| log.timestamp | bool                            | true          | Log time stamps (true or false).                                                                                                                 |
-| log.privacy   | bool                            | false         | Obfuscate log output (replace all alphanumeric characters with *) for user sensitive data like request domains or responses to increase privacy. |
+| Parameter     | Type                                   | Default value | Description                                                                                                                                      |
+| ------------- | -------------------------------------- | ------------- | ------------------------------------------------------------------------------------------------------------------------------------------------ |
+| log.level     | enum (trace, debug, info, warn, error) | info          | Log level                                                                                                                                        |
+| log.format    | enum (text, json)                      | text          | Log format (text or json).                                                                                                                       |
+| log.timestamp | bool                                   | true          | Log timestamps (true or false).                                                                                                                 |
+| log.privacy   | bool                                   | false         | Obfuscate log output (replace all alphanumeric characters with *) for user sensitive data like request domains or responses to increase privacy. |
 
 !!! example
 

log/context.go

@@ -0,0 +1,46 @@
+package log
+
+import (
+	"context"
+
+	"github.com/sirupsen/logrus"
+)
+
+type ctxKey struct{}
+
+func NewCtx(ctx context.Context, logger *logrus.Entry) (context.Context, *logrus.Entry) {
+	ctx = context.WithValue(ctx, ctxKey{}, logger)
+
+	return ctx, entryWithCtx(ctx, logger)
+}
+
+func FromCtx(ctx context.Context) *logrus.Entry {
+	logger, ok := ctx.Value(ctxKey{}).(*logrus.Entry)
+	if !ok {
+		// Fallback to the global logger
+		return logrus.NewEntry(Log())
+	}
+
+	// Ensure `logger.Context == ctx`, not always the case since `ctx` could be a child of `logger.Context`
+	return entryWithCtx(ctx, logger)
+}
+
+func entryWithCtx(ctx context.Context, logger *logrus.Entry) *logrus.Entry {
+	loggerCopy := *logger
+	loggerCopy.Context = ctx
+
+	return &loggerCopy
+}
+
+func WrapCtx(ctx context.Context, wrap func(*logrus.Entry) *logrus.Entry) (context.Context, *logrus.Entry) {
+	logger := FromCtx(ctx)
+	logger = wrap(logger)
+
+	return NewCtx(ctx, logger)
+}
+
+func CtxWithFields(ctx context.Context, fields logrus.Fields) (context.Context, *logrus.Entry) {
+	return WrapCtx(ctx, func(e *logrus.Entry) *logrus.Entry {
+		return e.WithFields(fields)
+	})
+}

log/logger.go

@@ -32,22 +32,12 @@ var (
 // )
 type FormatType int
 
-// Level log level ENUM(
-// info
-// trace
-// debug
-// warn
-// error
-// fatal
-// )
-type Level int
-
 // Config defines all logging configurations
 type Config struct {
-	Level     Level      `yaml:"level" default:"info"`
-	Format    FormatType `yaml:"format" default:"text"`
-	Privacy   bool       `yaml:"privacy" default:"false"`
-	Timestamp bool       `yaml:"timestamp" default:"true"`
+	Level     logrus.Level `yaml:"level" default:"info"`
+	Format    FormatType   `yaml:"format" default:"text"`
+	Privacy   bool         `yaml:"privacy" default:"false"`
+	Timestamp bool         `yaml:"timestamp" default:"true"`
 }
 
 // DefaultConfig returns a new Config initialized with default values.
@@ -106,11 +96,7 @@ func Configure(cfg *Config) {
 
 // Configure applies configuration to the given logger.
 func ConfigureLogger(logger *logrus.Logger, cfg *Config) {
-	if level, err := logrus.ParseLevel(cfg.Level.String()); err != nil {
-		logger.Fatalf("invalid log level %s %v", cfg.Level, err)
-	} else {
-		logger.SetLevel(level)
-	}
+	logger.SetLevel(cfg.Level)
 
 	switch cfg.Format {
 	case FormatTypeText:

model/models.go

@@ -6,7 +6,6 @@ import (
 	"time"
 
 	"github.com/miekg/dns"
-	"github.com/sirupsen/logrus"
 )
 
 // ResponseType represents the type of the response ENUM(
@@ -67,6 +66,5 @@ type Request struct {
 	Protocol        RequestProtocol
 	ClientNames     []string
 	Req             *dns.Msg
-	Log             *logrus.Entry
 	RequestTS       time.Time
 }

querylog/database_writer.go

@@ -128,7 +128,7 @@ func (d *DatabaseWriter) periodicFlush(ctx context.Context) {
 		case <-ticker.C:
 			err := d.doDBWrite()
 
-			util.LogOnError("can't write entries to the database: ", err)
+			util.LogOnError(ctx, "can't write entries to the database: ", err)
 
 		case <-ctx.Done():
 			return

resolver/blocking_resolver.go

@@ -174,18 +174,20 @@ func NewBlockingResolver(ctx context.Context,
 }
 
 func (r *BlockingResolver) redisSubscriber(ctx context.Context) {
+	ctx, logger := r.log(ctx)
+
 	for {
 		select {
 		case em := <-r.redisClient.EnabledChannel:
 			if em != nil {
-				r.log().Debug("Received state from redis: ", em)
+				logger.Debug("Received state from redis: ", em)
 
 				if em.State {
 					r.internalEnableBlocking()
 				} else {
 					err := r.internalDisableBlocking(ctx, em.Duration, em.Groups)
 					if err != nil {
-						r.log().Warn("Blocking couldn't be disabled:", err)
+						logger.Warn("Blocking couldn't be disabled:", err)
 					}
 				}
 			}
@@ -394,7 +396,7 @@ func (r *BlockingResolver) handleBlacklist(ctx context.Context, groupsToCheck []
 
 // Resolve checks the query against the blacklist and delegates to next resolver if domain is not blocked
 func (r *BlockingResolver) Resolve(ctx context.Context, request *model.Request) (*model.Response, error) {
-	logger := log.WithPrefix(request.Log, "blacklist_resolver")
+	ctx, logger := r.log(ctx)
 	groupsToCheck := r.groupsToCheckForClient(request)
 
 	if len(groupsToCheck) > 0 {
@@ -575,7 +577,9 @@ func (b ipBlockHandler) handleBlock(question dns.Question, response *dns.Msg) {
 }
 
 func (r *BlockingResolver) queryForFQIdentifierIPs(ctx context.Context, identifier string) (*[]net.IP, time.Duration) {
-	prefixedLog := log.WithPrefix(r.log(), "client_id_cache")
+	ctx, logger := r.logWith(ctx, func(logger *logrus.Entry) *logrus.Entry {
+		return log.WithPrefix(logger, "client_id_cache")
+	})
 
 	var result []net.IP
 
@@ -584,7 +588,6 @@ func (r *BlockingResolver) queryForFQIdentifierIPs(ctx context.Context, identifi
 	for _, qType := range []uint16{dns.TypeA, dns.TypeAAAA} {
 		resp, err := r.next.Resolve(ctx, &model.Request{
 			Req: util.NewMsgWithQuestion(identifier, dns.Type(qType)),
-			Log: prefixedLog,
 		})
 
 		if err == nil && resp.Res.Rcode == dns.RcodeSuccess {
@@ -598,11 +601,16 @@ func (r *BlockingResolver) queryForFQIdentifierIPs(ctx context.Context, identifi
 					result = append(result, v.AAAA)
 				}
 			}
-
-			prefixedLog.Debugf("resolved IPs '%v' for fq identifier '%s'", result, identifier)
 		}
 	}
 
+	if len(result) != 0 {
+		logger.WithFields(logrus.Fields{
+			"ips":       result,
+			"client_id": identifier,
+		}).Debug("resolved client IPs")
+	}
+
 	return &result, ttl
 }