Fix trace log duration for all logging implementations (#48)

palantir · May 2, 2019 · cb1c159 · cb1c159
1 parent 20c7378
commit cb1c159
Show file tree

Hide file tree

Showing 4 changed files with 40 additions and 5 deletions.
diff --git a/wlog-glog/internal/marshalers/wtracing_spanmodel.go b/wlog-glog/internal/marshalers/wtracing_spanmodel.go
@@ -55,7 +55,7 @@ func marshalWTracingSpanModel(key string, val interface{}) string {
 	if needSeparator {
 		_, _ = builder.WriteString(separator)
 	}
-	_, _ = builder.WriteString(fmt.Sprintf("%s: %d", trc1log.SpanDurationKey, int64(span.Duration.Round(time.Microsecond))))
+	_, _ = builder.WriteString(fmt.Sprintf("%s: %d", trc1log.SpanDurationKey, int64(span.Duration/time.Microsecond)))
 	needSeparator = true
 
 	if kind := span.Kind; kind != "" {

diff --git a/wlog-zap/internal/marshalers/wtracing_spanmodel.go b/wlog-zap/internal/marshalers/wtracing_spanmodel.go
@@ -35,7 +35,7 @@ func marshalWTracingSpanModel(key string, val interface{}) zapcore.Field {
 			enc.AddString(trc1log.SpanParentIDKey, string(*parentID))
 		}
 		enc.AddInt64(trc1log.SpanTimestampKey, span.Timestamp.Round(time.Microsecond).UnixNano()/1e3)
-		enc.AddInt64(trc1log.SpanDurationKey, int64(span.Duration.Round(time.Microsecond)))
+		enc.AddInt64(trc1log.SpanDurationKey, int64(span.Duration/time.Microsecond))
 		if kind := span.Kind; kind != "" {
 			// if kind is non-empty, manually create v1-style annotations
 			switch kind {

diff --git a/wlog-zerolog/internal/marshalers/wtracing_spanmodel.go b/wlog-zerolog/internal/marshalers/wtracing_spanmodel.go
@@ -34,7 +34,7 @@ func marshalWTracingSpanModel(evt *zerolog.Event, key string, val interface{}) *
 			e.Str(trc1log.SpanParentIDKey, string(*parentID))
 		}
 		e.Int64(trc1log.SpanTimestampKey, span.Timestamp.Round(time.Microsecond).UnixNano()/1e3)
-		e.Int64(trc1log.SpanDurationKey, int64(span.Duration.Round(time.Microsecond)))
+		e.Int64(trc1log.SpanDurationKey, int64(span.Duration/time.Microsecond))
 		if kind := span.Kind; kind != "" {
 			// if kind is non-empty, manually create v1-style annotations
 			switch kind {

diff --git a/wlog/trclog/trc1log/trc1logtests/tests.go b/wlog/trclog/trc1log/trc1logtests/tests.go
@@ -16,9 +16,12 @@ package trc1logtests
 
 import (
 	"bytes"
+	"encoding/json"
+	"fmt"
 	"io"
 	"net"
 	"testing"
+	"time"
 
 	"github.com/palantir/pkg/objmatcher"
 	"github.com/palantir/witchcraft-go-logging/wlog/logreader"
@@ -39,7 +42,6 @@ func TestCases(clientSpan wtracing.Span) []TestCase {
 	spanContext := clientSpan.Context()
 	traceID := string(spanContext.TraceID)
 	clientSpanID := string(spanContext.ID)
-
 	return []TestCase{
 		{
 			Name: "trace.1 log entry",
@@ -97,6 +99,26 @@ func TestCases(clientSpan wtracing.Span) []TestCase {
 
 func JSONTestSuite(t *testing.T, loggerProvider func(w io.Writer) trc1log.Logger) {
 	jsonOutputTests(t, loggerProvider)
+	durationFormatOutputTest(t, loggerProvider)
+}
+
+func durationFormatOutputTest(t *testing.T, loggerProvider func(w io.Writer) trc1log.Logger) {
+	buf := &bytes.Buffer{}
+	logger := loggerProvider(buf)
+	tracer, err := wzipkin.NewTracer(logger)
+	require.NoError(t, err)
+	span := tracer.StartSpan("testOp")
+	time.Sleep(100 * time.Millisecond)
+	// Finish() triggers logging
+	span.Finish()
+
+	entries, err := logreader.EntriesFromContent(buf.Bytes())
+	require.NoError(t, err)
+	require.Equal(t, 1, len(entries), "trace log should have exactly 1 entry")
+	// Ensure the duration matches the sleep amount
+	intValue := getDurationValue(t, entries[0])
+	assert.True(t, intValue*time.Microsecond < 200*time.Millisecond, fmt.Sprintf("duration must be less than 200 milliseconds and is %d", intValue))
+	assert.True(t, intValue*time.Microsecond > 100*time.Millisecond, fmt.Sprintf("duration must be more than 100 milliseconds and is %d", intValue))
 }
 
 func jsonOutputTests(t *testing.T, loggerProvider func(w io.Writer) trc1log.Logger) {
@@ -126,8 +148,21 @@ func jsonOutputTests(t *testing.T, loggerProvider func(w io.Writer) trc1log.Logg
 			entries, err := logreader.EntriesFromContent(buf.Bytes())
 			require.NoError(t, err)
 			require.Equal(t, 1, len(entries), "trace log should have exactly 1 entry")
-
 			assert.NoError(t, tc.JSONMatcher.Matches(map[string]interface{}(entries[0])), "Case %d: %s\n%v", i, tc.Name, err)
 		})
 	}
 }
+
+func getDurationValue(t *testing.T, entry logreader.Entry) time.Duration {
+	v, ok := entry["span"]
+	require.True(t, ok)
+	valueAsMap, ok := v.(map[string]interface{})
+	require.True(t, ok)
+	durationValue, ok := valueAsMap["duration"]
+	require.True(t, ok)
+	durationAsJSONNumber, ok := durationValue.(json.Number)
+	require.True(t, ok)
+	intValue, err := durationAsJSONNumber.Int64()
+	require.NoError(t, err)
+	return time.Duration(intValue)
+}