Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Merged
merged 8 commits into from
Mar 14, 2023
1 change: 1 addition & 0 deletions CHANGELOG.md
Original file line number Diff line number Diff line change
@@ -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)
2 changes: 1 addition & 1 deletion stat/transport.go
Original file line number Diff line number Diff line change
@@ -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(
34 changes: 31 additions & 3 deletions transaction/transactor.go
Original file line number Diff line number Diff line change
@@ -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
}
89 changes: 86 additions & 3 deletions transaction/transactor_test.go
Original file line number Diff line number Diff line change
@@ -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)
})
}
}
2 changes: 1 addition & 1 deletion translation/transport.go
Original file line number Diff line number Diff line change
@@ -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(