APM with blend/go-sdk

.gitignore

client/
server/

README.md

Datadog APM with blend/go-sdk

NOTE: Since this is a GitHub gist, subdirectories are not allowed, but that will mean we have two package main scripts in the same directory, which is problematic.

First, create symlinks to our scripts in separate directories

mkdir client/
ln -s ../client.go client/main.go
mkdir server/
ln -s ../server.go server/main.go

Then run two servers (a primary and downstream) and (after they are running) the client in three different shells. For example, the client output may resemble:

$ go run client/main.go
{"_timestamp":"2020-01-14T00:09:07.877225Z","flag":"info","text":"status: 200, body: \"ok!\""}
{"_timestamp":"2020-01-14T00:09:07.881183Z","flag":"info","text":"status: 200, body: \"outbound\""}

The main server:

$ go run server/main.go
{"_timestamp":"2020-01-14T00:08:54.076604Z","flag":"info","text":"http server started, listening on :8080"}
{"_timestamp":"2020-01-14T00:09:07.876169Z","flag":"http.request","host":"localhost:8080","ip":"::1","labels":{"web.route":"/"},"path":"/","query":"","route":"/","userAgent":"Go-http-client/1.1","verb":"GET"}
{"_timestamp":"2020-01-14T00:09:07.876286Z","annotations":{"dd":{"trace_id":1234567890,"span_id":5494006354809255998}},"flag":"info","labels":{"web.route":"/"},"text":"CLIENT: dd.trace_id: 1234567890 dd.span_id=9876543210"}
{"_timestamp":"2020-01-14T00:09:07.876403Z","annotations":{"dd":{"trace_id":1234567890,"span_id":5494006354809255998}},"flag":"info","labels":{"web.route":"/"},"text":"CURRENT: dd.trace_id: 1234567890 dd.span_id=5494006354809255998"}
{"_timestamp":"2020-01-14T00:09:07.876439Z","annotations":{"dd":{"trace_id":1234567890,"span_id":5494006354809255998}},"contentEncoding":"","contentLength":3,"contentType":"text/plain; charset=utf-8","elapsed":0.275,"flag":"http.response","host":"localhost:8080","ip":"::1","labels":{"web.route":"/"},"path":"/","query":"","route":"/","statusCode":200,"userAgent":"Go-http-client/1.1","verb":"GET"}
{"_timestamp":"2020-01-14T00:09:07.877457Z","flag":"http.request","host":"localhost:8080","ip":"::1","labels":{"web.route":"/outbound"},"path":"/outbound","query":"","route":"/outbound","userAgent":"Go-http-client/1.1","verb":"GET"}
{"_timestamp":"2020-01-14T00:09:07.880938Z","annotations":{"body":"ok!","dd":{"trace_id":1234567890,"span_id":4619113203306507260},"status":200},"flag":"info","labels":{"web.route":"/outbound"},"text":"HTTP response"}
{"_timestamp":"2020-01-14T00:09:07.88098Z","annotations":{"dd":{"trace_id":1234567890,"span_id":4619113203306507260}},"contentEncoding":"","contentLength":8,"contentType":"text/plain; charset=utf-8","elapsed":3.523,"flag":"http.response","host":"localhost:8080","ip":"::1","labels":{"web.route":"/outbound"},"path":"/outbound","query":"","route":"/outbound","statusCode":200,"userAgent":"Go-http-client/1.1","verb":"GET"}
{"_timestamp":"2020-01-14T00:09:27.522474Z","flag":"info","text":"server shutting down"}
{"_timestamp":"2020-01-14T00:09:27.522611Z","flag":"info","text":"server shutdown complete"}
{"_timestamp":"2020-01-14T00:09:27.522648Z","flag":"info","text":"server exited"}

and the second server (downstream of the main server, must be running on port 9090):

$ PORT=9090 go run server/main.go
{"_timestamp":"2020-01-14T00:09:06.17761Z","flag":"info","text":"http server started, listening on :9090"}
{"_timestamp":"2020-01-14T00:09:07.879909Z","flag":"http.request","host":"localhost:9090","ip":"::1","labels":{"web.route":"/"},"path":"/","query":"","route":"/","userAgent":"Go-http-client/1.1","verb":"GET"}
{"_timestamp":"2020-01-14T00:09:07.88004Z","annotations":{"dd":{"trace_id":1234567890,"span_id":8185291757207509523}},"flag":"info","labels":{"web.route":"/"},"text":"CLIENT: dd.trace_id: 1234567890 dd.span_id=5033722923861251624"}
{"_timestamp":"2020-01-14T00:09:07.880177Z","annotations":{"dd":{"trace_id":1234567890,"span_id":8185291757207509523}},"flag":"info","labels":{"web.route":"/"},"text":"CURRENT: dd.trace_id: 1234567890 dd.span_id=8185291757207509523"}
{"_timestamp":"2020-01-14T00:09:07.880212Z","annotations":{"dd":{"trace_id":1234567890,"span_id":8185291757207509523}},"contentEncoding":"","contentLength":3,"contentType":"text/plain; charset=utf-8","elapsed":0.315,"flag":"http.response","host":"localhost:9090","ip":"::1","labels":{"web.route":"/"},"path":"/","query":"","route":"/","statusCode":200,"userAgent":"Go-http-client/1.1","verb":"GET"}
{"_timestamp":"2020-01-14T00:09:26.395019Z","flag":"info","text":"server shutting down"}
{"_timestamp":"2020-01-14T00:09:26.395189Z","flag":"info","text":"server exited"}
{"_timestamp":"2020-01-14T00:09:26.395185Z","flag":"info","text":"server shutdown complete"}

Concerns and Comments

• There is no way to "merge" into context labels or annotations

• The incoming http.request log does not get the dd annotation, but to be useful (e.g. in Splunk), it should

• While doing this I stumbled upon the fact that the JSON logger drops this text log from the client on the floor

  2020-01-10T22:54:55.119712Z    [http.client.response]
  

client.go

package main

import (
	"fmt"
	"os"

	"github.com/blend/go-sdk/logger"
	"github.com/blend/go-sdk/r2"
	ddtracer "gopkg.in/DataDog/dd-trace-go.v1/ddtrace/tracer"
)

func mustNil(err error) {
	if err == nil {
		return
	}

	fmt.Fprintf(os.Stderr, "%v\n", err)
	os.Exit(1)
}

func main() {
	log := logger.MustNew(
		logger.OptAll(),
		logger.OptJSON(),
	)

	paths := []string{"", "/outbound"}
	for _, path := range paths {
		req := r2.New(
			fmt.Sprintf("http://localhost:8080%s", path),
			r2.OptHeaderValue("X-Sent-By", "go-sdk/request2"),
			r2.OptHeaderValue(ddtracer.DefaultTraceIDHeader, "1234567890"),
			r2.OptHeaderValue(ddtracer.DefaultParentIDHeader, "9876543210"),
			r2.OptCookieValue("r2-ray-id", "baileydog01"),
			r2.OptLogResponse(log),
		)

		body, res, err := req.Bytes()
		mustNil(err)

		log.Infof("status: %d, body: %q", res.StatusCode, string(body))
	}

	mustNil(log.Close())
}

server.go

package main

import (
	"github.com/blend/go-sdk/graceful"
	"github.com/blend/go-sdk/logger"
	"github.com/blend/go-sdk/r2"
	"github.com/blend/go-sdk/stats/tracing"
	"github.com/blend/go-sdk/stats/tracing/r2trace"
	"github.com/blend/go-sdk/stats/tracing/webtrace"
	"github.com/blend/go-sdk/web"
	opentracing "github.com/opentracing/opentracing-go"
	"gopkg.in/DataDog/dd-trace-go.v1/ddtrace"
	ddopentracer "gopkg.in/DataDog/dd-trace-go.v1/ddtrace/opentracer"
	ddtracer "gopkg.in/DataDog/dd-trace-go.v1/ddtrace/tracer"
)

// NOTE: Ensure that
//       * getCurrentContext satisfies spanContextFromCtx
var (
	_ spanContextFromCtx = getCurrentContext
)

type spanContextFromCtx = func(*web.Ctx) (opentracing.SpanContext, error)

type datadogAnnotation struct {
	TraceID uint64 `json:"trace_id"`
	SpanID  uint64 `json:"span_id"`
}

// IsZero returns if the object is set or not.
func (da datadogAnnotation) IsZero() bool {
	return da.TraceID == 0 || da.SpanID == 0
}

func makeGetClientContext(webTracer opentracing.Tracer) spanContextFromCtx {
	return func(r *web.Ctx) (opentracing.SpanContext, error) {
		carrier := opentracing.HTTPHeadersCarrier(r.Request.Header)
		return webTracer.Extract(opentracing.HTTPHeaders, carrier)
	}
}

func getCurrentContextNoErr(r *web.Ctx) opentracing.SpanContext {
	currSpan := opentracing.SpanFromContext(r.Context())
	return currSpan.Context()
}

func getCurrentContext(r *web.Ctx) (opentracing.SpanContext, error) {
	return getCurrentContextNoErr(r), nil
}

func logSpanContext(r *web.Ctx, prefix string, fromCtx spanContextFromCtx) {
	if r.App == nil || r.App.Log == nil {
		return
	}
	log := r.App.Log

	spanCtx, err := fromCtx(r)
	if err != nil {
		log.Error(err)
		return
	}

	da := getDatadogAnnotation(spanCtx)
	if da.IsZero() {
		return
	}

	logger.MaybeInfofContext(
		r.Context(),
		log,
		"%s: dd.trace_id: %d dd.span_id=%d",
		prefix,
		da.TraceID,
		da.SpanID,
	)
}

func getDatadogAnnotation(spanCtx opentracing.SpanContext) datadogAnnotation {
	ddSpanCtx, ok := spanCtx.(ddtrace.SpanContext)
	if !ok {
		return datadogAnnotation{}
	}

	return datadogAnnotation{
		TraceID: ddSpanCtx.TraceID(),
		SpanID:  ddSpanCtx.SpanID(),
	}
}

func rootHandler(webTracer opentracing.Tracer) web.Action {
	getClientContext := makeGetClientContext(webTracer)

	return func(r *web.Ctx) web.Result {
		spanCtx := getCurrentContextNoErr(r)
		da := getDatadogAnnotation(spanCtx)
		newCtx := logger.WithAnnotations(r.Context(), logger.Annotations{"dd": da})
		r.WithContext(newCtx)

		logSpanContext(r, "CLIENT", getClientContext)
		logSpanContext(r, "CURRENT", getCurrentContext)
		return web.Text.Result("ok!")
	}
}

func outboundHandler(webTracer opentracing.Tracer) web.Action {
	reqTracer := r2trace.Tracer(webTracer)

	return func(r *web.Ctx) web.Result {
		spanCtx := getCurrentContextNoErr(r)
		da := getDatadogAnnotation(spanCtx)
		newCtx := logger.WithAnnotations(r.Context(), logger.Annotations{"dd": da})
		r.WithContext(newCtx)

		var log logger.Log
		if r.App != nil {
			log = r.App.Log
		}

		req := r2.New(
			"http://localhost:9090",
			r2.OptHeaderValue("X-Sent-By", "go-sdk/request2"),
			r2.OptLogResponse(log),
			r2.OptContext(r.Context()),
			r2.OptTracer(reqTracer),
		)
		body, res, err := req.Bytes()
		la := logger.Annotations{
			"dd":   da, // TODO: Merge instead of manually glomming on
			"body": string(body),
		}
		if err == nil {
			la["status"] = res.StatusCode
		} else {
			la["err"] = err.Error()
		}

		logger.MaybeInfoContext(
			logger.WithAnnotations(r.Context(), la),
			log,
			"HTTP response",
		)

		return web.Text.Result("outbound")
	}
}

func main() {
	log := logger.MustNew(
		logger.OptAll(),
		logger.OptJSON(),
	)

	app := web.MustNew(
		web.OptConfigFromEnv(),
		web.OptLog(log),
	)
	webTracer := ddopentracer.New(
		ddtracer.WithAgentAddr("localhost:8126"),
		ddtracer.WithServiceName("local-web"),
		ddtracer.WithGlobalTag(tracing.TagKeyEnvironment, "dev"),
	)
	app.Tracer = webtrace.Tracer(webTracer)

	rh := rootHandler(webTracer)
	app.GET("/", rh)
	oh := outboundHandler(webTracer)
	app.GET("/outbound", oh)

	if err := graceful.Shutdown(app); err != nil {
		logger.FatalExit(err)
	}
}