drsybren/Flamenco
1
0
Fork 0
Code Issues 1 Pull Requests Actions Packages Projects Releases Wiki Activity

Manager: more gracefully log context cancellation errors in database layer

Browse Source 
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.
This commit is contained in:
Sybren A. Stüvel 2024-05-28 17:23:47 +02:00
parent ee4e41329a
commit ee31316d9d
2 changed files with 35 additions and 9 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

18
internal/manager/api_impl/jobs_query.go
View File

@ -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))

24
internal/manager/persistence/logger.go
View File

@ -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()
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.