From 4517674279a414620c962b9c328f3b8e3b3d8e81 Mon Sep 17 00:00:00 2001 From: Bremer Jonathan Date: Wed, 24 Mar 2021 19:13:53 -0400 Subject: [PATCH] Fix logrus logger hook data race condition (#181) Bumped logrus version from v1.8.0 to v1.8.1 --- go.mod | 2 +- go.sum | 4 +- .../receiver/smartagentreceiver/log_test.go | 98 ++++++++++++++----- 3 files changed, 76 insertions(+), 28 deletions(-) diff --git a/go.mod b/go.mod index bd6ef1bc33..ed3e96c62e 100644 --- a/go.mod +++ b/go.mod @@ -41,7 +41,7 @@ require ( github.com/signalfx/defaults v1.2.2-0.20180531161417-70562fe60657 github.com/signalfx/golib/v3 v3.3.16 github.com/signalfx/signalfx-agent v1.0.1-0.20210322175059-8828c6244c88 - github.com/sirupsen/logrus v1.8.0 + github.com/sirupsen/logrus v1.8.1 github.com/spf13/viper v1.7.1 github.com/stretchr/testify v1.7.0 go.opentelemetry.io/collector v0.22.1-0.20210317222125-85804ff25770 diff --git a/go.sum b/go.sum index 68e0e1cbbc..c9d002b0a3 100644 --- a/go.sum +++ b/go.sum @@ -1317,7 +1317,6 @@ github.com/linode/linodego v0.7.1/go.mod h1:ga11n3ivecUrPCHN0rANxKmfWBJVkOXfLMZi github.com/logrusorgru/aurora v0.0.0-20181002194514-a7b3b318ed4e/go.mod h1:7rIyQOR62GCctdiQpZ/zOJlFyk6y+94wXzv6RNZgaR4= github.com/lucasb-eyer/go-colorful v1.0.2/go.mod h1:0MS4r+7BZKSJ5mw4/S5MPN+qHFF1fYclkSPilDOKW0s= github.com/lucasb-eyer/go-colorful v1.0.3/go.mod h1:R4dSotOR9KMtayYi1e77YzuveK+i7ruzyGqttikkLy0= -github.com/magefile/mage v1.10.0 h1:3HiXzCUY12kh9bIuyXShaVe529fJfyqoVM42o/uom2g= github.com/magefile/mage v1.10.0/go.mod h1:z5UZb/iS3GoOSn0JgWuiw7dxlurVYTu+/jHXqQg881A= github.com/magiconair/properties v1.8.0/go.mod h1:PppfXfuXeibc/6YijjN8zIbojt8czPbwD3XqdrwzmxQ= github.com/magiconair/properties v1.8.1 h1:ZC2Vc7/ZFkGmsVC9KvOjumD+G5lXy2RtTKyzRKO2BQ4= @@ -1887,8 +1886,9 @@ github.com/sirupsen/logrus v1.4.0/go.mod h1:LxeOpSwHxABJmUn/MG1IvRgCAasNZTLOkJPx github.com/sirupsen/logrus v1.4.1/go.mod h1:ni0Sbl8bgC9z8RoU9G6nDWqqs/fq4eDPysMBDgk/93Q= github.com/sirupsen/logrus v1.4.2/go.mod h1:tLMulIdttU9McNUspp0xgXVQah82FyeX6MwdIuYE2rE= github.com/sirupsen/logrus v1.6.0/go.mod h1:7uNnSEd1DgxDLC74fIahvMZmmYsHGZGEOFrfsX/uA88= -github.com/sirupsen/logrus v1.8.0 h1:nfhvjKcUMhBMVqbKHJlk5RPrrfYr/NMo3692g0dwfWU= github.com/sirupsen/logrus v1.8.0/go.mod h1:4GuYW9TZmE769R5STWrRakJc4UqQ3+QQ95fyz7ENv1A= +github.com/sirupsen/logrus v1.8.1 h1:dJKuHgqk1NNQlqoA6BTlM1Wf9DOH3NBjQyu0h9+AZZE= +github.com/sirupsen/logrus v1.8.1/go.mod h1:yWOB1SBYBC5VeMP7gHvWumXLIWorT60ONWic61uBYv0= github.com/smartystreets/assertions v0.0.0-20180725160413-e900ae048470/go.mod h1:OnSkiWE9lh6wB0YB77sQom3nweQdgAjqCqsofrRNTgc= github.com/smartystreets/assertions v0.0.0-20180927180507-b2de0cb4f26d/go.mod h1:OnSkiWE9lh6wB0YB77sQom3nweQdgAjqCqsofrRNTgc= github.com/smartystreets/assertions v0.0.0-20190215210624-980c5ac6f3ac/go.mod h1:OnSkiWE9lh6wB0YB77sQom3nweQdgAjqCqsofrRNTgc= diff --git a/internal/receiver/smartagentreceiver/log_test.go b/internal/receiver/smartagentreceiver/log_test.go index 1017fc079b..19e3c19345 100644 --- a/internal/receiver/smartagentreceiver/log_test.go +++ b/internal/receiver/smartagentreceiver/log_test.go @@ -19,6 +19,7 @@ import ( "testing" "github.com/sirupsen/logrus" + "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" "go.uber.org/zap" "go.uber.org/zap/zapcore" @@ -53,18 +54,18 @@ func TestRedirectMonitorLogs(t *testing.T) { } // Simulating the creation of logrus entry/loggers in monitors (monitor1, monitor2). - monitor1Logger := logrus.WithFields(logrus.Fields{"monitorType": "monitor1"}) - monitor2Logger := logrus.WithFields(logrus.Fields{"monitorType": "monitor2"}) + monitor1LogrusLogger := logrus.WithFields(logrus.Fields{"monitorType": "monitor1"}) + monitor2LogrusLogger := logrus.WithFields(logrus.Fields{"monitorType": "monitor2"}) // Case where logs do not have "monitorType" field - monitor3Logger := logrus.WithFields(logrus.Fields{}) + monitor3LogrusLogger := logrus.WithFields(logrus.Fields{}) - // Checking that the logrus standard logger is the logger for monitor1 and monitor2. - require.Same(t, logrus.StandardLogger(), monitor1Logger.Logger, "Expected the standard logrus logger") - require.Same(t, logrus.StandardLogger(), monitor2Logger.Logger, "Expected the standard logrus logger") - require.Same(t, logrus.StandardLogger(), monitor3Logger.Logger, "Expected the standard logrus logger") + // Checking that the logrus standard logger is the logger in the monitors. + require.Same(t, logrus.StandardLogger(), monitor1LogrusLogger.Logger, "Expected the standard logrus logger") + require.Same(t, logrus.StandardLogger(), monitor2LogrusLogger.Logger, "Expected the standard logrus logger") + require.Same(t, logrus.StandardLogger(), monitor3LogrusLogger.Logger, "Expected the standard logrus logger") - // Simulating the creation of logrus keys for monitor1 and monitor2 in the smart agent receiver where: + // Simulating the creation of logrus keys for the monitors where: // 1. the monitor types (i.e. monitor1, monitor2) are known. // 2. the logger is assumed to be the standard logrus logger. monitor1LogrusKey := logrusKey{Logger: logrus.StandardLogger(), monitorType: "monitor1"} @@ -76,7 +77,7 @@ func TestRedirectMonitorLogs(t *testing.T) { monitor3ZapLogger, monitor3ZapLogs := newObservedLogs(zapLevel) defaultZapLogger, defaultLogs := newObservedLogs(zapLevel) - // Simulating logrus to zap redirections in receiver. + // Logrus to zap redirections. logToZap := newLogrusToZap(func() *zap.Logger { return defaultZapLogger }) logToZap.redirect(monitor1LogrusKey, monitor1ZapLogger) logToZap.redirect(monitor2LogrusKey, monitor2ZapLogger) @@ -86,24 +87,71 @@ func TestRedirectMonitorLogs(t *testing.T) { logMsg2 := "a log msg2" logMsg3 := "a log msg3" - // Simulating logging a message in the monitor1. - logAt(monitor1Logger, logrusLevel, logMsg1) - logAt(monitor2Logger, logrusLevel, logMsg2) - logAt(monitor3Logger, logrusLevel, logMsg3) + // Logrus logging. + logAt(monitor1LogrusLogger, logrusLevel, logMsg1) + logAt(monitor2LogrusLogger, logrusLevel, logMsg2) + logAt(monitor3LogrusLogger, logrusLevel, logMsg3) - // Checking the zap logger is logging the same number of messages logged by monitor1. + // Checking zap logs for redirected logrus logs. require.Equal(t, 1, monitor1ZapLogs.Len(), fmt.Sprintf("Expected 1 log message, got %d", monitor1ZapLogs.Len())) - require.Equal(t, 1, monitor2ZapLogs.Len(), fmt.Sprintf("Expected 1 log message, got %d", monitor2ZapLogs.Len())) - require.Equal(t, 0, monitor3ZapLogs.Len(), fmt.Sprintf("Expected 0 log message, got %d", monitor3ZapLogs.Len())) - require.Equal(t, 1, defaultLogs.Len(), fmt.Sprintf("Expected 1 log message, got %d", defaultLogs.Len())) - - // Checking that the zap logger is logging the message logged by monitor1. require.Equal(t, logMsg1, monitor1ZapLogs.All()[0].Message, fmt.Sprintf("Expected message '%s', got '%s'", logMsg1, monitor1ZapLogs.All()[0].Message)) + + require.Equal(t, 1, monitor2ZapLogs.Len(), fmt.Sprintf("Expected 1 log message, got %d", monitor2ZapLogs.Len())) require.Equal(t, logMsg2, monitor2ZapLogs.All()[0].Message, fmt.Sprintf("Expected message '%s', got '%s'", logMsg2, monitor2ZapLogs.All()[0].Message)) + + require.Equal(t, 0, monitor3ZapLogs.Len(), fmt.Sprintf("Expected 0 log message, got %d", monitor3ZapLogs.Len())) require.Equal(t, logMsg3, defaultLogs.All()[0].Message, fmt.Sprintf("Expected message '%s', got '%s'", logMsg3, defaultLogs.All()[0].Message)) + require.Equal(t, 1, defaultLogs.Len(), fmt.Sprintf("Expected 1 log message, got %d", defaultLogs.Len())) + logToZap.unRedirect(monitor1LogrusKey, monitor1ZapLogger) logToZap.unRedirect(monitor2LogrusKey, monitor2ZapLogger) + logToZap.unRedirect(monitor3LogrusKey, monitor3ZapLogger) + } +} + +func TestRedirectMonitorLogsWithNilLoggerMap(t *testing.T) { + for logrusLevel, zapLevel := range levelsMap { + //TODO: handle fatal and panic levels + if logrusLevel == logrus.FatalLevel || logrusLevel == logrus.PanicLevel { + continue + } + + // Simulating the creation of logrus entry/logger in monitor1. + monitor1LogrusLogger := logrus.WithFields(logrus.Fields{"monitorType": "monitor1"}) + + // Simulating the creation of logrus key for monitor1 in the smart agent receiver where: + // 1. the monitor types (i.e. monitor1) are known. + // 2. the logger is assumed to be the standard logrus logger. + monitor1LogrusKey := logrusKey{Logger: logrus.StandardLogger(), monitorType: "monitor1"} + + monitor1ZapLogger, monitor1ZapLogs := newObservedLogs(zapLevel) + defaultZapLogger, defaultZapLogs := newObservedLogs(zapLevel) + + // Logrus to zap redirection. + logToZap := newLogrusToZap(func() *zap.Logger { return defaultZapLogger }) + logToZap.redirect(monitor1LogrusKey, monitor1ZapLogger) + + require.Len(t, logToZap.loggerMap, 1) + require.Len(t, logToZap.loggerMap[monitor1LogrusKey], 1) + require.Equal(t, monitor1ZapLogger, logToZap.loggerMap[monitor1LogrusKey][0]) + + // Setting loggerMap to nil + logToZap.loggerMap = nil + + logMsg := "a log msg" + + // Logrus logging. + logAt(monitor1LogrusLogger, logrusLevel, logMsg) + + // Logrus logs should not be redirected to monitor1ZapLogger. + assert.Equal(t, 0, monitor1ZapLogs.Len(), fmt.Sprintf("Expected 0 log message, got %d", monitor1ZapLogs.Len())) + + // Logrus logs should be redirected to defaultZapLogger when loggerMap is nil. + assert.Equal(t, 1, defaultZapLogs.Len(), fmt.Sprintf("Expected 1 log message, got %d", monitor1ZapLogs.Len())) + require.Equal(t, logMsg, defaultZapLogs.All()[0].Message, fmt.Sprintf("Expected message '%s', got '%s'", logMsg, defaultZapLogs.All()[0].Message)) + + logToZap.unRedirect(monitor1LogrusKey, monitor1ZapLogger) } } @@ -115,8 +163,8 @@ func TestRedirectSameMonitorManyInstancesLogs(t *testing.T) { } // Simulating the creation of logrus entry/loggers in instances of a monitor (monitor1). - instance1Logger := logrus.WithFields(logrus.Fields{"monitorType": "monitor1"}) - instance2Logger := logrus.WithFields(logrus.Fields{"monitorType": "monitor1"}) + instance1LogrusLogger := logrus.WithFields(logrus.Fields{"monitorType": "monitor1"}) + instance2LogrusLogger := logrus.WithFields(logrus.Fields{"monitorType": "monitor1"}) // Simulating the creation of logrus keys for the instances of monitor1 in the smart agent receiver where: // 1. the monitor type (i.e. monitor1) is known. @@ -125,8 +173,8 @@ func TestRedirectSameMonitorManyInstancesLogs(t *testing.T) { instance2LogrusKey := logrusKey{Logger: logrus.StandardLogger(), monitorType: "monitor1"} // Checking that the logrus standard logger is the logger for both monitor1 instances. - require.Same(t, logrus.StandardLogger(), instance1Logger.Logger, "Expected the standard logrus logger") - require.Same(t, logrus.StandardLogger(), instance2Logger.Logger, "Expected the standard logrus logger") + require.Same(t, logrus.StandardLogger(), instance1LogrusLogger.Logger, "Expected the standard logrus logger") + require.Same(t, logrus.StandardLogger(), instance2LogrusLogger.Logger, "Expected the standard logrus logger") // Checking that the logrus keys are equal. require.Equal(t, instance1LogrusKey, instance2LogrusKey, "Expected the standard logrus logger") @@ -142,8 +190,8 @@ func TestRedirectSameMonitorManyInstancesLogs(t *testing.T) { logMsg2 := "a log msg2" // Simulating logging messages in the instances of monitor1. - logAt(instance1Logger, logrusLevel, logMsg1) - logAt(instance2Logger, logrusLevel, logMsg2) + logAt(instance1LogrusLogger, logrusLevel, logMsg1) + logAt(instance2LogrusLogger, logrusLevel, logMsg2) // Asserting that messages logged by all instances get logged by the zap logger of the first instance. require.Equal(t, 2, instance1ZapLogs.Len(), fmt.Sprintf("Expected 2 log message, got %d", instance1ZapLogs.Len()))