refactor(logging): 二次审计修复 oracle 漏掉的可观测性缺口与占位符冗余
二次深度审计发现:
1. shutdown.ts SIGINT/SIGTERM 路径完全沉默——生产环境 k8s pod 终止时
操作者在日志里看不到任何痕迹。补 getLogger(['shutdown']) 三条日志:
- "Draining for shutdown" {signal, graceMs} (优雅关停起点)
- "Forcing exit on repeated signal" {signal} (二次信号强制退出)
- "DB pool closed, exiting" (干净退出确认)
2. interceptors.ts 与 shutdown.ts 的 {error}/{signal} 占位符在 JSON 模式
下导致 message 字段重复 inspect 转义 properties 里的同一份内容
(Error/对象会被 JSON.stringify 内联进 message,引号被反斜杠转义)。
规则收敛:占位符仅用于"想要内联渲染"的基本类型(id、count、duration),
对象/Error 直接放 properties,message 保持人类可读短句。
3. AGENTS.md Logging 段更新示例与规则,反映实际最佳实践。
端到端验证(compose + Postgres 18-alpine):
- /api/rpc/todo/list 成功 → logger=db level=INFO 输出 SQL ✓
- /api/rpc/todo/create 校验失败 → logger=api level=ERROR
message="Unhandled error in ORPC handler" 干净,properties.error
完整保留 code/status/message/data 字段 ✓
- SIGTERM → 三条 shutdown logger 事件按预期输出 ✓
- typecheck / test 3/3 / build / compile 117M 全绿 ✓
This commit is contained in:
@@ -131,11 +131,11 @@ All server-side logging goes through `src/server/logger.ts`, a thin wrapper over
|
|||||||
import { getLogger } from '@/server/logger'
|
import { getLogger } from '@/server/logger'
|
||||||
const logger = getLogger(['feature', 'subsystem'])
|
const logger = getLogger(['feature', 'subsystem'])
|
||||||
logger.info('Created todo {id}', { id })
|
logger.info('Created todo {id}', { id })
|
||||||
logger.error('DB write failed: {err}', { err })
|
logger.error('DB write failed', { error })
|
||||||
```
|
```
|
||||||
|
|
||||||
- Categories are hierarchical arrays — they show up as dot-paths in JSON output (`"logger":"feature.subsystem"`) and let you filter by prefix when shipping logs.
|
- Categories are hierarchical arrays — they show up as dot-paths in JSON output (`"logger":"feature.subsystem"`) and let you filter by prefix when shipping logs.
|
||||||
- The `{name}` placeholders in the message string are filled from the second-arg properties object. Don't string-concatenate or template-literal — that defeats structured logging.
|
- The `{name}` placeholders are for **primitive** values you want rendered inline (numbers, short strings, IDs). For objects, errors, and anything multi-field, omit the placeholder and just pass the value in properties — `logger.error('Auth failed', { error, userId })` keeps the message clean while properties stay structured. Never string-concatenate or template-literal — that defeats structured logging.
|
||||||
- Format is `pretty` (icons + ANSI) on TTY, `json` (one-line JSON) when piped — perfect for Loki/Datadog/CloudWatch ingestion. Override with `LOG_FORMAT`.
|
- Format is `pretty` (icons + ANSI) on TTY, `json` (one-line JSON) when piped — perfect for Loki/Datadog/CloudWatch ingestion. Override with `LOG_FORMAT`.
|
||||||
- Drizzle SQL queries are logged at `info` under category `['db']` when `LOG_DB=true`, via `@logtape/drizzle-orm`'s `DrizzleLogger` adapter (constructed in `src/server/db/index.ts`). The `info` level is intentional: flipping `LOG_DB=true` alone is enough — no need to also lower `LOG_LEVEL`.
|
- Drizzle SQL queries are logged at `info` under category `['db']` when `LOG_DB=true`, via `@logtape/drizzle-orm`'s `DrizzleLogger` adapter (constructed in `src/server/db/index.ts`). The `info` level is intentional: flipping `LOG_DB=true` alone is enough — no need to also lower `LOG_LEVEL`.
|
||||||
- `src/server/api/interceptors.ts` calls `getLogger(['api']).error(...)` from `logError`. CLI subcommands lazy-import the logger inside `run()` — they are still required to be side-effect-free at module top (citty eager-loads for `--help`).
|
- `src/server/api/interceptors.ts` calls `getLogger(['api']).error(...)` from `logError`. CLI subcommands lazy-import the logger inside `run()` — they are still required to be side-effect-free at module top (citty eager-loads for `--help`).
|
||||||
|
|||||||
@@ -5,7 +5,7 @@ import { getLogger } from '@/server/logger'
|
|||||||
const logger = getLogger(['api'])
|
const logger = getLogger(['api'])
|
||||||
|
|
||||||
export const logError = (error: unknown) => {
|
export const logError = (error: unknown) => {
|
||||||
logger.error('Unhandled error in ORPC handler: {error}', { error })
|
logger.error('Unhandled error in ORPC handler', { error })
|
||||||
}
|
}
|
||||||
|
|
||||||
export const handleValidationError = (error: unknown) => {
|
export const handleValidationError = (error: unknown) => {
|
||||||
|
|||||||
@@ -1,21 +1,28 @@
|
|||||||
import { db } from '@/server/db'
|
import { db } from '@/server/db'
|
||||||
|
import { getLogger } from '@/server/logger'
|
||||||
|
|
||||||
export default () => {
|
export default () => {
|
||||||
if (import.meta.dev) return
|
if (import.meta.dev) return
|
||||||
|
|
||||||
|
const logger = getLogger(['shutdown'])
|
||||||
let exiting = false
|
let exiting = false
|
||||||
|
|
||||||
const shutdown = () => {
|
const shutdown = (signal: NodeJS.Signals) => {
|
||||||
if (exiting) {
|
if (exiting) {
|
||||||
|
logger.warn('Forcing exit on repeated signal', { signal })
|
||||||
process.exit(0)
|
process.exit(0)
|
||||||
}
|
}
|
||||||
exiting = true
|
exiting = true
|
||||||
|
logger.info('Draining for shutdown', { signal, graceMs: 500 })
|
||||||
|
|
||||||
setTimeout(() => {
|
setTimeout(() => {
|
||||||
db.$client.end().finally(() => process.exit(0))
|
db.$client.end().finally(() => {
|
||||||
|
logger.info('DB pool closed, exiting')
|
||||||
|
process.exit(0)
|
||||||
|
})
|
||||||
}, 500)
|
}, 500)
|
||||||
}
|
}
|
||||||
|
|
||||||
process.on('SIGINT', shutdown)
|
process.on('SIGINT', () => shutdown('SIGINT'))
|
||||||
process.on('SIGTERM', shutdown)
|
process.on('SIGTERM', () => shutdown('SIGTERM'))
|
||||||
}
|
}
|
||||||
|
|||||||
Reference in New Issue
Block a user