Merge pull request #50 from muir/forty

test complaints about extra calls to Done

logger.go

@@ -276,6 +276,9 @@ func (log *Log) hasActivity(startFlusher bool) {
 				DebugPrint("restarting timer", log.shared.FlushDelay)
 				log.shared.FlushTimer.Reset(log.shared.FlushDelay)
 			}
+			if wasDone := atomic.LoadInt32(&log.span.doneCount); wasDone != 0 {
+				log.Error().Static("XOP: log was already done, but was used again")
+			}
 		}
 	}
 }
@@ -308,7 +311,7 @@ func (log *Log) hasActivity(startFlusher bool) {
 // trigger a call to Flush().
 func (log *Log) Done() {
 	if log.nonSpanSubLog {
-		log.Error().Static("invalid call to Done() in non-span sub-log")
+		log.Error().Static("XOP: invalid call to Done() in non-span sub-log")
 		return
 	}
 	DebugPrint("starting Done {", log.span.description, log.span.logNumber)
@@ -346,7 +349,8 @@ func (log *Log) recursiveDone(done bool, now time.Time) (count int32) {
 func (log *Log) done(explicit bool, now time.Time) {
 	postCount := log.recursiveDone(true, now)
 	if postCount > 1 && explicit {
-		log.Error().Msg("Done() called on log object when it was already Done()")
+		DebugPrint("donecount=", postCount, "logging error")
+		log.Error().Static("XOP: Done() called on log object when it was already Done()")
 	}
 	if log.span.detached {
 		if func() bool {

xopjson/jsonlogger_test.go

@@ -422,8 +422,8 @@ func TestParameters(t *testing.T) {
 			name: "add/remove loggers with a span",
 			do: func(t *testing.T, log *xop.Log, tlog *xoptest.TestLogger) {
 				tlog2 := xoptest.New(t)
-				s2 := log.Sub().Step("R2", xop.WithBase(tlog2))
-				s3 := s2.Sub().Detach().Fork("R3", xop.WithoutBase(tlog2))
+				s2 := log.Sub().Step("S2", xop.WithBase(tlog2))
+				s3 := s2.Sub().Detach().Fork("S3", xop.WithoutBase(tlog2))
 				s2.Info().Static("log to both test loggers")
 				s3.Info().Static("log to just the original set")
 				xoptestutil.MicroNap()
@@ -432,6 +432,27 @@ func TestParameters(t *testing.T) {
 				log.Done()
 			},
 		},
+		{
+			name:         "log after done",
+			extraFlushes: 1,
+			do: func(t *testing.T, log *xop.Log, tlog *xoptest.TestLogger) {
+				s2 := log.Sub().Step("S2")
+				s2.Info().Int8("i8", 9).Msg("a line before done")
+				xoptestutil.MicroNap()
+				s2.Done()
+				assert.Empty(t, tlog.FindLines(xoptest.TextContains("XOP: log was already done, but was used again")), "no err")
+				s2.Info().Int16("i16", 940).Msg("a post-done line, should trigger an error log")
+				assert.NotEmpty(t, tlog.FindLines(xoptest.TextContains("XOP: log was already done, but was used again")), "no err")
+				assert.Empty(t, tlog.FindLines(xoptest.TextContains("called on log object when it was already Done")), "no err")
+				xoptestutil.MicroNap()
+				s2.Done()
+				assert.NotEmpty(t, tlog.FindLines(xoptest.TextContains("called on log object when it was already Done")), "now err")
+				log.Flush()
+				s2.Warn().Int32("i32", 940940).Msg("another post-done line, should trigger an error log")
+				xoptestutil.MicroNap()
+				log.Done()
+			},
+		},
 	}
 
 	for _, tc := range jsonCases {