Merge pull request #27 from instana/issue_27

Error handling inconsistent/not working

json_span.go

@@ -12,6 +12,8 @@ type jsonSpan struct {
 	Duration  uint64    `json:"d"`
 	Name      string    `json:"n"`
 	From      *fromS    `json:"f"`
+	Ec        int       `json:"ec,omitempty"`
+	Lang      string    `json:"ta,omitempty"`
 	Data      *jsonData `json:"data"`
 }
 

recorder.go

@@ -121,6 +121,8 @@ func (r *Recorder) RecordSpan(span *spanS) {
 		Timestamp: uint64(span.Start.UnixNano()) / uint64(time.Millisecond),
 		Duration:  uint64(span.Duration) / uint64(time.Millisecond),
 		Name:      "sdk",
+		Ec:        span.Ec,
+		Lang:      "go",
 		From:      sensor.agent.from,
 		Data:      data})
 

span.go

@@ -22,6 +22,7 @@ type spanS struct {
 	Duration     time.Duration
 	Tags         ot.Tags
 	Logs         []ot.LogRecord
+	Ec           int
 }
 
 func (r *spanS) BaggageItem(key string) string {
@@ -109,6 +110,14 @@ func (r *spanS) LogEventWithPayload(event string, payload interface{}) {
 }
 
 func (r *spanS) LogFields(fields ...otlog.Field) {
+
+	for _, v := range fields {
+		// If this tag indicates an error, increase the error count
+		if v.Key() == "error" {
+			r.Ec++
+		}
+	}
+
 	lr := ot.LogRecord{
 		Fields: fields,
 	}
@@ -156,6 +165,11 @@ func (r *spanS) SetTag(key string, value interface{}) ot.Span {
 		r.Tags = ot.Tags{}
 	}
 
+	// If this tag indicates an error, increase the error count
+	if key == "error" {
+		r.Ec++
+	}
+
 	r.Tags[key] = value
 
 	return r

span_test.go

@@ -1,13 +1,17 @@
 package instana_test
 
 import (
+	"errors"
+	"fmt"
 	"testing"
 	"time"
 
 	"github.com/stretchr/testify/assert"
 
 	"github.com/instana/golang-sensor"
 	ot "github.com/opentracing/opentracing-go"
+	ext "github.com/opentracing/opentracing-go/ext"
+	"github.com/opentracing/opentracing-go/log"
 )
 
 func TestBasicSpan(t *testing.T) {
@@ -31,6 +35,7 @@ func TestBasicSpan(t *testing.T) {
 	assert.Equal(t, "test", span.Data.SDK.Name, "Missing span name")
 	assert.Nil(t, span.Data.SDK.Custom.Tags, "Tags has an unexpected value")
 	assert.Nil(t, span.Data.SDK.Custom.Baggage, "Baggage has an unexpected value")
+	assert.Equal(t, "go", span.Lang, "Missing or wrong ta/lang")
 }
 
 func TestSpanHeritage(t *testing.T) {
@@ -101,3 +106,142 @@ func TestSpanTags(t *testing.T) {
 
 	assert.NotNil(t, span.Data.SDK.Custom.Tags, "Missing Tags")
 }
+
+func TestSpanLogFields(t *testing.T) {
+	const op = "test"
+	opts := instana.Options{LogLevel: instana.Debug}
+	recorder := instana.NewTestRecorder()
+	tracer := instana.NewTracerWithEverything(&opts, recorder)
+
+	span := tracer.StartSpan(op)
+	span.LogFields(
+		log.String("event", "soft error"),
+		log.String("type", "cache timeout"),
+		log.Int("waited.millis", 1500))
+	span.Finish()
+
+	spans := recorder.GetSpans()
+	assert.Equal(t, len(spans), 1)
+	firstSpan := spans[0]
+
+	// j, _ := json.MarshalIndent(spans, "", "  ")
+	// fmt.Printf("spans:", bytes.NewBuffer(j))
+
+	logData := firstSpan.Data.SDK.Custom.Logs
+	assert.NotNil(t, logData, "Missing logged fields")
+	assert.Equal(t, 1, len(logData), "Unexpected log count")
+
+	for _, v := range logData {
+		assert.Equal(t, "soft error", v["event"], "Wrong or missing log")
+		assert.Equal(t, "cache timeout", v["type"], "Wrong or missing log")
+		assert.Equal(t, 1500, v["waited.millis"], "Wrong or missing log")
+	}
+}
+
+func TestSpanLogKVs(t *testing.T) {
+	const op = "test"
+	opts := instana.Options{LogLevel: instana.Debug}
+	recorder := instana.NewTestRecorder()
+	tracer := instana.NewTracerWithEverything(&opts, recorder)
+
+	span := tracer.StartSpan(op)
+	span.LogKV(
+		"event", "soft error",
+		"type", "cache timeout",
+		"waited.millis", 1500)
+	span.Finish()
+
+	spans := recorder.GetSpans()
+	assert.Equal(t, len(spans), 1)
+	firstSpan := spans[0]
+
+	// j, _ := json.MarshalIndent(spans, "", "  ")
+	// fmt.Printf("spans:", bytes.NewBuffer(j))
+
+	logData := firstSpan.Data.SDK.Custom.Logs
+	assert.NotNil(t, logData, "Missing logged fields")
+	assert.Equal(t, 1, len(logData), "Unexpected log count")
+
+	for _, v := range logData {
+		assert.Equal(t, "soft error", v["event"], "Wrong or missing log")
+		assert.Equal(t, "cache timeout", v["type"], "Wrong or missing log")
+		assert.Equal(t, 1500, v["waited.millis"], "Wrong or missing log")
+	}
+}
+
+func TestOTLogError(t *testing.T) {
+	const op = "test"
+	opts := instana.Options{LogLevel: instana.Debug}
+	recorder := instana.NewTestRecorder()
+	tracer := instana.NewTracerWithEverything(&opts, recorder)
+
+	span := tracer.StartSpan(op)
+	ext.Error.Set(span, true)
+	span.Finish()
+
+	spans := recorder.GetSpans()
+	assert.Equal(t, len(spans), 1)
+	firstSpan := spans[0]
+
+	logData := firstSpan.Data.SDK.Custom.Logs
+	tagData := firstSpan.Data.SDK.Custom.Tags
+	assert.Equal(t, 1, len(tagData), "Unexpected log count")
+	assert.Equal(t, 1, firstSpan.Ec, "Error count should be 1")
+
+	for _, v := range logData {
+		for sk, sv := range v {
+			fmt.Print(v)
+			assert.Equal(t, "error", sk, "Wrong or missing log")
+			assert.Equal(t, "simulated error", sv, "Wrong or missing log")
+		}
+	}
+}
+
+func TestSpanErrorLogKV(t *testing.T) {
+	const op = "test"
+	opts := instana.Options{LogLevel: instana.Debug}
+	recorder := instana.NewTestRecorder()
+	tracer := instana.NewTracerWithEverything(&opts, recorder)
+
+	span := tracer.StartSpan(op)
+	span.LogKV("error", "simulated error")
+	span.Finish()
+
+	spans := recorder.GetSpans()
+	assert.Equal(t, len(spans), 1)
+	firstSpan := spans[0]
+
+	logData := firstSpan.Data.SDK.Custom.Logs
+	assert.NotNil(t, logData, "Missing logged fields")
+	assert.Equal(t, 1, len(logData), "Unexpected log count")
+	assert.Equal(t, 1, firstSpan.Ec, "Error count should be 1")
+
+	for _, v := range logData {
+		for sk, sv := range v {
+			assert.Equal(t, "error", sk, "Wrong or missing log")
+			assert.Equal(t, "simulated error", sv, "Wrong or missing log")
+		}
+	}
+}
+
+func TestSpanErrorLogFields(t *testing.T) {
+	const op = "test"
+	opts := instana.Options{LogLevel: instana.Debug}
+	recorder := instana.NewTestRecorder()
+	tracer := instana.NewTracerWithEverything(&opts, recorder)
+
+	span := tracer.StartSpan(op)
+
+	err := errors.New("simulated error")
+	span.LogFields(log.Error(err), log.String("function", "TestspanErrorLogFields"))
+	span.LogFields(log.Error(err), log.String("function", "TestspanErrorLogFields"))
+	span.Finish()
+
+	spans := recorder.GetSpans()
+	assert.Equal(t, len(spans), 1)
+	firstSpan := spans[0]
+
+	logData := firstSpan.Data.SDK.Custom.Logs
+	assert.Equal(t, 1, len(logData), "Unexpected tag count")
+	assert.Equal(t, 2, firstSpan.Ec, "Error count should be 2")
+}