From 49bd93aa2b15b95d695657803ad2e186953fc1d9 Mon Sep 17 00:00:00 2001 From: Ivana Huckova <30407135+ivanahuckova@users.noreply.github.com> Date: Thu, 7 Sep 2023 18:15:24 +0200 Subject: [PATCH] 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 | 15 +++++++++++++-- pkg/tsdb/elasticsearch/data_query.go | 8 ++++---- pkg/tsdb/elasticsearch/elasticsearch.go | 8 ++++++-- pkg/tsdb/elasticsearch/response_parser.go | 6 +++--- 4 files changed, 26 insertions(+), 11 deletions(-) diff --git a/pkg/tsdb/elasticsearch/client/client.go b/pkg/tsdb/elasticsearch/client/client.go index 70ed3946add..f172a61c4b3 100644 --- a/pkg/tsdb/elasticsearch/client/client.go +++ b/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 diff --git a/pkg/tsdb/elasticsearch/data_query.go b/pkg/tsdb/elasticsearch/data_query.go index a9f3d37f814..51ebb9037d0 100644 --- a/pkg/tsdb/elasticsearch/data_query.go +++ b/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 diff --git a/pkg/tsdb/elasticsearch/elasticsearch.go b/pkg/tsdb/elasticsearch/elasticsearch.go index a5d6b829560..4403ced8345 100644 --- a/pkg/tsdb/elasticsearch/elasticsearch.go +++ b/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 { diff --git a/pkg/tsdb/elasticsearch/response_parser.go b/pkg/tsdb/elasticsearch/response_parser.go index 2566aecf331..ed186d2848f 100644 --- a/pkg/tsdb/elasticsearch/response_parser.go +++ b/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 }