From ee31316d9d191438f01a0b74bc0f6a81e241d707 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Sybren=20A=2E=20St=C3=BCvel?= Date: Tue, 28 May 2024 17:23:47 +0200 Subject: [PATCH] Manager: more gracefully log context cancellation errors in database layer The context passed to the database layer will auto-close when the HTTP client disconnects. This will cancel any running query, which is the expected behaviour. Now this no longer results in an error being logged in the database layer. Instead, a message is logged at debug level. The API layer is also adjusted to silence logging of `context.Canceled` for certain operations, most notably getting all jobs and getting all tasks of a job. These calls occur when the webapp reconnects after a restart of the Manager. That may trigger a refresh of the page, which immediately aborts any pending API calls. This is normal and should not cause errors to be logged. --- internal/manager/api_impl/jobs_query.go | 18 ++++++++++++----- internal/manager/persistence/logger.go | 26 +++++++++++++++++++++---- 2 files changed, 35 insertions(+), 9 deletions(-) diff --git a/internal/manager/api_impl/jobs_query.go b/internal/manager/api_impl/jobs_query.go index bafe39bf..bfc18779 100644 --- a/internal/manager/api_impl/jobs_query.go +++ b/internal/manager/api_impl/jobs_query.go @@ -70,9 +70,13 @@ func (f *Flamenco) QueryJobs(e echo.Context) error { ctx := e.Request().Context() dbJobs, err := f.persist.QueryJobs(ctx, api.JobsQuery(jobsQuery)) - if err != nil { + switch { + case errors.Is(err, context.Canceled): + logger.Debug().AnErr("cause", err).Msg("could not query for jobs, remote end probably closed the connection") + return sendAPIError(e, http.StatusInternalServerError, "error querying for jobs: %v", err) + case err != nil: logger.Warn().Err(err).Msg("error querying for jobs") - return sendAPIError(e, http.StatusInternalServerError, "error querying for jobs") + return sendAPIError(e, http.StatusInternalServerError, "error querying for jobs: %v", err) } apiJobs := make([]api.Job, len(dbJobs)) @@ -97,9 +101,13 @@ func (f *Flamenco) FetchJobTasks(e echo.Context, jobID string) error { } tasks, err := f.persist.QueryJobTaskSummaries(ctx, jobID) - if err != nil { - logger.Warn().Err(err).Msg("error querying for jobs") - return sendAPIError(e, http.StatusInternalServerError, "error querying for jobs") + switch { + case errors.Is(err, context.Canceled): + logger.Debug().AnErr("cause", err).Msg("could not fetch job tasks, remote end probably closed connection") + return sendAPIError(e, http.StatusInternalServerError, "error fetching job tasks: %v", err) + case err != nil: + logger.Warn().Err(err).Msg("error fetching job tasks") + return sendAPIError(e, http.StatusInternalServerError, "error fetching job tasks: %v", err) } summaries := make([]api.TaskSummary, len(tasks)) diff --git a/internal/manager/persistence/logger.go b/internal/manager/persistence/logger.go index 3e346ef8..a5db0b8f 100644 --- a/internal/manager/persistence/logger.go +++ b/internal/manager/persistence/logger.go @@ -85,7 +85,7 @@ func (l *dbLogger) Trace(ctx context.Context, begin time.Time, fc func() (sql st // Function to lazily get the SQL, affected rows, and logger. buildLogger := func() (loggerPtr *zerolog.Logger, sql string) { sql, rows := fc() - logCtx = logCtx.Err(err) + logCtx = logCtx.AnErr("cause", err) if rows >= 0 { logCtx = logCtx.Int64("rowsAffected", rows) } @@ -94,9 +94,13 @@ func (l *dbLogger) Trace(ctx context.Context, begin time.Time, fc func() (sql st } switch { - case err != nil && zlogLevel <= zerolog.ErrorLevel && (!errors.Is(err, gorm.ErrRecordNotFound) || !l.IgnoreRecordNotFoundError): + case err != nil && zlogLevel <= zerolog.ErrorLevel: logger, sql := buildLogger() - logger.Error().Msg(sql) + if l.silenceLoggingError(err) { + logger.Debug().Msg(sql) + } else { + logger.Error().Msg(sql) + } case elapsed > l.SlowThreshold && l.SlowThreshold != 0 && zlogLevel <= zerolog.WarnLevel: logger, sql := buildLogger() @@ -112,13 +116,27 @@ func (l *dbLogger) Trace(ctx context.Context, begin time.Time, fc func() (sql st } } +func (l dbLogger) silenceLoggingError(err error) bool { + switch { + case l.IgnoreRecordNotFoundError && errors.Is(err, gorm.ErrRecordNotFound): + return true + case errors.Is(err, context.Canceled): + // These are usually caused by the HTTP client connection closing. Stopping + // a database query is normal behaviour in such a case, so this shouldn't be + // logged as an error. + return true + default: + return false + } +} + // logEvent logs an even at the given level. func (l dbLogger) logEvent(level zerolog.Level, msg string, args ...interface{}) { if l.zlog.GetLevel() > level { return } logger := l.logger(args) - logger.WithLevel(level).Msg(msg) + logger.WithLevel(level).Msg("logEvent: " + msg) } // logger constructs a zerolog logger. The given arguments are added via reflection.