Improve the "use-after-free" assertion

Let it print out the "previous" contents of the Span when it triggers
a use-after-free assertion. This is valuable in tracking down the past
of that Span, and thus the original call to Finish().

concurrency_test.go

@@ -1,6 +1,7 @@
 package basictracer
 
 import (
+	"strings"
 	"sync"
 	"testing"
 
@@ -40,19 +41,25 @@ func TestDebugAssertUseAfterFinish(t *testing.T) {
 	opts.Recorder = NewInMemoryRecorder()
 	opts.DebugAssertUseAfterFinish = true
 	tracer := NewWithOptions(opts)
+	const msg = "I shall be finished"
 	for _, double := range []bool{false, true} {
 		sp := tracer.StartSpan(op)
+		sp.Log(opentracing.LogData{Event: msg})
 		if double {
 			sp.Finish()
 		}
 		var panicked bool
 		func() {
 			defer func() {
 				r := recover()
-				_, panicked = r.(*errAssertionFailed)
+				var assertionErr error
+				assertionErr, panicked = r.(*errAssertionFailed)
 				if !panicked && r != nil {
 					panic(r)
 				}
+				if panicked && !strings.Contains(assertionErr.Error(), msg) {
+					t.Fatalf("debug output did not contain log message '%s': %+v", msg, assertionErr)
+				}
 				spImpl := sp.(*spanImpl)
 				// The panic should leave the Mutex unlocked.
 				spImpl.Mutex.Lock()

debug.go

@@ -11,7 +11,13 @@ import (
 const debugGoroutineIDTag = "_initial_goroutine"
 
 type errAssertionFailed struct {
-	msg string
+	span *spanImpl
+	msg  string
+}
+
+// Error implements the error interface.
+func (err *errAssertionFailed) Error() string {
+	return fmt.Sprintf("%s:\n%+v", err.msg, err.span)
 }
 
 func (s *spanImpl) Lock() {
@@ -22,9 +28,7 @@ func (s *spanImpl) Lock() {
 func (s *spanImpl) maybeAssertSanityLocked() {
 	if s.tracer == nil {
 		s.Mutex.Unlock()
-		panic(&errAssertionFailed{
-			msg: fmt.Sprintf("span used after Finish()"),
-		})
+		panic(&errAssertionFailed{span: s, msg: "span used after call to Finish()"})
 	}
 	if s.tracer.options.DebugAssertSingleGoroutine {
 		startID := curGoroutineID()
@@ -37,7 +41,8 @@ func (s *spanImpl) maybeAssertSanityLocked() {
 		if startID != curID {
 			s.Mutex.Unlock()
 			panic(&errAssertionFailed{
-				msg: fmt.Sprintf("span started on goroutine %d, but now running on %d", startID, curID),
+				span: s,
+				msg:  fmt.Sprintf("span started on goroutine %d, but now running on %d", startID, curID),
 			})
 		}
 	}

span.go

@@ -171,7 +171,9 @@ func (s *spanImpl) FinishWithOptions(opts opentracing.FinishOptions) {
 	if s.tracer.options.DebugAssertUseAfterFinish {
 		// This makes it much more likely to catch a panic on any subsequent
 		// operation since s.tracer is accessed on every call to `Lock`.
-		s.reset()
+		// We don't call `reset()` here to preserve the logs in the Span
+		// which are printed when the assertion triggers.
+		s.tracer = nil
 	}
 
 	if poolEnabled {