Elasticsearch: Adjust logging to follow convention (#74554)

* Elasticsearch: Adjust naming in logging according to convention

* Log response parsing per response

* Update

* Fix logging of errors when no response

* Add path to error loggigng

* Update pkg/tsdb/elasticsearch/response_parser.go

pkg/tsdb/elasticsearch/client/client.go

@@ -18,6 +18,13 @@ import (
 	"github.com/grafana/grafana/pkg/infra/log"
 )
 
+// Used in logging to mark a stage
+var (
+	StagePrepareRequest  = "prepareRequest"
+	StageDatabaseRequest = "databaseRequest"
+	StageParseResponse   = "parseResponse"
+)
+
 type DatasourceInfo struct {
 	ID                         int64
 	HTTPClient                 *http.Client
@@ -165,7 +172,11 @@ func (c *baseClientImpl) ExecuteMultisearch(r *MultiSearchRequest) (*MultiSearch
 		if errors.Is(err, context.Canceled) {
 			status = "cancelled"
 		}
-		c.logger.Error("Error received from Elasticsearch", "error", err, "status", status, "statusCode", clientRes.StatusCode, "duration", time.Since(start), "action", "databaseRequest")
+		lp := []any{"error", err, "status", status, "duration", time.Since(start), "stage", StageDatabaseRequest}
+		if clientRes != nil {
+			lp = append(lp, "statusCode", clientRes.StatusCode)
+		}
+		c.logger.Error("Error received from Elasticsearch", lp...)
 		return nil, err
 	}
 	res := clientRes
@@ -175,7 +186,7 @@ func (c *baseClientImpl) ExecuteMultisearch(r *MultiSearchRequest) (*MultiSearch
 		}
 	}()
 
-	c.logger.Info("Response received from Elasticsearch", "status", "ok", "statusCode", res.StatusCode, "contentLength", res.ContentLength, "duration", time.Since(start), "action", "databaseRequest")
+	c.logger.Info("Response received from Elasticsearch", "status", "ok", "statusCode", res.StatusCode, "contentLength", res.ContentLength, "duration", time.Since(start), "stage", StageDatabaseRequest)
 
 	start = time.Now()
 	var msr MultiSearchResponse

pkg/tsdb/elasticsearch/data_query.go

@@ -41,7 +41,7 @@ func (e *elasticsearchDataQuery) execute() (*backend.QueryDataResponse, error) {
 	queries, err := parseQuery(e.dataQueries, e.logger)
 	if err != nil {
 		mq, _ := json.Marshal(e.dataQueries)
-		e.logger.Error("Failed to parse queries", "error", err, "queries", string(mq), "queriesLength", len(queries), "duration", time.Since(start), "action", "prepareRequest")
+		e.logger.Error("Failed to parse queries", "error", err, "queries", string(mq), "queriesLength", len(queries), "duration", time.Since(start), "stage", es.StagePrepareRequest)
 		return &backend.QueryDataResponse{}, err
 	}
 
@@ -52,7 +52,7 @@ func (e *elasticsearchDataQuery) execute() (*backend.QueryDataResponse, error) {
 	for _, q := range queries {
 		if err := e.processQuery(q, ms, from, to); err != nil {
 			mq, _ := json.Marshal(q)
-			e.logger.Error("Failed to process query to multisearch request builder", "error", err, "query", string(mq), "queriesLength", len(queries), "duration", time.Since(start), "action", "prepareRequest")
+			e.logger.Error("Failed to process query to multisearch request builder", "error", err, "query", string(mq), "queriesLength", len(queries), "duration", time.Since(start), "stage", es.StagePrepareRequest)
 			return &backend.QueryDataResponse{}, err
 		}
 	}
@@ -60,11 +60,11 @@ func (e *elasticsearchDataQuery) execute() (*backend.QueryDataResponse, error) {
 	req, err := ms.Build()
 	if err != nil {
 		mqs, _ := json.Marshal(e.dataQueries)
-		e.logger.Error("Failed to build multisearch request", "error", err, "queriesLength", len(queries), "queries", string(mqs), "duration", time.Since(start), "action", "prepareRequest")
+		e.logger.Error("Failed to build multisearch request", "error", err, "queriesLength", len(queries), "queries", string(mqs), "duration", time.Since(start), "stage", es.StagePrepareRequest)
 		return &backend.QueryDataResponse{}, err
 	}
 
-	e.logger.Info("Prepared request", "queriesLength", len(queries), "duration", time.Since(start), "action", "prepareRequest")
+	e.logger.Info("Prepared request", "queriesLength", len(queries), "duration", time.Since(start), "stage", es.StagePrepareRequest)
 	res, err := e.client.ExecuteMultisearch(req)
 	if err != nil {
 		return &backend.QueryDataResponse{}, err

pkg/tsdb/elasticsearch/elasticsearch.go

@@ -229,10 +229,14 @@ func (s *Service) CallResource(ctx context.Context, req *backend.CallResourceReq
 		if errors.Is(err, context.Canceled) {
 			status = "cancelled"
 		}
-		logger.Error("Error received from Elasticsearch", "error", err, "status", status, "statusCode", response.StatusCode, "duration", time.Since(start), "action", "databaseRequest")
+		lp := []any{"error", err, "status", status, "duration", time.Since(start), "stage", es.StageDatabaseRequest, "resourcePath", req.Path}
+		if response != nil {
+			lp = append(lp, "statusCode", response.StatusCode)
+		}
+		logger.Error("Error received from Elasticsearch", lp...)
 		return err
 	}
-	logger.Info("Response received from Elasticsearch", "statusCode", response.StatusCode, "status", "ok", "duration", time.Since(start), "action", "databaseRequest", "contentLength", response.Header.Get("Content-Length"))
+	logger.Info("Response received from Elasticsearch", "statusCode", response.StatusCode, "status", "ok", "duration", time.Since(start), "stage", es.StageDatabaseRequest, "contentLength", response.Header.Get("Content-Length"), "resourcePath", req.Path)
 
 	defer func() {
 		if err := response.Body.Close(); err != nil {

pkg/tsdb/elasticsearch/response_parser.go

@@ -42,7 +42,6 @@ const (
 var searchWordsRegex = regexp.MustCompile(regexp.QuoteMeta(es.HighlightPreTagsString) + `(.*?)` + regexp.QuoteMeta(es.HighlightPostTagsString))
 
 func parseResponse(ctx context.Context, responses []*es.SearchResponse, targets []*Query, configuredFields es.ConfiguredFields, logger log.Logger) (*backend.QueryDataResponse, error) {
-	start := time.Now()
 	result := backend.QueryDataResponse{
 		Responses: backend.Responses{},
 	}
@@ -51,12 +50,13 @@ func parseResponse(ctx context.Context, responses []*es.SearchResponse, targets
 	}
 
 	for i, res := range responses {
+		start := time.Now()
 		target := targets[i]
 
 		if res.Error != nil {
 			mt, _ := json.Marshal(target)
 			me, _ := json.Marshal(res.Error)
-			logger.Error("Error response from Elasticsearch", "error", string(me), "query", string(mt))
+			logger.Error("Processing error response from Elasticsearch", "error", string(me), "query", string(mt))
 			errResult := getErrorFromElasticResponse(res)
 			result.Responses[target.RefID] = backend.DataResponse{
 				Error: errors.New(errResult),
@@ -102,9 +102,9 @@ func parseResponse(ctx context.Context, responses []*es.SearchResponse, targets
 
 			result.Responses[target.RefID] = queryRes
 		}
+		logger.Info("Finished processing of response", "duration", time.Since(start), "stage", es.StageParseResponse)
 	}
 
-	logger.Info("Finished processing responses", "duration", time.Since(start), "responsesLength", len(result.Responses), "queriesLength", len(targets), "action", "parseResponse")
 	return &result, nil
 }