diff --git a/.config/docker_example.yml b/.config/docker_example.yml index 4e10f771b0..4d7ec5e1e2 100644 --- a/.config/docker_example.yml +++ b/.config/docker_example.yml @@ -241,7 +241,7 @@ proxyBypassHosts: # Log settings # logging: -# # ログの出力形式。「json」で1行JSON、未指定時は「pretty」です。 +# # Log output format. "json" outputs one-line JSON; defaults to "pretty". # format: pretty # # Minimum level for all loggers. Defaults to info in production and debug otherwise. # level: info @@ -251,6 +251,19 @@ proxyBypassHosts: # queue: error # queue.deliver: debug # db.sql: off +# # HTTP status classes to record in the access log. No output when unspecified. +# access: +# statusClasses: +# - '2xx' +# - '3xx' +# - '4xx' +# - '5xx' +# # Enable body logging explicitly only during development. +# bodies: +# request: false +# response: false +# # 16 KiB by default, up to 128 KiB. +# maxBytes: 16384 # sql: # # Outputs query parameters during SQL execution to the log. # # default: false diff --git a/.config/example.yml b/.config/example.yml index 06a0ed0651..94e2388835 100644 --- a/.config/example.yml +++ b/.config/example.yml @@ -474,7 +474,7 @@ proxyBypassHosts: # Log settings # logging: -# # ログの出力形式。「json」で1行JSON、未指定時は「pretty」です。 +# # Log output format. "json" outputs one-line JSON; defaults to "pretty". # format: pretty # # Minimum level for all loggers. Defaults to info in production and debug otherwise. # level: info @@ -484,6 +484,19 @@ proxyBypassHosts: # queue: error # queue.deliver: debug # db.sql: off +# # HTTP status classes to record in the access log. No output when unspecified. +# access: +# statusClasses: +# - '2xx' +# - '3xx' +# - '4xx' +# - '5xx' +# # Enable body logging explicitly only during development. +# bodies: +# request: false +# response: false +# # 16 KiB by default, up to 128 KiB. +# maxBytes: 16384 # sql: # # Outputs query parameters during SQL execution to the log. # # default: false diff --git a/CHANGELOG.md b/CHANGELOG.md index 0d7908a6f9..090e681ab7 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -51,11 +51,12 @@ - 全ての受信HTTPリクエスト - 全ての送信HTTPリクエスト - ジョブキュー(エンキュー元のトレースを含む) -- Feat: ログ基盤の刷新(部分的に導入中) +- Feat: ログ基盤の刷新 - API内部エラーのログに構造化属性と正規化したエラー情報を付与し、認証情報を自動的に秘匿するように(従来形式の表示は維持) - ログ全体の既定出力レベルとドメインごとの出力レベルを設定できるように - バックエンドのログを1行JSON形式で出力できるように - OpenTelemetryのTrace ContextをJSON形式のログへ関連付けられるように + - HTTPのAccess logをstatus class単位で出力できるように(開発時のリクエスト・レスポンス本文、OpenTelemetryのTrace Contextにも対応) - Enhance: Sentry バックエンドの自動計装を `sentryForBackend.disabledIntegrations` で個別に無効化できるように - Enhance: センシティブメディアの判定を外部サービス ([sensitive-detector](https://github.com/misskey-dev/sensitive-detector)) に分離し、`nsfwjs` / `@tensorflow/tfjs(-node)` の同梱と NSFW 判定モデルを廃止 (#16804) - Enhance: Node.js 22.22.2以降、24.17.0以降、26.4.0以降をサポートするように diff --git a/packages/backend/src/config.ts b/packages/backend/src/config.ts index 9b49a48dd3..66540ae1d1 100644 --- a/packages/backend/src/config.ts +++ b/packages/backend/src/config.ts @@ -10,7 +10,7 @@ import { type FastifyServerOptions } from 'fastify'; import type * as Sentry from '@sentry/node'; import type * as SentryVue from '@sentry/vue'; import type { RedisOptions } from 'ioredis'; -import type { LogFormat, LogLevelSetting } from './logging/types.js'; +import type { AccessLogConfiguration, LogFormat, LogLevelSetting } from './logging/types.js'; type RedisOptionsSource = Partial & { host: string; @@ -136,6 +136,7 @@ type Source = { format?: LogFormat; level?: LogLevelSetting; domains?: Record | null; + access?: AccessLogConfiguration; sql?: { disableQueryTruncation?: boolean, enableQueryParamLogging?: boolean, @@ -201,6 +202,7 @@ export type Config = { format?: LogFormat; level?: LogLevelSetting; domains?: Record | null; + access?: AccessLogConfiguration; sql?: { disableQueryTruncation?: boolean, enableQueryParamLogging?: boolean, diff --git a/packages/backend/src/logging/BootstrapConsoleBackend.ts b/packages/backend/src/logging/BootstrapConsoleBackend.ts index b6b033c8b6..42016acef6 100644 --- a/packages/backend/src/logging/BootstrapConsoleBackend.ts +++ b/packages/backend/src/logging/BootstrapConsoleBackend.ts @@ -4,7 +4,7 @@ */ import type { LogBackend } from './LogBackend.js'; -import type { LogRecord } from './types.js'; +import type { AccessLogRecord, LogRecord } from './types.js'; /** 設定読込前の最小出力処理が外部から受け取る依存関係です。 */ export type BootstrapConsoleBackendDependencies = { @@ -46,4 +46,9 @@ export class BootstrapConsoleBackend implements LogBackend { this.dependencies.output(...args); } + + /** 設定前のAccess logは本文を含めず、最小限の情報だけを出力します。 */ + public writeAccess(record: AccessLogRecord): void { + this.dependencies.output(`${record.timestamp} ACCESS ${record.method} ${record.route ?? '-'} ${record.statusCode}`); + } } diff --git a/packages/backend/src/logging/JsonConsoleBackend.ts b/packages/backend/src/logging/JsonConsoleBackend.ts index 664ffd882d..fe6f8f0e2b 100644 --- a/packages/backend/src/logging/JsonConsoleBackend.ts +++ b/packages/backend/src/logging/JsonConsoleBackend.ts @@ -4,7 +4,7 @@ */ import type { LogBackend } from './LogBackend.js'; -import type { LogRecord } from './types.js'; +import type { AccessLogRecord, LogRecord } from './types.js'; /** JSON形式のログを1行で出力する処理が外部から受け取る依存関係です。 */ export type JsonConsoleBackendDependencies = { @@ -28,6 +28,26 @@ type JsonLogRecord = { readonly trace_flags?: number; }; +/** Access logのJSON出力項目です。通常ログと混同しない形を保ちます。 */ +type JsonAccessLogRecord = { + readonly type: 'access'; + readonly timestamp: string; + readonly method: string; + readonly route: string | null; + readonly statusCode: number; + readonly durationMs: number; + readonly responseSizeBytes: number | null; + readonly errorType?: string; + readonly requestBody?: AccessLogRecord['requestBody']; + readonly responseBody?: AccessLogRecord['responseBody']; + readonly processId: number; + readonly isPrimary: boolean; + readonly workerId: number | null; + readonly trace_id?: string; + readonly span_id?: string; + readonly trace_flags?: number; +}; + const defaultDependencies: JsonConsoleBackendDependencies = { output: line => console.log(line), }; @@ -55,6 +75,28 @@ function createJsonLogRecord(record: LogRecord): JsonLogRecord { }; } +/** Access logから公開する項目だけを選び、1行JSONの形へ整えます。 */ +function createJsonAccessLogRecord(record: AccessLogRecord): JsonAccessLogRecord { + return { + type: 'access', + timestamp: record.timestamp, + method: record.method, + route: record.route, + statusCode: record.statusCode, + durationMs: record.durationMs, + responseSizeBytes: record.responseSizeBytes, + ...(record.errorType != null ? { errorType: record.errorType } : {}), + ...(record.requestBody !== undefined ? { requestBody: record.requestBody } : {}), + ...(record.responseBody !== undefined ? { responseBody: record.responseBody } : {}), + processId: record.processId, + isPrimary: record.isPrimary, + workerId: record.workerId, + ...(record.traceId != null ? { trace_id: record.traceId } : {}), + ...(record.spanId != null ? { span_id: record.spanId } : {}), + ...(record.traceFlags != null ? { trace_flags: record.traceFlags } : {}), + }; +} + /** * LogRecordを1行のJSONへ変換し、ログ収集基盤が扱える標準出力へ渡します。 * LoggerやLogManagerから出力形式を切り離し、Pretty形式と同じ記録を共有します。 @@ -75,4 +117,10 @@ export class JsonConsoleBackend implements LogBackend { // JSON.stringifyが改行などをエスケープするため、1ログ1行の契約を保てます。 this.dependencies.output(JSON.stringify(createJsonLogRecord(record))); } + + /** Access logを1行JSONとして出力します。本文は設定で有効化された場合のみ、秘匿処理済みで含まれます。 */ + public writeAccess(record: AccessLogRecord): void { + // JSON.stringifyが改行をエスケープするため、1件を1物理行に保ちます。 + this.dependencies.output(JSON.stringify(createJsonAccessLogRecord(record))); + } } diff --git a/packages/backend/src/logging/LogBackend.ts b/packages/backend/src/logging/LogBackend.ts index 36d2a60bb6..0b79effe7f 100644 --- a/packages/backend/src/logging/LogBackend.ts +++ b/packages/backend/src/logging/LogBackend.ts @@ -3,7 +3,7 @@ * SPDX-License-Identifier: AGPL-3.0-only */ -import type { LogRecord } from './types.js'; +import type { AccessLogRecord, LogRecord } from './types.js'; /** * 整形済みのログを実際の出力先へ渡すための共通窓口です。 @@ -13,6 +13,9 @@ export interface LogBackend { /** ログを一件出力します。 */ write(record: LogRecord): void; + /** Access logを一件出力します。 */ + writeAccess?(record: AccessLogRecord): void; + /** 保留中の出力がある場合に、すべて書き出します。 */ flush?(): void | Promise; diff --git a/packages/backend/src/logging/LogManager.ts b/packages/backend/src/logging/LogManager.ts index b4381dd084..ef78f97bfe 100644 --- a/packages/backend/src/logging/LogManager.ts +++ b/packages/backend/src/logging/LogManager.ts @@ -9,11 +9,23 @@ import { envOption } from '@/env.js'; import { findLegacyLogError, normalizeLogAttributes, + normalizeLogValue, serializeLogError, type LogNormalizationProfile, } from './LogNormalizer.js'; import type { LogBackend } from './LogBackend.js'; -import type { LogLevel, LogLevelSetting, LogRecord, LogRecordInput, LogTraceContextProvider } from './types.js'; +import type { + AccessLogConfiguration, + AccessLogRecord, + AccessLogRecordInput, + AccessLogStatusClass, + LogLevel, + LogLevelSetting, + LogRecord, + LogRecordInput, + LogTraceContext, + LogTraceContextProvider, +} from './types.js'; /** ログを出力したプロセスを識別するための情報です。 */ export type LogProcessInfo = { @@ -43,6 +55,17 @@ export type LogManagerOptions = { export type LogManagerConfiguration = { readonly level?: LogLevelSetting; readonly domains?: Readonly> | null; + readonly access?: AccessLogConfiguration; +}; + +/** 正規化済みのAccess log設定です。 */ +export type ResolvedAccessLogConfiguration = { + readonly statusClasses: readonly AccessLogStatusClass[]; + readonly bodies: { + readonly request: boolean; + readonly response: boolean; + readonly maxBytes: number; + }; }; const logLevelOrder: Readonly> = { @@ -54,6 +77,9 @@ const logLevelOrder: Readonly> = { }; const validLogLevels = new Set(['debug', 'info', 'warn', 'error', 'fatal', 'off']); +const validAccessStatusClasses = new Set(['2xx', '3xx', '4xx', '5xx']); +const defaultAccessBodyMaxBytes = 16 * 1024; +const maxAccessBodyBytes = 128 * 1024; function validateLogLevel(value: unknown, path: string): LogLevelSetting | undefined { if (typeof value === 'undefined') return undefined; @@ -69,14 +95,96 @@ function validateDomainName(domain: string): void { } } -function resolveConfiguration(configuration: LogManagerConfiguration | undefined): { +/** Access logを明示的に有効化していない場合の設定を作成します。 */ +function createDisabledAccessLogConfiguration(): ResolvedAccessLogConfiguration { + return { + statusClasses: [], + bodies: { + request: false, + response: false, + maxBytes: defaultAccessBodyMaxBytes, + }, + }; +} + +/** Access log設定を検証し、本番環境では本文だけを無効化します。 */ +function resolveAccessConfiguration(configuration: unknown, nodeEnv: string | undefined): { + readonly access: ResolvedAccessLogConfiguration; + readonly warnings: readonly string[]; +} { + if (configuration == null) return { access: createDisabledAccessLogConfiguration(), warnings: [] }; + if (typeof configuration !== 'object' || Array.isArray(configuration)) { + throw new Error('logging.access must be an object'); + } + + const raw = configuration as { + statusClasses?: unknown; + bodies?: unknown; + }; + let statusClasses: AccessLogStatusClass[] = []; + if (typeof raw.statusClasses !== 'undefined') { + if (!Array.isArray(raw.statusClasses)) { + throw new Error('logging.access.statusClasses must be an array'); + } + statusClasses = [...new Set(raw.statusClasses.map((statusClass, index) => { + if (typeof statusClass !== 'string' || !validAccessStatusClasses.has(statusClass as AccessLogStatusClass)) { + throw new Error(`logging.access.statusClasses[${index}] must be one of 2xx, 3xx, 4xx, or 5xx`); + } + return statusClass as AccessLogStatusClass; + }))]; + } + + let request = false; + let response = false; + let maxBytes = defaultAccessBodyMaxBytes; + if (typeof raw.bodies !== 'undefined') { + if (typeof raw.bodies !== 'object' || raw.bodies === null || Array.isArray(raw.bodies)) { + throw new Error('logging.access.bodies must be an object'); + } + const bodies = raw.bodies as { request?: unknown; response?: unknown; maxBytes?: unknown }; + if (typeof bodies.request !== 'undefined' && typeof bodies.request !== 'boolean') { + throw new Error('logging.access.bodies.request must be a boolean'); + } + if (typeof bodies.response !== 'undefined' && typeof bodies.response !== 'boolean') { + throw new Error('logging.access.bodies.response must be a boolean'); + } + const configuredMaxBytes = bodies.maxBytes; + if (typeof configuredMaxBytes !== 'undefined' && (typeof configuredMaxBytes !== 'number' || !Number.isSafeInteger(configuredMaxBytes) || configuredMaxBytes <= 0 || configuredMaxBytes > maxAccessBodyBytes)) { + throw new Error(`logging.access.bodies.maxBytes must be a positive integer no greater than ${maxAccessBodyBytes}`); + } + request = bodies.request ?? false; + response = bodies.response ?? false; + maxBytes = typeof configuredMaxBytes === 'number' ? configuredMaxBytes : defaultAccessBodyMaxBytes; + } + + if (nodeEnv === 'production' && (request || response)) { + return { + access: { + statusClasses, + bodies: { request: false, response: false, maxBytes }, + }, + warnings: ['logging.access.bodies is disabled in production mode'], + }; + } + + return { + access: { statusClasses, bodies: { request, response, maxBytes } }, + warnings: [], + }; +} + +/** 通常ログとAccess logの設定をまとめて検証し、起動時警告も返します。 */ +function resolveConfiguration(configuration: LogManagerConfiguration | undefined, nodeEnv: string | undefined): { readonly level: LogLevelSetting | undefined; readonly domains: readonly (readonly [string, LogLevelSetting])[]; + readonly access: ResolvedAccessLogConfiguration; + readonly warnings: readonly string[]; } { - if (configuration == null) return { level: undefined, domains: [] }; + if (configuration == null) return { level: undefined, domains: [], access: createDisabledAccessLogConfiguration(), warnings: [] }; const level = validateLogLevel(configuration.level, 'logging.level'); - if (configuration.domains == null) return { level, domains: [] }; + const access = resolveAccessConfiguration(configuration.access, nodeEnv); + if (configuration.domains == null) return { level, domains: [], ...access }; if (typeof configuration.domains !== 'object' || configuration.domains === null || Array.isArray(configuration.domains)) { throw new Error('logging.domains must be an object'); } @@ -90,7 +198,7 @@ function resolveConfiguration(configuration: LogManagerConfiguration | undefined return [domain, level] as const; }).sort((left, right) => right[0].length - left[0].length); - return { level, domains }; + return { level, domains, ...access }; } const defaultDependencies: LogManagerDependencies = { @@ -116,6 +224,7 @@ export class LogManager { private traceContextProvider: LogTraceContextProvider | undefined; private configuredLevel: LogLevelSetting | undefined; private configuredDomains: readonly (readonly [string, LogLevelSetting])[]; + private accessConfiguration: ResolvedAccessLogConfiguration; private shutdownPromise: Promise | undefined; /** @@ -136,6 +245,7 @@ export class LogManager { this.traceContextProvider = undefined; this.configuredLevel = undefined; this.configuredDomains = []; + this.accessConfiguration = createDisabledAccessLogConfiguration(); } /** @@ -147,10 +257,17 @@ export class LogManager { } /** 起動時の既定levelとdomain別levelを適用します。 */ - public configure(configuration?: LogManagerConfiguration): void { - const resolved = resolveConfiguration(configuration); + public configure(configuration?: LogManagerConfiguration): readonly string[] { + const resolved = resolveConfiguration(configuration, this.dependencies.getNodeEnv()); this.configuredLevel = resolved.level; this.configuredDomains = resolved.domains; + this.accessConfiguration = resolved.access; + return resolved.warnings; + } + + /** Fastifyフックが参照する正規化済みのAccess log設定を返します。 */ + public getAccessLogConfiguration(): ResolvedAccessLogConfiguration { + return this.accessConfiguration; } /** 正規化方式を切り替え、既に作成済みのLoggerにも反映します。 */ @@ -163,6 +280,11 @@ export class LogManager { this.traceContextProvider = provider; } + /** 現在の処理に紐付くTrace Contextを取得します。 */ + public getActiveTraceContext(): LogTraceContext | undefined { + return this.traceContextProvider?.(); + } + /** backendに残っているログをflushしてから終了処理を行います。 */ public shutdown(): Promise { if (this.shutdownPromise != null) return this.shutdownPromise; @@ -244,4 +366,49 @@ export class LogManager { this.backend.write(record); } + + /** status classの設定を確認し、Access logの出力対象か判断します。 */ + public shouldWriteAccess(statusCode: number): boolean { + if (this.dependencies.isQuiet()) return false; + const statusClass = `${Math.floor(statusCode / 100)}xx` as AccessLogStatusClass; + return validAccessStatusClasses.has(statusClass) && this.accessConfiguration.statusClasses.includes(statusClass); + } + + /** Access logのフック自体を登録してよい状態か、quietを含めて判定します。 */ + public isAccessLogEnabled(): boolean { + return !this.dependencies.isQuiet() && this.accessConfiguration.statusClasses.length > 0; + } + + /** HTTP応答へ共通情報と本文の安全な正規化を加えてAccess logを渡します。 */ + public writeAccess(input: AccessLogRecordInput): void { + if (!this.shouldWriteAccess(input.statusCode)) return; + + const processInfo = this.dependencies.getProcessInfo(); + const { requestBody, responseBody, traceContext, ...inputWithoutOptionalValues } = input; + const bodyOptions = { + profile: this.normalizationProfile, + limits: { maxBytes: this.accessConfiguration.bodies.maxBytes }, + } as const; + const normalizedRequestBody = this.accessConfiguration.bodies.request && typeof requestBody !== 'undefined' + ? normalizeLogValue(requestBody, bodyOptions) + : undefined; + const normalizedResponseBody = this.accessConfiguration.bodies.response && typeof responseBody !== 'undefined' + ? normalizeLogValue(responseBody, bodyOptions) + : undefined; + // HTTPフックが開始時に保持したContextだけを使い、応答時に別のSpanを紐付けません。 + const resolvedTraceContext = traceContext; + const record: AccessLogRecord = { + type: 'access', + ...inputWithoutOptionalValues, + timestamp: this.dependencies.now().toISOString(), + processId: processInfo.processId, + isPrimary: processInfo.isPrimary, + workerId: processInfo.workerId, + ...(typeof normalizedRequestBody !== 'undefined' ? { requestBody: normalizedRequestBody } : {}), + ...(typeof normalizedResponseBody !== 'undefined' ? { responseBody: normalizedResponseBody } : {}), + ...(resolvedTraceContext ?? {}), + }; + + this.backend.writeAccess?.(record); + } } diff --git a/packages/backend/src/logging/LogNormalizer.ts b/packages/backend/src/logging/LogNormalizer.ts index aa3d1360a7..f020c3defc 100644 --- a/packages/backend/src/logging/LogNormalizer.ts +++ b/packages/backend/src/logging/LogNormalizer.ts @@ -60,6 +60,7 @@ const sensitiveKeyParts = [ 'apikey', 'privatekey', 'credential', + 'captcha', 'hcaptcharesponse', 'grecaptcharesponse', 'turnstileresponse', @@ -290,6 +291,14 @@ export function normalizeLogAttributes(value: unknown, options: LogNormalization return trimToByteLimit(root as LogAttributes, limits.maxBytes) as LogAttributes; } +/** 本文など単独の値を、既存ログと同じ秘匿・切り詰め規則で正規化します。 */ +export function normalizeLogValue(value: unknown, options: LogNormalizationOptions = {}): LogAttributeValue { + const limits = resolveLogNormalizationLimits(options); + const redactor = options.redactor ?? defaultLogRedactor; + const normalized = normalizeValue(value, [], 0, new WeakSet(), limits, redactor); + return trimToByteLimit(normalized, limits.maxBytes); +} + /** 旧APIのdata領域から、エラー本体を見つけて構造化した形へ渡します。 */ export function findLegacyLogError(value: unknown): unknown { if (isErrorValue(value)) return value; diff --git a/packages/backend/src/logging/PrettyConsoleBackend.ts b/packages/backend/src/logging/PrettyConsoleBackend.ts index 6e9bc313e3..779a6192a1 100644 --- a/packages/backend/src/logging/PrettyConsoleBackend.ts +++ b/packages/backend/src/logging/PrettyConsoleBackend.ts @@ -8,7 +8,7 @@ import { default as convertColor } from 'color-convert'; import { format as dateFormat } from 'date-fns'; import { envOption } from '@/env.js'; import type { LogBackend } from './LogBackend.js'; -import type { LogRecord } from './types.js'; +import type { AccessLogRecord, LogAttributeValue, LogRecord } from './types.js'; /** 見やすい形式の出力処理が外部から受け取る依存関係です。 */ export type PrettyConsoleBackendDependencies = { @@ -21,6 +21,15 @@ const defaultDependencies: PrettyConsoleBackendDependencies = { withLogTime: () => envOption.withLogTime, }; +/** Pretty形式でだけnull prototypeを通常のオブジェクトへ変換し、正規化済みの値自体は変更しません。 */ +function toPrettyLogValue(value: LogAttributeValue): LogAttributeValue { + if (Array.isArray(value)) return value.map(item => toPrettyLogValue(item)); + if (value !== null && typeof value === 'object') { + return Object.fromEntries(Object.entries(value).map(([key, child]) => [key, toPrettyLogValue(child)])); + } + return value; +} + /** * 人が読みやすい従来形式へ整形し、コンソールへ出力します。 * 色、ラベル、時刻などの見た目だけを担当し、出力可否はLogManagerへ任せます。 @@ -87,4 +96,30 @@ export class PrettyConsoleBackend implements LogBackend { } this.dependencies.output(...args); } + + /** Access logを人が読みやすい1行へ整形し、本文は追加情報として表示します。 */ + public writeAccess(record: AccessLogRecord): void { + const statusLevel = record.statusCode >= 500 ? 'error' : record.statusCode >= 400 ? 'warn' : 'info'; + const label = + statusLevel === 'error' ? chalk.red('ERR ') : + statusLevel === 'warn' ? chalk.yellow('WARN') : + chalk.blue('INFO'); + const worker = record.isPrimary ? '*' : record.workerId; + const route = record.route ?? '-'; + const size = record.responseSizeBytes == null ? '-' : `${record.responseSizeBytes}B`; + const message = `${record.method} ${route} ${record.statusCode} ${record.durationMs.toFixed(2)}ms ${size}`; + let log = `${label} ${worker}\t[access]\t${message}`; + if (this.dependencies.withLogTime()) { + log = chalk.gray(dateFormat(new Date(record.timestamp), 'HH:mm:ss')) + ' ' + log; + } + + const details = { + ...(record.errorType != null ? { errorType: record.errorType } : {}), + ...(record.requestBody !== undefined ? { requestBody: toPrettyLogValue(record.requestBody) } : {}), + ...(record.responseBody !== undefined ? { responseBody: toPrettyLogValue(record.responseBody) } : {}), + }; + const args: unknown[] = [log]; + if (Object.keys(details).length > 0) args.push(details); + this.dependencies.output(...args); + } } diff --git a/packages/backend/src/logging/logging-runtime.ts b/packages/backend/src/logging/logging-runtime.ts index bf933c8533..223f6e379e 100644 --- a/packages/backend/src/logging/logging-runtime.ts +++ b/packages/backend/src/logging/logging-runtime.ts @@ -28,8 +28,16 @@ function createLoggingBackend(format: unknown): LogBackend { export function configureLogging(configuration?: LogManagerConfiguration & { readonly format?: LogFormat }): void { // 出力処理を先に検証し、設定値が不正な場合は現在の出力処理を壊さないようにします。 const backend = createLoggingBackend(configuration?.format); - logManager.configure(configuration); + const warnings = logManager.configure(configuration); logManager.setBackend(backend); + // 設定を無視した理由を、選択済みの形式で起動時に一度だけ知らせます。 + for (const message of warnings) { + logManager.write({ + level: 'warn', + message, + context: [{ name: 'logging' }], + }); + } } /** Telemetry初期化後に、ログへTrace Contextを付加する取得処理を登録します。 */ diff --git a/packages/backend/src/logging/types.ts b/packages/backend/src/logging/types.ts index bab86e5b04..7f122364cc 100644 --- a/packages/backend/src/logging/types.ts +++ b/packages/backend/src/logging/types.ts @@ -14,6 +14,22 @@ export type LogLevelSetting = LogLevel | 'off'; /** コンソールへ出すログ形式です。未指定時は見やすい形式を使用します。 */ export type LogFormat = 'pretty' | 'json'; +/** Access logで対象にできるHTTP status classです。 */ +export type AccessLogStatusClass = '2xx' | '3xx' | '4xx' | '5xx'; + +/** Access logの本文採取設定です。 */ +export type AccessLogBodyConfiguration = { + readonly request?: boolean; + readonly response?: boolean; + readonly maxBytes?: number; +}; + +/** Access logの出力設定です。 */ +export type AccessLogConfiguration = { + readonly statusClasses?: readonly AccessLogStatusClass[]; + readonly bodies?: AccessLogBodyConfiguration; +}; + /** 正規化後にログ属性として扱えるJSONの値です。 */ export type LogAttributeValue = | string @@ -97,3 +113,30 @@ export type LogRecord = Omit & { readonly attributes?: LogAttributes; readonly error?: SerializedError; }; + +/** Access logとして記録するHTTP応答の入力です。 */ +export type AccessLogRecordInput = { + readonly method: string; + readonly route: string | null; + readonly statusCode: number; + readonly durationMs: number; + readonly responseSizeBytes: number | null; + readonly errorType?: string; + readonly requestBody?: unknown; + readonly responseBody?: unknown; + readonly traceContext?: LogTraceContext; +}; + +/** 出力先へ渡すAccess logです。本文は正規化後の値だけを含みます。 */ +export type AccessLogRecord = Omit & { + readonly type: 'access'; + readonly timestamp: string; + readonly processId: number; + readonly isPrimary: boolean; + readonly workerId: number | null; + readonly requestBody?: LogAttributeValue; + readonly responseBody?: LogAttributeValue; + readonly traceId?: string; + readonly spanId?: string; + readonly traceFlags?: number; +}; diff --git a/packages/backend/src/server/ServerService.ts b/packages/backend/src/server/ServerService.ts index 45ce830b29..522d6e2b71 100644 --- a/packages/backend/src/server/ServerService.ts +++ b/packages/backend/src/server/ServerService.ts @@ -33,6 +33,7 @@ import { ClientServerService } from './web/ClientServerService.js'; import { OpenApiServerService } from './api/openapi/OpenApiServerService.js'; import { OAuth2ProviderService } from './oauth/OAuth2ProviderService.js'; import { registerHttpServerInstrumentation } from './http-server-instrumentation.js'; +import { registerHttpAccessLog } from './http-access-log.js'; const _dirname = fileURLToPath(new URL('.', import.meta.url)); @@ -82,6 +83,7 @@ export class ServerService implements OnApplicationShutdown { }); this.#fastify = fastify; await registerHttpServerInstrumentation(fastify, this.config); + registerHttpAccessLog(fastify); // HSTS // 6months (15552000sec) diff --git a/packages/backend/src/server/http-access-log.ts b/packages/backend/src/server/http-access-log.ts new file mode 100644 index 0000000000..93b61aaf9d --- /dev/null +++ b/packages/backend/src/server/http-access-log.ts @@ -0,0 +1,182 @@ +/* + * SPDX-FileCopyrightText: syuilo and misskey-project + * SPDX-License-Identifier: AGPL-3.0-only + */ + +import { Buffer } from 'node:buffer'; +import type { FastifyInstance } from 'fastify'; +import { logManager } from '@/logging/logging-runtime.js'; +import type { LogManager } from '@/logging/LogManager.js'; +import type { LogTraceContext } from '@/logging/types.js'; + +type AccessRequestState = { + traceContext?: LogTraceContext; + errorType?: string; + requestBody?: unknown; + responseBody?: unknown; +}; + +type CapturedBody = { + value: unknown; +}; + +/** Content-Typeから本文の種類だけを取り出します。 */ +function getMediaType(value: string | string[] | number | undefined): string | undefined { + const first = Array.isArray(value) ? value[0] : value; + return typeof first === 'string' ? first.split(';', 1)[0].trim().toLowerCase() : undefined; +} + +/** 秘匿処理を適用できるJSON・form・text本文か判定します。 */ +function isSupportedMediaType(value: string | undefined): boolean { + return value === 'application/json' + || (value?.startsWith('application/') === true && value.endsWith('+json')) + || value === 'application/x-www-form-urlencoded' + || (value?.startsWith('text/') === true && value !== 'text/event-stream'); +} + +/** application/jsonとapplication/*+jsonを構造化対象として判定します。 */ +function isJsonMediaType(value: string | undefined): boolean { + return value === 'application/json' + || (value?.startsWith('application/') === true && value.endsWith('+json')); +} + +/** Streamやバイナリを本文ログの対象から外します。 */ +function isStream(value: unknown): boolean { + if (typeof value !== 'object' || value === null) return false; + try { + const candidate = value as { + pipe?: unknown; + getReader?: unknown; + [Symbol.asyncIterator]?: unknown; + }; + return typeof candidate.pipe === 'function' + || typeof candidate.getReader === 'function' + || typeof candidate[Symbol.asyncIterator] === 'function'; + } catch { + // 本文のgetterが壊れていても、ログ処理が応答を失敗させないよう除外します。 + return true; + } +} + +/** JSON文字列を構造化し、解析できない場合は元の文字列を保持します。 */ +function parseJsonBody(value: string): unknown { + try { + return JSON.parse(value); + } catch { + return value; + } +} + +/** form本文を項目ごとの値へ分解し、キー単位の秘匿処理を可能にします。 */ +function parseFormBody(value: string): Record { + const result: Record = Object.create(null) as Record; + for (const [key, item] of new URLSearchParams(value)) { + const previous = result[key]; + result[key] = typeof previous === 'undefined' + ? item + : Array.isArray(previous) ? [...previous, item] : [previous, item]; + } + return result; +} + +/** 送受信本文から、ログへ渡せる値だけを取り出します。 */ +function captureBody(value: unknown, contentType: string | string[] | number | undefined): CapturedBody | undefined { + const mediaType = getMediaType(contentType); + if (!isSupportedMediaType(mediaType) || isStream(value)) return undefined; + + if (isJsonMediaType(mediaType)) { + if (typeof value === 'string') return { value: parseJsonBody(value) }; + if (Buffer.isBuffer(value)) return { value: parseJsonBody(value.toString('utf8')) }; + return { value }; + } + + if (mediaType === 'application/x-www-form-urlencoded') { + if (typeof value === 'string') return { value: parseFormBody(value) }; + if (Buffer.isBuffer(value)) return { value: parseFormBody(value.toString('utf8')) }; + } + if (typeof value === 'string') return { value }; + if (Buffer.isBuffer(value)) return { value: value.toString('utf8') }; + // form parserなどが返す構造化済みの本文も、通常の正規化処理へ渡します。 + if (typeof value === 'object' && value !== null) return { value }; + return undefined; +} + +/** Errorから本文を含めない型名だけを取り出します。 */ +function getErrorType(error: unknown): string { + if (typeof error === 'object' && error !== null && typeof (error as { name?: unknown }).name === 'string') { + const name = (error as { name: string }).name; + if (name.length > 0) return name; + } + return 'Error'; +} + +/** content-lengthを安全なバイト数へ変換し、未知の応答ではnullを返します。 */ +function getResponseSize(value: string | string[] | number | undefined): number | null { + const first = Array.isArray(value) ? value[0] : value; + const size = typeof first === 'number' ? first : typeof first === 'string' && /^\d+$/.test(first) ? Number(first) : NaN; + return Number.isSafeInteger(size) && size >= 0 ? size : null; +} + +/** Fastify全体へAccess log用のリクエスト・エラー・応答フックを登録します。 */ +export function registerHttpAccessLog(fastify: FastifyInstance, manager: LogManager = logManager): void { + if (!manager.isAccessLogEnabled()) return; + + const states = new WeakMap(); + + // HTTP計装の後に登録し、リクエスト開始時のactiveなTrace Contextを保存します。 + fastify.addHook('onRequest', (request, _reply, done) => { + states.set(request, { + traceContext: manager.getActiveTraceContext(), + }); + done(); + }); + + // Fastifyが応答へ変換したErrorから、型名だけをリクエストへ一時保存します。 + fastify.addHook('onError', (request, _reply, error, done) => { + const state = states.get(request) ?? {}; + state.errorType = getErrorType(error); + states.set(request, state); + done(); + }); + + // 送信前のpayloadを読み取りますが、元の値は変更せず、そのまま次のhookへ渡します。 + fastify.addHook('onSend', (request, reply, payload, done) => { + if (!manager.shouldWriteAccess(reply.statusCode)) { + done(null, payload); + return; + } + + const bodyConfiguration = manager.getAccessLogConfiguration().bodies; + const state = states.get(request) ?? {}; + if (bodyConfiguration.request && !('requestBody' in state)) { + // ActivityPubもFastifyが解析したrequest.bodyだけを対象にし、rawBodyやheaderは参照しません。 + const captured = captureBody(request.body, request.headers['content-type']); + if (captured !== undefined) state.requestBody = captured.value; + } + if (bodyConfiguration.response && !('responseBody' in state)) { + const captured = captureBody(payload, reply.getHeader('content-type')); + if (captured !== undefined) state.responseBody = captured.value; + } + states.set(request, state); + done(null, payload); + }); + + // 応答完了時にFastifyの値を集め、LogManagerへAccess logを渡します。 + fastify.addHook('onResponse', (request, reply, done) => { + const state = states.get(request); + const input = { + method: request.method, + route: request.routeOptions.url ?? null, + statusCode: reply.statusCode, + durationMs: reply.elapsedTime, + responseSizeBytes: getResponseSize(reply.getHeader('content-length')), + ...(state?.errorType !== undefined ? { errorType: state.errorType } : {}), + ...(state != null && 'requestBody' in state ? { requestBody: state.requestBody } : {}), + ...(state != null && 'responseBody' in state ? { responseBody: state.responseBody } : {}), + ...(state?.traceContext !== undefined ? { traceContext: state.traceContext } : {}), + }; + manager.writeAccess(input); + states.delete(request); + done(); + }); +} diff --git a/packages/backend/test/unit/logging/JsonConsoleBackend.ts b/packages/backend/test/unit/logging/JsonConsoleBackend.ts index c9cbf998cd..67ca71fcc3 100644 --- a/packages/backend/test/unit/logging/JsonConsoleBackend.ts +++ b/packages/backend/test/unit/logging/JsonConsoleBackend.ts @@ -4,7 +4,7 @@ */ import { describe, expect, test, vi } from 'vitest'; -import type { LogRecord } from '@/logging/types.js'; +import type { AccessLogRecord, LogRecord } from '@/logging/types.js'; import { JsonConsoleBackend } from '@/logging/JsonConsoleBackend.js'; /** JSON形式のテストで使う共通のログを作成します。 */ @@ -23,6 +23,48 @@ function createRecord(overrides: Partial = {}): LogRecord { } describe('JsonConsoleBackend', () => { + test('writes Access log as a separate one-line schema', () => { + const output = vi.fn<(line: string) => void>(); + const backend = new JsonConsoleBackend({ output }); + const record: AccessLogRecord = { + type: 'access', + timestamp: '2025-01-02T03:04:05.678Z', + method: 'GET', + route: '/items/:id', + statusCode: 500, + durationMs: 12.5, + responseSizeBytes: null, + errorType: 'TypeError', + requestBody: { token: '[REDACTED]' }, + processId: 1234, + isPrimary: true, + workerId: null, + traceId: 'trace', + spanId: 'span', + traceFlags: 1, + }; + + backend.writeAccess(record); + + expect(JSON.parse(output.mock.calls[0][0])).toEqual({ + type: 'access', + timestamp: '2025-01-02T03:04:05.678Z', + method: 'GET', + route: '/items/:id', + statusCode: 500, + durationMs: 12.5, + responseSizeBytes: null, + errorType: 'TypeError', + requestBody: { token: '[REDACTED]' }, + processId: 1234, + isPrimary: true, + workerId: null, + trace_id: 'trace', + span_id: 'span', + trace_flags: 1, + }); + }); + test('writes a stable one-line JSON record', () => { const output = vi.fn<(line: string) => void>(); const backend = new JsonConsoleBackend({ output }); diff --git a/packages/backend/test/unit/logging/LogManager.ts b/packages/backend/test/unit/logging/LogManager.ts index 5695b34837..94880856a1 100644 --- a/packages/backend/test/unit/logging/LogManager.ts +++ b/packages/backend/test/unit/logging/LogManager.ts @@ -5,7 +5,7 @@ import { describe, expect, test, vi } from 'vitest'; import type { LogBackend } from '@/logging/LogBackend.js'; -import type { LogRecordInput, LogTraceContext } from '@/logging/types.js'; +import type { AccessLogRecord, AccessLogRecordInput, LogRecordInput, LogTraceContext } from '@/logging/types.js'; import { LogManager } from '@/logging/LogManager.js'; /** テストで使う最小構成のログ入力を作成します。 */ @@ -31,10 +31,15 @@ function createManager(options: { configuration?: { level?: 'debug' | 'info' | 'warn' | 'error' | 'fatal' | 'off'; domains?: Record; + access?: { + statusClasses?: ('2xx' | '3xx' | '4xx' | '5xx')[]; + bodies?: { request?: boolean; response?: boolean; maxBytes?: number }; + }; }; } = {}) { const write = vi.fn(); - const manager = new LogManager({ write }, { + const writeAccess = vi.fn<(record: AccessLogRecord) => void>(); + const manager = new LogManager({ write, writeAccess }, { now: () => new Date('2025-01-02T03:04:05.678Z'), getProcessInfo: () => ({ processId: 1234, @@ -49,7 +54,7 @@ function createManager(options: { }); if (options.configuration) manager.configure(options.configuration); - return { manager, write }; + return { manager, write, writeAccess }; } describe('LogManager', () => { @@ -221,6 +226,89 @@ describe('LogManager', () => { 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'); + expect(() => manager.configure({ access: { statusClasses: ['1xx' as never] } })).toThrow('statusClasses'); + expect(() => manager.configure({ access: { statusClasses: '4xx' as never } })).toThrow('statusClasses'); + expect(() => manager.configure({ access: { bodies: null as never } })).toThrow('bodies'); + expect(() => manager.configure({ access: { bodies: { maxBytes: 0 } } })).toThrow('maxBytes'); + expect(() => manager.configure({ access: { bodies: { maxBytes: 1.5 } } })).toThrow('maxBytes'); + expect(() => manager.configure({ access: { bodies: { maxBytes: 128 * 1024 + 1 } } })).toThrow('maxBytes'); + }); + + test('filters Access log by status class and keeps it independent from application level', () => { + const { manager, write, writeAccess } = createManager({ configuration: { level: 'off', access: { statusClasses: ['4xx', '5xx'] } } }); + const input: AccessLogRecordInput = { + method: 'GET', + route: '/items/:id', + statusCode: 200, + durationMs: 1, + responseSizeBytes: 10, + }; + + manager.writeAccess(input); + manager.writeAccess({ ...input, statusCode: 404 }); + manager.writeAccess({ ...input, statusCode: 500 }); + + expect(write).not.toHaveBeenCalled(); + expect(writeAccess).toHaveBeenCalledTimes(2); + expect(writeAccess.mock.calls[0][0]).toMatchObject({ type: 'access', statusCode: 404, processId: 1234, workerId: null }); + }); + + test('normalizes Access log bodies and keeps captured Trace Context', () => { + const { manager, writeAccess } = createManager({ + configuration: { + access: { + statusClasses: ['2xx'], + bodies: { request: true, response: true, maxBytes: 1024 }, + }, + }, + }); + const input: AccessLogRecordInput = { + method: 'POST', + route: '/body', + statusCode: 200, + durationMs: 2, + responseSizeBytes: 20, + requestBody: { i: 'secret', nested: { password: 'secret' } }, + responseBody: { token: 'secret', value: 'visible' }, + traceContext: { traceId: 'trace', spanId: 'span', traceFlags: 1 }, + }; + + manager.writeAccess(input); + + expect(writeAccess).toHaveBeenCalledWith(expect.objectContaining({ + requestBody: { i: '[REDACTED]', nested: { password: '[REDACTED]' } }, + responseBody: { token: '[REDACTED]', value: 'visible' }, + traceId: 'trace', + spanId: 'span', + })); + }); + + test('does not write Access log by default and preserves the default body limit', () => { + const { manager, writeAccess } = createManager(); + + manager.writeAccess({ + method: 'GET', + route: '/disabled', + statusCode: 200, + durationMs: 1, + responseSizeBytes: null, + }); + + expect(manager.getAccessLogConfiguration().bodies.maxBytes).toBe(16 * 1024); + expect(writeAccess).not.toHaveBeenCalled(); + }); + + test('accepts the maximum configured body limit', () => { + const { manager } = createManager({ + configuration: { + access: { + statusClasses: ['2xx'], + bodies: { maxBytes: 128 * 1024 }, + }, + }, + }); + + expect(manager.getAccessLogConfiguration().bodies.maxBytes).toBe(128 * 1024); }); test('uses a replaced backend for subsequent records', () => { diff --git a/packages/backend/test/unit/logging/LogNormalizer.ts b/packages/backend/test/unit/logging/LogNormalizer.ts index 642887d225..b183f03fcd 100644 --- a/packages/backend/test/unit/logging/LogNormalizer.ts +++ b/packages/backend/test/unit/logging/LogNormalizer.ts @@ -7,6 +7,7 @@ import { describe, expect, test } from 'vitest'; import { findLegacyLogError, normalizeLogAttributes, + normalizeLogValue, serializeLogError, } from '@/logging/LogNormalizer.js'; @@ -25,6 +26,13 @@ describe('LogNormalizer', () => { }); }); + test('normalizes a standalone body value with the same redaction and size rules', () => { + const normalized = normalizeLogValue({ token: 'secret', text: 'x'.repeat(100) }, { limits: { maxBytes: 256 } }); + + expect(normalized).toMatchObject({ token: '[REDACTED]' }); + expect(Buffer.byteLength(JSON.stringify(normalized), 'utf8')).toBeLessThanOrEqual(256); + }); + test('marks unsupported objects and invalid dates without throwing', () => { expect(normalizeLogAttributes({ map: new Map([['key', 'value']]), @@ -49,6 +57,7 @@ describe('LogNormalizer', () => { i: 'top-level-token', request: { Authorization: 'bearer-token', + captcha: 'captcha-value', password: 'password', nested: [{ api_key: 'api-key' }], }, @@ -57,6 +66,7 @@ describe('LogNormalizer', () => { i: '[REDACTED]', request: { Authorization: '[REDACTED]', + captcha: '[REDACTED]', password: '[REDACTED]', nested: [{ api_key: '[REDACTED]' }], }, diff --git a/packages/backend/test/unit/logging/PrettyConsoleBackend.ts b/packages/backend/test/unit/logging/PrettyConsoleBackend.ts index 8002b0a309..004c60f783 100644 --- a/packages/backend/test/unit/logging/PrettyConsoleBackend.ts +++ b/packages/backend/test/unit/logging/PrettyConsoleBackend.ts @@ -4,7 +4,7 @@ */ import { describe, expect, test, vi } from 'vitest'; -import type { LogRecord } from '@/logging/types.js'; +import type { AccessLogRecord, LogRecord } from '@/logging/types.js'; type Formatter = ((value: unknown) => string) & { white?: Formatter }; @@ -50,6 +50,23 @@ function createRecord(overrides: Partial = {}): LogRecord { }; } +/** Access logの表示確認用に、正規化後と同じnull prototypeの本文を作成します。 */ +function createAccessRecord(requestBody: AccessLogRecord['requestBody']): AccessLogRecord { + return { + type: 'access', + timestamp: '2025-01-02T03:04:05.678Z', + method: 'POST', + route: '/api/test', + statusCode: 200, + durationMs: 1, + responseSizeBytes: 10, + requestBody, + processId: 1234, + isPrimary: true, + workerId: null, + }; +} + describe('PrettyConsoleBackend', () => { test.each([ { level: 'error', label: 'ERR ', message: 'message' }, @@ -164,4 +181,23 @@ describe('PrettyConsoleBackend', () => { }, ); }); + + test('shows normalized body maps as regular objects in pretty output', () => { + const output = vi.fn(); + const backend = new PrettyConsoleBackend({ output, withLogTime: () => false }); + const nested = Object.create(null) as Record; + nested.visible = 'value'; + const requestBody = Object.create(null) as Record; + requestBody.nested = nested; + Object.defineProperty(requestBody, '__proto__', { value: 'safe', enumerable: true }); + + backend.writeAccess(createAccessRecord(requestBody as AccessLogRecord['requestBody'])); + + const details = output.mock.calls[0][1] as { requestBody: Record }; + expect(Object.getPrototypeOf(details.requestBody)).toBe(Object.prototype); + expect(Object.getPrototypeOf(details.requestBody.nested)).toBe(Object.prototype); + expect(details.requestBody).toHaveProperty('__proto__', 'safe'); + expect(Object.getPrototypeOf(requestBody)).toBe(null); + expect(Object.getPrototypeOf(nested)).toBe(null); + }); }); diff --git a/packages/backend/test/unit/server/http-access-log.ts b/packages/backend/test/unit/server/http-access-log.ts new file mode 100644 index 0000000000..ddc235a076 --- /dev/null +++ b/packages/backend/test/unit/server/http-access-log.ts @@ -0,0 +1,249 @@ +/* + * SPDX-FileCopyrightText: syuilo and misskey-project + * SPDX-License-Identifier: AGPL-3.0-only + */ + +import { Readable } from 'node:stream'; +import Fastify, { type FastifyInstance } from 'fastify'; +import { afterEach, describe, expect, test, vi } from 'vitest'; +import { LogManager } from '@/logging/LogManager.js'; +import type { AccessLogRecord, AccessLogStatusClass } from '@/logging/types.js'; +import { registerHttpAccessLog } from '@/server/http-access-log.js'; + +type TestServer = { + readonly fastify: FastifyInstance; + readonly manager: LogManager; + readonly writeAccess: ReturnType; +}; + +type TestManager = { + readonly manager: LogManager; + readonly writeAccess: ReturnType; +}; + +/** Access logの動作確認用に固定時刻・プロセス情報を持つManagerを作成します。 */ +function createManager(options: { + statusClasses?: AccessLogStatusClass[]; + requestBody?: boolean; + responseBody?: boolean; + maxBytes?: number; + nodeEnv?: string; + quiet?: boolean; +} = {}): TestManager { + const writeAccess = vi.fn<(record: AccessLogRecord) => void>(); + const manager = new LogManager({ write: vi.fn(), writeAccess }, { + now: () => new Date('2026-07-22T00:00:00.000Z'), + getProcessInfo: () => ({ processId: 123, isPrimary: true, workerId: null }), + isQuiet: () => options.quiet ?? false, + isVerbose: () => false, + getNodeEnv: () => options.nodeEnv ?? 'development', + }); + manager.configure({ + access: { + statusClasses: options.statusClasses ?? ['2xx', '3xx', '4xx', '5xx'], + bodies: { + request: options.requestBody ?? false, + response: options.responseBody ?? false, + maxBytes: options.maxBytes, + }, + }, + }); + return { manager, writeAccess }; +} + +/** Access logフックを登録したテスト用Fastifyを作成します。 */ +async function createServer(options: Parameters[0] = {}): Promise { + const { manager, writeAccess } = createManager(options); + const fastify = Fastify({ logger: false }); + registerHttpAccessLog(fastify, manager); + fastify.get('/items/:id', async () => ({ ok: true })); + fastify.get('/bad', async (_request, reply) => reply.code(400).send({ error: 'bad' })); + fastify.get('/fail', async () => { + throw new TypeError('failure'); + }); + fastify.get('/redirect', async (_request, reply) => reply.redirect('/items/redirect')); + fastify.post('/body', async (request) => ({ echo: request.body, token: 'response-secret' })); + fastify.get('/text', async (_request, reply) => reply.type('text/plain').send('response text')); + fastify.get('/form', async (_request, reply) => reply.type('application/x-www-form-urlencoded').send('i=form-token&password=form-password&visible=yes')); + fastify.get('/binary', async (_request, reply) => reply.type('application/octet-stream').send(Buffer.from('binary'))); + fastify.get('/stream', async (_request, reply) => reply.type('text/plain').send(Readable.from(['stream body']))); + await fastify.ready(); + return { fastify, manager, writeAccess }; +} + +const servers: FastifyInstance[] = []; + +afterEach(async () => { + await Promise.all(servers.splice(0).map(server => server.close())); +}); + +describe('registerHttpAccessLog', () => { + test('filters responses by configured status classes and keeps the route template', async () => { + const server = await createServer({ statusClasses: ['4xx', '5xx'] }); + servers.push(server.fastify); + + await server.fastify.inject({ method: 'GET', url: '/items/secret?id=hidden' }); + await server.fastify.inject({ method: 'GET', url: '/bad' }); + await server.fastify.inject({ method: 'GET', url: '/fail' }); + await server.fastify.inject({ method: 'GET', url: '/missing?token=hidden' }); + + expect(server.writeAccess).toHaveBeenCalledTimes(3); + expect(server.writeAccess.mock.calls.map(call => call[0])).toEqual(expect.arrayContaining([ + expect.objectContaining({ route: '/bad', statusCode: 400 }), + expect.objectContaining({ route: '/fail', statusCode: 500, errorType: 'TypeError' }), + expect.objectContaining({ route: null, statusCode: 404 }), + ])); + expect(server.writeAccess.mock.calls[0][0]).not.toHaveProperty('requestUrl'); + expect(server.writeAccess.mock.calls.find(call => call[0].statusCode === 404)?.[0]).not.toHaveProperty('errorType'); + }); + + test('records redirects and response size when the status class is selected', async () => { + const server = await createServer({ statusClasses: ['3xx'] }); + servers.push(server.fastify); + + await server.fastify.inject({ method: 'GET', url: '/redirect' }); + + expect(server.writeAccess).toHaveBeenCalledWith(expect.objectContaining({ + method: 'GET', + route: '/redirect', + statusCode: 302, + responseSizeBytes: expect.any(Number), + })); + }); + + test('captures and redacts JSON request and response bodies in development', async () => { + const server = await createServer({ requestBody: true, responseBody: true }); + servers.push(server.fastify); + + await server.fastify.inject({ + method: 'POST', + url: '/body', + headers: { 'content-type': 'application/json' }, + payload: { i: 'request-token', nested: { password: 'request-password' }, value: 'visible' }, + }); + + expect(server.writeAccess).toHaveBeenCalledWith(expect.objectContaining({ + requestBody: { + i: '[REDACTED]', + nested: { password: '[REDACTED]' }, + value: 'visible', + }, + responseBody: { + echo: { + i: '[REDACTED]', + nested: { password: '[REDACTED]' }, + value: 'visible', + }, + token: '[REDACTED]', + }, + })); + }); + + test('captures text but omits binary and stream bodies', async () => { + const server = await createServer({ statusClasses: ['2xx'], responseBody: true }); + servers.push(server.fastify); + + await server.fastify.inject({ method: 'GET', url: '/text' }); + await server.fastify.inject({ method: 'GET', url: '/binary' }); + await server.fastify.inject({ method: 'GET', url: '/stream' }); + + expect(server.writeAccess.mock.calls[0][0]).toHaveProperty('responseBody', 'response text'); + expect(server.writeAccess.mock.calls[1][0]).not.toHaveProperty('responseBody'); + expect(server.writeAccess.mock.calls[2][0]).not.toHaveProperty('responseBody'); + }); + + test('parses form bodies before redaction', async () => { + const server = await createServer({ statusClasses: ['2xx'], responseBody: true }); + servers.push(server.fastify); + + await server.fastify.inject({ method: 'GET', url: '/form' }); + + expect(server.writeAccess).toHaveBeenCalledWith(expect.objectContaining({ + responseBody: { + i: '[REDACTED]', + password: '[REDACTED]', + visible: 'yes', + }, + })); + }); + + test('truncates normalized bodies to the configured limit', async () => { + const server = await createServer({ requestBody: true, responseBody: true, maxBytes: 1024 }); + servers.push(server.fastify); + + await server.fastify.inject({ + method: 'POST', + url: '/body', + headers: { 'content-type': 'application/json' }, + payload: { value: 'x'.repeat(20_000) }, + }); + + const record = server.writeAccess.mock.calls[0][0]; + expect(Buffer.byteLength(JSON.stringify(record.requestBody), 'utf8')).toBeLessThanOrEqual(1024); + expect(Buffer.byteLength(JSON.stringify(record.responseBody), 'utf8')).toBeLessThanOrEqual(1024); + }); + + test('preserves the response payload and reports an unknown stream size', async () => { + const server = await createServer({ statusClasses: ['2xx'], responseBody: true }); + servers.push(server.fastify); + + const response = await server.fastify.inject({ method: 'GET', url: '/stream' }); + + expect(response.body).toBe('stream body'); + expect(server.writeAccess).toHaveBeenCalledWith(expect.objectContaining({ responseSizeBytes: null })); + }); + + test('does not capture bodies in production and returns a warning', async () => { + const { manager, writeAccess } = createManager({ nodeEnv: 'production', requestBody: true, responseBody: true }); + const warnings = manager.configure({ access: { statusClasses: ['2xx'], bodies: { request: true, response: true } } }); + const fastify = Fastify({ logger: false }); + registerHttpAccessLog(fastify, manager); + fastify.post('/body', async request => ({ body: request.body })); + await fastify.ready(); + servers.push(fastify); + + await fastify.inject({ method: 'POST', url: '/body', headers: { 'content-type': 'application/json' }, payload: { token: 'hidden' } }); + + expect(warnings).toEqual(['logging.access.bodies is disabled in production mode']); + expect(writeAccess).toHaveBeenCalledWith(expect.not.objectContaining({ requestBody: expect.anything(), responseBody: expect.anything() })); + }); + + test('keeps the request Trace Context through response completion', async () => { + const server = await createServer({ statusClasses: ['2xx'] }); + servers.push(server.fastify); + const traceContext = { traceId: 'trace', spanId: 'span', traceFlags: 1 }; + const provider = vi.fn(() => traceContext); + server.manager.setTraceContextProvider(provider); + + await server.fastify.inject({ method: 'GET', url: '/items/trace' }); + + expect(provider).toHaveBeenCalledOnce(); + expect(server.writeAccess).toHaveBeenCalledWith(expect.objectContaining(traceContext)); + }); + + test('omits a Trace Context that was not active at request start', async () => { + const server = await createServer({ statusClasses: ['2xx'] }); + servers.push(server.fastify); + const provider = vi.fn() + .mockReturnValueOnce(undefined) + .mockReturnValue({ traceId: 'late-trace', spanId: 'late-span', traceFlags: 1 }); + server.manager.setTraceContextProvider(provider); + + await server.fastify.inject({ method: 'GET', url: '/items/no-trace' }); + + expect(server.writeAccess.mock.calls[0][0]).not.toHaveProperty('traceId'); + expect(provider).toHaveBeenCalledOnce(); + }); + + test('does not write in quiet mode', async () => { + const server = await createServer({ quiet: true }); + servers.push(server.fastify); + const provider = vi.fn(() => ({ traceId: 'trace', spanId: 'span', traceFlags: 1 })); + server.manager.setTraceContextProvider(provider); + + await server.fastify.inject({ method: 'GET', url: '/items/quiet' }); + + expect(provider).not.toHaveBeenCalled(); + expect(server.writeAccess).not.toHaveBeenCalled(); + }); +});