From bcc146f96bac06492f800415b0ad6bd2ad1ff4fe Mon Sep 17 00:00:00 2001 From: Taylor Wrobel Date: Wed, 27 Nov 2019 20:03:38 -0800 Subject: [PATCH 1/2] Fix entity data bleed when using WithContext and WithTime Creates a copy of the data map when using WithContext to create a child entity. Without this, the data map of the parent entitiy, which is exposed in the entity struct, is shared between a parent and all children instances. This can create bugs of shared or overwritten data when a parent entity is used to make children in differing contexts, and behaves differently than `WithField` and its diritivites which does make a copy of the data. Additionally implements the same logic for WithTime, for API consistency in behavior. --- entry.go | 12 ++++++++++-- entry_test.go | 28 ++++++++++++++++++++++++++++ 2 files changed, 38 insertions(+), 2 deletions(-) diff --git a/entry.go b/entry.go index f24cf8d..7f28ba4 100644 --- a/entry.go +++ b/entry.go @@ -103,7 +103,11 @@ func (entry *Entry) WithError(err error) *Entry { // Add a context to the Entry. func (entry *Entry) WithContext(ctx context.Context) *Entry { - return &Entry{Logger: entry.Logger, Data: entry.Data, Time: entry.Time, err: entry.err, Context: ctx} + dataCopy := make(Fields, len(entry.Data)) + for k, v := range entry.Data { + dataCopy[k] = v + } + return &Entry{Logger: entry.Logger, Data: dataCopy, Time: entry.Time, err: entry.err, Context: ctx} } // Add a single field to the Entry. @@ -144,7 +148,11 @@ func (entry *Entry) WithFields(fields Fields) *Entry { // Overrides the time of the Entry. func (entry *Entry) WithTime(t time.Time) *Entry { - return &Entry{Logger: entry.Logger, Data: entry.Data, Time: t, err: entry.err, Context: entry.Context} + dataCopy := make(Fields, len(entry.Data)) + for k, v := range entry.Data { + dataCopy[k] = v + } + return &Entry{Logger: entry.Logger, Data: dataCopy, Time: t, err: entry.err, Context: entry.Context} } // getPackageName reduces a fully qualified function name to the package name diff --git a/entry_test.go b/entry_test.go index f764085..7be48aa 100644 --- a/entry_test.go +++ b/entry_test.go @@ -47,6 +47,34 @@ func TestEntryWithContext(t *testing.T) { assert.Equal(ctx, entry.WithContext(ctx).Context) } +func TestEntryWithContextCopiesData(t *testing.T) { + assert := assert.New(t) + ctx1 := context.WithValue(context.Background(), "foo", "bar") + ctx2 := context.WithValue(context.Background(), "bar", "baz") + assert.NotEqual(ctx1, ctx2) + + logger := New() + logger.Out = &bytes.Buffer{} + parentEntry := NewEntry(logger).WithField("parentKey", "parentValue") + childEntry1 := parentEntry.WithContext(ctx1) + assert.Equal(ctx1, childEntry1.Context) + childEntry2 := parentEntry.WithContext(ctx2) + assert.Equal(ctx2, childEntry2.Context) + assert.NotEqual(ctx1, ctx2) + assert.Equal("parentValue", childEntry1.Data["parentKey"]) + assert.Equal("parentValue", childEntry2.Data["parentKey"]) + + childEntry1.Data["ChildKeyValue1"] = "ChildDataValue1" + + val, exists := childEntry1.Data["ChildKeyValue1"] + assert.True(exists) + assert.Equal("ChildDataValue1", val) + + val, exists = childEntry2.Data["ChildKeyValue1"] + assert.False(exists) + assert.Empty(val) +} + func TestEntryPanicln(t *testing.T) { errBoom := fmt.Errorf("boom time") From 8fbaf3dbd079967afa0b5539c797b657edf97392 Mon Sep 17 00:00:00 2001 From: Taylor Wrobel Date: Tue, 3 Dec 2019 13:50:59 -0800 Subject: [PATCH 2/2] Make Entry WithContext and WithTime copy tests more clear Clarifies the data used in the EntryWithContextCopiesData test and adds an equivalent test to verify the behavior of WithTime. --- entry_test.go | 62 +++++++++++++++++++++++++++++++++++++++++++++------ 1 file changed, 55 insertions(+), 7 deletions(-) diff --git a/entry_test.go b/entry_test.go index 7be48aa..973091e 100644 --- a/entry_test.go +++ b/entry_test.go @@ -49,28 +49,76 @@ func TestEntryWithContext(t *testing.T) { func TestEntryWithContextCopiesData(t *testing.T) { assert := assert.New(t) - ctx1 := context.WithValue(context.Background(), "foo", "bar") - ctx2 := context.WithValue(context.Background(), "bar", "baz") - assert.NotEqual(ctx1, ctx2) + // Initialize a parent Entry object with a key/value set in its Data map logger := New() logger.Out = &bytes.Buffer{} parentEntry := NewEntry(logger).WithField("parentKey", "parentValue") + + // Create two children Entry objects from the parent in different contexts + ctx1 := context.WithValue(context.Background(), "foo", "bar") childEntry1 := parentEntry.WithContext(ctx1) assert.Equal(ctx1, childEntry1.Context) + + ctx2 := context.WithValue(context.Background(), "bar", "baz") childEntry2 := parentEntry.WithContext(ctx2) assert.Equal(ctx2, childEntry2.Context) assert.NotEqual(ctx1, ctx2) + + // Ensure that data set in the parent Entry are preserved to both children assert.Equal("parentValue", childEntry1.Data["parentKey"]) assert.Equal("parentValue", childEntry2.Data["parentKey"]) - childEntry1.Data["ChildKeyValue1"] = "ChildDataValue1" + // Modify data stored in the child entry + childEntry1.Data["childKey"] = "childValue" - val, exists := childEntry1.Data["ChildKeyValue1"] + // Verify that data is successfully stored in the child it was set on + val, exists := childEntry1.Data["childKey"] assert.True(exists) - assert.Equal("ChildDataValue1", val) + assert.Equal("childValue", val) - val, exists = childEntry2.Data["ChildKeyValue1"] + // Verify that the data change to child 1 has not affected its sibling + val, exists = childEntry2.Data["childKey"] + assert.False(exists) + assert.Empty(val) + + // Verify that the data change to child 1 has not affected its parent + val, exists = parentEntry.Data["childKey"] + assert.False(exists) + assert.Empty(val) +} + +func TestEntryWithTimeCopiesData(t *testing.T) { + assert := assert.New(t) + + // Initialize a parent Entry object with a key/value set in its Data map + logger := New() + logger.Out = &bytes.Buffer{} + parentEntry := NewEntry(logger).WithField("parentKey", "parentValue") + + // Create two children Entry objects from the parent with two different times + childEntry1 := parentEntry.WithTime(time.Now().AddDate(0, 0, 1)) + childEntry2 := parentEntry.WithTime(time.Now().AddDate(0, 0, 2)) + + // Ensure that data set in the parent Entry are preserved to both children + assert.Equal("parentValue", childEntry1.Data["parentKey"]) + assert.Equal("parentValue", childEntry2.Data["parentKey"]) + + // Modify data stored in the child entry + childEntry1.Data["childKey"] = "childValue" + + // Verify that data is successfully stored in the child it was set on + val, exists := childEntry1.Data["childKey"] + assert.True(exists) + assert.Equal("childValue", val) + + // Verify that the data change to child 1 has not affected its sibling + val, exists = childEntry2.Data["childKey"] + assert.False(exists) + assert.Empty(val) + + // Verify that the data change to child 1 has not affected its parent + val, exists = parentEntry.Data["childKey"] assert.False(exists) assert.Empty(val) }