Merge pull request #391 from xmidt-org/issue-373

Add a structured log field for just the normalized device-id.

CHANGELOG.md

@@ -5,6 +5,7 @@ The format is based on [Keep a Changelog](http://keepachangelog.com/en/1.0.0/)
 and this project adheres to [Semantic Versioning](http://semver.org/spec/v2.0.0.html).
 
 ## [Unreleased]
+- [Add a structured log field for just the normalized device-id. #391](https://github.com/xmidt-org/tr1d1um/pull/391)
 
 ## [v0.9.0]
 - [Tracing working, Correct tracestate spelling, pass on empty tracestate if none is provided #389](https://github.com/xmidt-org/tr1d1um/pull/389)

stat/transport.go

@@ -59,7 +59,7 @@ type Options struct {
 func ConfigHandler(c *Options) {
 	opts := []kithttp.ServerOption{
 		kithttp.ServerErrorEncoder(transaction.ErrorLogEncoder(sallust.Get, encodeError)),
-		kithttp.ServerFinalizer(transaction.Log(c.Log, c.ReducedLoggingResponseCodes)),
+		kithttp.ServerFinalizer(transaction.Log(c.ReducedLoggingResponseCodes)),
 	}
 
 	statHandler := kithttp.NewServer(

transaction/transactor.go

@@ -28,7 +28,9 @@ import (
 	"time"
 
 	kithttp "github.com/go-kit/kit/transport/http"
+	"github.com/gorilla/mux"
 	"github.com/xmidt-org/candlelight"
+	"github.com/xmidt-org/sallust"
 	"go.uber.org/zap"
 )
 
@@ -122,14 +124,16 @@ func (t *transactor) Transact(req *http.Request) (result *XmidtResponse, err err
 
 // Log is used by the different Tr1d1um services to
 // keep track of incoming requests and their corresponding responses
-func Log(logger *zap.Logger, reducedLoggingResponseCodes []int) kithttp.ServerFinalizerFunc {
+func Log(reducedLoggingResponseCodes []int) kithttp.ServerFinalizerFunc {
 	return func(ctx context.Context, code int, r *http.Request) {
 		tid, _ := ctx.Value(ContextKeyRequestTID).(string)
-
+		logger := sallust.Get(ctx)
 		requestArrival, ok := ctx.Value(ContextKeyRequestArrivalTime).(time.Time)
 
 		if !ok {
-			logger = logger.With(zap.Any("duration", time.Since(requestArrival)))
+			logger = logger.With(
+				zap.Any("duration", time.Since(requestArrival)),
+			)
 		} else {
 			traceID, spanID, ok := candlelight.ExtractTraceInfo(ctx)
 			if !ok {
@@ -183,6 +187,7 @@ func Welcome(delegate http.Handler) http.Handler {
 
 			ctx := context.WithValue(r.Context(), ContextKeyRequestTID, tid)
 			ctx = context.WithValue(ctx, ContextKeyRequestArrivalTime, time.Now())
+			ctx = addDeviceIdToLog(ctx, r)
 			delegate.ServeHTTP(w, r.WithContext(ctx))
 		})
 }
@@ -197,3 +202,26 @@ func genTID() (tid string) {
 	}
 	return
 }
+
+// updateLogger updates the logger with a device id field and adds it back into the context.
+func addDeviceIdToLog(ctx context.Context, r *http.Request) context.Context {
+	did := getDeviceId(r)
+	f := zap.String("deviceid", did)
+
+	logger := sallust.Get(ctx)
+	logger = logger.With(f)
+	ctx = sallust.With(ctx, logger)
+
+	return ctx
+}
+
+// getDeviceId extracts device id from the request path params
+func getDeviceId(r *http.Request) string {
+	vars := mux.Vars(r)
+	id := vars["deviceid"]
+	if id == "" {
+		id = "mac:000000000000"
+	}
+
+	return id
+}

transaction/transactor_test.go

@@ -27,12 +27,15 @@ import (
 	"testing"
 	"time"
 
+	"github.com/gorilla/mux"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
 	"github.com/xmidt-org/candlelight"
+	"github.com/xmidt-org/sallust"
 	"go.uber.org/zap"
 	"go.uber.org/zap/zapcore"
 	"go.uber.org/zap/zaptest"
+	"go.uber.org/zap/zaptest/observer"
 )
 
 func TestTransactError(t *testing.T) {
@@ -180,7 +183,6 @@ func TestLog(t *testing.T) {
 	ctxWithArrivalTime := context.WithValue(context.Background(), ContextKeyRequestArrivalTime, time.Date(2009, time.November, 10, 23, 0, 0, 0, time.UTC))
 	tcs := []struct {
 		desc                        string
-		logger                      *zap.Logger
 		reducedLoggingResponseCodes []int
 		ctx                         context.Context
 		code                        int
@@ -222,9 +224,90 @@ func TestLog(t *testing.T) {
 					logCount++
 					return nil
 				})))
-			s := Log(logger, tc.reducedLoggingResponseCodes)
-			s(tc.ctx, tc.code, tc.request)
+			ctx := sallust.With(tc.ctx, logger)
+			s := Log(tc.reducedLoggingResponseCodes)
+			s(ctx, tc.code, tc.request)
 			assert.Equal(tc.expectedLogCount, logCount)
 		})
 	}
 }
+
+func TestAddDeviceIdToLog(t *testing.T) {
+	tests := []struct {
+		desc     string
+		ctx      context.Context
+		req      func() (r *http.Request)
+		deviceid string
+	}{
+		{
+			desc: "device id in request",
+			ctx:  context.Background(),
+			req: func() (r *http.Request) {
+				r = httptest.NewRequest(http.MethodGet, "http://localhost:6100/api/v2/device/", nil)
+				r = mux.SetURLVars(r, map[string]string{"deviceid": "mac:112233445577"})
+				return
+			},
+			deviceid: "mac:112233445577",
+		},
+		{
+			desc: "device id added in code",
+			ctx:  context.Background(),
+			req: func() (r *http.Request) {
+				r = httptest.NewRequest(http.MethodGet, "http://localhost:6100/api/v2/device/", nil)
+				return
+			},
+			deviceid: "mac:000000000000",
+		},
+	}
+	for _, tc := range tests {
+		t.Run(tc.desc, func(t *testing.T) {
+			assert := assert.New(t)
+			observedZapCore, observedLogs := observer.New(zap.DebugLevel)
+			observedLogger := zap.New(observedZapCore)
+			ctx := sallust.With(tc.ctx, observedLogger)
+			ctx = addDeviceIdToLog(ctx, tc.req())
+
+			logger := sallust.Get(ctx)
+			logger.Debug("test")
+			gotLog := observedLogs.All()[0].Context
+
+			assert.Equal("deviceid", gotLog[0].Key)
+			assert.Equal(tc.deviceid, gotLog[0].String)
+
+		})
+	}
+}
+
+func TestGetDeviceId(t *testing.T) {
+	tests := []struct {
+		desc     string
+		req      func() *http.Request
+		expected string
+	}{
+		{
+			desc: "Request has id",
+			req: func() (r *http.Request) {
+				r = httptest.NewRequest(http.MethodGet, "http://localhost:6100/api/v2/device/", nil)
+				r = mux.SetURLVars(r, map[string]string{"deviceid": "mac:112233445577"})
+				return
+			},
+			expected: "mac:112233445577",
+		},
+		{
+			desc: "no id",
+			req: func() (r *http.Request) {
+				r = httptest.NewRequest(http.MethodGet, "http://localhost:6100/api/v2/device/", nil)
+				return
+			},
+			expected: "mac:000000000000",
+		},
+	}
+	for _, tc := range tests {
+		t.Run(tc.desc, func(t *testing.T) {
+			assert := assert.New(t)
+			id := getDeviceId(tc.req())
+			assert.NotNil(id)
+			assert.Equal(tc.expected, id)
+		})
+	}
+}

translation/transport.go

@@ -65,7 +65,7 @@ func ConfigHandler(c *Options) {
 	opts := []kithttp.ServerOption{
 		kithttp.ServerBefore(captureWDMPParameters),
 		kithttp.ServerErrorEncoder(transaction.ErrorLogEncoder(sallust.Get, encodeError)),
-		kithttp.ServerFinalizer(transaction.Log(c.Log, c.ReducedLoggingResponseCodes)),
+		kithttp.ServerFinalizer(transaction.Log(c.ReducedLoggingResponseCodes)),
 	}
 
 	WRPHandler := kithttp.NewServer(