diff --git a/AGENTS.md b/AGENTS.md index 1f30887..7ca1af1 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -13,6 +13,10 @@ - 実装完了の条件: 変更したパッケージに対応する CI ワークフロー(`.github/workflows/ci-{api,client,shared,task}.yml`)に書かれているコマンドをローカルで実行し、build/lint/test がエラーなく通ること。CI と異なるコマンドを実行して「通った」と判断しない - 特定の作業をするときだけ必要な詳細ガイドラインは `agents/` 配下に置き、この AGENTS.md からは「いつ読むか」を1行で指す +## Logging Guidelines + +- `logger.*` を呼ぶとき、logger / redact 実装や access log / error handler を変更するときは `agents/logging.md` を読む(console の単一入口、sensitive field の redaction、error の安全な serialize、requestId の引き回し) + ## Monorepo Guidelines - 複数パッケージ(api/bin/client/shared)の実装がたまたま似ていても、それだけを理由に共通化しない(ルートに tsconfig.base.json を作って extends させる、logger/fetcher のような実装コードを shared に抽出する、など) diff --git a/agents/lint-rules.md b/agents/lint-rules.md index 35f0351..0b2ee05 100644 --- a/agents/lint-rules.md +++ b/agents/lint-rules.md @@ -8,6 +8,9 @@ - `coding-style/no-process-env-outside-config` → `process.env` の参照を config ファイル(`config.ts` / `config.server.ts` 等)に集約する(テストファイルは対象外) - `coding-style/enforce-zod-entrypoint` → zod の entrypoint をパッケージごとに強制する(client は `zod/mini`、api は `zod`) +- `coding-style/enforce-logger-literal` → `logger.*` の第1引数と `meta` を object literal(spread / computed key なし)に限定する。何をログへ載せてよいかは logger の closed event schema(型)が決め、lint は excess property check が確実に効く形だけを保証する(テストファイルは runtime の最終防衛を検証するため対象外。詳細は `agents/logging.md`) + +builtin ルールでは `no-console` を `packages/{api,client,task}/src` に対して error にし、logger 実装本体とテストだけ `vite.config.ts` の override で除外している(structured log の単一入口を保つため)。 ルールを追加・変更したら、違反例・準拠例を `lint-rules/run-tests.ts` に追加し、`npm run test-lint-rules` を通すこと(CI では `ci-lint-rules.yml` が実行する)。 diff --git a/agents/logging.md b/agents/logging.md new file mode 100644 index 0000000..a8a3beb --- /dev/null +++ b/agents/logging.md @@ -0,0 +1,11 @@ +# Logging Guidelines + +ログ出力を伴うコード(`logger.*` の呼び出し、logger / redact 実装、access log / error handler)を書くときの原則。機械検査の詳細は `agents/lint-rules.md` を、何を meta へ載せられるかは各 logger の `LogEvents` 型を参照する。 + +- application code は `console.*` を直接呼ばず、パッケージごとの logger(api: `packages/api/src/lib/logger/index.ts`、client: `packages/client/src/app/_lib/logger/index.ts`、task: `packages/task/src/lib/logger/index.ts`)を単一入口にする。dev 専用 CLI(`packages/bin`)は人間が読む出力なので対象外 +- logger の public API は closed event schema。meta を持てるのは各 logger の `LogEvents` に定義した label だけで、field は primitive のみ。新しい情報をログへ載せたいときは、値を渡す前に `LogEvents` へ label / field を追加する +- `LogEvents` に secret / credential(authorization / cookie / token 等)を表す field や、request / response / headers / body を丸ごと表す field を追加しない。必要な primitive field だけを schema に起こす +- 何を渡してよいかの判断は型に寄せる。型検査に失敗する値を assertion で無理に通さない。runtime の `redactMeta()`(sensitive key 名 → `[REDACTED]`、primitive 以外 → `[UNSUPPORTED]`)は型をすり抜けた値への最後の防波堤であって、設計上の免罪符ではない +- `error` は `serializeError()` が name / message / stack / cause の限定 shape へ変換する。`{ ...error }` のような spread は、external SDK が enumerable property に詰めた credential / request payload を持ち出すため行わない +- `requestId` で access log と application log を突き合わせる。api では `accessLogMiddleware` が発行した値を `c.get('requestId')` から渡す。client / task は追跡したい単位の ID を呼び出し側が明示的に渡す +- `logger/` は api / client / task がそれぞれ自己完結して持ち、shared へ切り出さない。実行コンテキストが異なるため(AGENTS.md の Monorepo Guidelines) diff --git a/lint-rules/coding-style.ts b/lint-rules/coding-style.ts index ee5dcd6..30449fd 100644 --- a/lint-rules/coding-style.ts +++ b/lint-rules/coding-style.ts @@ -6,6 +6,7 @@ import type { Plugin } from './types.ts' import { enforceZodEntrypointRule } from './rules/enforce-zod-entrypoint.ts' import { noProcessEnvOutsideConfigRule } from './rules/no-process-env-outside-config.ts' +import { enforceLoggerLiteralRule } from './rules/enforce-logger-literal.ts' const plugin: Plugin = { meta: { @@ -13,7 +14,8 @@ const plugin: Plugin = { }, rules: { 'no-process-env-outside-config': noProcessEnvOutsideConfigRule, - 'enforce-zod-entrypoint': enforceZodEntrypointRule + 'enforce-zod-entrypoint': enforceZodEntrypointRule, + 'enforce-logger-literal': enforceLoggerLiteralRule } } diff --git a/lint-rules/rules/enforce-logger-literal.ts b/lint-rules/rules/enforce-logger-literal.ts new file mode 100644 index 0000000..1fee834 --- /dev/null +++ b/lint-rules/rules/enforce-logger-literal.ts @@ -0,0 +1,113 @@ +/** + * logger 呼び出しの引数を、型検査(closed event schema)が確実に効く形に + * 固定するルール。 + * + * 何をログへ載せてよいかは各パッケージ logger の `LogEvents` 型が決める。 + * sensitive な値そのものの検出は名前ベースの heuristic になるため lint では + * 行わず、この lint は AST で確実に判定できる形の制約だけを強制する。 + * + * - 第1引数は object literal に限定する(変数渡しでは TypeScript の + * excess property check が効かず、未知 field の混入を検出できない) + * - `meta` の値も object literal に限定する(同上) + * - 引数オブジェクト / meta 内での spread を禁止する(何が載るか静的に追えない) + * - computed key を禁止する(key 名を静的に追えない) + * + * テストファイルは対象外。runtime の最終防衛(`redactMeta()`)を検証するために、 + * 型検査をすり抜けた値を意図的に logger へ渡す必要があるため。 + */ +import type { CallExpressionNode, ObjectExpressionNode, Rule } from '../types.ts' + +const LOGGER_OBJECT = 'logger' +const LOGGER_METHODS = new Set(['log', 'error', 'debug']) + +/** 他のルールと同じ判定式。テストファイル・テスト補助ファイルを対象外にする。 */ +const TEST_FILE = /(\.test\.(ts|tsx)$|(^|\/)test\/)/ + +const ARGUMENT_LITERAL_MESSAGE = + 'logger の第1引数は object literal で渡してください。変数渡しでは closed event schema の excess property check が効きません(agents/logging.md 参照)' +const META_LITERAL_MESSAGE = + 'meta は object literal で渡してください。変数渡しでは closed event schema の excess property check が効きません(agents/logging.md 参照)' +const SPREAD_MESSAGE = + 'logger へ渡すオブジェクトを spread しないでください。何がログに載るか静的に追えなくなります(agents/logging.md 参照)' +const COMPUTED_KEY_MESSAGE = + 'logger へ渡すオブジェクトで computed key を使わないでください。key 名を静的に追えなくなります(agents/logging.md 参照)' + +function isLoggerCall(node: CallExpressionNode): boolean { + const callee = node.callee + return ( + callee.type === 'MemberExpression' && + !callee.computed && + callee.object.type === 'Identifier' && + callee.object.name === LOGGER_OBJECT && + callee.property.type === 'Identifier' && + LOGGER_METHODS.has(callee.property.name) + ) +} + +type KeyNode = ObjectExpressionNode['properties'][number] + +function getStaticKeyName(property: KeyNode): string | null { + if (property.type !== 'Property' || property.computed) { + return null + } + if (property.key.type === 'Identifier') { + return property.key.name + } + if (property.key.type === 'Literal' && typeof property.key.value === 'string') { + return property.key.value + } + return null +} + +export const enforceLoggerLiteralRule: Rule = { + meta: { + docs: { + description: + 'logger の引数を、closed event schema の型検査が効く object literal に限定する' + } + }, + create(context) { + if (TEST_FILE.test(context.filename)) { + return {} + } + function checkStaticShape(node: ObjectExpressionNode): void { + for (const property of node.properties) { + if (property.type === 'SpreadElement') { + context.report({ node: property, message: SPREAD_MESSAGE }) + continue + } + if (property.type === 'Property' && property.computed) { + context.report({ node: property, message: COMPUTED_KEY_MESSAGE }) + } + } + } + + return { + CallExpression(node) { + if (!isLoggerCall(node)) { + return + } + const [argument] = node.arguments + if (!argument) { + return + } + if (argument.type !== 'ObjectExpression') { + context.report({ node: argument, message: ARGUMENT_LITERAL_MESSAGE }) + return + } + checkStaticShape(argument) + for (const property of argument.properties) { + if (property.type !== 'Property' || getStaticKeyName(property) !== 'meta') { + continue + } + const meta = property.value + if (meta.type !== 'ObjectExpression') { + context.report({ node: property, message: META_LITERAL_MESSAGE }) + continue + } + checkStaticShape(meta) + } + } + } + } +} diff --git a/lint-rules/run-tests.ts b/lint-rules/run-tests.ts index a1bacb6..f92464c 100644 --- a/lint-rules/run-tests.ts +++ b/lint-rules/run-tests.ts @@ -9,6 +9,7 @@ import { requireHttpExceptionResRule } from './rules/require-httpexception-res.t import { requireValidatorForParamQueryRule } from './rules/require-validator-for-param-query.ts' import { noProcessEnvOutsideConfigRule } from './rules/no-process-env-outside-config.ts' import { enforceZodEntrypointRule } from './rules/enforce-zod-entrypoint.ts' +import { enforceLoggerLiteralRule } from './rules/enforce-logger-literal.ts' const handlerFile = 'packages/api/src/handlers/user/index.ts' const tester = new RuleTester() @@ -84,7 +85,10 @@ tester.run('no-process-env-outside-config', noProcessEnvOutsideConfigRule, { valid: [ // 準拠: config ファイル内の参照は許可 { code: 'export const PORT = process.env.PORT', filename: 'packages/api/src/config.ts' }, - { code: 'export const API_URI = process.env.API_URI', filename: 'packages/client/src/config.server.ts' }, + { + code: 'export const API_URI = process.env.API_URI', + filename: 'packages/client/src/config.server.ts' + }, // 対象外: テストファイル { code: 'const db = getTestDbClient(process.env)', filename: 'packages/api/src/app.test.ts' } ], @@ -124,4 +128,66 @@ tester.run('enforce-zod-entrypoint', enforceZodEntrypointRule, { ] }) +const loggerFile = 'packages/api/src/lib/middleware.ts' + +tester.run('enforce-logger-literal', enforceLoggerLiteralRule, { + valid: [ + // 準拠: 第1引数・meta とも object literal(値の型は closed event schema が検査する) + { + code: "logger.log({ label: 'access', requestId, body: 'GET /api/user', meta: { method: c.req.method, path: c.req.path, status: c.res.status, duration: 12 } })", + filename: loggerFile + }, + // 準拠: error は logger 側の serializeError で安全な shape になる + { + code: "logger.error({ label: 'handleError', body: 'failed', error })", + filename: loggerFile + }, + // 対象外: logger 以外の呼び出し + { code: 'client(url, { ...options })', filename: loggerFile }, + // 対象外: テストファイルは runtime の最終防衛を検証するため変数渡しを許す + { + code: 'logger.log(leakageFixture)', + filename: 'packages/api/src/lib/logger/index.test.ts' + } + ], + invalid: [ + // 第1引数の変数渡しは excess property check が効かない + { + code: 'logger.log(options)', + filename: loggerFile, + errors: 1 + }, + // 第1引数オブジェクトでの spread + { + code: "logger.log({ ...base, body: 'x' })", + filename: loggerFile, + errors: 1 + }, + // meta の変数渡し + { + code: "logger.debug({ body: 'x', meta: metaValues })", + filename: loggerFile, + errors: 1 + }, + // meta 内での spread + { + code: "logger.log({ body: 'x', meta: { ...payload } })", + filename: loggerFile, + errors: 1 + }, + // 第1引数オブジェクトでの computed key + { + code: "logger.log({ body: 'x', [key]: value })", + filename: loggerFile, + errors: 1 + }, + // meta 内での computed key + { + code: "logger.log({ body: 'x', meta: { [key]: value } })", + filename: loggerFile, + errors: 1 + } + ] +}) + console.log('lint-rules: all rule tests passed') diff --git a/packages/api/src/index.ts b/packages/api/src/index.ts index a8b92a8..5aa25df 100644 --- a/packages/api/src/index.ts +++ b/packages/api/src/index.ts @@ -1,7 +1,7 @@ import { serve } from '@hono/node-server' import { createApp } from './app.js' import { ENV, LOCAL_PROXY_CONFIG_DIR, PORT } from './config.js' -import { logger } from './lib/logger.js' +import { logger } from './lib/logger/index.js' let server: ReturnType | null = null diff --git a/packages/api/src/lib/logger.test.ts b/packages/api/src/lib/logger.test.ts deleted file mode 100644 index c21f318..0000000 --- a/packages/api/src/lib/logger.test.ts +++ /dev/null @@ -1,39 +0,0 @@ -import { expect, test, vi } from 'vite-plus/test' -import { logger } from './logger.js' - -vi.mock('console') - -test('logger.log', () => { - const logMock = vi - .spyOn(console, 'log') - .mockImplementationOnce(() => undefined) - - logger.log({ label: 'foo', body: 'bar' }) - - expect(logMock).toHaveBeenCalledTimes(1) - expect(logMock).toHaveBeenCalledWith( - JSON.stringify({ - label: 'foo', - body: 'bar', - level: 'INFO' - }) - ) -}) - -test('logger.error', () => { - const logMock = vi - .spyOn(console, 'error') - .mockImplementationOnce(() => undefined) - - logger.error({ label: 'foo', body: 'error', error: 'bar' }) - - expect(logMock).toHaveBeenCalledTimes(1) - expect(logMock).toHaveBeenCalledWith( - JSON.stringify({ - label: 'foo', - body: 'error', - error: 'bar', - level: 'ERROR' - }) - ) -}) diff --git a/packages/api/src/lib/logger.ts b/packages/api/src/lib/logger.ts deleted file mode 100644 index 591b237..0000000 --- a/packages/api/src/lib/logger.ts +++ /dev/null @@ -1,45 +0,0 @@ -import { ENV } from '../config.js' - -type Options = { - label?: string - body: string - meta?: any -} - -type ErrorOptions = Options & { - error?: any -} - -export const logger = { - log: (options: Options) => { - const json = { - ...options, - level: 'INFO' - } - if (ENV.local) { - console.dir(json, { depth: null }) - return - } - console.log(JSON.stringify(json)) - }, - error: (options: ErrorOptions) => { - const json = { - ...options, - level: 'ERROR' - } - if (ENV.local) { - console.dir(json, { depth: null }) - return - } - console.error(JSON.stringify(json)) - }, - debug: (options: Options) => { - if (!ENV.production) { - const json = { - ...options, - level: 'DEBUG' - } - console.dir(json, { depth: null }) - } - } -} as const diff --git a/packages/api/src/lib/logger/index.test.ts b/packages/api/src/lib/logger/index.test.ts new file mode 100644 index 0000000..ce91869 --- /dev/null +++ b/packages/api/src/lib/logger/index.test.ts @@ -0,0 +1,166 @@ +import { expect, test, vi } from 'vite-plus/test' +import { logger } from './index.js' +import { REDACTED, UNSUPPORTED } from './redact.js' + +vi.mock('console') + +// console の spy は同一ファイル内の test をまたいで呼び出し履歴が蓄積するため、 +// test ごとに履歴をクリアしてから使う +function spyOnConsole(method: 'log' | 'error') { + const spy = vi.spyOn(console, method).mockImplementation(() => { + return undefined + }) + spy.mockClear() + return spy +} + +test('logger.log outputs level / label / body as a structured log', () => { + const logMock = spyOnConsole('log') + + logger.log({ label: 'foo', body: 'bar' }) + + expect(logMock).toHaveBeenCalledTimes(1) + expect(logMock).toHaveBeenCalledWith( + JSON.stringify({ + level: 'INFO', + label: 'foo', + body: 'bar' + }) + ) +}) + +test('logger.log carries requestId as a top level field', () => { + const logMock = spyOnConsole('log') + + logger.log({ + label: 'access', + requestId: 'request-id-1', + body: 'GET /api/user', + meta: { method: 'GET', path: '/api/user', status: 200, duration: 3 } + }) + + expect(logMock).toHaveBeenCalledTimes(1) + expect(logMock).toHaveBeenCalledWith( + JSON.stringify({ + level: 'INFO', + label: 'access', + requestId: 'request-id-1', + body: 'GET /api/user', + meta: { method: 'GET', path: '/api/user', status: 200, duration: 3 } + }) + ) +}) + +test('logger meta is a closed event schema at compile time', () => { + const logMock = spyOnConsole('log') + + // @ts-expect-error LogEvents に無い label は meta を持てない + logger.log({ label: 'unknown-label', body: 'x', meta: { status: 200 } }) + + // @ts-expect-error 既知 label でも schema に無い field は渡せない + logger.log({ label: 'handleError', body: 'x', meta: { status: 500, authorization: 'Bearer x' } }) + + // @ts-expect-error meta の値は primitive のみで nested object は渡せない + logger.log({ label: 'handleError', body: 'x', meta: { status: { code: 500 } } }) + + const payload: Record = { status: 500 } + // @ts-expect-error 型の広い payload 変数を meta へ渡せない + logger.log({ label: 'handleError', body: 'x', meta: payload }) + + // @ts-expect-error payload 変数の spread も渡せない + logger.log({ label: 'handleError', body: 'x', meta: { ...payload } }) + + // 上記はいずれも型検査で弾かれることの検証であり、runtime では出力自体は行われる + expect(logMock).toHaveBeenCalledTimes(5) +}) + +test('redactMeta remains as a runtime last line of defense', () => { + const logMock = spyOnConsole('log') + + // wide な型の変数は closed event schema に代入できない(実際に型エラーになる) + const leaked: Record = { + status: 200, + authorization: 'Bearer super-secret-token', + provider: { idToken: 'id-token-value' } + } + logger.log({ + label: 'handleError', + body: 'verified', + // @ts-expect-error 型検査をすり抜けた値が runtime で redact されることを検証する + meta: leaked + }) + + const [output] = logMock.mock.calls[0] + expect(output).not.toContain('super-secret-token') + expect(output).not.toContain('id-token-value') + expect(JSON.parse(output)).toStrictEqual({ + level: 'INFO', + label: 'handleError', + body: 'verified', + meta: { + status: 200, + authorization: REDACTED, + provider: UNSUPPORTED + } + }) +}) + +test('logger.error serializes an Error into a limited shape', () => { + const logMock = spyOnConsole('error') + + logger.error({ + label: 'handleError', + requestId: 'request-id-1', + body: 'error', + error: new Error('boom') + }) + + expect(logMock).toHaveBeenCalledTimes(1) + const [output] = logMock.mock.calls[0] + const parsed = JSON.parse(output) + expect(parsed.level).toBe('ERROR') + expect(parsed.label).toBe('handleError') + expect(parsed.requestId).toBe('request-id-1') + expect(parsed.error.name).toBe('Error') + expect(parsed.error.message).toBe('boom') + expect(typeof parsed.error.stack).toBe('string') +}) + +test('logger.error does not leak enumerable properties of an external error', () => { + const logMock = spyOnConsole('error') + + class ProviderError extends Error { + config = { headers: { authorization: 'Bearer super-secret-token' } } + refreshToken = 'refresh-token-value' + } + + logger.error({ + label: 'provider', + body: 'provider call failed', + error: new ProviderError('provider failed') + }) + + const [output] = logMock.mock.calls[0] + expect(output).not.toContain('super-secret-token') + expect(output).not.toContain('refresh-token-value') + expect(Object.keys(JSON.parse(output).error).sort()).toStrictEqual(['message', 'name', 'stack']) +}) + +test('logger.error serializes a non-Error value without spreading it', () => { + const logMock = spyOnConsole('error') + + logger.error({ + label: 'foo', + body: 'error', + error: { code: 'auth/invalid-id-token', message: 'invalid', idToken: 'id' } + }) + + expect(logMock).toHaveBeenCalledWith( + JSON.stringify({ + level: 'ERROR', + label: 'foo', + body: 'error', + error: { name: 'auth/invalid-id-token', message: 'invalid' } + }) + ) +}) diff --git a/packages/api/src/lib/logger/index.ts b/packages/api/src/lib/logger/index.ts new file mode 100644 index 0000000..1c55449 --- /dev/null +++ b/packages/api/src/lib/logger/index.ts @@ -0,0 +1,95 @@ +import { ENV } from '../../config.js' +import { redactMeta, serializeError } from './redact.js' + +/** + * structured log の単一入口。application code から console を直接呼ばず、 + * 必ずこの logger を経由する(`no-console` lint で強制している)。 + * + * public API は closed event schema。meta を持てるのは `LogEvents` に定義した + * label だけで、field は primitive に限る。新しい情報をログへ載せたいときは、 + * 値を渡す前に `LogEvents` へ label / field を追加する(agents/logging.md 参照)。 + * + * - `error` は `serializeError()` で name/message/stack/cause の限定 shape にする + * - `requestId` は access log / application log を横断して追跡するための共通 field。 + * api では accessLogMiddleware が発行した値を `c.get('requestId')` から渡す + */ + +/** + * label ごとに meta として許可する field の閉じた schema。 + * secret / credential(authorization / cookie / token 等)を表す field や、 + * request / response / headers / body を丸ごと表す field を追加してはならない。 + */ +type LogEvents = { + /** accessLogMiddleware が出力する access log */ + access: { + method: string + path: string + status: number + duration: number + } + /** handleError が HTTPException をレスポンスへ変換するときの詳細 */ + handleError: { + status: number + } +} + +type BaseOptions = { + requestId?: string + body: string + error?: unknown +} + +/** `LogEvents` に定義した label は、その schema どおりの meta を渡せる。 */ +type EventLogOptions = { + [Label in keyof LogEvents]: BaseOptions & { + label: Label + meta: LogEvents[Label] + } +}[keyof LogEvents] + +/** それ以外の label は meta を持てない(`meta?: never`)。 */ +type PlainLogOptions = BaseOptions & { + label?: string + meta?: never +} + +type LogOptions = EventLogOptions | PlainLogOptions + +type Level = 'INFO' | 'ERROR' | 'DEBUG' + +function buildLog(level: Level, options: LogOptions) { + const { label, requestId, body, meta, error } = options + return { + level, + ...(label === undefined ? {} : { label }), + ...(requestId === undefined ? {} : { requestId }), + body, + ...(meta === undefined ? {} : { meta: redactMeta(meta) }), + ...(error === undefined ? {} : { error: serializeError(error) }) + } +} + +export const logger = { + log: (options: LogOptions) => { + const json = buildLog('INFO', options) + if (ENV.local) { + console.dir(json, { depth: null }) + return + } + console.log(JSON.stringify(json)) + }, + error: (options: LogOptions) => { + const json = buildLog('ERROR', options) + if (ENV.local) { + console.dir(json, { depth: null }) + return + } + console.error(JSON.stringify(json)) + }, + debug: (options: LogOptions) => { + if (!ENV.production) { + const json = buildLog('DEBUG', options) + console.dir(json, { depth: null }) + } + } +} as const diff --git a/packages/api/src/lib/logger/redact.test.ts b/packages/api/src/lib/logger/redact.test.ts new file mode 100644 index 0000000..8428865 --- /dev/null +++ b/packages/api/src/lib/logger/redact.test.ts @@ -0,0 +1,147 @@ +import { expect, test } from 'vite-plus/test' +import { REDACTED, UNSUPPORTED, isSensitiveKey, redactMeta, serializeError } from './redact.js' + +test('isSensitiveKey matches credential-ish keys regardless of case and separators', () => { + expect(isSensitiveKey('Authorization')).toBe(true) + expect(isSensitiveKey('cookie')).toBe(true) + expect(isSensitiveKey('set-cookie')).toBe(true) + expect(isSensitiveKey('Set-Cookie')).toBe(true) + expect(isSensitiveKey('password')).toBe(true) + expect(isSensitiveKey('client_secret')).toBe(true) + expect(isSensitiveKey('idToken')).toBe(true) + expect(isSensitiveKey('accessToken')).toBe(true) + expect(isSensitiveKey('refresh_token')).toBe(true) + expect(isSensitiveKey('sessionToken')).toBe(true) + expect(isSensitiveKey('x-api-key')).toBe(true) + + expect(isSensitiveKey('status')).toBe(false) + expect(isSensitiveKey('requestId')).toBe(false) + expect(isSensitiveKey('userId')).toBe(false) +}) + +test('redactMeta masks values bound to sensitive keys', () => { + const actual = redactMeta({ + status: 200, + Authorization: 'Bearer super-secret-token', + 'set-cookie': 'session=abcdef; HttpOnly', + idToken: 'id-token-value', + refreshToken: 'refresh-token-value' + }) + + expect(actual).toStrictEqual({ + status: 200, + Authorization: REDACTED, + 'set-cookie': REDACTED, + idToken: REDACTED, + refreshToken: REDACTED + }) + expect(JSON.stringify(actual)).not.toContain('super-secret-token') + expect(JSON.stringify(actual)).not.toContain('abcdef') +}) + +test('redactMeta keeps primitives and replaces non-primitive values', () => { + const actual = redactMeta({ + name: 'task', + count: 3, + ok: true, + empty: null, + missing: undefined, + headers: new Headers({ authorization: 'Bearer super-secret-token' }), + nested: { userId: 1 }, + list: [1, 2, 3] + }) + + expect(actual).toStrictEqual({ + name: 'task', + count: 3, + ok: true, + empty: null, + missing: undefined, + headers: UNSUPPORTED, + nested: UNSUPPORTED, + list: UNSUPPORTED + }) + expect(JSON.stringify(actual)).not.toContain('super-secret-token') +}) + +test('serializeError keeps only name / message / stack', () => { + const error = new Error('boom') + const actual = serializeError(error) + + expect(actual.name).toBe('Error') + expect(actual.message).toBe('boom') + expect(typeof actual.stack).toBe('string') + expect(actual.cause).toBeUndefined() +}) + +test('serializeError does not leak arbitrary enumerable properties of an error', () => { + class ProviderError extends Error { + // external SDK が request 情報を error に詰めてくるケース + config = { + headers: { authorization: 'Bearer super-secret-token' }, + body: { password: 'p@ssw0rd' } + } + accessToken = 'access-token-value' + } + const error = new ProviderError('provider failed') + error.name = 'ProviderError' + + const actual = serializeError(error) + + expect(actual.name).toBe('ProviderError') + expect(actual.message).toBe('provider failed') + expect(Object.keys(actual).sort()).toStrictEqual(['message', 'name', 'stack']) + expect(JSON.stringify(actual)).not.toContain('super-secret-token') + expect(JSON.stringify(actual)).not.toContain('access-token-value') + expect(JSON.stringify(actual)).not.toContain('p@ssw0rd') +}) + +test('serializeError follows the cause chain within a bounded depth', () => { + const error = new Error('level0', { + cause: new Error('level1', { + cause: new Error('level2', { cause: new Error('level3') }) + }) + }) + + const actual = serializeError(error) + + expect(actual.message).toBe('level0') + expect(actual.cause?.message).toBe('level1') + expect(actual.cause?.cause?.message).toBe('level2') + expect(actual.cause?.cause?.cause?.message).toBe('level3') + expect(actual.cause?.cause?.cause?.cause).toBeUndefined() +}) + +test('serializeError stops on a circular cause chain', () => { + const error = new Error('self referencing') + error.cause = error + + expect(serializeError(error).cause?.cause?.cause?.cause).toBeUndefined() +}) + +test('serializeError narrows non-Error values to name / message', () => { + expect(serializeError('boom')).toStrictEqual({ + name: 'NonError', + message: 'boom' + }) + expect(serializeError(500)).toStrictEqual({ + name: 'NonError', + message: '500' + }) + expect(serializeError(undefined)).toStrictEqual({ + name: 'NonError', + message: 'undefined' + }) + // external SDK の plain object error。message / name(なければ code)だけを残す + expect( + serializeError({ + code: 'auth/invalid-id-token', + message: 'invalid token', + idToken: 'id-token-value', + headers: { authorization: 'Bearer super-secret-token' } + }) + ).toStrictEqual({ + name: 'auth/invalid-id-token', + message: 'invalid token' + }) +}) diff --git a/packages/api/src/lib/logger/redact.ts b/packages/api/src/lib/logger/redact.ts new file mode 100644 index 0000000..6daea31 --- /dev/null +++ b/packages/api/src/lib/logger/redact.ts @@ -0,0 +1,145 @@ +/** + * ログ出力を安全側に倒すための redaction ヘルパー。logger の単一入口 + * (`lib/logger/index.ts`)から呼ばれる想定で、直接 console へ書き出す実装は持たない。 + * + * 第一の防御は logger の closed event schema(`logger/index.ts` の `LogEvents` 型)。 + * ここは型検査をすり抜けた値(assertion 等)に対する最後の防波堤: + * - `redactMeta()` は flat な meta を走査し、sensitive な key 名の値を + * `[REDACTED]` へ、primitive でない値を `[UNSUPPORTED]` へ置き換える + * - `serializeError()` は Error を name/message/stack/cause の限定 shape へ変換する + * + * 各パッケージは実行コンテキストが異なるため(AGENTS.md の Monorepo Guidelines)、 + * このファイルは shared へ切り出さず api/client/task がそれぞれ自己完結して持つ。 + */ + +/** 値が sensitive な key に紐づいていたことを示すプレースホルダ。 */ +export const REDACTED = '[REDACTED]' +/** primitive でない値が meta へ渡っていたことを示すプレースホルダ。 */ +export const UNSUPPORTED = '[UNSUPPORTED]' + +/** stack trace として残す最大行数(ログ量を有界にするため)。 */ +const MAX_STACK_LINES = 20 +/** cause チェーンを辿る最大段数(cause の循環でも停止させるため)。 */ +const MAX_CAUSE_DEPTH = 3 + +/** + * 正規化(小文字化 + 区切り文字除去)した key 名に対する部分一致で判定する。 + * `token` が idToken / accessToken / refreshToken / sessionToken を、 + * `cookie` が set-cookie を、それぞれまとめて拾う。 + * 判定回数を key ごとに 1 回へ抑えるため単一の正規表現にまとめている。 + */ +const SENSITIVE_KEY_PATTERN = + /authorization|cookie|password|passwd|secret|token|credential|apikey|privatekey|sessionid/ + +const KEY_SEPARATOR_PATTERN = /[-_\s.]/g + +/** ログの key 名が redaction 対象かどうかを返す。 */ +export function isSensitiveKey(key: string): boolean { + return SENSITIVE_KEY_PATTERN.test(key.toLowerCase().replace(KEY_SEPARATOR_PATTERN, '')) +} + +/** meta の field として logger が出力する値。primitive のみを許す。 */ +export type LogPrimitive = string | number | boolean | null | undefined + +/** + * ログの meta を flat に走査し、型検査をすり抜けた値を安全な形へ落とす。 + * sensitive な key 名の値は `[REDACTED]`、primitive でない値(object / + * Headers / provider response 等)は `[UNSUPPORTED]` に置き換える。 + */ +export function redactMeta(meta: Record): Record { + const result: Record = {} + for (const [key, value] of Object.entries(meta)) { + if (isSensitiveKey(key)) { + result[key] = REDACTED + continue + } + if ( + value === null || + value === undefined || + typeof value === 'string' || + typeof value === 'number' || + typeof value === 'boolean' + ) { + result[key] = value + continue + } + result[key] = UNSUPPORTED + } + return result +} + +/** Error を JSON へ安全に落とし込むための限定 shape。 */ +export type SerializedError = { + name: string + message: string + stack?: string + cause?: SerializedError +} + +function trimStack(stack: string | undefined): string | undefined { + if (!stack) { + return undefined + } + const lines = stack.split('\n') + if (lines.length <= MAX_STACK_LINES) { + return stack + } + return [ + ...lines.slice(0, MAX_STACK_LINES), + ` ... ${lines.length - MAX_STACK_LINES} more lines` + ].join('\n') +} + +function isRecord(value: unknown): value is Record { + return typeof value === 'object' && value !== null +} + +/** + * external SDK が投げる「Error ではないが name/message を持つ」オブジェクトから + * 文字列フィールドだけを取り出す。任意の enumerable property は読まない。 + */ +function serializeNonError(value: unknown): SerializedError { + if (typeof value === 'string') { + return { name: 'NonError', message: value } + } + if (typeof value === 'number' || typeof value === 'boolean' || typeof value === 'bigint') { + return { name: 'NonError', message: `${value}` } + } + if (!isRecord(value)) { + return { name: 'NonError', message: `${typeof value}` } + } + const name = + typeof value.name === 'string' + ? value.name + : typeof value.code === 'string' + ? value.code + : 'NonError' + const message = typeof value.message === 'string' ? value.message : '[unknown]' + return { name, message } +} + +function serializeErrorWithDepth(error: unknown, depth: number): SerializedError { + if (!(error instanceof Error)) { + return serializeNonError(error) + } + const cause = + error.cause !== undefined && depth < MAX_CAUSE_DEPTH + ? serializeErrorWithDepth(error.cause, depth + 1) + : undefined + const stack = trimStack(error.stack) + return { + name: error.name, + message: error.message, + ...(stack === undefined ? {} : { stack }), + ...(cause === undefined ? {} : { cause }) + } +} + +/** + * Error / external SDK error を name/message/stack/cause の限定 shape へ変換する。 + * `{ ...error }` のような spread と違い、任意の enumerable property + * (provider が詰めた credential や request payload)を持ち出さない。 + */ +export function serializeError(error: unknown): SerializedError { + return serializeErrorWithDepth(error, 0) +} diff --git a/packages/api/src/lib/middleware.test.ts b/packages/api/src/lib/middleware.test.ts new file mode 100644 index 0000000..ea760d3 --- /dev/null +++ b/packages/api/src/lib/middleware.test.ts @@ -0,0 +1,128 @@ +import { Hono } from 'hono' +import { expect, test, vi } from 'vite-plus/test' +import { accessLogMiddleware, verifyAuthorizationMiddleware } from './middleware.js' +import { handleError } from './wrap.js' + +// console の spy は同一ファイル内の test をまたいで呼び出し履歴が蓄積するため、 +// test ごとに履歴をクリアしてから使う +function spyOnConsole(method: 'log' | 'error' | 'dir') { + const spy = vi.spyOn(console, method).mockImplementation(() => { + return undefined + }) + spy.mockClear() + return spy +} + +function parseLogs(calls: ReadonlyArray>) { + return calls.map(([output]) => { + return JSON.parse(`${output}`) + }) +} + +test('access log and application log share the same requestId', async () => { + const logMock = spyOnConsole('log') + const errorMock = spyOnConsole('error') + + const app = new Hono() + app.use(accessLogMiddleware()) + app.onError(handleError) + app.get('/boom', () => { + throw new Error('boom') + }) + + const res = await app.request('/boom') + expect(res.status).toBe(500) + + const [accessLog] = parseLogs(logMock.mock.calls) + const [applicationLog] = parseLogs(errorMock.mock.calls) + + expect(accessLog.label).toBe('access') + expect(applicationLog.label).toBe('handleError') + expect(typeof accessLog.requestId).toBe('string') + expect(applicationLog.requestId).toBe(accessLog.requestId) +}) + +test('token verification failure is logged with the access log requestId', async () => { + const logMock = spyOnConsole('log') + spyOnConsole('dir') + + const app = new Hono() + app.use(accessLogMiddleware()) + app.use(verifyAuthorizationMiddleware()) + app.onError(handleError) + app.get('/secure', (c) => { + return c.text('ok') + }) + + const res = await app.request('/secure', { + headers: { Authorization: 'Bearer not-a-valid-token' } + }) + expect(res.status).toBe(401) + + const logs = parseLogs(logMock.mock.calls) + const accessLog = logs.find((log) => { + return log.label === 'access' + }) + const tokenLog = logs.find((log) => { + return log.label === 'token_verification' + }) + + expect(typeof accessLog?.requestId).toBe('string') + expect(tokenLog?.requestId).toBe(accessLog?.requestId) +}) + +test('token verification failure log does not contain the presented token', async () => { + const logMock = spyOnConsole('log') + spyOnConsole('dir') + + const app = new Hono() + app.use(accessLogMiddleware()) + app.use(verifyAuthorizationMiddleware()) + app.onError(handleError) + app.get('/secure', (c) => { + return c.text('ok') + }) + + await app.request('/secure', { + headers: { + Authorization: 'Bearer super-secret-token', + Cookie: 'session=abcdef' + } + }) + + const output = logMock.mock.calls + .map(([value]) => { + return `${value}` + }) + .join('\n') + + expect(output).toContain('token_verification') + expect(output).not.toContain('super-secret-token') + expect(output).not.toContain('abcdef') +}) + +test('access log does not contain request headers', async () => { + const logMock = spyOnConsole('log') + + const app = new Hono() + app.use(accessLogMiddleware()) + app.get('/', (c) => { + return c.text('ok') + }) + + await app.request('/', { + headers: { + Authorization: 'Bearer super-secret-token', + Cookie: 'session=abcdef' + } + }) + + const [accessLog] = parseLogs(logMock.mock.calls) + + expect(accessLog.meta).toStrictEqual({ + method: 'GET', + path: '/', + status: 200, + duration: expect.any(Number) + }) +}) diff --git a/packages/api/src/lib/middleware.ts b/packages/api/src/lib/middleware.ts index e0d4898..368111c 100644 --- a/packages/api/src/lib/middleware.ts +++ b/packages/api/src/lib/middleware.ts @@ -5,7 +5,7 @@ import type * as schema from 'shared/src/schema' import { CORS_OPTIONS } from '../config.js' import { localTokenVerifier } from '../lib/auth/local-verifier.js' import type { TokenVerifier } from '../lib/auth/token-verifier.js' -import { logger } from '../lib/logger.js' +import { logger } from './logger/index.js' import { createHttpException } from './wrap.js' // 実プロバイダ(Firebase Admin 等)に差し替える場合はここを変更する @@ -29,9 +29,9 @@ export function accessLogMiddleware() { await next() logger.log({ label: 'access', + requestId, body: `${c.req.method} ${c.req.path}`, meta: { - requestId, method: c.req.method, path: c.req.path, status: c.res.status, @@ -71,8 +71,9 @@ export function verifyAuthorizationMiddleware() { } catch (error) { logger.log({ label: 'token_verification', + requestId: c.get('requestId'), body: 'token verification failed', - meta: { error } + error }) throw createHttpException(401, { type: 'about:blank', diff --git a/packages/api/src/lib/wrap.ts b/packages/api/src/lib/wrap.ts index 4fca9e8..1acdbde 100644 --- a/packages/api/src/lib/wrap.ts +++ b/packages/api/src/lib/wrap.ts @@ -1,6 +1,6 @@ import type { Context } from 'hono' import { HTTPException } from 'hono/http-exception' -import { logger } from './logger.js' +import { logger } from './logger/index.js' export type ProblemDetails = { type: string @@ -10,12 +10,7 @@ export type ProblemDetails = { } function isProblemDetails(value: unknown): value is ProblemDetails { - return ( - typeof value === 'object' && - value !== null && - 'title' in value && - 'status' in value - ) + return typeof value === 'object' && value !== null && 'title' in value && 'status' in value } export function createHttpException>( @@ -35,8 +30,10 @@ export async function handleError(error: Error, c: Context) { if (error instanceof HTTPException) { logger.debug({ label: 'handleError', + requestId, body: error.message, - meta: { requestId, error } + meta: { status: error.status }, + error }) // res 付きの HTTPException(createHttpException 経由)はレスポンスの // 形状(拡張フィールドを含む)が確定しているため、そのまま返す。 @@ -52,8 +49,8 @@ export async function handleError(error: Error, c: Context) { } logger.error({ label: 'handleError', + requestId, body: 'Error occurred in handleError', - meta: { requestId }, error }) return c.json( diff --git a/packages/client/src/app/(authenticated)/actions.ts b/packages/client/src/app/(authenticated)/actions.ts index d69e7a2..eb396e9 100644 --- a/packages/client/src/app/(authenticated)/actions.ts +++ b/packages/client/src/app/(authenticated)/actions.ts @@ -8,35 +8,35 @@ import { logger } from '../_lib/logger' type FetchUserListResponse = APIResult, 200> -export const fetchUserList = fetcher( - async (): Promise => { - const sessionCookie = (await cookies()).get(SESSION_COOKIE_NAME)?.value - if (!sessionCookie) { - return { - ok: false, - status: 401, - body: 'not authenticated' - } +export const fetchUserList = fetcher(async (): Promise => { + const sessionCookie = (await cookies()).get(SESSION_COOKIE_NAME)?.value + if (!sessionCookie) { + return { + ok: false, + status: 401, + body: 'not authenticated' } + } - const url = new URL('/api/user', API_URI) - const res = await client(url.toString(), { - path: '/api/user', - method: 'get', - parameters: { - header: { - Authorization: `Bearer ${sessionCookie}` - } + const url = new URL('/api/user', API_URI) + const res = await client(url.toString(), { + path: '/api/user', + method: 'get', + parameters: { + header: { + Authorization: `Bearer ${sessionCookie}` } - }) - if (res.status === 200) { - return { ok: true, ...res } } - logger.debug({ - label: 'fetchUserList', - body: 'unexpected status', - meta: { status: res.status, body: res.body, url: url.toString() } - }) - return { ok: false, ...res } + }) + if (res.status === 200) { + return { ok: true, ...res } } -) + // レスポンス body を丸ごとログへ流すと provider 由来の値まで載るため、 + // status / url のみを残す(agents/logging.md 参照) + logger.debug({ + label: 'fetchUserList', + body: 'unexpected status', + meta: { status: res.status, url: url.toString() } + }) + return { ok: false, ...res } +}) diff --git a/packages/client/src/app/(authenticated)/page.tsx b/packages/client/src/app/(authenticated)/page.tsx index d83291a..69ba6da 100644 --- a/packages/client/src/app/(authenticated)/page.tsx +++ b/packages/client/src/app/(authenticated)/page.tsx @@ -3,7 +3,7 @@ import { fetchUserList } from './actions' export default async function Page() { const user = await fetchUserList() - logger.debug({ label: 'Top', body: 'render', meta: { user } }) + logger.debug({ label: 'Top', body: 'render', meta: { ok: user.ok } }) return (
diff --git a/packages/client/src/app/_lib/api.ts b/packages/client/src/app/_lib/api.ts index e7fa3a5..167a14e 100644 --- a/packages/client/src/app/_lib/api.ts +++ b/packages/client/src/app/_lib/api.ts @@ -1,16 +1,197 @@ import type { Result } from 'shared/src/index' -import { logger } from './logger' - -export { - client, - createFetchOptions, - extractErrorMessage -} from 'shared/src/api-client' -export type { - APIResult, - ClientResponse, - HttpMethod -} from 'shared/src/api-client' +import type * as schema from 'shared/src/schema' +import { logger } from './logger/index' + +type Prettify = { + [K in keyof T]: T[K] +} & {} + +type StatusNumKeys = Extract +type TypedResponse = { + [S in StatusNumKeys]: { + status: S + body: R[S] extends { content: { 'application/json': infer U } } + ? U + : R[S] extends { content: { 'text/plain': infer TP } } + ? TP extends string + ? TP + : string + : unknown + } +}[StatusNumKeys] + +type HttpStatus = 200 | 201 | 400 | 401 | 403 | 500 + +export type ClientResponse = + | TypedResponse + | { status: Exclude>; body: string } + +export type HttpMethod = + | 'get' + | 'post' + | 'put' + | 'delete' + | 'options' + | 'head' + | 'patch' + | 'trace' + +type OptionsFor< + T extends keyof schema.paths, + K extends HttpMethod +> = Parameters>[0] + +type ExtractQuery = Op extends { + parameters: { query?: infer Q } +} + ? NonNullable + : never + +type QueryType< + T extends keyof schema.paths, + K extends HttpMethod +> = K extends keyof schema.paths[T] ? ExtractQuery : never + +function isRecord(value: unknown): value is Record { + return typeof value === 'object' && value !== null +} + +export async function client< + T extends keyof schema.paths, + K extends HttpMethod +>( + url: string, + options: OptionsFor & { + appendQuery?: ( + urlSearchParams: URLSearchParams, + query: QueryType + ) => URLSearchParams + }, + _init?: { next?: RequestInit['next'] } & RequestInit +): Promise< + Prettify< + ClientResponse< + schema.paths[T][K] extends { responses: infer R } ? R : never + > + > +> { + const _options = options + const init: Parameters[1] = { + ..._init, + method: _options.method, + headers: { + 'Content-Type': 'application/json', + ..._init?.headers + } + } + + function hasHeader(o: typeof _options): o is typeof _options & { + parameters: { header: Record } + } { + if (!isRecord(o) || !('parameters' in o)) return false + const { parameters } = o + return isRecord(parameters) && 'header' in parameters + } + + if (hasHeader(_options)) { + init.headers = { + ...init.headers, + ..._options.parameters.header + } + } + + function hasRequestBody(o: typeof _options) { + return isRecord(o) && 'requestBody' in o + } + + if (hasRequestBody(_options)) { + init.body = JSON.stringify(_options.requestBody) + } + + function hasQuery(o: typeof _options): o is typeof _options & { + parameters: { query: QueryType } + } { + if (!isRecord(o) || !('parameters' in o)) return false + const { parameters } = o + return isRecord(parameters) && 'query' in parameters + } + + let _url = url + if (_options.appendQuery && hasQuery(_options)) { + const urlSearchParams = new URLSearchParams() + const sp = _options.appendQuery( + urlSearchParams, + _options.parameters.query + ) + const qs = sp.toString() + if (qs) { + _url = `${url}${url.includes('?') ? '&' : '?'}${qs}` + } + } + + const res = await fetch(_url, init) + let body = await res.text() + const contentType = res.headers.get('Content-Type') + if ( + body.length > 0 && + init.headers && + typeof contentType === 'string' && + contentType.includes('application/json') + ) { + body = JSON.parse(body) + } + + type Res = schema.paths[T][K] extends { responses: infer R } ? R : never + + return { + status: res.status, + body + } as Prettify> +} + +export function createFetchOptions< + T extends keyof schema.paths, + K extends HttpMethod +>( + options: { + path: T + method: K + } & (schema.paths[T][K] extends { parameters: infer P } + ? { parameters: P } + : Record) & + (schema.paths[T][K] extends { + requestBody: { content: { 'application/json': infer Q } } + } + ? { requestBody: Q } + : Record) +) { + return options +} + +type APIResultBase< + ClientFn extends (...args: never[]) => unknown, + SuccessStatus extends number, + APIResponse extends { status: number; body: unknown } = + Awaited> extends { status: number; body: unknown } + ? Awaited> + : never +> = Result< + Extract['body'], + | Extract< + APIResponse, + { status: Exclude; body: unknown } + >['body'] + | string +> + +// ClientFn には `typeof client<'/api/user', 'get'>` のように、path/method で +// 具体化した client() の型をそのまま渡す。path/method を APIResult 側で +// 再指定しない(単一の情報源から導出する)ことで、client() の型と APIResult の +// 型が食い違う余地を無くす +export type APIResult< + ClientFn extends (...args: never[]) => unknown, + SuccessStatus extends number +> = APIResultBase // 例外を握って `{ ok: false, status: 500, body: <メッセージ> }` に落とす高階関数。 // Server Action / クライアント関数の実装から try/catch による 500 フォールバックの @@ -31,3 +212,12 @@ export function fetcher( } } } + +// RFC9457 Problem Details (`detail`) からのエラーメッセージ抽出の単一入口。 +// エラー表示は必ずこのヘルパー経由に統一し、`body.detail` 等を直接参照しない +export function extractErrorMessage(body: unknown): string { + if (isRecord(body) && typeof body.detail === 'string') { + return body.detail + } + return 'エラーが発生しました' +} diff --git a/packages/client/src/app/_lib/logger.test.ts b/packages/client/src/app/_lib/logger.test.ts deleted file mode 100644 index c21f318..0000000 --- a/packages/client/src/app/_lib/logger.test.ts +++ /dev/null @@ -1,39 +0,0 @@ -import { expect, test, vi } from 'vite-plus/test' -import { logger } from './logger.js' - -vi.mock('console') - -test('logger.log', () => { - const logMock = vi - .spyOn(console, 'log') - .mockImplementationOnce(() => undefined) - - logger.log({ label: 'foo', body: 'bar' }) - - expect(logMock).toHaveBeenCalledTimes(1) - expect(logMock).toHaveBeenCalledWith( - JSON.stringify({ - label: 'foo', - body: 'bar', - level: 'INFO' - }) - ) -}) - -test('logger.error', () => { - const logMock = vi - .spyOn(console, 'error') - .mockImplementationOnce(() => undefined) - - logger.error({ label: 'foo', body: 'error', error: 'bar' }) - - expect(logMock).toHaveBeenCalledTimes(1) - expect(logMock).toHaveBeenCalledWith( - JSON.stringify({ - label: 'foo', - body: 'error', - error: 'bar', - level: 'ERROR' - }) - ) -}) diff --git a/packages/client/src/app/_lib/logger.ts b/packages/client/src/app/_lib/logger.ts deleted file mode 100644 index d3ed431..0000000 --- a/packages/client/src/app/_lib/logger.ts +++ /dev/null @@ -1,45 +0,0 @@ -import { NEXT_PUBLIC_ENV } from '../../constants' - -type Options = { - label?: string - body: string - meta?: any -} - -type ErrorOptions = Options & { - error?: any -} - -export const logger = { - log: (options: Options) => { - const json = { - ...options, - level: 'INFO' - } - if (NEXT_PUBLIC_ENV.local) { - console.dir(json, { depth: null }) - return - } - console.log(JSON.stringify(json)) - }, - error: (options: ErrorOptions) => { - const json = { - ...options, - level: 'ERROR' - } - if (NEXT_PUBLIC_ENV.local) { - console.dir(json, { depth: null }) - return - } - console.error(JSON.stringify(json)) - }, - debug: (options: Options) => { - if (!NEXT_PUBLIC_ENV.production) { - const json = { - ...options, - level: 'DEBUG' - } - console.dir(json, { depth: null }) - } - } -} as const diff --git a/packages/client/src/app/_lib/logger/index.test.ts b/packages/client/src/app/_lib/logger/index.test.ts new file mode 100644 index 0000000..643f89e --- /dev/null +++ b/packages/client/src/app/_lib/logger/index.test.ts @@ -0,0 +1,166 @@ +import { expect, test, vi } from 'vite-plus/test' +import { logger } from './index' +import { REDACTED, UNSUPPORTED } from './redact' + +vi.mock('console') + +// console の spy は同一ファイル内の test をまたいで呼び出し履歴が蓄積するため、 +// test ごとに履歴をクリアしてから使う +function spyOnConsole(method: 'log' | 'error') { + const spy = vi.spyOn(console, method).mockImplementation(() => { + return undefined + }) + spy.mockClear() + return spy +} + +test('logger.log outputs level / label / body as a structured log', () => { + const logMock = spyOnConsole('log') + + logger.log({ label: 'foo', body: 'bar' }) + + expect(logMock).toHaveBeenCalledTimes(1) + expect(logMock).toHaveBeenCalledWith( + JSON.stringify({ + level: 'INFO', + label: 'foo', + body: 'bar' + }) + ) +}) + +test('logger.log carries requestId as a top level field', () => { + const logMock = spyOnConsole('log') + + logger.log({ + label: 'fetchUserList', + requestId: 'request-id-1', + body: 'unexpected status', + meta: { status: 500, url: 'http://localhost:8000/api/user' } + }) + + expect(logMock).toHaveBeenCalledTimes(1) + expect(logMock).toHaveBeenCalledWith( + JSON.stringify({ + level: 'INFO', + label: 'fetchUserList', + requestId: 'request-id-1', + body: 'unexpected status', + meta: { status: 500, url: 'http://localhost:8000/api/user' } + }) + ) +}) + +test('logger meta is a closed event schema at compile time', () => { + const logMock = spyOnConsole('log') + + // @ts-expect-error LogEvents に無い label は meta を持てない + logger.log({ label: 'unknown-label', body: 'x', meta: { status: 200 } }) + + // @ts-expect-error 既知 label でも schema に無い field は渡せない + logger.log({ label: 'Top', body: 'x', meta: { ok: true, authorization: 'Bearer x' } }) + + // @ts-expect-error meta の値は primitive のみで nested object は渡せない + logger.log({ label: 'Top', body: 'x', meta: { ok: { rendered: true } } }) + + const payload: Record = { ok: true } + // @ts-expect-error 型の広い payload 変数を meta へ渡せない + logger.log({ label: 'Top', body: 'x', meta: payload }) + + // @ts-expect-error payload 変数の spread も渡せない + logger.log({ label: 'Top', body: 'x', meta: { ...payload } }) + + // 上記はいずれも型検査で弾かれることの検証であり、runtime では出力自体は行われる + expect(logMock).toHaveBeenCalledTimes(5) +}) + +test('redactMeta remains as a runtime last line of defense', () => { + const logMock = spyOnConsole('log') + + // wide な型の変数は closed event schema に代入できない(実際に型エラーになる) + const leaked: Record = { + ok: true, + authorization: 'Bearer super-secret-token', + provider: { idToken: 'id-token-value' } + } + logger.log({ + label: 'Top', + body: 'verified', + // @ts-expect-error 型検査をすり抜けた値が runtime で redact されることを検証する + meta: leaked + }) + + const [output] = logMock.mock.calls[0] + expect(output).not.toContain('super-secret-token') + expect(output).not.toContain('id-token-value') + expect(JSON.parse(output)).toStrictEqual({ + level: 'INFO', + label: 'Top', + body: 'verified', + meta: { + ok: true, + authorization: REDACTED, + provider: UNSUPPORTED + } + }) +}) + +test('logger.error serializes an Error into a limited shape', () => { + const logMock = spyOnConsole('error') + + logger.error({ + label: 'fetcher', + requestId: 'request-id-1', + body: 'error', + error: new Error('boom') + }) + + expect(logMock).toHaveBeenCalledTimes(1) + const [output] = logMock.mock.calls[0] + const parsed = JSON.parse(output) + expect(parsed.level).toBe('ERROR') + expect(parsed.label).toBe('fetcher') + expect(parsed.requestId).toBe('request-id-1') + expect(parsed.error.name).toBe('Error') + expect(parsed.error.message).toBe('boom') + expect(typeof parsed.error.stack).toBe('string') +}) + +test('logger.error does not leak enumerable properties of an external error', () => { + const logMock = spyOnConsole('error') + + class ProviderError extends Error { + config = { headers: { authorization: 'Bearer super-secret-token' } } + refreshToken = 'refresh-token-value' + } + + logger.error({ + label: 'provider', + body: 'provider call failed', + error: new ProviderError('provider failed') + }) + + const [output] = logMock.mock.calls[0] + expect(output).not.toContain('super-secret-token') + expect(output).not.toContain('refresh-token-value') + expect(Object.keys(JSON.parse(output).error).sort()).toStrictEqual(['message', 'name', 'stack']) +}) + +test('logger.error serializes a non-Error value without spreading it', () => { + const logMock = spyOnConsole('error') + + logger.error({ + label: 'foo', + body: 'error', + error: { code: 'auth/invalid-id-token', message: 'invalid', idToken: 'id' } + }) + + expect(logMock).toHaveBeenCalledWith( + JSON.stringify({ + level: 'ERROR', + label: 'foo', + body: 'error', + error: { name: 'auth/invalid-id-token', message: 'invalid' } + }) + ) +}) diff --git a/packages/client/src/app/_lib/logger/index.ts b/packages/client/src/app/_lib/logger/index.ts new file mode 100644 index 0000000..67bf074 --- /dev/null +++ b/packages/client/src/app/_lib/logger/index.ts @@ -0,0 +1,92 @@ +import { NEXT_PUBLIC_ENV } from '../../../constants' +import { redactMeta, serializeError } from './redact' + +/** + * structured log の単一入口。application code から console を直接呼ばず、 + * 必ずこの logger を経由する(`no-console` lint で強制している)。 + * + * public API は closed event schema。meta を持てるのは `LogEvents` に定義した + * label だけで、field は primitive に限る。新しい情報をログへ載せたいときは、 + * 値を渡す前に `LogEvents` へ label / field を追加する(agents/logging.md 参照)。 + * + * - `error` は `serializeError()` で name/message/stack/cause の限定 shape にする + * - `requestId` は api の access log と突き合わせるための共通 field(呼び出し側が明示的に渡す) + */ + +/** + * label ごとに meta として許可する field の閉じた schema。 + * secret / credential(authorization / cookie / token 等)を表す field や、 + * request / response / headers / body を丸ごと表す field を追加してはならない。 + */ +type LogEvents = { + /** Server Actions の fetch 結果(fetchUserList) */ + fetchUserList: { + status: number + url: string + } + /** Top ページの render デバッグ */ + Top: { + ok: boolean + } +} + +type BaseOptions = { + requestId?: string + body: string + error?: unknown +} + +/** `LogEvents` に定義した label は、その schema どおりの meta を渡せる。 */ +type EventLogOptions = { + [Label in keyof LogEvents]: BaseOptions & { + label: Label + meta: LogEvents[Label] + } +}[keyof LogEvents] + +/** それ以外の label は meta を持てない(`meta?: never`)。 */ +type PlainLogOptions = BaseOptions & { + label?: string + meta?: never +} + +type LogOptions = EventLogOptions | PlainLogOptions + +type Level = 'INFO' | 'ERROR' | 'DEBUG' + +function buildLog(level: Level, options: LogOptions) { + const { label, requestId, body, meta, error } = options + return { + level, + ...(label === undefined ? {} : { label }), + ...(requestId === undefined ? {} : { requestId }), + body, + ...(meta === undefined ? {} : { meta: redactMeta(meta) }), + ...(error === undefined ? {} : { error: serializeError(error) }) + } +} + +export const logger = { + log: (options: LogOptions) => { + const json = buildLog('INFO', options) + if (NEXT_PUBLIC_ENV.local) { + console.dir(json, { depth: null }) + return + } + console.log(JSON.stringify(json)) + }, + error: (options: LogOptions) => { + const json = buildLog('ERROR', options) + if (NEXT_PUBLIC_ENV.local) { + console.dir(json, { depth: null }) + return + } + console.error(JSON.stringify(json)) + }, + debug: (options: LogOptions) => { + if (!NEXT_PUBLIC_ENV.production) { + const json = buildLog('DEBUG', options) + console.dir(json, { depth: null }) + } + } +} as const diff --git a/packages/client/src/app/_lib/logger/redact.test.ts b/packages/client/src/app/_lib/logger/redact.test.ts new file mode 100644 index 0000000..9e11eab --- /dev/null +++ b/packages/client/src/app/_lib/logger/redact.test.ts @@ -0,0 +1,147 @@ +import { expect, test } from 'vite-plus/test' +import { REDACTED, UNSUPPORTED, isSensitiveKey, redactMeta, serializeError } from './redact' + +test('isSensitiveKey matches credential-ish keys regardless of case and separators', () => { + expect(isSensitiveKey('Authorization')).toBe(true) + expect(isSensitiveKey('cookie')).toBe(true) + expect(isSensitiveKey('set-cookie')).toBe(true) + expect(isSensitiveKey('Set-Cookie')).toBe(true) + expect(isSensitiveKey('password')).toBe(true) + expect(isSensitiveKey('client_secret')).toBe(true) + expect(isSensitiveKey('idToken')).toBe(true) + expect(isSensitiveKey('accessToken')).toBe(true) + expect(isSensitiveKey('refresh_token')).toBe(true) + expect(isSensitiveKey('sessionToken')).toBe(true) + expect(isSensitiveKey('x-api-key')).toBe(true) + + expect(isSensitiveKey('status')).toBe(false) + expect(isSensitiveKey('requestId')).toBe(false) + expect(isSensitiveKey('userId')).toBe(false) +}) + +test('redactMeta masks values bound to sensitive keys', () => { + const actual = redactMeta({ + status: 200, + Authorization: 'Bearer super-secret-token', + 'set-cookie': 'session=abcdef; HttpOnly', + idToken: 'id-token-value', + refreshToken: 'refresh-token-value' + }) + + expect(actual).toStrictEqual({ + status: 200, + Authorization: REDACTED, + 'set-cookie': REDACTED, + idToken: REDACTED, + refreshToken: REDACTED + }) + expect(JSON.stringify(actual)).not.toContain('super-secret-token') + expect(JSON.stringify(actual)).not.toContain('abcdef') +}) + +test('redactMeta keeps primitives and replaces non-primitive values', () => { + const actual = redactMeta({ + name: 'task', + count: 3, + ok: true, + empty: null, + missing: undefined, + headers: new Headers({ authorization: 'Bearer super-secret-token' }), + nested: { userId: 1 }, + list: [1, 2, 3] + }) + + expect(actual).toStrictEqual({ + name: 'task', + count: 3, + ok: true, + empty: null, + missing: undefined, + headers: UNSUPPORTED, + nested: UNSUPPORTED, + list: UNSUPPORTED + }) + expect(JSON.stringify(actual)).not.toContain('super-secret-token') +}) + +test('serializeError keeps only name / message / stack', () => { + const error = new Error('boom') + const actual = serializeError(error) + + expect(actual.name).toBe('Error') + expect(actual.message).toBe('boom') + expect(typeof actual.stack).toBe('string') + expect(actual.cause).toBeUndefined() +}) + +test('serializeError does not leak arbitrary enumerable properties of an error', () => { + class ProviderError extends Error { + // external SDK が request 情報を error に詰めてくるケース + config = { + headers: { authorization: 'Bearer super-secret-token' }, + body: { password: 'p@ssw0rd' } + } + accessToken = 'access-token-value' + } + const error = new ProviderError('provider failed') + error.name = 'ProviderError' + + const actual = serializeError(error) + + expect(actual.name).toBe('ProviderError') + expect(actual.message).toBe('provider failed') + expect(Object.keys(actual).sort()).toStrictEqual(['message', 'name', 'stack']) + expect(JSON.stringify(actual)).not.toContain('super-secret-token') + expect(JSON.stringify(actual)).not.toContain('access-token-value') + expect(JSON.stringify(actual)).not.toContain('p@ssw0rd') +}) + +test('serializeError follows the cause chain within a bounded depth', () => { + const error = new Error('level0', { + cause: new Error('level1', { + cause: new Error('level2', { cause: new Error('level3') }) + }) + }) + + const actual = serializeError(error) + + expect(actual.message).toBe('level0') + expect(actual.cause?.message).toBe('level1') + expect(actual.cause?.cause?.message).toBe('level2') + expect(actual.cause?.cause?.cause?.message).toBe('level3') + expect(actual.cause?.cause?.cause?.cause).toBeUndefined() +}) + +test('serializeError stops on a circular cause chain', () => { + const error = new Error('self referencing') + error.cause = error + + expect(serializeError(error).cause?.cause?.cause?.cause).toBeUndefined() +}) + +test('serializeError narrows non-Error values to name / message', () => { + expect(serializeError('boom')).toStrictEqual({ + name: 'NonError', + message: 'boom' + }) + expect(serializeError(500)).toStrictEqual({ + name: 'NonError', + message: '500' + }) + expect(serializeError(undefined)).toStrictEqual({ + name: 'NonError', + message: 'undefined' + }) + // external SDK の plain object error。message / name(なければ code)だけを残す + expect( + serializeError({ + code: 'auth/invalid-id-token', + message: 'invalid token', + idToken: 'id-token-value', + headers: { authorization: 'Bearer super-secret-token' } + }) + ).toStrictEqual({ + name: 'auth/invalid-id-token', + message: 'invalid token' + }) +}) diff --git a/packages/client/src/app/_lib/logger/redact.ts b/packages/client/src/app/_lib/logger/redact.ts new file mode 100644 index 0000000..f80e584 --- /dev/null +++ b/packages/client/src/app/_lib/logger/redact.ts @@ -0,0 +1,145 @@ +/** + * ログ出力を安全側に倒すための redaction ヘルパー。logger の単一入口 + * (`_lib/logger/index.ts`)から呼ばれる想定で、直接 console へ書き出す実装は持たない。 + * + * 第一の防御は logger の closed event schema(`logger/index.ts` の `LogEvents` 型)。 + * ここは型検査をすり抜けた値(assertion 等)に対する最後の防波堤: + * - `redactMeta()` は flat な meta を走査し、sensitive な key 名の値を + * `[REDACTED]` へ、primitive でない値を `[UNSUPPORTED]` へ置き換える + * - `serializeError()` は Error を name/message/stack/cause の限定 shape へ変換する + * + * 各パッケージは実行コンテキストが異なるため(AGENTS.md の Monorepo Guidelines)、 + * このファイルは shared へ切り出さず api/client/task がそれぞれ自己完結して持つ。 + */ + +/** 値が sensitive な key に紐づいていたことを示すプレースホルダ。 */ +export const REDACTED = '[REDACTED]' +/** primitive でない値が meta へ渡っていたことを示すプレースホルダ。 */ +export const UNSUPPORTED = '[UNSUPPORTED]' + +/** stack trace として残す最大行数(ログ量を有界にするため)。 */ +const MAX_STACK_LINES = 20 +/** cause チェーンを辿る最大段数(cause の循環でも停止させるため)。 */ +const MAX_CAUSE_DEPTH = 3 + +/** + * 正規化(小文字化 + 区切り文字除去)した key 名に対する部分一致で判定する。 + * `token` が idToken / accessToken / refreshToken / sessionToken を、 + * `cookie` が set-cookie を、それぞれまとめて拾う。 + * 判定回数を key ごとに 1 回へ抑えるため単一の正規表現にまとめている。 + */ +const SENSITIVE_KEY_PATTERN = + /authorization|cookie|password|passwd|secret|token|credential|apikey|privatekey|sessionid/ + +const KEY_SEPARATOR_PATTERN = /[-_\s.]/g + +/** ログの key 名が redaction 対象かどうかを返す。 */ +export function isSensitiveKey(key: string): boolean { + return SENSITIVE_KEY_PATTERN.test(key.toLowerCase().replace(KEY_SEPARATOR_PATTERN, '')) +} + +/** meta の field として logger が出力する値。primitive のみを許す。 */ +export type LogPrimitive = string | number | boolean | null | undefined + +/** + * ログの meta を flat に走査し、型検査をすり抜けた値を安全な形へ落とす。 + * sensitive な key 名の値は `[REDACTED]`、primitive でない値(object / + * Headers / provider response 等)は `[UNSUPPORTED]` に置き換える。 + */ +export function redactMeta(meta: Record): Record { + const result: Record = {} + for (const [key, value] of Object.entries(meta)) { + if (isSensitiveKey(key)) { + result[key] = REDACTED + continue + } + if ( + value === null || + value === undefined || + typeof value === 'string' || + typeof value === 'number' || + typeof value === 'boolean' + ) { + result[key] = value + continue + } + result[key] = UNSUPPORTED + } + return result +} + +/** Error を JSON へ安全に落とし込むための限定 shape。 */ +export type SerializedError = { + name: string + message: string + stack?: string + cause?: SerializedError +} + +function trimStack(stack: string | undefined): string | undefined { + if (!stack) { + return undefined + } + const lines = stack.split('\n') + if (lines.length <= MAX_STACK_LINES) { + return stack + } + return [ + ...lines.slice(0, MAX_STACK_LINES), + ` ... ${lines.length - MAX_STACK_LINES} more lines` + ].join('\n') +} + +function isRecord(value: unknown): value is Record { + return typeof value === 'object' && value !== null +} + +/** + * external SDK が投げる「Error ではないが name/message を持つ」オブジェクトから + * 文字列フィールドだけを取り出す。任意の enumerable property は読まない。 + */ +function serializeNonError(value: unknown): SerializedError { + if (typeof value === 'string') { + return { name: 'NonError', message: value } + } + if (typeof value === 'number' || typeof value === 'boolean' || typeof value === 'bigint') { + return { name: 'NonError', message: `${value}` } + } + if (!isRecord(value)) { + return { name: 'NonError', message: `${typeof value}` } + } + const name = + typeof value.name === 'string' + ? value.name + : typeof value.code === 'string' + ? value.code + : 'NonError' + const message = typeof value.message === 'string' ? value.message : '[unknown]' + return { name, message } +} + +function serializeErrorWithDepth(error: unknown, depth: number): SerializedError { + if (!(error instanceof Error)) { + return serializeNonError(error) + } + const cause = + error.cause !== undefined && depth < MAX_CAUSE_DEPTH + ? serializeErrorWithDepth(error.cause, depth + 1) + : undefined + const stack = trimStack(error.stack) + return { + name: error.name, + message: error.message, + ...(stack === undefined ? {} : { stack }), + ...(cause === undefined ? {} : { cause }) + } +} + +/** + * Error / external SDK error を name/message/stack/cause の限定 shape へ変換する。 + * `{ ...error }` のような spread と違い、任意の enumerable property + * (provider が詰めた credential や request payload)を持ち出さない。 + */ +export function serializeError(error: unknown): SerializedError { + return serializeErrorWithDepth(error, 0) +} diff --git a/packages/task/src/index.ts b/packages/task/src/index.ts index 0b31c65..cc3759b 100644 --- a/packages/task/src/index.ts +++ b/packages/task/src/index.ts @@ -1,5 +1,5 @@ import { parseArgs } from 'node:util' -import { logger } from './lib/logger.js' +import { logger } from './lib/logger/index.js' const { positionals } = parseArgs({ allowPositionals: true, diff --git a/packages/task/src/lib/logger.ts b/packages/task/src/lib/logger.ts deleted file mode 100644 index 591b237..0000000 --- a/packages/task/src/lib/logger.ts +++ /dev/null @@ -1,45 +0,0 @@ -import { ENV } from '../config.js' - -type Options = { - label?: string - body: string - meta?: any -} - -type ErrorOptions = Options & { - error?: any -} - -export const logger = { - log: (options: Options) => { - const json = { - ...options, - level: 'INFO' - } - if (ENV.local) { - console.dir(json, { depth: null }) - return - } - console.log(JSON.stringify(json)) - }, - error: (options: ErrorOptions) => { - const json = { - ...options, - level: 'ERROR' - } - if (ENV.local) { - console.dir(json, { depth: null }) - return - } - console.error(JSON.stringify(json)) - }, - debug: (options: Options) => { - if (!ENV.production) { - const json = { - ...options, - level: 'DEBUG' - } - console.dir(json, { depth: null }) - } - } -} as const diff --git a/packages/task/src/lib/logger/index.test.ts b/packages/task/src/lib/logger/index.test.ts new file mode 100644 index 0000000..ffee6bb --- /dev/null +++ b/packages/task/src/lib/logger/index.test.ts @@ -0,0 +1,166 @@ +import { expect, test, vi } from 'vite-plus/test' +import { logger } from './index.js' +import { REDACTED, UNSUPPORTED } from './redact.js' + +vi.mock('console') + +// console の spy は同一ファイル内の test をまたいで呼び出し履歴が蓄積するため、 +// test ごとに履歴をクリアしてから使う +function spyOnConsole(method: 'log' | 'error') { + const spy = vi.spyOn(console, method).mockImplementation(() => { + return undefined + }) + spy.mockClear() + return spy +} + +test('logger.log outputs level / label / body as a structured log', () => { + const logMock = spyOnConsole('log') + + logger.log({ label: 'foo', body: 'bar' }) + + expect(logMock).toHaveBeenCalledTimes(1) + expect(logMock).toHaveBeenCalledWith( + JSON.stringify({ + level: 'INFO', + label: 'foo', + body: 'bar' + }) + ) +}) + +test('logger.log carries requestId as a top level field', () => { + const logMock = spyOnConsole('log') + + logger.log({ + label: 'task', + requestId: 'request-id-1', + body: 'start', + meta: { command: 'migrate' } + }) + + expect(logMock).toHaveBeenCalledTimes(1) + expect(logMock).toHaveBeenCalledWith( + JSON.stringify({ + level: 'INFO', + label: 'task', + requestId: 'request-id-1', + body: 'start', + meta: { command: 'migrate' } + }) + ) +}) + +test('logger meta is a closed event schema at compile time', () => { + const logMock = spyOnConsole('log') + + // @ts-expect-error LogEvents に無い label は meta を持てない + logger.log({ label: 'unknown-label', body: 'x', meta: { command: 'migrate' } }) + + // @ts-expect-error 既知 label でも schema に無い field は渡せない + logger.log({ label: 'task', body: 'x', meta: { command: 'migrate', secret: 'x' } }) + + // @ts-expect-error meta の値は primitive のみで nested object は渡せない + logger.log({ label: 'task', body: 'x', meta: { command: { name: 'migrate' } } }) + + const payload: Record = { command: 'migrate' } + // @ts-expect-error 型の広い payload 変数を meta へ渡せない + logger.log({ label: 'task', body: 'x', meta: payload }) + + // @ts-expect-error payload 変数の spread も渡せない + logger.log({ label: 'task', body: 'x', meta: { ...payload } }) + + // 上記はいずれも型検査で弾かれることの検証であり、runtime では出力自体は行われる + expect(logMock).toHaveBeenCalledTimes(5) +}) + +test('redactMeta remains as a runtime last line of defense', () => { + const logMock = spyOnConsole('log') + + // wide な型の変数は closed event schema に代入できない(実際に型エラーになる) + const leaked: Record = { + command: 'migrate', + authorization: 'Bearer super-secret-token', + provider: { idToken: 'id-token-value' } + } + logger.log({ + label: 'task', + body: 'verified', + // @ts-expect-error 型検査をすり抜けた値が runtime で redact されることを検証する + meta: leaked + }) + + const [output] = logMock.mock.calls[0] + expect(output).not.toContain('super-secret-token') + expect(output).not.toContain('id-token-value') + expect(JSON.parse(output)).toStrictEqual({ + level: 'INFO', + label: 'task', + body: 'verified', + meta: { + command: 'migrate', + authorization: REDACTED, + provider: UNSUPPORTED + } + }) +}) + +test('logger.error serializes an Error into a limited shape', () => { + const logMock = spyOnConsole('error') + + logger.error({ + label: 'task', + requestId: 'request-id-1', + body: 'failed', + error: new Error('boom') + }) + + expect(logMock).toHaveBeenCalledTimes(1) + const [output] = logMock.mock.calls[0] + const parsed = JSON.parse(output) + expect(parsed.level).toBe('ERROR') + expect(parsed.label).toBe('task') + expect(parsed.requestId).toBe('request-id-1') + expect(parsed.error.name).toBe('Error') + expect(parsed.error.message).toBe('boom') + expect(typeof parsed.error.stack).toBe('string') +}) + +test('logger.error does not leak enumerable properties of an external error', () => { + const logMock = spyOnConsole('error') + + class ProviderError extends Error { + config = { headers: { authorization: 'Bearer super-secret-token' } } + refreshToken = 'refresh-token-value' + } + + logger.error({ + label: 'provider', + body: 'provider call failed', + error: new ProviderError('provider failed') + }) + + const [output] = logMock.mock.calls[0] + expect(output).not.toContain('super-secret-token') + expect(output).not.toContain('refresh-token-value') + expect(Object.keys(JSON.parse(output).error).sort()).toStrictEqual(['message', 'name', 'stack']) +}) + +test('logger.error serializes a non-Error value without spreading it', () => { + const logMock = spyOnConsole('error') + + logger.error({ + label: 'foo', + body: 'error', + error: { code: 'auth/invalid-id-token', message: 'invalid', idToken: 'id' } + }) + + expect(logMock).toHaveBeenCalledWith( + JSON.stringify({ + level: 'ERROR', + label: 'foo', + body: 'error', + error: { name: 'auth/invalid-id-token', message: 'invalid' } + }) + ) +}) diff --git a/packages/task/src/lib/logger/index.ts b/packages/task/src/lib/logger/index.ts new file mode 100644 index 0000000..625e07b --- /dev/null +++ b/packages/task/src/lib/logger/index.ts @@ -0,0 +1,87 @@ +import { ENV } from '../../config.js' +import { redactMeta, serializeError } from './redact.js' + +/** + * structured log の単一入口。application code から console を直接呼ばず、 + * 必ずこの logger を経由する(`no-console` lint で強制している)。 + * + * public API は closed event schema。meta を持てるのは `LogEvents` に定義した + * label だけで、field は primitive に限る。新しい情報をログへ載せたいときは、 + * 値を渡す前に `LogEvents` へ label / field を追加する(agents/logging.md 参照)。 + * + * - `error` は `serializeError()` で name/message/stack/cause の限定 shape にする + * - `requestId` は 1 実行を横断して追跡するための共通 field(呼び出し側が明示的に渡す) + */ + +/** + * label ごとに meta として許可する field の閉じた schema。 + * secret / credential(authorization / cookie / token 等)を表す field や、 + * request / response / headers / body を丸ごと表す field を追加してはならない。 + */ +type LogEvents = { + /** task runner の開始 / 終了 */ + task: { + command: string + } +} + +type BaseOptions = { + requestId?: string + body: string + error?: unknown +} + +/** `LogEvents` に定義した label は、その schema どおりの meta を渡せる。 */ +type EventLogOptions = { + [Label in keyof LogEvents]: BaseOptions & { + label: Label + meta: LogEvents[Label] + } +}[keyof LogEvents] + +/** それ以外の label は meta を持てない(`meta?: never`)。 */ +type PlainLogOptions = BaseOptions & { + label?: string + meta?: never +} + +type LogOptions = EventLogOptions | PlainLogOptions + +type Level = 'INFO' | 'ERROR' | 'DEBUG' + +function buildLog(level: Level, options: LogOptions) { + const { label, requestId, body, meta, error } = options + return { + level, + ...(label === undefined ? {} : { label }), + ...(requestId === undefined ? {} : { requestId }), + body, + ...(meta === undefined ? {} : { meta: redactMeta(meta) }), + ...(error === undefined ? {} : { error: serializeError(error) }) + } +} + +export const logger = { + log: (options: LogOptions) => { + const json = buildLog('INFO', options) + if (ENV.local) { + console.dir(json, { depth: null }) + return + } + console.log(JSON.stringify(json)) + }, + error: (options: LogOptions) => { + const json = buildLog('ERROR', options) + if (ENV.local) { + console.dir(json, { depth: null }) + return + } + console.error(JSON.stringify(json)) + }, + debug: (options: LogOptions) => { + if (!ENV.production) { + const json = buildLog('DEBUG', options) + console.dir(json, { depth: null }) + } + } +} as const diff --git a/packages/task/src/lib/logger/redact.test.ts b/packages/task/src/lib/logger/redact.test.ts new file mode 100644 index 0000000..8428865 --- /dev/null +++ b/packages/task/src/lib/logger/redact.test.ts @@ -0,0 +1,147 @@ +import { expect, test } from 'vite-plus/test' +import { REDACTED, UNSUPPORTED, isSensitiveKey, redactMeta, serializeError } from './redact.js' + +test('isSensitiveKey matches credential-ish keys regardless of case and separators', () => { + expect(isSensitiveKey('Authorization')).toBe(true) + expect(isSensitiveKey('cookie')).toBe(true) + expect(isSensitiveKey('set-cookie')).toBe(true) + expect(isSensitiveKey('Set-Cookie')).toBe(true) + expect(isSensitiveKey('password')).toBe(true) + expect(isSensitiveKey('client_secret')).toBe(true) + expect(isSensitiveKey('idToken')).toBe(true) + expect(isSensitiveKey('accessToken')).toBe(true) + expect(isSensitiveKey('refresh_token')).toBe(true) + expect(isSensitiveKey('sessionToken')).toBe(true) + expect(isSensitiveKey('x-api-key')).toBe(true) + + expect(isSensitiveKey('status')).toBe(false) + expect(isSensitiveKey('requestId')).toBe(false) + expect(isSensitiveKey('userId')).toBe(false) +}) + +test('redactMeta masks values bound to sensitive keys', () => { + const actual = redactMeta({ + status: 200, + Authorization: 'Bearer super-secret-token', + 'set-cookie': 'session=abcdef; HttpOnly', + idToken: 'id-token-value', + refreshToken: 'refresh-token-value' + }) + + expect(actual).toStrictEqual({ + status: 200, + Authorization: REDACTED, + 'set-cookie': REDACTED, + idToken: REDACTED, + refreshToken: REDACTED + }) + expect(JSON.stringify(actual)).not.toContain('super-secret-token') + expect(JSON.stringify(actual)).not.toContain('abcdef') +}) + +test('redactMeta keeps primitives and replaces non-primitive values', () => { + const actual = redactMeta({ + name: 'task', + count: 3, + ok: true, + empty: null, + missing: undefined, + headers: new Headers({ authorization: 'Bearer super-secret-token' }), + nested: { userId: 1 }, + list: [1, 2, 3] + }) + + expect(actual).toStrictEqual({ + name: 'task', + count: 3, + ok: true, + empty: null, + missing: undefined, + headers: UNSUPPORTED, + nested: UNSUPPORTED, + list: UNSUPPORTED + }) + expect(JSON.stringify(actual)).not.toContain('super-secret-token') +}) + +test('serializeError keeps only name / message / stack', () => { + const error = new Error('boom') + const actual = serializeError(error) + + expect(actual.name).toBe('Error') + expect(actual.message).toBe('boom') + expect(typeof actual.stack).toBe('string') + expect(actual.cause).toBeUndefined() +}) + +test('serializeError does not leak arbitrary enumerable properties of an error', () => { + class ProviderError extends Error { + // external SDK が request 情報を error に詰めてくるケース + config = { + headers: { authorization: 'Bearer super-secret-token' }, + body: { password: 'p@ssw0rd' } + } + accessToken = 'access-token-value' + } + const error = new ProviderError('provider failed') + error.name = 'ProviderError' + + const actual = serializeError(error) + + expect(actual.name).toBe('ProviderError') + expect(actual.message).toBe('provider failed') + expect(Object.keys(actual).sort()).toStrictEqual(['message', 'name', 'stack']) + expect(JSON.stringify(actual)).not.toContain('super-secret-token') + expect(JSON.stringify(actual)).not.toContain('access-token-value') + expect(JSON.stringify(actual)).not.toContain('p@ssw0rd') +}) + +test('serializeError follows the cause chain within a bounded depth', () => { + const error = new Error('level0', { + cause: new Error('level1', { + cause: new Error('level2', { cause: new Error('level3') }) + }) + }) + + const actual = serializeError(error) + + expect(actual.message).toBe('level0') + expect(actual.cause?.message).toBe('level1') + expect(actual.cause?.cause?.message).toBe('level2') + expect(actual.cause?.cause?.cause?.message).toBe('level3') + expect(actual.cause?.cause?.cause?.cause).toBeUndefined() +}) + +test('serializeError stops on a circular cause chain', () => { + const error = new Error('self referencing') + error.cause = error + + expect(serializeError(error).cause?.cause?.cause?.cause).toBeUndefined() +}) + +test('serializeError narrows non-Error values to name / message', () => { + expect(serializeError('boom')).toStrictEqual({ + name: 'NonError', + message: 'boom' + }) + expect(serializeError(500)).toStrictEqual({ + name: 'NonError', + message: '500' + }) + expect(serializeError(undefined)).toStrictEqual({ + name: 'NonError', + message: 'undefined' + }) + // external SDK の plain object error。message / name(なければ code)だけを残す + expect( + serializeError({ + code: 'auth/invalid-id-token', + message: 'invalid token', + idToken: 'id-token-value', + headers: { authorization: 'Bearer super-secret-token' } + }) + ).toStrictEqual({ + name: 'auth/invalid-id-token', + message: 'invalid token' + }) +}) diff --git a/packages/task/src/lib/logger/redact.ts b/packages/task/src/lib/logger/redact.ts new file mode 100644 index 0000000..6daea31 --- /dev/null +++ b/packages/task/src/lib/logger/redact.ts @@ -0,0 +1,145 @@ +/** + * ログ出力を安全側に倒すための redaction ヘルパー。logger の単一入口 + * (`lib/logger/index.ts`)から呼ばれる想定で、直接 console へ書き出す実装は持たない。 + * + * 第一の防御は logger の closed event schema(`logger/index.ts` の `LogEvents` 型)。 + * ここは型検査をすり抜けた値(assertion 等)に対する最後の防波堤: + * - `redactMeta()` は flat な meta を走査し、sensitive な key 名の値を + * `[REDACTED]` へ、primitive でない値を `[UNSUPPORTED]` へ置き換える + * - `serializeError()` は Error を name/message/stack/cause の限定 shape へ変換する + * + * 各パッケージは実行コンテキストが異なるため(AGENTS.md の Monorepo Guidelines)、 + * このファイルは shared へ切り出さず api/client/task がそれぞれ自己完結して持つ。 + */ + +/** 値が sensitive な key に紐づいていたことを示すプレースホルダ。 */ +export const REDACTED = '[REDACTED]' +/** primitive でない値が meta へ渡っていたことを示すプレースホルダ。 */ +export const UNSUPPORTED = '[UNSUPPORTED]' + +/** stack trace として残す最大行数(ログ量を有界にするため)。 */ +const MAX_STACK_LINES = 20 +/** cause チェーンを辿る最大段数(cause の循環でも停止させるため)。 */ +const MAX_CAUSE_DEPTH = 3 + +/** + * 正規化(小文字化 + 区切り文字除去)した key 名に対する部分一致で判定する。 + * `token` が idToken / accessToken / refreshToken / sessionToken を、 + * `cookie` が set-cookie を、それぞれまとめて拾う。 + * 判定回数を key ごとに 1 回へ抑えるため単一の正規表現にまとめている。 + */ +const SENSITIVE_KEY_PATTERN = + /authorization|cookie|password|passwd|secret|token|credential|apikey|privatekey|sessionid/ + +const KEY_SEPARATOR_PATTERN = /[-_\s.]/g + +/** ログの key 名が redaction 対象かどうかを返す。 */ +export function isSensitiveKey(key: string): boolean { + return SENSITIVE_KEY_PATTERN.test(key.toLowerCase().replace(KEY_SEPARATOR_PATTERN, '')) +} + +/** meta の field として logger が出力する値。primitive のみを許す。 */ +export type LogPrimitive = string | number | boolean | null | undefined + +/** + * ログの meta を flat に走査し、型検査をすり抜けた値を安全な形へ落とす。 + * sensitive な key 名の値は `[REDACTED]`、primitive でない値(object / + * Headers / provider response 等)は `[UNSUPPORTED]` に置き換える。 + */ +export function redactMeta(meta: Record): Record { + const result: Record = {} + for (const [key, value] of Object.entries(meta)) { + if (isSensitiveKey(key)) { + result[key] = REDACTED + continue + } + if ( + value === null || + value === undefined || + typeof value === 'string' || + typeof value === 'number' || + typeof value === 'boolean' + ) { + result[key] = value + continue + } + result[key] = UNSUPPORTED + } + return result +} + +/** Error を JSON へ安全に落とし込むための限定 shape。 */ +export type SerializedError = { + name: string + message: string + stack?: string + cause?: SerializedError +} + +function trimStack(stack: string | undefined): string | undefined { + if (!stack) { + return undefined + } + const lines = stack.split('\n') + if (lines.length <= MAX_STACK_LINES) { + return stack + } + return [ + ...lines.slice(0, MAX_STACK_LINES), + ` ... ${lines.length - MAX_STACK_LINES} more lines` + ].join('\n') +} + +function isRecord(value: unknown): value is Record { + return typeof value === 'object' && value !== null +} + +/** + * external SDK が投げる「Error ではないが name/message を持つ」オブジェクトから + * 文字列フィールドだけを取り出す。任意の enumerable property は読まない。 + */ +function serializeNonError(value: unknown): SerializedError { + if (typeof value === 'string') { + return { name: 'NonError', message: value } + } + if (typeof value === 'number' || typeof value === 'boolean' || typeof value === 'bigint') { + return { name: 'NonError', message: `${value}` } + } + if (!isRecord(value)) { + return { name: 'NonError', message: `${typeof value}` } + } + const name = + typeof value.name === 'string' + ? value.name + : typeof value.code === 'string' + ? value.code + : 'NonError' + const message = typeof value.message === 'string' ? value.message : '[unknown]' + return { name, message } +} + +function serializeErrorWithDepth(error: unknown, depth: number): SerializedError { + if (!(error instanceof Error)) { + return serializeNonError(error) + } + const cause = + error.cause !== undefined && depth < MAX_CAUSE_DEPTH + ? serializeErrorWithDepth(error.cause, depth + 1) + : undefined + const stack = trimStack(error.stack) + return { + name: error.name, + message: error.message, + ...(stack === undefined ? {} : { stack }), + ...(cause === undefined ? {} : { cause }) + } +} + +/** + * Error / external SDK error を name/message/stack/cause の限定 shape へ変換する。 + * `{ ...error }` のような spread と違い、任意の enumerable property + * (provider が詰めた credential や request payload)を持ち出さない。 + */ +export function serializeError(error: unknown): SerializedError { + return serializeErrorWithDepth(error, 0) +} diff --git a/packages/task/src/tasks/migrate.ts b/packages/task/src/tasks/migrate.ts index 167ca19..9718fdd 100644 --- a/packages/task/src/tasks/migrate.ts +++ b/packages/task/src/tasks/migrate.ts @@ -1,6 +1,6 @@ import { execFile } from 'node:child_process' import { promisify } from 'node:util' -import { logger } from '../lib/logger.js' +import { logger } from '../lib/logger/index.js' const execFileAsync = promisify(execFile) diff --git a/vite.config.ts b/vite.config.ts index 32d0e76..e282d32 100644 --- a/vite.config.ts +++ b/vite.config.ts @@ -53,8 +53,37 @@ export default defineConfig({ } }, { - files: ['**/*.test.ts'], + // structured logging の規約(agents/logging.md)。logger を持つ + // api/client/task では console を logger 実装だけに閉じ込め、logger の + // 引数は closed event schema の型検査(excess property check)が確実に + // 効く object literal に限定する。 + files: [ + 'packages/api/src/**', + 'packages/client/src/**', + 'packages/task/src/**' + ], + rules: { + 'coding-style/enforce-logger-literal': 'error', + 'no-console': 'error' + } + }, + { + // logger 実装本体だけが console へ書き出す(structured log の単一入口)。 + files: [ + 'packages/api/src/lib/logger/index.ts', + 'packages/client/src/app/_lib/logger/index.ts', + 'packages/task/src/lib/logger/index.ts' + ], + rules: { + 'no-console': 'off' + } + }, + { + files: ['**/*.test.ts', '**/*.test.tsx'], rules: { + // テストは logger の出力先である console を spy/assert するため対象外にする + // (enforce-logger-literal 側の除外はルール実装がファイル名で判定する)。 + 'no-console': 'off', // 並列耐性テストの規約(AGENTS.md 参照)として describe() を禁止する。 // 一時的な reminder ではなく恒久的なコーディング規約のため error にする。 'no-restricted-imports': [