From f7a3e50b23b6b4e5a40041996fd267646a313ec7 Mon Sep 17 00:00:00 2001 From: Emil Tullstedt Date: Mon, 26 Sep 2022 15:10:54 +0200 Subject: [PATCH] UsageStats: Add traces when sending usage stats (#55474) --- pkg/infra/usagestats/service/service.go | 11 ++- pkg/infra/usagestats/service/usage_stats.go | 88 ++++++++++++++----- .../usagestats/service/usage_stats_test.go | 16 ++-- 3 files changed, 83 insertions(+), 32 deletions(-) diff --git a/pkg/infra/usagestats/service/service.go b/pkg/infra/usagestats/service/service.go index c31385d7d5a..36ad25d29cd 100644 --- a/pkg/infra/usagestats/service/service.go +++ b/pkg/infra/usagestats/service/service.go @@ -7,6 +7,7 @@ import ( "github.com/grafana/grafana/pkg/api/routing" "github.com/grafana/grafana/pkg/infra/kvstore" "github.com/grafana/grafana/pkg/infra/log" + "github.com/grafana/grafana/pkg/infra/tracing" "github.com/grafana/grafana/pkg/infra/usagestats" "github.com/grafana/grafana/pkg/plugins" "github.com/grafana/grafana/pkg/setting" @@ -18,19 +19,21 @@ type UsageStats struct { RouteRegister routing.RouteRegister pluginStore plugins.Store - log log.Logger + log log.Logger + tracer tracing.Tracer externalMetrics []usagestats.MetricsFunc sendReportCallbacks []usagestats.SendReportCallbackFunc } -func ProvideService(cfg *setting.Cfg, pluginStore plugins.Store, kvStore kvstore.KVStore, routeRegister routing.RouteRegister) *UsageStats { +func ProvideService(cfg *setting.Cfg, pluginStore plugins.Store, kvStore kvstore.KVStore, routeRegister routing.RouteRegister, tracer tracing.Tracer) *UsageStats { s := &UsageStats{ Cfg: cfg, RouteRegister: routeRegister, pluginStore: pluginStore, kvStore: kvstore.WithNamespace(kvStore, 0, "infra.usagestats"), log: log.New("infra.usagestats"), + tracer: tracer, } s.registerAPIEndpoints() @@ -65,8 +68,8 @@ func (uss *UsageStats) Run(ctx context.Context) error { for { select { case <-sendReportTicker.C: - if err := uss.sendUsageStats(ctx); err != nil { - uss.log.Warn("Failed to send usage stats", "error", err) + if traceID, err := uss.sendUsageStats(ctx); err != nil { + uss.log.Warn("Failed to send usage stats", "error", err, "traceID", traceID) } lastSent = time.Now() diff --git a/pkg/infra/usagestats/service/usage_stats.go b/pkg/infra/usagestats/service/usage_stats.go index 15dc764d2cb..dd1c197143a 100644 --- a/pkg/infra/usagestats/service/usage_stats.go +++ b/pkg/infra/usagestats/service/usage_stats.go @@ -4,13 +4,18 @@ import ( "bytes" "context" "encoding/json" + "fmt" "net/http" + "reflect" "runtime" "strings" "time" "github.com/google/uuid" + "go.opentelemetry.io/otel/attribute" + "go.opentelemetry.io/otel/codes" + "github.com/grafana/grafana/pkg/infra/tracing" "github.com/grafana/grafana/pkg/infra/usagestats" ) @@ -18,8 +23,8 @@ var usageStatsURL = "https://stats.grafana.org/grafana-usage-report" func (uss *UsageStats) GetUsageReport(ctx context.Context) (usagestats.Report, error) { version := strings.ReplaceAll(uss.Cfg.BuildVersion, ".", "_") - metrics := map[string]interface{}{} + start := time.Now() edition := "oss" if uss.Cfg.IsEnterprise { @@ -44,16 +49,18 @@ func (uss *UsageStats) GetUsageReport(ctx context.Context) (usagestats.Report, e metrics["stats.valid_license.count"] = 0 } + uss.log.FromContext(ctx).Debug("Collected usage stats", "metricCount", len(metrics), "version", report.Version, "os", report.Os, "arch", report.Arch, "edition", report.Edition, "duration", time.Since(start)) return report, nil } func (uss *UsageStats) gatherMetrics(ctx context.Context, metrics map[string]interface{}) { + ctx, span := uss.tracer.Start(ctx, "UsageStats.GatherLoop") + defer span.End() totC, errC := 0, 0 for _, fn := range uss.externalMetrics { - fnMetrics, err := fn(ctx) + fnMetrics, err := uss.runMetricsFunc(ctx, fn) totC++ if err != nil { - uss.log.Error("Failed to fetch external metrics", "error", err) errC++ continue } @@ -66,47 +73,82 @@ func (uss *UsageStats) gatherMetrics(ctx context.Context, metrics map[string]int metrics["stats.usagestats.debug.collect.error.count"] = errC } +func (uss *UsageStats) runMetricsFunc(ctx context.Context, fn usagestats.MetricsFunc) (map[string]interface{}, error) { + start := time.Now() + ctx, span := uss.tracer.Start(ctx, "UsageStats.Gather") + fnName := runtime.FuncForPC(reflect.ValueOf(fn).Pointer()).Name() + span.SetAttributes("usageStats.function", fnName, attribute.Key("usageStats.function").String(fnName)) + defer span.End() + + fnMetrics, err := fn(ctx) + if err != nil { + uss.log.FromContext(ctx).Error("Failed to fetch usage stats from provider", "error", err, "duration", time.Since(start), "function", fnName) + span.SetStatus(codes.Error, fmt.Sprintf("failed to fetch usage stats from provider: %v", err)) + return nil, err + } + + uss.log.FromContext(ctx).Debug("Successfully fetched usage stats from provider", "duration", time.Since(start), "function", fnName) + return fnMetrics, nil +} + func (uss *UsageStats) RegisterMetricsFunc(fn usagestats.MetricsFunc) { uss.externalMetrics = append(uss.externalMetrics, fn) } -func (uss *UsageStats) sendUsageStats(ctx context.Context) error { +func (uss *UsageStats) sendUsageStats(ctx context.Context) (string, error) { if !uss.Cfg.ReportingEnabled { - return nil + return "", nil } - - uss.log.Debug("Sending anonymous usage stats", "url", usageStatsURL) + ctx, span := uss.tracer.Start(ctx, "UsageStats.BackgroundJob") + defer span.End() + traceID := tracing.TraceIDFromContext(ctx, false) + uss.log.FromContext(ctx).Debug("Sending anonymous usage stats", "url", usageStatsURL) + start := time.Now() report, err := uss.GetUsageReport(ctx) if err != nil { - return err + return traceID, err } out, err := json.MarshalIndent(report, "", " ") if err != nil { - return err + return traceID, err } data := bytes.NewBuffer(out) - sendUsageStats(uss, data) - return nil + err = sendUsageStats(uss, ctx, data) + if err != nil { + return traceID, err + } + + uss.log.FromContext(ctx).Info("Sent usage stats", "duration", time.Since(start)) + return traceID, nil } // sendUsageStats sends usage statistics. // // Stubbable by tests. -var sendUsageStats = func(uss *UsageStats, data *bytes.Buffer) { - go func() { - client := http.Client{Timeout: 5 * time.Second} - resp, err := client.Post(usageStatsURL, "application/json", data) - if err != nil { - uss.log.Error("Failed to send usage stats", "err", err) - return - } - if err := resp.Body.Close(); err != nil { - uss.log.Warn("Failed to close response body", "err", err) - } - }() +var sendUsageStats = func(uss *UsageStats, ctx context.Context, data *bytes.Buffer) error { + ctx, span := uss.tracer.Start(ctx, "UsageStats.Send") + defer span.End() + + client := http.Client{Timeout: 5 * time.Second} + req, err := http.NewRequestWithContext(ctx, http.MethodPost, usageStatsURL, data) + if err != nil { + span.SetStatus(codes.Error, fmt.Sprintf("failed to create request for usage stats: %v", err)) + return err + } + req.Header.Set("Content-Type", "application/json") + uss.tracer.Inject(ctx, req.Header, span) + resp, err := client.Do(req) + if err != nil { + span.SetStatus(codes.Error, fmt.Sprintf("failed to send usage stats: %v", err)) + return err + } + if err := resp.Body.Close(); err != nil { + uss.log.FromContext(ctx).Warn("Failed to close response body after sending usage stats", "err", err) + } + return nil } func (uss *UsageStats) GetUsageStatsId(ctx context.Context) string { diff --git a/pkg/infra/usagestats/service/usage_stats_test.go b/pkg/infra/usagestats/service/usage_stats_test.go index d394f7b1af2..318b8a054d6 100644 --- a/pkg/infra/usagestats/service/usage_stats_test.go +++ b/pkg/infra/usagestats/service/usage_stats_test.go @@ -12,6 +12,8 @@ import ( "testing" "time" + "github.com/grafana/grafana/pkg/infra/tracing" + "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" @@ -45,7 +47,7 @@ func TestMetrics(t *testing.T) { return map[string]interface{}{metricName: 1}, nil }) - err := uss.sendUsageStats(context.Background()) + _, err := uss.sendUsageStats(context.Background()) require.NoError(t, err) t.Run("Given reporting not enabled and sending usage stats", func(t *testing.T) { @@ -54,12 +56,13 @@ func TestMetrics(t *testing.T) { sendUsageStats = origSendUsageStats }) statsSent := false - sendUsageStats = func(uss *UsageStats, b *bytes.Buffer) { + sendUsageStats = func(uss *UsageStats, ctx context.Context, b *bytes.Buffer) error { statsSent = true + return nil } uss.Cfg.ReportingEnabled = false - err := uss.sendUsageStats(context.Background()) + _, err := uss.sendUsageStats(context.Background()) require.NoError(t, err) require.False(t, statsSent) @@ -105,8 +108,10 @@ func TestMetrics(t *testing.T) { }) usageStatsURL = ts.URL - err := uss.sendUsageStats(context.Background()) - require.NoError(t, err) + go func() { + _, err := uss.sendUsageStats(context.Background()) + require.NoError(t, err) + }() // Wait for fake HTTP server to receive a request var resp httpResp @@ -240,5 +245,6 @@ func createService(t *testing.T, cfg setting.Cfg, sqlStore sqlstore.Store, withD &fakePluginStore{}, kvstore.ProvideService(sqlStore), routing.NewRouteRegister(), + tracing.InitializeTracerForTest(), ) }