diff --git a/pkg/tsdb/loki/api.go b/pkg/tsdb/loki/api.go index cd5b863f0d3..af9585e2d99 100644 --- a/pkg/tsdb/loki/api.go +++ b/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.Debug("Response received from loki", "took", took, "status", resp.StatusCode, "length", resp.Header.Get("Content-Length")) + api.log.Info("Response received from loki", "duration", time.Since(start), "statusCode", resp.StatusCode, "contentLength", resp.Header.Get("Content-Length"), "stage", stageDatabaseRequest, "status", "ok") 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 diff --git a/pkg/tsdb/loki/loki.go b/pkg/tsdb/loki/loki.go index 07ce9040cb5..de9fd62ee9a 100644 --- a/pkg/tsdb/loki/loki.go +++ b/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 } }