diff --git a/go.mod b/go.mod index 1d4e446b..6fae6f2e 100644 --- a/go.mod +++ b/go.mod @@ -20,6 +20,9 @@ require ( require ( github.com/gogo/protobuf v1.3.2 // indirect github.com/stretchr/objx v0.3.0 // indirect + go.opentelemetry.io/otel v1.3.0 + go.opentelemetry.io/otel/sdk v1.3.0 + go.opentelemetry.io/otel/trace v1.3.0 golang.org/x/sys v0.0.0-20220114195835-da31bd327af9 // indirect google.golang.org/genproto v0.0.0-20220118154757-00ab72f36ad5 // indirect gopkg.in/yaml.v3 v3.0.0-20210107192922-496545a6307b // indirect diff --git a/go.sum b/go.sum index 683061aa..e9f9dc58 100644 --- a/go.sum +++ b/go.sum @@ -29,6 +29,11 @@ github.com/envoyproxy/go-control-plane v0.9.9-0.20210512163311-63b5d3c536b0/go.m github.com/envoyproxy/go-control-plane v0.9.10-0.20210907150352-cf90f659a021/go.mod h1:AFq3mo9L8Lqqiid3OhADV3RfLJnjiw63cSpi+fDTRC0= github.com/envoyproxy/protoc-gen-validate v0.1.0/go.mod h1:iSmxcyjqTsJpI2R4NaDN7+kN2VEUnK/pcBlmesArF7c= github.com/ghodss/yaml v1.0.0/go.mod h1:4dBDuWmgqj2HViK6kFavaiC9ZROes6MMH2rRYeMEF04= +github.com/go-logr/logr v1.2.0/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A= +github.com/go-logr/logr v1.2.1 h1:DX7uPQ4WgAWfoh+NGGlbJQswnYIVvz0SRlLS3rPZQDA= +github.com/go-logr/logr v1.2.1/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A= +github.com/go-logr/stdr v1.2.0 h1:j4LrlVXgrbIWO83mmQUnK0Hi+YnbD+vzrE1z/EphbFE= +github.com/go-logr/stdr v1.2.0/go.mod h1:YkVgnZu1ZjjL7xTxrfm/LLZBfkhTqSR1ydtm6jTKKwI= github.com/gogo/protobuf v1.3.1 h1:DqDEcV5aeaTmdFBePNpYsp3FlcVH/2ISVVM9Qf8PSls= github.com/gogo/protobuf v1.3.1/go.mod h1:SlYgWuQ5SjCEi6WLHjHCa1yvBfUnHcTbrrZtXPKa29o= github.com/gogo/protobuf v1.3.2 h1:Ov1cvc58UF3b5XjBnZv7+opcTcQFZebYjWzi34vdm4Q= @@ -54,8 +59,9 @@ github.com/google/go-cmp v0.3.0/go.mod h1:8QqcDgzrUqlUb/G2PQTWiueGozuR1884gddMyw github.com/google/go-cmp v0.3.1/go.mod h1:8QqcDgzrUqlUb/G2PQTWiueGozuR1884gddMywk6iLU= github.com/google/go-cmp v0.4.0/go.mod h1:v8dTdLbMG2kIc/vJvl+f65V22dbkXbowE6jgT/gNBxE= github.com/google/go-cmp v0.5.0/go.mod h1:v8dTdLbMG2kIc/vJvl+f65V22dbkXbowE6jgT/gNBxE= -github.com/google/go-cmp v0.5.5 h1:Khx7svrCpmxxtHBq5j2mp/xVjsi8hQMfNLvJFAlrGgU= github.com/google/go-cmp v0.5.5/go.mod h1:v8dTdLbMG2kIc/vJvl+f65V22dbkXbowE6jgT/gNBxE= +github.com/google/go-cmp v0.5.6 h1:BKbKCqvP6I+rmFHt06ZmyQtvB8xAkWdhFyr0ZUNZcxQ= +github.com/google/go-cmp v0.5.6/go.mod h1:v8dTdLbMG2kIc/vJvl+f65V22dbkXbowE6jgT/gNBxE= github.com/google/uuid v1.1.2/go.mod h1:TIyPZe4MgqvfeYDBFedMoGGpEw/LqOeaOT+nhxU+yHo= github.com/grpc-ecosystem/grpc-gateway v1.16.0/go.mod h1:BDjrQk3hbvj6Nolgz8mAMFbcEtjT1g+wF4CSlocrBnw= github.com/hashicorp/go-version v1.3.0 h1:McDWVJIU/y+u1BRV06dPaLfLCaT7fUTJLp5r04x7iNw= @@ -83,6 +89,12 @@ github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UV github.com/stretchr/testify v1.5.1/go.mod h1:5W2xD1RspED5o8YsWQXVCued0rvSQ+mT+I5cxcmMvtA= github.com/stretchr/testify v1.7.0 h1:nwc3DEeHmmLAfoZucVR881uASk0Mfjw8xYJ99tb5CcY= github.com/stretchr/testify v1.7.0/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg= +go.opentelemetry.io/otel v1.3.0 h1:APxLf0eiBwLl+SOXiJJCVYzA1OOJNyAoV8C5RNRyy7Y= +go.opentelemetry.io/otel v1.3.0/go.mod h1:PWIKzi6JCp7sM0k9yZ43VX+T345uNbAkDKwHVjb2PTs= +go.opentelemetry.io/otel/sdk v1.3.0 h1:3278edCoH89MEJ0Ky8WQXVmDQv3FX4ZJ3Pp+9fJreAI= +go.opentelemetry.io/otel/sdk v1.3.0/go.mod h1:rIo4suHNhQwBIPg9axF8V9CA72Wz2mKF1teNrup8yzs= +go.opentelemetry.io/otel/trace v1.3.0 h1:doy8Hzb1RJ+I3yFhtDmwNc7tIyw1tNMOIsyPzp1NOGY= +go.opentelemetry.io/otel/trace v1.3.0/go.mod h1:c/VDhno8888bvQYmbYLqe41/Ldmr/KKunbvWM4/fEjk= github.com/yuin/goldmark v1.1.27/go.mod h1:3hX8gzYuyVAZsxl0MRgGTJEmQBFcNTphYh9decYSb74= github.com/yuin/goldmark v1.2.1/go.mod h1:3hX8gzYuyVAZsxl0MRgGTJEmQBFcNTphYh9decYSb74= go.opentelemetry.io/proto/otlp v0.7.0/go.mod h1:PqfVotwruBrMGOCsRd/89rSnXhoiJIqeYNgFYFoEGnI= @@ -128,6 +140,7 @@ golang.org/x/sys v0.0.0-20200323222414-85ca7c5b95cd/go.mod h1:h1NjWce9XRLGQEsW7w golang.org/x/sys v0.0.0-20200930185726-fdedc70b468f/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/sys v0.0.0-20201119102817-f84b799fce68/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/sys v0.0.0-20210330210617-4fbd30eecc44/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= +golang.org/x/sys v0.0.0-20210423185535-09eb48e85fd7/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/sys v0.0.0-20210510120138-977fb7262007/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.0.0-20210615035016-665e8c7367d1/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.0.0-20211216021012-1d35b9e2eb4e/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= diff --git a/v1/ao/context.go b/v1/ao/context.go index b4ae3989..31921bb3 100644 --- a/v1/ao/context.go +++ b/v1/ao/context.go @@ -2,7 +2,11 @@ package ao -import "context" +import ( + "context" + "github.com/appoptics/appoptics-apm-go/v1/ao/internal/log" + "github.com/appoptics/appoptics-apm-go/v1/ao/internal/reporter" +) type contextKeyT interface{} @@ -19,6 +23,14 @@ func newSpanContext(ctx context.Context, l Span) context.Context { return context.WithValue(ctx, contextSpanKey, l) } +func FromXTraceIDContext(ctx context.Context, xTraceID string) context.Context { + aoCtx, err := reporter.NewContextFromMetadataString(xTraceID) + if err != nil { + log.Warningf("xTrace ID %v is invalid \n", xTraceID) + } + return context.WithValue(ctx, contextSpanKey, contextSpan{aoCtx: aoCtx}) +} + // FromContext returns the Span bound to the context, if any. func FromContext(ctx context.Context) Span { l, ok := fromContext(ctx) diff --git a/v1/ao/exporter.go b/v1/ao/exporter.go new file mode 100644 index 00000000..6b7be102 --- /dev/null +++ b/v1/ao/exporter.go @@ -0,0 +1,202 @@ +package ao // + +import ( + "context" + "encoding/hex" + "fmt" + "strings" + "time" + + "go.opentelemetry.io/otel/attribute" + sdktrace "go.opentelemetry.io/otel/sdk/trace" +) + +type Exporter struct { + shutdownDelay int // number of seconds to sleep when Shutdown is called, to allow spans to send before short test script exits. +} + +const ( + xtraceVersionHeader = "2B" + sampledFlags = "01" + otEventNameKey = "ot.event_name" + otStatusCodeKey = "ot.span_status.code" + otSpanStatusDescKey = "ot.span_status.description" +) + +func fromAttributeValue(attributeValue attribute.Value) interface{} { + switch attributeValue.Type() { + case attribute.STRING: + return attributeValue.AsString() + case attribute.INT64: + return attributeValue.AsInt64() + case attribute.FLOAT64: + return attributeValue.AsFloat64() + case attribute.BOOL: + return attributeValue.AsBool() + case attribute.STRINGSLICE: + return attributeValue.AsStringSlice() + case attribute.INT64SLICE: + return attributeValue.AsInt64Slice() + case attribute.FLOAT64SLICE: + return attributeValue.AsFloat64Slice() + case attribute.BOOLSLICE: + return attributeValue.AsBoolSlice() + default: + return nil + } +} + +var wsKeyMap = map[string]string{ + "http.method": "HTTPMethod", + "http.url": "URL", + "http.status_code": "Status", +} +var queryKeyMap = map[string]string{ + "db.connection_string": "RemoteHost", + "db.name": "Database", + "db.statement": "Query", + "db.system": "Flavor", +} + +func extractWebserverKvs(span sdktrace.ReadOnlySpan) []interface{} { + return extractSpecKvs(span, wsKeyMap, "ws") +} + +func extractQueryKvs(span sdktrace.ReadOnlySpan) []interface{} { + return extractSpecKvs(span, queryKeyMap, "query") +} + +func extractSpecKvs(span sdktrace.ReadOnlySpan, lookup map[string]string, specValue string) []interface{} { + attrMap := span.Attributes() + result := []interface{}{} + for otKey, aoKey := range lookup { + for _, attr := range attrMap { + if string(attr.Key) == otKey { + result = append(result, aoKey) + result = append(result, fromAttributeValue(attr.Value)) + } + } + } + if len(result) > 0 { + result = append(result, "Spec") + result = append(result, specValue) + } + return result +} + +func extractKvs(span sdktrace.ReadOnlySpan) []interface{} { + var kvs []interface{} + for _, attributeValue := range span.Attributes() { + if _, ok := wsKeyMap[string(attributeValue.Key)]; ok { // in wsKeyMap, skip it and handle later + continue + } + if _, ok := queryKeyMap[string(attributeValue.Key)]; ok { // in queryKeyMap, skip it and handle later + continue + } + // all other keys + kvs = append(kvs, string(attributeValue.Key)) + kvs = append(kvs, fromAttributeValue(attributeValue.Value)) + } + + spanStatus := span.Status() + kvs = append(kvs, otStatusCodeKey) + kvs = append(kvs, uint32(spanStatus.Code)) + if spanStatus.Code == 1 { // if the span status code is an error, send the description. otel will ignore the description on any other status code + kvs = append(kvs, otSpanStatusDescKey) + kvs = append(kvs, spanStatus.Description) + } + if !span.Parent().IsValid() { // root span, attempt to extract webserver KVs + kvs = append(kvs, extractWebserverKvs(span)...) + } + kvs = append(kvs, extractQueryKvs(span)...) + + return kvs +} + +func extractInfoEvents(span sdktrace.ReadOnlySpan) [][]interface{} { + events := span.Events() + kvs := make([][]interface{}, len(events)) + + for i, event := range events { + kvs[i] = make([]interface{}, 0) + kvs[i] = append(kvs[i], otEventNameKey) + kvs[i] = append(kvs[i], string(event.Name)) + for _, attr := range event.Attributes { + kvs[i] = append(kvs[i], string(attr.Key)) + kvs[i] = append(kvs[i], fromAttributeValue(attr.Value)) + } + } + + return kvs +} + +func getXTraceID(traceID []byte, spanID []byte) string { + taskId := strings.ToUpper(strings.ReplaceAll(fmt.Sprintf("%0-40v", hex.EncodeToString(traceID)), " ", "0")) + opId := strings.ToUpper(strings.ReplaceAll(fmt.Sprintf("%0-16v", hex.EncodeToString(spanID)), " ", "0")) + return xtraceVersionHeader + taskId + opId + sampledFlags +} + +func exportSpan(ctx context.Context, s sdktrace.ReadOnlySpan) { + traceID := s.SpanContext().TraceID() + spanID := s.SpanContext().SpanID() + xTraceID := getXTraceID(traceID[:], spanID[:]) + + startOverrides := Overrides{ + ExplicitTS: s.StartTime(), + ExplicitMdStr: xTraceID, + } + + endOverrides := Overrides{ + ExplicitTS: s.EndTime(), + } + + kvs := extractKvs(s) + + infoEvents := extractInfoEvents(s) + + if s.Parent().IsValid() { // this is a child span, not a start of a trace but rather a continuation of an existing one + parentSpanID := s.Parent().SpanID() + parentXTraceID := getXTraceID(traceID[:], parentSpanID[:]) + traceContext := FromXTraceIDContext(ctx, parentXTraceID) + aoSpan, _ := BeginSpanWithOverrides(traceContext, s.Name(), SpanOptions{}, startOverrides) + + // report otel Span Events as AO Info KVs + for _, infoEventKvs := range infoEvents { + aoSpan.InfoWithOverrides(Overrides{ExplicitTS: s.StartTime()}, SpanOptions{}, infoEventKvs...) + } + + aoSpan.EndWithOverrides(endOverrides, kvs...) + } else { // no parent means this is the beginning of the trace (root span) + trace := NewTraceWithOverrides(s.Name(), startOverrides, nil) + trace.SetStartTime(s.StartTime()) //this is for histogram only + + // report otel Span Events as AO Info KVs + for _, infoEventKvs := range infoEvents { + trace.InfoWithOverrides(Overrides{ExplicitTS: s.StartTime()}, SpanOptions{}, infoEventKvs...) + } + trace.EndWithOverrides(endOverrides, kvs...) + } +} + +func (e *Exporter) ExportSpans(ctx context.Context, spans []sdktrace.ReadOnlySpan) error { + WaitForReady(ctx) + for _, s := range spans { + exportSpan(ctx, s) + } + return nil +} + +func (e *Exporter) Shutdown(ctx context.Context) error { + // Most applications should never set this value, it is only useful for testing short running (cli) scripts. + if e.shutdownDelay != 0 { + time.Sleep(time.Duration(e.shutdownDelay) * time.Second) + } + + Shutdown(ctx) + return nil +} + +// NewExporter creates an instance of the Solarwinds AppOptics exporter for OTEL traces. +func NewExporter(shutdownDelay int) *Exporter { + return &Exporter{shutdownDelay: shutdownDelay} +} diff --git a/v1/ao/exporter_test.go b/v1/ao/exporter_test.go new file mode 100644 index 00000000..d473bab3 --- /dev/null +++ b/v1/ao/exporter_test.go @@ -0,0 +1,322 @@ +package ao + +import ( + "context" + "encoding/hex" + "fmt" + "strings" + "testing" + + "github.com/stretchr/testify/require" + "go.opentelemetry.io/otel" + "go.opentelemetry.io/otel/attribute" + "go.opentelemetry.io/otel/sdk/trace" + sdktrace "go.opentelemetry.io/otel/sdk/trace" + ot "go.opentelemetry.io/otel/trace" +) + +func setup() (ot.Tracer, func()) { + tp := trace.NewTracerProvider( + trace.WithBatcher(NewDummyExporter()), + trace.WithSampler(NewDummySampler()), + ) + otel.SetTracerProvider(tp) + tr := otel.Tracer("foo123", ot.WithInstrumentationVersion("123"), ot.WithSchemaURL("https://www.schema.url/foo123")) + + return tr, func() { + if err := tp.Shutdown(context.Background()); err != nil { + fmt.Println(err) + } + } +} + +type DummySampler struct{} + +func (ds *DummySampler) ShouldSample(parameters trace.SamplingParameters) trace.SamplingResult { + return trace.SamplingResult{ + Decision: trace.RecordAndSample, + } +} + +func (ds *DummySampler) Description() string { + return "Dummy Sampler" +} + +func NewDummySampler() trace.Sampler { + return &DummySampler{} +} + +type DummyExporter struct{} + +func NewDummyExporter() *DummyExporter { + return &DummyExporter{} +} + +func (de *DummyExporter) ExportSpans(ctx context.Context, spans []sdktrace.ReadOnlySpan) error { + return nil +} + +func (de *DummyExporter) Shutdown(ctx context.Context) error { + return nil +} + +func Test_extractKvs_Basic(t *testing.T) { + tr, teardown := setup() + defer teardown() + _, sp := tr.Start(context.Background(), "ROOT SPAN NAME aaaa") + sp.SetName("span name") + + priority_val := "high" + priority := attribute.Key("some.priority") + answers := attribute.Key("some.answers-bool-slice") + + boolSlice := []bool{true, false} + + sp.SetAttributes(priority.String(priority_val), answers.BoolSlice(boolSlice)) + sp.SetStatus(1, "uh oh, problem!") // when the status code is an error, a description "uh oh, problem!" will be inserted into the span as well + /* Possible otel status codes, see otel/codes.go + + Unset Code = 0 + + // Error indicates the operation contains an error. + Error Code = 1 + + // Ok indicates operation has been validated by an Application developers + // or Operator to have completed successfully, or contain no error. + Ok Code = 2 + */ + + sp.End() + + kvs := extractKvs(sp.(trace.ReadOnlySpan)) + + require.Equal(t, len(kvs), 8, "kvs length didn't match") + require.Equal(t, kvs[0], string(priority), "kvs[0] didn't match") + require.Equal(t, kvs[1], priority_val, "kvs[1] didn't match") + require.Equal(t, kvs[2], string(answers), "kvs[2] didn't match") + require.Equal(t, kvs[3], boolSlice, "kvs[3] didn't match") + require.Equal(t, kvs[4], otStatusCodeKey, "kvs[4] didn't match") + require.Equal(t, kvs[5], uint32(1), "kvs[5] didn't match") + require.Equal(t, kvs[6], otSpanStatusDescKey, "kvs[6] didn't match") // description will now be present since the status code was 1 == Error + require.Equal(t, kvs[7], "uh oh, problem!", "kvs[7] didn't match") +} + +func Test_extractKvs_WS_Basic(t *testing.T) { + tr, teardown := setup() + defer teardown() + _, sp := tr.Start(context.Background(), "ROOT SPAN NAME aaaa") + sp.SetName("span name") + + attrs := make([]attribute.KeyValue, len(wsKeyMap)) + for k := range wsKeyMap { + var attr attribute.KeyValue + if k == "http.status_code" { + attr = attribute.KeyValue(attribute.Int(k, 200)) + } else { + attr = attribute.KeyValue(attribute.String(k, "value for "+k)) + } + attrs = append(attrs, attr) + } + sp.SetAttributes(attrs...) + sp.End() + kvs := extractKvs(sp.(trace.ReadOnlySpan)) + + require.Equal(t, 10, len(kvs), "kvs length didn't match") + for idx, v := range kvs { + if v == "Status" { + require.Equal(t, kvs[idx+1], int64(200), "status code should be 200") + } + if v == "Spec" { + require.Equal(t, kvs[idx+1], "ws", "spec should be ws") + } + + } +} + +func Test_extractKvs_Empty(t *testing.T) { + tr, teardown := setup() + defer teardown() + _, sp := tr.Start(context.Background(), "ROOT SPAN NAME aaaa") + sp.SetName("span name") + + attrs := make([]attribute.KeyValue, 0) + sp.SetAttributes(attrs...) + + kvs := extractKvs(sp.(trace.ReadOnlySpan)) + + require.Equal(t, len(kvs), 2, "kvs length didn't match") // its 2 and not 0 because we always add otStatusCodeKey and it's value + require.Equal(t, kvs[0], otStatusCodeKey, "ot status code key didn't match") + require.Equal(t, kvs[1], uint32(0), "status code didn't match") +} + +func Test_extractInfoEvents(t *testing.T) { + tr, teardown := setup() + defer teardown() + _, sp := tr.Start(context.Background(), "ROOT SPAN NAME aaaa") + sp.SetName("span name") + + float64attr := attribute.Key("some.float64-slice") + stringslice := attribute.Key("some.string-slice") + sp.SetAttributes(float64attr.Float64Slice([]float64{2.3490, 3.14159, 0.49581}), stringslice.StringSlice([]string{"string1", "string2", "string3"})) + + sp.AddEvent("auth", ot.WithAttributes(attribute.String("username", "joe"), attribute.Int("uid", 100))) + sp.AddEvent("buy", ot.WithAttributes(attribute.String("product", "iPhone"), attribute.Float64("price", 799.99))) + sp.AddEvent("unsubscribe", ot.WithAttributes(attribute.String("mailing-list-id", "list1"), attribute.Bool("eula-read", true))) + + slInt64 := []int64{-1337, 30, 2, 30000, 45} + sp.AddEvent("test-int64-slice-event", ot.WithAttributes(attribute.Int64Slice("int64-slice-key", slInt64))) + slString := []string{"s1", "s2", "s3", "s4"} + sp.AddEvent("test-string-slice-event", ot.WithAttributes(attribute.StringSlice("string-slice-key", slString))) + slBool := []bool{true, false, false, true} + sp.AddEvent("test-bool-slice-event", ot.WithAttributes(attribute.BoolSlice("bool-slice-key", slBool))) + slFloat64 := []float64{-3.14159, 300.30409, 2, 2.0, 2.001} + sp.AddEvent("test-float64-slice-event", ot.WithAttributes(attribute.Float64Slice("float64-slice-key", slFloat64))) + sp.SetStatus(2, "all good!") // description is ignored if the status is not an error + sp.End() + + kvs := extractKvs(sp.(trace.ReadOnlySpan)) + require.Equal(t, len(kvs), 6, "kvs length mismatch") + + infoEvents := extractInfoEvents(sp.(trace.ReadOnlySpan)) + require.Equal(t, len(infoEvents), 7, "infoEvents length mismatch") + + require.Equal(t, infoEvents[0][0], otEventNameKey, "ot event key mismatch") + require.Equal(t, infoEvents[0][1], "auth", "first event name mismatch") + require.Equal(t, infoEvents[0][2], "username", "attribute 1 key mismatch") + require.Equal(t, infoEvents[0][3], "joe", "attribute 1 value mismatch") + require.Equal(t, infoEvents[0][4], "uid", "attribute 2 key mismatch") + // even though we set the "uid" value to int 100 above, otel converts int to int64, see: otel/attribute/value/IntValue in value.go + require.Equal(t, infoEvents[0][5], int64(100), "attribute 2 value mismatch") + + require.Equal(t, infoEvents[1][0], otEventNameKey, "ot event key mismatch") + require.Equal(t, infoEvents[1][1], "buy", "second event name mismatch") + require.Equal(t, infoEvents[1][2], "product", "second event, attribute 1 key mismatch") + require.Equal(t, infoEvents[1][3], "iPhone", "second event, attribute 1 value mismatch") + require.Equal(t, infoEvents[1][4], "price", "second event, attribute 2 key mismatch") + require.Equal(t, infoEvents[1][5], float64(799.99), "second event, attribute 2 value mismatch") + + require.Equal(t, infoEvents[2][0], otEventNameKey, "ot event key mismatch") + require.Equal(t, infoEvents[2][1], "unsubscribe", "third event name mismatch") + require.Equal(t, infoEvents[2][2], "mailing-list-id", "third event, attribute 1 key mismatch") + require.Equal(t, infoEvents[2][3], "list1", "third event, attribute 1 value mismatch") + require.Equal(t, infoEvents[2][4], "eula-read", "third event, attribute 2 key mismatch") + require.Equal(t, infoEvents[2][5], true, "third event, attribute 2 value mismatch") + + // Test slice data types + require.Equal(t, infoEvents[3][0], otEventNameKey, "ot event key mismatch") + require.Equal(t, infoEvents[3][1], "test-int64-slice-event", "int64 slice event name mismatch") + require.Equal(t, infoEvents[3][2], "int64-slice-key", "int64 slice key mismatch") + require.Equal(t, infoEvents[3][3], slInt64, "int64 slice values mismatch") + + require.Equal(t, infoEvents[4][0], otEventNameKey, "ot event key mismatch") + require.Equal(t, infoEvents[4][1], "test-string-slice-event", "string slice event name mismatch") + require.Equal(t, infoEvents[4][2], "string-slice-key", "string slice key mismatch") + require.Equal(t, infoEvents[4][3], slString, "string slice values mismatch") + + require.Equal(t, infoEvents[5][0], otEventNameKey, "ot event key mismatch") + require.Equal(t, infoEvents[5][1], "test-bool-slice-event", "bool slice event name mismatch") + require.Equal(t, infoEvents[5][2], "bool-slice-key", "bool slice key mismatch") + require.Equal(t, infoEvents[5][3], slBool, "bool slice values mismatch") + + require.Equal(t, infoEvents[6][0], otEventNameKey, "ot event key mismatch") + require.Equal(t, infoEvents[6][1], "test-float64-slice-event", "float64 slice event name mismatch") + require.Equal(t, infoEvents[6][2], "float64-slice-key", "float64 slice key mismatch") + require.Equal(t, infoEvents[6][3], slFloat64, "float64 slice values mismatch") + + // fmt.Println("infoEvents") + // for idx, v := range infoEvents { + // fmt.Println("idx:", idx) + // for k2, v2 := range v { + // fmt.Println("\tidx:", k2, " v:", v2) + // } + // } +} + +func Test_extractKvs_WS_NotRootSpan(t *testing.T) { + tr, teardown := setup() + defer teardown() + ctx, sp := tr.Start(context.Background(), "ROOT SPAN NAME aaaa") + sp.SetName("span name") + sp.End() + + kvs := extractKvs(sp.(trace.ReadOnlySpan)) + + require.Equal(t, len(kvs), 2, "kvs length didn't match") + + // Check to make sure that we do not read webserver keys from child spans, only from root span! + _, sp2 := tr.Start(ctx, "child span") + attrs := make([]attribute.KeyValue, len(wsKeyMap)) + for k := range wsKeyMap { + var attr attribute.KeyValue + if k == "http.status_code" { + attr = attribute.KeyValue(attribute.Int(k, 200)) + } else { + attr = attribute.KeyValue(attribute.String(k, "value for "+k)) + } + attrs = append(attrs, attr) + } + sp2.SetAttributes(attrs...) + + kvs = extractKvs(sp2.(trace.ReadOnlySpan)) + + require.Equal(t, len(kvs), 2, "kvs length didn't match") + for idx, v := range kvs { + if v == "Status" { + require.Equal(t, kvs[idx+1], int64(200), "status code should be 200") + break + } + } +} + +func Test_extractKvs_Query_Basic(t *testing.T) { + tr, teardown := setup() + defer teardown() + _, sp := tr.Start(context.Background(), "ROOT SPAN NAME aaaa") + sp.SetName("span name") + + // "db.connection_string": "RemoteHost", + // "db.name": "Database", + // "db.statement": "Query", + // "db.system": "Flavor", + + attrs := make([]attribute.KeyValue, len(queryKeyMap)) + for k := range queryKeyMap { + attr := attribute.KeyValue(attribute.String(k, "value for "+k)) + attrs = append(attrs, attr) + } + sp.SetAttributes(attrs...) + sp.End() + kvs := extractKvs(sp.(trace.ReadOnlySpan)) + require.Equal(t, 12, len(kvs), "kvs length didn't match") + + found := 0 + // ensure all queryKeyMap keys are found in the kvs produced since we populated them all above when creating the span attributes + for _, queryKey := range queryKeyMap { + for _, v := range kvs { + if queryKey == v { + found++ + } + } + } + require.Equal(t, len(queryKeyMap), found, "should find all queryKeyMap keys in extracted kvs") + + // ensure we have the Spec key that's set to query + for idx, v := range kvs { + if v == "Spec" { + require.Equal(t, "query", kvs[idx+1], "spec should be query") + break + } + } +} + +func Test_getXTraceID(t *testing.T) { + var traceID ot.TraceID + var spanID ot.SpanID + + traceID = [16]byte{1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16} + spanID = [8]byte{1, 2, 3, 4, 5, 6, 7, 8} + xTraceID := getXTraceID(traceID[:], spanID[:]) + //2B 0102030405060708090A0B0C0D0E0F10 00000000 0102030405060708 01 + expectedXTraceID := strings.ToUpper(xtraceVersionHeader + hex.EncodeToString(traceID[:]) + "00000000" + hex.EncodeToString(spanID[:]) + sampledFlags) + require.Equal(t, expectedXTraceID, xTraceID, "xTraceID should be equal") +} diff --git a/v1/ao/internal/bson/bson.go b/v1/ao/internal/bson/bson.go index c75407c4..113051c6 100644 --- a/v1/ao/internal/bson/bson.go +++ b/v1/ao/internal/bson/bson.go @@ -2,7 +2,9 @@ package bson -import "math" +import ( + "math" +) type Buffer struct { buf []byte diff --git a/v1/ao/internal/reporter/context.go b/v1/ao/internal/reporter/context.go index 82f96d3d..1fe54d4d 100644 --- a/v1/ao/internal/reporter/context.go +++ b/v1/ao/internal/reporter/context.go @@ -82,6 +82,11 @@ type transactionContext struct { type KVMap map[string]interface{} +type Overrides struct { + ExplicitTS time.Time + ExplicitMdStr string +} + // ContextOptions defines the options of creating a context. type ContextOptions struct { // MdStr is the string representation of the X-Trace ID. @@ -90,10 +95,11 @@ type ContextOptions struct { URL string // XTraceOptions represents the X-Trace-Options header. XTraceOptions string + // CB is the callback function to produce the KVs. // XTraceOptionsSignature represents the X-Trace-Options-Signature header. XTraceOptionsSignature string - // CB is the callback function to produce the KVs. - CB func() KVMap + Overrides Overrides + CB func() KVMap } // ValidMetadata checks if a metadata string is valid. @@ -320,6 +326,7 @@ func (md *oboeMetadata) isSampled() bool { // A Context is an oboe context that may or not be tracing. type Context interface { ReportEvent(label Label, layer string, args ...interface{}) error + ReportEventWithOverrides(label Label, layer string, overrides Overrides, args ...interface{}) error ReportEventMap(label Label, layer string, keys map[string]interface{}) error Copy() Context IsSampled() bool @@ -346,6 +353,11 @@ type nullEvent struct{} func (e *nullContext) ReportEvent(label Label, layer string, args ...interface{}) error { return nil } + +func (e *nullContext) ReportEventWithOverrides(label Label, layer string, overrides Overrides, args ...interface{}) error { + return nil +} + func (e *nullContext) ReportEventMap(label Label, layer string, keys map[string]interface{}) error { return nil } @@ -377,7 +389,7 @@ func newContext(sampled bool) Context { return ctx } -func newContextFromMetadataString(mdstr string) (*oboeContext, error) { +func NewContextFromMetadataString(mdstr string) (*oboeContext, error) { ctx := &oboeContext{txCtx: &transactionContext{enabled: true}} ctx.metadata.Init() err := ctx.metadata.FromString(mdstr) @@ -538,6 +550,7 @@ func NewContext(layer string, reportEntry bool, opts ContextOptions, traced := false addCtxEdge := false + explicitTraceDecision := false tMode, tKVs, tIgnoredKeys, authErr := parseTriggerTraceFlag(opts.XTraceOptions, opts.XTraceOptionsSignature) @@ -579,11 +592,13 @@ func NewContext(layer string, reportEntry bool, opts ContextOptions, if opts.MdStr != "" { var err error - if ctx, err = newContextFromMetadataString(opts.MdStr); err != nil { - log.Debug("passed in x-trace seems invalid, ignoring") + if ctx, err = NewContextFromMetadataString(opts.MdStr); err != nil { + log.Info("passed in x-trace seems invalid, ignoring") } else if ctx.GetVersion() != xtrCurrentVersion { - log.Debug("passed in x-trace has wrong version, ignoring") + log.Info("passed in x-trace has wrong version, ignoring") } else if ctx.IsSampled() { + ctx.MetadataString() + log.Info("passed in x-trace is sampled") traced = true addCtxEdge = true continuedTrace = true @@ -603,6 +618,23 @@ func NewContext(layer string, reportEntry bool, opts ContextOptions, SetHeaders(ttNotRequested) } + return ctx, true, headers + } + } else if opts.Overrides.ExplicitMdStr != "" { + var err error + //take note that the ctx here will be the same as the entry event + //we might consider randomizing the opID or the set it to zero in the future + //for now we will just disable the opID check in reporter.prepareEvent as the Op ID will be the same + //for context and entry event + if ctx, err = NewContextFromMetadataString(opts.Overrides.ExplicitMdStr); err != nil { + log.Info("passed in x-trace seems invalid, ignoring") + } else if ctx.GetVersion() != xtrCurrentVersion { + log.Info("passed in x-trace has wrong version, ignoring") + } else if ctx.IsSampled() { + log.Info("passed in x-trace is sampled") + traced = true + explicitTraceDecision = true + } else { return ctx, true, headers } } @@ -611,7 +643,12 @@ func NewContext(layer string, reportEntry bool, opts ContextOptions, ctx = newContext(true) } - decision := shouldTraceRequestWithURL(layer, traced, opts.URL, tMode) + var decision SampleDecision + if explicitTraceDecision { + decision = SampleDecision{trace: true} + } else { + decision = shouldTraceRequestWithURL(layer, traced, opts.URL, tMode) + } ctx.SetEnabled(decision.enabled) if decision.trace { @@ -641,7 +678,7 @@ func NewContext(layer string, reportEntry bool, opts ContextOptions, if _, ok = ctx.(*oboeContext); !ok { return &nullContext{}, false, headers } - if err := ctx.(*oboeContext).reportEventMap(LabelEntry, layer, addCtxEdge, kvs); err != nil { + if err := ctx.(*oboeContext).reportEventMapWithOverrides(LabelEntry, layer, addCtxEdge, opts.Overrides, kvs); err != nil { return &nullContext{}, false, headers } } @@ -654,6 +691,7 @@ func NewContext(layer string, reportEntry bool, opts ContextOptions, SetHeaders(decision.xTraceOptsRsp) return ctx, true, headers + } func (ctx *oboeContext) Copy() Context { @@ -695,11 +733,15 @@ func (ctx *oboeContext) GetTransactionName() string { } func (ctx *oboeContext) newEvent(label Label, layer string) (*event, error) { - return newEvent(&ctx.metadata, label, layer) + return newEvent(&ctx.metadata, label, layer, "") +} + +func (ctx *oboeContext) newEventWithExplicitID(label Label, layer string, xTraceID string) (*event, error) { + return newEvent(&ctx.metadata, label, layer, xTraceID) } func (ctx *oboeContext) NewEvent(label Label, layer string, addCtxEdge bool) Event { - e, err := newEvent(&ctx.metadata, label, layer) + e, err := newEvent(&ctx.metadata, label, layer, "") if err != nil { return &nullEvent{} } @@ -718,40 +760,55 @@ func (ctx *oboeContext) ReportEventMap(label Label, layer string, keys map[strin return ctx.reportEventMap(label, layer, true, keys) } -func (ctx *oboeContext) reportEventMap(label Label, layer string, addCtxEdge bool, keys map[string]interface{}) error { +func (ctx *oboeContext) reportEventMapWithOverrides(label Label, layer string, addCtxEdge bool, overrides Overrides, keys map[string]interface{}) error { var args []interface{} for k, v := range keys { args = append(args, k) args = append(args, v) } - return ctx.reportEvent(label, layer, addCtxEdge, args...) + return ctx.reportEventWithOverrides(label, layer, addCtxEdge, overrides, args...) +} + +func (ctx *oboeContext) reportEventMap(label Label, layer string, addCtxEdge bool, keys map[string]interface{}) error { + return ctx.reportEventMapWithOverrides(label, layer, addCtxEdge, Overrides{}, keys) } // Create and report an event using KVs from variadic args func (ctx *oboeContext) ReportEvent(label Label, layer string, args ...interface{}) error { - return ctx.reportEvent(label, layer, true, args...) + return ctx.reportEventWithOverrides(label, layer, true, Overrides{}, args...) +} + +func (ctx *oboeContext) ReportEventWithOverrides(label Label, layer string, overrides Overrides, args ...interface{}) error { + return ctx.reportEventWithOverrides(label, layer, true, overrides, args...) } -// Create and report an event using KVs from variadic args func (ctx *oboeContext) reportEvent(label Label, layer string, addCtxEdge bool, args ...interface{}) error { + return ctx.reportEventWithOverrides(label, layer, addCtxEdge, Overrides{}, args) +} + +// Create and report an event using KVs from variadic args +func (ctx *oboeContext) reportEventWithOverrides(label Label, layer string, addCtxEdge bool, overrides Overrides, args ...interface{}) error { // create new event from context - e, err := ctx.newEvent(label, layer) + e, err := ctx.newEventWithExplicitID(label, layer, overrides.ExplicitMdStr) if err != nil { // error creating event (e.g. couldn't init random IDs) return err } - return ctx.report(e, addCtxEdge, args...) + + return ctx.report(e, addCtxEdge, overrides, args...) } // report an event using KVs from variadic args -func (ctx *oboeContext) report(e *event, addCtxEdge bool, args ...interface{}) error { +func (ctx *oboeContext) report(e *event, addCtxEdge bool, overrides Overrides, args ...interface{}) error { for i := 0; i+1 < len(args); i += 2 { if err := e.AddKV(args[i], args[i+1]); err != nil { return err } } + if addCtxEdge { e.AddEdge(ctx) } + e.overrides = overrides // report event return e.Report(ctx) } diff --git a/v1/ao/internal/reporter/event.go b/v1/ao/internal/reporter/event.go index d2016b34..33bbb26a 100644 --- a/v1/ao/internal/reporter/event.go +++ b/v1/ao/internal/reporter/event.go @@ -9,6 +9,7 @@ import ( "errors" "fmt" "math" + "strconv" "github.com/appoptics/appoptics-apm-go/v1/ao/internal/bson" "github.com/appoptics/appoptics-apm-go/v1/ao/internal/config" @@ -16,8 +17,9 @@ import ( ) type event struct { - metadata oboeMetadata - bbuf *bson.Buffer + metadata oboeMetadata + overrides Overrides + bbuf *bson.Buffer } // Label is a required event attribute. @@ -149,7 +151,7 @@ func (tm tracingMode) ToString() string { } } -func oboeEventInit(evt *event, md *oboeMetadata) error { +func oboeEventInit(evt *event, md *oboeMetadata, explicitXTraceId string) error { if evt == nil || md == nil { return errors.New("oboeEventInit got nil args") } @@ -157,14 +159,17 @@ func oboeEventInit(evt *event, md *oboeMetadata) error { // Metadata initialization evt.metadata.Init() - evt.metadata.taskLen = md.taskLen - evt.metadata.opLen = md.opLen - - copy(evt.metadata.ids.taskID, md.ids.taskID) - if err := evt.metadata.SetRandomOpID(); err != nil { - return err + if explicitXTraceId == "" { + evt.metadata.taskLen = md.taskLen + evt.metadata.opLen = md.opLen + if err := evt.metadata.SetRandomOpID(); err != nil { + return err + } + copy(evt.metadata.ids.taskID, md.ids.taskID) + evt.metadata.flags = md.flags + } else { + evt.metadata.FromString(explicitXTraceId) } - evt.metadata.flags = md.flags // Buffer initialization evt.bbuf = bson.NewBuffer() @@ -181,9 +186,9 @@ func oboeEventInit(evt *event, md *oboeMetadata) error { return nil } -func newEvent(md *oboeMetadata, label Label, layer string) (*event, error) { +func newEvent(md *oboeMetadata, label Label, layer string, explicitXTraceID string) (*event, error) { e := &event{} - if err := oboeEventInit(e, md); err != nil { + if err := oboeEventInit(e, md, explicitXTraceID); err != nil { return nil, err } e.addLabelLayer(label, layer) @@ -228,6 +233,38 @@ func (e *event) AddEdge(ctx *oboeContext) { e.bbuf.AppendString(EdgeKey, ctx.metadata.opString()) } +func (e *event) AddInt64Slice(key string, values []int64) { + start := e.bbuf.AppendStartArray(key) + for i, value := range values { + e.bbuf.AppendInt64(strconv.Itoa(i), value) + } + e.bbuf.AppendFinishObject(start) +} + +func (e *event) AddStringSlice(key string, values []string) { + start := e.bbuf.AppendStartArray(key) + for i, value := range values { + e.bbuf.AppendString(strconv.Itoa(i), value) + } + e.bbuf.AppendFinishObject(start) +} + +func (e *event) AddFloat64Slice(key string, values []float64) { + start := e.bbuf.AppendStartArray(key) + for i, value := range values { + e.bbuf.AppendFloat64(strconv.Itoa(i), value) + } + e.bbuf.AppendFinishObject(start) +} + +func (e *event) AddBoolSlice(key string, values []bool) { + start := e.bbuf.AppendStartArray(key) + for i, value := range values { + e.bbuf.AppendBool(strconv.Itoa(i), value) + } + e.bbuf.AppendFinishObject(start) +} + func (e *event) AddEdgeFromMetadataString(mdstr string) { var md oboeMetadata md.Init() @@ -338,6 +375,22 @@ func (e *event) AddKV(key, value interface{}) error { if v != nil { e.AddBool(k, *v) } + case []int64: + if v != nil { + e.AddInt64Slice(k, v) + } + case []string: + if v != nil { + e.AddStringSlice(k, v) + } + case []float64: + if v != nil { + e.AddFloat64Slice(k, v) + } + case []bool: + if v != nil { + e.AddBoolSlice(k, v) + } default: log.Debugf("Ignoring unrecognized Event key %v val %v valType %T", k, v, v) } @@ -363,7 +416,7 @@ func (e *event) ReportStatus(c *oboeContext) error { return e.ReportUsing(c, glo // Report event using Context interface func (e *event) ReportContext(c Context, addCtxEdge bool, args ...interface{}) error { if ctx, ok := c.(*oboeContext); ok { - return ctx.report(e, addCtxEdge, args...) + return ctx.report(e, addCtxEdge, Overrides{}, args...) } return nil } diff --git a/v1/ao/internal/reporter/event_test.go b/v1/ao/internal/reporter/event_test.go index f459782a..881aec7d 100644 --- a/v1/ao/internal/reporter/event_test.go +++ b/v1/ao/internal/reporter/event_test.go @@ -105,13 +105,13 @@ func TestOboeEvent(t *testing.T) { // oboe_event_init evt := &event{} var md, emptyMd oboeMetadata - assert.Error(t, oboeEventInit(nil, nil)) // init nil evt, md - assert.Error(t, oboeEventInit(evt, nil)) // init evt, nil md - assert.Error(t, oboeEventInit(evt, &emptyMd)) // init evt, uninit'd md - md.Init() // init valid md - assert.NoError(t, md.SetRandom()) // make random md + assert.Error(t, oboeEventInit(nil, nil, "")) // init nil evt, md + assert.Error(t, oboeEventInit(evt, nil, "")) // init evt, nil md + assert.Error(t, oboeEventInit(evt, &emptyMd, "")) // init evt, uninit'd md + md.Init() // init valid md + assert.NoError(t, md.SetRandom()) // make random md t.Logf("TestEvent md: %v", md.String()) - assert.NoError(t, oboeEventInit(evt, &md)) // init valid evt, md + assert.NoError(t, oboeEventInit(evt, &md, "")) // init valid evt, md assert.Equal(t, evt.metadata.ids.taskID, md.ids.taskID) // task IDs should match assert.NotEqual(t, evt.metadata.ids.opID, md.ids.opID) // op IDs should not match assert.Len(t, evt.MetadataString(), oboeMetadataStringLen) // event md string correct length diff --git a/v1/ao/internal/reporter/oboe.go b/v1/ao/internal/reporter/oboe.go index 9934f8e1..781b644f 100644 --- a/v1/ao/internal/reporter/oboe.go +++ b/v1/ao/internal/reporter/oboe.go @@ -63,7 +63,7 @@ func (s *oboeSettings) hasOverrideFlag() bool { func newOboeSettings() *oboeSettings { return &oboeSettings{ - bucket: globalTokenBucket, + bucket: globalTokenBucket, triggerTraceRelaxedBucket: triggerTraceRelaxedBucket, triggerTraceStrictBucket: triggerTraceStrictBucket, } diff --git a/v1/ao/internal/reporter/reporter.go b/v1/ao/internal/reporter/reporter.go index ba2f30b2..f7818bac 100644 --- a/v1/ao/internal/reporter/reporter.go +++ b/v1/ao/internal/reporter/reporter.go @@ -85,7 +85,7 @@ func (r *nullReporter) CustomSummaryMetric(name string, value float64, opts metr func (r *nullReporter) CustomIncrementMetric(name string, opts metrics.MetricOptions) error { return nil } -func (r *nullReporter) Flush() error { return nil } +func (r *nullReporter) Flush() error { return nil } func (r *nullReporter) SetServiceKey(string) {} // init() is called only once on program startup. Here we create the reporter @@ -169,17 +169,28 @@ func prepareEvent(ctx *oboeContext, e *event) error { return errors.New("invalid context, event") } - // The context metadata must have the same task_id as the event. - if !bytes.Equal(ctx.metadata.ids.taskID, e.metadata.ids.taskID) { - return errors.New("invalid event, different task_id from context") + // For now, disable the check if the entry event is using an explicit x-trace ID + // as the current logic in context.NewContext would use the same x-trace ID for + // context as the entry event. Therefore the opID is the same. + if e.overrides.ExplicitMdStr == "" { + // The context metadata must have the same task_id as the event. + if !bytes.Equal(ctx.metadata.ids.taskID, e.metadata.ids.taskID) { + return errors.New("invalid event, different task_id from context") + } + + // The context metadata must have a different op_id than the event. + if bytes.Equal(ctx.metadata.ids.opID, e.metadata.ids.opID) { + return errors.New("invalid event, same as context") + } } - // The context metadata must have a different op_id than the event. - if bytes.Equal(ctx.metadata.ids.opID, e.metadata.ids.opID) { - return errors.New("invalid event, same as context") + var us int64 + if e.overrides.ExplicitTS.IsZero() { + us = time.Now().UnixNano() / 1000 + } else { + us = e.overrides.ExplicitTS.UnixNano() / 1000 } - us := time.Now().UnixNano() / 1000 e.AddInt64("Timestamp_u", us) e.AddString("Hostname", host.Hostname()) @@ -272,4 +283,4 @@ func IncrementMetric(name string, opts metrics.MetricOptions) error { func SetServiceKey(key string) { globalReporter.SetServiceKey(key) -} \ No newline at end of file +} diff --git a/v1/ao/internal/reporter/reporter_grpc.go b/v1/ao/internal/reporter/reporter_grpc.go index 1f508785..7cae7787 100644 --- a/v1/ao/internal/reporter/reporter_grpc.go +++ b/v1/ao/internal/reporter/reporter_grpc.go @@ -33,10 +33,10 @@ import ( "github.com/appoptics/appoptics-apm-go/v1/ao/internal/log" "github.com/appoptics/appoptics-apm-go/v1/ao/internal/reporter/collector" + uatomic "go.uber.org/atomic" "google.golang.org/grpc" "google.golang.org/grpc/codes" "google.golang.org/grpc/status" - uatomic "go.uber.org/atomic" ) const ( @@ -211,7 +211,7 @@ type grpcReporter struct { getSettingsInterval int // settings retrieval interval in seconds settingsTimeoutCheckInterval int // check interval for timed out settings in seconds - serviceKey *uatomic.String // service key + serviceKey *uatomic.String // service key eventMessages chan []byte // channel for event messages (sent from agent) spanMessages chan metrics.SpanMessage // channel for span messages (sent from agent) @@ -693,7 +693,6 @@ func (r *grpcReporter) eventSender() { // Pour as much water as we can into the bucket. It blocks until it's // full or timeout. evtBucket.PourIn() - // The events can only be pushed into the channel when the bucket // is drainable (either full or timeout) and we've got the token // to push events. @@ -1095,7 +1094,6 @@ func (c *grpcConnection) InvokeRPC(exit chan struct{}, m Method) error { } default: } - var err = errConnStale // Protect the call to the client object or we could run into problems // if another goroutine is messing with it at the same time, e.g. doing diff --git a/v1/ao/layer.go b/v1/ao/layer.go index d65190bb..697d229e 100644 --- a/v1/ao/layer.go +++ b/v1/ao/layer.go @@ -66,6 +66,8 @@ type Span interface { // BeginSpanWithOptions starts a new child span with provided options BeginSpanWithOptions(spanName string, opts SpanOptions, args ...interface{}) Span + BeginSpanWithOverrides(spanName string, opts SpanOptions, overrides Overrides, args ...interface{}) Span + // BeginProfile starts a new Profile, used to measure a named span // of time spent in this Span. // @@ -74,6 +76,9 @@ type Span interface { BeginProfile(profileName string, args ...interface{}) Profile // End ends a Span, optionally reporting KV pairs provided by args. End(args ...interface{}) + + EndWithOverrides(overrides Overrides, args ...interface{}) + // AddEndArgs adds additional KV pairs that will be serialized (and // dereferenced, for pointer values) at the end of this trace's span. AddEndArgs(args ...interface{}) @@ -84,8 +89,9 @@ type Span interface { // InfoWithOptions reports a new info event with the KVs and options provided InfoWithOptions(opts SpanOptions, args ...interface{}) - // ErrorWithOpts reports an error with customized options - ErrorWithOpts(opts... ErrOpt) + // InfoWithOverrides reports a new info event with the KVs, options and overrides + InfoWithOverrides(overrides Overrides, opts SpanOptions, args ...interface{}) + // Error reports details about an error (along with a stack trace) for this Span. Error(class, msg string) // Err reports details about error err (along with a stack trace) for this Span. @@ -197,9 +203,13 @@ func fromKVs(kvs ...interface{}) KVMap { // BeginSpanWithOptions starts a span with provided options func BeginSpanWithOptions(ctx context.Context, spanName string, opts SpanOptions, args ...interface{}) (Span, context.Context) { + return BeginSpanWithOverrides(ctx, spanName, opts, Overrides{}, args...) +} + +func BeginSpanWithOverrides(ctx context.Context, spanName string, opts SpanOptions, overrides Overrides, args ...interface{}) (Span, context.Context) { kvs := addKVsFromOpts(opts, args...) if parent, ok := fromContext(ctx); ok && parent.ok() { // report span entry from parent context - l := newSpan(parent.aoContext().Copy(), spanName, parent, kvs...) + l := newSpan(parent.aoContext().Copy(), spanName, parent, overrides, kvs...) return l, newSpanContext(ctx, l) } return nullSpan{}, ctx @@ -212,9 +222,14 @@ func (s *layerSpan) BeginSpan(spanName string, args ...interface{}) Span { // BeginSpanWithOptions starts a new child span with provided options func (s *layerSpan) BeginSpanWithOptions(spanName string, opts SpanOptions, args ...interface{}) Span { + return s.BeginSpanWithOverrides(spanName, opts, Overrides{}, args...) +} + +// BeginSpanWithOptions starts a new child span with provided options +func (s *layerSpan) BeginSpanWithOverrides(spanName string, opts SpanOptions, overrides Overrides, args ...interface{}) Span { if s.ok() { // copy parent context and report entry from child kvs := addKVsFromOpts(opts, args...) - return newSpan(s.aoCtx.Copy(), spanName, s, kvs...) + return newSpan(s.aoCtx.Copy(), spanName, s, overrides, kvs...) } return nullSpan{} } @@ -242,7 +257,6 @@ func (s *layerSpan) BeginProfile(profileName string, args ...interface{}) Profil return s.BeginSpan(profileName, args) } -// End a profiled block or method. func (s *span) End(args ...interface{}) { if s.ok() { s.lock.Lock() @@ -265,6 +279,32 @@ func (s *span) End(args ...interface{}) { } } +// End a profiled block or method. +func (s *span) EndWithOverrides(overrides Overrides, args ...interface{}) { + if s.ok() { + s.lock.Lock() + defer s.lock.Unlock() + for _, prof := range s.childProfiles { + prof.End() + } + args = append(args, s.endArgs...) + for _, edge := range s.childEdges { // add Edge KV for each joined child + args = append(args, keyEdge, edge) + } + _ = s.aoCtx.ReportEventWithOverrides(s.exitLabel(), s.layerName(), reporter.Overrides{ + ExplicitTS: overrides.ExplicitTS, + ExplicitMdStr: overrides.ExplicitMdStr, + }, args...) + s.childEdges = nil // clear child edge list + s.endArgs = nil + s.ended = true + // add this span's context to list to be used as Edge by parent exit + if s.parent != nil && s.parent.ok() { + s.parent.addChildEdge(s.aoCtx) + } + } +} + // AddEndArgs adds KV pairs as variadic args that will be serialized (and dereferenced, // for pointer values) at the end of this trace's span. func (s *layerSpan) AddEndArgs(args ...interface{}) { @@ -292,6 +332,17 @@ func (s *layerSpan) InfoWithOptions(opts SpanOptions, args ...interface{}) { } } +// InfoWithOverrides reports a new info event with the KVs, options and overrides +func (s *layerSpan) InfoWithOverrides(overrides Overrides, opts SpanOptions, args ...interface{}) { + if s.ok() { + kvs := addKVsFromOpts(opts, args...) + s.aoCtx.ReportEventWithOverrides(reporter.LabelInfo, s.layerName(), reporter.Overrides{ + ExplicitTS: overrides.ExplicitTS, + ExplicitMdStr: overrides.ExplicitMdStr, + }, kvs...) + } +} + // MetadataString returns a representation of the Span's context for use with distributed // tracing (to create a remote child span). If the Span has ended, an empty string is returned. func (s *layerSpan) MetadataString() string { @@ -343,86 +394,18 @@ func (s *span) GetTransactionName() string { return s.aoCtx.GetTransactionName() } -type ErrType string - -const ( - ErrTypeException = "exception" - ErrTypeStatus = "status" -) - -// error classes -const ( - ErrClassHTTPError = "http error" - ErrClassError = "error" -) - -type ErrOpts struct { - Type ErrType - Class string - Msg string - WithBackTrace bool -} - -type ErrOpt func(*ErrOpts) - -func WithErrType(tp ErrType) ErrOpt { - return func(opts *ErrOpts) { - opts.Type = tp - } -} - -func WithErrClass(c string) ErrOpt { - return func(opts *ErrOpts) { - opts.Class = c - } -} - -func WithErrMsg(msg string) ErrOpt { - return func (opts *ErrOpts) { - opts.Msg = msg - } -} - -func WithErrBackTrace(withBackTrace bool) ErrOpt { - return func(opts *ErrOpts) { - opts.WithBackTrace = withBackTrace - } -} - -func (s *span) ErrorWithOpts(opts... ErrOpt) { - errOpts := &ErrOpts{ - Type: "exception", - Class: "error", - } - - for _, opt := range opts { - opt(errOpts) - } - - var backTrace string - if errOpts.WithBackTrace { - backTrace = string(debug.Stack()) - } - - if errOpts.Type == ErrTypeStatus { - errOpts.Class = ErrClassHTTPError - } - +// Error reports an error, distinguished by its class and message +func (s *span) Error(class, msg string) { if s.ok() { s.aoCtx.ReportEvent(reporter.LabelError, s.layerName(), keySpec, "error", - keyErrorType, errOpts.Type, - keyErrorClass, errOpts.Class, - keyErrorMsg, errOpts.Msg, - KeyBackTrace, backTrace) + keyErrorType, "exception", + keyErrorClass, class, + keyErrorMsg, msg, + KeyBackTrace, string(debug.Stack())) } } -// Error reports an error, distinguished by its class and message -func (s *span) Error(class, msg string) { - s.ErrorWithOpts(WithErrType(ErrTypeException), WithErrClass(class), WithErrMsg(msg), WithErrBackTrace(true)) -} - // Err reports the provided error type func (s *span) Err(err error) { if err == nil { @@ -446,30 +429,42 @@ type span struct { type layerSpan struct{ span } // satisfies Span type profileSpan struct{ span } // satisfies Profile type nullSpan struct{} // a span that is not tracing; satisfies Span & Profile +type contextSpan struct { + nullSpan + aoCtx reporter.Context +} func (s nullSpan) BeginSpan(spanName string, args ...interface{}) Span { return nullSpan{} } func (s nullSpan) BeginSpanWithOptions(spanName string, opts SpanOptions, args ...interface{}) Span { return nullSpan{} } -func (s nullSpan) BeginProfile(name string, args ...interface{}) Profile { return nullSpan{} } -func (s nullSpan) End(args ...interface{}) {} -func (s nullSpan) AddEndArgs(args ...interface{}) {} -func (s nullSpan) Error(class, msg string) {} -func (s nullSpan) ErrorWithOpts(opts... ErrOpt) {} -func (s nullSpan) Err(err error) {} -func (s nullSpan) Info(args ...interface{}) {} -func (s nullSpan) InfoWithOptions(opts SpanOptions, args ...interface{}) {} -func (s nullSpan) IsReporting() bool { return false } -func (s nullSpan) addChildEdge(reporter.Context) {} -func (s nullSpan) addProfile(Profile) {} -func (s nullSpan) ok() bool { return false } -func (s nullSpan) aoContext() reporter.Context { return reporter.NewNullContext() } -func (s nullSpan) MetadataString() string { return "" } -func (s nullSpan) IsSampled() bool { return false } -func (s nullSpan) SetAsync(bool) {} -func (s nullSpan) SetOperationName(string) {} -func (s nullSpan) SetTransactionName(string) error { return nil } -func (s nullSpan) GetTransactionName() string { return "" } +func (s nullSpan) BeginSpanWithOverrides(spanName string, opts SpanOptions, overrides Overrides, args ...interface{}) Span { + return nullSpan{} +} + +func (s nullSpan) BeginProfile(name string, args ...interface{}) Profile { return nullSpan{} } +func (s nullSpan) End(args ...interface{}) {} +func (s nullSpan) EndWithOverrides(overrides Overrides, args ...interface{}) {} +func (s nullSpan) AddEndArgs(args ...interface{}) {} +func (s nullSpan) Error(class, msg string) {} +func (s nullSpan) Err(err error) {} +func (s nullSpan) Info(args ...interface{}) {} +func (s nullSpan) InfoWithOptions(opts SpanOptions, args ...interface{}) {} +func (s nullSpan) InfoWithOverrides(overrides Overrides, opts SpanOptions, args ...interface{}) {} +func (s nullSpan) IsReporting() bool { return false } +func (s nullSpan) addChildEdge(reporter.Context) {} +func (s nullSpan) addProfile(Profile) {} +func (s nullSpan) ok() bool { return false } +func (s nullSpan) aoContext() reporter.Context { return reporter.NewNullContext() } +func (s nullSpan) MetadataString() string { return "" } +func (s nullSpan) IsSampled() bool { return false } +func (s nullSpan) SetAsync(bool) {} +func (s nullSpan) SetOperationName(string) {} +func (s nullSpan) SetTransactionName(string) error { return nil } +func (s nullSpan) GetTransactionName() string { return "" } + +func (s contextSpan) aoContext() reporter.Context { return s.aoCtx } +func (s contextSpan) ok() bool { return true } // is this span still valid (has it timed out, expired, not sampled) func (s *span) ok() bool { @@ -513,13 +508,18 @@ func (l spanLabeler) exitLabel() reporter.Label { return reporter.LabelExit } func (l spanLabeler) layerName() string { return l.name } func (l spanLabeler) setName(name string) { l.name = name } -func newSpan(aoCtx reporter.Context, spanName string, parent Span, args ...interface{}) Span { +func newSpan(aoCtx reporter.Context, spanName string, parent Span, overrides Overrides, args ...interface{}) Span { if spanName == "" { return nullSpan{} } ll := spanLabeler{spanName} - if err := aoCtx.ReportEvent(ll.entryLabel(), ll.layerName(), args...); err != nil { + + //fmt.Printf("Starting new span with context %+v\n", aoCtx) + if err := aoCtx.ReportEventWithOverrides(ll.entryLabel(), ll.layerName(), reporter.Overrides{ + ExplicitTS: overrides.ExplicitTS, + ExplicitMdStr: overrides.ExplicitMdStr, + }, args...); err != nil { return nullSpan{} } return &layerSpan{span: span{aoCtx: aoCtx.Copy(), labeler: ll, parent: parent}} diff --git a/v1/ao/trace.go b/v1/ao/trace.go index 90d0e8e9..9759d18c 100644 --- a/v1/ao/trace.go +++ b/v1/ao/trace.go @@ -74,6 +74,11 @@ type Trace interface { SetHTTPRspHeaders(map[string]string) } +type Overrides struct { + ExplicitTS time.Time + ExplicitMdStr string +} + // KVMap is a map of additional key-value pairs to report along with the event data provided // to AppOptics. Certain key names (such as "Query" or "RemoteHost") are used by AppOptics to // provide details about program activity and distinguish between different types of spans. @@ -87,6 +92,7 @@ type ContextOptions = reporter.ContextOptions type traceHTTPSpan struct { span metrics.HTTPSpanMessage start time.Time + end time.Time controller string action string } @@ -96,6 +102,7 @@ type aoTrace struct { exitEvent reporter.Event httpSpan traceHTTPSpan httpRspHeaders map[string]string + overrides Overrides } func (t *aoTrace) aoContext() reporter.Context { return t.aoCtx } @@ -150,6 +157,10 @@ func NewTraceFromID(spanName, mdStr string, cb func() KVMap) Trace { return NewTraceFromIDForURL(spanName, mdStr, "", cb) } +func NewTraceWithOverrides(spanName string, overrides Overrides, cb func() KVMap) Trace { + return NewTraceFromIDForURLWithOverrides(spanName, "", "", overrides, cb) +} + // NewTraceFromIDForURL creates a new Trace for the provided URL to report to AppOptics, // provided an incoming trace ID (e.g. from a incoming RPC or service call's "X-Trace" header). // If callback is provided & trace is sampled, cb will be called for entry event KVs @@ -164,6 +175,25 @@ func NewTraceFromIDForURL(spanName, mdStr string, url string, cb func() KVMap) T }) } +// NewTraceFromIDForURLWithOverrides creates a new Trace for the provided URL to report to AppOptics, +// provided an incoming trace ID (e.g. from a incoming RPC or service call's "X-Trace" header). +// Adds ability to provide overrides. +// If callback is provided & trace is sampled, cb will be called for entry event KVs +func NewTraceFromIDForURLWithOverrides(spanName, mdStr string, url string, overrides Overrides, cb func() KVMap) Trace { + return NewTraceWithOptions(spanName, SpanOptions{ + WithBackTrace: false, + ContextOptions: ContextOptions{ + MdStr: mdStr, + URL: url, + Overrides: reporter.Overrides{ + ExplicitTS: overrides.ExplicitTS, + ExplicitMdStr: overrides.ExplicitMdStr, + }, + CB: cb, + }, + }) +} + // SetTransactionName can be called inside a http handler to set the custom transaction name. func SetTransactionName(ctx context.Context, name string) error { return TraceFromContext(ctx).SetTransactionName(name) @@ -184,6 +214,15 @@ func (t *aoTrace) End(args ...interface{}) { } } +func (t *aoTrace) EndWithOverrides(overrides Overrides, args ...interface{}) { + if t.ok() { + t.overrides = overrides + t.AddEndArgs(args...) + t.reportExit() + flushAgent() + } +} + // EndCallback ends a Trace, reporting additional KV pairs returned by calling cb func (t *aoTrace) EndCallback(cb func() KVMap) { if t.ok() { @@ -204,6 +243,10 @@ func (t *aoTrace) SetStartTime(start time.Time) { t.httpSpan.start = start } +func (t *aoTrace) SetEndTime(end time.Time) { + t.httpSpan.end = end +} + // SetMethod sets the request's HTTP method, if any func (t *aoTrace) SetMethod(method string) { t.httpSpan.span.Method = method @@ -239,7 +282,13 @@ func (t *aoTrace) reportExit() { // record a new span if !t.httpSpan.start.IsZero() && t.aoCtx.GetEnabled() { - t.httpSpan.span.Duration = time.Now().Sub(t.httpSpan.start) + var end time.Time + if t.httpSpan.end.IsZero() { + end = time.Now() + } else { + end = t.httpSpan.end + } + t.httpSpan.span.Duration = end.Sub(t.httpSpan.start) t.recordHTTPSpan() } @@ -249,7 +298,10 @@ func (t *aoTrace) reportExit() { if t.exitEvent != nil { // use exit event, if one was provided t.exitEvent.ReportContext(t.aoCtx, true, t.endArgs...) } else { - t.aoCtx.ReportEvent(reporter.LabelExit, t.layerName(), t.endArgs...) + t.aoCtx.ReportEventWithOverrides(reporter.LabelExit, t.layerName(), reporter.Overrides{ + ExplicitTS: t.overrides.ExplicitTS, + ExplicitMdStr: t.overrides.ExplicitMdStr, + }, t.endArgs...) } t.childEdges = nil // clear child edge list