/**
* pino の実出力を捕捉して検証するスモークテスト。
* 目視確認は再現性が無く「書いたが一度も動いていない」状態を見逃すため、
* 完了条件の確認をここで機械化している(logging-design.md §10)。
*/
import { afterEach, describe, expect, test, vi } from "vitest";
import { createLogger, emitTo } from "@/lib/logger";
import { runWithRequestId } from "@/lib/logger/context";
import type { LogEvent } from "@/lib/logger/events";
import { FORBIDDEN_LOG_FIELDS } from "@/lib/logger/redact";
/** pino の出力先を差し替えて1行 JSON を集める */
function captureLines(): { lines: string[]; stream: { write(s: string): void } } {
const lines: string[] = [];
return {
lines,
stream: {
write(s: string) {
lines.push(s);
},
},
};
}
const baseEvent: LogEvent = {
event: "api.error",
route: "/api/clean-logs",
method: "GET",
error_code: "internal_error",
error_message: "内部エラーが発生しました",
http_status: 500,
};
function emitOne(
event: LogEvent,
level: "info" | "warn" | "error" = "info",
err?: unknown
): Record<string, unknown> {
const { lines, stream } = captureLines();
const target = createLogger(stream);
runWithRequestId("smoke-req-0001", () => {
emitTo(target, level, event, err);
});
expect(lines).toHaveLength(1);
return JSON.parse(lines[0]) as Record<string, unknown>;
}
afterEach(() => {
vi.unstubAllEnvs();
});
describe("logger smoke", () => {
test("timestamp が ISO 8601 +09:00(ミリ秒付き)で出る", () => {
const out = emitOne(baseEvent);
expect(out.timestamp).toMatch(
/^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}\+09:00$/
);
// pino 既定の epoch ms フィールドが残っていないこと
expect(out.time).toBeUndefined();
});
test("level が数値ではなく文字列で出る", () => {
expect(emitOne(baseEvent, "info").level).toBe("info");
expect(emitOne(baseEvent, "warn").level).toBe("warn");
expect(emitOne(baseEvent, "error").level).toBe("error");
});
test("request_id と data_source が mixin で自動付与される", () => {
const out = emitOne(baseEvent);
expect(out.request_id).toBe("smoke-req-0001");
expect(out.data_source).toBe("fixtures");
});
test("request_id 未設定でもキーが消えず '-' になる", () => {
const { lines, stream } = captureLines();
emitTo(createLogger(stream), "info", baseEvent);
const out = JSON.parse(lines[0]) as Record<string, unknown>;
expect(out.request_id).toBe("-");
});
test("err は error レベルで message / stack ごと出る", () => {
const out = emitOne(baseEvent, "error", new Error("boom"));
const err = out.err as { message?: string; stack?: string } | undefined;
expect(err?.message).toBe("boom");
expect(err?.stack).toBeTruthy();
});
});
describe("instrumentation のイベント", () => {
test("app.start に LOG_LEVEL と data_source が載る", () => {
const out = emitOne({
event: "app.start",
log_level: "info",
node_env: "production",
next_runtime: "nodejs",
});
expect(out.event).toBe("app.start");
expect(out.log_level).toBe("info");
expect(out.data_source).toBe("fixtures");
});
test("app.uncaught は api.error と別イベントで出る", () => {
const out = emitOne(
{
event: "app.uncaught",
route: "/api/clean-logs",
method: "GET",
route_path: "/api/clean-logs",
router_kind: "App Router",
route_type: "route",
revalidate_reason: undefined,
error_digest: undefined,
},
"error",
new Error("uncaught boom")
);
expect(out.event).toBe("app.uncaught");
expect(out.event).not.toBe("api.error");
expect((out.err as { message?: string }).message).toBe("uncaught boom");
});
});
/**
* 判定ログは「入力の生値」「その時点のしきい値」「結果」の3点セットが揃って初めて
* 後から再現できる(logging-design.md §5)。欠けても型は通るのでここで固定する。
*/
describe("judge.* の3点セット", () => {
test("judge.advice に入力・しきい値・結果が揃う", () => {
const out = emitOne({
event: "judge.advice",
route: "/api/clean-logs/[id]/advice",
method: "GET",
facility_id: 12,
clean_log_id: 34,
departed: false,
raw_completion_rate: 89.5,
consecutive_problem_days: 2,
status_1h: "待機中",
status_30m: "ハンドルアップ",
thresholds_used: {
excellent: 90,
good: 70,
poor: 10,
level2Days: 2,
level3Days: 3,
},
result_rules: ["R1", "R3", "B2"],
});
// 入力は丸める前の生値のまま(89.5 を 90 にしない)
expect(out.raw_completion_rate).toBe(89.5);
expect(out.departed).toBe(false);
expect(out.consecutive_problem_days).toBe(2);
expect(out.thresholds_used).toEqual({
excellent: 90,
good: 70,
poor: 10,
level2Days: 2,
level3Days: 3,
});
expect(out.result_rules).toEqual(["R1", "R3", "B2"]);
// 施設は ID で参照する
expect(out.facility_id).toBe(12);
expect(out).not.toHaveProperty("facility_name");
});
test("judge.advice: 事前チェックの予定が無い(status が null)行も null のまま記録される(D-171)", () => {
const out = emitOne({
event: "judge.advice",
route: "/api/clean-logs/[id]/advice",
method: "GET",
facility_id: 12,
clean_log_id: 34,
departed: true,
raw_completion_rate: 95,
consecutive_problem_days: 0,
status_1h: null,
status_30m: null,
thresholds_used: {
excellent: 90,
good: 70,
poor: 10,
level2Days: 2,
level3Days: 3,
},
result_rules: [],
});
// ★「予定が無い」と「項目が無い」を区別できるよう、null を落とさない★
expect(out.status_1h).toBeNull();
expect(out.status_30m).toBeNull();
});
test("judge.escalation に入力・しきい値・結果が揃う", () => {
const out = emitOne({
event: "judge.escalation",
route: "/api/clean-logs/[id]/advice",
method: "GET",
facility_id: 12,
consecutive_problem_days: 3,
thresholds_used: { level2Days: 2, level3Days: 3 },
result_level: "L3",
});
expect(out.consecutive_problem_days).toBe(3);
expect(out.thresholds_used).toEqual({ level2Days: 2, level3Days: 3 });
expect(out.result_level).toBe("L3");
});
test("問題なしの結果(null)もキーが消えずに残る", () => {
const { lines, stream } = captureLines();
emitTo(createLogger(stream), "info", {
event: "judge.escalation",
route: "/api/clean-logs/[id]/advice",
method: "GET",
consecutive_problem_days: 0,
thresholds_used: { level2Days: 2, level3Days: 3 },
result_level: null,
});
const out = JSON.parse(lines[0]) as Record<string, unknown>;
expect(out).toHaveProperty("result_level");
expect(out.result_level).toBeNull();
});
});
describe("forbidden fields in real output", () => {
/** 型は allowlist なので、混入経路(スプレッド等)を模して as で流し込む */
const leaky = {
...baseEvent,
facility_name: "ダミー店舗",
nested: { comment: "自由記述", phone: "000-0000-0000" },
} as unknown as LogEvent;
test("本番では例外を投げず、禁止フィールドを取り除いて出力し、別途warnも出る", () => {
vi.stubEnv("NODE_ENV", "production");
const { lines, stream } = captureLines();
const target = createLogger(stream);
expect(() =>
runWithRequestId("smoke-req-0002", () => {
emitTo(target, "info", leaky);
})
).not.toThrow();
// 1行目: 禁止フィールド検出を伝えるwarn(値は載せずキー名のみ)
// 2行目: 元のイベント本体(禁止キーを除去した上で、元のレベル=infoのまま出力)
expect(lines).toHaveLength(2);
const warnLine = JSON.parse(lines[0]) as Record<string, unknown>;
expect(warnLine.level).toBe("warn");
expect(warnLine.event).toBe("log.forbidden_fields_stripped");
expect(warnLine.forbidden_keys).toEqual(
expect.arrayContaining(["facility_name", "comment", "phone"])
);
const bodyLine = JSON.parse(lines[1]) as Record<string, unknown>;
expect(bodyLine.level).toBe("info");
// 落としてよいのは禁止キーだけ。許可フィールドは残る
expect(bodyLine.route).toBe("/api/clean-logs");
expect(bodyLine.request_id).toBe("smoke-req-0002");
for (const field of FORBIDDEN_LOG_FIELDS) {
expect(bodyLine).not.toHaveProperty(field);
}
// どちらの行にも値(施設名・電話番号・自由記述)そのものが残っていないこと
const raw = lines.join("\n");
expect(raw).not.toContain("ダミー店舗");
expect(raw).not.toContain("000-0000-0000");
expect(raw).not.toContain("自由記述");
});
test("非本番では例外を投げて開発中に気づかせる", () => {
vi.stubEnv("NODE_ENV", "development");
const { lines, stream } = captureLines();
const target = createLogger(stream);
expect(() => emitTo(target, "info", leaky)).toThrow(/facility_name/);
expect(lines).toHaveLength(0);
});
test("許可フィールドのみのイベントは本番でも1行だけ・warnは出ない", () => {
vi.stubEnv("NODE_ENV", "production");
const out = emitOne(baseEvent); // emitOne内部で lines.length===1 を検証済み
expect(out.level).toBe("info");
});
});
describe("forbidden fields on err(例外の独自プロパティ)", () => {
/** Prisma のエラーを模した、meta に認証情報を持つ例外 */
function leakyError(): Error {
const err = new Error("Unique constraint failed") as Error & {
code: string;
meta: Record<string, unknown>;
};
err.code = "P2002";
err.meta = {
authorization: "Bearer secret-token-value",
nested: { cookie: "dwatch_session=secret-cookie-value" },
facility_id: 1,
};
return err;
}
test("本番では err の禁止キーを除去して出力し、別途warnも出る", () => {
vi.stubEnv("NODE_ENV", "production");
const { lines, stream } = captureLines();
const target = createLogger(stream);
expect(() =>
runWithRequestId("smoke-req-0003", () => {
emitTo(target, "error", baseEvent, leakyError());
})
).not.toThrow();
expect(lines).toHaveLength(2);
const warnLine = JSON.parse(lines[0]) as Record<string, unknown>;
expect(warnLine.event).toBe("log.forbidden_fields_stripped");
expect(warnLine.forbidden_keys).toEqual(
expect.arrayContaining(["authorization", "cookie"])
);
const bodyLine = JSON.parse(lines[1]) as Record<string, unknown>;
const errOut = bodyLine.err as {
message?: string;
stack?: string;
code?: string;
meta?: Record<string, unknown>;
};
// デバッグに必要な message / stack は維持する
expect(errOut.message).toBe("Unique constraint failed");
expect(errOut.stack).toBeTruthy();
expect(errOut.code).toBe("P2002");
// 禁止キーは消え、許可キーは残る
expect(errOut.meta).toEqual({ facility_id: 1, nested: {} });
for (const field of FORBIDDEN_LOG_FIELDS) {
expect(errOut.meta).not.toHaveProperty(field);
}
// 値そのものがどちらの行にも残っていないこと
const raw = lines.join("\n");
expect(raw).not.toContain("secret-token-value");
expect(raw).not.toContain("secret-cookie-value");
});
test("非本番では err の禁止キーで例外を投げ、1行も出さない", () => {
vi.stubEnv("NODE_ENV", "development");
const { lines, stream } = captureLines();
const target = createLogger(stream);
expect(() => emitTo(target, "error", baseEvent, leakyError())).toThrow(
/authorization/
);
expect(lines).toHaveLength(0);
});
test("禁止キーの無い err は本番でも1行だけ・warnは出ない", () => {
vi.stubEnv("NODE_ENV", "production");
const err = new Error("boom") as Error & { code: string };
err.code = "P2002";
const out = emitOne(baseEvent, "error", err);
const errOut = out.err as { message?: string; code?: string };
expect(errOut.message).toBe("boom");
expect(errOut.code).toBe("P2002");
});
});