diff --git a/go.mod b/go.mod index fcb03a04..8dd7d3a6 100644 --- a/go.mod +++ b/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 diff --git a/pkg/handlers/activate.go b/pkg/handlers/activate.go index 4a48f90a..2768f919 100644 --- 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 index 1b32e81f..cb8908dd 100644 --- 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 index c047da4d..7eef55c2 100644 --- 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 index 368374ba..d458cb1b 100644 --- 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 index 0682d298..30298d2c 100644 --- 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 index 1659cbf5..5ad19a4d 100644 --- 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 index dff9aa9e..36cb3ec4 100644 --- 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 index 7d7903ce..2281aab7 100644 --- 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 index 7464ec24..d991afa9 100644 --- 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 index 61e40c7b..010431df 100644 --- 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 index 82605cc7..e632fb1c 100644 --- 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 index 24940c83..cf45b041 100644 --- 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 index 8418e4a2..799477a3 100644 --- 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,15 +56,26 @@ 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) @@ -70,6 +83,9 @@ func TestGetLogger(t *testing.T) { 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) {