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
This commit is contained in:
Agnès Toulet 2025-01-09 10:19:11 +01:00 committed by GitHub
parent 4f2d8a1a3b
commit 4ae627e420
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194
3 changed files with 35 additions and 21 deletions

View File

@ -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) { 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) filePath, err := rs.getNewFilePath(renderType)
if err != nil { if err != nil {
return nil, err return nil, err
@ -118,13 +120,13 @@ func (rs *RenderingService) doRequestAndWriteToFile(ctx context.Context, renderT
defer func() { defer func() {
if err := resp.Body.Close(); err != nil { 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 we didn't get a 200 response, something went wrong.
if resp.StatusCode != http.StatusOK { 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, return nil, fmt.Errorf("remote rendering request failed, status code: %d, status: %s", resp.StatusCode,
resp.Status) 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) { 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) req, err := http.NewRequestWithContext(ctx, "GET", u.String(), nil)
if err != nil { if err != nil {
return nil, err return nil, err
@ -159,12 +163,12 @@ func (rs *RenderingService) doRequest(ctx context.Context, u *url.URL, headers m
req.Header[k] = v 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 // make request to renderer server
resp, err := netClient.Do(req) resp, err := netClient.Do(req)
if err != nil { 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 var urlErr *url.Error
if errors.As(err, &urlErr) { if errors.As(err, &urlErr) {
if urlErr.Timeout() { 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 { func (rs *RenderingService) writeResponseToFile(ctx context.Context, resp *http.Response, filePath string) error {
logger := rs.log.FromContext(ctx)
// check for timeout first // check for timeout first
if errors.Is(ctx.Err(), context.DeadlineExceeded) { if errors.Is(ctx.Err(), context.DeadlineExceeded) {
rs.log.Info("Rendering timed out") logger.Error("Rendering timed out")
return ErrTimeout return ErrTimeout
} }
@ -193,7 +199,7 @@ func (rs *RenderingService) writeResponseToFile(ctx context.Context, resp *http.
defer func() { defer func() {
if err := out.Close(); err != nil && !errors.Is(err, fs.ErrClosed) { 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 // 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 { if err != nil {
// check that we didn't timeout while receiving the response. // check that we didn't timeout while receiving the response.
if errors.Is(ctx.Err(), context.DeadlineExceeded) { if errors.Is(ctx.Err(), context.DeadlineExceeded) {
rs.log.Info("Rendering timed out") logger.Error("Rendering timed out")
return ErrTimeout 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) return fmt.Errorf("remote rendering request failed: %w", err)
} }
if err := out.Close(); err != nil { if err := out.Close(); err != nil {

View File

@ -9,6 +9,8 @@ import (
) )
func (rs *RenderingService) renderViaPlugin(ctx context.Context, renderType RenderType, renderKey string, opts Opts) (*RenderResult, error) { 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. // gives plugin some additional time to timeout and return possible errors.
ctx, cancel := context.WithTimeout(ctx, getRequestTimeout(opts.TimeoutOpts)) ctx, cancel := context.WithTimeout(ctx, getRequestTimeout(opts.TimeoutOpts))
defer cancel() defer cancel()
@ -40,7 +42,7 @@ func (rs *RenderingService) renderViaPlugin(ctx context.Context, renderType Rend
AuthToken: rs.Cfg.RendererAuthToken, AuthToken: rs.Cfg.RendererAuthToken,
Encoding: string(renderType), Encoding: string(renderType),
} }
rs.log.Debug("Calling renderer plugin", "req", req) logger.Debug("Calling renderer plugin", "req", req)
rc, err := rs.plugin.Client() rc, err := rs.plugin.Client()
if err != nil { if err != nil {
@ -48,7 +50,7 @@ func (rs *RenderingService) renderViaPlugin(ctx context.Context, renderType Rend
} }
rsp, err := rc.Render(ctx, req) rsp, err := rc.Render(ctx, req)
if errors.Is(ctx.Err(), context.DeadlineExceeded) { if errors.Is(ctx.Err(), context.DeadlineExceeded) {
rs.log.Info("Rendering timed out") logger.Error("Rendering timed out")
return nil, ErrTimeout return nil, ErrTimeout
} }
if err != nil { 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) { 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. // gives plugin some additional time to timeout and return possible errors.
ctx, cancel := context.WithTimeout(ctx, getRequestTimeout(opts.TimeoutOpts)) ctx, cancel := context.WithTimeout(ctx, getRequestTimeout(opts.TimeoutOpts))
defer cancel() defer cancel()
@ -88,7 +92,7 @@ func (rs *RenderingService) renderCSVViaPlugin(ctx context.Context, renderKey st
Headers: headers, Headers: headers,
AuthToken: rs.Cfg.RendererAuthToken, AuthToken: rs.Cfg.RendererAuthToken,
} }
rs.log.Debug("Calling renderer plugin", "req", req) logger.Debug("Calling renderer plugin", "req", req)
rc, err := rs.plugin.Client() rc, err := rs.plugin.Client()
if err != nil { if err != nil {
@ -98,7 +102,7 @@ func (rs *RenderingService) renderCSVViaPlugin(ctx context.Context, renderKey st
rsp, err := rc.RenderCSV(ctx, req) rsp, err := rc.RenderCSV(ctx, req)
if err != nil { if err != nil {
if errors.Is(ctx.Err(), context.DeadlineExceeded) { if errors.Is(ctx.Err(), context.DeadlineExceeded) {
rs.log.Info("Rendering timed out") logger.Error("Rendering timed out")
return nil, ErrTimeout return nil, ErrTimeout
} }

View File

@ -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) { func (rs *RenderingService) render(ctx context.Context, renderType RenderType, opts Opts, renderKeyProvider renderKeyProvider) (*RenderResult, error) {
logger := rs.log.FromContext(ctx)
if !rs.IsAvailable(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. " + "For image rendering support please install the grafana-image-renderer plugin. " +
"Read more at https://grafana.com/docs/grafana/latest/administration/image_rendering/") "Read more at https://grafana.com/docs/grafana/latest/administration/image_rendering/")
if opts.ErrorRenderUnavailable { 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 { 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 { if opts.ErrorConcurrentLimitReached {
return nil, ErrConcurrentLimitReached 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 { if math.IsInf(opts.DeviceScaleFactor, 0) || math.IsNaN(opts.DeviceScaleFactor) || opts.DeviceScaleFactor == 0 {
opts.DeviceScaleFactor = 1 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) res, err := rs.renderAction(ctx, renderType, renderKey, opts)
if err != nil { 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 return nil, err
} }
rs.log.Debug("Successfully rendered image", "path", opts.Path) logger.Debug("Successfully rendered image", "path", opts.Path)
return res, nil 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) { func (rs *RenderingService) renderCSV(ctx context.Context, opts CSVOpts, renderKeyProvider renderKeyProvider) (*RenderCSVResult, error) {
if int(atomic.LoadInt32(&rs.inProgressCount)) > opts.ConcurrentLimit { logger := rs.log.FromContext(ctx)
return nil, ErrConcurrentLimitReached
}
if !rs.IsAvailable(ctx) { if !rs.IsAvailable(ctx) {
return nil, ErrRenderUnavailable 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) renderKey, err := renderKeyProvider.get(ctx, opts.AuthOpts)
if err != nil { if err != nil {
return nil, err return nil, err