From 06705a49e236dc3ab3b35db51b7bad8625e4866f Mon Sep 17 00:00:00 2001 From: Carl Bergquist Date: Wed, 2 Nov 2022 14:51:51 +0100 Subject: [PATCH] Instrumentation: Log plugin and datasource info for each plugin request. (#54769) Signed-off-by: bergquist --- .../src/types/featureToggles.gen.ts | 1 + pkg/api/metrics_test.go | 3 +- .../instrumentation/instrumentation.go | 52 ++++++++++++++----- pkg/plugins/config/config.go | 4 ++ pkg/plugins/manager/client/client.go | 13 +++-- pkg/plugins/manager/client/client_test.go | 5 +- .../manager/manager_integration_test.go | 11 ++-- pkg/services/featuremgmt/registry.go | 4 ++ pkg/services/featuremgmt/toggles_gen.go | 4 ++ 9 files changed, 72 insertions(+), 25 deletions(-) diff --git a/packages/grafana-data/src/types/featureToggles.gen.ts b/packages/grafana-data/src/types/featureToggles.gen.ts index c4b420ce536..b5aa97e742a 100644 --- a/packages/grafana-data/src/types/featureToggles.gen.ts +++ b/packages/grafana-data/src/types/featureToggles.gen.ts @@ -78,6 +78,7 @@ export interface FeatureToggles { queryLibrary?: boolean; showDashboardValidationWarnings?: boolean; mysqlAnsiQuotes?: boolean; + datasourceLogger?: boolean; accessControlOnCall?: boolean; nestedFolders?: boolean; } diff --git a/pkg/api/metrics_test.go b/pkg/api/metrics_test.go index aac61e368e9..8f7961a9daf 100644 --- a/pkg/api/metrics_test.go +++ b/pkg/api/metrics_test.go @@ -18,6 +18,7 @@ import ( "github.com/grafana/grafana/pkg/models" "github.com/grafana/grafana/pkg/plugins" "github.com/grafana/grafana/pkg/plugins/backendplugin" + "github.com/grafana/grafana/pkg/plugins/config" pluginClient "github.com/grafana/grafana/pkg/plugins/manager/client" "github.com/grafana/grafana/pkg/plugins/manager/registry" "github.com/grafana/grafana/pkg/services/datasources" @@ -290,7 +291,7 @@ func TestDataSourceQueryError(t *testing.T) { nil, &fakePluginRequestValidator{}, &fakeDatasources.FakeDataSourceService{}, - pluginClient.ProvideService(r), + pluginClient.ProvideService(r, &config.Cfg{}), &fakeOAuthTokenService{}, ) hs.QuotaService = quotatest.NewQuotaServiceFake() diff --git a/pkg/plugins/backendplugin/instrumentation/instrumentation.go b/pkg/plugins/backendplugin/instrumentation/instrumentation.go index a7bf104e6b9..5a42ef9a1fc 100644 --- a/pkg/plugins/backendplugin/instrumentation/instrumentation.go +++ b/pkg/plugins/backendplugin/instrumentation/instrumentation.go @@ -2,8 +2,13 @@ package instrumentation import ( + "context" "time" + "github.com/grafana/grafana-plugin-sdk-go/backend" + "github.com/grafana/grafana/pkg/infra/log" + "github.com/grafana/grafana/pkg/infra/tracing" + "github.com/grafana/grafana/pkg/plugins/config" "github.com/prometheus/client_golang/prometheus" "github.com/prometheus/client_golang/prometheus/promauto" ) @@ -23,8 +28,10 @@ var ( }, []string{"plugin_id", "endpoint"}) ) +var logger log.Logger = log.New("plugin.instrumentation") + // instrumentPluginRequest instruments success rate and latency of `fn` -func instrumentPluginRequest(pluginID string, endpoint string, fn func() error) error { +func instrumentPluginRequest(ctx context.Context, cfg *config.Cfg, pluginCtx *backend.PluginContext, endpoint string, fn func() error) error { status := "ok" start := time.Now() @@ -34,29 +41,50 @@ func instrumentPluginRequest(pluginID string, endpoint string, fn func() error) status = "error" } - elapsed := time.Since(start) / time.Millisecond - pluginRequestDuration.WithLabelValues(pluginID, endpoint).Observe(float64(elapsed)) - pluginRequestCounter.WithLabelValues(pluginID, endpoint, status).Inc() + elapsed := time.Since(start) + pluginRequestDuration.WithLabelValues(pluginCtx.PluginID, endpoint).Observe(float64(elapsed / time.Millisecond)) + pluginRequestCounter.WithLabelValues(pluginCtx.PluginID, endpoint, status).Inc() + + if cfg.LogDatasourceRequests { + logParams := []interface{}{ + "status", status, + "duration", elapsed, + "pluginId", pluginCtx.PluginID, + "endpoint", endpoint, + } + + traceID := tracing.TraceIDFromContext(ctx, false) + if traceID != "" { + logParams = append(logParams, "traceID", traceID) + } + + if pluginCtx.DataSourceInstanceSettings != nil { + logParams = append(logParams, "dsName", pluginCtx.DataSourceInstanceSettings.Name) + logParams = append(logParams, "dsUID", pluginCtx.DataSourceInstanceSettings.UID) + } + + logger.Info("Plugin Request Completed", logParams...) + } return err } // InstrumentCollectMetrics instruments collectMetrics. -func InstrumentCollectMetrics(pluginID string, fn func() error) error { - return instrumentPluginRequest(pluginID, "collectMetrics", fn) +func InstrumentCollectMetrics(ctx context.Context, req *backend.PluginContext, cfg *config.Cfg, fn func() error) error { + return instrumentPluginRequest(ctx, cfg, req, "collectMetrics", fn) } // InstrumentCheckHealthRequest instruments checkHealth. -func InstrumentCheckHealthRequest(pluginID string, fn func() error) error { - return instrumentPluginRequest(pluginID, "checkHealth", fn) +func InstrumentCheckHealthRequest(ctx context.Context, req *backend.PluginContext, cfg *config.Cfg, fn func() error) error { + return instrumentPluginRequest(ctx, cfg, req, "checkHealth", fn) } // InstrumentCallResourceRequest instruments callResource. -func InstrumentCallResourceRequest(pluginID string, fn func() error) error { - return instrumentPluginRequest(pluginID, "callResource", fn) +func InstrumentCallResourceRequest(ctx context.Context, req *backend.PluginContext, cfg *config.Cfg, fn func() error) error { + return instrumentPluginRequest(ctx, cfg, req, "callResource", fn) } // InstrumentQueryDataRequest instruments success rate and latency of query data requests. -func InstrumentQueryDataRequest(pluginID string, fn func() error) error { - return instrumentPluginRequest(pluginID, "queryData", fn) +func InstrumentQueryDataRequest(ctx context.Context, req *backend.PluginContext, cfg *config.Cfg, fn func() error) error { + return instrumentPluginRequest(ctx, cfg, req, "queryData", fn) } diff --git a/pkg/plugins/config/config.go b/pkg/plugins/config/config.go index bd8278f6103..a90062d1ecd 100644 --- a/pkg/plugins/config/config.go +++ b/pkg/plugins/config/config.go @@ -6,6 +6,7 @@ import ( "github.com/grafana/grafana-azure-sdk-go/azsettings" "github.com/grafana/grafana/pkg/infra/log" + "github.com/grafana/grafana/pkg/services/featuremgmt" "github.com/grafana/grafana/pkg/setting" ) @@ -29,6 +30,8 @@ type Cfg struct { Azure *azsettings.AzureSettings BuildVersion string // TODO Remove + + LogDatasourceRequests bool } func ProvideConfig(settingProvider setting.Provider, grafanaCfg *setting.Cfg) *Cfg { @@ -67,6 +70,7 @@ func NewCfg(settingProvider setting.Provider, grafanaCfg *setting.Cfg) *Cfg { ManagedIdentityEnabled: azure.KeyValue("managed_identity_enabled").MustBool(grafanaCfg.Azure.ManagedIdentityEnabled), ManagedIdentityClientId: azure.KeyValue("managed_identity_client_id").MustString(grafanaCfg.Azure.ManagedIdentityClientId), }, + LogDatasourceRequests: grafanaCfg.IsFeatureToggleEnabled(featuremgmt.FlagDatasourceLogger), } } diff --git a/pkg/plugins/manager/client/client.go b/pkg/plugins/manager/client/client.go index 686af19359e..fe7d67ba497 100644 --- a/pkg/plugins/manager/client/client.go +++ b/pkg/plugins/manager/client/client.go @@ -10,6 +10,7 @@ import ( "github.com/grafana/grafana/pkg/plugins" "github.com/grafana/grafana/pkg/plugins/backendplugin" "github.com/grafana/grafana/pkg/plugins/backendplugin/instrumentation" + "github.com/grafana/grafana/pkg/plugins/config" "github.com/grafana/grafana/pkg/plugins/manager/registry" ) @@ -17,11 +18,13 @@ var _ plugins.Client = (*Service)(nil) type Service struct { pluginRegistry registry.Service + cfg *config.Cfg } -func ProvideService(pluginRegistry registry.Service) *Service { +func ProvideService(pluginRegistry registry.Service, cfg *config.Cfg) *Service { return &Service{ pluginRegistry: pluginRegistry, + cfg: cfg, } } @@ -32,7 +35,7 @@ func (s *Service) QueryData(ctx context.Context, req *backend.QueryDataRequest) } var resp *backend.QueryDataResponse - err := instrumentation.InstrumentQueryDataRequest(req.PluginContext.PluginID, func() (innerErr error) { + err := instrumentation.InstrumentQueryDataRequest(ctx, &req.PluginContext, s.cfg, func() (innerErr error) { resp, innerErr = plugin.QueryData(ctx, req) return }) @@ -66,7 +69,7 @@ func (s *Service) CallResource(ctx context.Context, req *backend.CallResourceReq if !exists { return backendplugin.ErrPluginNotRegistered } - err := instrumentation.InstrumentCallResourceRequest(p.PluginID(), func() error { + err := instrumentation.InstrumentCallResourceRequest(ctx, &req.PluginContext, s.cfg, func() error { if err := p.CallResource(ctx, req, sender); err != nil { return err } @@ -87,7 +90,7 @@ func (s *Service) CollectMetrics(ctx context.Context, req *backend.CollectMetric } var resp *backend.CollectMetricsResult - err := instrumentation.InstrumentCollectMetrics(p.PluginID(), func() (innerErr error) { + err := instrumentation.InstrumentCollectMetrics(ctx, &req.PluginContext, s.cfg, func() (innerErr error) { resp, innerErr = p.CollectMetrics(ctx, req) return }) @@ -105,7 +108,7 @@ func (s *Service) CheckHealth(ctx context.Context, req *backend.CheckHealthReque } var resp *backend.CheckHealthResult - err := instrumentation.InstrumentCheckHealthRequest(p.PluginID(), func() (innerErr error) { + err := instrumentation.InstrumentCheckHealthRequest(ctx, &req.PluginContext, s.cfg, func() (innerErr error) { resp, innerErr = p.CheckHealth(ctx, req) return }) diff --git a/pkg/plugins/manager/client/client_test.go b/pkg/plugins/manager/client/client_test.go index 5351e0a478b..a9ec4111379 100644 --- a/pkg/plugins/manager/client/client_test.go +++ b/pkg/plugins/manager/client/client_test.go @@ -9,6 +9,7 @@ import ( "github.com/grafana/grafana-plugin-sdk-go/backend" "github.com/grafana/grafana/pkg/plugins" "github.com/grafana/grafana/pkg/plugins/backendplugin" + "github.com/grafana/grafana/pkg/plugins/config" "github.com/grafana/grafana/pkg/plugins/manager/fakes" "github.com/stretchr/testify/require" ) @@ -16,7 +17,7 @@ import ( func TestQueryData(t *testing.T) { t.Run("Empty registry should return not registered error", func(t *testing.T) { registry := fakes.NewFakePluginRegistry() - client := ProvideService(registry) + client := ProvideService(registry, &config.Cfg{}) _, err := client.QueryData(context.Background(), &backend.QueryDataRequest{}) require.Error(t, err) require.ErrorIs(t, err, plugins.ErrPluginNotRegistered) @@ -57,7 +58,7 @@ func TestQueryData(t *testing.T) { err := registry.Add(context.Background(), p) require.NoError(t, err) - client := ProvideService(registry) + client := ProvideService(registry, &config.Cfg{}) _, err = client.QueryData(context.Background(), &backend.QueryDataRequest{ PluginContext: backend.PluginContext{ PluginID: "grafana", diff --git a/pkg/plugins/manager/manager_integration_test.go b/pkg/plugins/manager/manager_integration_test.go index bd6c9b78568..52723ed43b7 100644 --- a/pkg/plugins/manager/manager_integration_test.go +++ b/pkg/plugins/manager/manager_integration_test.go @@ -73,10 +73,11 @@ func TestIntegrationPluginManager(t *testing.T) { require.NoError(t, err) cfg := &setting.Cfg{ - Raw: raw, - StaticRootPath: staticRootPath, - BundledPluginsPath: bundledPluginsPath, - Azure: &azsettings.AzureSettings{}, + Raw: raw, + StaticRootPath: staticRootPath, + BundledPluginsPath: bundledPluginsPath, + Azure: &azsettings.AzureSettings{}, + IsFeatureToggleEnabled: func(_ string) bool { return false }, } tracer := tracing.InitializeTracerForTest() @@ -115,7 +116,7 @@ func TestIntegrationPluginManager(t *testing.T) { verifyBundledPlugins(t, ctx, ps) verifyPluginStaticRoutes(t, ctx, ps) verifyBackendProcesses(t, reg.Plugins(ctx)) - verifyPluginQuery(t, ctx, client.ProvideService(reg)) + verifyPluginQuery(t, ctx, client.ProvideService(reg, pCfg)) } func verifyPluginQuery(t *testing.T, ctx context.Context, c plugins.Client) { diff --git a/pkg/services/featuremgmt/registry.go b/pkg/services/featuremgmt/registry.go index 581615cf49d..a100ba302dc 100644 --- a/pkg/services/featuremgmt/registry.go +++ b/pkg/services/featuremgmt/registry.go @@ -340,6 +340,10 @@ var ( Description: "Use double quote to escape keyword in Mysql query", State: FeatureStateAlpha, }, + { + Name: "datasourceLogger", + Description: "Logs all datasource requests", + }, { Name: "accessControlOnCall", Description: "Access control primitives for OnCall", diff --git a/pkg/services/featuremgmt/toggles_gen.go b/pkg/services/featuremgmt/toggles_gen.go index 23b7bc6f8df..b61653916a8 100644 --- a/pkg/services/featuremgmt/toggles_gen.go +++ b/pkg/services/featuremgmt/toggles_gen.go @@ -255,6 +255,10 @@ const ( // Use double quote to escape keyword in Mysql query FlagMysqlAnsiQuotes = "mysqlAnsiQuotes" + // FlagDatasourceLogger + // Logs all datasource requests + FlagDatasourceLogger = "datasourceLogger" + // FlagAccessControlOnCall // Access control primitives for OnCall FlagAccessControlOnCall = "accessControlOnCall"