Logging 架構設計

核心概念:logging 是橫切關注點,設計上用 ambient static singleton(全域一份實作)+ AsyncLocalStorage 自動串接 trace,而非靠 DI 到處注入。以 CarbonX / Madeleine(NestJS + Winston + GCP Cloud Logging)為具體範例:從 bootstrap 設定、全域機制、Winston format pipeline,到 Cloud Logging 與 trace 串接。專案內另有 TRACE_CONTEXT.md 專講 trace context 傳遞細節,兩文互補。

1. 全景圖

flowchart TD
    boot["<b>main.ts bootstrap</b>(只跑一次)<br/>NestFactory.create(App, {<br/>logger: getLogger('madeleine') })"]
    shell["<b>任何 class</b><br/>new Logger('RawMaterialService').log('...')<br/><i>薄殼,只帶 context</i>"]
    static["<b>Logger.staticInstanceRef</b>(全域 static)<br/>= Winston logger<br/><i>singleton,全專案只有 1 個</i>"]
    pipe["<b>format pipeline</b>(每寫一筆 log)<br/>autoTraceContextFormat<br/>→ autoActivityContextFormat<br/>→ cloudLoggingFormat"]
    local["<b>NODE_ENV=local</b><br/>Console(彩色 pretty)"]
    deployed["<b>deployed</b><br/>Console(JSON)<br/>+ LoggingWinston → GCP Cloud Logging"]

    boot -- "Logger.overrideLogger()" --> static
    shell -- "轉發(自己不寫)" --> static
    static --> pipe
    pipe -->|NODE_ENV=local| local
    pipe -->|其他| deployed

    classDef impl fill:#e3f2fd,stroke:#1565c0,color:#0d1b2a;
    classDef shell fill:#fff8e1,stroke:#f9a825,color:#0d1b2a;
    classDef sink fill:#e8f5e9,stroke:#2e7d32,color:#0d1b2a;
    class static,pipe impl;
    class boot,shell shell;
    class local,deployed sink;

核心檔案:

檔案角色
src/util/logging-util.tsgetLogger() 工廠 + 三個 Winston format + toLoggableError()
src/main.ts (L18-20)getLogger('madeleine') 設為全 app 預設 logger
src/context/trace-context.store.tsAsyncLocalStorage 存 trace context,提供 getTraceId()
src/context/activity-log-context.store.tsAsyncLocalStorage 存 Temporal activity metadata
src/middlewares/trace-context.middleware.tsHTTP 入口解析 X-Cloud-Trace-Context

2. 「兩個 logger」— 最容易混淆的地方

實際上有兩個不同的東西,別搞混:

getLogger('madeleine') 回傳的new Logger(ClassName.name)
是什麼真正幹活的實作(Winston,寫 Console / Cloud Logging)輕量 facade / 代理殼
有幾個全專案 1 個(singleton)每個 class 各 new 一個
存了什麼transport、format pipeline 等真正設定只存一個 context 字串(class 名)
誰真的輸出把工作轉發給左邊那個

this.logger 不是 getLogger() 那個 service 本身,而是一個只記著「我是誰」的薄殼。

為什麼每個地方都有 this.logger 可用 — 不是 DI,是全域 static

Logger(來自 @nestjs/common)內部簡化版:

class Logger {
  // ★ 類別層級靜態欄位,全 app 共用一份
  private static staticInstanceRef: LoggerService = defaultConsoleLogger;
 
  constructor(private context: string) {}   // new 時只記住 context
 
  log(message) {
    Logger.staticInstanceRef.log(message, this.context);  // 自己不寫,轉發給全域 static
  }
}

main.ts 這段的本質:

NestFactory.create(App, { logger: getLogger('madeleine') })
//  ↑ Nest 內部呼叫 Logger.overrideLogger(getLogger('madeleine'))
//    → 把 staticInstanceRef 換成我們的 Winston logger

所以「到處都能用」不是因為它被注入到每個 class,而是因為 new Logger() 這個殼內部都指向同一個 class static。就像 console.log 到處能用一樣 —— 它是 ambient(環境級)singleton。相關:JS 中的 Singleton

這樣讓大家共用一份合理嗎?—— 合理,而且刻意

Logging 是橫切關注點(cross-cutting concern)

  • 業務 service 有邊界 → 誰要用誰 DI 注入,受 module 封裝、有生命週期。
  • logging 相反:每個角落都要記,且該記到同一處、同一種格式。若也走 DI,每個 class 都得在 constructor 多注入一個 logger,repository / guard / filter 注入還很麻煩。

DI 適合「有邊界、要管依賴」的東西;logging 是「無所不在、共用一份」的橫切能力,所以走全域 static 而非注入。

那為什麼還要 new Logger(ClassName.name)?

實作只有一個,但每個 class 仍各 new 一個殼,是為了帶上 ClassName.name(context),讓每筆 log 知道自己是哪個 class 印的。薄殼帶 context,實作負責格式與 trace 注入 —— 分工,背後是同一支筆。


3. 哪些地方寫 log

實測 new Logger( 出現分佈:

檔案類型檔案數說明
service56業務邏輯主場
repository52✅ 會寫(碰 DB,記 query 失敗等)
controller16進入點、參數
activity9Temporal activity
processor / consumer7Bull queue
guard / filter / middleware / strategy各 1–2認證、例外、request log
module0❌ 不寫

判斷原則:有 runtime 邏輯 / 會出錯的地方就寫;純設定/接線的不寫。

  • ✅ service、repository、controller、guard、filter、processor、activity
  • ❌ module(只是啟動時接線的裝配檔)、entity、dto、interface、const/enum

每個要寫 log 的 class 開頭放(CLAUDE.md 規定):

private readonly logger = new Logger(ClassName.name);

4. getLogger() 內部 — Winston 組裝

src/util/logging-util.ts

let logger: LoggerService;
 
export function getLogger(serviceName: string): LoggerService {
  if (logger) return logger;   // ★ singleton 守衛,全專案只造一次
 
  // local:彩色 pretty console
  const consoleSettings = { format: winston.format.combine(
    autoTraceContextFormat(),
    autoActivityContextFormat(),
    winston.format.timestamp({ format: 'YYYY-MM-DD HH:mm:ss.SSS' }),
    nestWinstonModuleUtilities.format.nestLike(serviceName, { colors: true, prettyPrint: true }),
  )};
 
  // deployed:JSON + Cloud Logging severity
  const productionFormat = winston.format.combine(
    autoTraceContextFormat(),
    autoActivityContextFormat(),
    cloudLoggingFormat(),
    winston.format.timestamp({ format: 'YYYY-MM-DD HH:mm:ss.SSS' }),
    winston.format.json(),
  );
 
  const transportsOption = process.env.NODE_ENV === 'local'
    ? [new transports.Console(consoleSettings)]
    : [
        new transports.Console({ format: productionFormat }),
        new LoggingWinston({                    // ← GCP 官方 transport
          labels: { name: 'carbonx', host: os.hostname() },
          logName: `winston-${serviceName}`,    // GCP 的 log 名稱 = winston-madeleine
          prefix: serviceName,
          defaultCallback: (err) => { if (err) console.log('google winston error:', err); },
        }),
      ];
 
  logger = WinstonModule.createLogger({ format: format.json(), transports: transportsOption });
  return logger;
}
環境 (NODE_ENV)Transport
localConsole(彩色 pretty)
其他Console(JSON) LoggingWinston → GCP Cloud Logging

5. Winston format pipeline — 三個自動注入

每筆 log 依序經過三個自訂 format:

5.1 autoTraceContextFormat (logging-util.ts:30)

從 AsyncLocalStorage 撈 trace context,自動補上 GCP 關聯欄位,並在 message 前面加短 traceId 前綴 [105445aa]

const autoTraceContextFormat = winston.format((info) => {
  const cloudLoggingFields = getCloudLoggingFieldsFromContext();  // 執行當下現撈
  const traceId = getTraceId();
  Object.entries(cloudLoggingFields).forEach(([k, v]) => { if (!(k in info)) info[k] = v; });
  if (traceId && typeof info.message === 'string' && !info.message.startsWith('[')) {
    info.message = `[${traceId.substring(0, 8)}] ${info.message}`;
  }
  return info;
});

5.2 autoActivityContextFormat (:64)

在 Temporal activity 內時,把 activityId/activityType/attempt/workflowRunId 塞進 GCP 的 labels(透過 magic field logging.googleapis.com/labels,GCP 會把它升級成 LogEntry.labels)。不在 activity 內則 store 為空、什麼都不加。

5.3 cloudLoggingFormat (:86)

把 Winston level 映射成 GCP severity:

const WINSTON_TO_CLOUD_SEVERITY = { error:'ERROR', warn:'WARNING', info:'INFO', http:'INFO',
  verbose:'DEBUG', debug:'DEBUG', silly:'DEBUG' };
// info.severity = 對應值;非 local 時刪掉 info.level 避免混淆

5.4 為什麼 format 用 () 呼叫、又不傳參數 — 重要細節

winston.format(fn) 回傳的是工廠(factory),不是 format 本身;要再 () 一次才生出實例(format.combine 要的是實例)。

const factory  = winston.format((info) => {...});  // 工廠
const instance = factory();                         // ★ () 才生實例

工廠 () 其實可收一個 opts(設定),但這幾個不傳,原因兩層:

  1. 淺層:行為固定,沒有可調選項。

  2. 深層(關鍵):它們要的資料(trace / activity)是每筆 log、每個 request 都不同的動態值,而 getLogger() 只在 bootstrap 跑一次。若靠參數傳:

    autoTraceContextFormat({ traceId: getTraceId() })  // ❌ traceId 會被凍結成啟動當下的值

    所以刻意不從參數拿,而把 (info) => {...} 延後到「每寫一筆 log 時」才執行,那時才呼叫 getTraceId(),才能拿到當前 async context 的 traceId。info(每筆 log 內容)則由 Winston 在寫 log 時自動塞入。

() = 把 format 工廠實體化;不傳參 = 沒選項可調 + 動態資料要 runtime 現撈,參數化反而凍死。


6. Trace context 怎麼串起來

AsyncLocalStoragesrc/context/trace-context.store.ts)讓 traceId 在整條 async 鏈都能拿到,不用一路傳 req

flowchart LR
    req["HTTP request"] --> mw["TraceContextMiddleware"]
    mw --> run["runWithTraceContext()"]
    run --> chain["Controller / Service / Repository"]
    chain --> log["logger 自動注入 traceId"]
  1. 入口 TraceContextMiddleware:解析 header X-Cloud-Trace-Context(格式 TRACE_ID/SPAN_ID;o=1,通常來自 GKE Ingress / LB / Cream proxy);缺或不合法 → 產生 fallback UUID(去 - 湊 32 char,source:'fallback');用 runWithTraceContext() 包住整個 request。
  2. 跨邊界傳遞(同一 traceId 延續):
    • Bull queue:producer 用 getTraceId() 塞進 job data;consumer 用 runWithTraceContext() 還原。
    • Temporal activity:traceId 放 activity input,內部用 runWithTraceContext() 還原。
    • 對外呼叫:用 formatCloudTraceHeader(ctx) 把 traceId 塞回 X-Cloud-Trace-Context header 傳下去。

在 code 裡通常不用手動加 trace 欄位,format pipeline 會自動補:

this.logger.log('Operation completed');
// GCP 收到:{ severity:'INFO',
//   'logging.googleapis.com/trace':'projects/<GCLOUD_PROJECT>/traces/105445aa...',
//   message:'[105445aa] Operation completed' }

GCLOUD_PROJECT 環境變數在 main.tsinitTraceContextStore() 初始化,trace 欄位完整格式 = projects/{GCLOUD_PROJECT}/traces/{traceId}


7. 從哪裡 trace(GCP Logs Explorer)

# 依 service 過濾(logName = winston-<serviceName>)
logName =~ "winston-"

# 依 label 過濾本專案
labels.name = "carbonx"

# 追某一條完整請求鏈路(最重要)
trace = "projects/<GCLOUD_PROJECT>/traces/105445aa7843bc8bf206b120001000"

實務追法:

  1. 任一筆 log 的 message 前綴 [105445aa](traceId 前 8 碼),或直接看 trace 欄位。
  2. 點該筆的 trace → 「Show entries for this trace」,把同一次請求跨 HTTP → Bull job → Temporal activity 的所有 log 串起來看。
  3. trace 有被 sampled(o=1)時,可在 Cloud Trace UI 看 span timeline。
  4. Temporal 的 log 有 labels.activity/activityIdactivity/attempt,可鎖定某 activity 的某次 retry。
  5. fallback traceId(source:'fallback')不會進 Cloud Trace UI,但在 Cloud Logging 仍能用 trace= 搜尋串連。

8. 記 error 的小工具:toLoggableError()

logging-util.ts:162。原生 Error 直接 JSON 化會變 {}(message/stack 是 non-enumerable),會漏掉真正錯誤原因。記 error 物件時改用:

this.logger.error({ message: '...', error: toLoggableError(err) });

它保留 name/message/stack,並帶上 enumerable own props(例如 TypeORM QueryFailedErrorcode/detail/constraint,能定位到違反的 DB 約束)。特別適合 repository 記 DB 錯誤。


9. 速查

想做的事怎麼做
一般記 logthis.logger.log('...')(trace 自動注入)
每個 class 的 loggerprivate readonly logger = new Logger(ClassName.name);
記 error 物件this.logger.error({ message, error: toLoggableError(err) })
拿目前 traceIdgetTraceId() / getTraceContext()
Bull/Temporal 還原 tracerunWithTraceContext(ctx, fn)
對外傳 traceformatCloudTraceHeader(ctx) → 塞 X-Cloud-Trace-Context
GCP 追一條請求Logs Explorer 搜 trace = "projects/<proj>/traces/<id>"