Loki: Adjust to logging convention (#74531)

* adjust Loki to logging convention

* Fix call resource logging

* Update dataquery

* Update

* Remove redundant logging

* Fix TODO

* Rename action to stage and use variables

* `resp` might be `nil`

* `resp` might be `nil` here as well

* change to `statusCode`

* use correct logger

* also here

* add query information to logging

---------

Co-authored-by: Ivana Huckova <ivana.huckova@gmail.com>

pkg/tsdb/loki/api.go

@@ -4,6 +4,7 @@ import (
 	"bytes"
 	"context"
 	"encoding/json"
+	"errors"
 	"fmt"
 	"io"
 	"net/http"
@@ -158,26 +159,35 @@ func (api *LokiAPI) DataQuery(ctx context.Context, query lokiQuery, responseOpts
 		return nil, err
 	}
 
-	api.log.Debug("Sending query to loki", "start", query.Start, "end", query.End, "step", query.Step, "query", query.Expr, "queryType", query.QueryType, "direction", query.Direction, "maxLines", query.MaxLines, "supportingQueryType", query.SupportingQueryType, "lokiHost", req.URL.Host, "lokiPath", req.URL.Path)
+	queryAttrs := []any{"start", query.Start, "end", query.End, "step", query.Step, "query", query.Expr, "queryType", query.QueryType, "direction", query.Direction, "maxLines", query.MaxLines, "supportingQueryType", query.SupportingQueryType, "lokiHost", req.URL.Host, "lokiPath", req.URL.Path}
+	api.log.Debug("Sending query to loki", queryAttrs...)
 	start := time.Now()
-
 	resp, err := api.client.Do(req)
 	if err != nil {
+		status := "error"
+		if errors.Is(err, context.Canceled) {
+			status = "cancelled"
+		}
+		lp := []any{"error", err, "status", status, "duration", time.Since(start), "stage", stageDatabaseRequest}
+		lp = append(lp, queryAttrs...)
+		if resp != nil {
+			lp = append(lp, "statusCode", resp.StatusCode)
+		}
+		api.log.Error("Error received from Loki", lp...)
 		return nil, err
 	}
 
-	took := time.Since(start)
+	api.log.Info("Response received from loki", "duration", time.Since(start), "statusCode", resp.StatusCode, "contentLength", resp.Header.Get("Content-Length"), "stage", stageDatabaseRequest, "status", "ok")
-	api.log.Debug("Response received from loki", "took", took, "status", resp.StatusCode, "length", resp.Header.Get("Content-Length"))
 
 	defer func() {
 		if err := resp.Body.Close(); err != nil {
-			api.log.Warn("Failed to close response body", "err", err)
+			api.log.Warn("Failed to close response body", "error", err)
 		}
 	}()
 
 	if resp.StatusCode/100 != 2 {
 		err := readLokiError(resp.Body)
-		api.log.Error("Error received from loki", "err", err, "status", resp.StatusCode)
+		api.log.Error("Error received from loki", "error", err, "status", resp.StatusCode)
 		return nil, err
 	}
 
@@ -188,16 +198,15 @@ func (api *LokiAPI) DataQuery(ctx context.Context, query lokiQuery, responseOpts
 
 	iter := jsoniter.Parse(jsoniter.ConfigDefault, resp.Body, 1024)
 	res := converter.ReadPrometheusStyleResult(iter, converter.Options{Dataplane: responseOpts.metricDataplane})
-	took = time.Since(start)
 
 	if res.Error != nil {
 		span.RecordError(res.Error)
 		span.SetStatus(codes.Error, err.Error())
-		logger.Error("Error parsing response from loki", "err", res.Error, "metricDataplane", responseOpts.metricDataplane, "took", took)
+		api.log.Error("Error parsing response from loki", "error", res.Error, "metricDataplane", responseOpts.metricDataplane, "duration", time.Since(start), "stage", stageParseResponse)
 		return nil, res.Error
 	}
 
-	logger.Debug("Response parsed from loki", "took", took, "metricDataplane", responseOpts.metricDataplane, "framesLength", len(res.Frames))
+	api.log.Info("Response parsed from loki", "duration", time.Since(start), "metricDataplane", responseOpts.metricDataplane, "framesLength", len(res.Frames), "stage", stageParseResponse)
 
 	return res.Frames, nil
 }
@@ -228,25 +237,33 @@ func makeRawRequest(ctx context.Context, lokiDsUrl string, resourcePath string)
 
 func (api *LokiAPI) RawQuery(ctx context.Context, resourcePath string) (RawLokiResponse, error) {
 	api.log.Debug("Sending raw query to loki", "resourcePath", resourcePath)
-	start := time.Now()
 	req, err := makeRawRequest(ctx, api.url, resourcePath)
 	if err != nil {
-		api.log.Error("Failed to prepare request to loki", "err", err, "resourcePath", resourcePath)
+		api.log.Error("Failed to prepare request to loki", "error", err, "resourcePath", resourcePath)
 		return RawLokiResponse{}, err
 	}
-
+	start := time.Now()
 	resp, err := api.client.Do(req)
 	if err != nil {
+		status := "error"
+		if errors.Is(err, context.Canceled) {
+			status = "cancelled"
+		}
+		lp := []any{"error", err, "resourcePath", resourcePath, "status", status, "duration", time.Since(start), "stage", stageDatabaseRequest}
+		if resp != nil {
+			lp = append(lp, "statusCode", resp.StatusCode)
+		}
+		api.log.Error("Error received from Loki", lp...)
 		return RawLokiResponse{}, err
 	}
 
 	defer func() {
 		if err := resp.Body.Close(); err != nil {
-			api.log.Warn("Failed to close response body", "err", err)
+			api.log.Warn("Failed to close response body", "error", err)
 		}
 	}()
 
-	api.log.Debug("Response received from loki", "status", resp.StatusCode, "length", resp.Header.Get("Content-Length"), "took", time.Since(start), "encoding", resp.Header.Get("Content-Encoding"))
+	api.log.Info("Response received from loki", "status", "ok", "statusCode", resp.StatusCode, "contentLength", resp.Header.Get("Content-Length"), "duration", time.Since(start), "contentEncoding", resp.Header.Get("Content-Encoding"), "stage", stageDatabaseRequest)
 
 	// server errors are handled by the plugin-proxy to hide the error message
 	if resp.StatusCode/100 == 5 {
@@ -255,13 +272,14 @@ func (api *LokiAPI) RawQuery(ctx context.Context, resourcePath string) (RawLokiR
 
 	body, err := io.ReadAll(resp.Body)
 	if err != nil {
+		api.log.Error("Error reading response body bytes", "error", err)
 		return RawLokiResponse{}, err
 	}
 
 	// client errors are passed as a json struct to the client
 	if resp.StatusCode/100 != 2 {
 		lokiResponseErr := lokiResponseError{Message: makeLokiError(body).Error()}
-		api.log.Warn("Non 200 HTTP status received from loki", "err", lokiResponseErr.Message, "status", resp.StatusCode, "resourcePath", resourcePath)
+		api.log.Warn("Non 200 HTTP status received from loki", "error", lokiResponseErr.Message, "statusCode", resp.StatusCode, "resourcePath", resourcePath)
 		traceID := tracing.TraceIDFromContext(ctx, false)
 		if traceID != "" {
 			lokiResponseErr.TraceID = traceID

pkg/tsdb/loki/loki.go

@@ -8,6 +8,7 @@ import (
 	"regexp"
 	"strings"
 	"sync"
+	"time"
 
 	"github.com/grafana/grafana-plugin-sdk-go/backend"
 	"github.com/grafana/grafana-plugin-sdk-go/backend/datasource"
@@ -52,6 +53,13 @@ var (
 	legendFormat = regexp.MustCompile(`\{\{\s*(.+?)\s*\}\}`)
 )
 
+// Used in logging to mark a stage
+var (
+	stagePrepareRequest  = "prepareRequest"
+	stageDatabaseRequest = "databaseRequest"
+	stageParseResponse   = "parseResponse"
+)
+
 type datasourceInfo struct {
 	HTTPClient *http.Client
 	URL        string
@@ -101,9 +109,9 @@ func newInstanceSettings(httpClientProvider httpclient.Provider) datasource.Inst
 
 func (s *Service) CallResource(ctx context.Context, req *backend.CallResourceRequest, sender backend.CallResourceResponseSender) error {
 	dsInfo, err := s.getDSInfo(ctx, req.PluginContext)
-	logger := logger.FromContext(ctx).New("api", "CallResource")
+	logger := s.logger.FromContext(ctx)
 	if err != nil {
-		logger.Error("Failed to get data source info", "err", err)
+		logger.Error("Failed to get data source info", "error", err)
 		return err
 	}
 	return callResource(ctx, req, sender, dsInfo, logger, s.tracer)
@@ -154,7 +162,7 @@ func callResource(ctx context.Context, req *backend.CallResourceRequest, sender
 func (s *Service) QueryData(ctx context.Context, req *backend.QueryDataRequest) (*backend.QueryDataResponse, error) {
 	dsInfo, err := s.getDSInfo(ctx, req.PluginContext)
 	_, fromAlert := req.Headers[ngalertmodels.FromAlertHeaderName]
-	logger := logger.FromContext(ctx).New("api", "QueryData", "fromAlert", fromAlert)
+	logger := logger.FromContext(ctx).New("fromAlert", fromAlert)
 	if err != nil {
 		logger.Error("Failed to get data source info", "err", err)
 		result := backend.NewQueryDataResponse()
@@ -174,11 +182,13 @@ func queryData(ctx context.Context, req *backend.QueryDataRequest, dsInfo *datas
 
 	api := newLokiAPI(dsInfo.HTTPClient, dsInfo.URL, plog, tracer)
 
+	start := time.Now()
 	queries, err := parseQuery(req)
 	if err != nil {
-		plog.Error("Failed to parse queries", "err", err)
+		plog.Error("Failed to prepare request to Loki", "error", err, "duration", time.Since(start), "queriesLength", len(queries), "stage", stagePrepareRequest)
 		return result, err
 	}
+	plog.Info("Prepared request to Loki", "duration", time.Since(start), "queriesLength", len(queries), "stage", stagePrepareRequest)
 
 	for _, query := range queries {
 		ctx, span := tracer.Start(ctx, "datasource.loki.queryData.runQuery")
@@ -212,7 +222,7 @@ func queryData(ctx context.Context, req *backend.QueryDataRequest, dsInfo *datas
 func runQuery(ctx context.Context, api *LokiAPI, query *lokiQuery, responseOpts ResponseOpts) (data.Frames, error) {
 	frames, err := api.DataQuery(ctx, *query, responseOpts)
 	if err != nil {
-		logger.Error("Error querying loki", "err", err)
+		logger.Error("Error querying loki", "error", err)
 		return data.Frames{}, err
 	}
 
@@ -220,7 +230,7 @@ func runQuery(ctx context.Context, api *LokiAPI, query *lokiQuery, responseOpts
 		err = adjustFrame(frame, query, !responseOpts.metricDataplane, responseOpts.logsDataplane)
 
 		if err != nil {
-			logger.Error("Error adjusting frame", "err", err)
+			logger.Error("Error adjusting frame", "error", err)
 			return data.Frames{}, err
 		}
 	}