enhance: JSON形式の構造化ログ出力に対応 (#17728)

* enhance: JSON形式の構造化ログ出力に対応

* 起動時ログがJSON化出来ていなかったのを調整

---------

Co-authored-by: syuilo <4439005+syuilo@users.noreply.github.com>

.config/docker_example.yml

@@ -241,6 +241,8 @@ proxyBypassHosts:
 
 # Log settings
 # logging:
+#   # ログの出力形式。「json」で1行JSON、未指定時は「pretty」です。
+#   format: pretty
 #   # Minimum level for all loggers. Defaults to info in production and debug otherwise.
 #   level: info
 #   # The longest matching logger domain takes precedence over the global level.

.config/example.yml

@@ -474,6 +474,8 @@ proxyBypassHosts:
 
 # Log settings
 # logging:
+#   # ログの出力形式。「json」で1行JSON、未指定時は「pretty」です。
+#   format: pretty
 #   # Minimum level for all loggers. Defaults to info in production and debug otherwise.
 #   level: info
 #   # The longest matching logger domain takes precedence over the global level.

CHANGELOG.md

@@ -54,6 +54,7 @@
 - Enhance: URLプレビューの結果を内部でキャッシュするように
 - Enhance: API内部エラーのログに構造化属性と正規化したエラー情報を付与し、認証情報を自動的に秘匿するように（従来形式の表示は維持）
 - Enhance: ログ全体の既定levelとlogger domainごとの出力levelを設定できるように
+- Enhance: バックエンドのログを1行JSON形式で出力できるように
 - Fix: `/stats` API のレスポンス型が正しくない問題を修正
 - Fix: ハッシュタグに関連するデータを更新する際のエラーハンドリングを修正
 - Fix: Sentry 使用環境下にて、Misskey が発行した SQL クエリが span に含まれない問題を修正

packages/backend/src/boot/entry.ts

@@ -10,10 +10,10 @@
 import cluster from 'node:cluster';
 import { EventEmitter } from 'node:events';
 import { writeHeapSnapshot } from 'node:v8';
-import chalk from 'chalk';
 import Xev from 'xev';
 import Logger from '@/logger.js';
 import { envOption } from '../env.js';
+import { installProcessErrorHandlers } from './process-error-handler.js';
 import { isShutdownInProgress } from './shutdown-handler.js';
 import { readyRef } from './ready.js';
 
@@ -28,6 +28,8 @@ const logger = new Logger('core', 'cyan');
 const clusterLogger = logger.createSubLogger('cluster', 'orange');
 const ev = new Xev();
 
+installProcessErrorHandlers({ logger, quiet: envOption.quiet });
+
 //#region Events
 
 // Listen new workers
@@ -47,25 +49,11 @@ cluster.on('exit', worker => {
 		return;
 	}
 
-	// Replace the dead worker,
-	// we're not sentimental
-	clusterLogger.error(chalk.red(`[${worker.id}] died :(`));
+	// 終了したワーカーは従来どおり再生成し、表示色は出力処理へ任せます。
+	clusterLogger.error(`[${worker.id}] died :(`);
 	cluster.fork();
 });
 
-// Display detail of unhandled promise rejection
-if (!envOption.quiet) {
-	process.on('unhandledRejection', console.dir);
-}
-
-// Display detail of uncaught exception
-process.on('uncaughtException', err => {
-	try {
-		logger.error(err);
-		console.trace(err);
-	} catch { }
-});
-
 // Dying away...
 process.on('exit', code => {
 	if (isShutdownInProgress()) return;
@@ -76,12 +64,10 @@ process.on('exit', code => {
 
 if (!envOption.disableClustering) {
 	if (cluster.isPrimary) {
-		logger.info(`Start main process... pid: ${process.pid}`);
 		const { masterMain } = await import('./master.js');
 		await masterMain();
 		ev.mount();
 	} else if (cluster.isWorker) {
-		logger.info(`Start worker process... pid: ${process.pid}`);
 		const { workerMain } = await import('./worker.js');
 		await workerMain();
 	} else {
@@ -89,7 +75,6 @@ if (!envOption.disableClustering) {
 	}
 } else {
 	// 非clusterの場合はMasterのみが起動するため、Workerの処理は行わない(cluster.isWorker === trueの状態でこのブロックに来ることはない)
-	logger.info(`Start main process... pid: ${process.pid}`);
 	const { masterMain } = await import('./master.js');
 	await masterMain();
 	ev.mount();

packages/backend/src/boot/master.ts

@@ -12,6 +12,7 @@ import Logger from '@/logger.js';
 import { loadConfig } from '@/config.js';
 import type { Config } from '@/config.js';
 import { configureLogging, shutdownLogging } from '@/logging/logging-runtime.js';
+import type { LogFormat } from '@/logging/types.js';
 import { showMachineInfo } from '@/misc/show-machine-info.js';
 import { envOption } from '@/env.js';
 import { initTelemetry, shutdownTelemetry } from '@/core/telemetry/telemetry-registry.js';
@@ -23,7 +24,17 @@ const bootLogger = logger.createSubLogger('boot', 'magenta');
 
 const themeColor = chalk.hex('#86b300');
 
-function greet(props: { version: string }) {
+/** 起動時の案内を、選択されたログ形式に合わせて出力します。 */
+function greet(props: { version: string; format: LogFormat }) {
+	if (!envOption.quiet && props.format === 'json') {
+		// JSONモードでは生のコンソール出力を避け、各案内を1件ずつ構造化ログにします。
+		bootLogger.info('Welcome to Misskey!');
+		bootLogger.info(`Misskey v${props.version}`, null, true);
+		bootLogger.info('Misskey is an open-source decentralized microblogging platform.');
+		bootLogger.info('If you like Misskey, please consider donating to support dev. https://misskey-hub.net/docs/donate/');
+		return;
+	}
+
 	if (!envOption.quiet) {
 		//#region Misskey logo
 		const v = `v${props.version}`;
@@ -54,7 +65,9 @@ export async function masterMain() {
 	// initialize app
 	try {
 		config = loadConfigBoot();
-		greet({ version: config.version });
+		logger.info(`Start main process... pid: ${process.pid}`);
+		bootLogger.createSubLogger('config').succ('Loaded');
+		greet({ version: config.version, format: config.logging?.format ?? 'pretty' });
 		showEnvironment();
 		await showMachineInfo(bootLogger);
 		showNodejsVersion();
@@ -136,6 +149,7 @@ function showNodejsVersion(): void {
 	nodejsLogger.info(`Version ${process.version} detected.`);
 }
 
+/** 設定を読み込み、成功時に後続のログ出力形式を適用します。 */
 function loadConfigBoot(): Config {
 	const configLogger = bootLogger.createSubLogger('config');
 	let config;
@@ -154,8 +168,6 @@ function loadConfigBoot(): Config {
 		throw exception;
 	}
 
-	configLogger.succ('Loaded');
-
 	return config;
 }
 

packages/backend/src/boot/process-error-handler.ts

@@ -0,0 +1,59 @@
+/*
+ * SPDX-FileCopyrightText: syuilo and misskey-project
+ * SPDX-License-Identifier: AGPL-3.0-only
+ */
+
+import type { LogWriteInput } from '@/logging/types.js';
+
+/** プロセス例外をロガーへ渡すために必要な最小の処理対象です。 */
+export type ProcessErrorHandlerProcess = {
+	on(event: 'unhandledRejection', listener: (reason: unknown) => void): unknown;
+	on(event: 'uncaughtException', listener: (error: Error) => void): unknown;
+};
+
+/** 例外記録に必要なロガーの最小インターフェースです。 */
+export type ProcessErrorHandlerLogger = {
+	write(input: LogWriteInput): void;
+};
+
+/** プロセス例外ハンドラーの登録に使う依存関係です。 */
+export type ProcessErrorHandlerOptions = {
+	readonly process?: ProcessErrorHandlerProcess;
+	readonly logger: ProcessErrorHandlerLogger;
+	readonly quiet: boolean;
+};
+
+/** ログ記録の失敗が別の例外を起こさないよう、プロセス異常を安全に記録します。 */
+function writeProcessError(
+	logger: ProcessErrorHandlerLogger,
+	eventName: 'process.unhandled_rejection' | 'process.uncaught_exception',
+	message: string,
+	error: unknown,
+): void {
+	try {
+		// 元の値をerrorへ渡し、JSON形式の出力処理で安全な形へ正規化します。
+		logger.write({
+			level: 'error',
+			eventName,
+			message,
+			error,
+		});
+	} catch {
+		// 例外処理中のログ失敗で、さらにプロセスを不安定にしないよう握りつぶします。
+	}
+}
+
+/** 未処理のPromise拒否と未捕捉例外を構造化ログへ接続します。 */
+export function installProcessErrorHandlers(options: ProcessErrorHandlerOptions): void {
+	const processLike: ProcessErrorHandlerProcess = options.process ?? (process as unknown as ProcessErrorHandlerProcess);
+
+	if (!options.quiet) {
+		processLike.on('unhandledRejection', reason => {
+			writeProcessError(options.logger, 'process.unhandled_rejection', 'Unhandled promise rejection', reason);
+		});
+	}
+
+	processLike.on('uncaughtException', error => {
+		writeProcessError(options.logger, 'process.uncaught_exception', 'Uncaught exception', error);
+	});
+}

packages/backend/src/boot/worker.ts

@@ -24,6 +24,7 @@ export async function workerMain() {
 	try {
 		config = loadConfig();
 		configureLogging(config.logging);
+		logger.info(`Start worker process... pid: ${process.pid}`);
 	} catch (e) {
 		bootLogger.error(e instanceof Error ? e : new Error(String(e)), null, true);
 		process.exit(1);

packages/backend/src/config.ts

@@ -10,7 +10,7 @@ import { type FastifyServerOptions } from 'fastify';
 import type * as Sentry from '@sentry/node';
 import type * as SentryVue from '@sentry/vue';
 import type { RedisOptions } from 'ioredis';
-import type { LogLevelSetting } from './logging/types.js';
+import type { LogFormat, LogLevelSetting } from './logging/types.js';
 
 type RedisOptionsSource = Partial<RedisOptions> & {
 	host: string;
@@ -133,6 +133,7 @@ type Source = {
 	pidFile: string;
 
 	logging?: {
+		format?: LogFormat;
 		level?: LogLevelSetting;
 		domains?: Record<string, LogLevelSetting> | null;
 		sql?: {
@@ -197,6 +198,7 @@ export type Config = {
 	deliverJobMaxAttempts: number | undefined;
 	inboxJobMaxAttempts: number | undefined;
 	logging?: {
+		format?: LogFormat;
 		level?: LogLevelSetting;
 		domains?: Record<string, LogLevelSetting> | null;
 		sql?: {

packages/backend/src/logging/JsonConsoleBackend.ts

@@ -0,0 +1,71 @@
+/*
+ * SPDX-FileCopyrightText: syuilo and misskey-project
+ * SPDX-License-Identifier: AGPL-3.0-only
+ */
+
+import type { LogBackend } from './LogBackend.js';
+import type { LogRecord } from './types.js';
+
+/** JSON形式のログを1行で出力する処理が外部から受け取る依存関係です。 */
+export type JsonConsoleBackendDependencies = {
+	readonly output: (line: string) => void;
+};
+
+/** JSON形式で出力する項目を、運用上安定した形として定義します。 */
+type JsonLogRecord = {
+	readonly timestamp: string;
+	readonly level: LogRecord['level'];
+	readonly message: string;
+	readonly loggerName: string;
+	readonly eventName?: string;
+	readonly attributes?: LogRecord['attributes'];
+	readonly error?: LogRecord['error'];
+	readonly processId: number;
+	readonly isPrimary: boolean;
+	readonly workerId: number | null;
+};
+
+const defaultDependencies: JsonConsoleBackendDependencies = {
+	output: line => console.log(line),
+};
+
+/** LogRecordからJSONへ出す項目だけを選び、内部情報を誤って含めないようにします。 */
+function createJsonLogRecord(record: LogRecord): JsonLogRecord {
+	// 色や旧APIの生データは表示専用の情報なので、機械向け形式へは持ち込みません。
+	return {
+		timestamp: record.timestamp,
+		level: record.level,
+		message: record.message,
+		loggerName: record.loggerName,
+		// 任意項目は値がある場合だけ含め、空の項目を増やさないようにします。
+		...(record.eventName != null ? { eventName: record.eventName } : {}),
+		...(record.attributes != null ? { attributes: record.attributes } : {}),
+		...(record.error != null ? { error: record.error } : {}),
+		// 実行主体の情報は常に出し、ログを横断して検索できる形を保ちます。
+		processId: record.processId,
+		isPrimary: record.isPrimary,
+		workerId: record.workerId,
+	};
+}
+
+/**
+ * LogRecordを1行のJSONへ変換し、ログ収集基盤が扱える標準出力へ渡します。
+ * LoggerやLogManagerから出力形式を切り離し、Pretty形式と同じ記録を共有します。
+ */
+export class JsonConsoleBackend implements LogBackend {
+	private readonly dependencies: JsonConsoleBackendDependencies;
+
+	/** 出力処理を受け取り、テストや起動環境ごとに出力先を差し替えます。 */
+	constructor(dependencies: Partial<JsonConsoleBackendDependencies> = {}) {
+		this.dependencies = {
+			...defaultDependencies,
+			...dependencies,
+		};
+	}
+
+	/** 1件のログをJSON文字列へ変換し、改行を含まない1回の出力として渡します。 */
+	public write(record: LogRecord): void {
+		// JSON.stringifyが改行などをエスケープするため、1ログ1行の契約を保てます。
+		this.dependencies.output(JSON.stringify(createJsonLogRecord(record)));
+	}
+}

packages/backend/src/logging/logging-runtime.ts

@@ -5,8 +5,11 @@
 
 import { LogManager } from './LogManager.js';
 import { BootstrapConsoleBackend } from './BootstrapConsoleBackend.js';
+import { JsonConsoleBackend } from './JsonConsoleBackend.js';
 import { PrettyConsoleBackend } from './PrettyConsoleBackend.js';
 import type { LogManagerConfiguration } from './LogManager.js';
+import type { LogBackend } from './LogBackend.js';
+import type { LogFormat } from './types.js';
 
 /**
  * プロセス内のすべてのLoggerが共有するLogManagerです。
@@ -14,13 +17,22 @@ import type { LogManagerConfiguration } from './LogManager.js';
  */
 export const logManager = new LogManager(new BootstrapConsoleBackend());
 
-/** 設定読込後のlogging設定とPretty backendを適用します。 */
-export function configureLogging(configuration?: LogManagerConfiguration): void {
-	logManager.configure(configuration);
-	logManager.setBackend(new PrettyConsoleBackend());
+/** ログ形式を検証し、指定された形式に対応する出力処理を作成します。 */
+function createLoggingBackend(format: unknown): LogBackend {
+	if (format == null || format === 'pretty') return new PrettyConsoleBackend();
+	if (format === 'json') return new JsonConsoleBackend();
+	throw new Error('logging.format must be either pretty or json');
 }
 
-/** プロセス終了前に現在のlogging backendをflushして閉じます。 */
+/** 起動時のログ設定を適用し、選択した出力処理へ切り替えます。 */
+export function configureLogging(configuration?: LogManagerConfiguration & { readonly format?: LogFormat }): void {
+	// 出力処理を先に検証し、設定値が不正な場合は現在の出力処理を壊さないようにします。
+	const backend = createLoggingBackend(configuration?.format);
+	logManager.configure(configuration);
+	logManager.setBackend(backend);
+}
+
+/** プロセス終了前に現在のログ出力処理を保留分まで書き出して閉じます。 */
 export function shutdownLogging(): Promise<void> {
 	return logManager.shutdown();
 }

packages/backend/src/logging/types.ts

@@ -11,6 +11,9 @@ export type LogLevel = 'debug' | 'info' | 'warn' | 'error' | 'fatal';
 /** 設定で指定できるログの閾値です。`off`はログイベントのlevelには使用しません。 */
 export type LogLevelSetting = LogLevel | 'off';
 
+/** コンソールへ出すログ形式です。未指定時は見やすい形式を使用します。 */
+export type LogFormat = 'pretty' | 'json';
+
 /** 正規化後にログ属性として扱えるJSONの値です。 */
 export type LogAttributeValue =
 	| string

packages/backend/test/unit/boot/process-error-handler.ts

@@ -0,0 +1,72 @@
+/*
+ * SPDX-FileCopyrightText: syuilo and misskey-project
+ * SPDX-License-Identifier: AGPL-3.0-only
+ */
+
+import { describe, expect, test, vi } from 'vitest';
+import type { LogWriteInput } from '@/logging/types.js';
+import { installProcessErrorHandlers } from '@/boot/process-error-handler.js';
+
+type ProcessListener = (...args: unknown[]) => void;
+
+/** テスト用に、登録されたプロセスイベントを呼び出せる処理対象を作成します。 */
+function createProcessLike(): {
+	readonly process: { on: (event: string, listener: ProcessListener) => void };
+	readonly listeners: Map<string, ProcessListener>;
+} {
+	const listeners = new Map<string, ProcessListener>();
+	return {
+		process: {
+			on: (event, listener) => listeners.set(event, listener),
+		},
+		listeners,
+	};
+}
+
+describe('installProcessErrorHandlers', () => {
+	test('records unhandled rejections and uncaught exceptions as structured errors', () => {
+		const { process, listeners } = createProcessLike();
+		const write = vi.fn<(input: LogWriteInput) => void>();
+		const rejection = new Error('rejected');
+		const exception = new TypeError('uncaught');
+
+		installProcessErrorHandlers({ process: process as never, logger: { write }, quiet: false });
+		// eslint-disable-next-line @typescript-eslint/no-non-null-assertion
+		listeners.get('unhandledRejection')!(rejection);
+		// eslint-disable-next-line @typescript-eslint/no-non-null-assertion
+		listeners.get('uncaughtException')!(exception);
+
+		expect(write).toHaveBeenNthCalledWith(1, {
+			level: 'error',
+			eventName: 'process.unhandled_rejection',
+			message: 'Unhandled promise rejection',
+			error: rejection,
+		});
+		expect(write).toHaveBeenNthCalledWith(2, {
+			level: 'error',
+			eventName: 'process.uncaught_exception',
+			message: 'Uncaught exception',
+			error: exception,
+		});
+	});
+
+	test('does not register the unhandled rejection handler in quiet mode', () => {
+		const { process, listeners } = createProcessLike();
+
+		installProcessErrorHandlers({ process: process as never, logger: { write: vi.fn() }, quiet: true });
+
+		expect([...listeners.keys()]).toEqual(['uncaughtException']);
+	});
+
+	test('does not rethrow when the logger fails', () => {
+		const { process, listeners } = createProcessLike();
+		const write = vi.fn(() => {
+			throw new Error('logger failed');
+		});
+
+		installProcessErrorHandlers({ process: process as never, logger: { write }, quiet: false });
+
+		expect(() => listeners.get('unhandledRejection')!(new Error('rejected'))).not.toThrow();
+		expect(() => listeners.get('uncaughtException')!(new Error('uncaught'))).not.toThrow();
+	});
+});

packages/backend/test/unit/logging/JsonConsoleBackend.ts

@@ -0,0 +1,76 @@
+/*
+ * SPDX-FileCopyrightText: syuilo and misskey-project
+ * SPDX-License-Identifier: AGPL-3.0-only
+ */
+
+import { describe, expect, test, vi } from 'vitest';
+import type { LogRecord } from '@/logging/types.js';
+import { JsonConsoleBackend } from '@/logging/JsonConsoleBackend.js';
+
+/** JSON形式のテストで使う共通のログを作成します。 */
+function createRecord(overrides: Partial<LogRecord> = {}): LogRecord {
+	return {
+		level: 'error',
+		message: 'delivery failed',
+		context: [{ name: 'queue' }, { name: 'deliver' }],
+		timestamp: '2025-01-02T03:04:05.678Z',
+		loggerName: 'queue.deliver',
+		processId: 1234,
+		isPrimary: false,
+		workerId: 7,
+		...overrides,
+	};
+}
+
+describe('JsonConsoleBackend', () => {
+	test('writes a stable one-line JSON record', () => {
+		const output = vi.fn<(line: string) => void>();
+		const backend = new JsonConsoleBackend({ output });
+
+		backend.write(createRecord({
+			eventName: 'queue.job.failed',
+			attributes: { jobId: '123', attempt: 2 },
+			error: { type: 'TypeError', message: 'broken', stack: 'stack' },
+		}));
+
+		expect(output).toHaveBeenCalledOnce();
+		expect(output.mock.calls[0][0]).toMatchInlineSnapshot(`"{\"timestamp\":\"2025-01-02T03:04:05.678Z\",\"level\":\"error\",\"message\":\"delivery failed\",\"loggerName\":\"queue.deliver\",\"eventName\":\"queue.job.failed\",\"attributes\":{\"jobId\":\"123\",\"attempt\":2},\"error\":{\"type\":\"TypeError\",\"message\":\"broken\",\"stack\":\"stack\"},\"processId\":1234,\"isPrimary\":false,\"workerId\":7}"`);
+	});
+
+	test('omits pretty-only compatibility data and context colors', () => {
+		const output = vi.fn<(line: string) => void>();
+		const backend = new JsonConsoleBackend({ output });
+		const record = createRecord({
+			context: [{ name: 'queue', color: 'red' }],
+			compatibility: {
+				legacyLevel: 'success',
+				important: true,
+				data: { secret: 'must not be written' },
+			},
+		});
+
+		backend.write(record);
+
+		expect(JSON.parse(output.mock.calls[0][0])).toEqual({
+			timestamp: '2025-01-02T03:04:05.678Z',
+			level: 'error',
+			message: 'delivery failed',
+			loggerName: 'queue.deliver',
+			processId: 1234,
+			isPrimary: false,
+			workerId: 7,
+		});
+	});
+
+	test('escapes newlines so each record remains one physical line', () => {
+		const output = vi.fn<(line: string) => void>();
+		const backend = new JsonConsoleBackend({ output });
+		const message = 'first line\nsecond line "quoted"';
+
+		backend.write(createRecord({ message }));
+
+		const line = output.mock.calls[0][0];
+		expect(line).not.toContain('\n');
+		expect(JSON.parse(line).message).toBe(message);
+	});
+});

packages/backend/test/unit/logging/logging-runtime.ts

@@ -0,0 +1,40 @@
+/*
+ * SPDX-FileCopyrightText: syuilo and misskey-project
+ * SPDX-License-Identifier: AGPL-3.0-only
+ */
+
+import { afterEach, describe, expect, test, vi } from 'vitest';
+import { JsonConsoleBackend } from '@/logging/JsonConsoleBackend.js';
+import { logManager, configureLogging } from '@/logging/logging-runtime.js';
+import { PrettyConsoleBackend } from '@/logging/PrettyConsoleBackend.js';
+
+describe('logging-runtime', () => {
+	afterEach(() => {
+		vi.restoreAllMocks();
+	});
+
+	test('uses Pretty backend when the format is omitted', () => {
+		const setBackend = vi.spyOn(logManager, 'setBackend');
+
+		configureLogging();
+
+		expect(setBackend).toHaveBeenCalledWith(expect.any(PrettyConsoleBackend));
+	});
+
+	test('uses JSON backend when the format is json', () => {
+		const setBackend = vi.spyOn(logManager, 'setBackend');
+
+		configureLogging({ format: 'json' });
+
+		expect(setBackend).toHaveBeenCalledWith(expect.any(JsonConsoleBackend));
+	});
+
+	test('rejects an unknown format before changing logging configuration', () => {
+		const setBackend = vi.spyOn(logManager, 'setBackend');
+		const configure = vi.spyOn(logManager, 'configure');
+
+		expect(() => configureLogging({ format: 'xml' as never })).toThrow('logging.format');
+		expect(setBackend).not.toHaveBeenCalled();
+		expect(configure).not.toHaveBeenCalled();
+	});
+});