mirror of
https://github.com/misskey-dev/misskey.git
synced 2026-07-29 18:44:39 +02:00
Merge branch 'develop' into feature/role-hidden-setting
This commit is contained in:
@@ -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
|
||||
|
||||
@@ -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
|
||||
|
||||
51
.github/scripts/backend-memory-report.mts
vendored
51
.github/scripts/backend-memory-report.mts
vendored
@@ -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)}<br>${util.formatDeltaPercent(percent, 0.1).replaceAll('\\%', '\\\\%')}`;
|
||||
const deltaMedian = `${formatDeltaMemory(summary.median)}<br>${util.formatDeltaPercent(percent, 0.1).replaceAll('\\%', '\\\\%')}`;
|
||||
|
||||
lines.push(`| **${metric}** | ${formatMemoryMb(baseValue)} <br> ± ${formatMemoryMb(baseSpread)} | ${formatMemoryMb(headValue)} <br> ± ${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)} <br> ± ${formatMemoryMb(baseSpread)} | ${formatMemoryMb(headValue)} <br> ± ${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('');
|
||||
}
|
||||
|
||||
|
||||
@@ -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,
|
||||
|
||||
110
.github/scripts/memory-stability-util.test.mts
vendored
Normal file
110
.github/scripts/memory-stability-util.test.mts
vendored
Normal file
@@ -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<string, number>[]) {
|
||||
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,
|
||||
});
|
||||
});
|
||||
11
.github/workflows/get-backend-memory.yml
vendored
11
.github/workflows/get-backend-memory.yml
vendored
@@ -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
|
||||
|
||||
1
.github/workflows/lint.yml
vendored
1
.github/workflows/lint.yml
vendored
@@ -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
|
||||
|
||||
19
.github/workflows/report-backend-memory.yml
vendored
19
.github/workflows/report-backend-memory.yml
vendored
@@ -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:
|
||||
|
||||
@@ -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 に含まれない問題を修正
|
||||
|
||||
@@ -57,14 +57,14 @@ type HeapSnapshotErrorMessage = {
|
||||
};
|
||||
type HeapSnapshotResponseMessage = HeapSnapshotMessage | HeapSnapshotErrorMessage;
|
||||
|
||||
function parseMemoryFile<KS extends readonly string[]>(content: string, keys: KS, path: string, required: boolean): Record<KS[number], number> {
|
||||
function parseMemoryFile<KS extends readonly string[]>(content: string, keys: KS, path: string): Record<KS[number], number> {
|
||||
const result = {} as Record<KS[number], number>;
|
||||
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<string, unknown> {
|
||||
|
||||
@@ -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}`);
|
||||
});
|
||||
|
||||
|
||||
@@ -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);
|
||||
|
||||
100
packages/backend/src/boot/shutdown-handler.ts
Normal file
100
packages/backend/src/boot/shutdown-handler.ts
Normal file
@@ -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<void>): unknown;
|
||||
};
|
||||
|
||||
const SHUTDOWN_TIMEOUT_MS = 10_000;
|
||||
|
||||
export type ShutdownTask = () => Promise<void>;
|
||||
|
||||
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<void>(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;
|
||||
}
|
||||
@@ -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();
|
||||
|
||||
@@ -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<RedisOptions> & {
|
||||
host: string;
|
||||
@@ -132,6 +133,8 @@ type Source = {
|
||||
pidFile: string;
|
||||
|
||||
logging?: {
|
||||
level?: LogLevelSetting;
|
||||
domains?: Record<string, LogLevelSetting> | null;
|
||||
sql?: {
|
||||
disableQueryTruncation?: boolean,
|
||||
enableQueryParamLogging?: boolean,
|
||||
@@ -194,6 +197,8 @@ export type Config = {
|
||||
deliverJobMaxAttempts: number | undefined;
|
||||
inboxJobMaxAttempts: number | undefined;
|
||||
logging?: {
|
||||
level?: LogLevelSetting;
|
||||
domains?: Record<string, LogLevelSetting> | null;
|
||||
sql?: {
|
||||
disableQueryTruncation?: boolean,
|
||||
enableQueryParamLogging?: boolean,
|
||||
|
||||
@@ -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<void>): unknown;
|
||||
};
|
||||
|
||||
type InstallTelemetrySignalHandlersOptions = {
|
||||
process?: SignalProcess;
|
||||
shutdownTelemetry?: () => Promise<void>;
|
||||
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';
|
||||
|
||||
49
packages/backend/src/logging/BootstrapConsoleBackend.ts
Normal file
49
packages/backend/src/logging/BootstrapConsoleBackend.ts
Normal file
@@ -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<BootstrapConsoleBackendDependencies> = {}) {
|
||||
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);
|
||||
}
|
||||
}
|
||||
@@ -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<Record<string, LogLevelSetting>> | null;
|
||||
};
|
||||
|
||||
const logLevelOrder: Readonly<Record<LogLevel, number>> = {
|
||||
debug: 0,
|
||||
info: 1,
|
||||
warn: 2,
|
||||
error: 3,
|
||||
fatal: 4,
|
||||
};
|
||||
|
||||
const validLogLevels = new Set<LogLevelSetting>(['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<void> | 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<void> {
|
||||
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,
|
||||
|
||||
@@ -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<void> {
|
||||
return logManager.shutdown();
|
||||
}
|
||||
|
||||
@@ -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
|
||||
|
||||
113
packages/backend/test/unit/boot/shutdown-handler.ts
Normal file
113
packages/backend/test/unit/boot/shutdown-handler.ts
Normal file
@@ -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<string, () => Promise<void>>();
|
||||
const processLike = {
|
||||
once: vi.fn((event: string, handler: () => Promise<void>) => {
|
||||
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<string, () => Promise<void>>();
|
||||
const processLike = {
|
||||
once: vi.fn((event: string, handler: () => Promise<void>) => {
|
||||
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<string, () => Promise<void>>();
|
||||
const processLike = {
|
||||
once: vi.fn((event: string, handler: () => Promise<void>) => {
|
||||
handlers.set(event, handler);
|
||||
return processLike;
|
||||
}),
|
||||
};
|
||||
const exit = vi.fn();
|
||||
const consoleError = vi.spyOn(console, 'error').mockImplementation(() => {});
|
||||
|
||||
try {
|
||||
installShutdownSignalHandlers({
|
||||
process: processLike,
|
||||
shutdownTasks: [() => new Promise<void>(() => {})],
|
||||
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();
|
||||
}
|
||||
});
|
||||
});
|
||||
@@ -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> = {}): 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' },
|
||||
},
|
||||
);
|
||||
});
|
||||
});
|
||||
@@ -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<string, 'debug' | 'info' | 'warn' | 'error' | 'fatal' | 'off'>;
|
||||
};
|
||||
} = {}) {
|
||||
const write = vi.fn<LogBackend['write']>();
|
||||
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<LogBackend['write']>();
|
||||
@@ -126,6 +201,19 @@ describe('LogManager', () => {
|
||||
expect(replacementWrite).toHaveBeenCalledOnce();
|
||||
});
|
||||
|
||||
test('flushes and closes the backend once during shutdown', async () => {
|
||||
const write = vi.fn<LogBackend['write']>();
|
||||
const flush = vi.fn<NonNullable<LogBackend['flush']>>().mockResolvedValue(undefined);
|
||||
const close = vi.fn<NonNullable<LogBackend['close']>>().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');
|
||||
|
||||
@@ -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<string, () => Promise<void>>();
|
||||
const processLike = {
|
||||
once: vi.fn((event: string, handler: () => Promise<void>) => {
|
||||
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<string, () => Promise<void>>();
|
||||
const processLike = {
|
||||
once: vi.fn((event: string, handler: () => Promise<void>) => {
|
||||
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);
|
||||
});
|
||||
});
|
||||
Reference in New Issue
Block a user