Update log.entry() to not use global logger (#1524)

Multiple log entries sharing a global logger can cause changes to the
entries' loggers to escape to the global level. For example, if an entry
is changed to output its log lines to a custom io.Writer, the global
logger will also be changed to write logs the custom io.Writer.

Also, when concurrent callers attempt to change the output target of
their respective log entries, the global logger will end up with racey
outputs.

This change clones the global logger inside the log.entry() function and
binds the clone logger to the entry instance.

Signed-off-by: Ivan Sim <ivan.sim@kasten.io>

Co-authored-by: mergify[bot] <37929162+mergify[bot]@users.noreply.github.com>

pkg/log/log.go

@@ -192,7 +192,6 @@ func (l *logger) PrintTo(w io.Writer, msg string, fields ...field.M) {
 
 func (l *logger) entry(fields ...field.M) *logrus.Entry {
 	logFields := make(logrus.Fields)
-
 	if envVarFields != nil {
 		for _, f := range envVarFields.Fields() {
 			logFields[f.Key()] = f.Value()
@@ -216,7 +215,10 @@ func (l *logger) entry(fields ...field.M) *logrus.Entry {
 		}
 	}
 
-	entry := log.WithFields(logFields)
+	// use a cloned logger for this entry, so that any changes to this clone
+	// (e.g., via SetOutput()) will not affect the global logger.
+	cloned := cloneGlobalLogger()
+	entry := cloned.WithFields(logFields)
 	if l.err != nil {
 		entry = entry.WithError(l.err)
 	}
@@ -254,3 +256,19 @@ func entryToJSON(entry *logrus.Entry) []byte {
 
 	return bytes
 }
+
+func cloneGlobalLogger() *logrus.Logger {
+	cloned := logrus.New()
+	cloned.SetFormatter(log.Formatter)
+	cloned.SetReportCaller(log.ReportCaller)
+	cloned.SetLevel(log.Level)
+	cloned.SetOutput(log.Out)
+	cloned.ExitFunc = log.ExitFunc
+	for _, hooks := range log.Hooks {
+		for _, hook := range hooks {
+			cloned.Hooks.Add(hook)
+		}
+	}
+
+	return cloned
+}

pkg/log/log_test.go

@@ -5,7 +5,9 @@ import (
 	"context"
 	"encoding/json"
 	"errors"
+	"fmt"
 	"os"
+	"sync"
 	"testing"
 	"time"
 
@@ -111,6 +113,45 @@ func (s *LogSuite) TestLogPrintTo(c *C) {
 	c.Assert(entry["msg"], Equals, msg)
 }
 
+func (s *LogSuite) TestLogPrintToParallel(c *C) {
+	// this test ensures that the io.Writer passed to PrintTo() doesn't override
+	// that of the global logger.
+	// previously, the entry() function would return an entry bound to the global
+	// logger where changes made to the entry's logger yields a global effect.
+	// see https://github.com/kanisterio/kanister/issues/1523.
+
+	var (
+		msg     = "test log message"
+		buffers = []*bytes.Buffer{
+			{},
+			{},
+		}
+		wg = sync.WaitGroup{}
+	)
+
+	for i := 0; i < len(buffers); i++ {
+		wg.Add(1)
+		go func(i int) {
+			defer wg.Done()
+
+			fields := map[string]interface{}{
+				"field1": "value1",
+				"field2": "value2",
+			}
+			PrintTo(buffers[i], fmt.Sprintf("%s %d", msg, i), fields)
+		}(i)
+	}
+	wg.Wait()
+
+	for i := 0; i < len(buffers); i++ {
+		actual := map[string]interface{}{}
+		err := json.Unmarshal(buffers[i].Bytes(), &actual)
+		c.Assert(err, IsNil)
+		c.Assert(actual, NotNil)
+		c.Assert(actual["msg"], Equals, fmt.Sprintf("%s %d", msg, i))
+	}
+}
+
 func testLogMessage(c *C, msg string, print func(string, ...field.M), fields ...field.M) map[string]interface{} {
 	log.SetFormatter(&logrus.JSONFormatter{TimestampFormat: time.RFC3339Nano})
 	var memLog bytes.Buffer
@@ -148,8 +189,44 @@ func (s *LogSuite) TestLogLevel(c *C) {
 	}()
 	initLogLevel()
 	Debug().WithContext(ctx).Print("Testing debug level")
+
 	cerr := json.Unmarshal(output.Bytes(), &entry)
 	c.Assert(cerr, IsNil)
 	c.Assert(entry, NotNil)
 	c.Assert(entry["msg"], Equals, "Testing debug level")
 }
+
+func (s *LogSuite) TestCloneGlobalLogger(c *C) {
+	actual := cloneGlobalLogger()
+	c.Assert(actual.Formatter, Equals, log.Formatter)
+	c.Assert(actual.ReportCaller, Equals, log.ReportCaller)
+	c.Assert(actual.Level, Equals, log.Level)
+	c.Assert(actual.Out, Equals, log.Out)
+	c.Assert(actual.Hooks, DeepEquals, log.Hooks)
+
+	// changing `actual` should not affect global logger
+	actual.SetFormatter(&logrus.TextFormatter{})
+	actual.SetReportCaller(true)
+	actual.SetLevel(logrus.ErrorLevel)
+	actual.SetOutput(&bytes.Buffer{})
+	actual.AddHook(&testLogHook{})
+
+	c.Assert(actual.Formatter, Not(Equals), log.Formatter)
+	c.Assert(actual.ReportCaller, Not(Equals), log.ReportCaller)
+	c.Assert(actual.Level, Not(Equals), log.Level)
+	c.Assert(actual.Out, Not(Equals), log.Out)
+	c.Assert(actual.Hooks, Not(DeepEquals), log.Hooks)
+}
+
+type testLogHook struct{}
+
+func (t *testLogHook) Levels() []logrus.Level {
+	return []logrus.Level{
+		logrus.InfoLevel,
+		logrus.DebugLevel,
+	}
+}
+
+func (t *testLogHook) Fire(*logrus.Entry) error {
+	return nil
+}