Add logging to legacy datasource look up path (#97065)

pkg/registry/apis/query/parser.go

@@ -12,6 +12,7 @@ import (
 
 	query "github.com/grafana/grafana/pkg/apis/query/v0alpha1"
 	"github.com/grafana/grafana/pkg/expr"
+	"github.com/grafana/grafana/pkg/infra/log"
 	"github.com/grafana/grafana/pkg/infra/tracing"
 	"github.com/grafana/grafana/pkg/services/datasources/service"
 )
@@ -48,13 +49,15 @@ type queryParser struct {
 	legacy service.LegacyDataSourceLookup
 	reader *expr.ExpressionQueryReader
 	tracer tracing.Tracer
+	logger log.Logger
 }
 
-func newQueryParser(reader *expr.ExpressionQueryReader, legacy service.LegacyDataSourceLookup, tracer tracing.Tracer) *queryParser {
+func newQueryParser(reader *expr.ExpressionQueryReader, legacy service.LegacyDataSourceLookup, tracer tracing.Tracer, logger log.Logger) *queryParser {
 	return &queryParser{
 		reader: reader,
 		legacy: legacy,
 		tracer: tracer,
+		logger: logger,
 	}
 }
 
@@ -82,6 +85,7 @@ func (p *queryParser) parseRequest(ctx context.Context, input *query.QueryDataRe
 
 		ds, err := p.getValidDataSourceRef(ctx, q.Datasource, q.DatasourceID)
 		if err != nil {
+			p.logger.Error("Failed to get valid datasource ref", "error", err)
 			return rsp, err
 		}
 
@@ -93,14 +97,17 @@ func (p *queryParser) parseRequest(ctx context.Context, input *query.QueryDataRe
 			// but this approach lets us focus on well typed behavior first
 			raw, err := json.Marshal(q)
 			if err != nil {
+				p.logger.Error("Failed to marshal query for expression", "error", err)
 				return rsp, err
 			}
 			iter, err := jsoniter.ParseBytes(jsoniter.ConfigDefault, raw)
 			if err != nil {
+				p.logger.Error("Failed to parse bytes for expression", "error", err)
 				return rsp, err
 			}
 			exp, err := p.reader.ReadQuery(q, iter)
 			if err != nil {
+				p.logger.Error("Failed to read query for expression", "error", err)
 				return rsp, NewErrorWithRefID(q.RefID, err)
 			}
 			exp.GraphID = int64(len(expressions) + 1)
@@ -170,6 +177,7 @@ func (p *queryParser) parseRequest(ctx context.Context, input *query.QueryDataRe
 		// Add the sorted expressions
 		sortedNodes, err := topo.SortStabilized(dg, nil)
 		if err != nil {
+			p.logger.Error("Error when sorting nodes", "error", err)
 			return rsp, makeCyclicError("")
 		}
 		for _, v := range sortedNodes {

pkg/registry/apis/query/parser_test.go

@@ -15,6 +15,7 @@ import (
 
 	query "github.com/grafana/grafana/pkg/apis/query/v0alpha1"
 	"github.com/grafana/grafana/pkg/expr"
+	"github.com/grafana/grafana/pkg/infra/log"
 	"github.com/grafana/grafana/pkg/infra/tracing"
 	"github.com/grafana/grafana/pkg/services/featuremgmt"
 )
@@ -29,7 +30,7 @@ type parserTestObject struct {
 func TestQuerySplitting(t *testing.T) {
 	ctx := context.Background()
 	parser := newQueryParser(expr.NewExpressionQueryReader(featuremgmt.WithFeatures()),
-		&legacyDataSourceRetriever{}, tracing.InitializeTracerForTest())
+		&legacyDataSourceRetriever{}, tracing.InitializeTracerForTest(), log.NewNopLogger())
 
 	t.Run("missing datasource flavors", func(t *testing.T) {
 		split, err := parser.parseRequest(ctx, &query.QueryDataRequest{

pkg/registry/apis/query/query_test.go

@@ -26,7 +26,7 @@ func TestQueryRestConnectHandler(t *testing.T) {
 		},
 		tracer: tracing.InitializeTracerForTest(),
 		parser: newQueryParser(expr.NewExpressionQueryReader(featuremgmt.WithFeatures()),
-			&legacyDataSourceRetriever{}, tracing.InitializeTracerForTest()),
+			&legacyDataSourceRetriever{}, tracing.InitializeTracerForTest(), nil),
 		log: log.New("test"),
 	}
 	qr := newQueryREST(b)

pkg/registry/apis/query/register.go

@@ -75,7 +75,7 @@ func NewQueryAPIBuilder(features featuremgmt.FeatureToggles,
 		log:                  log.New("query_apiserver"),
 		client:               client,
 		registry:             registry,
-		parser:               newQueryParser(reader, legacy, tracer),
+		parser:               newQueryParser(reader, legacy, tracer, log.New("query_parser")),
 		metrics:              newQueryMetrics(registerer),
 		tracer:               tracer,
 		features:             features,

pkg/services/datasources/service/legacy.go

@@ -9,6 +9,7 @@ import (
 	data "github.com/grafana/grafana-plugin-sdk-go/experimental/apis/data/v0alpha1"
 
 	"github.com/grafana/grafana/pkg/apimachinery/identity"
+	"github.com/grafana/grafana/pkg/infra/log"
 	"github.com/grafana/grafana/pkg/services/datasources"
 )
 
@@ -38,6 +39,7 @@ type cachingLegacyDataSourceLookup struct {
 	retriever DataSourceRetriever
 	cache     map[string]cachedValue
 	cacheMu   sync.Mutex
+	log       log.Logger
 }
 
 type cachedValue struct {
@@ -49,15 +51,18 @@ func ProvideLegacyDataSourceLookup(p *Service) LegacyDataSourceLookup {
 	return &cachingLegacyDataSourceLookup{
 		retriever: p,
 		cache:     make(map[string]cachedValue),
+		log:       log.New("legacy-datasource-lookup"),
 	}
 }
 
 func (s *cachingLegacyDataSourceLookup) GetDataSourceFromDeprecatedFields(ctx context.Context, name string, id int64) (*data.DataSourceRef, error) {
 	if id == 0 && name == "" {
+		s.log.Error("missing id and name in GetDataSourceFromDeprecatedFields")
 		return nil, fmt.Errorf("either name or ID must be set")
 	}
 	user, err := identity.GetRequester(ctx)
 	if err != nil {
+		s.log.Error("failed to get user from context after getRequester", "error", err)
 		return nil, err
 	}
 	key := fmt.Sprintf("%d/%s/%d", user.GetOrgID(), name, id)
@@ -74,6 +79,9 @@ func (s *cachingLegacyDataSourceLookup) GetDataSourceFromDeprecatedFields(ctx co
 		Name:  name,
 		ID:    id,
 	})
+	if err != nil {
+		s.log.Error("failed to get datasource from retriever", "error", err)
+	}
 	if errors.Is(err, datasources.ErrDataSourceNotFound) && name != "" {
 		ds, err = s.retriever.GetDataSource(ctx, &datasources.GetDataSourceQuery{
 			OrgID: user.GetOrgID(),