Merge pull request #75 from netlify/add-tracing-package

add tracing framework

Author: rybit

go.mod

@@ -24,17 +24,20 @@ require (
 	github.com/lib/pq v1.0.0 // indirect
 	github.com/magiconair/properties v0.0.0-20190110142458-7757cc9fdb85 // indirect
 	github.com/mitchellh/mapstructure v1.1.2 // indirect
-	github.com/nats-io/gnatsd v1.4.1
+	github.com/nats-io/gnatsd v1.4.1 // indirect
 	github.com/nats-io/go-nats v1.3.0
 	github.com/nats-io/go-nats-streaming v0.3.4
 	github.com/nats-io/nats-streaming-server v0.12.2 // indirect
 	github.com/nats-io/nuid v0.0.0-20180712044959-3024a71c3cbe // indirect
 	github.com/onsi/ginkgo v1.8.0 // indirect
 	github.com/onsi/gomega v1.5.0 // indirect
+	github.com/opentracing/opentracing-go v1.1.0
 	github.com/pascaldekloe/goe v0.1.0 // indirect
 	github.com/pelletier/go-toml v0.0.0-20181124002727-27c6b39a135b // indirect
+	github.com/philhofer/fwd v1.0.0 // indirect
 	github.com/pkg/errors v0.8.0
 	github.com/prometheus/procfs v0.0.0-20190403104016-ea9eea638872 // indirect
+	github.com/satori/go.uuid v1.2.0
 	github.com/shopify/logrus-bugsnag v0.0.0-20171204204709-577dee27f20d
 	github.com/sirupsen/logrus v1.0.5
 	github.com/spf13/afero v1.2.1 // indirect
@@ -44,9 +47,11 @@ require (
 	github.com/spf13/pflag v1.0.0 // indirect
 	github.com/spf13/viper v1.0.2
 	github.com/stretchr/testify v1.2.2
+	github.com/tinylib/msgp v1.1.0 // indirect
 	go.etcd.io/bbolt v1.3.2 // indirect
 	golang.org/x/crypto v0.0.0-20161031180806-9477e0b78b9a // indirect
 	google.golang.org/appengine v1.5.0 // indirect
+	gopkg.in/DataDog/dd-trace-go.v1 v1.12.1
 	gopkg.in/airbrake/gobrake.v2 v2.0.9 // indirect
 	gopkg.in/gemnasium/logrus-airbrake-hook.v2 v2.1.2 // indirect
 	gopkg.in/yaml.v2 v2.2.2 // indirect

go.sum

@@ -75,16 +75,22 @@ github.com/onsi/ginkgo v1.8.0 h1:VkHVNpR4iVnU8XQR6DBm8BqYjN7CRzw+xKUbVVbbW9w=
 github.com/onsi/ginkgo v1.8.0/go.mod h1:lLunBs/Ym6LB5Z9jYTR76FiuTmxDTDusOGeTQH+WWjE=
 github.com/onsi/gomega v1.5.0 h1:izbySO9zDPmjJ8rDjLvkA2zJHIo+HkYXHnf7eN7SSyo=
 github.com/onsi/gomega v1.5.0/go.mod h1:ex+gbHU/CVuBBDIJjb2X0qEXbFg53c61hWP/1CpauHY=
+github.com/opentracing/opentracing-go v1.1.0 h1:pWlfV3Bxv7k65HYwkikxat0+s3pV4bsqf19k25Ur8rU=
+github.com/opentracing/opentracing-go v1.1.0/go.mod h1:UkNAQd3GIcIGf0SeVgPpRdFStlNbqXla1AfSYxPUl2o=
 github.com/pascaldekloe/goe v0.1.0 h1:cBOtyMzM9HTpWjXfbbunk26uA6nG3a8n06Wieeh0MwY=
 github.com/pascaldekloe/goe v0.1.0/go.mod h1:lzWF7FIEvWOWxwDKqyGYQf6ZUaNfKdP144TG7ZOy1lc=
 github.com/pelletier/go-toml v0.0.0-20181124002727-27c6b39a135b h1:q2XlNu7oriSkQtLMfX18sYspQfYOCihpMRZNGHT1VQY=
 github.com/pelletier/go-toml v0.0.0-20181124002727-27c6b39a135b/go.mod h1:5z9KED0ma1S8pY6P1sdut58dfprrGBbd/94hg7ilaic=
+github.com/philhofer/fwd v1.0.0 h1:UbZqGr5Y38ApvM/V/jEljVxwocdweyH+vmYvRPBnbqQ=
+github.com/philhofer/fwd v1.0.0/go.mod h1:gk3iGcWd9+svBvR0sR+KPcfE+RNWozjowpeBVG3ZVNU=
 github.com/pkg/errors v0.8.0 h1:WdK/asTD0HN+q6hsWO3/vpuAkAr+tw6aNJNDFFf0+qw=
 github.com/pkg/errors v0.8.0/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0=
 github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM=
 github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
 github.com/prometheus/procfs v0.0.0-20190403104016-ea9eea638872 h1:0aNv3xC7DmQoy1/x1sMh18g+fihWW68LL13i8ao9kl4=
 github.com/prometheus/procfs v0.0.0-20190403104016-ea9eea638872/go.mod h1:TjEm7ze935MbeOT/UhFTIMYKhuLP4wbCsTZCD3I8kEA=
+github.com/satori/go.uuid v1.2.0 h1:0uYX9dsZ2yD7q2RtLRtPSdGDWzjeM3TbMJP9utgA0ww=
+github.com/satori/go.uuid v1.2.0/go.mod h1:dA0hQrYB0VpLJoorglMZABFdXlWrHn1NEOzdhQKdks0=
 github.com/shopify/logrus-bugsnag v0.0.0-20171204204709-577dee27f20d h1:2ZhZbXlQKtsDYOx922QgmzuxNqhj8WcG1XlH/uIWw+Q=
 github.com/shopify/logrus-bugsnag v0.0.0-20171204204709-577dee27f20d/go.mod h1:DmcHeT/UuSDXaCVb8IijmL+fHX+FK9TLy98W7mfDXXg=
 github.com/sirupsen/logrus v1.0.5 h1:8c8b5uO0zS4X6RPl/sd1ENwSkIc0/H2PaHxE3udaE8I=
@@ -103,6 +109,8 @@ github.com/spf13/viper v1.0.2 h1:Ncr3ZIuJn322w2k1qmzXDnkLAdQMlJqBa9kfAH+irso=
 github.com/spf13/viper v1.0.2/go.mod h1:A8kyI5cUJhb8N+3pkfONlcEcZbueH6nhAm0Fq7SrnBM=
 github.com/stretchr/testify v1.2.2 h1:bSDNvY7ZPG5RlJ8otE/7V6gMiyenm9RtJ7IUVIAoJ1w=
 github.com/stretchr/testify v1.2.2/go.mod h1:a8OnRcib4nhh0OaRAV+Yts87kKdq0PP7pXfy6kDkUVs=
+github.com/tinylib/msgp v1.1.0 h1:9fQd+ICuRIu/ue4vxJZu6/LzxN0HwMds2nq/0cFvxHU=
+github.com/tinylib/msgp v1.1.0/go.mod h1:+d+yLhGm8mzTaHzB+wgMYrodPfmZrzkirds8fDWklFE=
 go.etcd.io/bbolt v1.3.2 h1:Z/90sZLPOeCy2PwprqkFa25PdkusRzaj9P8zm/KNyvk=
 go.etcd.io/bbolt v1.3.2/go.mod h1:IbVyRI1SCnLcuJnV2u8VeU0CEYM7e686BmAb1XKL+uU=
 golang.org/x/crypto v0.0.0-20161031180806-9477e0b78b9a h1:Esnda2KnXoH6s+xVTf9zaZg3o4p6d9C25WBNxxDHwOU=
@@ -119,6 +127,8 @@ golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=
 golang.org/x/tools v0.0.0-20180221164845-07fd8470d635/go.mod h1:n7NCudcB/nEzxVGmLbDWY5pfWTLqBcC2KZ6jyYvM4mQ=
 google.golang.org/appengine v1.5.0 h1:KxkO13IPW4Lslp2bz+KHP2E3gtFlrIGNThxkZQ3g+4c=
 google.golang.org/appengine v1.5.0/go.mod h1:xpcJRLb0r/rnEns0DIKYYv+WjYCduHsrkT7/EB5XEv4=
+gopkg.in/DataDog/dd-trace-go.v1 v1.12.1 h1:zkyLw+Uq6BvGwy5hFeLVI1ePgOkqJswFPL1uOx6SSA4=
+gopkg.in/DataDog/dd-trace-go.v1 v1.12.1/go.mod h1:DVp8HmDh8PuTu2Z0fVVlBsyWaC++fzwVCaGWylTe3tg=
 gopkg.in/airbrake/gobrake.v2 v2.0.9 h1:7z2uVWwn7oVeeugY1DtlPAy5H+KYgB1KeKTnqjNatLo=
 gopkg.in/airbrake/gobrake.v2 v2.0.9/go.mod h1:/h5ZAUhDkGaJfjzjKLSjv6zCL6O0LLBxU4K+aSYdM/U=
 gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405 h1:yhCVgyC4o1eVCa2tZl7eS0r+SDo693bJlVdllGtEeKM=

tracing/config.go

@@ -0,0 +1,39 @@
+package tracing
+
+import (
+	"fmt"
+
+	"github.com/opentracing/opentracing-go"
+	"gopkg.in/DataDog/dd-trace-go.v1/ddtrace/opentracer"
+	"gopkg.in/DataDog/dd-trace-go.v1/ddtrace/tracer"
+)
+
+const (
+	HeaderNFDebugLogging = "X-NF-Debug-Logging"
+	HeaderRequestUUID    = "X-BB-CLIENT-REQUEST-UUID"
+)
+
+type Config struct {
+	Enabled bool   `default:"false"`
+	Host    string `default:"localhost"`
+	Port    string `default:"8126"`
+	Tags    map[string]string
+}
+
+func Configure(tc *Config, svcName string) {
+	var t opentracing.Tracer = opentracing.NoopTracer{}
+	if tc.Enabled {
+		tracerAddr := fmt.Sprintf("%s:%s", tc.Host, tc.Port)
+		tracerOps := []tracer.StartOption{
+			tracer.WithServiceName(svcName),
+			tracer.WithAgentAddr(tracerAddr),
+		}
+
+		for k, v := range tc.Tags {
+			tracerOps = append(tracerOps, tracer.WithGlobalTag(k, v))
+		}
+
+		t = opentracer.New(tracerOps...)
+	}
+	opentracing.SetGlobalTracer(t)
+}

tracing/context.go

@@ -0,0 +1,26 @@
+package tracing
+
+import (
+	"context"
+	"net/http"
+)
+
+type contextKey string
+
+const tracerKey = contextKey("nf-tracer-key")
+
+func WrapWithTracer(r *http.Request, rt *RequestTracer) *http.Request {
+	return r.WithContext(context.WithValue(r.Context(), tracerKey, rt))
+}
+
+func GetTracer(r *http.Request) *RequestTracer {
+	val := r.Context().Value(tracerKey)
+	if val == nil {
+		return nil
+	}
+	entry, ok := val.(*RequestTracer)
+	if ok {
+		return entry
+	}
+	return nil
+}

tracing/logging.go

@@ -0,0 +1,68 @@
+package tracing
+
+import (
+	"net/http"
+
+	"github.com/sirupsen/logrus"
+)
+
+const (
+	logKey = contextKey("nf-log-key")
+)
+
+func requestLogger(r *http.Request, log logrus.FieldLogger) logrus.FieldLogger {
+	if r.Header.Get(HeaderNFDebugLogging) != "" {
+		logger := logrus.New()
+		logger.SetLevel(logrus.DebugLevel)
+
+		if entry, ok := log.(*logrus.Entry); ok {
+			log = logger.WithFields(entry.Data)
+		}
+	}
+
+	reqID := RequestID(r)
+
+	log = log.WithFields(logrus.Fields{
+		"request_id": reqID,
+	})
+	return log
+}
+
+func GetLogger(r *http.Request) logrus.FieldLogger {
+	entry := GetTracer(r)
+	if entry == nil {
+		return logrus.NewEntry(logrus.StandardLogger())
+	}
+	return entry.FieldLogger
+}
+
+// SetLogField will add the field to this log line and every one following
+func SetLogField(r *http.Request, key string, value interface{}) logrus.FieldLogger {
+	entry := GetTracer(r)
+	if entry == nil {
+		return logrus.StandardLogger().WithField(key, value)
+	}
+	return entry.SetLogField(key, value)
+}
+
+// SetLogFields will add the fields to this log line and every one following
+func SetLogFields(r *http.Request, fields logrus.Fields) logrus.FieldLogger {
+	entry := GetTracer(r)
+	if entry == nil {
+		return logrus.StandardLogger().WithFields(fields)
+	}
+
+	return entry.SetLogFields(fields)
+}
+
+// SetFinalField will add a field to the canonical line created at in Finish. It will add
+// it to this line, but not every log line in between
+func SetFinalField(r *http.Request, key string, value interface{}) logrus.FieldLogger {
+	entry := GetTracer(r)
+	if entry == nil {
+		return logrus.StandardLogger().WithField(key, value)
+	}
+
+	entry.FinalFields[key] = value
+	return entry.FieldLogger.WithField(key, value)
+}

tracing/middleware.go

@@ -0,0 +1,15 @@
+package tracing
+
+import (
+	"net/http"
+
+	"github.com/sirupsen/logrus"
+)
+
+func Middleware(log logrus.FieldLogger, svcName string) func(http.Handler) http.Handler {
+	return func(next http.Handler) http.Handler {
+		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+			TrackRequest(w, r, log, svcName, next)
+		})
+	}
+}

tracing/req_tracer.go

@@ -0,0 +1,89 @@
+package tracing
+
+import (
+	"net/http"
+	"time"
+
+	opentracing "github.com/opentracing/opentracing-go"
+	"github.com/sirupsen/logrus"
+)
+
+type RequestTracer struct {
+	*trackingWriter
+	logrus.FieldLogger
+
+	RequestID   string
+	FinalFields map[string]interface{}
+
+	remoteAddr  string
+	method      string
+	originalURL string
+	referrer    string
+	span        opentracing.Span
+	start       time.Time
+}
+
+func NewTracer(w http.ResponseWriter, r *http.Request, log logrus.FieldLogger, service string) (http.ResponseWriter, *http.Request, *RequestTracer) {
+	reqID := RequestID(r)
+	log = requestLogger(r, log)
+	r, span := WrapWithSpan(r, reqID, service)
+	trackWriter := &trackingWriter{
+		writer: w,
+		log:    log,
+	}
+
+	rt := &RequestTracer{
+		originalURL: r.URL.String(),
+		method:      r.Method,
+		referrer:    r.Referer(),
+		remoteAddr:  r.RemoteAddr,
+
+		RequestID:      reqID,
+		span:           span,
+		trackingWriter: trackWriter,
+		FieldLogger:    log,
+		FinalFields:    make(map[string]interface{}),
+	}
+	r = WrapWithTracer(r, rt)
+
+	return rt, r, rt
+}
+
+func (rt *RequestTracer) Start() {
+	rt.start = time.Now()
+	rt.WithFields(logrus.Fields{
+		"method":      rt.method,
+		"remote_addr": rt.remoteAddr,
+		"referer":     rt.referrer,
+		"url":         rt.originalURL,
+	}).Info("Starting Request")
+}
+
+func (rt *RequestTracer) Finish() {
+	dur := time.Since(rt.start)
+
+	fields := logrus.Fields{}
+	for k, v := range rt.FinalFields {
+		fields[k] = v
+	}
+
+	fields["status_code"] = rt.trackingWriter.status
+	fields["rsp_bytes"] = rt.trackingWriter.rspBytes
+	fields["url"] = rt.originalURL
+	fields["method"] = rt.method
+	fields["dur"] = dur.String()
+	fields["dur_ns"] = dur.Nanoseconds()
+
+	rt.span.Finish()
+	rt.WithFields(fields).Info("Completed Request")
+}
+
+func (rt *RequestTracer) SetLogField(key string, value interface{}) logrus.FieldLogger {
+	rt.FieldLogger = rt.FieldLogger.WithField(key, value)
+	return rt.FieldLogger
+}
+
+func (rt *RequestTracer) SetLogFields(fields logrus.Fields) logrus.FieldLogger {
+	rt.FieldLogger = rt.FieldLogger.WithFields(fields)
+	return rt.FieldLogger
+}

tracing/req_tracer_test.go

@@ -0,0 +1,67 @@
+package tracing
+
+import (
+	"fmt"
+	"net/http"
+	"net/http/httptest"
+	"testing"
+
+	logtest "github.com/sirupsen/logrus/hooks/test"
+	"github.com/stretchr/testify/assert"
+)
+
+func TestTracerLogging(t *testing.T) {
+	// func NewTracer(w http.ResponseWriter, r *http.Request, log logrus.FieldLogger, service string) (http.ResponseWriter, *http.Request, *RequestTracer) {
+	rec := httptest.NewRecorder()
+	req := httptest.NewRequest(http.MethodGet, "http://whatever.com/something", nil)
+
+	log, hook := logtest.NewNullLogger()
+
+	_, r, rt := NewTracer(rec, req, log, t.Name())
+
+	rt.Start()
+	e := hook.LastEntry()
+	assert.Equal(t, 5, len(e.Data))
+	assert.NotEmpty(t, e.Data["request_id"])
+	assert.NotEmpty(t, e.Data["remote_addr"])
+	assert.Empty(t, e.Data["referrer"])
+	assert.NotEmpty(t, e.Data["method"])
+	assert.Equal(t, "http://whatever.com/something", e.Data["url"])
+	fmt.Println(e.Data)
+
+	_ = SetLogField(r, "first", "second")
+	SetFinalField(r, "final", "line").Info("should have the final here")
+	e = hook.LastEntry()
+	assert.Equal(t, 3, len(e.Data))
+	assert.NotEmpty(t, e.Data["request_id"])
+	assert.Equal(t, "line", e.Data["final"])
+	assert.Equal(t, "second", e.Data["first"])
+	fmt.Println(e.Data)
+
+	rt.Info("Shouldn't have the final line")
+	e = hook.LastEntry()
+	assert.Equal(t, 2, len(e.Data))
+	assert.NotEmpty(t, e.Data["request_id"])
+	assert.Equal(t, "second", e.Data["first"])
+	fmt.Println(e.Data)
+
+	rt.WriteHeader(http.StatusOK)
+	rt.Write([]byte{0, 1, 2, 3})
+	rt.Finish()
+	e = hook.LastEntry()
+
+	assert.Equal(t, 9, len(e.Data))
+
+	// the automatic fields
+	assert.NotEmpty(t, e.Data["dur"])
+	assert.NotEmpty(t, e.Data["dur_ns"])
+	assert.NotEmpty(t, e.Data["request_id"])
+	assert.Equal(t, 4, e.Data["rsp_bytes"])
+	assert.Equal(t, 200, e.Data["status_code"])
+	assert.Equal(t, "http://whatever.com/something", e.Data["url"])
+	assert.Equal(t, "GET", e.Data["method"])
+
+	// the value that we added above
+	assert.Equal(t, "second", e.Data["first"])
+	assert.Equal(t, "line", e.Data["final"])
+}