enhance: OTel設定時、JSONログにtrace_id, span_id, trace_flagがつくように (#17748)

* enhance: OTel設定時、JSONログにtrace_id, span_id, trace_flagがつくように * fix
2026-07-27 02:54:36 +02:00 · 2026-07-20 19:00:54 +09:00
parent 36c442a7b4
commit bbd57c751c
17 changed files with 449 additions and 89 deletions
--- a/packages/backend/src/queue/QueueProcessorService.ts
+++ b/packages/backend/src/queue/QueueProcessorService.ts
@@ -11,6 +11,7 @@ import type Logger from '@/logger.js';
 import { bindThis } from '@/decorators.js';
 import { TelemetryService } from '@/core/telemetry/TelemetryService.js';
 import { CheckModeratorsActivityProcessorService } from '@/queue/processors/CheckModeratorsActivityProcessorService.js';
+import { runQueueJobWithTraceContext } from './queue-job-runner.js';
 import { UserWebhookDeliverProcessorService } from './processors/UserWebhookDeliverProcessorService.js';
 import { SystemWebhookDeliverProcessorService } from './processors/SystemWebhookDeliverProcessorService.js';
 import { EndedPollNotificationProcessorService } from './processors/EndedPollNotificationProcessorService.js';
@@ -176,26 +177,30 @@ export class QueueProcessorService implements OnApplicationShutdown {
 					default: throw new Error(`unrecognized job type ${job.name} for system`);
 				}
 			};
+			const logger = this.logger.createSubLogger('system');

 			this.systemQueueWorker = new Bull.Worker(QUEUE.SYSTEM, (job) => {
-				return this.telemetryService.startSpanWithTraceContext('Queue: System: ' + job.name, job.data, () => processer(job));
+				return runQueueJobWithTraceContext(
+					this.telemetryService,
+					'Queue: System: ' + job.name,
+					job.data,
+					() => processer(job) as Promise<void>,
+					err => {
+						logger.error(`failed(${err.name}: ${err.message}) id=${job.id}`, { job: renderJob(job), e: renderError(err) });
+						this.telemetryService.captureMessage(`Queue: System: ${job.name}: ${err.name}: ${err.message}`, {
+							level: 'error',
+							extra: { job, err },
+						});
+					},
+				);
 			}, {
 				...baseWorkerOptions(this.config, QUEUE.SYSTEM),
 				autorun: false,
 			});

-			const logger = this.logger.createSubLogger('system');
-
 			this.systemQueueWorker
 				.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.name}: ${err.message}) id=${job?.id ?? '?'}`, { job: renderJob(job), e: renderError(err) });
-					this.telemetryService.captureMessage(`Queue: System: ${job?.name ?? '?'}: ${err.name}: ${err.message}`, {
-						level: 'error',
-						extra: { job, err },
-					});
-				})
 				.on('error', (err: Error) => logger.error(`error ${err.name}: ${err.message}`, { e: renderError(err) }))
 				.on('stalled', (jobId) => logger.warn(`stalled id=${jobId}`));
 		}
@@ -227,26 +232,30 @@ export class QueueProcessorService implements OnApplicationShutdown {
 					default: throw new Error(`unrecognized job type ${job.name} for db`);
 				}
 			};
+			const logger = this.logger.createSubLogger('db');

 			this.dbQueueWorker = new Bull.Worker(QUEUE.DB, (job) => {
-				return this.telemetryService.startSpanWithTraceContext('Queue: DB: ' + job.name, job.data, () => processer(job));
+				return runQueueJobWithTraceContext(
+					this.telemetryService,
+					'Queue: DB: ' + job.name,
+					job.data,
+					() => processer(job),
+					err => {
+						logger.error(`failed(${err.name}: ${err.message}) id=${job.id}`, { job: renderJob(job), e: renderError(err) });
+						this.telemetryService.captureMessage(`Queue: DB: ${job.name}: ${err.name}: ${err.message}`, {
+							level: 'error',
+							extra: { job, err },
+						});
+					},
+				);
 			}, {
 				...baseWorkerOptions(this.config, QUEUE.DB),
 				autorun: false,
 			});

-			const logger = this.logger.createSubLogger('db');
-
 			this.dbQueueWorker
 				.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.name}: ${err.message}) id=${job?.id ?? '?'}`, { job: renderJob(job), e: renderError(err) });
-					this.telemetryService.captureMessage(`Queue: DB: ${job?.name ?? '?'}: ${err.name}: ${err.message}`, {
-						level: 'error',
-						extra: { job, err },
-					});
-				})
 				.on('error', (err: Error) => logger.error(`error ${err.name}: ${err.message}`, { e: renderError(err) }))
 				.on('stalled', (jobId) => logger.warn(`stalled id=${jobId}`));
 		}
@@ -254,8 +263,22 @@ export class QueueProcessorService implements OnApplicationShutdown {

 		//#region deliver
 		{
+			const logger = this.logger.createSubLogger('deliver');
+
 			this.deliverQueueWorker = new Bull.Worker(QUEUE.DELIVER, (job) => {
-				return this.telemetryService.startSpanWithTraceContext('Queue: Deliver', job.data, () => this.deliverProcessorService.process(job));
+				return runQueueJobWithTraceContext(
+					this.telemetryService,
+					'Queue: Deliver',
+					job.data,
+					() => this.deliverProcessorService.process(job),
+					err => {
+						logger.error(`failed(${err.name}: ${err.message}) ${getJobInfo(job)} to=${job.data.to}`, { e: renderError(err) });
+						this.telemetryService.captureMessage(`Queue: Deliver: ${err.name}: ${err.message}`, {
+							level: 'error',
+							extra: { job, err },
+						});
+					},
+				);
 			}, {
 				...baseWorkerOptions(this.config, QUEUE.DELIVER),
 				autorun: false,
@@ -269,18 +292,9 @@ export class QueueProcessorService implements OnApplicationShutdown {
 				},
 			});

-			const logger = this.logger.createSubLogger('deliver');
-
 			this.deliverQueueWorker
 				.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.name}: ${err.message}) ${getJobInfo(job)} to=${job ? job.data.to : '-'}`);
-					this.telemetryService.captureMessage(`Queue: Deliver: ${err.name}: ${err.message}`, {
-						level: 'error',
-						extra: { job, err },
-					});
-				})
 				.on('error', (err: Error) => logger.error(`error ${err.name}: ${err.message}`, { e: renderError(err) }))
 				.on('stalled', (jobId) => logger.warn(`stalled id=${jobId}`));
 		}
@@ -288,8 +302,23 @@ export class QueueProcessorService implements OnApplicationShutdown {

 		//#region inbox
 		{
+			const logger = this.logger.createSubLogger('inbox');
+
 			this.inboxQueueWorker = new Bull.Worker(QUEUE.INBOX, (job) => {
-				return this.telemetryService.startSpanWithTraceContext('Queue: Inbox', job.data, () => this.inboxProcessorService.process(job));
+				return runQueueJobWithTraceContext(
+					this.telemetryService,
+					'Queue: Inbox',
+					job.data,
+					() => this.inboxProcessorService.process(job),
+					err => {
+						const activityId = job.data.activity ? job.data.activity.id : 'none';
+						logger.error(`failed(${err.name}: ${err.message}) ${getJobInfo(job)} activity=${activityId}`, { job: renderJob(job), e: renderError(err) });
+						this.telemetryService.captureMessage(`Queue: Inbox: ${err.name}: ${err.message}`, {
+							level: 'error',
+							extra: { job, err },
+						});
+					},
+				);
 			}, {
 				...baseWorkerOptions(this.config, QUEUE.INBOX),
 				autorun: false,
@@ -303,18 +332,9 @@ export class QueueProcessorService implements OnApplicationShutdown {
 				},
 			});

-			const logger = this.logger.createSubLogger('inbox');
-
 			this.inboxQueueWorker
 				.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.name}: ${err.message}) ${getJobInfo(job)} activity=${job ? (job.data.activity ? job.data.activity.id : 'none') : '-'}`, { job: renderJob(job), e: renderError(err) });
-					this.telemetryService.captureMessage(`Queue: Inbox: ${err.name}: ${err.message}`, {
-						level: 'error',
-						extra: { job, err },
-					});
-				})
 				.on('error', (err: Error) => logger.error(`error ${err.name}: ${err.message}`, { e: renderError(err) }))
 				.on('stalled', (jobId) => logger.warn(`stalled id=${jobId}`));
 		}
@@ -322,8 +342,22 @@ export class QueueProcessorService implements OnApplicationShutdown {

 		//#region user-webhook deliver
 		{
+			const logger = this.logger.createSubLogger('user-webhook');
+
 			this.userWebhookDeliverQueueWorker = new Bull.Worker(QUEUE.USER_WEBHOOK_DELIVER, (job) => {
-				return this.telemetryService.startSpanWithTraceContext('Queue: UserWebhookDeliver', job.data, () => this.userWebhookDeliverProcessorService.process(job));
+				return runQueueJobWithTraceContext(
+					this.telemetryService,
+					'Queue: UserWebhookDeliver',
+					job.data,
+					() => this.userWebhookDeliverProcessorService.process(job),
+					err => {
+						logger.error(`failed(${err.name}: ${err.message}) ${getJobInfo(job)} to=${job.data.to}`, { e: renderError(err) });
+						this.telemetryService.captureMessage(`Queue: UserWebhookDeliver: ${err.name}: ${err.message}`, {
+							level: 'error',
+							extra: { job, err },
+						});
+					},
+				);
 			}, {
 				...baseWorkerOptions(this.config, QUEUE.USER_WEBHOOK_DELIVER),
 				autorun: false,
@@ -337,18 +371,9 @@ export class QueueProcessorService implements OnApplicationShutdown {
 				},
 			});

-			const logger = this.logger.createSubLogger('user-webhook');
-
 			this.userWebhookDeliverQueueWorker
 				.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.name}: ${err.message}) ${getJobInfo(job)} to=${job ? job.data.to : '-'}`);
-					this.telemetryService.captureMessage(`Queue: UserWebhookDeliver: ${err.name}: ${err.message}`, {
-						level: 'error',
-						extra: { job, err },
-					});
-				})
 				.on('error', (err: Error) => logger.error(`error ${err.name}: ${err.message}`, { e: renderError(err) }))
 				.on('stalled', (jobId) => logger.warn(`stalled id=${jobId}`));
 		}
@@ -356,8 +381,22 @@ export class QueueProcessorService implements OnApplicationShutdown {

 		//#region system-webhook deliver
 		{
+			const logger = this.logger.createSubLogger('system-webhook');
+
 			this.systemWebhookDeliverQueueWorker = new Bull.Worker(QUEUE.SYSTEM_WEBHOOK_DELIVER, (job) => {
-				return this.telemetryService.startSpanWithTraceContext('Queue: SystemWebhookDeliver', job.data, () => this.systemWebhookDeliverProcessorService.process(job));
+				return runQueueJobWithTraceContext(
+					this.telemetryService,
+					'Queue: SystemWebhookDeliver',
+					job.data,
+					() => this.systemWebhookDeliverProcessorService.process(job),
+					err => {
+						logger.error(`failed(${err.name}: ${err.message}) ${getJobInfo(job)} to=${job.data.to}`, { e: renderError(err) });
+						this.telemetryService.captureMessage(`Queue: SystemWebhookDeliver: ${err.name}: ${err.message}`, {
+							level: 'error',
+							extra: { job, err },
+						});
+					},
+				);
 			}, {
 				...baseWorkerOptions(this.config, QUEUE.SYSTEM_WEBHOOK_DELIVER),
 				autorun: false,
@@ -371,18 +410,9 @@ export class QueueProcessorService implements OnApplicationShutdown {
 				},
 			});

-			const logger = this.logger.createSubLogger('system-webhook');
-
 			this.systemWebhookDeliverQueueWorker
 				.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.name}: ${err.message}) ${getJobInfo(job)} to=${job ? job.data.to : '-'}`);
-					this.telemetryService.captureMessage(`Queue: SystemWebhookDeliver: ${err.name}: ${err.message}`, {
-						level: 'error',
-						extra: { job, err },
-					});
-				})
 				.on('error', (err: Error) => logger.error(`error ${err.name}: ${err.message}`, { e: renderError(err) }))
 				.on('stalled', (jobId) => logger.warn(`stalled id=${jobId}`));
 		}
@@ -399,9 +429,22 @@ export class QueueProcessorService implements OnApplicationShutdown {
 					default: throw new Error(`unrecognized job type ${job.name} for relationship`);
 				}
 			};
+			const logger = this.logger.createSubLogger('relationship');

 			this.relationshipQueueWorker = new Bull.Worker(QUEUE.RELATIONSHIP, (job) => {
-				return this.telemetryService.startSpanWithTraceContext('Queue: Relationship: ' + job.name, job.data, () => processer(job));
+				return runQueueJobWithTraceContext(
+					this.telemetryService,
+					'Queue: Relationship: ' + job.name,
+					job.data,
+					() => processer(job),
+					err => {
+						logger.error(`failed(${err.name}: ${err.message}) id=${job.id}`, { job: renderJob(job), e: renderError(err) });
+						this.telemetryService.captureMessage(`Queue: Relationship: ${job.name}: ${err.name}: ${err.message}`, {
+							level: 'error',
+							extra: { job, err },
+						});
+					},
+				);
 			}, {
 				...baseWorkerOptions(this.config, QUEUE.RELATIONSHIP),
 				autorun: false,
@@ -412,18 +455,9 @@ export class QueueProcessorService implements OnApplicationShutdown {
 				},
 			});

-			const logger = this.logger.createSubLogger('relationship');
-
 			this.relationshipQueueWorker
 				.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.name}: ${err.message}) id=${job?.id ?? '?'}`, { job: renderJob(job), e: renderError(err) });
-					this.telemetryService.captureMessage(`Queue: Relationship: ${job?.name ?? '?'}: ${err.name}: ${err.message}`, {
-						level: 'error',
-						extra: { job, err },
-					});
-				})
 				.on('error', (err: Error) => logger.error(`error ${err.name}: ${err.message}`, { e: renderError(err) }))
 				.on('stalled', (jobId) => logger.warn(`stalled id=${jobId}`));
 		}
@@ -438,27 +472,31 @@ export class QueueProcessorService implements OnApplicationShutdown {
 					default: throw new Error(`unrecognized job type ${job.name} for objectStorage`);
 				}
 			};
+			const logger = this.logger.createSubLogger('objectStorage');

 			this.objectStorageQueueWorker = new Bull.Worker(QUEUE.OBJECT_STORAGE, (job) => {
-				return this.telemetryService.startSpanWithTraceContext('Queue: ObjectStorage: ' + job.name, job.data, () => processer(job));
+				return runQueueJobWithTraceContext(
+					this.telemetryService,
+					'Queue: ObjectStorage: ' + job.name,
+					job.data,
+					() => processer(job) as Promise<void>,
+					err => {
+						logger.error(`failed(${err.name}: ${err.message}) id=${job.id}`, { job: renderJob(job), e: renderError(err) });
+						this.telemetryService.captureMessage(`Queue: ObjectStorage: ${job.name}: ${err.name}: ${err.message}`, {
+							level: 'error',
+							extra: { job, err },
+						});
+					},
+				);
 			}, {
 				...baseWorkerOptions(this.config, QUEUE.OBJECT_STORAGE),
 				autorun: false,
 				concurrency: 16,
 			});

-			const logger = this.logger.createSubLogger('objectStorage');
-
 			this.objectStorageQueueWorker
 				.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.name}: ${err.message}) id=${job?.id ?? '?'}`, { job: renderJob(job), e: renderError(err) });
-					this.telemetryService.captureMessage(`Queue: ObjectStorage: ${job?.name ?? '?'}: ${err.name}: ${err.message}`, {
-						level: 'error',
-						extra: { job, err },
-					});
-				})
 				.on('error', (err: Error) => logger.error(`error ${err.name}: ${err.message}`, { e: renderError(err) }))
 				.on('stalled', (jobId) => logger.warn(`stalled id=${jobId}`));
 		}
@@ -466,8 +504,22 @@ export class QueueProcessorService implements OnApplicationShutdown {

 		//#region ended poll notification
 		{
+			const logger = this.logger.createSubLogger('ended-poll-notification');
+
 			this.endedPollNotificationQueueWorker = new Bull.Worker(QUEUE.ENDED_POLL_NOTIFICATION, (job) => {
-				return this.telemetryService.startSpanWithTraceContext('Queue: EndedPollNotification', job.data, () => this.endedPollNotificationProcessorService.process(job));
+				return runQueueJobWithTraceContext(
+					this.telemetryService,
+					'Queue: EndedPollNotification',
+					job.data,
+					() => this.endedPollNotificationProcessorService.process(job),
+					err => {
+						logger.error(`failed(${err.name}: ${err.message}) id=${job.id}`, { job: renderJob(job), e: renderError(err) });
+						this.telemetryService.captureMessage(`Queue: EndedPollNotification: ${err.name}: ${err.message}`, {
+							level: 'error',
+							extra: { job, err },
+						});
+					},
+				);
 			}, {
 				...baseWorkerOptions(this.config, QUEUE.ENDED_POLL_NOTIFICATION),
 				autorun: false,
@@ -477,8 +529,22 @@ export class QueueProcessorService implements OnApplicationShutdown {

 		//#region post scheduled note
 		{
-			this.postScheduledNoteQueueWorker = new Bull.Worker(QUEUE.POST_SCHEDULED_NOTE, async (job) => {
-				return this.telemetryService.startSpanWithTraceContext('Queue: PostScheduledNote', job.data, () => this.postScheduledNoteProcessorService.process(job));
+			const logger = this.logger.createSubLogger('post-scheduled-note');
+
+			this.postScheduledNoteQueueWorker = new Bull.Worker(QUEUE.POST_SCHEDULED_NOTE, (job) => {
+				return runQueueJobWithTraceContext(
+					this.telemetryService,
+					'Queue: PostScheduledNote',
+					job.data,
+					() => this.postScheduledNoteProcessorService.process(job),
+					err => {
+						logger.error(`failed(${err.name}: ${err.message}) id=${job.id}`, { job: renderJob(job), e: renderError(err) });
+						this.telemetryService.captureMessage(`Queue: PostScheduledNote: ${err.name}: ${err.message}`, {
+							level: 'error',
+							extra: { job, err },
+						});
+					},
+				);
 			}, {
 				...baseWorkerOptions(this.config, QUEUE.POST_SCHEDULED_NOTE),
 				autorun: false,
--- a/packages/backend/src/queue/queue-job-runner.ts
+++ b/packages/backend/src/queue/queue-job-runner.ts
@@ -0,0 +1,32 @@
+/*
+ * SPDX-FileCopyrightText: syuilo and misskey-project
+ * SPDX-License-Identifier: AGPL-3.0-only
+ */
+
+import type { TelemetryService } from '@/core/telemetry/TelemetryService.js';
+
+type QueueTelemetryService = Pick<TelemetryService, 'startSpanWithTraceContext'>;
+
+/** QueueのprocessorをTrace Context付きで実行し、失敗処理をSpan内で行います。 */
+export function runQueueJobWithTraceContext<T>(
+	telemetryService: QueueTelemetryService,
+	spanName: string,
+	jobData: object,
+	processJob: () => T | Promise<T>,
+	onError: (error: Error) => void,
+): Promise<T> {
+	return telemetryService.startSpanWithTraceContext(spanName, jobData, async (): Promise<T> => {
+		try {
+			return await processJob();
+		} catch (error) {
+			// 失敗イベントを待たず、processor Spanがactiveな間にログと通知を行います。
+			const normalizedError = error instanceof Error ? error : new Error(String(error));
+			try {
+				onError(normalizedError);
+			} catch {
+				// 失敗ログの処理が例外を投げても、Queueへは元のエラーを返します。
+			}
+			throw error;
+		}
+	});
+}