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/.github/scripts/backend-memory-report.mts b/.github/scripts/backend-memory-report.mts index 9aae10d887..4a701655ec 100644 --- a/.github/scripts/backend-memory-report.mts +++ b/.github/scripts/backend-memory-report.mts @@ -47,8 +47,7 @@ const memoryReportPhases = [ const metrics = [ 'HeapUsed', 'Pss', - 'Private_Dirty', - 'VmRSS', + 'USS', 'External', ] as const; @@ -57,16 +56,27 @@ function formatMemoryMb(valueKiB: number | null | undefined) { return `${util.formatNumber(valueKiB / 1000)} MB`; } -function getMemoryValue(report: MemoryReport, phase: typeof memoryReportPhases[number]['key'], metric: typeof metrics[number]) { - return report.summary[phase].memoryUsage[metric]; +function formatMetricName(metric: typeof metrics[number]) { + return metric === 'Pss' ? 'PSS' : metric; } function getMemoryValueFromSample(sample: MemoryReport['samples'][number], phase: typeof memoryReportPhases[number]['key'], metric: typeof metrics[number]) { - return sample.phases[phase].memoryUsage[metric]; + const memoryUsage = sample.phases[phase].memoryUsage; + if (metric !== 'USS') return memoryUsage[metric]; + return memoryUsage.Private_Clean + memoryUsage.Private_Dirty; +} + +function getSampleValues(report: MemoryReport, phase: typeof memoryReportPhases[number]['key'], metric: typeof metrics[number]) { + return report.samples.map(sample => getMemoryValueFromSample(sample, phase, metric)); +} + +function getMemoryValue(report: MemoryReport, phase: typeof memoryReportPhases[number]['key'], metric: typeof metrics[number]) { + if (metric !== 'USS') return report.summary[phase].memoryUsage[metric]; + return util.median(getSampleValues(report, phase, metric)); } function getSampleSpread(report: MemoryReport, phase: typeof memoryReportPhases[number]['key'], metric: typeof metrics[number]) { - const values = report.samples.map(sample => getMemoryValueFromSample(sample, phase, metric)); + const values = getSampleValues(report, phase, metric); if (values.length < 2) return null; const center = util.median(values); @@ -91,9 +101,9 @@ function renderMainTableForPhase(base: MemoryReport, head: MemoryReport, phase: const headSpread = getSampleSpread(head, phase, metric); const summary = util.pairedDeltaSummary(base.samples, head.samples, (sample) => getMemoryValueFromSample(sample, phase, metric)); const percent = summary.median * 100 / baseValue; - const deltaMedian = summary == null ? '-' : `${formatDeltaMemory(summary.median)}
${util.formatDeltaPercent(percent, 0.1).replaceAll('\\%', '\\\\%')}`; + const deltaMedian = `${formatDeltaMemory(summary.median)}
${util.formatDeltaPercent(percent, 0.1).replaceAll('\\%', '\\\\%')}`; - lines.push(`| **${metric}** | ${formatMemoryMb(baseValue)}
± ${formatMemoryMb(baseSpread)} | ${formatMemoryMb(headValue)}
± ${formatMemoryMb(headSpread)} | ${deltaMedian} | ${summary?.mad == null ? '-' : formatMemoryMb(summary.mad)} | ${summary == null ? '-' : formatDeltaMemory(summary.min)} | ${summary == null ? '-' : formatDeltaMemory(summary.max)} |`); + lines.push(`| **${formatMetricName(metric)}** | ${formatMemoryMb(baseValue)}
± ${formatMemoryMb(baseSpread)} | ${formatMemoryMb(headValue)}
± ${formatMemoryMb(headSpread)} | ${deltaMedian} | ${formatMemoryMb(summary.mad)} | ${formatDeltaMemory(summary.min)} | ${formatDeltaMemory(summary.max)} |`); } return lines.join('\n'); @@ -374,8 +384,9 @@ if (heapSnapshotSection != null) { lines.push(''); } -const artifactUrl = process.env.MK_MEMORY_HEAP_SNAPSHOT_ARTIFACT_URL_HEAD!.trim(); -lines.push(`[Download representative V8 heap snapshot (head)](${artifactUrl})`); +const baseHeapSnapshotArtifactUrl = process.env.MK_MEMORY_HEAP_SNAPSHOT_ARTIFACT_URL_BASE!.trim(); +const headHeapSnapshotArtifactUrl = process.env.MK_MEMORY_HEAP_SNAPSHOT_ARTIFACT_URL_HEAD!.trim(); +lines.push(`Download representative V8 heap snapshot [base](${baseHeapSnapshotArtifactUrl}) / [head](${headHeapSnapshotArtifactUrl})`); lines.push(''); const jsFootprintSection = renderJsFootprintSection(baseJsFootprint, headJsFootprint); @@ -384,27 +395,15 @@ if (jsFootprintSection != null) { lines.push(''); } -function getWarningMetric(base: MemoryReport, head: MemoryReport) { - for (const metric of ['Pss', 'Private_Dirty', 'VmRSS'] as const) { - if (getMemoryValue(base, 'afterGc', metric) != null && getMemoryValue(head, 'afterGc', metric) != null) { - return metric; - } - } - return null; -} - function getDiffPercent(base: MemoryReport, head: MemoryReport, phase: typeof memoryReportPhases[number]['key'], metric: typeof metrics[number]) { const baseValue = getMemoryValue(base, phase, metric); const headValue = getMemoryValue(head, phase, metric); - if (baseValue == null || headValue == null || baseValue <= 0) return null; - return ((headValue - baseValue) * 100) / baseValue; } function isBeyondSampleNoise(base: MemoryReport, head: MemoryReport, phase: typeof memoryReportPhases[number]['key'], metric: typeof metrics[number]) { const baseValue = getMemoryValue(base, phase, metric); const headValue = getMemoryValue(head, phase, metric); - if (baseValue == null || headValue == null) return false; const delta = headValue - baseValue; if (delta <= 0) return false; @@ -417,10 +416,10 @@ function isBeyondSampleNoise(base: MemoryReport, head: MemoryReport, phase: type return delta > combinedSpread * 3; } -const warningMetric = getWarningMetric(base, head); -const warningDiffPercent = warningMetric == null ? null : getDiffPercent(base, head, 'afterGc', warningMetric); -if (warningMetric != null && warningDiffPercent != null && warningDiffPercent > 5 && isBeyondSampleNoise(base, head, 'afterGc', warningMetric)) { - lines.push(`⚠️ **Warning**: Memory usage (${warningMetric}) has increased by more than 5% and exceeds the observed sample noise. Please verify this is not an unintended change.`); +const warningMetric = 'Pss'; +const warningDiffPercent = getDiffPercent(base, head, 'afterGc', warningMetric); +if (warningDiffPercent > 5 && isBeyondSampleNoise(base, head, 'afterGc', warningMetric)) { + lines.push(`⚠️ **Warning**: Memory usage (${formatMetricName(warningMetric)}) has increased by more than 5% and exceeds the observed sample noise. Please verify this is not an unintended change.`); lines.push(''); } diff --git a/.github/scripts/measure-backend-memory-comparison.mts b/.github/scripts/measure-backend-memory-comparison.mts index ee95c68165..a4e93b3ce4 100644 --- a/.github/scripts/measure-backend-memory-comparison.mts +++ b/.github/scripts/measure-backend-memory-comparison.mts @@ -28,8 +28,15 @@ export type MemoryReport = { const [baseDirArg, headDirArg, baseOutputArg, headOutputArg] = process.argv.slice(2); const HEAP_SNAPSHOT_BREAKDOWN_TOP_N = util.readIntegerEnv('MK_MEMORY_HEAP_SNAPSHOT_BREAKDOWN_TOP_N', heapSnapshotUtil.defaultHeapSnapshotBreakdownTopN, 1); -const HEAD_HEAP_SNAPSHOT_WORK_DIR = resolve('head-heap-snapshots'); -const HEAD_HEAP_SNAPSHOT_OUTPUT_PATH = resolve('head-heap-snapshot.heapsnapshot'); +const heapSnapshotLabels = ['base', 'head'] as const; +const HEAP_SNAPSHOT_WORK_DIRS = { + base: resolve('base-heap-snapshots'), + head: resolve('head-heap-snapshots'), +}; +const HEAP_SNAPSHOT_OUTPUT_PATHS = { + base: resolve('base-heap-snapshot.heapsnapshot'), + head: resolve('head-heap-snapshot.heapsnapshot'), +}; // Use the head checkout's measurement harness for both targets so only the built backend differs. const MEASURE_MEMORY_SCRIPT = resolve(import.meta.dirname, '../../packages/backend/scripts/measure-memory.mts'); @@ -119,11 +126,11 @@ async function measureRepo(label: string, repoDir: string, round: number, option return JSON.parse(stdout) as MemorySample; } -function headHeapSnapshotPath(round: number) { - return join(HEAD_HEAP_SNAPSHOT_WORK_DIR, `round-${round}.heapsnapshot`); +function heapSnapshotPath(label: typeof heapSnapshotLabels[number], round: number) { + return join(HEAP_SNAPSHOT_WORK_DIRS[label], `round-${round}.heapsnapshot`); } -function selectRepresentativeHeadHeapSnapshotRound(samples: MemoryReport['samples'], summary: MemoryReport['summary']) { +function selectRepresentativeHeapSnapshotRound(samples: MemoryReport['samples'], summary: MemoryReport['summary']) { const medianTotal = summary.afterGc.heapSnapshot?.categories?.total; if (medianTotal == null || !Number.isFinite(medianTotal)) return null; @@ -144,13 +151,13 @@ function selectRepresentativeHeadHeapSnapshotRound(samples: MemoryReport['sample return selected?.round ?? null; } -async function saveRepresentativeHeadHeapSnapshot(samples: MemoryReport['samples'], summary: MemoryReport['summary']) { - const round = selectRepresentativeHeadHeapSnapshotRound(samples, summary); +async function saveRepresentativeHeapSnapshot(label: typeof heapSnapshotLabels[number], samples: MemoryReport['samples'], summary: MemoryReport['summary']) { + const round = selectRepresentativeHeapSnapshotRound(samples, summary); if (round == null) return; - await copyFile(headHeapSnapshotPath(round), HEAD_HEAP_SNAPSHOT_OUTPUT_PATH); - process.stderr.write(`Selected head heap snapshot round ${round} for artifact\n`); - await rm(HEAD_HEAP_SNAPSHOT_WORK_DIR, { recursive: true, force: true }); + await copyFile(heapSnapshotPath(label, round), HEAP_SNAPSHOT_OUTPUT_PATHS[label]); + process.stderr.write(`Selected ${label} heap snapshot round ${round} for artifact\n`); + await rm(HEAP_SNAPSHOT_WORK_DIRS[label], { recursive: true, force: true }); } async function main() { @@ -162,8 +169,10 @@ async function main() { const warmupRounds = util.readIntegerEnv('MK_MEMORY_COMPARE_WARMUP_ROUNDS', 1, 0); const startedAt = new Date().toISOString(); - await rm(HEAD_HEAP_SNAPSHOT_WORK_DIR, { recursive: true, force: true }); - await rm(HEAD_HEAP_SNAPSHOT_OUTPUT_PATH, { force: true }); + for (const label of heapSnapshotLabels) { + await rm(HEAP_SNAPSHOT_WORK_DIRS[label], { recursive: true, force: true }); + await rm(HEAP_SNAPSHOT_OUTPUT_PATHS[label], { force: true }); + } const reports = { base: { @@ -178,7 +187,7 @@ async function main() { for (let round = 1; round <= warmupRounds; round++) { process.stderr.write(`Starting warmup round ${round}/${warmupRounds}\n`); - for (const label of ['base', 'head'] as const) { + for (const label of heapSnapshotLabels) { await measureRepo(label, reports[label].dir, -round); } } @@ -188,10 +197,7 @@ async function main() { process.stderr.write(`Starting measurement round ${round}/${rounds}: ${order.join(' -> ')}\n`); for (const label of order) { - const shouldSaveHeadHeapSnapshot = label === 'head'; - const options = shouldSaveHeadHeapSnapshot - ? { heapSnapshotSavePath: headHeapSnapshotPath(round) } - : {}; + const options = { heapSnapshotSavePath: heapSnapshotPath(label, round) }; const sample = await measureRepo(label, reports[label].dir, round, options); reports[label].samples.push({ ...sample, @@ -204,9 +210,11 @@ async function main() { base: summarizeSamples(reports.base.samples), head: summarizeSamples(reports.head.samples), }; - await saveRepresentativeHeadHeapSnapshot(reports.head.samples, summaries.head); + for (const label of heapSnapshotLabels) { + await saveRepresentativeHeapSnapshot(label, reports[label].samples, summaries[label]); + } - for (const label of ['base', 'head'] as const) { + for (const label of heapSnapshotLabels) { const report = { timestamp: new Date().toISOString(), sampleCount: reports[label].samples.length, diff --git a/.github/scripts/memory-stability-util.test.mts b/.github/scripts/memory-stability-util.test.mts new file mode 100644 index 0000000000..70bbb3924b --- /dev/null +++ b/.github/scripts/memory-stability-util.test.mts @@ -0,0 +1,110 @@ +/* + * SPDX-FileCopyrightText: syuilo and misskey-project + * SPDX-License-Identifier: AGPL-3.0-only + */ + +import assert from 'node:assert/strict'; +import test from 'node:test'; +import { measureMemoryUntilStable } from './memory-stability-util.mts'; + +function createTimer() { + let elapsedMs = 0; + + return { + now: () => elapsedMs, + wait: async (durationMs: number) => { + elapsedMs += durationMs; + }, + }; +} + +async function measure(readings: Record[]) { + let readCount = 0; + const result = await measureMemoryUntilStable( + async () => readings[readCount++], + createTimer(), + ); + return { result, readCount }; +} + +test('adopts the latest reading once Pss and Private_Dirty slopes converge', async () => { + const readings = [ + { Pss: 1000, Private_Dirty: 500, HeapUsed: 300 }, + { Pss: 1100, Private_Dirty: 520, HeapUsed: 310 }, + { Pss: 1200, Private_Dirty: 540, HeapUsed: 320 }, + ]; + const { result, readCount } = await measure(readings); + + assert.equal(readCount, 3); + assert.deepEqual(result.memoryUsage, readings[2]); + assert.deepEqual(result.stability, { + converged: true, + readingCount: 3, + elapsedMs: 4000, + maxAbsoluteSlopesKiBPerSecond: { + Pss: 50, + Private_Dirty: 10, + }, + }); +}); + +test('uses only the latest readings when determining convergence', async () => { + const readings = [ + { Pss: 1000, Private_Dirty: 500 }, + { Pss: 2000, Private_Dirty: 1000 }, + { Pss: 3000, Private_Dirty: 1500 }, + { Pss: 3040, Private_Dirty: 1520 }, + { Pss: 3080, Private_Dirty: 1540 }, + ]; + const { result, readCount } = await measure(readings); + + assert.equal(readCount, 5); + assert.equal(result.stability.converged, true); + assert.deepEqual(result.stability.maxAbsoluteSlopesKiBPerSecond, { + Pss: 20, + Private_Dirty: 10, + }); +}); + +test('bounds the wait and reports the latest slopes when memory does not converge', async () => { + const readings = [ + { Pss: 1000, Private_Dirty: 500 }, + { Pss: 1600, Private_Dirty: 520 }, + { Pss: 2200, Private_Dirty: 540 }, + { Pss: 2800, Private_Dirty: 560 }, + { Pss: 3400, Private_Dirty: 580 }, + { Pss: 4000, Private_Dirty: 600 }, + ]; + const { result, readCount } = await measure(readings); + + assert.equal(readCount, 6); + assert.deepEqual(result.memoryUsage, readings[5]); + assert.deepEqual(result.stability, { + converged: false, + readingCount: 6, + elapsedMs: 10000, + maxAbsoluteSlopesKiBPerSecond: { + Pss: 300, + Private_Dirty: 10, + }, + }); +}); + +test('does not treat opposing adjacent slopes as convergence', async () => { + const readings = [ + { Pss: 1000, Private_Dirty: 500 }, + { Pss: 1600, Private_Dirty: 500 }, + { Pss: 1000, Private_Dirty: 500 }, + { Pss: 1600, Private_Dirty: 500 }, + { Pss: 1000, Private_Dirty: 500 }, + { Pss: 1600, Private_Dirty: 500 }, + ]; + const { result, readCount } = await measure(readings); + + assert.equal(readCount, 6); + assert.equal(result.stability.converged, false); + assert.deepEqual(result.stability.maxAbsoluteSlopesKiBPerSecond, { + Pss: 300, + Private_Dirty: 0, + }); +}); diff --git a/.github/workflows/get-backend-memory.yml b/.github/workflows/get-backend-memory.yml index 0d0bec3307..1f933444bd 100644 --- a/.github/workflows/get-backend-memory.yml +++ b/.github/workflows/get-backend-memory.yml @@ -93,15 +93,22 @@ jobs: run: pnpm build - name: Measure backend memory usage env: - MK_MEMORY_COMPARE_ROUNDS: 5 + MK_MEMORY_COMPARE_ROUNDS: 10 MK_MEMORY_COMPARE_WARMUP_ROUNDS: 1 MK_MEMORY_HEAP_SNAPSHOT: 1 run: node head/.github/scripts/measure-backend-memory-comparison.mts base head memory-base.json memory-head.json + - name: Upload base heap snapshot + uses: actions/upload-artifact@v7 + with: + path: base-heap-snapshot.heapsnapshot + archive: false + if-no-files-found: error + retention-days: 7 - name: Upload head heap snapshot uses: actions/upload-artifact@v7 with: - name: backend-memory-head-heap-snapshot path: head-heap-snapshot.heapsnapshot + archive: false if-no-files-found: error retention-days: 7 - name: Measure backend loaded JS footprint diff --git a/.github/workflows/lint.yml b/.github/workflows/lint.yml index c8e24fb19b..63f8684c33 100644 --- a/.github/workflows/lint.yml +++ b/.github/workflows/lint.yml @@ -151,3 +151,4 @@ jobs: with: node-version-file: '.node-version' - run: node --test .github/scripts/frontend-js-size.test.mts + - run: node --test .github/scripts/memory-stability-util.test.mts diff --git a/.github/workflows/report-backend-memory.yml b/.github/workflows/report-backend-memory.yml index 3343ec745e..a6c0b4afdf 100644 --- a/.github/workflows/report-backend-memory.yml +++ b/.github/workflows/report-backend-memory.yml @@ -33,8 +33,8 @@ jobs: - name: Load PR Number id: load-pr-num run: echo "pr-number=$(cat artifacts/pr_number)" >> "$GITHUB_OUTPUT" - - name: Find head heap snapshot artifact - id: find-heap-snapshot-artifact + - name: Find heap snapshot artifacts + id: find-heap-snapshot-artifacts uses: actions/github-script@v8 with: script: | @@ -45,14 +45,21 @@ jobs: repo, run_id, }); - const artifact = artifacts.find(artifact => artifact.name === 'backend-memory-head-heap-snapshot'); - if (artifact == null) return; - core.setOutput('url', `https://github.com/${owner}/${repo}/actions/runs/${run_id}/artifacts/${artifact.id}`); + const artifactNames = { + base: 'base-heap-snapshot.heapsnapshot', + head: 'head-heap-snapshot.heapsnapshot', + }; + for (const [label, artifactName] of Object.entries(artifactNames)) { + const artifact = artifacts.find(artifact => artifact.name === artifactName); + if (artifact == null) throw new Error(`Artifact not found: ${artifactName}`); + core.setOutput(`${label}-url`, `https://github.com/${owner}/${repo}/actions/runs/${run_id}/artifacts/${artifact.id}`); + } - id: build-comment name: Build memory comment env: - MK_MEMORY_HEAP_SNAPSHOT_ARTIFACT_URL_HEAD: ${{ steps.find-heap-snapshot-artifact.outputs.url }} + MK_MEMORY_HEAP_SNAPSHOT_ARTIFACT_URL_BASE: ${{ steps.find-heap-snapshot-artifacts.outputs.base-url }} + MK_MEMORY_HEAP_SNAPSHOT_ARTIFACT_URL_HEAD: ${{ steps.find-heap-snapshot-artifacts.outputs.head-url }} run: node .github/scripts/backend-memory-report.mts ./artifacts/memory-base.json ./artifacts/memory-head.json ./output.md ./artifacts/js-footprint-base.json ./artifacts/js-footprint-head.json - uses: thollander/actions-comment-pull-request@v3 with: diff --git a/CHANGELOG.md b/CHANGELOG.md index dda2c1880f..b714676e42 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -56,6 +56,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/scripts/measure-memory.mts b/packages/backend/scripts/measure-memory.mts index 55aab61a84..a95eb3075c 100644 --- a/packages/backend/scripts/measure-memory.mts +++ b/packages/backend/scripts/measure-memory.mts @@ -57,14 +57,14 @@ type HeapSnapshotErrorMessage = { }; type HeapSnapshotResponseMessage = HeapSnapshotMessage | HeapSnapshotErrorMessage; -function parseMemoryFile(content: string, keys: KS, path: string, required: boolean): Record { +function parseMemoryFile(content: string, keys: KS, path: string): Record { const result = {} as Record; for (const _key of keys) { const key = _key as KS[number]; const match = content.match(new RegExp(`${key}:\\s+(\\d+)\\s+kB`)); if (match) { result[key] = parseInt(match[1], 10); - } else if (required) { + } else { throw new Error(`Failed to parse ${key} from ${path}`); } } @@ -78,13 +78,13 @@ function bytesToKiB(value: number) { async function getMemoryUsage(pid: number) { const path = `/proc/${pid}/status`; const status = await fs.readFile(path, 'utf-8'); - return parseMemoryFile(status, procStatusKeys, path, true); + return parseMemoryFile(status, procStatusKeys, path); } async function getSmapsRollupMemoryUsage(pid: number) { const path = `/proc/${pid}/smaps_rollup`; const smapsRollup = await fs.readFile(path, 'utf-8'); - return parseMemoryFile(smapsRollup, smapsRollupKeys, path, false); + return parseMemoryFile(smapsRollup, smapsRollupKeys, path); } function isRecord(value: unknown): value is Record { 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); - }); -});