tracer: add debug log for finished spans (#1877)

Log finished spans in debug the same way we log started spans.

ddtrace/tracer/span.go

@@ -497,6 +497,11 @@ func (s *span) finish(finishTime int64) {
 		// a single kept span keeps the whole trace.
 		s.context.trace.keep()
 	}
+	if log.DebugEnabled() {
+		// avoid allocating the ...interface{} argument if debug logging is disabled
+		log.Debug("Finished Span: %v, Operation: %s, Resource: %s, Tags: %v, %v",
+			s, s.Name, s.Resource, s.Meta, s.Metrics)
+	}
 	s.context.finish()
 }
 

ddtrace/tracer/span_test.go

@@ -16,6 +16,7 @@ import (
 	"time"
 
 	"gopkg.in/DataDog/dd-trace-go.v1/ddtrace/ext"
+	"gopkg.in/DataDog/dd-trace-go.v1/internal/log"
 	"gopkg.in/DataDog/dd-trace-go.v1/internal/samplernames"
 
 	"github.com/DataDog/datadog-agent/pkg/obfuscate"
@@ -834,6 +835,30 @@ func TestRootSpanAccessor(t *testing.T) {
 	})
 }
 
+func TestSpanStartAndFinishLogs(t *testing.T) {
+	tp := new(log.RecordLogger)
+	tracer, _, _, stop := startTestTracer(t, WithLogger(tp), WithDebugMode(true))
+	defer stop()
+
+	span := tracer.StartSpan("op")
+	time.Sleep(time.Millisecond * 2)
+	span.Finish()
+	started, finished := false, false
+	for _, l := range tp.Logs() {
+		if !started {
+			started = strings.Contains(l, "DEBUG: Started Span")
+		}
+		if !finished {
+			finished = strings.Contains(l, "DEBUG: Finished Span")
+		}
+		if started && finished {
+			break
+		}
+	}
+	require.True(t, started)
+	require.True(t, finished)
+}
+
 func BenchmarkSetTagMetric(b *testing.B) {
 	span := newBasicSpan("bench.span")
 	keys := "abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ"