tracing refactor

CHANGELOG.md

@@ -8,10 +8,11 @@ and this project adheres to [Semantic Versioning](http://semver.org/spec/v2.0.0.
 ### Added
 - Gzip support.
 - `Update` method to `Store` interface.
+- Additional Opentracing span to capture target request.
+- _Average Target Response Time_ Grafana panel.
 ### Changed
 - Fixed [#61](https://github.com/northwesternmutual/kanali/issues/61)
 - Fixed [#57](https://github.com/northwesternmutual/kanali/issues/57).
-- Using Alpine as base Docker image.
 - Using versioned API key plugin in distributed `Dockefile` and examples.
 - Refactored configuration items.
 - Using `TOML` as configuration format in distribution and examples.

Dockerfile

@@ -1,25 +1,12 @@
 ARG GO_VERSION=1.8.3
-ARG ALPINE_VERSION=3.6
+ARG CENTOS_VERSION=7
 
-FROM golang:${GO_VERSION}-alpine${ALPINE_VERSION} AS BUILD
+FROM golang:${GO_VERSION} AS BUILD
 LABEL maintainer="frankgreco@northwesternmutual.com"
 LABEL version="${VERSION}"
 ARG VERSION=""
 ARG GLIDE_VERSION=0.12.3
 WORKDIR /go/src/github.com/northwesternmutual/kanali/
-RUN apk add --update curl \
-                     build-base \
-                     gcc \
-                     abuild \
-                     binutils \
-                     binutils-doc \
-                     gcc-doc \
-                     git \
-                     make \
-                     wget \
-    && apk update \
-    && apk add ca-certificates \
-    && update-ca-certificates
 RUN wget "https://github.com/Masterminds/glide/releases/download/v${GLIDE_VERSION}/glide-v${GLIDE_VERSION}-`go env GOHOSTOS`-`go env GOHOSTARCH`.tar.gz" -O /tmp/glide.tar.gz \
     && mkdir /tmp/glide \
     && tar --directory=/tmp/glide -xvf /tmp/glide.tar.gz \
@@ -33,11 +20,9 @@ RUN curl -O https://raw.githubusercontent.com/northwesternmutual/kanali-plugin-a
 RUN GOOS=`go env GOHOSTOS` GOARCH=`go env GOHOSTARCH` go build -buildmode=plugin -o apiKey_v1.1.0.so plugin.go
 RUN GOOS=`go env GOHOSTOS` GOARCH=`go env GOHOSTARCH` go build -o kanali
 
-FROM alpine:${ALPINE_VERSION}
+FROM centos:${CENTOS_VERSION}
 LABEL maintainer="frankgreco@northwesternmutual.com"
 LABEL version="${VERSION}"
 COPY --from=BUILD /go/src/github.com/northwesternmutual/kanali/apiKey_v1.1.0.so  /go/src/github.com/northwesternmutual/kanali/kanali /
-RUN apk add --update ca-certificates \
-    && update-ca-certificates \
-    && cp apiKey_v1.1.0.so apiKey.so
+RUN cp /apiKey_v1.1.0.so /apiKey.so
 ENTRYPOINT ["/kanali"]

flow/flow.go

@@ -27,6 +27,7 @@ import (
 	"github.com/Sirupsen/logrus"
 	"github.com/northwesternmutual/kanali/controller"
 	"github.com/northwesternmutual/kanali/metrics"
+	"github.com/northwesternmutual/kanali/tracer"
 	"github.com/opentracing/opentracing-go"
 )
 
@@ -46,7 +47,7 @@ func (f *Flow) Play(ctx context.Context, metrics *metrics.Metrics, ctlr *control
 	for _, step := range *f {
 		logrus.Debugf("playing step %s", step.GetName())
 		if err := step.Do(ctx, metrics, ctlr, w, r, resp, trace); err != nil {
-			trace.SetTag("error", true)
+			trace.SetTag(tracer.Error, true)
 			trace.LogKV(
 				"event", "error",
 				"error.message", err.Error(),
@@ -55,5 +56,4 @@ func (f *Flow) Play(ctx context.Context, metrics *metrics.Metrics, ctlr *control
 		}
 	}
 	return nil
-
 }

handlers/handler.go

@@ -30,13 +30,12 @@ import (
 	"time"
 
 	"github.com/Sirupsen/logrus"
-	"github.com/northwesternmutual/kanali/config"
 	"github.com/northwesternmutual/kanali/controller"
 	"github.com/northwesternmutual/kanali/metrics"
 	"github.com/northwesternmutual/kanali/monitor"
+	"github.com/northwesternmutual/kanali/tracer"
 	"github.com/northwesternmutual/kanali/utils"
 	"github.com/opentracing/opentracing-go"
-	"github.com/spf13/viper"
 )
 
 // Handler is used to provide additional parameters to an HTTP handler
@@ -69,98 +68,78 @@ func (h Handler) serveHTTP(w http.ResponseWriter, r *http.Request) {
 		}()
 	}()
 
-	// start a global trace
 	sp := opentracing.StartSpan(fmt.Sprintf("%s %s",
 		r.Method,
 		r.URL.EscapedPath(),
 	))
-
-	closer, str, err := utils.DupReaderAndString(r.Body)
-	if err != nil {
-		logrus.Errorf("error copying request body: %s", err.Error())
-	}
-
-	// copy new reader into freshly drained reader
-	r.Body = closer
-
-	sp.SetTag("http.request_body", str)
-	sp.SetTag("http.url", r.URL.EscapedPath())
-	sp.SetTag("http.method", r.Method)
-
-	jsonHeaders, err := json.Marshal(utils.FlattenHTTPHeaders(utils.OmitHeaderValues(r.Header, viper.GetString(config.FlagProxyHeaderMaskValue.GetLong()), viper.GetStringSlice(config.FlagProxyMaskHeaderKeys.GetLong())...)))
-	if err != nil {
-		logrus.Warnf("could not marsah request headers into JSON - tracing data maybe not be as expected")
-	} else {
-		sp.SetTag("http.headers", string(jsonHeaders))
-	}
-
 	defer sp.Finish()
 
-	err = h.H(context.Background(), m, h.Controller, w, r, sp)
+	tracer.HydrateSpanFromRequest(r, sp)
 
-	// handle request errors
-	if err != nil {
+	err := h.H(context.Background(), m, h.Controller, w, r, sp)
+	if err == nil {
+		return
+	}
 
-		// all errors will need the application/json Content-Type header
-		w.Header().Set("Content-Type", "application/json")
+	// all errors will need the application/json Content-Type header
+	w.Header().Set("Content-Type", "application/json")
 
-		// we'll have multiple types off errors
-		switch e := err.(type) {
-		case utils.Error:
+	// we'll have multiple types off errors
+	switch e := err.(type) {
+	case utils.Error:
 
-			sp.SetTag("http.status_code", e.Status())
+		sp.SetTag(tracer.HTTPResponseStatusCode, e.Status())
 
-			// log error
-			logrus.WithFields(logrus.Fields{
-				"method": r.Method,
-				"uri":    r.URL.EscapedPath(),
-			}).Error(e.Error())
+		// log error
+		logrus.WithFields(logrus.Fields{
+			"method": r.Method,
+			"uri":    r.URL.EscapedPath(),
+		}).Error(e.Error())
 
-			m.Add(metrics.Metric{Name: "http_response_code", Value: strconv.Itoa(e.Status()), Index: true})
+		m.Add(metrics.Metric{Name: "http_response_code", Value: strconv.Itoa(e.Status()), Index: true})
 
-			errStatus, err := json.Marshal(utils.JSONErr{Code: e.Status(), Msg: e.Error()})
-			if err != nil {
-				logrus.Warnf("could not marsah request headers into JSON - tracing data maybe not be as expected")
-			} else {
-				sp.SetTag("http.response_body", string(errStatus))
-			}
+		errStatus, err := json.Marshal(utils.JSONErr{Code: e.Status(), Msg: e.Error()})
+		if err != nil {
+			logrus.Warnf("could not marsah request headers into JSON - tracing data maybe not be as expected")
+		} else {
+			sp.SetTag(tracer.HTTPResponseBody, string(errStatus))
+		}
 
-			// write error code to response
-			w.WriteHeader(e.Status())
+		// write error code to response
+		w.WriteHeader(e.Status())
 
-			// write error message to response
-			if err := json.NewEncoder(w).Encode(utils.JSONErr{Code: e.Status(), Msg: e.Error()}); err != nil {
-				logrus.Fatal(err.Error())
-			}
+		// write error message to response
+		if err := json.NewEncoder(w).Encode(utils.JSONErr{Code: e.Status(), Msg: e.Error()}); err != nil {
+			logrus.Fatal(err.Error())
+		}
 
-		default:
+	default:
 
-			sp.SetTag("http.status_code", http.StatusInternalServerError)
+		sp.SetTag(tracer.HTTPResponseStatusCode, http.StatusInternalServerError)
 
-			// log error
-			logrus.WithFields(logrus.Fields{
-				"method": r.Method,
-				"uri":    r.URL.EscapedPath(),
-			}).Error("unknown error")
+		// log error
+		logrus.WithFields(logrus.Fields{
+			"method": r.Method,
+			"uri":    r.URL.EscapedPath(),
+		}).Error("unknown error")
 
-			m.Add(metrics.Metric{Name: "http_response_code", Value: strconv.Itoa(http.StatusInternalServerError), Index: true})
+		m.Add(metrics.Metric{Name: "http_response_code", Value: strconv.Itoa(http.StatusInternalServerError), Index: true})
 
-			errStatus, err := json.Marshal(utils.JSONErr{Code: http.StatusInternalServerError, Msg: "unknown error"})
-			if err != nil {
-				logrus.Warnf("could not marsah request headers into JSON - tracing data maybe not be as expected")
-			} else {
-				sp.SetTag("http.response_body", string(errStatus))
-			}
-
-			// write error code to response
-			w.WriteHeader(http.StatusInternalServerError)
+		errStatus, err := json.Marshal(utils.JSONErr{Code: http.StatusInternalServerError, Msg: "unknown error"})
+		if err != nil {
+			logrus.Warnf("could not marsah request headers into JSON - tracing data maybe not be as expected")
+		} else {
+			sp.SetTag(tracer.HTTPResponseBody, string(errStatus))
+		}
 
-			// write error message to response
-			if err := json.NewEncoder(w).Encode(utils.JSONErr{Code: http.StatusInternalServerError, Msg: "unknown error"}); err != nil {
-				logrus.Fatal(err.Error())
-			}
+		// write error code to response
+		w.WriteHeader(http.StatusInternalServerError)
 
+		// write error message to response
+		if err := json.NewEncoder(w).Encode(utils.JSONErr{Code: http.StatusInternalServerError, Msg: "unknown error"}); err != nil {
+			logrus.Fatal(err.Error())
 		}
+
 	}
 }
 

helm/values.yaml

@@ -1,7 +1,7 @@
 
-imageRegistry: northwesternmutual
+imageRegistry: fbgrecojr
 
-dockerImageTag: latest
+dockerImageTag: test
 
 pullPolicy: Always
 

steps/proxypass.go

@@ -29,12 +29,14 @@ import (
 	"net/http"
 	"net/url"
 	"strings"
+	"time"
 
 	"github.com/Sirupsen/logrus"
 	"github.com/northwesternmutual/kanali/config"
 	"github.com/northwesternmutual/kanali/controller"
 	"github.com/northwesternmutual/kanali/metrics"
 	"github.com/northwesternmutual/kanali/spec"
+	"github.com/northwesternmutual/kanali/tracer"
 	"github.com/northwesternmutual/kanali/utils"
 	"github.com/opentracing/opentracing-go"
 	"github.com/spf13/viper"
@@ -83,7 +85,7 @@ func (step ProxyPassStep) Do(ctx context.Context, m *metrics.Metrics, c *control
 		Target: typedProxy, // shouldn't be nil (unless the proxy is removed within the microseconds it takes to get to this code)
 	}
 
-	up := create(p).setUpstreamURL(p).configureTLS(p).setUpstreamHeaders(p).performProxy(trace)
+	up := create(p).setUpstreamURL(p).configureTLS(p).setUpstreamHeaders(p).performProxy(m, trace)
 
 	if up.Error != (utils.StatusError{}) {
 		logrus.Errorf("error performing proxypass: %s", up.Error)
@@ -226,34 +228,44 @@ func (up *upstream) setUpstreamHeaders(p *proxy) *upstream {
 
 }
 
-func (up *upstream) performProxy(trace opentracing.Span) *upstream {
-
+func (up *upstream) performProxy(m *metrics.Metrics, span opentracing.Span) *upstream {
 	if up.Error != (utils.StatusError{}) {
 		return up
 	}
 
-	logrus.Infof("upstream url: %s", up.Request.URL.String())
-
-	err := trace.Tracer().Inject(trace.Context(),
+	if err := span.Tracer().Inject(
+		span.Context(),
 		opentracing.TextMap,
-		opentracing.HTTPHeadersCarrier(up.Request.Header))
-
-	if err != nil {
-		logrus.Error("could not inject headers")
+		opentracing.HTTPHeadersCarrier(up.Request.Header),
+	); err != nil {
+		logrus.Error("error injecting headers")
 	}
 
+	sp := opentracing.StartSpan(fmt.Sprintf("%s %s",
+		up.Request.Method,
+		up.Request.URL.EscapedPath(),
+	), opentracing.ChildOf(span.Context()))
+	defer sp.Finish()
+
+	tracer.HydrateSpanFromRequest(up.Request, sp)
+
+	t0 := time.Now()
 	resp, err := up.Client.Do(up.Request)
 	if err != nil {
 		up.Error = utils.StatusError{
 			Code: http.StatusInternalServerError,
 			Err:  err,
 		}
-	} else {
-		up.Response = resp
 	}
 
-	return up
+	m.Add(
+		metrics.Metric{Name: "total_target_time", Value: int(time.Now().Sub(t0) / time.Millisecond), Index: false},
+	)
 
+	tracer.HydrateSpanFromResponse(resp, sp)
+
+	up.Response = resp
+	return up
 }
 
 func (p *proxy) setK8sDiscoveredURI() (*url.URL, *utils.StatusError) {

steps/validateproxy.go

@@ -29,6 +29,7 @@ import (
 	"github.com/northwesternmutual/kanali/controller"
 	"github.com/northwesternmutual/kanali/metrics"
 	"github.com/northwesternmutual/kanali/spec"
+	"github.com/northwesternmutual/kanali/tracer"
 	"github.com/northwesternmutual/kanali/utils"
 	"github.com/opentracing/opentracing-go"
 )
@@ -52,8 +53,8 @@ func (step ValidateProxyStep) Do(ctx context.Context, m *metrics.Metrics, c *con
 			logrus.Error(err.Error())
 		}
 
-		trace.SetTag("kanali.proxy_name", "unknown")
-		trace.SetTag("kanali.proxy_namespace", "unknown")
+		trace.SetTag(tracer.KanaliProxyName, "unknown")
+		trace.SetTag(tracer.KanaliProxyNamespace, "unknown")
 
 		m.Add(
 			metrics.Metric{Name: "proxy_name", Value: "unknown", Index: true},
@@ -66,8 +67,8 @@ func (step ValidateProxyStep) Do(ctx context.Context, m *metrics.Metrics, c *con
 	proxy, ok := untypedProxy.(spec.APIProxy)
 	if !ok {
 
-		trace.SetTag("kanali.proxy_name", "unknown")
-		trace.SetTag("kanali.proxy_namespace", "unknown")
+		trace.SetTag(tracer.KanaliProxyName, "unknown")
+		trace.SetTag(tracer.KanaliProxyNamespace, "unknown")
 
 		m.Add(
 			metrics.Metric{Name: "proxy_name", Value: "unknown", Index: true},
@@ -77,8 +78,8 @@ func (step ValidateProxyStep) Do(ctx context.Context, m *metrics.Metrics, c *con
 		return utils.StatusError{Code: http.StatusNotFound, Err: errors.New("proxy not found")}
 	}
 
-	trace.SetTag("kanali.proxy_name", proxy.ObjectMeta.Name)
-	trace.SetTag("kanali.proxy_namespace", proxy.ObjectMeta.Namespace)
+	trace.SetTag(tracer.KanaliProxyName, proxy.ObjectMeta.Name)
+	trace.SetTag(tracer.KanaliProxyNamespace, proxy.ObjectMeta.Namespace)
 
 	m.Add(
 		metrics.Metric{Name: "proxy_name", Value: proxy.ObjectMeta.Name, Index: true},