From 464580b0719ce9e443d1c0c1f6552214f1cd81f9 Mon Sep 17 00:00:00 2001 From: Marcus Efraimsson Date: Fri, 20 Oct 2023 10:01:04 +0200 Subject: [PATCH] Testdata: Use contextual logging (#76833) --- .../resource_handler.go | 30 +++++++++++-------- .../grafana-testdata-datasource/scenarios.go | 17 +++++++---- .../stream_handler.go | 12 +++++--- 3 files changed, 36 insertions(+), 23 deletions(-) diff --git a/pkg/tsdb/grafana-testdata-datasource/resource_handler.go b/pkg/tsdb/grafana-testdata-datasource/resource_handler.go index 91756d0ffe2..616baf78507 100644 --- a/pkg/tsdb/grafana-testdata-datasource/resource_handler.go +++ b/pkg/tsdb/grafana-testdata-datasource/resource_handler.go @@ -26,20 +26,22 @@ func (s *Service) registerRoutes() *http.ServeMux { } func (s *Service) testGetHandler(rw http.ResponseWriter, req *http.Request) { - s.logger.Debug("Received resource call", "url", req.URL.String(), "method", req.Method) + ctxLogger := s.logger.FromContext(req.Context()) + ctxLogger.Debug("Received resource call", "url", req.URL.String(), "method", req.Method) if req.Method != http.MethodGet { return } if _, err := rw.Write([]byte("Hello world from test datasource!")); err != nil { - s.logger.Error("Failed to write response", "error", err) + ctxLogger.Error("Failed to write response", "error", err) return } rw.WriteHeader(http.StatusOK) } func (s *Service) getScenariosHandler(rw http.ResponseWriter, req *http.Request) { + ctxLogger := s.logger.FromContext(req.Context()) result := make([]any, 0) scenarioIds := make([]string, 0) @@ -60,18 +62,19 @@ func (s *Service) getScenariosHandler(rw http.ResponseWriter, req *http.Request) bytes, err := json.Marshal(&result) if err != nil { - s.logger.Error("Failed to marshal response body to JSON", "error", err) + ctxLogger.Error("Failed to marshal response body to JSON", "error", err) } rw.Header().Set("Content-Type", "application/json") rw.WriteHeader(http.StatusOK) if _, err := rw.Write(bytes); err != nil { - s.logger.Error("Failed to write response", "error", err) + ctxLogger.Error("Failed to write response", "error", err) } } func (s *Service) testStreamHandler(rw http.ResponseWriter, req *http.Request) { - s.logger.Debug("Received resource call", "url", req.URL.String(), "method", req.Method) + ctxLogger := s.logger.FromContext(req.Context()) + ctxLogger.Debug("Received resource call", "url", req.URL.String(), "method", req.Method) if req.Method != http.MethodGet { return @@ -96,7 +99,7 @@ func (s *Service) testStreamHandler(rw http.ResponseWriter, req *http.Request) { for i := 1; i <= count; i++ { if _, err := io.WriteString(rw, fmt.Sprintf("Message #%d", i)); err != nil { - s.logger.Error("Failed to write response", "error", err) + ctxLogger.Error("Failed to write response", "error", err) return } rw.(http.Flusher).Flush() @@ -106,25 +109,26 @@ func (s *Service) testStreamHandler(rw http.ResponseWriter, req *http.Request) { func createJSONHandler(logger log.Logger) http.Handler { return http.HandlerFunc(func(rw http.ResponseWriter, req *http.Request) { - logger.Debug("Received resource call", "url", req.URL.String(), "method", req.Method) + ctxLogger := logger.FromContext(req.Context()) + ctxLogger.Debug("Received resource call", "url", req.URL.String(), "method", req.Method) var reqData map[string]any if req.Body != nil { defer func() { if err := req.Body.Close(); err != nil { - logger.Warn("Failed to close response body", "err", err) + ctxLogger.Warn("Failed to close response body", "err", err) } }() b, err := io.ReadAll(req.Body) if err != nil { - logger.Error("Failed to read request body to bytes", "error", err) + ctxLogger.Error("Failed to read request body to bytes", "error", err) } else { err := json.Unmarshal(b, &reqData) if err != nil { - logger.Error("Failed to unmarshal request body to JSON", "error", err) + ctxLogger.Error("Failed to unmarshal request body to JSON", "error", err) } - logger.Debug("Received resource call body", "body", reqData) + ctxLogger.Debug("Received resource call body", "body", reqData) } } @@ -139,13 +143,13 @@ func createJSONHandler(logger log.Logger) http.Handler { } bytes, err := json.Marshal(&data) if err != nil { - logger.Error("Failed to marshal response body to JSON", "error", err) + ctxLogger.Error("Failed to marshal response body to JSON", "error", err) } rw.Header().Set("Content-Type", "application/json") rw.WriteHeader(http.StatusOK) if _, err := rw.Write(bytes); err != nil { - logger.Error("Failed to write response", "error", err) + ctxLogger.Error("Failed to write response", "error", err) } }) } diff --git a/pkg/tsdb/grafana-testdata-datasource/scenarios.go b/pkg/tsdb/grafana-testdata-datasource/scenarios.go index 6b83af3db46..a187aac0f6e 100644 --- a/pkg/tsdb/grafana-testdata-datasource/scenarios.go +++ b/pkg/tsdb/grafana-testdata-datasource/scenarios.go @@ -12,6 +12,7 @@ import ( "time" "github.com/grafana/grafana-plugin-sdk-go/backend" + "github.com/grafana/grafana-plugin-sdk-go/backend/log" "github.com/grafana/grafana-plugin-sdk-go/backend/tracing" "github.com/grafana/grafana-plugin-sdk-go/data" "go.opentelemetry.io/otel/attribute" @@ -231,10 +232,10 @@ Timestamps will line up evenly on timeStepSeconds (For example, 60 seconds means func (s *Service) registerScenario(scenario *Scenario) { s.scenarios[scenario.ID] = scenario - s.queryMux.HandleFunc(scenario.ID, traceScenarioHandler(scenario.ID, scenario.handler)) + s.queryMux.HandleFunc(scenario.ID, instrumentScenarioHandler(s.logger, scenario.ID, scenario.handler)) } -func traceScenarioHandler(scenario string, fn backend.QueryDataHandlerFunc) backend.QueryDataHandlerFunc { +func instrumentScenarioHandler(logger log.Logger, scenario string, fn backend.QueryDataHandlerFunc) backend.QueryDataHandlerFunc { return backend.QueryDataHandlerFunc(func(ctx context.Context, req *backend.QueryDataRequest) (*backend.QueryDataResponse, error) { ctx, span := tracing.DefaultTracer().Start(ctx, "testdatasource.queryData", trace.WithAttributes( @@ -242,6 +243,9 @@ func traceScenarioHandler(scenario string, fn backend.QueryDataHandlerFunc) back )) defer span.End() + ctxLogger := logger.FromContext(ctx) + ctxLogger.Debug("queryData", "scenario", scenario) + return fn(ctx, req) }) } @@ -298,12 +302,13 @@ func GetJSONModel(j json.RawMessage) (JSONModel, error) { // handleFallbackScenario handles the scenario where queryType is not set and fallbacks to scenarioId. func (s *Service) handleFallbackScenario(ctx context.Context, req *backend.QueryDataRequest) (*backend.QueryDataResponse, error) { + ctxLogger := s.logger.FromContext(ctx) scenarioQueries := map[string][]backend.DataQuery{} for _, q := range req.Queries { model, err := GetJSONModel(q.JSON) if err != nil { - s.logger.Error("Failed to unmarshal query model to JSON", "error", err) + ctxLogger.Error("Failed to unmarshal query model to JSON", "error", err) continue } @@ -315,7 +320,7 @@ func (s *Service) handleFallbackScenario(ctx context.Context, req *backend.Query scenarioQueries[scenarioID] = append(scenarioQueries[scenarioID], q) } else { - s.logger.Error("Scenario not found", "scenarioId", scenarioID) + ctxLogger.Error("Scenario not found", "scenarioId", scenarioID) } } @@ -327,9 +332,9 @@ func (s *Service) handleFallbackScenario(ctx context.Context, req *backend.Query Headers: req.Headers, Queries: queries, } - handler := traceScenarioHandler(scenarioID, scenario.handler) + handler := instrumentScenarioHandler(s.logger, scenarioID, scenario.handler) if sResp, err := handler(ctx, sReq); err != nil { - s.logger.Error("Failed to handle scenario", "scenarioId", scenarioID, "error", err) + ctxLogger.Error("Failed to handle scenario", "scenarioId", scenarioID, "error", err) } else { for refID, dr := range sResp.Responses { resp.Responses[refID] = dr diff --git a/pkg/tsdb/grafana-testdata-datasource/stream_handler.go b/pkg/tsdb/grafana-testdata-datasource/stream_handler.go index 9583ceb3d26..c862116f5a3 100644 --- a/pkg/tsdb/grafana-testdata-datasource/stream_handler.go +++ b/pkg/tsdb/grafana-testdata-datasource/stream_handler.go @@ -15,7 +15,8 @@ import ( var random20HzStreamRegex = regexp.MustCompile(`random-20Hz-stream(-\d+)?`) func (s *Service) SubscribeStream(ctx context.Context, req *backend.SubscribeStreamRequest) (*backend.SubscribeStreamResponse, error) { - s.logger.Debug("Allowing access to stream", "path", req.Path, "user", req.PluginContext.User) + ctxLogger := s.logger.FromContext(ctx) + ctxLogger.Debug("Allowing access to stream", "path", req.Path, "user", req.PluginContext.User) if strings.HasPrefix(req.Path, "sim/") { return s.sims.SubscribeStream(ctx, req) @@ -40,7 +41,8 @@ func (s *Service) SubscribeStream(ctx context.Context, req *backend.SubscribeStr } func (s *Service) PublishStream(ctx context.Context, req *backend.PublishStreamRequest) (*backend.PublishStreamResponse, error) { - s.logger.Debug("Attempt to publish into stream", "path", req.Path, "user", req.PluginContext.User) + ctxLogger := s.logger.FromContext(ctx) + ctxLogger.Debug("Attempt to publish into stream", "path", req.Path, "user", req.PluginContext.User) if strings.HasPrefix(req.Path, "sim/") { return s.sims.PublishStream(ctx, req) @@ -52,7 +54,8 @@ func (s *Service) PublishStream(ctx context.Context, req *backend.PublishStreamR } func (s *Service) RunStream(ctx context.Context, request *backend.RunStreamRequest, sender *backend.StreamSender) error { - s.logger.Debug("New stream call", "path", request.Path) + ctxLogger := s.logger.FromContext(ctx) + ctxLogger.Debug("New stream call", "path", request.Path) if strings.HasPrefix(request.Path, "sim/") { return s.sims.RunStream(ctx, request, sender) @@ -92,6 +95,7 @@ type testStreamConfig struct { } func (s *Service) runTestStream(ctx context.Context, path string, conf testStreamConfig, sender *backend.StreamSender) error { + ctxLogger := s.logger.FromContext(ctx) spread := 50.0 walker := rand.Float64() * 100 @@ -107,7 +111,7 @@ func (s *Service) runTestStream(ctx context.Context, path string, conf testStrea for { select { case <-ctx.Done(): - s.logger.Debug("Stop streaming data for path", "path", path) + ctxLogger.Debug("Stop streaming data for path", "path", path) return ctx.Err() case t := <-ticker.C: if rand.Float64() < conf.Drop {