Skip to content

Commit

Permalink
fix(backend): キューのエラーログを簡略化するように (#14748)
Browse files Browse the repository at this point in the history 
* reduce federation log spam

* Don't record stack trace for unrecoverable errors.
* Avoid logging duplicate stace traces.

(cherry picked from commit ed05701)

* improve error summaries

(cherry picked from commit 20dd66f)

* fix lint errors

(cherry picked from commit 83869e1)

* condense job info

(cherry picked from commit 786702e)

* fix maxAttempts calculation

(cherry picked from commit b4d10aa)

* condense error info

(cherry picked from commit f62cd89)

* normalize ID logging

(cherry picked from commit d8e1e48)

* further condense error details

(cherry picked from commit d867c20)

* collapse AbortErrors

(cherry picked from commit 5171ba7)

* don't log job name unless it has one

(cherry picked from commit a5316c0)

* Update Changelog

* Record origin

---------

Co-authored-by: Hazel K <[email protected]>
  • Loading branch information
@kakkokari-gtyih @warriordog
kakkokari-gtyih and warriordog authored Oct 11, 2024
1 parent 7778046 commit 2f09d69
Show file tree
Hide file tree
Showing 2 changed files with 52 additions and 38 deletions.
4 changes: 4 additions & 0 deletions CHANGELOG.md
View file
Original file line number Diff line number Diff line change
Expand Up @@ -12,6 +12,10 @@
- Feat: モデレータ権限を持つユーザが全員7日間活動しなかった場合は自動的に招待制へと移行するように ( #13437 )
- Fix: `admin/emoji/update`エンドポイントのidのみ指定した時不正なエラーが発生するバグを修正

### Server
- Fix: キューのエラーログを簡略化するように
(Cherry-picked from https://activitypub.software/TransFem-org/Sharkey/-/merge_requests/649)

## 2024.10.0

### Note
Expand Down
86 changes: 48 additions & 38 deletions packages/backend/src/queue/QueueProcessorService.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -67,7 +67,7 @@ function getJobInfo(job: Bull.Job | undefined, increment = false): string {

// onActiveとかonCompletedのattemptsMadeがなぜか0始まりなのでインクリメントする
const currentAttempts = job.attemptsMade + (increment ? 1 : 0);
const maxAttempts = job.opts ? job.opts.attempts : 0;
const maxAttempts = job.opts.attempts ?? 0;

return `id=${job.id} attempts=${currentAttempts}/${maxAttempts} age=${formated}`;
}
Expand Down Expand Up @@ -126,20 +126,30 @@ export class QueueProcessorService implements OnApplicationShutdown {
) {
this.logger = this.queueLoggerService.logger;

function renderError(e: Error): any {
if (e) { // 何故かeがundefinedで来ることがある
return {
stack: e.stack,
message: e.message,
name: e.name,
};
} else {
return {
stack: '?',
message: '?',
name: '?',
};
function renderError(e?: Error) {
// 何故かeがundefinedで来ることがある
if (!e) return '?';

if (e instanceof Bull.UnrecoverableError || e.name === 'AbortError') {
return `${e.name}: ${e.message}`;
}

return {
stack: e.stack,
message: e.message,
name: e.name,
};
}

function renderJob(job?: Bull.Job) {
if (!job) return '?';

return {
name: job.name || undefined,
info: getJobInfo(job),
failedReason: job.failedReason || undefined,
data: job.data,
};
}

//#region system
Expand Down Expand Up @@ -175,15 +185,15 @@ export class QueueProcessorService implements OnApplicationShutdown {
.on('active', (job) => logger.debug(`active id=${job.id}`))
.on('completed', (job, result) => logger.debug(`completed(${result}) id=${job.id}`))
.on('failed', (job, err: Error) => {
logger.error(`failed(${err.stack}) id=${job ? job.id : '-'}`, { job, e: renderError(err) });
logger.error(`failed(${err.name}: ${err.message}) id=${job?.id ?? '?'}`, { job: renderJob(job), e: renderError(err) });
if (config.sentryForBackend) {
Sentry.captureMessage(`Queue: System: ${job?.name ?? '?'}: ${err.message}`, {
Sentry.captureMessage(`Queue: System: ${job?.name ?? '?'}: ${err.name}: ${err.message}`, {
level: 'error',
extra: { job, err },
});
}
})
.on('error', (err: Error) => logger.error(`error ${err.stack}`, { e: renderError(err) }))
.on('error', (err: Error) => logger.error(`error ${err.name}: ${err.message}`, { e: renderError(err) }))
.on('stalled', (jobId) => logger.warn(`stalled id=${jobId}`));
}
//#endregion
Expand Down Expand Up @@ -232,15 +242,15 @@ export class QueueProcessorService implements OnApplicationShutdown {
.on('active', (job) => logger.debug(`active id=${job.id}`))
.on('completed', (job, result) => logger.debug(`completed(${result}) id=${job.id}`))
.on('failed', (job, err) => {
logger.error(`failed(${err.stack}) id=${job ? job.id : '-'}`, { job, e: renderError(err) });
logger.error(`failed(${err.name}: ${err.message}) id=${job?.id ?? '?'}`, { job: renderJob(job), e: renderError(err) });
if (config.sentryForBackend) {
Sentry.captureMessage(`Queue: DB: ${job?.name ?? '?'}: ${err.message}`, {
Sentry.captureMessage(`Queue: DB: ${job?.name ?? '?'}: ${err.name}: ${err.message}`, {
level: 'error',
extra: { job, err },
});
}
})
.on('error', (err: Error) => logger.error(`error ${err.stack}`, { e: renderError(err) }))
.on('error', (err: Error) => logger.error(`error ${err.name}: ${err.message}`, { e: renderError(err) }))
.on('stalled', (jobId) => logger.warn(`stalled id=${jobId}`));
}
//#endregion
Expand Down Expand Up @@ -272,15 +282,15 @@ export class QueueProcessorService implements OnApplicationShutdown {
.on('active', (job) => logger.debug(`active ${getJobInfo(job, true)} to=${job.data.to}`))
.on('completed', (job, result) => logger.debug(`completed(${result}) ${getJobInfo(job, true)} to=${job.data.to}`))
.on('failed', (job, err) => {
logger.error(`failed(${err.stack}) ${getJobInfo(job)} to=${job ? job.data.to : '-'}`);
logger.error(`failed(${err.name}: ${err.message}) ${getJobInfo(job)} to=${job ? job.data.to : '-'}`);
if (config.sentryForBackend) {
Sentry.captureMessage(`Queue: Deliver: ${err.message}`, {
Sentry.captureMessage(`Queue: Deliver: ${err.name}: ${err.message}`, {
level: 'error',
extra: { job, err },
});
}
})
.on('error', (err: Error) => logger.error(`error ${err.stack}`, { e: renderError(err) }))
.on('error', (err: Error) => logger.error(`error ${err.name}: ${err.message}`, { e: renderError(err) }))
.on('stalled', (jobId) => logger.warn(`stalled id=${jobId}`));
}
//#endregion
Expand Down Expand Up @@ -312,15 +322,15 @@ export class QueueProcessorService implements OnApplicationShutdown {
.on('active', (job) => logger.debug(`active ${getJobInfo(job, true)}`))
.on('completed', (job, result) => logger.debug(`completed(${result}) ${getJobInfo(job, true)}`))
.on('failed', (job, err) => {
logger.error(`failed(${err.stack}) ${getJobInfo(job)} activity=${job ? (job.data.activity ? job.data.activity.id : 'none') : '-'}`, { job, e: renderError(err) });
logger.error(`failed(${err.name}: ${err.message}) ${getJobInfo(job)} activity=${job ? (job.data.activity ? job.data.activity.id : 'none') : '-'}`, { job: renderJob(job), e: renderError(err) });
if (config.sentryForBackend) {
Sentry.captureMessage(`Queue: Inbox: ${err.message}`, {
Sentry.captureMessage(`Queue: Inbox: ${err.name}: ${err.message}`, {
level: 'error',
extra: { job, err },
});
}
})
.on('error', (err: Error) => logger.error(`error ${err.stack}`, { e: renderError(err) }))
.on('error', (err: Error) => logger.error(`error ${err.name}: ${err.message}`, { e: renderError(err) }))
.on('stalled', (jobId) => logger.warn(`stalled id=${jobId}`));
}
//#endregion
Expand Down Expand Up @@ -352,15 +362,15 @@ export class QueueProcessorService implements OnApplicationShutdown {
.on('active', (job) => logger.debug(`active ${getJobInfo(job, true)} to=${job.data.to}`))
.on('completed', (job, result) => logger.debug(`completed(${result}) ${getJobInfo(job, true)} to=${job.data.to}`))
.on('failed', (job, err) => {
logger.error(`failed(${err.stack}) ${getJobInfo(job)} to=${job ? job.data.to : '-'}`);
logger.error(`failed(${err.name}: ${err.message}) ${getJobInfo(job)} to=${job ? job.data.to : '-'}`);
if (config.sentryForBackend) {
Sentry.captureMessage(`Queue: UserWebhookDeliver: ${err.message}`, {
Sentry.captureMessage(`Queue: UserWebhookDeliver: ${err.name}: ${err.message}`, {
level: 'error',
extra: { job, err },
});
}
})
.on('error', (err: Error) => logger.error(`error ${err.stack}`, { e: renderError(err) }))
.on('error', (err: Error) => logger.error(`error ${err.name}: ${err.message}`, { e: renderError(err) }))
.on('stalled', (jobId) => logger.warn(`stalled id=${jobId}`));
}
//#endregion
Expand Down Expand Up @@ -392,15 +402,15 @@ export class QueueProcessorService implements OnApplicationShutdown {
.on('active', (job) => logger.debug(`active ${getJobInfo(job, true)} to=${job.data.to}`))
.on('completed', (job, result) => logger.debug(`completed(${result}) ${getJobInfo(job, true)} to=${job.data.to}`))
.on('failed', (job, err) => {
logger.error(`failed(${err.stack}) ${getJobInfo(job)} to=${job ? job.data.to : '-'}`);
logger.error(`failed(${err.name}: ${err.message}) ${getJobInfo(job)} to=${job ? job.data.to : '-'}`);
if (config.sentryForBackend) {
Sentry.captureMessage(`Queue: SystemWebhookDeliver: ${err.message}`, {
Sentry.captureMessage(`Queue: SystemWebhookDeliver: ${err.name}: ${err.message}`, {
level: 'error',
extra: { job, err },
});
}
})
.on('error', (err: Error) => logger.error(`error ${err.stack}`, { e: renderError(err) }))
.on('error', (err: Error) => logger.error(`error ${err.name}: ${err.message}`, { e: renderError(err) }))
.on('stalled', (jobId) => logger.warn(`stalled id=${jobId}`));
}
//#endregion
Expand Down Expand Up @@ -439,15 +449,15 @@ export class QueueProcessorService implements OnApplicationShutdown {
.on('active', (job) => logger.debug(`active id=${job.id}`))
.on('completed', (job, result) => logger.debug(`completed(${result}) id=${job.id}`))
.on('failed', (job, err) => {
logger.error(`failed(${err.stack}) id=${job ? job.id : '-'}`, { job, e: renderError(err) });
logger.error(`failed(${err.name}: ${err.message}) id=${job?.id ?? '?'}`, { job: renderJob(job), e: renderError(err) });
if (config.sentryForBackend) {
Sentry.captureMessage(`Queue: Relationship: ${job?.name ?? '?'}: ${err.message}`, {
Sentry.captureMessage(`Queue: Relationship: ${job?.name ?? '?'}: ${err.name}: ${err.message}`, {
level: 'error',
extra: { job, err },
});
}
})
.on('error', (err: Error) => logger.error(`error ${err.stack}`, { e: renderError(err) }))
.on('error', (err: Error) => logger.error(`error ${err.name}: ${err.message}`, { e: renderError(err) }))
.on('stalled', (jobId) => logger.warn(`stalled id=${jobId}`));
}
//#endregion
Expand Down Expand Up @@ -480,15 +490,15 @@ export class QueueProcessorService implements OnApplicationShutdown {
.on('active', (job) => logger.debug(`active id=${job.id}`))
.on('completed', (job, result) => logger.debug(`completed(${result}) id=${job.id}`))
.on('failed', (job, err) => {
logger.error(`failed(${err.stack}) id=${job ? job.id : '-'}`, { job, e: renderError(err) });
logger.error(`failed(${err.name}: ${err.message}) id=${job?.id ?? '?'}`, { job: renderJob(job), e: renderError(err) });
if (config.sentryForBackend) {
Sentry.captureMessage(`Queue: ObjectStorage: ${job?.name ?? '?'}: ${err.message}`, {
Sentry.captureMessage(`Queue: ObjectStorage: ${job?.name ?? '?'}: ${err.name}: ${err.message}`, {
level: 'error',
extra: { job, err },
});
}
})
.on('error', (err: Error) => logger.error(`error ${err.stack}`, { e: renderError(err) }))
.on('error', (err: Error) => logger.error(`error ${err.name}: ${err.message}`, { e: renderError(err) }))
.on('stalled', (jobId) => logger.warn(`stalled id=${jobId}`));
}
//#endregion
Expand Down

0 comments on commit 2f09d69

Please sign in to comment.