Pluggable tracing support in gkelog (#17)

* gkelog: Pluggable interface for trace contexts

Split up the existing jsonTrace function so it can use a different
implementation for extracting the trace from the context.

Add support for including the logging.googleapis.com/trace_sampled key
in the logging payload.

reference for structured logs ingested by the stackdriver logging agent
(as used in GKE):
https://cloud.google.com/logging/docs/agent/configuration#special-fields

* Add gitignore with vim excludes

* gkelog: opencensus TraceSpanExtractor

Create a submodule to contain the opencensus TraceSpanExtractor since
that has a rather expansive set of dependencies that we wouldn't want to
force on all users.

* gkelog: add an opentelemetry TraceSpanExtractor

Similar to Opencensus, this one is its own submodule as well.
It locks the current head version of opentelemetry because they renamed
the context-extraction method and I don't want to rename it later.

I had to remove the "sampled" variant of the test because there's
currently no way that I could find to enable sampling without doing
unholy things to the otel SpanContext struct (mostly setting flags
manually).

It looks like they have some missing plumbing, that should get resolved,
so there's a TODO waiting for us when that's working.

.gitignore

@@ -0,0 +1 @@
+*.sw[op]

emitter/gkelog/emitter.go

@@ -132,30 +132,41 @@ var reservedKeys = map[string]bool{
 	"time":                                  true,
 }
 
-func jsonTrace(ctx context.Context, w *bytes.Buffer) {
-	var (
-		trace string
-		span  string
-	)
+func defaultTraceExtractor(ctx context.Context) SpanContext {
+	sctx := SpanContext{}
 
 	traceV := ctx.Value(traceKey)
 	if traceV != nil {
-		trace = traceV.(string)
+		sctx.TraceID = traceV.(string)
+		sctx.Sampled = true
 	}
 	spanV := ctx.Value(spanKey)
 	if spanV != nil {
-		span = spanV.(string)
+		sctx.SpanID = spanV.(string)
+		sctx.Sampled = true
 	}
+	return sctx
+}
 
-	if trace != "" {
+func jsonTrace(ctx context.Context, o *Options, w *bytes.Buffer) {
+	if o.spanExtractor == nil {
+		return
+	}
+	sctx := o.spanExtractor(ctx)
+	if sctx.TraceID != "" {
 		jsonKey(w, "logging.googleapis.com/trace")
-		jsonString(w, trace)
+		jsonString(w, sctx.TraceID)
 		w.WriteString(", ")
 	}
 
-	if span != "" {
+	if sctx.SpanID != "" {
 		jsonKey(w, "logging.googleapis.com/spanId")
-		jsonString(w, span)
+		jsonString(w, sctx.SpanID)
+		w.WriteString(", ")
+	}
+	if sctx.TraceID != "" || sctx.SpanID != "" {
+		jsonKey(w, "logging.googleapis.com/trace_sampled")
+		w.WriteString(strconv.FormatBool(sctx.Sampled))
 		w.WriteString(", ")
 	}
 }
@@ -317,7 +328,9 @@ func jsonHTTPRequest(ctx context.Context, w *bytes.Buffer) {
 // Logs are output to w. Every entry generates a single Write call to w, and
 // calls are serialized.
 func Emitter(opt ...Option) alog.Emitter {
-	o := new(Options)
+	o := &Options{
+		spanExtractor: defaultTraceExtractor,
+	}
 	for _, option := range opt {
 		option(o)
 	}
@@ -350,7 +363,7 @@ func Emitter(opt ...Option) alog.Emitter {
 
 		jsonHTTPRequest(ctx, b)
 
-		jsonTrace(ctx, b)
+		jsonTrace(ctx, o, b)
 
 		tagClean := make(map[string]int, len(e.Tags))
 		for i, tag := range e.Tags {

emitter/gkelog/emitter_test.go

@@ -104,7 +104,7 @@ func TestRequest(t *testing.T) {
 
 	l.Print(ctx, "test")
 
-	want := `{"time":"0001-01-01T00:00:00Z", "httpRequest":{"requestMethod":"GET", "requestUrl":"/test/endpoint?q=1&c=pink", "userAgent":"curl/7.54.0", "referer":"https://vimeo.com"}, "httpHeaders":{"Content-Type":"text/plain", "Dnt":"1"}, "httpQuery":{"c":"pink", "q":"1"}, "logging.googleapis.com/trace":"a2fbf27a2ed90077e0d4af0e40a241f9", "logging.googleapis.com/spanId":"b01d4e1cf2bd7f4d", "message":"test"}` + "\n"
+	want := `{"time":"0001-01-01T00:00:00Z", "httpRequest":{"requestMethod":"GET", "requestUrl":"/test/endpoint?q=1&c=pink", "userAgent":"curl/7.54.0", "referer":"https://vimeo.com"}, "httpHeaders":{"Content-Type":"text/plain", "Dnt":"1"}, "httpQuery":{"c":"pink", "q":"1"}, "logging.googleapis.com/trace":"a2fbf27a2ed90077e0d4af0e40a241f9", "logging.googleapis.com/spanId":"b01d4e1cf2bd7f4d", "logging.googleapis.com/trace_sampled":true, "message":"test"}` + "\n"
 	got := b.String()
 	if got != want {
 		t.Errorf("got:\n%s\nwant:\n%s", got, want)
@@ -120,7 +120,7 @@ func TestTrace(t *testing.T) {
 
 	l.Print(ctx, "test")
 
-	want := `{"time":"0001-01-01T00:00:00Z", "logging.googleapis.com/trace":"a2fbf27a2ed90077e0d4af0e40a241f9", "message":"test"}` + "\n"
+	want := `{"time":"0001-01-01T00:00:00Z", "logging.googleapis.com/trace":"a2fbf27a2ed90077e0d4af0e40a241f9", "logging.googleapis.com/trace_sampled":true, "message":"test"}` + "\n"
 	got := b.String()
 	if got != want {
 		t.Errorf("got:\n%s\nwant:\n%s", got, want)
@@ -156,7 +156,7 @@ func TestSpan(t *testing.T) {
 
 	l.Print(ctx, "test")
 
-	want := `{"time":"0001-01-01T00:00:00Z", "logging.googleapis.com/spanId":"b01d4e1cf2bd7f4d", "message":"test"}` + "\n"
+	want := `{"time":"0001-01-01T00:00:00Z", "logging.googleapis.com/spanId":"b01d4e1cf2bd7f4d", "logging.googleapis.com/trace_sampled":true, "message":"test"}` + "\n"
 	got := b.String()
 	if got != want {
 		t.Errorf("got:\n%s\nwant:\n%s", got, want)
@@ -176,7 +176,7 @@ func TestRequestTrace(t *testing.T) {
 
 	l.Print(ctx, "test")
 
-	want := `{"time":"0001-01-01T00:00:00Z", "logging.googleapis.com/trace":"a2fbf27a2ed90077e0d4af0e40a241f9", "logging.googleapis.com/spanId":"b01d4e1cf2bd7f4d", "message":"test"}` + "\n"
+	want := `{"time":"0001-01-01T00:00:00Z", "logging.googleapis.com/trace":"a2fbf27a2ed90077e0d4af0e40a241f9", "logging.googleapis.com/spanId":"b01d4e1cf2bd7f4d", "logging.googleapis.com/trace_sampled":true, "message":"test"}` + "\n"
 	got := b.String()
 	if got != want {
 		t.Errorf("got:\n%s\nwant:\n%s", got, want)

emitter/gkelog/options.go

@@ -1,14 +1,16 @@
 package gkelog
 
 import (
+	"context"
 	"io"
 )
 
 // Options holds option values.
 type Options struct {
-	reqWriter io.Writer
-	appWriter io.Writer
-	shortfile bool
+	reqWriter     io.Writer
+	appWriter     io.Writer
+	spanExtractor TraceSpanExtractor
+	shortfile     bool
 }
 
 // Option sets an option for the emitter.
@@ -41,3 +43,26 @@ func WithWriters(req io.Writer, app io.Writer) Option {
 func WithShortFile() Option {
 	return func(o *Options) { o.shortfile = true }
 }
+
+// SpanContext contains the necessary trace-context data to populate the
+// logging.googleapis.com/spanId, logging.googleapis.com/trace and
+// logging.googleapis.com/trace_sampled fields.
+// See https://cloud.google.com/logging/docs/agent/configuration#special-fields
+// for details on these fields.
+type SpanContext struct {
+	SpanID  string
+	TraceID string
+	Sampled bool
+}
+
+// TraceSpanExtractor implementations extract a trace spanID from the passed
+// context.
+// The return values should be: spanID, traceID, isSampled
+type TraceSpanExtractor func(context.Context) SpanContext
+
+// WithTraceSpanExtractor registers a trace-span extractor so trace-span IDs
+// from the context (as found by the extractor) are placed in the appropriate
+// fields to be correlated by stackdriver tracing.
+func WithTraceSpanExtractor(extractor TraceSpanExtractor) Option {
+	return func(o *Options) { o.spanExtractor = extractor }
+}

emitter/gkelog/traceextractors/oc/go.mod

@@ -0,0 +1,11 @@
+module github.com/vimeo/alog/emitter/gkelog/traceextractors/oc
+
+go 1.12
+
+require (
+	github.com/golang/groupcache v0.0.0-20200121045136-8c9f03a8e57e // indirect
+	github.com/vimeo/alog/v3 v3.5.0
+	go.opencensus.io v0.22.3
+)
+
+replace github.com/vimeo/alog/v3 => ../../../../