Plugins: Adds logging around loading of plugins for better tracking (#76896)

pkg/plugins/log/logger.go

@@ -23,7 +23,6 @@ func (d *grafanaInfraLogWrapper) New(ctx ...any) Logger {
 		}
 	}
 
-	ctx = append([]any{"logger"}, ctx...)
 	return &grafanaInfraLogWrapper{
 		l: d.l.New(ctx...),
 	}

pkg/plugins/manager/loader/loader.go

@@ -2,6 +2,9 @@ package loader
 
 import (
 	"context"
+	"sort"
+	"strings"
+	"time"
 
 	"github.com/grafana/grafana/pkg/plugins"
 	"github.com/grafana/grafana/pkg/plugins/log"
@@ -34,6 +37,8 @@ func New(discovery discovery.Discoverer, bootstrap bootstrap.Bootstrapper, valid
 }
 
 func (l *Loader) Load(ctx context.Context, src plugins.PluginSource) ([]*plugins.Plugin, error) {
+	end := l.instrumentLoad(ctx, src)
+
 	discoveredPlugins, err := l.discovery.Discover(ctx, src)
 	if err != nil {
 		return nil, err
@@ -54,9 +59,30 @@ func (l *Loader) Load(ctx context.Context, src plugins.PluginSource) ([]*plugins
 		return nil, err
 	}
 
+	end(initializedPlugins)
+
 	return initializedPlugins, nil
 }
 
 func (l *Loader) Unload(ctx context.Context, p *plugins.Plugin) (*plugins.Plugin, error) {
 	return l.termination.Terminate(ctx, p)
 }
+
+func (l *Loader) instrumentLoad(ctx context.Context, src plugins.PluginSource) func([]*plugins.Plugin) {
+	start := time.Now()
+	sourceLogger := l.log.New("source", src.PluginClass(ctx)).FromContext(ctx)
+	sourceLogger.Debug("Loading plugin source...")
+
+	return func(logger log.Logger, start time.Time) func([]*plugins.Plugin) {
+		return func(plugins []*plugins.Plugin) {
+			names := make([]string, len(plugins))
+			for i, p := range plugins {
+				names[i] = p.ID
+			}
+			sort.Strings(names)
+			pluginsStr := strings.Join(names, ", ")
+
+			logger.Debug("Plugin source loaded", "plugins", pluginsStr, "duration", time.Since(start))
+		}
+	}(sourceLogger, start)
+}

pkg/services/pluginsintegration/pluginstore/store.go

@@ -4,7 +4,9 @@ import (
 	"context"
 	"sort"
 	"sync"
+	"time"
 
+	"github.com/grafana/grafana/pkg/infra/log"
 	"github.com/grafana/grafana/pkg/plugins"
 	"github.com/grafana/grafana/pkg/plugins/manager/loader"
 	"github.com/grafana/grafana/pkg/plugins/manager/registry"
@@ -29,11 +31,23 @@ type Service struct {
 func ProvideService(pluginRegistry registry.Service, pluginSources sources.Registry,
 	pluginLoader loader.Service) (*Service, error) {
 	ctx := context.Background()
+	start := time.Now()
+	totalPlugins := 0
+	logger := log.New("plugin.store")
+	logger.Info("Loading plugins...")
+
 	for _, ps := range pluginSources.List(ctx) {
-		if _, err := pluginLoader.Load(ctx, ps); err != nil {
+		loadedPlugins, err := pluginLoader.Load(ctx, ps)
+		if err != nil {
+			logger.Error("Loading plugin source failed", "source", ps.PluginClass(ctx), "error", err)
 			return nil, err
 		}
+
+		totalPlugins += len(loadedPlugins)
 	}
+
+	logger.Info("Plugins loaded", "count", totalPlugins, "duration", time.Since(start))
+
 	return New(pluginRegistry, pluginLoader), nil
 }