From 6366d006450b99dddf7283a14ff7cecb49a5c692 Mon Sep 17 00:00:00 2001 From: Loren Osborn Date: Sun, 4 Nov 2018 21:31:52 -0800 Subject: [PATCH] Attemping to make test more simple and clear as per @dgsb I don't think I made these much simpler, but I tried to make them more clear. I was also unable to find the fragility in the tests @dgsb previously alluded to. --- entry_test.go | 219 +++++++++++--------------------- internal/testutils/testutils.go | 78 +++++++++++- 2 files changed, 151 insertions(+), 146 deletions(-) diff --git a/entry_test.go b/entry_test.go index f589f1f1d..d35212a7e 100644 --- a/entry_test.go +++ b/entry_test.go @@ -1,15 +1,16 @@ -package logrus +package logrus_test import ( "bytes" "encoding/json" "fmt" - "sort" - "strings" "testing" "time" "github.com/stretchr/testify/assert" + + "github.com/sirupsen/logrus" + "github.com/sirupsen/logrus/internal/testutils" ) func TestEntryWithError(t *testing.T) { @@ -17,20 +18,20 @@ func TestEntryWithError(t *testing.T) { assert := assert.New(t) defer func() { - ErrorKey = "error" + logrus.ErrorKey = "error" }() err := fmt.Errorf("kaboom at layer %d", 4711) - assert.Equal(err, WithError(err).Data["error"]) + assert.Equal(err, logrus.WithError(err).Data["error"]) - logger := New() + logger := logrus.New() logger.Out = &bytes.Buffer{} - entry := NewEntry(logger) + entry := logrus.NewEntry(logger) assert.Equal(err, entry.WithError(err).Data["error"]) - ErrorKey = "err" + logrus.ErrorKey = "err" assert.Equal(err, entry.WithError(err).Data["err"]) @@ -38,8 +39,8 @@ func TestEntryWithError(t *testing.T) { func TestEntryPanicln(t *testing.T) { errBoom := fmt.Errorf("boom time") - logger := New() - logger.Formatter = &TextFormatter{DisableTimestamp: true, DisableColors: true} + logger := logrus.New() + logger.Formatter = &logrus.TextFormatter{DisableTimestamp: true, DisableColors: true} outBuffer := bytes.Buffer{} defer func() { @@ -47,7 +48,7 @@ func TestEntryPanicln(t *testing.T) { assert.NotNil(t, p) switch pVal := p.(type) { - case *Entry: + case *logrus.Entry: assert.Equal(t, "kaboom", pVal.Message) assert.Equal(t, errBoom, pVal.Data["err"]) assert.Regexp(t, `^level=panic msg=kaboom err="boom time"`, outBuffer.String()) @@ -57,28 +58,29 @@ func TestEntryPanicln(t *testing.T) { }() logger.Out = &outBuffer - entry := NewEntry(logger) + entry := logrus.NewEntry(logger) entry.WithField("err", errBoom).Panicln("kaboom") } // TestEntryFormattingError tests proper handling of any field formatting errors func TestEntryFormattingError(t *testing.T) { - logger := New() + logger := logrus.New() // Turning off timestamp makes comparing the result easier: - logger.Formatter = &JSONFormatter{DisableTimestamp: true} + logger.Formatter = &logrus.JSONFormatter{DisableTimestamp: true} + // Functions can't be serialized, so they aren't allowed as a field value. + badFieldValue := func() {} // This allows us to have multiple distinct tests, each with a new entry. // While it is really a good idea to break tests out into separate // independent units, we covered all the obvious cases with one multi-part // test. (Multi-part tests share an entry and test the entry state after // each change.) - for _, independantTestCase := range [][]struct { - Group Fields + for description, independantTestCase := range map[string][]struct { + Group logrus.Fields ExpectedFields map[string][]string }{ - // Fields with no errors: - { + "Fields with no errors": { { - Group: Fields{ + Group: logrus.Fields{ "foo": "bar", }, ExpectedFields: map[string][]string{ @@ -86,24 +88,22 @@ func TestEntryFormattingError(t *testing.T) { }, }, }, - // Fields with one error: - { + "Fields with one error": { { - Group: Fields{ - "foo": func() {}, + Group: logrus.Fields{ + "foo": badFieldValue, }, ExpectedFields: map[string][]string{ "logrus_error": {`can not add field "foo"`}, }, }, }, - // Fields with multiple errors: - { + "Fields with multiple errors": { { - Group: Fields{ - "foo": func() {}, - "bar": func() {}, - "baz": func() {}, + Group: logrus.Fields{ + "foo": badFieldValue, + "bar": badFieldValue, + "baz": badFieldValue, }, ExpectedFields: map[string][]string{ "logrus_error": { @@ -114,13 +114,12 @@ func TestEntryFormattingError(t *testing.T) { }, }, }, - // Mixed fields with and without errors: - { + "Mixed fields with and without errors": { { - Group: Fields{ - "apple": func() {}, + Group: logrus.Fields{ + "apple": badFieldValue, "banana": "yellow", - "carrot": func() {}, + "carrot": badFieldValue, "daisy": "gerber", }, ExpectedFields: map[string][]string{ @@ -133,10 +132,9 @@ func TestEntryFormattingError(t *testing.T) { }, }, }, - // no errors followed by multiple errors: - { + "No errors followed by multiple errors": { { - Group: Fields{ + Group: logrus.Fields{ "foo": "bar", }, ExpectedFields: map[string][]string{ @@ -144,11 +142,11 @@ func TestEntryFormattingError(t *testing.T) { }, }, { - Group: Fields{ - "Fred": func() {}, - "George": func() {}, - "Ron": func() {}, - "Ginnie": func() {}, + Group: logrus.Fields{ + "Fred": badFieldValue, + "George": badFieldValue, + "Ron": badFieldValue, + "Ginnie": badFieldValue, }, ExpectedFields: map[string][]string{ "foo": {"bar"}, @@ -161,10 +159,9 @@ func TestEntryFormattingError(t *testing.T) { }, }, }, - // Compound example - { + "Compound example": { { - Group: Fields{ + Group: logrus.Fields{ "foo": "bar", }, ExpectedFields: map[string][]string{ @@ -172,11 +169,11 @@ func TestEntryFormattingError(t *testing.T) { }, }, { - Group: Fields{ - "Fred": func() {}, - "George": func() {}, - "Ron": func() {}, - "Ginnie": func() {}, + Group: logrus.Fields{ + "Fred": badFieldValue, + "George": badFieldValue, + "Ron": badFieldValue, + "Ginnie": badFieldValue, }, ExpectedFields: map[string][]string{ "foo": {"bar"}, @@ -189,8 +186,8 @@ func TestEntryFormattingError(t *testing.T) { }, }, { - Group: Fields{ - "six": func() {}, + Group: logrus.Fields{ + "six": badFieldValue, }, ExpectedFields: map[string][]string{ "foo": {"bar"}, @@ -204,7 +201,7 @@ func TestEntryFormattingError(t *testing.T) { }, }, { - Group: Fields{ + Group: logrus.Fields{ "red": "green", }, ExpectedFields: map[string][]string{ @@ -220,8 +217,8 @@ func TestEntryFormattingError(t *testing.T) { }, }, { - Group: Fields{ - "seven": func() {}, + Group: logrus.Fields{ + "seven": badFieldValue, }, ExpectedFields: map[string][]string{ "foo": {"bar"}, @@ -239,7 +236,7 @@ func TestEntryFormattingError(t *testing.T) { }, } { // Independant tests have a new Entry, and a new expected final state. - entry := NewEntry(logger) + entry := logrus.NewEntry(logger) var lastExpected map[string][]string for _, fieldGroupTestPart := range independantTestCase { // Set outBuffer as a new "file" to log to. @@ -257,24 +254,14 @@ func TestEntryFormattingError(t *testing.T) { entry.Info("baz") outputMap := make(map[string]string, len(fieldGroupTestPart.ExpectedFields)+2) if err := json.Unmarshal(outBuffer.Bytes(), &outputMap); err != nil { - assert.Fail(t, fmt.Sprintf("Failure unmarshalling logger output, %#v from output %#v", err.Error(), outBuffer.String())) + assert.Fail(t, fmt.Sprintf("Failure unmarshalling logger output, %#v testing %s from output %#v", err.Error(), description, outBuffer.String())) } else { - assert.True(t, len(outputMap) > 0, "Expect at least one field") - - // Inject level=info and msg=baz into our expected data, as they - // come from the Info() call above: - expectedFields := make(map[string][]string, len(fieldGroupTestPart.ExpectedFields)+2) - for _, fieldSets := range []map[string][]string{ - map[string][]string{"level": {"info"}, "msg": {"baz"}}, - fieldGroupTestPart.ExpectedFields, - } { - for key, strValParts := range fieldSets { - expectedFields[key] = strValParts - } - } - lastExpected = expectedFields - - AssertMapOfStringToUnorderdStringsEqual(t, ", ", expectedFields, outputMap, outBuffer.String()) + // Remove level and msg created by logrus: + delete(outputMap, "level") + delete(outputMap, "msg") + lastExpected = fieldGroupTestPart.ExpectedFields + + testutils.AssertMapOfStringToUnorderdStringsEqualf(t, ", ", fieldGroupTestPart.ExpectedFields, outputMap, "testing %s from map %#v", description, outputMap) } } @@ -291,72 +278,16 @@ func TestEntryFormattingError(t *testing.T) { entry.Info("baz") outputMap := make(map[string]string, len(lastExpected)) if err := json.Unmarshal(outBuffer.Bytes(), &outputMap); err != nil { - assert.Fail(t, fmt.Sprintf("Failure unmarshalling logger output, %#v from output %#v", err.Error(), outBuffer.String())) + assert.Fail(t, fmt.Sprintf("Failure unmarshalling logger output, %#v testing %s from output %#v", err.Error(), description, outBuffer.String())) } else { - assert.True(t, len(outputMap) > 0, "Expect at least one field") - AssertMapOfStringToUnorderdStringsEqual(t, ", ", lastExpected, outputMap, outBuffer.String()) + // Remove level and msg created by logrus: + delete(outputMap, "level") + delete(outputMap, "msg") + testutils.AssertMapOfStringToUnorderdStringsEqualf(t, ", ", lastExpected, outputMap, "testing %s from map %#v", description, outputMap) } } } -func AssertMapOfStringToUnorderdStringsEqual(t *testing.T, seperator string, expected map[string][]string, actual map[string]string, output string) { - // A map of how many times we see each expected key. At the end - // these should all be 1. - expectedKeysFound := make(map[string]int, len(expected)) - for key := range expected { - expectedKeysFound[key] = 0 - } - - // each key - value pair - for actualKey, actualValue := range actual { - - // Enforce no duplicate or unexpected keys - foundTimes, wasExpected := expectedKeysFound[actualKey] - assert.Truef( - t, - wasExpected, - "Expected %#v to be an expected key from output %#v", - actualKey, - output) - assert.Equalf( - t, - 0, - foundTimes, - "Expected %#v to only appear once from output %#v", - actualKey, - output) - expectedKeysFound[actualKey]++ - - // Split the value on `seperator` so it can be sorted and reassembeled - valParts := strings.Split(actualValue, seperator) - sort.Strings(valParts) - sort.Strings(expected[actualKey]) - - // Glue the string slices back together for comparison. - assert.Equal( - t, - strings.Join(expected[actualKey], seperator), - strings.Join(valParts, seperator), - "Expected key %#v (with value %#v) from output %#v to have same parts as %#v", - actualKey, - actualValue, - output, - expected[actualKey]) - } - // Make sure no expected keys were missing (or duplicate, already - // checked for.) - for key, foundTimes := range expectedKeysFound { - assert.Equalf( - t, - 1, - foundTimes, - "Expected key %#v to be found 1 time (not %#v times) in output %#v", - key, - foundTimes, - output) - } -} - func TestEntryPanicf(t *testing.T) { errBoom := fmt.Errorf("boom again") @@ -365,7 +296,7 @@ func TestEntryPanicf(t *testing.T) { assert.NotNil(t, p) switch pVal := p.(type) { - case *Entry: + case *logrus.Entry: assert.Equal(t, "kaboom true", pVal.Message) assert.Equal(t, errBoom, pVal.Data["err"]) default: @@ -373,9 +304,9 @@ func TestEntryPanicf(t *testing.T) { } }() - logger := New() + logger := logrus.New() logger.Out = &bytes.Buffer{} - entry := NewEntry(logger) + entry := logrus.NewEntry(logger) entry.WithField("err", errBoom).Panicf("kaboom %v", true) } @@ -386,11 +317,11 @@ const ( type panickyHook struct{} -func (p *panickyHook) Levels() []Level { - return []Level{InfoLevel} +func (p *panickyHook) Levels() []logrus.Level { + return []logrus.Level{logrus.InfoLevel} } -func (p *panickyHook) Fire(entry *Entry) error { +func (p *panickyHook) Fire(entry *logrus.Entry) error { if entry.Message == badMessage { panic(panicMessage) } @@ -399,9 +330,9 @@ func (p *panickyHook) Fire(entry *Entry) error { } func TestEntryHooksPanic(t *testing.T) { - logger := New() + logger := logrus.New() logger.Out = &bytes.Buffer{} - logger.Level = InfoLevel + logger.Level = logrus.InfoLevel logger.Hooks.Add(&panickyHook{}) defer func() { @@ -409,10 +340,10 @@ func TestEntryHooksPanic(t *testing.T) { assert.NotNil(t, p) assert.Equal(t, panicMessage, p) - entry := NewEntry(logger) + entry := logrus.NewEntry(logger) entry.Info("another message") }() - entry := NewEntry(logger) + entry := logrus.NewEntry(logger) entry.Info(badMessage) } diff --git a/internal/testutils/testutils.go b/internal/testutils/testutils.go index 20bc3c3b6..88371d867 100644 --- a/internal/testutils/testutils.go +++ b/internal/testutils/testutils.go @@ -3,13 +3,16 @@ package testutils import ( "bytes" "encoding/json" + "fmt" + "sort" "strconv" "strings" "testing" - . "github.com/sirupsen/logrus" - + "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" + + . "github.com/sirupsen/logrus" ) func LogAndAssertJSON(t *testing.T, log func(*Logger), assertions func(fields Fields)) { @@ -56,3 +59,74 @@ func LogAndAssertText(t *testing.T, log func(*Logger), assertions func(fields ma } assertions(fields) } + +// AssertMapOfStringToUnorderdStringsEqualf ensures actual matches expected, +// without regard to order of the seperator delimited parts of each key's value +func AssertMapOfStringToUnorderdStringsEqualf(t *testing.T, seperator string, expected map[string][]string, actual map[string]string, format string, msgParts ...interface{}) { + message := fmt.Sprintf(format, msgParts...) + AssertMapOfStringToUnorderdStringsEqual(t, seperator, expected, actual, message) +} + +// AssertMapOfStringToUnorderdStringsEqual ensures actual matches expected, +// without regard to order of the seperator delimited parts of each key's value +func AssertMapOfStringToUnorderdStringsEqual(t *testing.T, seperator string, expected map[string][]string, actual map[string]string, msgParts ...interface{}) { + message := fmt.Sprint(msgParts...) + if message != "" { + message = ": " + message + } + // A map of how many times we see each expected key. At the end + // these should all be 1. + expectedKeysFound := make(map[string]int, len(expected)) + for key := range expected { + expectedKeysFound[key] = 0 + } + + // each key - value pair + for actualKey, actualValue := range actual { + + // Enforce no duplicate or unexpected keys + foundTimes, wasExpected := expectedKeysFound[actualKey] + assert.Truef( + t, + wasExpected, + "Expected %#v to be an expected key%s", + actualKey, + message) + assert.Equalf( + t, + 0, + foundTimes, + "Expected %#v to only appear once%s", + actualKey, + message) + expectedKeysFound[actualKey]++ + + // Split the value on `seperator` so it can be sorted and reassembeled + valParts := strings.Split(actualValue, seperator) + sort.Strings(valParts) + sort.Strings(expected[actualKey]) + + // Glue the string slices back together for comparison. + assert.Equal( + t, + strings.Join(expected[actualKey], seperator), + strings.Join(valParts, seperator), + "Expected key %#v (with value %#v) to have same parts as %#v%s", + actualKey, + actualValue, + expected[actualKey], + message) + } + // Make sure no expected keys were missing (or duplicate, already + // checked for.) + for key, foundTimes := range expectedKeysFound { + assert.Equalf( + t, + 1, + foundTimes, + "Expected key %#v to be found 1 time (not %#v times)%s", + key, + foundTimes, + message) + } +}