From 7e877dd12973f34ce3ec9a5b8cdbdb2dc2d19e21 Mon Sep 17 00:00:00 2001 From: David Muir Sharnoff Date: Sat, 3 Sep 2022 14:41:13 -0700 Subject: [PATCH] bugfix for prefill in xopjson .Done no longer supported for span-less logs bugfix and doc fix for context --- context.go | 6 ++- context_test.go | 23 +++++----- logger.go | 90 ++++++++++++++++++++++++-------------- xopjson/jsonlogger.go | 2 +- xopjson/jsonlogger.zzzgo | 2 +- xopjson/jsonlogger_test.go | 10 +++++ 6 files changed, 86 insertions(+), 47 deletions(-) diff --git a/context.go b/context.go index 2e479671..ebcdeece 100644 --- a/context.go +++ b/context.go @@ -8,7 +8,8 @@ type contextKeyType struct{} var contextKey = contextKeyType{} -// TODO: have a default log that prints +// Default serves as a fallback logger if FromContextOrDefault +// does not find a logger. Unless modified, it discards all logs. var Default = NewSeed().Request("discard") func (log *Log) IntoContext(ctx context.Context) context.Context { @@ -42,6 +43,9 @@ func FromContextOrPanic(ctx context.Context) *Log { // CustomFromContext returns a convenience function: it calls either // FromContextOrPanic() or FromContextOrDefault() and then calls a // function to adjust setting. +// +// Pass FromContextOrPanic or FromContextOrDefault as the first argument +// and a function to adjust settings as the second argument. func CustomFromContext(getLogFromContext func(context.Context) *Log, adjustSettings func(*Sub) *Sub) func(context.Context) *Log { return func(ctx context.Context) *Log { log := getLogFromContext(ctx) diff --git a/context_test.go b/context_test.go index fe911cf7..b33bd146 100644 --- a/context_test.go +++ b/context_test.go @@ -9,14 +9,14 @@ import ( func TestIntoContext(t *testing.T) { log := NewSeed().Request("myLog") - ctx := context.TODO() + ctx := context.Background() ctxWithLog := log.IntoContext(ctx) assert.Equal(t, log, ctxWithLog.Value(contextKey)) } func TestFromContext(t *testing.T) { log := NewSeed().Request("myLog") - ctx := context.TODO() + ctx := context.Background() ctxLog, ok := FromContext(ctx) assert.False(t, ok) assert.Nil(t, ctxLog) @@ -27,7 +27,7 @@ func TestFromContext(t *testing.T) { } func TestFromContextOrDefault(t *testing.T) { - ctx := context.TODO() + ctx := context.Background() log := FromContextOrDefault(ctx) assert.Equal(t, Default, log) log = NewSeed().Request("myLog") @@ -36,7 +36,7 @@ func TestFromContextOrDefault(t *testing.T) { } func TestFromContextOrPanic(t *testing.T) { - ctx := context.TODO() + ctx := context.Background() assert.Panics(t, func() { _ = FromContextOrPanic(ctx) }) log := NewSeed().Request("myLog") ctxLog := log.IntoContext(ctx) @@ -44,12 +44,13 @@ func TestFromContextOrPanic(t *testing.T) { } func TestCustomFromContext(t *testing.T) { - getDefaultLogFromContext := func(ctx context.Context) *Log { - return Default + adjustSettings := func(sub *Sub) *Sub { + return sub.PrefillText("banana") } - noOpAdjustSettings := func(sub *Sub) *Sub { - return sub - } - customFromContextFun := CustomFromContext(getDefaultLogFromContext, noOpAdjustSettings) - assert.Equal(t, Default, customFromContextFun(context.TODO())) + customLogFun := CustomFromContext(FromContextOrDefault, adjustSettings) + customLog := customLogFun(context.Background()) + defer customLog.Done() + assert.NotEqual(t, Default, customLog, "logs are not equal") + assert.NotEqual(t, Default.Settings(), customLog.Settings(), "default settings") + assert.Equal(t, Default.Sub().PrefillText("banana").Log().Settings(), customLog.Settings(), "modified settings") } diff --git a/logger.go b/logger.go index 03881690..6a1ba4fc 100644 --- a/logger.go +++ b/logger.go @@ -17,13 +17,14 @@ import ( ) type Log struct { - request *Log // XXX changed from *Span - span *span - capSpan *Span // added - parent *Log // added - shared *shared // shared between spans in a request - settings LogSettings - prefilled xopbase.Prefilled // XXX double-check, in request? + request *Log // The ancestor request-level Log + span *span // span associated with this Log + capSpan *Span // Span associated with this Log + parent *Log // immediate parent Log + shared *shared // shared between logs with same request-level Log + settings LogSettings // settings for this Log + prefilled xopbase.Prefilled // XXX double-check, in request? + nonSpanSubLog bool // true if created by log.Sub().Log() } type Span struct { @@ -41,12 +42,12 @@ type span struct { description string stepCounter int32 //nolint:structcheck // false report forkCounter int32 //nolint:structcheck // false report - spanNumber int32 detached bool - doneCount int32 - knownActive int32 dependentLock sync.Mutex activeDependents map[int32]*Log + doneCount int32 + knownActive int32 + logNumber int32 } // shared is common between the loggers that share a search index @@ -58,7 +59,7 @@ type shared struct { FlushActive int32 // 1 == timer is running, 0 = timer is not running Flushers map[string]xopbase.Request // key is xopbase.Logger.ID() // XXX change key to int? Description string - SpanCount int32 + LogCount int32 ActiveDetached map[int32]*Log } @@ -78,8 +79,8 @@ func (seed Seed) Request(descriptionOrName string) *Log { }, span: span{ seed: seed.spanSeed.Copy(), - knownActive: 1, description: descriptionOrName, + knownActive: 1, }, shared: shared{ FlushActive: 1, @@ -122,12 +123,13 @@ func (sub *Sub) Log() *Log { } alloc := singleAlloc{ Log: Log{ - request: sub.log.request, - span: sub.log.span, - capSpan: sub.log.capSpan, - parent: sub.log.parent, - shared: sub.log.shared, - settings: sub.settings, + request: sub.log.request, + span: sub.log.span, + capSpan: sub.log.capSpan, + parent: sub.log.parent, + shared: sub.log.shared, + settings: sub.settings, + nonSpanSubLog: true, // XXX prefilled? }, Span: Span{ @@ -138,7 +140,7 @@ func (sub *Sub) Log() *Log { alloc.Log.capSpan = &alloc.Span log := &alloc.Log log.sendPrefill() - log.addMyselfAsDependent() + log.hasActivity(false) return log } @@ -158,10 +160,10 @@ func (old *Log) newChildLog(spanSeed spanSeed, description string, settings LogS }, span: span{ seed: spanSeed, - knownActive: 1, - spanNumber: atomic.AddInt32(&old.shared.SpanCount, 1), detached: detached, description: description, + knownActive: 1, + logNumber: atomic.AddInt32(&old.shared.LogCount, 1), }, } alloc.Span.span = &alloc.span @@ -234,7 +236,7 @@ func (log *Log) addMyselfAsDependent() bool { log.Info().String("span", log.span.seed.traceBundle.Trace.SpanID().String()).Msg("XXX is detached") log.request.span.dependentLock.Lock() defer log.request.span.dependentLock.Unlock() - log.shared.ActiveDetached[log.span.spanNumber] = log + log.shared.ActiveDetached[log.span.logNumber] = log return false } log.Info().String("span", log.span.seed.traceBundle.Trace.SpanID().String()).Msg("XXX is attached") @@ -243,8 +245,8 @@ func (log *Log) addMyselfAsDependent() bool { if log.parent.span.activeDependents == nil { log.parent.span.activeDependents = make(map[int32]*Log) } - DebugPrint("add to active deps", log.span.description, ":", log.span.spanNumber) - log.parent.span.activeDependents[log.span.spanNumber] = log + DebugPrint("add to active deps", log.span.description, ":", log.span.logNumber) + log.parent.span.activeDependents[log.span.logNumber] = log return len(log.parent.span.activeDependents) == 1 } @@ -263,22 +265,44 @@ func (log *Log) hasActivity(startFlusher bool) { } } -// Done is used to indicate that a log is complete. All non-Detach()ed -// logs that were created from this log are also considered complete. +// Done is used to indicate that a log is complete. Buffered base loggers +// (implementing xopbase.Logger) wait for Done to be called before flushing their data. +// +// Requests (Log's created by seed.Request()) and detached logs (created by +// log.Sub().Detach().Fork() or log.Sub().Detah().Step()) are considered +// top-level logs. A call to Done() on a top-level log marks all +// sub-spans as Done() if they were not already marked done. +// +// Calling Done() on a log that is already done generates a logged error +// message. +// +// Non-detached sub-spans (created by log.Sub().Fork() and log.Sub().Step()) +// are done when either Done is called on the sub-span or when their associated +// top-level log is done. +// +// Sub-logs that are not spans (created by log.Sub().Log()) should not use +// Done(). Any call to Done on such a sub-log will log an error and otherwise +// be ignored. +// +// When all the logs associated with a Request are done, the Flush() is +// automatically triggered. The Flush() call can be +// synchronous or asynchronous depending on the SynchronousFlush settings +// of the request-level Log. // // Any logging activity after a Done() causes an error to be logged and may // trigger a call to Flush(). -// -// Done can be synchronous or asynchronous depending on the SynchronousFlush -// settings. func (log *Log) Done() { + if log.nonSpanSubLog { + log.Error().Static("invalid call to Done() in non-span sub-log") + return + } DebugPrint("starting Done") log.done(true, true, time.Now()) DebugPrint("done with Done") } func (log *Log) recursiveDone(done bool, now time.Time) (count int32) { - DebugPrint("recursive done on", done, log.span.description) + DebugPrint("recursive done on", done, log.span.description, log.span.logNumber) if done { atomic.StoreInt32(&log.span.knownActive, 0) count = atomic.AddInt32(&log.span.doneCount, 1) @@ -312,7 +336,7 @@ func (log *Log) done(explicit bool, doUp bool, now time.Time) { if func() bool { log.request.span.dependentLock.Lock() defer log.request.span.dependentLock.Unlock() - delete(log.shared.ActiveDetached, log.span.spanNumber) + delete(log.shared.ActiveDetached, log.span.logNumber) return len(log.shared.ActiveDetached) == 0 && len(log.request.span.activeDependents) == 0 }() { @@ -337,8 +361,8 @@ func (log *Log) done(explicit bool, doUp bool, now time.Time) { if func() bool { log.parent.span.dependentLock.Lock() defer log.parent.span.dependentLock.Unlock() - DebugPrint("delete from active deps", log.span.description, ":", log.span.spanNumber) - delete(log.parent.span.activeDependents, log.span.spanNumber) + DebugPrint("delete from active deps", log.span.description, ":", log.span.logNumber) + delete(log.parent.span.activeDependents, log.span.logNumber) return len(log.parent.span.activeDependents) == 0 }() && doUp { log.parent.done(explicit, doUp, now) diff --git a/xopjson/jsonlogger.go b/xopjson/jsonlogger.go index 8945c017..3c7efcb3 100644 --- a/xopjson/jsonlogger.go +++ b/xopjson/jsonlogger.go @@ -378,7 +378,7 @@ func (p *prefilling) PrefillComplete(m string) xopbase.Prefilled { copy(prefilled.data, p.builder.B) if len(m) > 0 { msgBuffer := xoputil.JBuilder{ - B: make([]byte, len(m)), // alloc-per-prefill + B: make([]byte, 0, len(m)), // alloc-per-prefill } msgBuffer.AddStringBody(m) prefilled.preEncodedMsg = msgBuffer.B diff --git a/xopjson/jsonlogger.zzzgo b/xopjson/jsonlogger.zzzgo index 5e7aa542..521c4435 100644 --- a/xopjson/jsonlogger.zzzgo +++ b/xopjson/jsonlogger.zzzgo @@ -376,7 +376,7 @@ func (p *prefilling) PrefillComplete(m string) xopbase.Prefilled { copy(prefilled.data, p.builder.B) if len(m) > 0 { msgBuffer := xoputil.JBuilder{ - B: make([]byte, len(m)), // alloc-per-prefill + B: make([]byte, 0, len(m)), // alloc-per-prefill } msgBuffer.AddStringBody(m) prefilled.preEncodedMsg = msgBuffer.B diff --git a/xopjson/jsonlogger_test.go b/xopjson/jsonlogger_test.go index 0b17cdc1..2b63c512 100644 --- a/xopjson/jsonlogger_test.go +++ b/xopjson/jsonlogger_test.go @@ -387,6 +387,16 @@ func TestParameters(t *testing.T) { log.Done() }, }, + { + name: "prefill", + do: func(t *testing.T, log *xop.Log, tlog *xoptest.TestLogger) { + p := log.Sub().PrefillFloat64("f", 23).PrefillText("pre!").Log() + p.Error().Int16("i16", int16(7)).Msg("pf") + log.Alert().Int32("i32", int32(77)).Msgf("pf %s", "bar") + xoptestutil.MicroNap() + log.Done() + }, + }, } for _, tc := range jsonCases {