From 5e7dac8f47c0cec806f6fb7cec1f2caea275de64 Mon Sep 17 00:00:00 2001
From: Adam Wolfe Gordon <awg@digitalocean.com>
Date: Tue, 31 Mar 2020 16:05:16 -0600
Subject: [PATCH] log: Include configured fields in all logs

It's possible to configure log fields in the configuration file, and we would
like these fields to be included in all logs. Previously these fields were
included only in logs produced using the main routine's context, meaning that
any logs from a request handler were missing the fields since those use a
context based on the HTTP request's context.

Add a configurable default logger to the `context` package, and set it when
configuring logging at startup time.

Signed-off-by: Adam Wolfe Gordon <awg@digitalocean.com>
---
 context/logger.go         | 24 ++++++++++++++--
 registry/registry.go      |  1 +
 registry/registry_test.go | 59 +++++++++++++++++++++++++++++++++++++++
 3 files changed, 81 insertions(+), 3 deletions(-)

diff --git a/context/logger.go b/context/logger.go
index 3e5b81bbf..f956a2282 100644
--- a/context/logger.go
+++ b/context/logger.go
@@ -4,10 +4,16 @@ import (
 	"context"
 	"fmt"
 	"runtime"
+	"sync"
 
 	"github.com/sirupsen/logrus"
 )
 
+var (
+	defaultLogger   *logrus.Entry = logrus.StandardLogger().WithField("go.version", runtime.Version())
+	defaultLoggerMu sync.RWMutex
+)
+
 // Logger provides a leveled-logging interface.
 type Logger interface {
 	// standard logger methods
@@ -80,6 +86,18 @@ func GetLogger(ctx context.Context, keys ...interface{}) Logger {
 	return getLogrusLogger(ctx, keys...)
 }
 
+// SetDefaultLogger sets the default logger upon which to base new loggers.
+func SetDefaultLogger(logger Logger) {
+	entry, ok := logger.(*logrus.Entry)
+	if !ok {
+		return
+	}
+
+	defaultLoggerMu.Lock()
+	defaultLogger = entry
+	defaultLoggerMu.Unlock()
+}
+
 // GetLogrusLogger returns the logrus logger for the context. If one more keys
 // are provided, they will be resolved on the context and included in the
 // logger. Only use this function if specific logrus functionality is
@@ -104,9 +122,9 @@ func getLogrusLogger(ctx context.Context, keys ...interface{}) *logrus.Entry {
 			fields["instance.id"] = instanceID
 		}
 
-		fields["go.version"] = runtime.Version()
-		// If no logger is found, just return the standard logger.
-		logger = logrus.StandardLogger().WithFields(fields)
+		defaultLoggerMu.RLock()
+		logger = defaultLogger.WithFields(fields)
+		defaultLoggerMu.RUnlock()
 	}
 
 	fields := logrus.Fields{}
diff --git a/registry/registry.go b/registry/registry.go
index 39c0fade9..5cc77bff0 100644
--- a/registry/registry.go
+++ b/registry/registry.go
@@ -304,6 +304,7 @@ func configureLogging(ctx context.Context, config *configuration.Configuration)
 		ctx = dcontext.WithLogger(ctx, dcontext.GetLogger(ctx, fields...))
 	}
 
+	dcontext.SetDefaultLogger(dcontext.GetLogger(ctx))
 	return ctx, nil
 }
 
diff --git a/registry/registry_test.go b/registry/registry_test.go
index d8deb35e1..206a8899f 100644
--- a/registry/registry_test.go
+++ b/registry/registry_test.go
@@ -13,7 +13,10 @@ import (
 	"time"
 
 	"github.com/docker/distribution/configuration"
+	dcontext "github.com/docker/distribution/context"
 	_ "github.com/docker/distribution/registry/storage/driver/inmemory"
+	"github.com/sirupsen/logrus"
+	"gopkg.in/yaml.v2"
 )
 
 // Tests to ensure nextProtos returns the correct protocols when:
@@ -98,3 +101,59 @@ func TestGracefulShutdown(t *testing.T) {
 		t.Error("Body is not {}; ", string(body))
 	}
 }
+
+func TestConfigureLogging(t *testing.T) {
+	yamlConfig := `---
+log:
+  level: warn
+  fields:
+    foo: bar
+    baz: xyzzy
+`
+
+	var config configuration.Configuration
+	err := yaml.Unmarshal([]byte(yamlConfig), &config)
+	if err != nil {
+		t.Fatal("failed to parse config: ", err)
+	}
+
+	ctx, err := configureLogging(context.Background(), &config)
+	if err != nil {
+		t.Fatal("failed to configure logging: ", err)
+	}
+
+	// Check that the log level was set to Warn.
+	if logrus.IsLevelEnabled(logrus.InfoLevel) {
+		t.Error("expected Info to be disabled, is enabled")
+	}
+
+	// Check that the returned context's logger includes the right fields.
+	logger := dcontext.GetLogger(ctx)
+	entry, ok := logger.(*logrus.Entry)
+	if !ok {
+		t.Fatalf("expected logger to be a *logrus.Entry, is: %T", entry)
+	}
+	val, ok := entry.Data["foo"].(string)
+	if !ok || val != "bar" {
+		t.Error("field foo not configured correctly; expected 'bar' got: ", val)
+	}
+	val, ok = entry.Data["baz"].(string)
+	if !ok || val != "xyzzy" {
+		t.Error("field baz not configured correctly; expected 'xyzzy' got: ", val)
+	}
+
+	// Get a logger for a new, empty context and make sure it also has the right fields.
+	logger = dcontext.GetLogger(context.Background())
+	entry, ok = logger.(*logrus.Entry)
+	if !ok {
+		t.Fatalf("expected logger to be a *logrus.Entry, is: %T", entry)
+	}
+	val, ok = entry.Data["foo"].(string)
+	if !ok || val != "bar" {
+		t.Error("field foo not configured correctly; expected 'bar' got: ", val)
+	}
+	val, ok = entry.Data["baz"].(string)
+	if !ok || val != "xyzzy" {
+		t.Error("field baz not configured correctly; expected 'xyzzy' got: ", val)
+	}
+}