From 216fcd4c5e28717068a8a85457dc20e1985bd6b0 Mon Sep 17 00:00:00 2001 From: Pulak Bhowmick Date: Mon, 11 Dec 2023 18:35:17 +0600 Subject: [PATCH 1/8] add logging for decide api --- config.yaml | 4 ++-- go.mod | 2 +- pkg/handlers/decide.go | 10 +++++++--- 3 files changed, 10 insertions(+), 6 deletions(-) diff --git a/config.yaml b/config.yaml index 431ddd6c..e8f69592 100644 --- a/config.yaml +++ b/config.yaml @@ -22,7 +22,7 @@ log: level: info ## enable pretty colorized console logging. setting to false will output ## structured JSON logs. Recommended false in production. - pretty: true + pretty: false ## to set whether or not the SDK key is included in the logging output. includeSdkKey: true @@ -35,7 +35,7 @@ log: tracing: ## bydefault tracing is disabled ## to enable tracing set enabled to true - enabled: false + enabled: true # opentelemetry tracing configuration opentelemetry: ## bydefault stdout exporter is enabled 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/decide.go b/pkg/handlers/decide.go index 1b32e81f..606fc1a6 100644 --- a/pkg/handlers/decide.go +++ b/pkg/handlers/decide.go @@ -21,14 +21,14 @@ import ( "errors" "net/http" - "github.com/optimizely/agent/pkg/middleware" + "github.com/go-chi/render" + "go.opentelemetry.io/otel/trace" + "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 @@ -63,6 +63,8 @@ func Decide(w http.ResponseWriter, r *http.Request) { return } + span := trace.SpanFromContext(r.Context()) + db, err := getUserContextWithOptions(r) if err != nil { RenderError(err, http.StatusBadRequest, w, r) @@ -108,6 +110,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().Str("traceID", span.SpanContext().TraceID().String()).Str("spanID", span.SpanContext().SpanID().String()).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 +123,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().Str("traceID", span.SpanContext().TraceID().String()).Str("spanID", span.SpanContext().SpanID().String()).Msgf("Feature %q is enabled for user %s? %t", d.FlagKey, d.UserContext.UserID, d.Enabled) } render.JSON(w, r, decideOuts) } From 59b63828d5617c30fbbb4c3f09c5efba6838d041 Mon Sep 17 00:00:00 2001 From: Pulak Bhowmick Date: Mon, 11 Dec 2023 19:25:09 +0600 Subject: [PATCH 2/8] log traceid for trace api --- pkg/handlers/activate.go | 5 ++--- pkg/handlers/track.go | 7 +++++-- 2 files changed, 7 insertions(+), 5 deletions(-) diff --git a/pkg/handlers/activate.go b/pkg/handlers/activate.go index 4a48f90a..4d187cb8 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 diff --git a/pkg/handlers/track.go b/pkg/handlers/track.go index 61e40c7b..7c01a3bb 100644 --- a/pkg/handlers/track.go +++ b/pkg/handlers/track.go @@ -22,9 +22,10 @@ import ( "net/http" "github.com/go-chi/render" - "github.com/optimizely/go-sdk/pkg/entities" + "go.opentelemetry.io/otel/trace" "github.com/optimizely/agent/pkg/middleware" + "github.com/optimizely/go-sdk/pkg/entities" ) type trackBody struct { @@ -40,6 +41,8 @@ func TrackEvent(w http.ResponseWriter, r *http.Request) { RenderError(err, http.StatusInternalServerError, w, r) return } + logger := middleware.GetLogger(r) + span := trace.SpanFromContext(r.Context()) var body trackBody err = ParseRequestBody(r, &body) @@ -66,6 +69,6 @@ func TrackEvent(w http.ResponseWriter, r *http.Request) { return } - middleware.GetLogger(r).Debug().Str("eventKey", eventKey).Msg("tracking event") + logger.Info().Str("traceID", span.SpanContext().TraceID().String()).Str("spanID", span.SpanContext().SpanID().String()).Str("eventKey", eventKey).Msg("tracked event") render.JSON(w, r, track) } From e88e1e3aac87a2e3ffacad100f8900ca17eaea9b Mon Sep 17 00:00:00 2001 From: Pulak Bhowmick Date: Mon, 11 Dec 2023 20:58:25 +0600 Subject: [PATCH 3/8] log traceid for override api --- pkg/handlers/override.go | 5 ++++- pkg/handlers/send_odp_event.go | 2 +- 2 files changed, 5 insertions(+), 2 deletions(-) diff --git a/pkg/handlers/override.go b/pkg/handlers/override.go index dff9aa9e..dcb96dcf 100644 --- a/pkg/handlers/override.go +++ b/pkg/handlers/override.go @@ -22,6 +22,7 @@ import ( "net/http" "github.com/go-chi/render" + "go.opentelemetry.io/otel/trace" "github.com/optimizely/agent/pkg/middleware" ) @@ -42,6 +43,8 @@ func Override(w http.ResponseWriter, r *http.Request) { return } + span := trace.SpanFromContext(r.Context()) + var body OverrideBody if parseErr := ParseRequestBody(r, &body); parseErr != nil { RenderError(parseErr, http.StatusBadRequest, w, r) @@ -69,7 +72,7 @@ func Override(w http.ResponseWriter, r *http.Request) { return } - logger.Debug().Str("experimentKey", experimentKey).Str("variationKey", body.VariationKey).Msg("setting override") + logger.Info().Str("traceID", span.SpanContext().TraceID().String()).Str("spanID", span.SpanContext().SpanID().String()).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 { diff --git a/pkg/handlers/send_odp_event.go b/pkg/handlers/send_odp_event.go index 7464ec24..867eca3f 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 From c8cf2eb916a47d0ae5ff06afa1f2576eec1daba2 Mon Sep 17 00:00:00 2001 From: Pulak Bhowmick Date: Mon, 11 Dec 2023 21:43:07 +0600 Subject: [PATCH 4/8] add traceid for error log --- pkg/handlers/utils.go | 13 +++++++++---- 1 file changed, 9 insertions(+), 4 deletions(-) diff --git a/pkg/handlers/utils.go b/pkg/handlers/utils.go index 82605cc7..bbbb6ae6 100644 --- a/pkg/handlers/utils.go +++ b/pkg/handlers/utils.go @@ -24,6 +24,7 @@ import ( "net/http" "github.com/go-chi/render" + "go.opentelemetry.io/otel/trace" "github.com/optimizely/agent/pkg/middleware" ) @@ -35,7 +36,8 @@ 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") + span := trace.SpanFromContext(r.Context()) + middleware.GetLogger(r).Err(err).Int("status", status).Str("traceID", span.SpanContext().TraceID().String()).Str("spanID", span.SpanContext().SpanID().String()).Msg("render error") render.Status(r, status) render.JSON(w, r, ErrorResponse{Error: err.Error()}) } @@ -44,22 +46,25 @@ 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) + span := trace.SpanFromContext(r.Context()) + 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).Str("traceID", span.SpanContext().TraceID().String()).Str("spanID", span.SpanContext().SpanID().String()).Msg(msg) return fmt.Errorf("%s", msg) } if len(body) == 0 { - middleware.GetLogger(r).Debug().Msg("body was empty skip JSON unmarshal") + logger.Info().Str("traceID", span.SpanContext().TraceID().String()).Str("spanID", span.SpanContext().SpanID().String()).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).Str("traceID", span.SpanContext().TraceID().String()).Str("spanID", span.SpanContext().SpanID().String()).Msg(msg) return fmt.Errorf("%s", msg) } From 16239e74bd5ad8d849f68aed8a2d9b0a87c105ea Mon Sep 17 00:00:00 2001 From: Pulak Bhowmick Date: Tue, 12 Dec 2023 17:07:29 +0600 Subject: [PATCH 5/8] add traceid into logs --- config.yaml | 2 +- pkg/handlers/activate.go | 6 +++++- pkg/handlers/decide_test.go | 9 ++++----- pkg/handlers/get_datafile.go | 6 ++++++ pkg/handlers/lookup.go | 9 +++++++-- pkg/handlers/optimizely_config.go | 5 +++++ pkg/handlers/override.go | 2 +- pkg/handlers/save.go | 9 +++++++-- pkg/handlers/send_odp_event.go | 5 +++++ 9 files changed, 41 insertions(+), 12 deletions(-) diff --git a/config.yaml b/config.yaml index e8f69592..33bc2452 100644 --- a/config.yaml +++ b/config.yaml @@ -22,7 +22,7 @@ log: level: info ## enable pretty colorized console logging. setting to false will output ## structured JSON logs. Recommended false in production. - pretty: false + pretty: true ## to set whether or not the SDK key is included in the logging output. includeSdkKey: true diff --git a/pkg/handlers/activate.go b/pkg/handlers/activate.go index 4d187cb8..2643706f 100644 --- a/pkg/handlers/activate.go +++ b/pkg/handlers/activate.go @@ -23,6 +23,7 @@ import ( "net/http" "github.com/go-chi/render" + "go.opentelemetry.io/otel/trace" "github.com/optimizely/agent/pkg/middleware" "github.com/optimizely/agent/pkg/optimizely" @@ -41,12 +42,14 @@ 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) + span := trace.SpanFromContext(r.Context()) + uc, err := getUserContext(r) if err != nil { RenderError(err, http.StatusBadRequest, w, r) @@ -107,6 +110,7 @@ func Activate(w http.ResponseWriter, r *http.Request) { } decisions = filterDecisions(r, decisions) + logger.Info().Str("traceID", span.SpanContext().TraceID().String()).Str("spanID", span.SpanContext().SpanID().String()).Msgf("Made activate decisions for user %s", uc.ID) render.JSON(w, r, decisions) } 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..4c105223 100644 --- a/pkg/handlers/get_datafile.go +++ b/pkg/handlers/get_datafile.go @@ -22,6 +22,7 @@ import ( "net/http" "github.com/go-chi/render" + "go.opentelemetry.io/otel/trace" "github.com/optimizely/agent/pkg/middleware" ) @@ -34,11 +35,16 @@ func GetDatafile(w http.ResponseWriter, r *http.Request) { return } + logger := middleware.GetLogger(r) + span := trace.SpanFromContext(r.Context()) + 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().Str("traceID", span.SpanContext().TraceID().String()).Str("spanID", span.SpanContext().SpanID().String()).Msg("Successfully returned datafile") render.JSON(w, r, raw) } diff --git a/pkg/handlers/lookup.go b/pkg/handlers/lookup.go index 0682d298..e0b5a7cb 100644 --- a/pkg/handlers/lookup.go +++ b/pkg/handlers/lookup.go @@ -21,9 +21,10 @@ import ( "errors" "net/http" - "github.com/optimizely/agent/pkg/middleware" - "github.com/go-chi/render" + "go.opentelemetry.io/otel/trace" + + "github.com/optimizely/agent/pkg/middleware" ) type lookupBody struct { @@ -47,6 +48,9 @@ func Lookup(w http.ResponseWriter, r *http.Request) { return } + logger := middleware.GetLogger(r) + span := trace.SpanFromContext(r.Context()) + if optlyClient.UserProfileService == nil { RenderError(ErrNoUPS, http.StatusInternalServerError, w, r) return @@ -75,5 +79,6 @@ func Lookup(w http.ResponseWriter, r *http.Request) { experimentBucketMap[k.ExperimentID] = map[string]interface{}{k.Field: v} } lookupResponse.ExperimentBucketMap = experimentBucketMap + logger.Info().Str("traceID", span.SpanContext().TraceID().String()).Str("spanID", span.SpanContext().SpanID().String()).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..60267329 100644 --- a/pkg/handlers/optimizely_config.go +++ b/pkg/handlers/optimizely_config.go @@ -21,6 +21,7 @@ import ( "net/http" "github.com/go-chi/render" + "go.opentelemetry.io/otel/trace" "github.com/optimizely/agent/pkg/middleware" ) @@ -33,6 +34,10 @@ func OptimizelyConfig(w http.ResponseWriter, r *http.Request) { return } + logger := middleware.GetLogger(r) + span := trace.SpanFromContext(r.Context()) + conf := optlyClient.GetOptimizelyConfig() + logger.Info().Str("traceID", span.SpanContext().TraceID().String()).Str("spanID", span.SpanContext().SpanID().String()).Msg("Successfully returned OptimizelyConfig") render.JSON(w, r, conf) } diff --git a/pkg/handlers/override.go b/pkg/handlers/override.go index dcb96dcf..81294a3e 100644 --- a/pkg/handlers/override.go +++ b/pkg/handlers/override.go @@ -72,10 +72,10 @@ func Override(w http.ResponseWriter, r *http.Request) { return } - logger.Info().Str("traceID", span.SpanContext().TraceID().String()).Str("spanID", span.SpanContext().SpanID().String()).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("traceID", span.SpanContext().TraceID().String()).Str("spanID", span.SpanContext().SpanID().String()).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..ac7a593f 100644 --- a/pkg/handlers/save.go +++ b/pkg/handlers/save.go @@ -20,10 +20,11 @@ package handlers import ( "net/http" + "github.com/go-chi/render" + "go.opentelemetry.io/otel/trace" + "github.com/optimizely/agent/pkg/middleware" "github.com/optimizely/go-sdk/pkg/decision" - - "github.com/go-chi/render" ) type saveBody struct { @@ -38,6 +39,9 @@ func Save(w http.ResponseWriter, r *http.Request) { return } + logger := middleware.GetLogger(r) + span := trace.SpanFromContext(r.Context()) + if optlyClient.UserProfileService == nil { RenderError(ErrNoUPS, http.StatusInternalServerError, w, r) return @@ -58,6 +62,7 @@ func Save(w http.ResponseWriter, r *http.Request) { convertedProfile := convertToUserProfile(body) optlyClient.UserProfileService.Save(convertedProfile) + logger.Info().Str("traceID", span.SpanContext().TraceID().String()).Str("spanID", span.SpanContext().SpanID().String()).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 867eca3f..815467b2 100644 --- a/pkg/handlers/send_odp_event.go +++ b/pkg/handlers/send_odp_event.go @@ -22,6 +22,7 @@ import ( "net/http" "github.com/go-chi/render" + "go.opentelemetry.io/otel/trace" "github.com/optimizely/agent/pkg/middleware" "github.com/optimizely/agent/pkg/optimizely" @@ -36,6 +37,9 @@ func SendOdpEvent(w http.ResponseWriter, r *http.Request) { return } + logger := middleware.GetLogger(r) + span := trace.SpanFromContext(r.Context()) + body, err := getRequestOdpEvent(r) if err != nil { RenderError(err, http.StatusBadRequest, w, r) @@ -52,6 +56,7 @@ func SendOdpEvent(w http.ResponseWriter, r *http.Request) { Success: true, } + logger.Info().Str("traceID", span.SpanContext().TraceID().String()).Str("spanID", span.SpanContext().SpanID().String()).Msg("Successfully sent event to ODP platform") render.JSON(w, r, returnResult) } From 1baadbf7c2e5aa6af220a1921152f0a3e5af49cd Mon Sep 17 00:00:00 2001 From: Pulak Bhowmick Date: Tue, 12 Dec 2023 17:13:23 +0600 Subject: [PATCH 6/8] clean up --- config.yaml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/config.yaml b/config.yaml index 33bc2452..431ddd6c 100644 --- a/config.yaml +++ b/config.yaml @@ -35,7 +35,7 @@ log: tracing: ## bydefault tracing is disabled ## to enable tracing set enabled to true - enabled: true + enabled: false # opentelemetry tracing configuration opentelemetry: ## bydefault stdout exporter is enabled From e770ccd6c4065e02807ff6d608314d437d7f3aaf Mon Sep 17 00:00:00 2001 From: Pulak Bhowmick Date: Tue, 12 Dec 2023 19:29:44 +0600 Subject: [PATCH 7/8] clean up --- pkg/handlers/activate.go | 4 +--- pkg/handlers/decide.go | 7 ++----- pkg/handlers/get_datafile.go | 4 +--- pkg/handlers/lookup.go | 4 +--- pkg/handlers/optimizely_config.go | 4 +--- pkg/handlers/override.go | 5 +---- pkg/handlers/save.go | 4 +--- pkg/handlers/send_odp_event.go | 4 +--- pkg/handlers/track.go | 4 +--- pkg/handlers/utils.go | 11 ++++------- pkg/middleware/utils.go | 14 ++++++++++---- 11 files changed, 24 insertions(+), 41 deletions(-) diff --git a/pkg/handlers/activate.go b/pkg/handlers/activate.go index 2643706f..2768f919 100644 --- a/pkg/handlers/activate.go +++ b/pkg/handlers/activate.go @@ -23,7 +23,6 @@ import ( "net/http" "github.com/go-chi/render" - "go.opentelemetry.io/otel/trace" "github.com/optimizely/agent/pkg/middleware" "github.com/optimizely/agent/pkg/optimizely" @@ -48,7 +47,6 @@ func Activate(w http.ResponseWriter, r *http.Request) { } logger := middleware.GetLogger(r) - span := trace.SpanFromContext(r.Context()) uc, err := getUserContext(r) if err != nil { @@ -110,7 +108,7 @@ func Activate(w http.ResponseWriter, r *http.Request) { } decisions = filterDecisions(r, decisions) - logger.Info().Str("traceID", span.SpanContext().TraceID().String()).Str("spanID", span.SpanContext().SpanID().String()).Msgf("Made activate decisions for user %s", uc.ID) + 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 606fc1a6..cb8908dd 100644 --- a/pkg/handlers/decide.go +++ b/pkg/handlers/decide.go @@ -22,7 +22,6 @@ import ( "net/http" "github.com/go-chi/render" - "go.opentelemetry.io/otel/trace" "github.com/optimizely/agent/pkg/middleware" "github.com/optimizely/go-sdk/pkg/client" @@ -63,8 +62,6 @@ func Decide(w http.ResponseWriter, r *http.Request) { return } - span := trace.SpanFromContext(r.Context()) - db, err := getUserContextWithOptions(r) if err != nil { RenderError(err, http.StatusBadRequest, w, r) @@ -110,7 +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().Str("traceID", span.SpanContext().TraceID().String()).Str("spanID", span.SpanContext().SpanID().String()).Msgf("Feature %q is enabled for user %s? %t", d.FlagKey, d.UserContext.UserID, d.Enabled) + 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 @@ -123,7 +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().Str("traceID", span.SpanContext().TraceID().String()).Str("spanID", span.SpanContext().SpanID().String()).Msgf("Feature %q is enabled for user %s? %t", d.FlagKey, d.UserContext.UserID, d.Enabled) + 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/get_datafile.go b/pkg/handlers/get_datafile.go index 4c105223..d458cb1b 100644 --- a/pkg/handlers/get_datafile.go +++ b/pkg/handlers/get_datafile.go @@ -22,7 +22,6 @@ import ( "net/http" "github.com/go-chi/render" - "go.opentelemetry.io/otel/trace" "github.com/optimizely/agent/pkg/middleware" ) @@ -36,7 +35,6 @@ func GetDatafile(w http.ResponseWriter, r *http.Request) { } logger := middleware.GetLogger(r) - span := trace.SpanFromContext(r.Context()) datafile := optlyClient.GetOptimizelyConfig().GetDatafile() var raw map[string]interface{} @@ -45,6 +43,6 @@ func GetDatafile(w http.ResponseWriter, r *http.Request) { return } - logger.Info().Str("traceID", span.SpanContext().TraceID().String()).Str("spanID", span.SpanContext().SpanID().String()).Msg("Successfully returned datafile") + logger.Info().Msg("Successfully returned datafile") render.JSON(w, r, raw) } diff --git a/pkg/handlers/lookup.go b/pkg/handlers/lookup.go index e0b5a7cb..30298d2c 100644 --- a/pkg/handlers/lookup.go +++ b/pkg/handlers/lookup.go @@ -22,7 +22,6 @@ import ( "net/http" "github.com/go-chi/render" - "go.opentelemetry.io/otel/trace" "github.com/optimizely/agent/pkg/middleware" ) @@ -49,7 +48,6 @@ func Lookup(w http.ResponseWriter, r *http.Request) { } logger := middleware.GetLogger(r) - span := trace.SpanFromContext(r.Context()) if optlyClient.UserProfileService == nil { RenderError(ErrNoUPS, http.StatusInternalServerError, w, r) @@ -79,6 +77,6 @@ func Lookup(w http.ResponseWriter, r *http.Request) { experimentBucketMap[k.ExperimentID] = map[string]interface{}{k.Field: v} } lookupResponse.ExperimentBucketMap = experimentBucketMap - logger.Info().Str("traceID", span.SpanContext().TraceID().String()).Str("spanID", span.SpanContext().SpanID().String()).Msgf("Looked up user profile for user %s", body.UserID) + 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 60267329..5ad19a4d 100644 --- a/pkg/handlers/optimizely_config.go +++ b/pkg/handlers/optimizely_config.go @@ -21,7 +21,6 @@ import ( "net/http" "github.com/go-chi/render" - "go.opentelemetry.io/otel/trace" "github.com/optimizely/agent/pkg/middleware" ) @@ -35,9 +34,8 @@ func OptimizelyConfig(w http.ResponseWriter, r *http.Request) { } logger := middleware.GetLogger(r) - span := trace.SpanFromContext(r.Context()) conf := optlyClient.GetOptimizelyConfig() - logger.Info().Str("traceID", span.SpanContext().TraceID().String()).Str("spanID", span.SpanContext().SpanID().String()).Msg("Successfully returned OptimizelyConfig") + logger.Info().Msg("Successfully returned OptimizelyConfig") render.JSON(w, r, conf) } diff --git a/pkg/handlers/override.go b/pkg/handlers/override.go index 81294a3e..36cb3ec4 100644 --- a/pkg/handlers/override.go +++ b/pkg/handlers/override.go @@ -22,7 +22,6 @@ import ( "net/http" "github.com/go-chi/render" - "go.opentelemetry.io/otel/trace" "github.com/optimizely/agent/pkg/middleware" ) @@ -43,8 +42,6 @@ func Override(w http.ResponseWriter, r *http.Request) { return } - span := trace.SpanFromContext(r.Context()) - var body OverrideBody if parseErr := ParseRequestBody(r, &body); parseErr != nil { RenderError(parseErr, http.StatusBadRequest, w, r) @@ -75,7 +72,7 @@ func Override(w http.ResponseWriter, r *http.Request) { if override, err := optlyClient.SetForcedVariation(r.Context(), experimentKey, body.UserID, body.VariationKey); err != nil { RenderError(err, http.StatusInternalServerError, w, r) } else { - logger.Info().Str("traceID", span.SpanContext().TraceID().String()).Str("spanID", span.SpanContext().SpanID().String()).Str("experimentKey", experimentKey).Str("variationKey", body.VariationKey).Msg("Successfully set override") + 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 ac7a593f..2281aab7 100644 --- a/pkg/handlers/save.go +++ b/pkg/handlers/save.go @@ -21,7 +21,6 @@ import ( "net/http" "github.com/go-chi/render" - "go.opentelemetry.io/otel/trace" "github.com/optimizely/agent/pkg/middleware" "github.com/optimizely/go-sdk/pkg/decision" @@ -40,7 +39,6 @@ func Save(w http.ResponseWriter, r *http.Request) { } logger := middleware.GetLogger(r) - span := trace.SpanFromContext(r.Context()) if optlyClient.UserProfileService == nil { RenderError(ErrNoUPS, http.StatusInternalServerError, w, r) @@ -62,7 +60,7 @@ func Save(w http.ResponseWriter, r *http.Request) { convertedProfile := convertToUserProfile(body) optlyClient.UserProfileService.Save(convertedProfile) - logger.Info().Str("traceID", span.SpanContext().TraceID().String()).Str("spanID", span.SpanContext().SpanID().String()).Msgf("Saved user profile for user %s", body.UserID) + 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 815467b2..d991afa9 100644 --- a/pkg/handlers/send_odp_event.go +++ b/pkg/handlers/send_odp_event.go @@ -22,7 +22,6 @@ import ( "net/http" "github.com/go-chi/render" - "go.opentelemetry.io/otel/trace" "github.com/optimizely/agent/pkg/middleware" "github.com/optimizely/agent/pkg/optimizely" @@ -38,7 +37,6 @@ func SendOdpEvent(w http.ResponseWriter, r *http.Request) { } logger := middleware.GetLogger(r) - span := trace.SpanFromContext(r.Context()) body, err := getRequestOdpEvent(r) if err != nil { @@ -56,7 +54,7 @@ func SendOdpEvent(w http.ResponseWriter, r *http.Request) { Success: true, } - logger.Info().Str("traceID", span.SpanContext().TraceID().String()).Str("spanID", span.SpanContext().SpanID().String()).Msg("Successfully sent event to ODP platform") + 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 7c01a3bb..010431df 100644 --- a/pkg/handlers/track.go +++ b/pkg/handlers/track.go @@ -22,7 +22,6 @@ import ( "net/http" "github.com/go-chi/render" - "go.opentelemetry.io/otel/trace" "github.com/optimizely/agent/pkg/middleware" "github.com/optimizely/go-sdk/pkg/entities" @@ -42,7 +41,6 @@ func TrackEvent(w http.ResponseWriter, r *http.Request) { return } logger := middleware.GetLogger(r) - span := trace.SpanFromContext(r.Context()) var body trackBody err = ParseRequestBody(r, &body) @@ -69,6 +67,6 @@ func TrackEvent(w http.ResponseWriter, r *http.Request) { return } - logger.Info().Str("traceID", span.SpanContext().TraceID().String()).Str("spanID", span.SpanContext().SpanID().String()).Str("eventKey", eventKey).Msg("tracked 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 bbbb6ae6..e632fb1c 100644 --- a/pkg/handlers/utils.go +++ b/pkg/handlers/utils.go @@ -24,7 +24,6 @@ import ( "net/http" "github.com/go-chi/render" - "go.opentelemetry.io/otel/trace" "github.com/optimizely/agent/pkg/middleware" ) @@ -36,8 +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) { - span := trace.SpanFromContext(r.Context()) - middleware.GetLogger(r).Err(err).Int("status", status).Str("traceID", span.SpanContext().TraceID().String()).Str("spanID", span.SpanContext().SpanID().String()).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()}) } @@ -47,24 +45,23 @@ func RenderError(err error, status int, w http.ResponseWriter, r *http.Request) // so that it is not leaked back to the requestor. func ParseRequestBody(r *http.Request, v interface{}) error { logger := middleware.GetLogger(r) - span := trace.SpanFromContext(r.Context()) body, err := io.ReadAll(r.Body) if err != nil { msg := "error reading request body" - logger.Err(err).Str("traceID", span.SpanContext().TraceID().String()).Str("spanID", span.SpanContext().SpanID().String()).Msg(msg) + logger.Err(err).Msg(msg) return fmt.Errorf("%s", msg) } if len(body) == 0 { - logger.Info().Str("traceID", span.SpanContext().TraceID().String()).Str("spanID", span.SpanContext().SpanID().String()).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" - logger.Err(err).Str("traceID", span.SpanContext().TraceID().String()).Str("spanID", span.SpanContext().SpanID().String()).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, ":") From 58700eebd7c340787b4a856cf335eec03b4dce72 Mon Sep 17 00:00:00 2001 From: Pulak Bhowmick Date: Tue, 12 Dec 2023 22:00:02 +0600 Subject: [PATCH 8/8] update unit test --- pkg/middleware/utils_test.go | 20 ++++++++++++++++++-- 1 file changed, 18 insertions(+), 2 deletions(-) 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) {