Skip to content

Commit

Permalink
Fix logrus logger hook data race condition (#181)
Browse files Browse the repository at this point in the history
Bumped logrus version from v1.8.0 to v1.8.1
  • Loading branch information
bjsignalfx authored Mar 24, 2021
1 parent 5169d0e commit 4517674
Show file tree
Hide file tree
Showing 3 changed files with 76 additions and 28 deletions.
2 changes: 1 addition & 1 deletion go.mod
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
4 changes: 2 additions & 2 deletions go.sum
Original file line number Diff line number Diff line change
Expand Up @@ -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=
Expand Down Expand Up @@ -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=
Expand Down
98 changes: 73 additions & 25 deletions internal/receiver/smartagentreceiver/log_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down Expand Up @@ -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"}
Expand All @@ -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)
Expand All @@ -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)
}
}

Expand All @@ -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.
Expand All @@ -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")

Expand All @@ -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()))
Expand Down

0 comments on commit 4517674

Please sign in to comment.