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

* 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

go.mod

@@ -25,6 +25,7 @@ require (
 	go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp v1.19.0
 	go.opentelemetry.io/otel/exporters/stdout/stdouttrace v1.19.0
 	go.opentelemetry.io/otel/sdk v1.19.0
+	go.opentelemetry.io/otel/trace v1.19.0
 	golang.org/x/crypto v0.11.0
 	golang.org/x/sync v0.3.0
 	gopkg.in/yaml.v2 v2.4.0
@@ -42,7 +43,6 @@ require (
 	github.com/prometheus/common v0.30.0 // indirect
 	github.com/prometheus/procfs v0.7.3 // indirect
 	go.opentelemetry.io/otel/metric v1.19.0 // indirect
-	go.opentelemetry.io/otel/trace v1.19.0 // indirect
 	go.opentelemetry.io/proto/otlp v1.0.0 // indirect
 	golang.org/x/net v0.12.0 // indirect
 	google.golang.org/genproto/googleapis/api v0.0.0-20230711160842-782d3b101e98 // indirect

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)
 }
 

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)
 }

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 {

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)
 }

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)
 }

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)
 }

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)
 	}
 }

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)
 }
 

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)
 }
 

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)
 }

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)
 	}
 

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, ":")

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) {