Instrumentation: Log plugin and datasource info for each plugin request. (#54769)

Signed-off-by: bergquist <carl.bergquist@gmail.com>

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;
 }

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()

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
+	elapsed := time.Since(start)
-	pluginRequestDuration.WithLabelValues(pluginID, endpoint).Observe(float64(elapsed))
+	pluginRequestDuration.WithLabelValues(pluginCtx.PluginID, endpoint).Observe(float64(elapsed / time.Millisecond))
-	pluginRequestCounter.WithLabelValues(pluginID, endpoint, status).Inc()
+	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 {
+func InstrumentCollectMetrics(ctx context.Context, req *backend.PluginContext, cfg *config.Cfg, fn func() error) error {
-	return instrumentPluginRequest(pluginID, "collectMetrics", fn)
+	return instrumentPluginRequest(ctx, cfg, req, "collectMetrics", fn)
 }
 
 // InstrumentCheckHealthRequest instruments checkHealth.
-func InstrumentCheckHealthRequest(pluginID string, fn func() error) error {
+func InstrumentCheckHealthRequest(ctx context.Context, req *backend.PluginContext, cfg *config.Cfg, fn func() error) error {
-	return instrumentPluginRequest(pluginID, "checkHealth", fn)
+	return instrumentPluginRequest(ctx, cfg, req, "checkHealth", fn)
 }
 
 // InstrumentCallResourceRequest instruments callResource.
-func InstrumentCallResourceRequest(pluginID string, fn func() error) error {
+func InstrumentCallResourceRequest(ctx context.Context, req *backend.PluginContext, cfg *config.Cfg, fn func() error) error {
-	return instrumentPluginRequest(pluginID, "callResource", fn)
+	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 {
+func InstrumentQueryDataRequest(ctx context.Context, req *backend.PluginContext, cfg *config.Cfg, fn func() error) error {
-	return instrumentPluginRequest(pluginID, "queryData", fn)
+	return instrumentPluginRequest(ctx, cfg, req, "queryData", fn)
 }

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),
 	}
 }
 

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
 	})

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",

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,
+		Raw:                    raw,
-		StaticRootPath:     staticRootPath,
+		StaticRootPath:         staticRootPath,
-		BundledPluginsPath: bundledPluginsPath,
+		BundledPluginsPath:     bundledPluginsPath,
-		Azure:              &azsettings.AzureSettings{},
+		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) {

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",

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"