2014-03-11 03:22:08 +04:00
|
|
|
package logrus
|
|
|
|
|
|
|
|
import (
|
|
|
|
"bytes"
|
|
|
|
"encoding/json"
|
2018-08-26 14:40:51 +03:00
|
|
|
"io/ioutil"
|
2014-09-21 21:16:35 +04:00
|
|
|
"strconv"
|
|
|
|
"strings"
|
2015-02-17 04:06:45 +03:00
|
|
|
"sync"
|
2014-03-11 03:22:08 +04:00
|
|
|
"testing"
|
2016-12-01 21:23:00 +03:00
|
|
|
"time"
|
2014-03-11 03:22:08 +04:00
|
|
|
|
|
|
|
"github.com/stretchr/testify/assert"
|
|
|
|
)
|
|
|
|
|
|
|
|
func LogAndAssertJSON(t *testing.T, log func(*Logger), assertions func(fields Fields)) {
|
|
|
|
var buffer bytes.Buffer
|
|
|
|
var fields Fields
|
|
|
|
|
|
|
|
logger := New()
|
|
|
|
logger.Out = &buffer
|
|
|
|
logger.Formatter = new(JSONFormatter)
|
|
|
|
|
|
|
|
log(logger)
|
|
|
|
|
|
|
|
err := json.Unmarshal(buffer.Bytes(), &fields)
|
|
|
|
assert.Nil(t, err)
|
|
|
|
|
|
|
|
assertions(fields)
|
|
|
|
}
|
|
|
|
|
2014-09-21 21:16:35 +04:00
|
|
|
func LogAndAssertText(t *testing.T, log func(*Logger), assertions func(fields map[string]string)) {
|
|
|
|
var buffer bytes.Buffer
|
|
|
|
|
|
|
|
logger := New()
|
|
|
|
logger.Out = &buffer
|
|
|
|
logger.Formatter = &TextFormatter{
|
|
|
|
DisableColors: true,
|
|
|
|
}
|
|
|
|
|
|
|
|
log(logger)
|
|
|
|
|
|
|
|
fields := make(map[string]string)
|
|
|
|
for _, kv := range strings.Split(buffer.String(), " ") {
|
|
|
|
if !strings.Contains(kv, "=") {
|
|
|
|
continue
|
|
|
|
}
|
|
|
|
kvArr := strings.Split(kv, "=")
|
|
|
|
key := strings.TrimSpace(kvArr[0])
|
2014-12-18 17:14:24 +03:00
|
|
|
val := kvArr[1]
|
|
|
|
if kvArr[1][0] == '"' {
|
|
|
|
var err error
|
|
|
|
val, err = strconv.Unquote(val)
|
|
|
|
assert.NoError(t, err)
|
|
|
|
}
|
2014-09-21 21:16:35 +04:00
|
|
|
fields[key] = val
|
|
|
|
}
|
|
|
|
assertions(fields)
|
|
|
|
}
|
|
|
|
|
2016-12-06 23:53:21 +03:00
|
|
|
// TestReportCaller verifies that when ReportCaller is set, the 'func' field
|
2016-11-26 06:02:56 +03:00
|
|
|
// is added, and when it is unset it is not set or modified
|
2017-08-03 03:21:18 +03:00
|
|
|
// Verify that functions within the Logrus package aren't considered when
|
|
|
|
// discovering the caller.
|
|
|
|
func TestReportCallerWhenConfigured(t *testing.T) {
|
2016-11-26 06:02:56 +03:00
|
|
|
LogAndAssertJSON(t, func(log *Logger) {
|
2016-12-01 01:07:10 +03:00
|
|
|
log.ReportCaller = false
|
2016-11-26 06:02:56 +03:00
|
|
|
log.Print("testNoCaller")
|
|
|
|
}, func(fields Fields) {
|
2016-12-01 01:07:10 +03:00
|
|
|
assert.Equal(t, "testNoCaller", fields["msg"])
|
|
|
|
assert.Equal(t, "info", fields["level"])
|
2016-12-06 23:53:21 +03:00
|
|
|
assert.Equal(t, nil, fields["func"])
|
2016-11-26 06:02:56 +03:00
|
|
|
})
|
|
|
|
|
|
|
|
LogAndAssertJSON(t, func(log *Logger) {
|
2016-12-01 01:07:10 +03:00
|
|
|
log.ReportCaller = true
|
2016-11-26 06:02:56 +03:00
|
|
|
log.Print("testWithCaller")
|
|
|
|
}, func(fields Fields) {
|
2016-12-01 01:07:10 +03:00
|
|
|
assert.Equal(t, "testWithCaller", fields["msg"])
|
|
|
|
assert.Equal(t, "info", fields["level"])
|
2016-12-06 23:53:21 +03:00
|
|
|
assert.Equal(t, "testing.tRunner", fields["func"])
|
2016-11-26 06:02:56 +03:00
|
|
|
})
|
|
|
|
}
|
|
|
|
|
2017-08-03 03:21:18 +03:00
|
|
|
func logSomething(t *testing.T, message string) Fields {
|
|
|
|
var buffer bytes.Buffer
|
|
|
|
var fields Fields
|
|
|
|
|
|
|
|
logger := New()
|
|
|
|
logger.Out = &buffer
|
|
|
|
logger.Formatter = new(JSONFormatter)
|
|
|
|
logger.ReportCaller = true
|
|
|
|
|
|
|
|
// override the filter to allow reporting of functions within the logrus package
|
2018-10-27 16:21:30 +03:00
|
|
|
logrusPackage = "bogusForTesting"
|
2017-08-03 03:21:18 +03:00
|
|
|
|
|
|
|
entry := logger.WithFields(Fields{
|
|
|
|
"foo": "bar",
|
|
|
|
})
|
|
|
|
|
|
|
|
entry.Info(message)
|
|
|
|
|
|
|
|
err := json.Unmarshal(buffer.Bytes(), &fields)
|
|
|
|
assert.Nil(t, err)
|
|
|
|
|
|
|
|
// now clear the override so as not to mess with other usage
|
2018-10-27 16:21:30 +03:00
|
|
|
logrusPackage = ""
|
2017-08-03 03:21:18 +03:00
|
|
|
return fields
|
|
|
|
}
|
|
|
|
|
|
|
|
// TestReportCallerHelperDirect - verify reference when logging from a regular function
|
|
|
|
func TestReportCallerHelperDirect(t *testing.T) {
|
|
|
|
fields := logSomething(t, "direct")
|
|
|
|
|
|
|
|
assert.Equal(t, "direct", fields["msg"])
|
|
|
|
assert.Equal(t, "info", fields["level"])
|
2017-08-03 03:28:13 +03:00
|
|
|
assert.Regexp(t, "github.com/.*/logrus.logSomething", fields["func"])
|
2017-08-03 03:21:18 +03:00
|
|
|
}
|
|
|
|
|
|
|
|
// TestReportCallerHelperDirect - verify reference when logging from a function called via pointer
|
|
|
|
func TestReportCallerHelperViaPointer(t *testing.T) {
|
|
|
|
fptr := logSomething
|
|
|
|
fields := fptr(t, "via pointer")
|
|
|
|
|
|
|
|
assert.Equal(t, "via pointer", fields["msg"])
|
|
|
|
assert.Equal(t, "info", fields["level"])
|
2017-08-03 03:28:13 +03:00
|
|
|
assert.Regexp(t, "github.com/.*/logrus.logSomething", fields["func"])
|
2017-08-03 03:21:18 +03:00
|
|
|
}
|
|
|
|
|
2014-03-11 03:22:08 +04:00
|
|
|
func TestPrint(t *testing.T) {
|
|
|
|
LogAndAssertJSON(t, func(log *Logger) {
|
|
|
|
log.Print("test")
|
|
|
|
}, func(fields Fields) {
|
2016-12-01 01:07:10 +03:00
|
|
|
assert.Equal(t, "test", fields["msg"])
|
|
|
|
assert.Equal(t, "info", fields["level"])
|
2014-03-11 03:22:08 +04:00
|
|
|
})
|
|
|
|
}
|
|
|
|
|
|
|
|
func TestInfo(t *testing.T) {
|
|
|
|
LogAndAssertJSON(t, func(log *Logger) {
|
|
|
|
log.Info("test")
|
|
|
|
}, func(fields Fields) {
|
2016-12-01 01:07:10 +03:00
|
|
|
assert.Equal(t, "test", fields["msg"])
|
|
|
|
assert.Equal(t, "info", fields["level"])
|
2014-03-11 03:22:08 +04:00
|
|
|
})
|
|
|
|
}
|
|
|
|
|
|
|
|
func TestWarn(t *testing.T) {
|
|
|
|
LogAndAssertJSON(t, func(log *Logger) {
|
|
|
|
log.Warn("test")
|
|
|
|
}, func(fields Fields) {
|
2016-12-01 01:07:10 +03:00
|
|
|
assert.Equal(t, "test", fields["msg"])
|
|
|
|
assert.Equal(t, "warning", fields["level"])
|
2014-03-11 03:22:08 +04:00
|
|
|
})
|
|
|
|
}
|
2014-03-19 20:02:00 +04:00
|
|
|
|
2014-05-04 03:51:12 +04:00
|
|
|
func TestInfolnShouldAddSpacesBetweenStrings(t *testing.T) {
|
|
|
|
LogAndAssertJSON(t, func(log *Logger) {
|
|
|
|
log.Infoln("test", "test")
|
|
|
|
}, func(fields Fields) {
|
2016-12-01 01:07:10 +03:00
|
|
|
assert.Equal(t, "test test", fields["msg"])
|
2014-05-04 03:51:12 +04:00
|
|
|
})
|
|
|
|
}
|
|
|
|
|
|
|
|
func TestInfolnShouldAddSpacesBetweenStringAndNonstring(t *testing.T) {
|
|
|
|
LogAndAssertJSON(t, func(log *Logger) {
|
|
|
|
log.Infoln("test", 10)
|
|
|
|
}, func(fields Fields) {
|
2016-12-01 01:07:10 +03:00
|
|
|
assert.Equal(t, "test 10", fields["msg"])
|
2014-05-04 03:51:12 +04:00
|
|
|
})
|
|
|
|
}
|
|
|
|
|
|
|
|
func TestInfolnShouldAddSpacesBetweenTwoNonStrings(t *testing.T) {
|
|
|
|
LogAndAssertJSON(t, func(log *Logger) {
|
|
|
|
log.Infoln(10, 10)
|
|
|
|
}, func(fields Fields) {
|
2016-12-01 01:07:10 +03:00
|
|
|
assert.Equal(t, "10 10", fields["msg"])
|
2014-05-04 03:51:12 +04:00
|
|
|
})
|
|
|
|
}
|
|
|
|
|
|
|
|
func TestInfoShouldAddSpacesBetweenTwoNonStrings(t *testing.T) {
|
|
|
|
LogAndAssertJSON(t, func(log *Logger) {
|
|
|
|
log.Infoln(10, 10)
|
|
|
|
}, func(fields Fields) {
|
2016-12-01 01:07:10 +03:00
|
|
|
assert.Equal(t, "10 10", fields["msg"])
|
2014-05-04 03:51:12 +04:00
|
|
|
})
|
|
|
|
}
|
|
|
|
|
|
|
|
func TestInfoShouldNotAddSpacesBetweenStringAndNonstring(t *testing.T) {
|
|
|
|
LogAndAssertJSON(t, func(log *Logger) {
|
|
|
|
log.Info("test", 10)
|
|
|
|
}, func(fields Fields) {
|
2016-12-01 01:07:10 +03:00
|
|
|
assert.Equal(t, "test10", fields["msg"])
|
2014-05-04 03:51:12 +04:00
|
|
|
})
|
|
|
|
}
|
|
|
|
|
|
|
|
func TestInfoShouldNotAddSpacesBetweenStrings(t *testing.T) {
|
|
|
|
LogAndAssertJSON(t, func(log *Logger) {
|
|
|
|
log.Info("test", "test")
|
|
|
|
}, func(fields Fields) {
|
2016-12-01 01:07:10 +03:00
|
|
|
assert.Equal(t, "testtest", fields["msg"])
|
2014-05-04 03:51:12 +04:00
|
|
|
})
|
|
|
|
}
|
2014-06-09 19:53:23 +04:00
|
|
|
|
|
|
|
func TestWithFieldsShouldAllowAssignments(t *testing.T) {
|
|
|
|
var buffer bytes.Buffer
|
|
|
|
var fields Fields
|
|
|
|
|
|
|
|
logger := New()
|
|
|
|
logger.Out = &buffer
|
|
|
|
logger.Formatter = new(JSONFormatter)
|
|
|
|
|
|
|
|
localLog := logger.WithFields(Fields{
|
|
|
|
"key1": "value1",
|
|
|
|
})
|
|
|
|
|
|
|
|
localLog.WithField("key2", "value2").Info("test")
|
|
|
|
err := json.Unmarshal(buffer.Bytes(), &fields)
|
|
|
|
assert.Nil(t, err)
|
|
|
|
|
|
|
|
assert.Equal(t, "value2", fields["key2"])
|
|
|
|
assert.Equal(t, "value1", fields["key1"])
|
|
|
|
|
|
|
|
buffer = bytes.Buffer{}
|
|
|
|
fields = Fields{}
|
|
|
|
localLog.Info("test")
|
|
|
|
err = json.Unmarshal(buffer.Bytes(), &fields)
|
|
|
|
assert.Nil(t, err)
|
|
|
|
|
|
|
|
_, ok := fields["key2"]
|
|
|
|
assert.Equal(t, false, ok)
|
|
|
|
assert.Equal(t, "value1", fields["key1"])
|
|
|
|
}
|
2014-07-27 05:02:08 +04:00
|
|
|
|
2014-07-27 05:26:04 +04:00
|
|
|
func TestUserSuppliedFieldDoesNotOverwriteDefaults(t *testing.T) {
|
|
|
|
LogAndAssertJSON(t, func(log *Logger) {
|
|
|
|
log.WithField("msg", "hello").Info("test")
|
|
|
|
}, func(fields Fields) {
|
2016-12-01 01:07:10 +03:00
|
|
|
assert.Equal(t, "test", fields["msg"])
|
2014-07-27 05:26:04 +04:00
|
|
|
})
|
|
|
|
}
|
|
|
|
|
|
|
|
func TestUserSuppliedMsgFieldHasPrefix(t *testing.T) {
|
|
|
|
LogAndAssertJSON(t, func(log *Logger) {
|
|
|
|
log.WithField("msg", "hello").Info("test")
|
|
|
|
}, func(fields Fields) {
|
2016-12-01 01:07:10 +03:00
|
|
|
assert.Equal(t, "test", fields["msg"])
|
|
|
|
assert.Equal(t, "hello", fields["fields.msg"])
|
2014-07-27 05:26:04 +04:00
|
|
|
})
|
|
|
|
}
|
|
|
|
|
|
|
|
func TestUserSuppliedTimeFieldHasPrefix(t *testing.T) {
|
|
|
|
LogAndAssertJSON(t, func(log *Logger) {
|
|
|
|
log.WithField("time", "hello").Info("test")
|
|
|
|
}, func(fields Fields) {
|
2016-12-01 01:07:10 +03:00
|
|
|
assert.Equal(t, "hello", fields["fields.time"])
|
2014-07-27 05:26:04 +04:00
|
|
|
})
|
|
|
|
}
|
|
|
|
|
|
|
|
func TestUserSuppliedLevelFieldHasPrefix(t *testing.T) {
|
|
|
|
LogAndAssertJSON(t, func(log *Logger) {
|
|
|
|
log.WithField("level", 1).Info("test")
|
|
|
|
}, func(fields Fields) {
|
2016-12-01 01:07:10 +03:00
|
|
|
assert.Equal(t, "info", fields["level"])
|
|
|
|
assert.Equal(t, 1.0, fields["fields.level"]) // JSON has floats only
|
2014-07-27 05:26:04 +04:00
|
|
|
})
|
|
|
|
}
|
|
|
|
|
2014-09-21 21:16:35 +04:00
|
|
|
func TestDefaultFieldsAreNotPrefixed(t *testing.T) {
|
|
|
|
LogAndAssertText(t, func(log *Logger) {
|
|
|
|
ll := log.WithField("herp", "derp")
|
|
|
|
ll.Info("hello")
|
|
|
|
ll.Info("bye")
|
|
|
|
}, func(fields map[string]string) {
|
|
|
|
for _, fieldName := range []string{"fields.level", "fields.time", "fields.msg"} {
|
|
|
|
if _, ok := fields[fieldName]; ok {
|
|
|
|
t.Fatalf("should not have prefixed %q: %v", fieldName, fields)
|
|
|
|
}
|
|
|
|
}
|
|
|
|
})
|
|
|
|
}
|
|
|
|
|
2018-06-29 17:53:51 +03:00
|
|
|
func TestWithTimeShouldOverrideTime(t *testing.T) {
|
|
|
|
now := time.Now().Add(24 * time.Hour)
|
|
|
|
|
|
|
|
LogAndAssertJSON(t, func(log *Logger) {
|
|
|
|
log.WithTime(now).Info("foobar")
|
|
|
|
}, func(fields Fields) {
|
|
|
|
assert.Equal(t, fields["time"], now.Format(defaultTimestampFormat))
|
|
|
|
})
|
|
|
|
}
|
|
|
|
|
|
|
|
func TestWithTimeShouldNotOverrideFields(t *testing.T) {
|
|
|
|
now := time.Now().Add(24 * time.Hour)
|
|
|
|
|
|
|
|
LogAndAssertJSON(t, func(log *Logger) {
|
|
|
|
log.WithField("herp", "derp").WithTime(now).Info("blah")
|
|
|
|
}, func(fields Fields) {
|
|
|
|
assert.Equal(t, fields["time"], now.Format(defaultTimestampFormat))
|
|
|
|
assert.Equal(t, fields["herp"], "derp")
|
|
|
|
})
|
|
|
|
}
|
|
|
|
|
|
|
|
func TestWithFieldShouldNotOverrideTime(t *testing.T) {
|
|
|
|
now := time.Now().Add(24 * time.Hour)
|
|
|
|
|
|
|
|
LogAndAssertJSON(t, func(log *Logger) {
|
|
|
|
log.WithTime(now).WithField("herp", "derp").Info("blah")
|
|
|
|
}, func(fields Fields) {
|
|
|
|
assert.Equal(t, fields["time"], now.Format(defaultTimestampFormat))
|
|
|
|
assert.Equal(t, fields["herp"], "derp")
|
|
|
|
})
|
|
|
|
}
|
|
|
|
|
|
|
|
func TestTimeOverrideMultipleLogs(t *testing.T) {
|
|
|
|
var buffer bytes.Buffer
|
|
|
|
var firstFields, secondFields Fields
|
|
|
|
|
|
|
|
logger := New()
|
|
|
|
logger.Out = &buffer
|
|
|
|
formatter := new(JSONFormatter)
|
|
|
|
formatter.TimestampFormat = time.StampMilli
|
|
|
|
logger.Formatter = formatter
|
|
|
|
|
|
|
|
llog := logger.WithField("herp", "derp")
|
|
|
|
llog.Info("foo")
|
|
|
|
|
|
|
|
err := json.Unmarshal(buffer.Bytes(), &firstFields)
|
|
|
|
assert.NoError(t, err, "should have decoded first message")
|
|
|
|
|
|
|
|
buffer.Reset()
|
|
|
|
|
|
|
|
time.Sleep(10 * time.Millisecond)
|
|
|
|
llog.Info("bar")
|
|
|
|
|
|
|
|
err = json.Unmarshal(buffer.Bytes(), &secondFields)
|
|
|
|
assert.NoError(t, err, "should have decoded second message")
|
|
|
|
|
|
|
|
assert.NotEqual(t, firstFields["time"], secondFields["time"], "timestamps should not be equal")
|
|
|
|
}
|
|
|
|
|
2014-12-10 05:53:14 +03:00
|
|
|
func TestDoubleLoggingDoesntPrefixPreviousFields(t *testing.T) {
|
|
|
|
|
|
|
|
var buffer bytes.Buffer
|
|
|
|
var fields Fields
|
|
|
|
|
|
|
|
logger := New()
|
|
|
|
logger.Out = &buffer
|
|
|
|
logger.Formatter = new(JSONFormatter)
|
|
|
|
|
|
|
|
llog := logger.WithField("context", "eating raw fish")
|
|
|
|
|
|
|
|
llog.Info("looks delicious")
|
|
|
|
|
|
|
|
err := json.Unmarshal(buffer.Bytes(), &fields)
|
|
|
|
assert.NoError(t, err, "should have decoded first message")
|
2015-01-21 04:38:13 +03:00
|
|
|
assert.Equal(t, len(fields), 4, "should only have msg/time/level/context fields")
|
2014-12-10 05:53:14 +03:00
|
|
|
assert.Equal(t, fields["msg"], "looks delicious")
|
|
|
|
assert.Equal(t, fields["context"], "eating raw fish")
|
|
|
|
|
|
|
|
buffer.Reset()
|
|
|
|
|
|
|
|
llog.Warn("omg it is!")
|
|
|
|
|
|
|
|
err = json.Unmarshal(buffer.Bytes(), &fields)
|
|
|
|
assert.NoError(t, err, "should have decoded second message")
|
2015-01-21 04:38:13 +03:00
|
|
|
assert.Equal(t, len(fields), 4, "should only have msg/time/level/context fields")
|
2016-12-01 01:07:10 +03:00
|
|
|
assert.Equal(t, "omg it is!", fields["msg"])
|
|
|
|
assert.Equal(t, "eating raw fish", fields["context"])
|
2014-12-10 05:53:14 +03:00
|
|
|
assert.Nil(t, fields["fields.msg"], "should not have prefixed previous `msg` entry")
|
|
|
|
|
|
|
|
}
|
|
|
|
|
2016-11-26 06:02:56 +03:00
|
|
|
func TestNestedLoggingReportsCorrectCaller(t *testing.T) {
|
|
|
|
var buffer bytes.Buffer
|
|
|
|
var fields Fields
|
|
|
|
|
|
|
|
logger := New()
|
|
|
|
logger.Out = &buffer
|
|
|
|
logger.Formatter = new(JSONFormatter)
|
2016-12-01 01:07:10 +03:00
|
|
|
logger.ReportCaller = true
|
2016-11-26 06:02:56 +03:00
|
|
|
|
|
|
|
llog := logger.WithField("context", "eating raw fish")
|
|
|
|
|
|
|
|
llog.Info("looks delicious")
|
|
|
|
|
|
|
|
err := json.Unmarshal(buffer.Bytes(), &fields)
|
|
|
|
assert.NoError(t, err, "should have decoded first message")
|
2016-12-06 23:53:21 +03:00
|
|
|
assert.Equal(t, len(fields), 5, "should have msg/time/level/func/context fields")
|
2016-12-01 01:07:10 +03:00
|
|
|
assert.Equal(t, "looks delicious", fields["msg"])
|
|
|
|
assert.Equal(t, "eating raw fish", fields["context"])
|
2016-12-06 23:53:21 +03:00
|
|
|
assert.Equal(t, "testing.tRunner", fields["func"])
|
2016-11-26 06:02:56 +03:00
|
|
|
|
|
|
|
buffer.Reset()
|
|
|
|
|
|
|
|
logger.WithFields(Fields{
|
2016-12-06 23:53:21 +03:00
|
|
|
"Clyde": "Stubblefield",
|
2016-11-26 06:02:56 +03:00
|
|
|
}).WithFields(Fields{
|
2016-12-06 23:53:21 +03:00
|
|
|
"Jab'o": "Starks",
|
2016-11-26 06:02:56 +03:00
|
|
|
}).WithFields(Fields{
|
2016-12-06 23:53:21 +03:00
|
|
|
"uri": "https://www.youtube.com/watch?v=V5DTznu-9v0",
|
2016-11-26 06:02:56 +03:00
|
|
|
}).WithFields(Fields{
|
2016-12-06 23:53:21 +03:00
|
|
|
"func": "y drummer",
|
2016-11-26 06:02:56 +03:00
|
|
|
}).WithFields(Fields{
|
2016-12-06 23:53:21 +03:00
|
|
|
"James": "Brown",
|
|
|
|
}).Print("The hardest workin' man in show business")
|
2016-11-26 06:02:56 +03:00
|
|
|
|
|
|
|
err = json.Unmarshal(buffer.Bytes(), &fields)
|
|
|
|
assert.NoError(t, err, "should have decoded second message")
|
2016-11-30 21:47:03 +03:00
|
|
|
assert.Equal(t, 10, len(fields), "should have all builtin fields plus foo,bar,baz,...")
|
2016-12-06 23:53:21 +03:00
|
|
|
assert.Equal(t, "Stubblefield", fields["Clyde"])
|
|
|
|
assert.Equal(t, "Starks", fields["Jab'o"])
|
|
|
|
assert.Equal(t, "https://www.youtube.com/watch?v=V5DTznu-9v0", fields["uri"])
|
|
|
|
assert.Equal(t, "y drummer", fields["fields.func"])
|
|
|
|
assert.Equal(t, "Brown", fields["James"])
|
|
|
|
assert.Equal(t, "The hardest workin' man in show business", fields["msg"])
|
2016-11-26 06:02:56 +03:00
|
|
|
assert.Nil(t, fields["fields.msg"], "should not have prefixed previous `msg` entry")
|
2016-12-06 23:53:21 +03:00
|
|
|
assert.Equal(t, "testing.tRunner", fields["func"])
|
2016-11-26 06:02:56 +03:00
|
|
|
|
2016-12-01 01:07:10 +03:00
|
|
|
logger.ReportCaller = false // return to default value
|
2016-11-26 06:02:56 +03:00
|
|
|
}
|
|
|
|
|
2016-12-01 21:23:00 +03:00
|
|
|
func logLoop(iterations int, reportCaller bool) {
|
|
|
|
var buffer bytes.Buffer
|
|
|
|
|
|
|
|
logger := New()
|
|
|
|
logger.Out = &buffer
|
|
|
|
logger.Formatter = new(JSONFormatter)
|
|
|
|
logger.ReportCaller = reportCaller
|
|
|
|
|
|
|
|
for i := 0; i < iterations; i++ {
|
|
|
|
logger.Infof("round %d of %d", i, iterations)
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
// Assertions for upper bounds to reporting overhead
|
|
|
|
func TestCallerReportingOverhead(t *testing.T) {
|
2016-12-01 22:12:44 +03:00
|
|
|
iterations := 5000
|
2016-12-01 21:23:00 +03:00
|
|
|
before := time.Now()
|
|
|
|
logLoop(iterations, false)
|
|
|
|
during := time.Now()
|
|
|
|
logLoop(iterations, true)
|
|
|
|
after := time.Now()
|
|
|
|
|
|
|
|
elapsedNotReporting := during.Sub(before).Nanoseconds()
|
|
|
|
elapsedReporting := after.Sub(during).Nanoseconds()
|
|
|
|
|
|
|
|
maxDelta := 1 * time.Second
|
|
|
|
assert.WithinDuration(t, during, before, maxDelta,
|
|
|
|
"%d log calls without caller name lookup takes less than %d second(s) (was %d nanoseconds)",
|
|
|
|
iterations, maxDelta.Seconds(), elapsedNotReporting)
|
|
|
|
assert.WithinDuration(t, after, during, maxDelta,
|
|
|
|
"%d log calls without caller name lookup takes less than %d second(s) (was %d nanoseconds)",
|
|
|
|
iterations, maxDelta.Seconds(), elapsedReporting)
|
|
|
|
}
|
|
|
|
|
|
|
|
// benchmarks for both with and without caller-function reporting
|
|
|
|
func BenchmarkWithoutCallerTracing(b *testing.B) {
|
|
|
|
for i := 0; i < b.N; i++ {
|
|
|
|
logLoop(1000, false)
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
func BenchmarkWithCallerTracing(b *testing.B) {
|
|
|
|
for i := 0; i < b.N; i++ {
|
|
|
|
logLoop(1000, true)
|
|
|
|
}
|
2014-12-10 05:53:14 +03:00
|
|
|
}
|
|
|
|
|
2014-07-27 05:02:08 +04:00
|
|
|
func TestConvertLevelToString(t *testing.T) {
|
2017-10-02 19:38:29 +03:00
|
|
|
assert.Equal(t, "trace", TraceLevel.String())
|
2014-07-27 05:02:08 +04:00
|
|
|
assert.Equal(t, "debug", DebugLevel.String())
|
|
|
|
assert.Equal(t, "info", InfoLevel.String())
|
|
|
|
assert.Equal(t, "warning", WarnLevel.String())
|
|
|
|
assert.Equal(t, "error", ErrorLevel.String())
|
|
|
|
assert.Equal(t, "fatal", FatalLevel.String())
|
|
|
|
assert.Equal(t, "panic", PanicLevel.String())
|
|
|
|
}
|
2014-09-18 02:03:34 +04:00
|
|
|
|
|
|
|
func TestParseLevel(t *testing.T) {
|
|
|
|
l, err := ParseLevel("panic")
|
|
|
|
assert.Nil(t, err)
|
|
|
|
assert.Equal(t, PanicLevel, l)
|
|
|
|
|
2016-02-16 18:27:38 +03:00
|
|
|
l, err = ParseLevel("PANIC")
|
|
|
|
assert.Nil(t, err)
|
|
|
|
assert.Equal(t, PanicLevel, l)
|
|
|
|
|
2014-09-18 02:03:34 +04:00
|
|
|
l, err = ParseLevel("fatal")
|
|
|
|
assert.Nil(t, err)
|
|
|
|
assert.Equal(t, FatalLevel, l)
|
|
|
|
|
2016-02-16 18:27:38 +03:00
|
|
|
l, err = ParseLevel("FATAL")
|
|
|
|
assert.Nil(t, err)
|
|
|
|
assert.Equal(t, FatalLevel, l)
|
|
|
|
|
2014-09-18 02:03:34 +04:00
|
|
|
l, err = ParseLevel("error")
|
|
|
|
assert.Nil(t, err)
|
|
|
|
assert.Equal(t, ErrorLevel, l)
|
|
|
|
|
2016-02-16 18:27:38 +03:00
|
|
|
l, err = ParseLevel("ERROR")
|
|
|
|
assert.Nil(t, err)
|
|
|
|
assert.Equal(t, ErrorLevel, l)
|
|
|
|
|
2014-09-18 02:03:34 +04:00
|
|
|
l, err = ParseLevel("warn")
|
|
|
|
assert.Nil(t, err)
|
|
|
|
assert.Equal(t, WarnLevel, l)
|
|
|
|
|
2016-02-16 18:27:38 +03:00
|
|
|
l, err = ParseLevel("WARN")
|
|
|
|
assert.Nil(t, err)
|
|
|
|
assert.Equal(t, WarnLevel, l)
|
|
|
|
|
2014-09-18 02:03:34 +04:00
|
|
|
l, err = ParseLevel("warning")
|
|
|
|
assert.Nil(t, err)
|
|
|
|
assert.Equal(t, WarnLevel, l)
|
|
|
|
|
2016-02-16 18:27:38 +03:00
|
|
|
l, err = ParseLevel("WARNING")
|
|
|
|
assert.Nil(t, err)
|
|
|
|
assert.Equal(t, WarnLevel, l)
|
|
|
|
|
2014-09-18 02:03:34 +04:00
|
|
|
l, err = ParseLevel("info")
|
|
|
|
assert.Nil(t, err)
|
|
|
|
assert.Equal(t, InfoLevel, l)
|
|
|
|
|
2016-02-16 18:27:38 +03:00
|
|
|
l, err = ParseLevel("INFO")
|
|
|
|
assert.Nil(t, err)
|
|
|
|
assert.Equal(t, InfoLevel, l)
|
|
|
|
|
2014-09-18 02:03:34 +04:00
|
|
|
l, err = ParseLevel("debug")
|
|
|
|
assert.Nil(t, err)
|
|
|
|
assert.Equal(t, DebugLevel, l)
|
|
|
|
|
2016-02-16 18:27:38 +03:00
|
|
|
l, err = ParseLevel("DEBUG")
|
|
|
|
assert.Nil(t, err)
|
|
|
|
assert.Equal(t, DebugLevel, l)
|
|
|
|
|
2017-10-02 19:38:29 +03:00
|
|
|
l, err = ParseLevel("trace")
|
|
|
|
assert.Nil(t, err)
|
|
|
|
assert.Equal(t, TraceLevel, l)
|
|
|
|
|
|
|
|
l, err = ParseLevel("TRACE")
|
|
|
|
assert.Nil(t, err)
|
|
|
|
assert.Equal(t, TraceLevel, l)
|
|
|
|
|
2014-09-18 02:03:34 +04:00
|
|
|
l, err = ParseLevel("invalid")
|
|
|
|
assert.Equal(t, "not a valid logrus Level: \"invalid\"", err.Error())
|
|
|
|
}
|
2015-02-17 04:06:45 +03:00
|
|
|
|
|
|
|
func TestGetSetLevelRace(t *testing.T) {
|
|
|
|
wg := sync.WaitGroup{}
|
|
|
|
for i := 0; i < 100; i++ {
|
|
|
|
wg.Add(1)
|
|
|
|
go func(i int) {
|
|
|
|
defer wg.Done()
|
|
|
|
if i%2 == 0 {
|
|
|
|
SetLevel(InfoLevel)
|
|
|
|
} else {
|
|
|
|
GetLevel()
|
|
|
|
}
|
|
|
|
}(i)
|
|
|
|
|
|
|
|
}
|
|
|
|
wg.Wait()
|
|
|
|
}
|
2016-01-23 12:54:36 +03:00
|
|
|
|
|
|
|
func TestLoggingRace(t *testing.T) {
|
|
|
|
logger := New()
|
|
|
|
|
|
|
|
var wg sync.WaitGroup
|
|
|
|
wg.Add(100)
|
|
|
|
|
|
|
|
for i := 0; i < 100; i++ {
|
|
|
|
go func() {
|
|
|
|
logger.Info("info")
|
|
|
|
wg.Done()
|
|
|
|
}()
|
|
|
|
}
|
|
|
|
wg.Wait()
|
|
|
|
}
|
2016-02-01 19:55:14 +03:00
|
|
|
|
2018-02-05 22:52:11 +03:00
|
|
|
func TestLoggingRaceWithHooksOnEntry(t *testing.T) {
|
2018-02-05 22:42:00 +03:00
|
|
|
logger := New()
|
|
|
|
hook := new(ModifyHook)
|
|
|
|
logger.AddHook(hook)
|
2018-02-05 22:52:11 +03:00
|
|
|
entry := logger.WithField("context", "clue")
|
2018-02-05 22:42:00 +03:00
|
|
|
|
|
|
|
var wg sync.WaitGroup
|
|
|
|
wg.Add(100)
|
|
|
|
|
|
|
|
for i := 0; i < 100; i++ {
|
|
|
|
go func() {
|
2018-02-05 22:52:11 +03:00
|
|
|
entry.Info("info")
|
2018-02-05 22:42:00 +03:00
|
|
|
wg.Done()
|
|
|
|
}()
|
|
|
|
}
|
|
|
|
wg.Wait()
|
|
|
|
}
|
|
|
|
|
2018-08-26 14:40:51 +03:00
|
|
|
func TestReplaceHooks(t *testing.T) {
|
2018-08-22 12:10:05 +03:00
|
|
|
old, cur := &TestHook{}, &TestHook{}
|
|
|
|
|
|
|
|
logger := New()
|
2018-08-26 14:40:51 +03:00
|
|
|
logger.SetOutput(ioutil.Discard)
|
2018-08-22 12:10:05 +03:00
|
|
|
logger.AddHook(old)
|
|
|
|
|
|
|
|
hooks := make(LevelHooks)
|
|
|
|
hooks.Add(cur)
|
2018-08-26 14:40:51 +03:00
|
|
|
replaced := logger.ReplaceHooks(hooks)
|
2018-08-22 12:10:05 +03:00
|
|
|
|
|
|
|
logger.Info("test")
|
|
|
|
|
|
|
|
assert.Equal(t, old.Fired, false)
|
|
|
|
assert.Equal(t, cur.Fired, true)
|
2018-08-26 14:40:51 +03:00
|
|
|
|
|
|
|
logger.ReplaceHooks(replaced)
|
|
|
|
logger.Info("test")
|
|
|
|
assert.Equal(t, old.Fired, true)
|
2018-08-22 12:10:05 +03:00
|
|
|
}
|
|
|
|
|
2016-02-01 19:55:14 +03:00
|
|
|
// Compile test
|
2018-10-18 19:33:43 +03:00
|
|
|
func TestLogrusInterfaces(t *testing.T) {
|
2016-02-01 19:55:14 +03:00
|
|
|
var buffer bytes.Buffer
|
2018-10-18 19:33:43 +03:00
|
|
|
// This verifies FieldLogger and Ext1FieldLogger work as designed.
|
|
|
|
// Please don't use them. Use Logger and Entry directly.
|
|
|
|
fn := func(xl Ext1FieldLogger) {
|
|
|
|
var l FieldLogger = xl
|
2016-02-01 19:55:14 +03:00
|
|
|
b := l.WithField("key", "value")
|
|
|
|
b.Debug("Test")
|
|
|
|
}
|
|
|
|
// test logger
|
|
|
|
logger := New()
|
|
|
|
logger.Out = &buffer
|
|
|
|
fn(logger)
|
|
|
|
|
|
|
|
// test Entry
|
|
|
|
e := logger.WithField("another", "value")
|
|
|
|
fn(e)
|
|
|
|
}
|
2016-06-21 01:55:49 +03:00
|
|
|
|
|
|
|
// Implements io.Writer using channels for synchronization, so we can wait on
|
|
|
|
// the Entry.Writer goroutine to write in a non-racey way. This does assume that
|
|
|
|
// there is a single call to Logger.Out for each message.
|
|
|
|
type channelWriter chan []byte
|
|
|
|
|
|
|
|
func (cw channelWriter) Write(p []byte) (int, error) {
|
|
|
|
cw <- p
|
|
|
|
return len(p), nil
|
|
|
|
}
|
|
|
|
|
|
|
|
func TestEntryWriter(t *testing.T) {
|
|
|
|
cw := channelWriter(make(chan []byte, 1))
|
|
|
|
log := New()
|
|
|
|
log.Out = cw
|
|
|
|
log.Formatter = new(JSONFormatter)
|
|
|
|
log.WithField("foo", "bar").WriterLevel(WarnLevel).Write([]byte("hello\n"))
|
|
|
|
|
|
|
|
bs := <-cw
|
|
|
|
var fields Fields
|
|
|
|
err := json.Unmarshal(bs, &fields)
|
|
|
|
assert.Nil(t, err)
|
|
|
|
assert.Equal(t, fields["foo"], "bar")
|
|
|
|
assert.Equal(t, fields["level"], "warning")
|
|
|
|
}
|
2018-05-30 02:47:39 +03:00
|
|
|
|
|
|
|
func TestLogLevelEnabled(t *testing.T) {
|
|
|
|
log := New()
|
|
|
|
log.SetLevel(PanicLevel)
|
2018-08-27 00:51:09 +03:00
|
|
|
assert.Equal(t, true, log.IsLevelEnabled(PanicLevel))
|
|
|
|
assert.Equal(t, false, log.IsLevelEnabled(FatalLevel))
|
|
|
|
assert.Equal(t, false, log.IsLevelEnabled(ErrorLevel))
|
|
|
|
assert.Equal(t, false, log.IsLevelEnabled(WarnLevel))
|
|
|
|
assert.Equal(t, false, log.IsLevelEnabled(InfoLevel))
|
|
|
|
assert.Equal(t, false, log.IsLevelEnabled(DebugLevel))
|
2018-10-19 08:35:59 +03:00
|
|
|
assert.Equal(t, false, log.IsLevelEnabled(TraceLevel))
|
2018-05-30 02:47:39 +03:00
|
|
|
|
|
|
|
log.SetLevel(FatalLevel)
|
2018-08-27 00:51:09 +03:00
|
|
|
assert.Equal(t, true, log.IsLevelEnabled(PanicLevel))
|
|
|
|
assert.Equal(t, true, log.IsLevelEnabled(FatalLevel))
|
|
|
|
assert.Equal(t, false, log.IsLevelEnabled(ErrorLevel))
|
|
|
|
assert.Equal(t, false, log.IsLevelEnabled(WarnLevel))
|
|
|
|
assert.Equal(t, false, log.IsLevelEnabled(InfoLevel))
|
|
|
|
assert.Equal(t, false, log.IsLevelEnabled(DebugLevel))
|
2018-10-19 08:35:59 +03:00
|
|
|
assert.Equal(t, false, log.IsLevelEnabled(TraceLevel))
|
2018-05-30 02:47:39 +03:00
|
|
|
|
|
|
|
log.SetLevel(ErrorLevel)
|
2018-08-27 00:51:09 +03:00
|
|
|
assert.Equal(t, true, log.IsLevelEnabled(PanicLevel))
|
|
|
|
assert.Equal(t, true, log.IsLevelEnabled(FatalLevel))
|
|
|
|
assert.Equal(t, true, log.IsLevelEnabled(ErrorLevel))
|
|
|
|
assert.Equal(t, false, log.IsLevelEnabled(WarnLevel))
|
|
|
|
assert.Equal(t, false, log.IsLevelEnabled(InfoLevel))
|
|
|
|
assert.Equal(t, false, log.IsLevelEnabled(DebugLevel))
|
2018-10-19 08:35:59 +03:00
|
|
|
assert.Equal(t, false, log.IsLevelEnabled(TraceLevel))
|
2018-05-30 02:47:39 +03:00
|
|
|
|
|
|
|
log.SetLevel(WarnLevel)
|
2018-08-27 00:51:09 +03:00
|
|
|
assert.Equal(t, true, log.IsLevelEnabled(PanicLevel))
|
|
|
|
assert.Equal(t, true, log.IsLevelEnabled(FatalLevel))
|
|
|
|
assert.Equal(t, true, log.IsLevelEnabled(ErrorLevel))
|
|
|
|
assert.Equal(t, true, log.IsLevelEnabled(WarnLevel))
|
|
|
|
assert.Equal(t, false, log.IsLevelEnabled(InfoLevel))
|
|
|
|
assert.Equal(t, false, log.IsLevelEnabled(DebugLevel))
|
2018-10-19 08:35:59 +03:00
|
|
|
assert.Equal(t, false, log.IsLevelEnabled(TraceLevel))
|
2018-05-30 02:47:39 +03:00
|
|
|
|
|
|
|
log.SetLevel(InfoLevel)
|
2018-08-27 00:51:09 +03:00
|
|
|
assert.Equal(t, true, log.IsLevelEnabled(PanicLevel))
|
|
|
|
assert.Equal(t, true, log.IsLevelEnabled(FatalLevel))
|
|
|
|
assert.Equal(t, true, log.IsLevelEnabled(ErrorLevel))
|
|
|
|
assert.Equal(t, true, log.IsLevelEnabled(WarnLevel))
|
|
|
|
assert.Equal(t, true, log.IsLevelEnabled(InfoLevel))
|
|
|
|
assert.Equal(t, false, log.IsLevelEnabled(DebugLevel))
|
2018-10-19 08:35:59 +03:00
|
|
|
assert.Equal(t, false, log.IsLevelEnabled(TraceLevel))
|
2018-05-30 02:47:39 +03:00
|
|
|
|
|
|
|
log.SetLevel(DebugLevel)
|
2018-08-27 00:51:09 +03:00
|
|
|
assert.Equal(t, true, log.IsLevelEnabled(PanicLevel))
|
|
|
|
assert.Equal(t, true, log.IsLevelEnabled(FatalLevel))
|
|
|
|
assert.Equal(t, true, log.IsLevelEnabled(ErrorLevel))
|
|
|
|
assert.Equal(t, true, log.IsLevelEnabled(WarnLevel))
|
|
|
|
assert.Equal(t, true, log.IsLevelEnabled(InfoLevel))
|
|
|
|
assert.Equal(t, true, log.IsLevelEnabled(DebugLevel))
|
2018-10-19 08:35:59 +03:00
|
|
|
assert.Equal(t, false, log.IsLevelEnabled(TraceLevel))
|
|
|
|
|
|
|
|
log.SetLevel(TraceLevel)
|
|
|
|
assert.Equal(t, true, log.IsLevelEnabled(PanicLevel))
|
|
|
|
assert.Equal(t, true, log.IsLevelEnabled(FatalLevel))
|
|
|
|
assert.Equal(t, true, log.IsLevelEnabled(ErrorLevel))
|
|
|
|
assert.Equal(t, true, log.IsLevelEnabled(WarnLevel))
|
|
|
|
assert.Equal(t, true, log.IsLevelEnabled(InfoLevel))
|
|
|
|
assert.Equal(t, true, log.IsLevelEnabled(DebugLevel))
|
|
|
|
assert.Equal(t, true, log.IsLevelEnabled(TraceLevel))
|
2018-05-30 02:47:39 +03:00
|
|
|
}
|