From 4ae627e420b1ac557d7869235aacaab63d721b43 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Agn=C3=A8s=20Toulet?= <35176601+AgnesToulet@users.noreply.github.com> Date: Thu, 9 Jan 2025 10:19:11 +0100 Subject: [PATCH] Render Service: Add trace ID to logs (#98006) * Rendering: add logs * fix tests and lint issues * add context to logs * update timed out logs to error logs --- pkg/services/rendering/http_mode.go | 22 ++++++++++++++-------- pkg/services/rendering/plugin_mode.go | 12 ++++++++---- pkg/services/rendering/rendering.go | 22 +++++++++++++--------- 3 files changed, 35 insertions(+), 21 deletions(-) diff --git a/pkg/services/rendering/http_mode.go b/pkg/services/rendering/http_mode.go index 0900f9fd90f..f278acca7d8 100644 --- a/pkg/services/rendering/http_mode.go +++ b/pkg/services/rendering/http_mode.go @@ -102,6 +102,8 @@ func (rs *RenderingService) generateImageRendererURL(renderType RenderType, opts } func (rs *RenderingService) doRequestAndWriteToFile(ctx context.Context, renderType RenderType, rendererURL *url.URL, timeoutOpts TimeoutOpts, headers map[string][]string) (*Result, error) { + logger := rs.log.FromContext(ctx) + filePath, err := rs.getNewFilePath(renderType) if err != nil { return nil, err @@ -118,13 +120,13 @@ func (rs *RenderingService) doRequestAndWriteToFile(ctx context.Context, renderT defer func() { if err := resp.Body.Close(); err != nil { - rs.log.Warn("Failed to close response body", "err", err) + logger.Warn("Failed to close response body", "err", err) } }() // if we didn't get a 200 response, something went wrong. if resp.StatusCode != http.StatusOK { - rs.log.Error("Remote rendering request failed", "error", resp.Status, "url", rendererURL.Query().Get("url")) + logger.Error("Remote rendering request failed", "error", resp.Status, "url", rendererURL.Query().Get("url")) return nil, fmt.Errorf("remote rendering request failed, status code: %d, status: %s", resp.StatusCode, resp.Status) } @@ -148,6 +150,8 @@ func (rs *RenderingService) doRequestAndWriteToFile(ctx context.Context, renderT } func (rs *RenderingService) doRequest(ctx context.Context, u *url.URL, headers map[string][]string) (*http.Response, error) { + logger := rs.log.FromContext(ctx) + req, err := http.NewRequestWithContext(ctx, "GET", u.String(), nil) if err != nil { return nil, err @@ -159,12 +163,12 @@ func (rs *RenderingService) doRequest(ctx context.Context, u *url.URL, headers m req.Header[k] = v } - rs.log.Debug("calling remote rendering service", "url", u) + logger.Debug("calling remote rendering service", "url", u) // make request to renderer server resp, err := netClient.Do(req) if err != nil { - rs.log.Error("Failed to send request to remote rendering service", "error", err) + logger.Error("Failed to send request to remote rendering service", "error", err) var urlErr *url.Error if errors.As(err, &urlErr) { if urlErr.Timeout() { @@ -178,9 +182,11 @@ func (rs *RenderingService) doRequest(ctx context.Context, u *url.URL, headers m } func (rs *RenderingService) writeResponseToFile(ctx context.Context, resp *http.Response, filePath string) error { + logger := rs.log.FromContext(ctx) + // check for timeout first if errors.Is(ctx.Err(), context.DeadlineExceeded) { - rs.log.Info("Rendering timed out") + logger.Error("Rendering timed out") return ErrTimeout } @@ -193,7 +199,7 @@ func (rs *RenderingService) writeResponseToFile(ctx context.Context, resp *http. defer func() { if err := out.Close(); err != nil && !errors.Is(err, fs.ErrClosed) { // We already close the file explicitly in the non-error path, so shouldn't be a problem - rs.log.Warn("Failed to close file", "path", filePath, "err", err) + logger.Warn("Failed to close file", "path", filePath, "err", err) } }() @@ -201,11 +207,11 @@ func (rs *RenderingService) writeResponseToFile(ctx context.Context, resp *http. if err != nil { // check that we didn't timeout while receiving the response. if errors.Is(ctx.Err(), context.DeadlineExceeded) { - rs.log.Info("Rendering timed out") + logger.Error("Rendering timed out") return ErrTimeout } - rs.log.Error("Remote rendering request failed", "error", err) + logger.Error("Remote rendering request failed", "error", err) return fmt.Errorf("remote rendering request failed: %w", err) } if err := out.Close(); err != nil { diff --git a/pkg/services/rendering/plugin_mode.go b/pkg/services/rendering/plugin_mode.go index 6a69d1c56d0..98eea55eb46 100644 --- a/pkg/services/rendering/plugin_mode.go +++ b/pkg/services/rendering/plugin_mode.go @@ -9,6 +9,8 @@ import ( ) func (rs *RenderingService) renderViaPlugin(ctx context.Context, renderType RenderType, renderKey string, opts Opts) (*RenderResult, error) { + logger := rs.log.FromContext(ctx) + // gives plugin some additional time to timeout and return possible errors. ctx, cancel := context.WithTimeout(ctx, getRequestTimeout(opts.TimeoutOpts)) defer cancel() @@ -40,7 +42,7 @@ func (rs *RenderingService) renderViaPlugin(ctx context.Context, renderType Rend AuthToken: rs.Cfg.RendererAuthToken, Encoding: string(renderType), } - rs.log.Debug("Calling renderer plugin", "req", req) + logger.Debug("Calling renderer plugin", "req", req) rc, err := rs.plugin.Client() if err != nil { @@ -48,7 +50,7 @@ func (rs *RenderingService) renderViaPlugin(ctx context.Context, renderType Rend } rsp, err := rc.Render(ctx, req) if errors.Is(ctx.Err(), context.DeadlineExceeded) { - rs.log.Info("Rendering timed out") + logger.Error("Rendering timed out") return nil, ErrTimeout } if err != nil { @@ -62,6 +64,8 @@ func (rs *RenderingService) renderViaPlugin(ctx context.Context, renderType Rend } func (rs *RenderingService) renderCSVViaPlugin(ctx context.Context, renderKey string, opts CSVOpts) (*RenderCSVResult, error) { + logger := rs.log.FromContext(ctx) + // gives plugin some additional time to timeout and return possible errors. ctx, cancel := context.WithTimeout(ctx, getRequestTimeout(opts.TimeoutOpts)) defer cancel() @@ -88,7 +92,7 @@ func (rs *RenderingService) renderCSVViaPlugin(ctx context.Context, renderKey st Headers: headers, AuthToken: rs.Cfg.RendererAuthToken, } - rs.log.Debug("Calling renderer plugin", "req", req) + logger.Debug("Calling renderer plugin", "req", req) rc, err := rs.plugin.Client() if err != nil { @@ -98,7 +102,7 @@ func (rs *RenderingService) renderCSVViaPlugin(ctx context.Context, renderKey st rsp, err := rc.RenderCSV(ctx, req) if err != nil { if errors.Is(ctx.Err(), context.DeadlineExceeded) { - rs.log.Info("Rendering timed out") + logger.Error("Rendering timed out") return nil, ErrTimeout } diff --git a/pkg/services/rendering/rendering.go b/pkg/services/rendering/rendering.go index 36799f69a7a..cb25268154f 100644 --- a/pkg/services/rendering/rendering.go +++ b/pkg/services/rendering/rendering.go @@ -271,8 +271,10 @@ func (rs *RenderingService) Render(ctx context.Context, renderType RenderType, o } func (rs *RenderingService) render(ctx context.Context, renderType RenderType, opts Opts, renderKeyProvider renderKeyProvider) (*RenderResult, error) { + logger := rs.log.FromContext(ctx) + if !rs.IsAvailable(ctx) { - rs.log.Warn("Could not render image, no image renderer found/installed. " + + logger.Warn("Could not render image, no image renderer found/installed. " + "For image rendering support please install the grafana-image-renderer plugin. " + "Read more at https://grafana.com/docs/grafana/latest/administration/image_rendering/") if opts.ErrorRenderUnavailable { @@ -282,7 +284,7 @@ func (rs *RenderingService) render(ctx context.Context, renderType RenderType, o } if int(atomic.LoadInt32(&rs.inProgressCount)) > opts.ConcurrentLimit { - rs.log.Warn("Could not render image, hit the currency limit", "concurrencyLimit", opts.ConcurrentLimit, "path", opts.Path) + logger.Warn("Could not render image, hit the currency limit", "concurrencyLimit", opts.ConcurrentLimit, "path", opts.Path) if opts.ErrorConcurrentLimitReached { return nil, ErrConcurrentLimitReached } @@ -312,7 +314,7 @@ func (rs *RenderingService) render(ctx context.Context, renderType RenderType, o } } - rs.log.Info("Rendering", "path", opts.Path, "userID", opts.AuthOpts.UserID) + logger.Info("Rendering", "path", opts.Path, "userID", opts.AuthOpts.UserID) if math.IsInf(opts.DeviceScaleFactor, 0) || math.IsNaN(opts.DeviceScaleFactor) || opts.DeviceScaleFactor == 0 { opts.DeviceScaleFactor = 1 } @@ -325,10 +327,10 @@ func (rs *RenderingService) render(ctx context.Context, renderType RenderType, o res, err := rs.renderAction(ctx, renderType, renderKey, opts) if err != nil { - rs.log.Error("Failed to render image", "path", opts.Path, "error", err) + logger.Error("Failed to render image", "path", opts.Path, "error", err) return nil, err } - rs.log.Debug("Successfully rendered image", "path", opts.Path) + logger.Debug("Successfully rendered image", "path", opts.Path) return res, nil } @@ -367,15 +369,17 @@ func (rs *RenderingService) SanitizeSVG(ctx context.Context, req *SanitizeSVGReq } func (rs *RenderingService) renderCSV(ctx context.Context, opts CSVOpts, renderKeyProvider renderKeyProvider) (*RenderCSVResult, error) { - if int(atomic.LoadInt32(&rs.inProgressCount)) > opts.ConcurrentLimit { - return nil, ErrConcurrentLimitReached - } + logger := rs.log.FromContext(ctx) if !rs.IsAvailable(ctx) { return nil, ErrRenderUnavailable } - rs.log.Info("Rendering", "path", opts.Path) + if int(atomic.LoadInt32(&rs.inProgressCount)) > opts.ConcurrentLimit { + return nil, ErrConcurrentLimitReached + } + + logger.Info("Rendering", "path", opts.Path) renderKey, err := renderKeyProvider.get(ctx, opts.AuthOpts) if err != nil { return nil, err