From 79aa5b26b122a128662848c9616edb3d4a753491 Mon Sep 17 00:00:00 2001 From: Thorsten Lanfer Date: Thu, 11 Aug 2022 09:36:32 +0200 Subject: [PATCH 1/4] Add methods for adding a uid to log events --- otellog/event.go | 1 + otellog/option.go | 22 +++++++++++++++++ otellog/option_test.go | 41 +++++++++++++++++++------------ otellog/uid.go | 24 ++++++++++++++++++ otellog/uid_test.go | 56 ++++++++++++++++++++++++++++++++++++++++++ 5 files changed, 128 insertions(+), 16 deletions(-) create mode 100644 otellog/uid.go create mode 100644 otellog/uid_test.go diff --git a/otellog/event.go b/otellog/event.go index 11bdfa5..65f29df 100644 --- a/otellog/event.go +++ b/otellog/event.go @@ -11,6 +11,7 @@ type Event struct { Severity Severity `json:"sev,omitempty"` // Numerical value of the severity cf. Severity constants like SeverityInfo for possible values and their semantics Name string `json:"name,omitempty"` // Short event identifier that does not contain varying parts. Name describes what happened (e.g. "ProcessStarted"). Recommended to be no longer than 50 characters. Not guaranteed to be unique in any way. Typically used for filtering and grouping purposes in backends. Can be used to identify domain events like FeaturesRequested or UserLoggedIn (cf. example). Body interface{} `json:"body,omitempty"` // A value containing the body of the log record. Can be for example a human-readable string message (including multi-line) describing the event in a free form or it can be a structured data composed of arrays and maps of other values. Can vary for each occurrence of the event coming from the same source. + UserIdHash string `json:"uid,omitempty"` // The userId of the user causing this event. Must be the sha256 hash of the userId from the current identity provider for pseudonymization TenantId string `json:"tn,omitempty"` // ID of the tenant to which this event belongs. TraceId string `json:"trace,omitempty"` // Request trace-id as defined in W3C Trace Context (https://www.w3.org/TR/trace-context/#trace-id) specification. That is the ID of the whole trace forest used to uniquely identify a distributed trace through a system. SpanId string `json:"span,omitempty"` // span-id. Can be set for logs that are part of a particular processing span. A span (https://opentracing.io/docs/overview/spans/) is the primary building block of a distributed trace, representing an individual unit of work done in a distributed system. diff --git a/otellog/option.go b/otellog/option.go index 74c80d8..c5d1598 100644 --- a/otellog/option.go +++ b/otellog/option.go @@ -2,6 +2,8 @@ package otellog import ( "context" + "crypto/sha256" + "encoding/hex" "fmt" "net/http" "strings" @@ -131,6 +133,19 @@ func (ob *LogBuilder) WithDB(db DB) *LogBuilder { return ob } +func (ob *LogBuilder) WithUserId(userId string) *LogBuilder { + ob.options = append(ob.options, func(e *Event) { + if userId != "" { + hash := sha256.New() + hash.Write([]byte(userId)) + sum := hash.Sum(nil) + uidHash := hex.EncodeToString(sum) + e.UserIdHash = uidHash + } + }) + return ob +} + // WithException adds the exception attribute to the log event. func (ob *LogBuilder) WithException(err Exception) *LogBuilder { ob.options = append(ob.options, func(e *Event) { @@ -212,6 +227,13 @@ func WithDB(db DB) *LogBuilder { return ob } +// WithUserId hashes the userId and adds the uid attribute to the log event. +func WithUserId(userId string) *LogBuilder { + ob := &LogBuilder{} + ob.WithUserId(userId) + return ob +} + // WithException adds the exception attribute to the log event. func WithException(err Exception) *LogBuilder { ob := &LogBuilder{} diff --git a/otellog/option_test.go b/otellog/option_test.go index 497b605..a8b54c9 100644 --- a/otellog/option_test.go +++ b/otellog/option_test.go @@ -44,12 +44,12 @@ func TestLogMessageWithVisibilityIsFalse_Error_AddVisPropertyAndWritesJSONToBuff func TestLogMessageWithVisibilityIsFalseAndStructAsBody_Debug_WritesJSONToBuffer(t *testing.T) { rec := initializeLogger(t) body := &struct { - Id string `json:"id,omitempty"` - Toggle bool `json:"toggle,omitempty"` - Counter int `json:"counter,omitempty"` + Id string `json:"id,omitempty"` + Toggle bool `json:"toggle,omitempty"` + Counter int `json:"counter,omitempty"` }{ - Id: "id", - Toggle: true, + Id: "id", + Toggle: true, Counter: 5, } @@ -61,12 +61,12 @@ func TestLogMessageWithVisibilityIsFalseAndStructAsBody_Debug_WritesJSONToBuffer func TestLogMessageWithVisibilityIsFalseAndStructAsBody_Info_WritesJSONToBuffer(t *testing.T) { rec := initializeLogger(t) body := &struct { - Id string `json:"id,omitempty"` - Toggle bool `json:"toggle,omitempty"` - Counter int `json:"counter,omitempty"` + Id string `json:"id,omitempty"` + Toggle bool `json:"toggle,omitempty"` + Counter int `json:"counter,omitempty"` }{ - Id: "id", - Toggle: true, + Id: "id", + Toggle: true, Counter: 5, } @@ -78,12 +78,12 @@ func TestLogMessageWithVisibilityIsFalseAndStructAsBody_Info_WritesJSONToBuffer( func TestLogMessageWithVisibilityIsFalseAndStructAsBody_Error_WritesJSONToBuffer(t *testing.T) { rec := initializeLogger(t) body := &struct { - Id string `json:"id,omitempty"` - Toggle bool `json:"toggle,omitempty"` - Counter int `json:"counter,omitempty"` + Id string `json:"id,omitempty"` + Toggle bool `json:"toggle,omitempty"` + Counter int `json:"counter,omitempty"` }{ - Id: "id", - Toggle: true, + Id: "id", + Toggle: true, Counter: 5, } @@ -225,6 +225,14 @@ func TestLogMessageWithDB_Info_AddDBPropertyAndWritesJSONToBuffer(t *testing.T) rec.OutputShouldBe("{\"time\":\"2022-01-01T01:02:03.000000004Z\",\"sev\":9,\"body\":\"Log message\",\"attr\":{\"db\":{\"name\":\"CustomDb\"}}}\n") } +func TestLogMessageWithUserId_Info_AddsUserIdHashAndWritesJSONToBuffer(t *testing.T) { + rec := initializeLogger(t) + + log.WithUserId("a63554a8-1234-5678-1199-37a3b7d24e82").Info(context.Background(), "Log message") + + rec.OutputShouldBe("{\"time\":\"2022-01-01T01:02:03.000000004Z\",\"sev\":9,\"body\":\"Log message\",\"uid\":\"5219bb0e97ae8956431ca19e10105c0d82a0cf1386cec6e01a7eaeae04722ded\"}\n") +} + func TestLogMessageWithException_Info_AddExceptionPropertyAndWritesJSONToBuffer(t *testing.T) { rec := initializeLogger(t) @@ -287,11 +295,12 @@ func TestLogMessageWithEveryPossibleOption_Info_AddAllPropertiesAndWritesJSONToB WithVisibility(false). WithHttp(log.Http{Method: "Get"}). WithDB(log.DB{Name: "CustomDb"}). + WithUserId("a63554a8-1234-5678-1199-37a3b7d24e82"). WithException(log.Exception{Type: "CustomLogException"}). WithAdditionalAttributes(customAttr). Info(context.Background(), "Log message") - rec.OutputShouldBe("{\"time\":\"2022-01-01T01:02:03.000000004Z\",\"sev\":9,\"name\":\"Log message name\",\"body\":\"Log message\",\"attr\":{\"a\":{\"one\":1,\"two\":2},\"b\":{\"one\":1,\"two\":2},\"c\":\"3\",\"db\":{\"name\":\"CustomDb\"},\"exception\":{\"type\":\"CustomLogException\"},\"http\":{\"method\":\"Get\"}},\"vis\":0}\n") + rec.OutputShouldBe("{\"time\":\"2022-01-01T01:02:03.000000004Z\",\"sev\":9,\"name\":\"Log message name\",\"body\":\"Log message\",\"uid\":\"5219bb0e97ae8956431ca19e10105c0d82a0cf1386cec6e01a7eaeae04722ded\",\"attr\":{\"a\":{\"one\":1,\"two\":2},\"b\":{\"one\":1,\"two\":2},\"c\":\"3\",\"db\":{\"name\":\"CustomDb\"},\"exception\":{\"type\":\"CustomLogException\"},\"http\":{\"method\":\"Get\"}},\"vis\":0}\n") } func TestLogMessageWithRegisteredHookAndOtherService_Info_OverrideServicePropertyAndWritesJSONToBuffer(t *testing.T) { diff --git a/otellog/uid.go b/otellog/uid.go new file mode 100644 index 0000000..b8d6c40 --- /dev/null +++ b/otellog/uid.go @@ -0,0 +1,24 @@ +package otellog + +import ( + "context" + "crypto/sha256" + "encoding/hex" +) + +type UidFromContextFn func(ctx context.Context) (string, error) + +func AddUidToLogEvent(uidFn UidFromContextFn) Hook { + + return func(ctx context.Context, e *Event) { + uid, _ := uidFn(ctx) + if uid != "" { + hash := sha256.New() + hash.Write([]byte(uid)) + sum := hash.Sum(nil) + uidHash := hex.EncodeToString(sum) + e.UserIdHash = uidHash + } + } + +} diff --git a/otellog/uid_test.go b/otellog/uid_test.go new file mode 100644 index 0000000..2fbbf28 --- /dev/null +++ b/otellog/uid_test.go @@ -0,0 +1,56 @@ +package otellog_test + +import ( + "context" + "errors" + log "github.com/d-velop/dvelop-sdk-go/otellog" + "testing" +) + +func TestAddUidToLogEvent_givenUidFnReturnsUid_whenLogWritten_thenAddsUidToLog(t *testing.T) { + + uidFn := log.UidFromContextFn(func(ctx context.Context) (string, error) { + return "a63554a8-6044-417b-a0aa-37a3b7d24e82", nil + }) + + hook := log.AddUidToLogEvent(uidFn) + + rec := initializeLogger(t) + + log.RegisterHook(hook) + log.Info(context.Background(), "Testmessage") + + rec.OutputShouldBe(`{"time":"2022-01-01T01:02:03.000000004Z","sev":9,"body":"Testmessage","uid":"89757a7742548835532f1809558e0ab24eb39057966ad1630f1c493d94c3aec1"}` + "\n") +} + +func TestAddUidToLogEvent_givenUidFnReturnsEmptyUid_whenLogWritten_thenAddsNothingToLog(t *testing.T) { + + uidFn := log.UidFromContextFn(func(ctx context.Context) (string, error) { + return "", nil + }) + + hook := log.AddUidToLogEvent(uidFn) + + rec := initializeLogger(t) + + log.RegisterHook(hook) + log.Info(context.Background(), "Testmessage") + + rec.OutputShouldBe(`{"time":"2022-01-01T01:02:03.000000004Z","sev":9,"body":"Testmessage"}` + "\n") +} + +func TestAddUidToLogEvent_givenUidFnReturnsError_whenLogWritten_thenAddsNothingToLog(t *testing.T) { + + uidFn := log.UidFromContextFn(func(ctx context.Context) (string, error) { + return "", errors.New("some error") + }) + + hook := log.AddUidToLogEvent(uidFn) + + rec := initializeLogger(t) + + log.RegisterHook(hook) + log.Info(context.Background(), "Testmessage") + + rec.OutputShouldBe(`{"time":"2022-01-01T01:02:03.000000004Z","sev":9,"body":"Testmessage"}` + "\n") +} From 2c876859a4aed910f7d1a4515adf9879d9923874 Mon Sep 17 00:00:00 2001 From: Thorsten Lanfer Date: Thu, 11 Aug 2022 09:51:30 +0200 Subject: [PATCH 2/4] Add test to verify that explicitly set UIDs take precedence --- otellog/{uid.go => uidhook.go} | 0 otellog/{uid_test.go => uidhook_test.go} | 0 2 files changed, 0 insertions(+), 0 deletions(-) rename otellog/{uid.go => uidhook.go} (100%) rename otellog/{uid_test.go => uidhook_test.go} (100%) diff --git a/otellog/uid.go b/otellog/uidhook.go similarity index 100% rename from otellog/uid.go rename to otellog/uidhook.go diff --git a/otellog/uid_test.go b/otellog/uidhook_test.go similarity index 100% rename from otellog/uid_test.go rename to otellog/uidhook_test.go From 401c9268f912259d79381c2303e65ff09c4074b2 Mon Sep 17 00:00:00 2001 From: Thorsten Lanfer Date: Thu, 11 Aug 2022 09:56:43 +0200 Subject: [PATCH 3/4] Add test to verify that explicitly set UIDs take precedence --- otellog/uidhook_test.go | 16 ++++++++++++++++ 1 file changed, 16 insertions(+) diff --git a/otellog/uidhook_test.go b/otellog/uidhook_test.go index 2fbbf28..1bce8eb 100644 --- a/otellog/uidhook_test.go +++ b/otellog/uidhook_test.go @@ -23,6 +23,22 @@ func TestAddUidToLogEvent_givenUidFnReturnsUid_whenLogWritten_thenAddsUidToLog(t rec.OutputShouldBe(`{"time":"2022-01-01T01:02:03.000000004Z","sev":9,"body":"Testmessage","uid":"89757a7742548835532f1809558e0ab24eb39057966ad1630f1c493d94c3aec1"}` + "\n") } +func TestAddUidToLogEvent_givenUidExplicitlySet_whenLogWritten_thenHookDoesNotReplaceExplicitValue(t *testing.T) { + + uidFn := log.UidFromContextFn(func(ctx context.Context) (string, error) { + return "a63554a8-6044-417b-a0aa-37a3b7d24e82", nil + }) + + hook := log.AddUidToLogEvent(uidFn) + + rec := initializeLogger(t) + + log.RegisterHook(hook) + log.WithUserId("a63554a8-aaaa-bbbbb-cccc-37a3b7d24e82").Info(context.Background(), "Testmessage") + + rec.OutputShouldBe(`{"time":"2022-01-01T01:02:03.000000004Z","sev":9,"body":"Testmessage","uid":"b91aa04538b01137e2e4733f9591f901d0e29a7b48d671c33a8e38972f9ee7e3"}` + "\n") +} + func TestAddUidToLogEvent_givenUidFnReturnsEmptyUid_whenLogWritten_thenAddsNothingToLog(t *testing.T) { uidFn := log.UidFromContextFn(func(ctx context.Context) (string, error) { From 62b97345d8165e9679a07aa0dd445cc568215c9c Mon Sep 17 00:00:00 2001 From: Thorsten Lanfer Date: Thu, 11 Aug 2022 10:25:45 +0200 Subject: [PATCH 4/4] Rename function to create userId hook --- otellog/uidhook.go | 2 +- otellog/uidhook_test.go | 8 ++++---- 2 files changed, 5 insertions(+), 5 deletions(-) diff --git a/otellog/uidhook.go b/otellog/uidhook.go index b8d6c40..d75f4c7 100644 --- a/otellog/uidhook.go +++ b/otellog/uidhook.go @@ -8,7 +8,7 @@ import ( type UidFromContextFn func(ctx context.Context) (string, error) -func AddUidToLogEvent(uidFn UidFromContextFn) Hook { +func AddUserIdToLogEvents(uidFn UidFromContextFn) Hook { return func(ctx context.Context, e *Event) { uid, _ := uidFn(ctx) diff --git a/otellog/uidhook_test.go b/otellog/uidhook_test.go index 1bce8eb..2eb6409 100644 --- a/otellog/uidhook_test.go +++ b/otellog/uidhook_test.go @@ -13,7 +13,7 @@ func TestAddUidToLogEvent_givenUidFnReturnsUid_whenLogWritten_thenAddsUidToLog(t return "a63554a8-6044-417b-a0aa-37a3b7d24e82", nil }) - hook := log.AddUidToLogEvent(uidFn) + hook := log.AddUserIdToLogEvents(uidFn) rec := initializeLogger(t) @@ -29,7 +29,7 @@ func TestAddUidToLogEvent_givenUidExplicitlySet_whenLogWritten_thenHookDoesNotRe return "a63554a8-6044-417b-a0aa-37a3b7d24e82", nil }) - hook := log.AddUidToLogEvent(uidFn) + hook := log.AddUserIdToLogEvents(uidFn) rec := initializeLogger(t) @@ -45,7 +45,7 @@ func TestAddUidToLogEvent_givenUidFnReturnsEmptyUid_whenLogWritten_thenAddsNothi return "", nil }) - hook := log.AddUidToLogEvent(uidFn) + hook := log.AddUserIdToLogEvents(uidFn) rec := initializeLogger(t) @@ -61,7 +61,7 @@ func TestAddUidToLogEvent_givenUidFnReturnsError_whenLogWritten_thenAddsNothingT return "", errors.New("some error") }) - hook := log.AddUidToLogEvent(uidFn) + hook := log.AddUserIdToLogEvents(uidFn) rec := initializeLogger(t)