From 828a24f6dfc7965d691d9195431fde66a33a6517 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=E3=81=8A=E3=81=95=E3=82=80=E3=81=AE=E3=81=B2=E3=81=A8?= <46447427+samunohito@users.noreply.github.com> Date: Thu, 16 Jul 2026 17:39:28 +0900 Subject: [PATCH] =?UTF-8?q?enhance:=20=E3=83=97=E3=83=AD=E3=82=BB=E3=82=B9?= =?UTF-8?q?=E8=B5=B7=E5=8B=95=E7=9B=B4=E5=BE=8C=E3=81=AE=E3=83=AD=E3=82=B0?= =?UTF-8?q?=E3=81=8B=E3=82=89=E6=96=B0logger=E9=81=A9=E7=94=A8=EF=BC=8Blog?= =?UTF-8?q?ger=E8=A8=AD=E5=AE=9A=E6=A9=9F=E6=A7=8B=E3=81=AE=E8=BF=BD?= =?UTF-8?q?=E5=8A=A0=20(#17725)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * enhance: プロセスのライフサイクルに合わせてlogger初期化・終了＋logger設定機構の追加 * fix --------- Co-authored-by: syuilo <4439005+syuilo@users.noreply.github.com> --- .config/docker_example.yml | 8 ++ .config/example.yml | 8 ++ CHANGELOG.md | 1 + packages/backend/src/boot/entry.ts | 5 +- packages/backend/src/boot/master.ts | 11 +- packages/backend/src/boot/shutdown-handler.ts | 100 +++++++++++++++ packages/backend/src/boot/worker.ts | 21 +++- packages/backend/src/config.ts | 5 + .../src/core/telemetry/telemetry-shutdown.ts | 67 +--------- .../src/logging/BootstrapConsoleBackend.ts | 49 ++++++++ packages/backend/src/logging/LogManager.ts | 116 +++++++++++++++++- .../backend/src/logging/logging-runtime.ts | 15 ++- packages/backend/src/logging/types.ts | 3 + .../test/unit/boot/shutdown-handler.ts | 113 +++++++++++++++++ .../unit/logging/BootstrapConsoleBackend.ts | 54 ++++++++ .../backend/test/unit/logging/LogManager.ts | 90 +++++++++++++- .../backend/test/unit/telemetry-shutdown.ts | 59 --------- 17 files changed, 590 insertions(+), 135 deletions(-) create mode 100644 packages/backend/src/boot/shutdown-handler.ts create mode 100644 packages/backend/src/logging/BootstrapConsoleBackend.ts create mode 100644 packages/backend/test/unit/boot/shutdown-handler.ts create mode 100644 packages/backend/test/unit/logging/BootstrapConsoleBackend.ts delete mode 100644 packages/backend/test/unit/telemetry-shutdown.ts diff --git a/.config/docker_example.yml b/.config/docker_example.yml index 2f4ea329d2..bc2549d5cf 100644 --- a/.config/docker_example.yml +++ b/.config/docker_example.yml @@ -241,6 +241,14 @@ proxyBypassHosts: # Log settings # logging: +# # 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. +# domains: +# core.boot: info +# queue: error +# queue.deliver: debug +# db.sql: off # sql: # # Outputs query parameters during SQL execution to the log. # # default: false diff --git a/.config/example.yml b/.config/example.yml index 14808e2795..961417cb30 100644 --- a/.config/example.yml +++ b/.config/example.yml @@ -474,6 +474,14 @@ proxyBypassHosts: # Log settings # logging: +# # 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. +# domains: +# core.boot: info +# queue: error +# queue.deliver: debug +# db.sql: off # sql: # # Outputs query parameters during SQL execution to the log. # # default: false diff --git a/CHANGELOG.md b/CHANGELOG.md index d2cb4e8e40..1fc991d0a1 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -53,6 +53,7 @@ - Enhance: Docker Image の Node.js を 26.4.0 に、Debian を trixie (v13) に更新 - Enhance: URLプレビューの結果を内部でキャッシュするように - Enhance: API内部エラーのログに構造化属性と正規化したエラー情報を付与し、認証情報を自動的に秘匿するように（従来形式の表示は維持） +- Enhance: ログ全体の既定levelとlogger domainごとの出力levelを設定できるように - Fix: `/stats` API のレスポンス型が正しくない問題を修正 - Fix: ハッシュタグに関連するデータを更新する際のエラーハンドリングを修正 - Fix: Sentry 使用環境下にて、Misskey が発行した SQL クエリが span に含まれない問題を修正 diff --git a/packages/backend/src/boot/entry.ts b/packages/backend/src/boot/entry.ts index a35bd41272..3c2d56c73c 100644 --- a/packages/backend/src/boot/entry.ts +++ b/packages/backend/src/boot/entry.ts @@ -13,8 +13,8 @@ import { writeHeapSnapshot } from 'node:v8'; import chalk from 'chalk'; import Xev from 'xev'; import Logger from '@/logger.js'; -import { isTelemetryShutdownInProgress } from '@/core/telemetry/telemetry-shutdown.js'; import { envOption } from '../env.js'; +import { isShutdownInProgress } from './shutdown-handler.js'; import { readyRef } from './ready.js'; import 'reflect-metadata'; @@ -42,7 +42,7 @@ cluster.on('online', worker => { // Listen for dying workers cluster.on('exit', worker => { - if (isTelemetryShutdownInProgress()) { + if (isShutdownInProgress()) { clusterLogger.info(`Process exited during shutdown: [${worker.id}]`); return; } @@ -68,6 +68,7 @@ process.on('uncaughtException', err => { // Dying away... process.on('exit', code => { + if (isShutdownInProgress()) return; logger.info(`The process is going to exit with code ${code}`); }); diff --git a/packages/backend/src/boot/master.ts b/packages/backend/src/boot/master.ts index 59e1351ea1..4f78e602d0 100644 --- a/packages/backend/src/boot/master.ts +++ b/packages/backend/src/boot/master.ts @@ -11,11 +11,12 @@ import chalkTemplate from 'chalk-template'; 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 { showMachineInfo } from '@/misc/show-machine-info.js'; import { envOption } from '@/env.js'; -import { initTelemetry } from '@/core/telemetry/telemetry-registry.js'; -import { installTelemetrySignalHandlers } from '@/core/telemetry/telemetry-shutdown.js'; +import { initTelemetry, shutdownTelemetry } from '@/core/telemetry/telemetry-registry.js'; import { initExtraThreadPool, jobQueue, server } from './common.js'; +import { installShutdownSignalHandlers } from './shutdown-handler.js'; const logger = new Logger('core', 'cyan'); const bootLogger = logger.createSubLogger('boot', 'magenta'); @@ -74,7 +75,10 @@ export async function masterMain() { bootLogger.error(e instanceof Error ? e : new Error(String(e)), null, true); process.exit(1); } - installTelemetrySignalHandlers(); + installShutdownSignalHandlers({ + shutdownTasks: [shutdownTelemetry, shutdownLogging], + onRegistered: message => bootLogger.info(message), + }); bootLogger.info( `mode: [disableClustering: ${envOption.disableClustering}, onlyServer: ${envOption.onlyServer}, onlyQueue: ${envOption.onlyQueue}]`, @@ -138,6 +142,7 @@ function loadConfigBoot(): Config { try { config = loadConfig(); + configureLogging(config.logging); } catch (exception) { if (typeof exception === 'string') { configLogger.error(exception); diff --git a/packages/backend/src/boot/shutdown-handler.ts b/packages/backend/src/boot/shutdown-handler.ts new file mode 100644 index 0000000000..a0d85d1df6 --- /dev/null +++ b/packages/backend/src/boot/shutdown-handler.ts @@ -0,0 +1,100 @@ +/* + * SPDX-FileCopyrightText: syuilo and misskey-project + * SPDX-License-Identifier: AGPL-3.0-only + */ + +type ShutdownSignalProcess = { + once(event: 'SIGTERM' | 'SIGINT', listener: () => Promise): unknown; +}; + +const SHUTDOWN_TIMEOUT_MS = 10_000; + +export type ShutdownTask = () => Promise; + +export type ShutdownHandlerOptions = { + /** The process-like object that receives the signal handlers. */ + process?: ShutdownSignalProcess; + /** Shutdown tasks, executed in array order. */ + shutdownTasks: readonly ShutdownTask[]; + /** Process termination function. */ + exit?: (code: number) => void; + /** Optional boot logger hook used after signal handlers are registered. */ + onRegistered?: (message: string) => void; +}; + +let shuttingDown = false; + +/** + * Register the process-level shutdown signals. + * + * Boot owns signal coordination and receives shutdown tasks through callbacks + * so individual domains do not depend on each other. + * + * 注意: このプロジェクトでは app.enableShutdownHooks() が一切呼ばれていないため、 + * NestJSのOnApplicationShutdown経由のgraceful shutdown(GlobalModule.dispose()によるDB/Redis切断、 + * QueueProcessorService.stop()によるqueue drain、ServerService.dispose()によるfastify/WebSocket close)は + * SIGTERM/SIGINTを起点には発火しない。このhandlerはそれらを経由せず、登録された終了処理を実行して即exitする。 + * 将来enableShutdownHooks()を配線する場合は、この即exitとNestJS側のshutdown sequenceが競合しないよう順序を設計すること。 + */ +export function installShutdownSignalHandlers(options: ShutdownHandlerOptions): void { + // テストではprocess/exitを差し替え、本番では実processにSIGTERM/SIGINT handlerを登録する。 + const processLike = options.process ?? process; + const exit = options.exit ?? ((code: number) => process.exit(code)); + + const handleSignal = async () => { + // 同時に複数signalが来てもflushを二重実行せず、cluster refork抑止用の状態もここで立てる。 + if (shuttingDown) return; + shuttingDown = true; + + let timedOut = false; + let timeout: NodeJS.Timeout | undefined; + try { + // 処理時間上限つきのシャットダウンプロセス + await Promise.race([ + (async () => { + for (const shutdownTask of options.shutdownTasks) { + if (timedOut) return; + try { + await shutdownTask(); + } catch (error) { + // 1つの終了処理の失敗で後続タスクを妨げないよう、stderrへフォールバックする。 + try { + console.error('Shutdown task failed:', error); + } catch { + // stderrの出力自体が失敗しても、残りの終了処理とexitは継続する。 + } + } + } + })(), + new Promise(resolve => { + timeout = setTimeout(() => { + timedOut = true; + try { + console.error(`Shutdown tasks timed out after ${SHUTDOWN_TIMEOUT_MS}ms.`); + } catch { + // stderrの出力自体が失敗してもexitは継続する。 + } + resolve(); + }, SHUTDOWN_TIMEOUT_MS); + }), + ]); + } finally { + if (timeout != null) clearTimeout(timeout); + } + + // 既存挙動と同じく、終了処理後はプロセスを終了する。 + exit(0); + }; + + // onceにして、同じsignalでhandlerが再入しないようにする。 + processLike.once('SIGTERM', handleSignal); + processLike.once('SIGINT', handleSignal); + + // app.enableShutdownHooks()未配線の現状、SIGTERM/SIGINT時には登録済み終了処理のみを行う。 + options.onRegistered?.('Registered SIGTERM/SIGINT shutdown handler (this process does not perform NestJS graceful shutdown on these signals).'); +} + +export function isShutdownInProgress(): boolean { + // masterのcluster exit handlerが、意図したshutdown中のworker終了を再forkしないために参照する。 + return shuttingDown; +} diff --git a/packages/backend/src/boot/worker.ts b/packages/backend/src/boot/worker.ts index 32bcbe8fb4..ad15296440 100644 --- a/packages/backend/src/boot/worker.ts +++ b/packages/backend/src/boot/worker.ts @@ -7,9 +7,11 @@ import cluster from 'node:cluster'; import Logger from '@/logger.js'; import { envOption } from '@/env.js'; import { loadConfig } from '@/config.js'; -import { initTelemetry } from '@/core/telemetry/telemetry-registry.js'; -import { installTelemetrySignalHandlers } from '@/core/telemetry/telemetry-shutdown.js'; +import type { Config } from '@/config.js'; +import { configureLogging, shutdownLogging } from '@/logging/logging-runtime.js'; +import { initTelemetry, shutdownTelemetry } from '@/core/telemetry/telemetry-registry.js'; import { initExtraThreadPool, jobQueue, server } from './common.js'; +import { installShutdownSignalHandlers } from './shutdown-handler.js'; const logger = new Logger('core', 'cyan'); const bootLogger = logger.createSubLogger('boot', 'magenta'); @@ -18,7 +20,15 @@ const bootLogger = logger.createSubLogger('boot', 'magenta'); * Init worker process */ export async function workerMain() { - const config = loadConfig(); + let config: Config; + try { + config = loadConfig(); + configureLogging(config.logging); + } catch (e) { + bootLogger.error(e instanceof Error ? e : new Error(String(e)), null, true); + process.exit(1); + return; + } initExtraThreadPool(config); @@ -28,7 +38,10 @@ export async function workerMain() { bootLogger.error(e instanceof Error ? e : new Error(String(e)), null, true); process.exit(1); } - installTelemetrySignalHandlers(); + installShutdownSignalHandlers({ + shutdownTasks: [shutdownTelemetry, shutdownLogging], + onRegistered: message => bootLogger.info(message), + }); if (envOption.onlyServer) { await server(); diff --git a/packages/backend/src/config.ts b/packages/backend/src/config.ts index de67daa31b..ab46416b35 100644 --- a/packages/backend/src/config.ts +++ b/packages/backend/src/config.ts @@ -10,6 +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'; type RedisOptionsSource = Partial & { host: string; @@ -132,6 +133,8 @@ type Source = { pidFile: string; logging?: { + level?: LogLevelSetting; + domains?: Record | null; sql?: { disableQueryTruncation?: boolean, enableQueryParamLogging?: boolean, @@ -194,6 +197,8 @@ export type Config = { deliverJobMaxAttempts: number | undefined; inboxJobMaxAttempts: number | undefined; logging?: { + level?: LogLevelSetting; + domains?: Record | null; sql?: { disableQueryTruncation?: boolean, enableQueryParamLogging?: boolean, diff --git a/packages/backend/src/core/telemetry/telemetry-shutdown.ts b/packages/backend/src/core/telemetry/telemetry-shutdown.ts index 07d950f70d..1ee1b42649 100644 --- a/packages/backend/src/core/telemetry/telemetry-shutdown.ts +++ b/packages/backend/src/core/telemetry/telemetry-shutdown.ts @@ -3,64 +3,9 @@ * SPDX-License-Identifier: AGPL-3.0-only */ -import Logger from '@/logger.js'; -import { shutdownTelemetry as defaultShutdownTelemetry } from './telemetry-registry.js'; - -const logger = new Logger('telemetry', 'green'); - -type SignalProcess = { - once(event: 'SIGTERM' | 'SIGINT', listener: () => Promise): unknown; -}; - -type InstallTelemetrySignalHandlersOptions = { - process?: SignalProcess; - shutdownTelemetry?: () => Promise; - exit?: (code: number) => void; -}; - -let shuttingDown = false; - -export function installTelemetrySignalHandlers(options: InstallTelemetrySignalHandlersOptions = {}): void { - // テストではprocess/exitを差し替え、本番では実processにSIGTERM/SIGINT handlerを登録する。 - // - // 注意: このプロジェクトでは app.enableShutdownHooks() が一切呼ばれていないため、 - // NestJSのOnApplicationShutdown経由のgraceful shutdown(GlobalModule.dispose()によるDB/Redis切断、 - // QueueProcessorService.stop()によるqueue drain、ServerService.dispose()によるfastify/WebSocket close)は - // 本PR以前から実質的に無効(SIGTERM/SIGINTを起点に発火することが無い)だった。 - // このhandlerはリポジトリで初めて有効になる本番SIGTERM/SIGINT handlerであり、telemetryのflushのみを行い - // 上記のgraceful shutdown処理を経由せずに即exitする。将来enableShutdownHooks()を配線する場合は、 - // この即exitとNestJS側のshutdown sequenceが競合しないよう順序を設計すること。 - const processLike = options.process ?? process; - const shutdownTelemetry = options.shutdownTelemetry ?? defaultShutdownTelemetry; - const exit = options.exit ?? ((code: number) => process.exit(code)); - - const handleSignal = async () => { - // 同時に複数signalが来てもflushを二重実行せず、cluster refork抑止用の状態もここで立てる。 - if (shuttingDown) return; - shuttingDown = true; - - try { - // 終了直前にBatchSpanProcessor/Sentryのbufferをflushする。 - // (DB/Redis/queue/HTTPサーバーのgraceful closeはここでは行わない。上記の注意を参照。) - await shutdownTelemetry(); - } catch { - // telemetry flushの失敗でプロセス終了が止まらないよう、ここでは握り潰す。 - } finally { - // 既存挙動と同じく、telemetry flush後はプロセスを終了する。 - exit(0); - } - }; - - // onceにして、同じsignalでhandlerが再入しないようにする。 - processLike.once('SIGTERM', handleSignal); - processLike.once('SIGINT', handleSignal); - - // app.enableShutdownHooks()未配線の現状、SIGTERM/SIGINT時の処理はtelemetry flushのみであることを - // 起動時に明示し、DB/Redis/queue/HTTPサーバーのgraceful closeが行われない点を運用者が把握できるようにする。 - logger.info('Registered SIGTERM/SIGINT handler for telemetry flush (this process does not perform NestJS graceful shutdown on these signals).'); -} - -export function isTelemetryShutdownInProgress(): boolean { - // masterのcluster exit handlerが、意図したshutdown中のworker終了を再forkしないために参照する。 - return shuttingDown; -} +/** + * Telemetry-specific shutdown is implemented by telemetry-registry.ts. + * Signal coordination belongs to boot/shutdown-handler.ts so telemetry and + * logging remain independent domains. + */ +export { shutdownTelemetry } from './telemetry-registry.js'; diff --git a/packages/backend/src/logging/BootstrapConsoleBackend.ts b/packages/backend/src/logging/BootstrapConsoleBackend.ts new file mode 100644 index 0000000000..b6b033c8b6 --- /dev/null +++ b/packages/backend/src/logging/BootstrapConsoleBackend.ts @@ -0,0 +1,49 @@ +/* + * 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'; + +/** 設定読込前の最小出力処理が外部から受け取る依存関係です。 */ +export type BootstrapConsoleBackendDependencies = { + readonly output: (...args: unknown[]) => void; +}; + +const defaultDependencies: BootstrapConsoleBackendDependencies = { + output: (...args) => console.log(...args), +}; + +/** + * 設定読込前でも利用できる、依存の少ないコンソール出力です。 + * 設定ファイルの読み込み失敗を報告するため、Pretty backendやTelemetryには依存しません。 + */ +export class BootstrapConsoleBackend implements LogBackend { + private readonly dependencies: BootstrapConsoleBackendDependencies; + + constructor(dependencies: Partial = {}) { + this.dependencies = { + ...defaultDependencies, + ...dependencies, + }; + } + + public write(record: LogRecord): void { + const worker = record.isPrimary ? '*' : record.workerId ?? '?'; + const line = `${record.timestamp} ${record.level.toUpperCase()} ${worker}\t[${record.loggerName}]\t${record.message}`; + const args: unknown[] = [line]; + + if (record.compatibility?.data != null) { + args.push(record.compatibility.data); + } else if (record.eventName != null || record.attributes != null || record.error != null) { + args.push({ + ...(record.eventName != null ? { eventName: record.eventName } : {}), + ...(record.attributes != null ? { attributes: record.attributes } : {}), + ...(record.error != null ? { error: record.error } : {}), + }); + } + + this.dependencies.output(...args); + } +} diff --git a/packages/backend/src/logging/LogManager.ts b/packages/backend/src/logging/LogManager.ts index 6fef23d35f..565bc5e0b4 100644 --- a/packages/backend/src/logging/LogManager.ts +++ b/packages/backend/src/logging/LogManager.ts @@ -13,7 +13,7 @@ import { type LogNormalizationProfile, } from './LogNormalizer.js'; import type { LogBackend } from './LogBackend.js'; -import type { LogRecord, LogRecordInput } from './types.js'; +import type { LogLevel, LogLevelSetting, LogRecord, LogRecordInput } from './types.js'; /** ログを出力したプロセスを識別するための情報です。 */ export type LogProcessInfo = { @@ -39,6 +39,60 @@ export type LogManagerOptions = { readonly normalizationProfile?: LogNormalizationProfile; }; +/** 起動時に適用するログ出力設定です。 */ +export type LogManagerConfiguration = { + readonly level?: LogLevelSetting; + readonly domains?: Readonly> | null; +}; + +const logLevelOrder: Readonly> = { + debug: 0, + info: 1, + warn: 2, + error: 3, + fatal: 4, +}; + +const validLogLevels = new Set(['debug', 'info', 'warn', 'error', 'fatal', 'off']); + +function validateLogLevel(value: unknown, path: string): LogLevelSetting | undefined { + if (typeof value === 'undefined') return undefined; + if (typeof value !== 'string' || !validLogLevels.has(value as LogLevelSetting)) { + throw new Error(`${path} must be one of debug, info, warn, error, fatal, or off`); + } + return value as LogLevelSetting; +} + +function validateDomainName(domain: string): void { + if (domain.length === 0 || domain.trim() !== domain || domain.split('.').some(segment => segment.length === 0)) { + throw new Error(`logging.domains contains an invalid domain name: ${JSON.stringify(domain)}`); + } +} + +function resolveConfiguration(configuration: LogManagerConfiguration | undefined): { + readonly level: LogLevelSetting | undefined; + readonly domains: readonly (readonly [string, LogLevelSetting])[]; +} { + if (configuration == null) return { level: undefined, domains: [] }; + + const level = validateLogLevel(configuration.level, 'logging.level'); + if (configuration.domains == null) return { level, domains: [] }; + if (typeof configuration.domains !== 'object' || configuration.domains === null || Array.isArray(configuration.domains)) { + throw new Error('logging.domains must be an object'); + } + + const domains = Object.entries(configuration.domains).map(([domain, value]) => { + validateDomainName(domain); + const level = validateLogLevel(value, `logging.domains.${domain}`); + if (typeof level === 'undefined') { + throw new Error(`logging.domains.${domain} must be configured`); + } + return [domain, level] as const; + }).sort((left, right) => right[0].length - left[0].length); + + return { level, domains }; +} + const defaultDependencies: LogManagerDependencies = { now: () => new Date(), getProcessInfo: () => ({ @@ -59,6 +113,9 @@ export class LogManager { private backend: LogBackend; private readonly dependencies: LogManagerDependencies; private normalizationProfile: LogNormalizationProfile; + private configuredLevel: LogLevelSetting | undefined; + private configuredDomains: readonly (readonly [string, LogLevelSetting])[]; + private shutdownPromise: Promise | undefined; /** * 出力先と実行環境から値を取得する処理を受け取ります。 @@ -75,6 +132,8 @@ export class LogManager { ...dependencies, }; this.normalizationProfile = options.normalizationProfile ?? 'standard'; + this.configuredLevel = undefined; + this.configuredDomains = []; } /** @@ -85,11 +144,60 @@ export class LogManager { this.backend = backend; } + /** 起動時の既定levelとdomain別levelを適用します。 */ + public configure(configuration?: LogManagerConfiguration): void { + const resolved = resolveConfiguration(configuration); + this.configuredLevel = resolved.level; + this.configuredDomains = resolved.domains; + } + /** 正規化方式を切り替え、既に作成済みのLoggerにも反映します。 */ public setNormalizationProfile(profile: LogNormalizationProfile): void { this.normalizationProfile = profile; } + /** backendに残っているログをflushしてから終了処理を行います。 */ + public shutdown(): Promise { + if (this.shutdownPromise != null) return this.shutdownPromise; + + this.shutdownPromise = (async () => { + try { + await this.backend.flush?.(); + } finally { + await this.backend.close?.(); + } + })(); + + return this.shutdownPromise; + } + + private getDefaultLevel(): LogLevel { + if (this.dependencies.isVerbose()) return 'debug'; + return this.dependencies.getNodeEnv() === 'production' ? 'info' : 'debug'; + } + + private getThreshold(loggerName: string): LogLevelSetting { + let threshold: LogLevelSetting | undefined; + for (const [domain, level] of this.configuredDomains) { + if (loggerName === domain || loggerName.startsWith(`${domain}.`)) { + threshold = level; + break; + } + } + + threshold ??= this.configuredLevel ?? this.getDefaultLevel(); + + // verboseは障害調査用の緊急モードとして、明示されたoff以外をdebugまで下げる。 + // offは意図的な無効化なので、verboseでも再有効化しない。 + return threshold === 'off' || !this.dependencies.isVerbose() ? threshold : 'debug'; + } + + private shouldWrite(input: LogRecordInput, loggerName: string): boolean { + const threshold = this.getThreshold(loggerName); + if (threshold === 'off') return false; + return logLevelOrder[input.level] >= logLevelOrder[threshold]; + } + /** * 出力条件を確認し、共通情報を付加して出力先へ渡します。 */ @@ -97,8 +205,8 @@ export class LogManager { // `quiet`は他の条件より優先し、ログに付随する情報の取得も行いません。 if (this.dependencies.isQuiet()) return; - // 本番環境のデバッグログは、明示的に`verbose`が指定された場合だけ出力します。 - if (input.level === 'debug' && this.dependencies.getNodeEnv() === 'production' && !this.dependencies.isVerbose()) return; + const loggerName = input.context.map(segment => segment.name).join('.'); + if (!this.shouldWrite(input, loggerName)) return; const processInfo = this.dependencies.getProcessInfo(); // 呼び出し側の配列を共有せず、親から末端までの順序を固定します。 @@ -116,7 +224,7 @@ export class LogManager { ...inputWithoutStructuredValues, context, timestamp: this.dependencies.now().toISOString(), - loggerName: context.map(segment => segment.name).join('.'), + loggerName, processId: processInfo.processId, isPrimary: processInfo.isPrimary, workerId: processInfo.workerId, diff --git a/packages/backend/src/logging/logging-runtime.ts b/packages/backend/src/logging/logging-runtime.ts index 79890ad496..e4f97f56e6 100644 --- a/packages/backend/src/logging/logging-runtime.ts +++ b/packages/backend/src/logging/logging-runtime.ts @@ -4,10 +4,23 @@ */ import { LogManager } from './LogManager.js'; +import { BootstrapConsoleBackend } from './BootstrapConsoleBackend.js'; import { PrettyConsoleBackend } from './PrettyConsoleBackend.js'; +import type { LogManagerConfiguration } from './LogManager.js'; /** * プロセス内のすべてのLoggerが共有するLogManagerです。 * Logger作成後も同じLogManagerを参照するため、出力先の切り替えを一括で反映できます。 */ -export const logManager = new LogManager(new PrettyConsoleBackend()); +export const logManager = new LogManager(new BootstrapConsoleBackend()); + +/** 設定読込後のlogging設定とPretty backendを適用します。 */ +export function configureLogging(configuration?: LogManagerConfiguration): void { + logManager.configure(configuration); + logManager.setBackend(new PrettyConsoleBackend()); +} + +/** プロセス終了前に現在のlogging backendをflushして閉じます。 */ +export function shutdownLogging(): Promise { + return logManager.shutdown(); +} diff --git a/packages/backend/src/logging/types.ts b/packages/backend/src/logging/types.ts index aa3b63edec..1993cd1809 100644 --- a/packages/backend/src/logging/types.ts +++ b/packages/backend/src/logging/types.ts @@ -8,6 +8,9 @@ import type { Keyword } from 'color-convert'; /** ログの重要度を表します。 */ export type LogLevel = 'debug' | 'info' | 'warn' | 'error' | 'fatal'; +/** 設定で指定できるログの閾値です。`off`はログイベントのlevelには使用しません。 */ +export type LogLevelSetting = LogLevel | 'off'; + /** 正規化後にログ属性として扱えるJSONの値です。 */ export type LogAttributeValue = | string diff --git a/packages/backend/test/unit/boot/shutdown-handler.ts b/packages/backend/test/unit/boot/shutdown-handler.ts new file mode 100644 index 0000000000..399820f08c --- /dev/null +++ b/packages/backend/test/unit/boot/shutdown-handler.ts @@ -0,0 +1,113 @@ +/* + * SPDX-FileCopyrightText: syuilo and misskey-project + * SPDX-License-Identifier: AGPL-3.0-only + */ + +import { describe, expect, test, vi } from 'vitest'; + +describe('shutdown-handler', () => { + test('runs shutdown tasks once and exits on SIGTERM or SIGINT', async () => { + vi.resetModules(); + const { installShutdownSignalHandlers, isShutdownInProgress } = await import('@/boot/shutdown-handler.js'); + const handlers = new Map Promise>(); + const processLike = { + once: vi.fn((event: string, handler: () => Promise) => { + handlers.set(event, handler); + return processLike; + }), + }; + const calls: string[] = []; + const shutdownTelemetry = vi.fn(async () => { + calls.push('telemetry'); + }); + const shutdownLogging = vi.fn(async () => { + calls.push('logging'); + }); + const exit = vi.fn(); + const onRegistered = vi.fn(); + + installShutdownSignalHandlers({ process: processLike, shutdownTasks: [shutdownTelemetry, shutdownLogging], exit, onRegistered }); + + expect(processLike.once).toHaveBeenCalledWith('SIGTERM', expect.any(Function)); + expect(processLike.once).toHaveBeenCalledWith('SIGINT', expect.any(Function)); + expect(onRegistered).toHaveBeenCalledOnce(); + expect(isShutdownInProgress()).toBe(false); + + await handlers.get('SIGTERM')!(); + await handlers.get('SIGINT')!(); + + expect(isShutdownInProgress()).toBe(true); + expect(calls).toEqual(['telemetry', 'logging']); + expect(shutdownTelemetry).toHaveBeenCalledTimes(1); + expect(shutdownLogging).toHaveBeenCalledTimes(1); + expect(exit).toHaveBeenCalledTimes(1); + expect(exit).toHaveBeenCalledWith(0); + }); + + test('continues with later shutdown tasks when an earlier task rejects', async () => { + vi.resetModules(); + const { installShutdownSignalHandlers } = await import('@/boot/shutdown-handler.js'); + const handlers = new Map Promise>(); + const processLike = { + once: vi.fn((event: string, handler: () => Promise) => { + handlers.set(event, handler); + return processLike; + }), + }; + const exit = vi.fn(); + const shutdownLogging = vi.fn().mockResolvedValue(undefined); + const shutdownError = new Error('flush failed'); + const consoleError = vi.spyOn(console, 'error').mockImplementation(() => {}); + + try { + installShutdownSignalHandlers({ + process: processLike, + shutdownTasks: [vi.fn().mockRejectedValue(shutdownError), shutdownLogging], + exit, + }); + + await handlers.get('SIGINT')!(); + + expect(exit).toHaveBeenCalledWith(0); + expect(shutdownLogging).toHaveBeenCalledOnce(); + expect(consoleError).toHaveBeenCalledWith('Shutdown task failed:', shutdownError); + } finally { + consoleError.mockRestore(); + } + }); + + test('exits after the shutdown deadline when a task remains pending', async () => { + vi.resetModules(); + vi.useFakeTimers(); + const { installShutdownSignalHandlers } = await import('@/boot/shutdown-handler.js'); + const handlers = new Map Promise>(); + const processLike = { + once: vi.fn((event: string, handler: () => Promise) => { + handlers.set(event, handler); + return processLike; + }), + }; + const exit = vi.fn(); + const consoleError = vi.spyOn(console, 'error').mockImplementation(() => {}); + + try { + installShutdownSignalHandlers({ + process: processLike, + shutdownTasks: [() => new Promise(() => {})], + exit, + }); + + const signalPromise = handlers.get('SIGTERM')!(); + expect(exit).not.toHaveBeenCalled(); + + await vi.advanceTimersByTimeAsync(10_000); + await signalPromise; + + expect(consoleError).toHaveBeenCalledWith('Shutdown tasks timed out after 10000ms.'); + expect(exit).toHaveBeenCalledWith(0); + } finally { + consoleError.mockRestore(); + vi.useRealTimers(); + } + }); +}); diff --git a/packages/backend/test/unit/logging/BootstrapConsoleBackend.ts b/packages/backend/test/unit/logging/BootstrapConsoleBackend.ts new file mode 100644 index 0000000000..43545a0693 --- /dev/null +++ b/packages/backend/test/unit/logging/BootstrapConsoleBackend.ts @@ -0,0 +1,54 @@ +/* + * 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 { BootstrapConsoleBackend } from '@/logging/BootstrapConsoleBackend.js'; + +function createRecord(overrides: Partial = {}): LogRecord { + return { + level: 'error', + message: 'configuration failed', + context: [{ name: 'core' }, { name: 'boot' }], + timestamp: '2025-01-02T03:04:05.678Z', + loggerName: 'core.boot', + processId: 1234, + isPrimary: true, + workerId: null, + ...overrides, + }; +} + +describe('BootstrapConsoleBackend', () => { + test('writes a minimal line with legacy data', () => { + const output = vi.fn(); + const backend = new BootstrapConsoleBackend({ output }); + const data = { detail: 'failed' }; + + backend.write(createRecord({ compatibility: { data } })); + + expect(output).toHaveBeenCalledWith('2025-01-02T03:04:05.678Z ERROR *\t[core.boot]\tconfiguration failed', data); + }); + + test('writes structured details without depending on Pretty formatting', () => { + const output = vi.fn(); + const backend = new BootstrapConsoleBackend({ output }); + + backend.write(createRecord({ + eventName: 'config.load.failed', + attributes: { path: '.config/default.yml' }, + error: { type: 'Error', message: 'not found' }, + })); + + expect(output).toHaveBeenCalledWith( + '2025-01-02T03:04:05.678Z ERROR *\t[core.boot]\tconfiguration failed', + { + eventName: 'config.load.failed', + attributes: { path: '.config/default.yml' }, + error: { type: 'Error', message: 'not found' }, + }, + ); + }); +}); diff --git a/packages/backend/test/unit/logging/LogManager.ts b/packages/backend/test/unit/logging/LogManager.ts index 9329059033..eac853afdb 100644 --- a/packages/backend/test/unit/logging/LogManager.ts +++ b/packages/backend/test/unit/logging/LogManager.ts @@ -4,9 +4,9 @@ */ import { describe, expect, test, vi } from 'vitest'; -import { LogManager } from '@/logging/LogManager.js'; import type { LogBackend } from '@/logging/LogBackend.js'; import type { LogRecordInput } from '@/logging/types.js'; +import { LogManager } from '@/logging/LogManager.js'; /** テストで使う最小構成のログ入力を作成します。 */ function createInput(level: LogRecordInput['level'] = 'info'): LogRecordInput { @@ -28,6 +28,10 @@ function createManager(options: { isPrimary?: boolean; workerId?: number | null; normalizationProfile?: 'standard' | 'detailed'; + configuration?: { + level?: 'debug' | 'info' | 'warn' | 'error' | 'fatal' | 'off'; + domains?: Record; + }; } = {}) { const write = vi.fn(); const manager = new LogManager({ write }, { @@ -43,6 +47,7 @@ function createManager(options: { }, { normalizationProfile: options.normalizationProfile, }); + if (options.configuration) manager.configure(options.configuration); return { manager, write }; } @@ -115,6 +120,76 @@ describe('LogManager', () => { expect(write).toHaveBeenCalledOnce(); }); + test('applies the configured global level', () => { + const { manager, write } = createManager({ configuration: { level: 'warn' } }); + + manager.write(createInput('info')); + manager.write(createInput('warn')); + + expect(write).toHaveBeenCalledOnce(); + expect(write.mock.calls[0][0].level).toBe('warn'); + }); + + test('uses the longest matching domain and supports child re-enablement', () => { + const { manager, write } = createManager({ + configuration: { + level: 'info', + domains: { + queue: 'off', + 'queue.deliver': 'debug', + }, + }, + }); + + manager.write({ ...createInput('info'), context: [{ name: 'queue' }, { name: 'inbox' }] }); + manager.write({ ...createInput('debug'), context: [{ name: 'queue' }, { name: 'deliver' }] }); + manager.write({ ...createInput('debug'), context: [{ name: 'queueing' }] }); + + expect(write).toHaveBeenCalledOnce(); + expect(write.mock.calls[0][0].loggerName).toBe('queue.deliver'); + }); + + test('lowers configured levels to debug in verbose mode', () => { + const { manager, write } = createManager({ + nodeEnv: 'production', + verbose: true, + configuration: { level: 'info' }, + }); + + manager.write(createInput('debug')); + + expect(write).toHaveBeenCalledOnce(); + }); + + test('keeps explicit off levels disabled in verbose mode', () => { + const { manager, write } = createManager({ + verbose: true, + configuration: { + level: 'off', + domains: { + queue: 'off', + 'queue.deliver': 'warn', + }, + }, + }); + + manager.write({ ...createInput('fatal'), context: [{ name: 'system' }] }); + manager.write({ ...createInput('debug'), context: [{ name: 'queue' }] }); + manager.write({ ...createInput('debug'), context: [{ name: 'queue' }, { name: 'deliver' }] }); + + expect(write).toHaveBeenCalledOnce(); + expect(write.mock.calls[0][0].loggerName).toBe('queue.deliver'); + }); + + test('rejects invalid logging configuration', () => { + const { manager } = createManager(); + + expect(() => manager.configure({ domains: null })).not.toThrow(); + expect(() => manager.configure({ level: 'notice' as never })).toThrow('logging.level'); + expect(() => manager.configure({ domains: { queue: 'notice' as never } })).toThrow('logging.domains.queue'); + expect(() => manager.configure({ domains: { 'queue.': 'info' } })).toThrow('invalid domain name'); + }); + test('uses a replaced backend for subsequent records', () => { const { manager, write } = createManager(); const replacementWrite = vi.fn(); @@ -126,6 +201,19 @@ describe('LogManager', () => { expect(replacementWrite).toHaveBeenCalledOnce(); }); + test('flushes and closes the backend once during shutdown', async () => { + const write = vi.fn(); + const flush = vi.fn>().mockResolvedValue(undefined); + const close = vi.fn>().mockResolvedValue(undefined); + const manager = new LogManager({ write, flush, close }); + + await Promise.all([manager.shutdown(), manager.shutdown()]); + + expect(flush).toHaveBeenCalledOnce(); + expect(close).toHaveBeenCalledOnce(); + expect(flush.mock.invocationCallOrder[0]).toBeLessThan(close.mock.invocationCallOrder[0]); + }); + test('normalizes structured attributes and errors before writing', () => { const { manager, write } = createManager(); const error = new TypeError('broken'); diff --git a/packages/backend/test/unit/telemetry-shutdown.ts b/packages/backend/test/unit/telemetry-shutdown.ts deleted file mode 100644 index 11c47c4181..0000000000 --- a/packages/backend/test/unit/telemetry-shutdown.ts +++ /dev/null @@ -1,59 +0,0 @@ -/* - * SPDX-FileCopyrightText: syuilo and misskey-project - * SPDX-License-Identifier: AGPL-3.0-only - */ - -import { describe, expect, test, vi } from 'vitest'; - -describe('telemetry-shutdown', () => { - test('flushes telemetry once and exits on SIGTERM or SIGINT', async () => { - vi.resetModules(); - const { installTelemetrySignalHandlers, isTelemetryShutdownInProgress } = await import('@/core/telemetry/telemetry-shutdown.js'); - const handlers = new Map Promise>(); - const processLike = { - once: vi.fn((event: string, handler: () => Promise) => { - handlers.set(event, handler); - return processLike; - }), - }; - const shutdownTelemetry = vi.fn().mockResolvedValue(undefined); - const exit = vi.fn(); - - installTelemetrySignalHandlers({ process: processLike, shutdownTelemetry, exit }); - - expect(processLike.once).toHaveBeenCalledWith('SIGTERM', expect.any(Function)); - expect(processLike.once).toHaveBeenCalledWith('SIGINT', expect.any(Function)); - expect(isTelemetryShutdownInProgress()).toBe(false); - - await handlers.get('SIGTERM')!(); - await handlers.get('SIGINT')!(); - - expect(isTelemetryShutdownInProgress()).toBe(true); - expect(shutdownTelemetry).toHaveBeenCalledTimes(1); - expect(exit).toHaveBeenCalledTimes(1); - expect(exit).toHaveBeenCalledWith(0); - }); - - test('exits even when telemetry shutdown rejects', async () => { - vi.resetModules(); - const { installTelemetrySignalHandlers } = await import('@/core/telemetry/telemetry-shutdown.js'); - const handlers = new Map Promise>(); - const processLike = { - once: vi.fn((event: string, handler: () => Promise) => { - handlers.set(event, handler); - return processLike; - }), - }; - const exit = vi.fn(); - - installTelemetrySignalHandlers({ - process: processLike, - shutdownTelemetry: vi.fn().mockRejectedValue(new Error('flush failed')), - exit, - }); - - await handlers.get('SIGINT')!(); - - expect(exit).toHaveBeenCalledWith(0); - }); -});