sql expressions - logging (#88193)

* sql expressions - logging

pkg/expr/sql/parser.go

@@ -6,6 +6,7 @@ import (
 	"sort"
 	"strings"
 
+	"github.com/grafana/grafana/pkg/infra/log"
 	"github.com/jeremywohl/flatten"
 	"github.com/scottlepp/go-duck/duck"
 )
@@ -16,6 +17,8 @@ const (
 	ERROR_MESSAGE = ".error_message"
 )
 
+var logger = log.New("sql_expr")
+
 // TablesList returns a list of tables for the sql statement
 func TablesList(rawSQL string) ([]string, error) {
 	duckDB := duck.NewInMemoryDB()
@@ -23,21 +26,25 @@ func TablesList(rawSQL string) ([]string, error) {
 	cmd := fmt.Sprintf("SELECT json_serialize_sql('%s')", rawSQL)
 	ret, err := duckDB.RunCommands([]string{cmd})
 	if err != nil {
+		logger.Error("error serializing sql", "error", err.Error(), "sql", rawSQL, "cmd", cmd)
 		return nil, fmt.Errorf("error serializing sql: %s", err.Error())
 	}
 
 	ast := []map[string]any{}
 	err = json.Unmarshal([]byte(ret), &ast)
 	if err != nil {
+		logger.Error("error converting json sql to ast", "error", err.Error(), "ret", ret)
 		return nil, fmt.Errorf("error converting json to ast: %s", err.Error())
 	}
 
 	return tablesFromAST(ast)
 }
 
+// tablesFromAST returns a list of tables from the ast
 func tablesFromAST(ast []map[string]any) ([]string, error) {
 	flat, err := flatten.Flatten(ast[0], "", flatten.DotStyle)
 	if err != nil {
+		logger.Error("error flattening ast", "error", err.Error(), "ast", ast)
 		return nil, fmt.Errorf("error flattening ast: %s", err.Error())
 	}
 
@@ -46,6 +53,7 @@ func tablesFromAST(ast []map[string]any) ([]string, error) {
 		if strings.HasSuffix(k, ERROR) {
 			v, ok := v.(bool)
 			if ok && v {
+				logger.Error("error in sql", "error", k)
 				return nil, astError(k, flat)
 			}
 		}
@@ -58,6 +66,8 @@ func tablesFromAST(ast []map[string]any) ([]string, error) {
 	}
 	sort.Strings(tables)
 
+	logger.Debug("tables found in sql", "tables", tables)
+
 	return tables, nil
 }
 

pkg/expr/sql_command.go

@@ -35,6 +35,12 @@ func NewSQLCommand(refID, rawSQL string) (*SQLCommand, error) {
 			errutil.WithPublicMessage("error reading SQL command"),
 		)
 	}
+	if len(tables) == 0 {
+		logger.Warn("no tables found in SQL query", "sql", rawSQL)
+	}
+	if tables != nil {
+		logger.Debug("REF tables", "tables", tables, "sql", rawSQL)
+	}
 	return &SQLCommand{
 		query:       rawSQL,
 		varsToQuery: tables,
@@ -45,15 +51,18 @@ func NewSQLCommand(refID, rawSQL string) (*SQLCommand, error) {
 // UnmarshalSQLCommand creates a SQLCommand from Grafana's frontend query.
 func UnmarshalSQLCommand(rn *rawNode) (*SQLCommand, error) {
 	if rn.TimeRange == nil {
+		logger.Error("time range must be specified for refID", "refID", rn.RefID)
 		return nil, fmt.Errorf("time range must be specified for refID %s", rn.RefID)
 	}
 
 	expressionRaw, ok := rn.Query["expression"]
 	if !ok {
+		logger.Error("no expression in the query", "query", rn.Query)
 		return nil, errors.New("no expression in the query")
 	}
 	expression, ok := expressionRaw.(string)
 	if !ok {
+		logger.Error("expected sql expression to be type string", "expression", expressionRaw)
 		return nil, fmt.Errorf("expected sql expression to be type string, but got type %T", expressionRaw)
 	}
 
@@ -87,11 +96,15 @@ func (gr *SQLCommand) Execute(ctx context.Context, now time.Time, vars mathexp.V
 
 	duckDB := duck.NewInMemoryDB()
 	var frame = &data.Frame{}
+
+	logger.Debug("Executing query", "query", gr.query, "frames", len(allFrames))
 	err := duckDB.QueryFramesInto(gr.refID, gr.query, allFrames, frame)
 	if err != nil {
+		logger.Error("Failed to query frames", "error", err.Error())
 		rsp.Error = err
 		return rsp, nil
 	}
+	logger.Debug("Done Executing query", "query", gr.query, "rows", frame.Rows())
 
 	frame.RefID = gr.refID