[FSSDK-9840] chore: add traceID & spanID to logs (#407)

pulak-opti · pulak-opti · commit 054b50df99ae · 2023-12-14T00:01:53.000+06:00
* add logging for decide api

* log traceid for trace api

* log traceid for override api

* add traceid for error log

* add traceid into logs

* clean up

* clean up

* update unit test
diff --git a/pkg/handlers/activate.go b/pkg/handlers/activate.go
@@ -22,13 +22,12 @@ import (
 	"fmt"
 	"net/http"
 
+	"github.com/go-chi/render"
+
 	"github.com/optimizely/agent/pkg/middleware"
 	"github.com/optimizely/agent/pkg/optimizely"
-
 	"github.com/optimizely/go-sdk/pkg/config"
 	"github.com/optimizely/go-sdk/pkg/entities"
-
-	"github.com/go-chi/render"
 )
 
 type keyMap map[string]string
@@ -42,12 +41,13 @@ type ActivateBody struct {
 // Activate makes feature and experiment decisions for the selected query parameters.
 func Activate(w http.ResponseWriter, r *http.Request) {
 	optlyClient, err := middleware.GetOptlyClient(r)
-	logger := middleware.GetLogger(r)
 	if err != nil {
 		RenderError(err, http.StatusInternalServerError, w, r)
 		return
 	}
 
+	logger := middleware.GetLogger(r)
+
 	uc, err := getUserContext(r)
 	if err != nil {
 		RenderError(err, http.StatusBadRequest, w, r)
@@ -108,6 +108,7 @@ func Activate(w http.ResponseWriter, r *http.Request) {
 	}
 
 	decisions = filterDecisions(r, decisions)
+	logger.Info().Msgf("Made activate decisions for user %s", uc.ID)
 	render.JSON(w, r, decisions)
 }
 
diff --git a/pkg/handlers/decide.go b/pkg/handlers/decide.go
@@ -21,14 +21,13 @@ import (
 	"errors"
 	"net/http"
 
-	"github.com/optimizely/agent/pkg/middleware"
+	"github.com/go-chi/render"
 
+	"github.com/optimizely/agent/pkg/middleware"
 	"github.com/optimizely/go-sdk/pkg/client"
 	"github.com/optimizely/go-sdk/pkg/decide"
 	"github.com/optimizely/go-sdk/pkg/decision"
 	"github.com/optimizely/go-sdk/pkg/odp/segment"
-
-	"github.com/go-chi/render"
 )
 
 // DecideBody defines the request body for decide API
@@ -108,6 +107,7 @@ func Decide(w http.ResponseWriter, r *http.Request) {
 		key := keys[0]
 		logger.Debug().Str("featureKey", key).Msg("fetching feature decision")
 		d := optimizelyUserContext.Decide(key, decideOptions)
+		logger.Info().Msgf("Feature %q is enabled for user %s? %t", d.FlagKey, d.UserContext.UserID, d.Enabled)
 		decideOut := DecideOut{d, d.Variables.ToMap()}
 		render.JSON(w, r, decideOut)
 		return
@@ -120,6 +120,7 @@ func Decide(w http.ResponseWriter, r *http.Request) {
 	for _, d := range decides {
 		decideOut := DecideOut{d, d.Variables.ToMap()}
 		decideOuts = append(decideOuts, decideOut)
+		logger.Info().Msgf("Feature %q is enabled for user %s? %t", d.FlagKey, d.UserContext.UserID, d.Enabled)
 	}
 	render.JSON(w, r, decideOuts)
 }
diff --git a/pkg/handlers/decide_test.go b/pkg/handlers/decide_test.go
@@ -26,18 +26,17 @@ import (
 	"net/http/httptest"
 	"testing"
 
+	"github.com/go-chi/chi/v5"
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/suite"
+
 	"github.com/optimizely/agent/pkg/middleware"
 	"github.com/optimizely/agent/pkg/optimizely"
 	"github.com/optimizely/agent/pkg/optimizely/optimizelytest"
-
 	"github.com/optimizely/go-sdk/pkg/client"
 	"github.com/optimizely/go-sdk/pkg/decide"
 	"github.com/optimizely/go-sdk/pkg/entities"
 	"github.com/optimizely/go-sdk/pkg/odp/segment"
-
-	"github.com/go-chi/chi/v5"
-	"github.com/stretchr/testify/assert"
-	"github.com/stretchr/testify/suite"
 )
 
 type DecideTestSuite struct {
diff --git a/pkg/handlers/get_datafile.go b/pkg/handlers/get_datafile.go
@@ -34,11 +34,15 @@ func GetDatafile(w http.ResponseWriter, r *http.Request) {
 		return
 	}
 
+	logger := middleware.GetLogger(r)
+
 	datafile := optlyClient.GetOptimizelyConfig().GetDatafile()
 	var raw map[string]interface{}
 	if err = json.Unmarshal([]byte(datafile), &raw); err != nil {
 		RenderError(err, http.StatusInternalServerError, w, r)
 		return
 	}
+
+	logger.Info().Msg("Successfully returned datafile")
 	render.JSON(w, r, raw)
 }
diff --git a/pkg/handlers/lookup.go b/pkg/handlers/lookup.go
@@ -21,9 +21,9 @@ import (
 	"errors"
 	"net/http"
 
-	"github.com/optimizely/agent/pkg/middleware"
-
 	"github.com/go-chi/render"
+
+	"github.com/optimizely/agent/pkg/middleware"
 )
 
 type lookupBody struct {
@@ -47,6 +47,8 @@ func Lookup(w http.ResponseWriter, r *http.Request) {
 		return
 	}
 
+	logger := middleware.GetLogger(r)
+
 	if optlyClient.UserProfileService == nil {
 		RenderError(ErrNoUPS, http.StatusInternalServerError, w, r)
 		return
@@ -75,5 +77,6 @@ func Lookup(w http.ResponseWriter, r *http.Request) {
 		experimentBucketMap[k.ExperimentID] = map[string]interface{}{k.Field: v}
 	}
 	lookupResponse.ExperimentBucketMap = experimentBucketMap
+	logger.Info().Msgf("Looked up user profile for user %s", body.UserID)
 	render.JSON(w, r, lookupResponse)
 }
diff --git a/pkg/handlers/optimizely_config.go b/pkg/handlers/optimizely_config.go
@@ -33,6 +33,9 @@ func OptimizelyConfig(w http.ResponseWriter, r *http.Request) {
 		return
 	}
 
+	logger := middleware.GetLogger(r)
+
 	conf := optlyClient.GetOptimizelyConfig()
+	logger.Info().Msg("Successfully returned OptimizelyConfig")
 	render.JSON(w, r, conf)
 }
diff --git a/pkg/handlers/override.go b/pkg/handlers/override.go
@@ -69,10 +69,10 @@ func Override(w http.ResponseWriter, r *http.Request) {
 		return
 	}
 
-	logger.Debug().Str("experimentKey", experimentKey).Str("variationKey", body.VariationKey).Msg("setting override")
 	if override, err := optlyClient.SetForcedVariation(r.Context(), experimentKey, body.UserID, body.VariationKey); err != nil {
 		RenderError(err, http.StatusInternalServerError, w, r)
 	} else {
+		logger.Info().Str("experimentKey", experimentKey).Str("variationKey", body.VariationKey).Msg("Successfully set override")
 		render.JSON(w, r, override)
 	}
 }
diff --git a/pkg/handlers/save.go b/pkg/handlers/save.go
@@ -20,10 +20,10 @@ package handlers
 import (
 	"net/http"
 
+	"github.com/go-chi/render"
+
 	"github.com/optimizely/agent/pkg/middleware"
 	"github.com/optimizely/go-sdk/pkg/decision"
-
-	"github.com/go-chi/render"
 )
 
 type saveBody struct {
@@ -38,6 +38,8 @@ func Save(w http.ResponseWriter, r *http.Request) {
 		return
 	}
 
+	logger := middleware.GetLogger(r)
+
 	if optlyClient.UserProfileService == nil {
 		RenderError(ErrNoUPS, http.StatusInternalServerError, w, r)
 		return
@@ -58,6 +60,7 @@ func Save(w http.ResponseWriter, r *http.Request) {
 
 	convertedProfile := convertToUserProfile(body)
 	optlyClient.UserProfileService.Save(convertedProfile)
+	logger.Info().Msgf("Saved user profile for user %s", body.UserID)
 	render.Status(r, http.StatusOK)
 }
 
diff --git a/pkg/handlers/send_odp_event.go b/pkg/handlers/send_odp_event.go
@@ -22,10 +22,10 @@ import (
 	"net/http"
 
 	"github.com/go-chi/render"
-	"github.com/optimizely/go-sdk/pkg/odp/event"
 
 	"github.com/optimizely/agent/pkg/middleware"
 	"github.com/optimizely/agent/pkg/optimizely"
+	"github.com/optimizely/go-sdk/pkg/odp/event"
 )
 
 // SendOdpEvent sends event to ODP platform
@@ -36,6 +36,8 @@ func SendOdpEvent(w http.ResponseWriter, r *http.Request) {
 		return
 	}
 
+	logger := middleware.GetLogger(r)
+
 	body, err := getRequestOdpEvent(r)
 	if err != nil {
 		RenderError(err, http.StatusBadRequest, w, r)
@@ -52,6 +54,7 @@ func SendOdpEvent(w http.ResponseWriter, r *http.Request) {
 		Success: true,
 	}
 
+	logger.Info().Msg("Successfully sent event to ODP platform")
 	render.JSON(w, r, returnResult)
 }
 
diff --git a/pkg/handlers/track.go b/pkg/handlers/track.go
@@ -22,9 +22,9 @@ import (
 	"net/http"
 
 	"github.com/go-chi/render"
-	"github.com/optimizely/go-sdk/pkg/entities"
 
 	"github.com/optimizely/agent/pkg/middleware"
+	"github.com/optimizely/go-sdk/pkg/entities"
 )
 
 type trackBody struct {
@@ -40,6 +40,7 @@ func TrackEvent(w http.ResponseWriter, r *http.Request) {
 		RenderError(err, http.StatusInternalServerError, w, r)
 		return
 	}
+	logger := middleware.GetLogger(r)
 
 	var body trackBody
 	err = ParseRequestBody(r, &body)
@@ -66,6 +67,6 @@ func TrackEvent(w http.ResponseWriter, r *http.Request) {
 		return
 	}
 
-	middleware.GetLogger(r).Debug().Str("eventKey", eventKey).Msg("tracking event")
+	logger.Info().Str("eventKey", eventKey).Msg("tracked event")
 	render.JSON(w, r, track)
 }
diff --git a/pkg/handlers/utils.go b/pkg/handlers/utils.go
@@ -35,7 +35,7 @@ type ErrorResponse struct {
 
 // RenderError sets the request status and renders the error message.
 func RenderError(err error, status int, w http.ResponseWriter, r *http.Request) {
-	middleware.GetLogger(r).Info().Err(err).Int("status", status).Msg("render error")
+	middleware.GetLogger(r).Err(err).Int("status", status).Msg("render error")
 	render.Status(r, status)
 	render.JSON(w, r, ErrorResponse{Error: err.Error()})
 }
@@ -44,22 +44,24 @@ func RenderError(err error, status int, w http.ResponseWriter, r *http.Request)
 // into the provided interface. Note that we're sanitizing the returned error
 // so that it is not leaked back to the requestor.
 func ParseRequestBody(r *http.Request, v interface{}) error {
+	logger := middleware.GetLogger(r)
+
 	body, err := io.ReadAll(r.Body)
 	if err != nil {
 		msg := "error reading request body"
-		middleware.GetLogger(r).Error().Err(err).Msg(msg)
+		logger.Err(err).Msg(msg)
 		return fmt.Errorf("%s", msg)
 	}
 
 	if len(body) == 0 {
-		middleware.GetLogger(r).Debug().Msg("body was empty skip JSON unmarshal")
+		logger.Info().Msg("body was empty skip JSON unmarshal")
 		return nil
 	}
 
 	err = json.Unmarshal(body, &v)
 	if err != nil {
 		msg := "error parsing request body"
-		middleware.GetLogger(r).Error().Err(err).Msg(msg)
+		logger.Err(err).Msg(msg)
 		return fmt.Errorf("%s", msg)
 	}
 
diff --git a/pkg/middleware/utils.go b/pkg/middleware/utils.go
@@ -23,13 +23,13 @@ import (
 	"strconv"
 	"strings"
 
-	"github.com/optimizely/agent/pkg/optimizely"
-
-	"github.com/optimizely/go-sdk/pkg/config"
-
 	"github.com/go-chi/render"
 	"github.com/rs/zerolog"
 	"github.com/rs/zerolog/log"
+	"go.opentelemetry.io/otel/trace"
+
+	"github.com/optimizely/agent/pkg/optimizely"
+	"github.com/optimizely/go-sdk/pkg/config"
 )
 
 // ErrorResponse Model
@@ -52,6 +52,12 @@ func GetLogger(r *http.Request) *zerolog.Logger {
 	reqID := r.Header.Get(OptlyRequestHeader)
 	logger := log.With().Str("requestId", reqID).Logger()
 
+	span := trace.SpanFromContext(r.Context())
+	if span.SpanContext().TraceID().IsValid() {
+		logger = logger.With().Str("traceId", span.SpanContext().TraceID().String()).Logger()
+		logger = logger.With().Str("spanId", span.SpanContext().SpanID().String()).Logger()
+	}
+
 	if optimizely.ShouldIncludeSDKKey {
 		sdkKey := r.Header.Get(OptlySDKHeader)
 		sdkKeySplit := strings.Split(sdkKey, ":")
diff --git a/pkg/middleware/utils_test.go b/pkg/middleware/utils_test.go
@@ -21,13 +21,15 @@ import (
 	"bytes"
 	"context"
 	"encoding/json"
+	"fmt"
 	"net/http/httptest"
 	"testing"
 
 	"github.com/stretchr/testify/assert"
+	"go.opentelemetry.io/otel"
+	"go.opentelemetry.io/otel/propagation"
 
 	"github.com/optimizely/agent/pkg/optimizely"
-
 	"github.com/optimizely/go-sdk/pkg/config"
 )
 
@@ -54,22 +56,36 @@ func TestGetLogger(t *testing.T) {
 	out := &bytes.Buffer{}
 	req := httptest.NewRequest("GET", "/", nil)
 
+	traceId := "0af7651916cd43dd8448eb211c80319c"
+	spanId := "b9c7c989f97918e1"
+
 	req.Header.Set(OptlyRequestHeader, "12345")
 	req.Header.Set(OptlySDKHeader, "some_key")
-	logger := GetLogger(req)
+	req.Header.Set("traceparent", fmt.Sprintf("00-%s-%s-01", traceId, spanId))
+
+	otel.SetTextMapPropagator(propagation.TraceContext{})
+	ctx := otel.GetTextMapPropagator().Extract(req.Context(), propagation.HeaderCarrier(req.Header))
+
+	logger := GetLogger(req.WithContext(ctx))
 	newLogger := logger.Output(out)
 	newLogger.Info().Msg("some_message")
 
 	assert.Contains(t, out.String(), `"requestId":"12345"`)
 	assert.Contains(t, out.String(), `"sdkKey":"some_key"`)
 
+	assert.Contains(t, out.String(), `"traceId":"`+traceId+`"`)
+	assert.Contains(t, out.String(), `"spanId":"`+spanId+`"`)
+
 	optimizely.ShouldIncludeSDKKey = false
 	out = &bytes.Buffer{}
 	logger = GetLogger(req)
 	newLogger = logger.Output(out)
 	newLogger.Info().Msg("some_message")
 	assert.Contains(t, out.String(), `"requestId":"12345"`)
 	assert.NotContains(t, out.String(), `"sdkKey":"some_key"`)
+
+	assert.NotContains(t, out.String(), `"traceId":"`+traceId+`"`)
+	assert.NotContains(t, out.String(), `"spanId":"`+spanId+`"`)
 }
 
 func TestGetFeature(t *testing.T) {

Original file line number	Diff line number	Diff line change
`@@ -34,11 +34,15 @@ func GetDatafile(w http.ResponseWriter, r *http.Request) {`
`34`	`34`	`return`
`35`	`35`	`}`
`36`	`36`
	`37`	`+ logger := middleware.GetLogger(r)`
	`38`	`+`
`37`	`39`	`datafile := optlyClient.GetOptimizelyConfig().GetDatafile()`
`38`	`40`	`var raw map[string]interface{}`
`39`	`41`	`if err = json.Unmarshal([]byte(datafile), &raw); err != nil {`
`40`	`42`	`RenderError(err, http.StatusInternalServerError, w, r)`
`41`	`43`	`return`
`42`	`44`	`}`
	`45`	`+`
	`46`	`+ logger.Info().Msg("Successfully returned datafile")`
`43`	`47`	`render.JSON(w, r, raw)`
`44`	`48`	`}`
Original file line number	Diff line number	Diff line change
`@@ -21,9 +21,9 @@ import (`
`21`	`21`	`"errors"`
`22`	`22`	`"net/http"`
`23`	`23`
`24`		`- "github.com/optimizely/agent/pkg/middleware"`
`25`		`-`
`26`	`24`	`"github.com/go-chi/render"`
	`25`	`+`
	`26`	`+ "github.com/optimizely/agent/pkg/middleware"`
`27`	`27`	`)`
`28`	`28`
`29`	`29`	`type lookupBody struct {`
`@@ -47,6 +47,8 @@ func Lookup(w http.ResponseWriter, r *http.Request) {`
`47`	`47`	`return`
`48`	`48`	`}`
`49`	`49`
	`50`	`+ logger := middleware.GetLogger(r)`
	`51`	`+`
`50`	`52`	`if optlyClient.UserProfileService == nil {`
`51`	`53`	`RenderError(ErrNoUPS, http.StatusInternalServerError, w, r)`
`52`	`54`	`return`
`@@ -75,5 +77,6 @@ func Lookup(w http.ResponseWriter, r *http.Request) {`
`75`	`77`	`experimentBucketMap[k.ExperimentID] = map[string]interface{}{k.Field: v}`
`76`	`78`	`}`
`77`	`79`	`lookupResponse.ExperimentBucketMap = experimentBucketMap`
	`80`	`+ logger.Info().Msgf("Looked up user profile for user %s", body.UserID)`
`78`	`81`	`render.JSON(w, r, lookupResponse)`
`79`	`82`	`}`
Original file line number	Diff line number	Diff line change
`@@ -33,6 +33,9 @@ func OptimizelyConfig(w http.ResponseWriter, r *http.Request) {`
`33`	`33`	`return`
`34`	`34`	`}`
`35`	`35`
	`36`	`+ logger := middleware.GetLogger(r)`
	`37`	`+`
`36`	`38`	`conf := optlyClient.GetOptimizelyConfig()`
	`39`	`+ logger.Info().Msg("Successfully returned OptimizelyConfig")`
`37`	`40`	`render.JSON(w, r, conf)`
`38`	`41`	`}`
Original file line number	Diff line number	Diff line change
`@@ -69,10 +69,10 @@ func Override(w http.ResponseWriter, r *http.Request) {`
`69`	`69`	`return`
`70`	`70`	`}`
`71`	`71`
`72`		`- logger.Debug().Str("experimentKey", experimentKey).Str("variationKey", body.VariationKey).Msg("setting override")`
`73`	`72`	`if override, err := optlyClient.SetForcedVariation(r.Context(), experimentKey, body.UserID, body.VariationKey); err != nil {`
`74`	`73`	`RenderError(err, http.StatusInternalServerError, w, r)`
`75`	`74`	`} else {`
	`75`	`+ logger.Info().Str("experimentKey", experimentKey).Str("variationKey", body.VariationKey).Msg("Successfully set override")`
`76`	`76`	`render.JSON(w, r, override)`
`77`	`77`	`}`
`78`	`78`	`}`
Original file line number	Diff line number	Diff line change
`@@ -22,10 +22,10 @@ import (`
`22`	`22`	`"net/http"`
`23`	`23`
`24`	`24`	`"github.com/go-chi/render"`
`25`		`- "github.com/optimizely/go-sdk/pkg/odp/event"`
`26`	`25`
`27`	`26`	`"github.com/optimizely/agent/pkg/middleware"`
`28`	`27`	`"github.com/optimizely/agent/pkg/optimizely"`
	`28`	`+ "github.com/optimizely/go-sdk/pkg/odp/event"`
`29`	`29`	`)`
`30`	`30`
`31`	`31`	`// SendOdpEvent sends event to ODP platform`
`@@ -36,6 +36,8 @@ func SendOdpEvent(w http.ResponseWriter, r *http.Request) {`
`36`	`36`	`return`
`37`	`37`	`}`
`38`	`38`
	`39`	`+ logger := middleware.GetLogger(r)`
	`40`	`+`
`39`	`41`	`body, err := getRequestOdpEvent(r)`
`40`	`42`	`if err != nil {`
`41`	`43`	`RenderError(err, http.StatusBadRequest, w, r)`
`@@ -52,6 +54,7 @@ func SendOdpEvent(w http.ResponseWriter, r *http.Request) {`
`52`	`54`	`Success: true,`
`53`	`55`	`}`
`54`	`56`
	`57`	`+ logger.Info().Msg("Successfully sent event to ODP platform")`
`55`	`58`	`render.JSON(w, r, returnResult)`
`56`	`59`	`}`
`57`	`60`
Original file line number	Diff line number	Diff line change
`@@ -22,9 +22,9 @@ import (`
`22`	`22`	`"net/http"`
`23`	`23`
`24`	`24`	`"github.com/go-chi/render"`
`25`		`- "github.com/optimizely/go-sdk/pkg/entities"`
`26`	`25`
`27`	`26`	`"github.com/optimizely/agent/pkg/middleware"`
	`27`	`+ "github.com/optimizely/go-sdk/pkg/entities"`
`28`	`28`	`)`
`29`	`29`
`30`	`30`	`type trackBody struct {`
`@@ -40,6 +40,7 @@ func TrackEvent(w http.ResponseWriter, r *http.Request) {`
`40`	`40`	`RenderError(err, http.StatusInternalServerError, w, r)`
`41`	`41`	`return`
`42`	`42`	`}`
	`43`	`+ logger := middleware.GetLogger(r)`
`43`	`44`
`44`	`45`	`var body trackBody`
`45`	`46`	`err = ParseRequestBody(r, &body)`
`@@ -66,6 +67,6 @@ func TrackEvent(w http.ResponseWriter, r *http.Request) {`
`66`	`67`	`return`
`67`	`68`	`}`
`68`	`69`
`69`		`- middleware.GetLogger(r).Debug().Str("eventKey", eventKey).Msg("tracking event")`
	`70`	`+ logger.Info().Str("eventKey", eventKey).Msg("tracked event")`
`70`	`71`	`render.JSON(w, r, track)`
`71`	`72`	`}`