From 6ccbc5144d98bd396e234bee1da7688bee3a2784 Mon Sep 17 00:00:00 2001 From: Sergio Salvatore Date: Wed, 8 Mar 2023 17:45:06 -0500 Subject: [PATCH] Support Structured Tags Adds `STags` to `Entry` and delegates marshalling those structures to the emitters in whatever format is most appropriate. Structured tags are added via the alog.AddStructuredTags(ctx, sTag1, sTag2...) function. --- context.go | 43 +++++++++++++++++++++++++++------ emitter/gkelog/emitter.go | 33 ++++++++++++++++++++++--- emitter/gkelog/emitter_test.go | 11 ++++++++- emitter/jsonlog/emitter.go | 39 ++++++++++++++++++++++++++---- emitter/jsonlog/emitter_test.go | 16 ++++++++++-- emitter/testlog/emitter.go | 2 +- emitter/testlog/emitter_test.go | 9 ++++++- emitter/textlog/emitter.go | 13 ++++++++++ emitter/textlog/emitter_test.go | 9 ++++++- entry.go | 11 +++++---- logger.go | 7 +++--- 11 files changed, 163 insertions(+), 30 deletions(-) diff --git a/context.go b/context.go index f0b8735..e4edaa6 100644 --- a/context.go +++ b/context.go @@ -2,28 +2,57 @@ package alog import "context" -type key struct{} +type stringKey struct{} +type structuredKey struct{} -var ctxkey = &key{} +var stringCtxKey = stringKey{} +var structuredCtxKey = structuredKey{} + +// STag is a structured tag. +type STag struct { + // A unique key for the structure being logged. + Key string + // The structure you would like logged. This will be marshalled into an + // appropriate form based on the chosen emitter. + Val interface{} +} // AddTags adds paired strings to the set of tags in the Context. // // Any unpaired strings are ignored. func AddTags(ctx context.Context, pairs ...string) context.Context { - old := fromContext(ctx) + old := tagsFromContext(ctx) new := make([][2]string, len(old)+(len(pairs)/2)) copy(new, old) for o := range new[len(old):] { new[len(old)+o][0] = pairs[o*2] new[len(old)+o][1] = pairs[o*2+1] } - return context.WithValue(ctx, ctxkey, new) + return context.WithValue(ctx, stringCtxKey, new) } -// fromContext wraps the type assertion coming out of a Context. -func fromContext(ctx context.Context) [][2]string { - if t, ok := ctx.Value(ctxkey).([][2]string); ok { +// tagsFromContext wraps the type assertion coming out of a Context. +func tagsFromContext(ctx context.Context) [][2]string { + if t, ok := ctx.Value(stringCtxKey).([][2]string); ok { return t } return nil } + +// AddStructuredTags adds tag structures to the Context. +func AddStructuredTags(ctx context.Context, tags ...STag) context.Context { + oldTags := sTagsFromContext(ctx) + + newTags := append(oldTags[:len(oldTags):len(oldTags)], tags...) + + return context.WithValue(ctx, structuredCtxKey, newTags) +} + +// sTagsFromContext wraps the type assertion for structured tags coming out +// of the context. +func sTagsFromContext(ctx context.Context) []STag { + if tags, ok := ctx.Value(structuredCtxKey).([]STag); ok { + return tags + } + return ([]STag)(nil) +} diff --git a/emitter/gkelog/emitter.go b/emitter/gkelog/emitter.go index 37c9dce..b207ad5 100644 --- a/emitter/gkelog/emitter.go +++ b/emitter/gkelog/emitter.go @@ -357,12 +357,15 @@ func Emitter(opt ...Option) alog.Emitter { jsonTrace(ctx, o, b) - tagClean := make(map[string]int, len(e.Tags)) - for i, tag := range e.Tags { - tagClean[tag[0]] = i + // Get all the tags and take their positions in the list. If there are + // tags with the same key (first element of the string tuple) the latest + // tag will take precedence. + tagPositions := make(map[string]int, len(e.Tags)) + for i, t := range e.Tags { + tagPositions[t[0]] = i } for i, tag := range e.Tags { - if tagClean[tag[0]] != i || reservedKeys[tag[0]] { + if tagPositions[tag[0]] != i || reservedKeys[tag[0]] { continue } jsonKey(b, tag[0]) @@ -370,6 +373,28 @@ func Emitter(opt ...Option) alog.Emitter { b.WriteString(", ") } + sTagPositions := make(map[string]int, len(e.STags)) + for i, t := range e.STags { + sTagPositions[t.Key] = i + } + for i, sTag := range e.STags { + _, asStringTag := tagPositions[sTag.Key] // has this already been used as a string tag? + if tagPositions[sTag.Key] != i || asStringTag || reservedKeys[sTag.Key] { + continue + } + + jsonKey(b, sTag.Key) + + marshalled, marshalErr := json.Marshal(sTag.Val) + if marshalErr == nil { + b.Write(marshalled) + } else { + jsonString(b, "json marshal err: "+marshalErr.Error()) + } + + b.WriteString(", ") + } + if e.File != "" { jsonKey(b, "logging.googleapis.com/sourceLocation") b.WriteByte('{') diff --git a/emitter/gkelog/emitter_test.go b/emitter/gkelog/emitter_test.go index 4520c82..bfbfdd2 100644 --- a/emitter/gkelog/emitter_test.go +++ b/emitter/gkelog/emitter_test.go @@ -49,10 +49,19 @@ func TestLabels(t *testing.T) { ctx := context.Background() l := alog.New(alog.WithEmitter(Emitter(WithWriter(b))), zeroTimeOpt) + structured := alog.STag{ + Key: "structured", + Val: struct { + X int `json:"x"` + }{ + X: 1, + }, + } ctx = alog.AddTags(ctx, "allthese", "tags", "andanother", "tag") + ctx = alog.AddStructuredTags(ctx, structured) l.Print(ctx, "test") - want := `{"time":"0001-01-01T00:00:00Z", "allthese":"tags", "andanother":"tag", "message":"test"}` + "\n" + want := `{"time":"0001-01-01T00:00:00Z", "allthese":"tags", "andanother":"tag", "structured":{"x":1}, "message":"test"}` + "\n" got := b.String() if got != want { t.Errorf("got:\n%s\nwant:\n%s", got, want) diff --git a/emitter/jsonlog/emitter.go b/emitter/jsonlog/emitter.go index 233fc05..f8f349f 100644 --- a/emitter/jsonlog/emitter.go +++ b/emitter/jsonlog/emitter.go @@ -106,14 +106,15 @@ func Emitter(w io.Writer, opt ...Option) alog.Emitter { b.WriteString(", ") } + tagPositions := make(map[string]int, len(e.Tags)) + for i, tag := range e.Tags { + tagPositions[tag[0]] = i + } + if len(e.Tags) > 0 { b.WriteString(`"tags":{`) - tagClean := make(map[string]int, len(e.Tags)) for i, tag := range e.Tags { - tagClean[tag[0]] = i - } - for i, tag := range e.Tags { - if tagClean[tag[0]] != i { + if tagPositions[tag[0]] != i { continue } jsonString(b, tag[0]) @@ -126,6 +127,34 @@ func Emitter(w io.Writer, opt ...Option) alog.Emitter { b.WriteString("}, ") } + if len(e.STags) > 0 { + sTagPositions := make(map[string]int, len(e.STags)) + for i, tag := range e.STags { + sTagPositions[tag.Key] = i + } + b.WriteString(`"sTags":{`) + for i, tag := range e.STags { + _, asStringTag := tagPositions[tag.Key] + if sTagPositions[tag.Key] != i || asStringTag { + continue + } + + jsonString(b, tag.Key) + b.WriteByte(':') + + marshalled, marshalErr := json.Marshal(tag.Val) + if marshalErr == nil { + b.Write(marshalled) + } else { + jsonString(b, "json marshal err: "+marshalErr.Error()) + } + if i < len(e.Tags)-1 { + b.WriteString(", ") + } + } + b.WriteString("}, ") + } + b.WriteString(messageField) b.WriteByte(':') jsonString(b, e.Msg) diff --git a/emitter/jsonlog/emitter_test.go b/emitter/jsonlog/emitter_test.go index 68b8984..931c6e1 100644 --- a/emitter/jsonlog/emitter_test.go +++ b/emitter/jsonlog/emitter_test.go @@ -17,14 +17,26 @@ func TestEmitter(t *testing.T) { ctx := context.Background() l := alog.New(alog.WithCaller(), alog.WithEmitter(Emitter(b, WithShortFile())), zeroTimeOpt) + structuredVal := struct { + X int `json:"x"` + Y int `json:"why"` + }{ + X: 1, + Y: 42, + } + ctx = alog.AddTags(ctx, "allthese", "tags", "andanother", "tag") + ctx = alog.AddStructuredTags(ctx, alog.STag{Key: "structured", Val: structuredVal}, alog.STag{Key: "other-struct", Val: structuredVal}) l.Print(ctx, "test") - want := `{"timestamp":"0001-01-01T00:00:00.000000000Z", "caller":"emitter_test.go:21", "tags":{"allthese":"tags", "andanother":"tag"}, "message":"test"}` + "\n" + want := `{"timestamp":"0001-01-01T00:00:00.000000000Z", "caller":"emitter_test.go:30", "tags":{"allthese":"tags", "andanother":"tag"}, "sTags":{"structured":{"x":1,"why":42}, "other-struct":{"x":1,"why":42}}, "message":"test"}` + "\n" got := b.String() if got != want { t.Errorf("got:\n%s\nwant:\n%s", got, want) } + if !json.Valid([]byte(got)) { + t.Errorf("invalid json: %s", got) + } } func TestMessageOnly(t *testing.T) { @@ -53,7 +65,7 @@ func TestCustomFieldNames(t *testing.T) { l.Print(ctx, "test") - want := `{"ts":"0001-01-01T00:00:00.000000000Z", "called_at":"emitter_test.go:54", "msg":"test"}` + "\n" + want := `{"ts":"0001-01-01T00:00:00.000000000Z", "called_at":"emitter_test.go:66", "msg":"test"}` + "\n" got := b.String() if got != want { t.Errorf("got:\n%s\nwant:\n%s", got, want) diff --git a/emitter/testlog/emitter.go b/emitter/testlog/emitter.go index e825a6e..78577c3 100644 --- a/emitter/testlog/emitter.go +++ b/emitter/testlog/emitter.go @@ -29,6 +29,6 @@ func Emitter(t testing.TB, opt ...Option) alog.Emitter { if o.shortfile { e.File = path.Base(e.File) } - t.Logf("%s %s %v", e.File, e.Msg, e.Tags) + t.Logf("%s %s %v %+v", e.File, e.Msg, e.Tags, e.STags) }) } diff --git a/emitter/testlog/emitter_test.go b/emitter/testlog/emitter_test.go index a0decfa..1a6ec9a 100644 --- a/emitter/testlog/emitter_test.go +++ b/emitter/testlog/emitter_test.go @@ -12,9 +12,16 @@ func TestEmitter(t *testing.T) { ctx := context.Background() l := DefaultLogger(t, WithShortFile()) + structured := struct { + X int + }{ + X: 1, + } + ctx = alog.AddTags(ctx, "test", "tags") + ctx = alog.AddStructuredTags(ctx, alog.STag{Key: "structured", Val: structured}) l.Print(ctx, "testMessage") // Output - // logger.go:40: emitter_test.go testMessage [[test tags]] + // logger.go:40: emitter_test.go testMessage [[test tags]] [{Key:structured Val:{X:1}}] } diff --git a/emitter/textlog/emitter.go b/emitter/textlog/emitter.go index fb9115f..4c4d065 100644 --- a/emitter/textlog/emitter.go +++ b/emitter/textlog/emitter.go @@ -2,6 +2,7 @@ package textlog import ( "context" + "fmt" "io" "os" "time" @@ -64,6 +65,18 @@ func Emitter(w io.Writer, opt ...Option) alog.Emitter { } m.WriteString("] ") } + if t := e.STags; len(t) != 0 { + m.WriteByte('[') + for i, p := range t { + if i != 0 { + m.WriteByte(' ') + } + m.WriteString(p.Key) + m.WriteByte('=') + fmt.Fprintf(m, "%+v", p.Val) + } + m.WriteString("] ") + } m.WriteString(e.Msg) if m.Bytes()[m.Len()-1] != '\n' { m.WriteByte('\n') diff --git a/emitter/textlog/emitter_test.go b/emitter/textlog/emitter_test.go index 7e96f14..56f246b 100644 --- a/emitter/textlog/emitter_test.go +++ b/emitter/textlog/emitter_test.go @@ -14,8 +14,15 @@ func ExampleEmitter() { alog.WithEmitter(Emitter(os.Stdout, WithShortFile(), WithDateFormat(time.RFC3339))), alog.OverrideTimestamp(func() time.Time { return time.Time{} })) + structuredVal := struct { + X int + }{ + X: 1, + } + ctx = alog.AddTags(ctx, "allthese", "tags") + ctx = alog.AddStructuredTags(ctx, alog.STag{Key: "structured", Val: structuredVal}) l.Print(ctx, "test") // Output: - // 0001-01-01T00:00:00Z emitter_test.go:18: [allthese=tags] test + // 0001-01-01T00:00:00Z emitter_test.go:25: [allthese=tags] [structured={X:1}] test } diff --git a/entry.go b/entry.go index 124b413..769377f 100644 --- a/entry.go +++ b/entry.go @@ -4,9 +4,10 @@ import "time" // Entry is the struct passed to user-supplied formatters. type Entry struct { - Time time.Time - Tags [][2]string - File string - Line int - Msg string + Time time.Time + Tags [][2]string + STags []STag + File string + Line int + Msg string } diff --git a/logger.go b/logger.go index b484aef..363c6dd 100644 --- a/logger.go +++ b/logger.go @@ -67,9 +67,10 @@ func (l *Logger) Output(ctx context.Context, calldepth int, msg string) { l.now = time.Now } e := Entry{ - Time: l.now(), - Tags: fromContext(ctx), - Msg: msg, + Time: l.now(), + Tags: tagsFromContext(ctx), + STags: sTagsFromContext(ctx), + Msg: msg, } if l.caller {