Web Day 22 日誌設計與追蹤
執行需求:CPU 可跑。今天是「Web 系統實戰:用 FastAPI 打造能上線的後端」系列的第二十二篇。昨天我們用 APScheduler 讓服務「自己做事」,今天要把這些事「記下來」:什麼時候發生了什麼、誰發起的請求、耗時多久、出了什麼錯。這是品質區塊的最後一篇,也是後續上線篇的銜接點。一個沒有結構化日誌的後端,出了事只能靠「使用者打來說壞了」除錯;有結構化日誌,你可以從 log 裡 30 秒內找到問題根源。
引言
「日誌」聽起來簡單,但實作起來有很多層次:第一層是「把訊息印出來」,print() 就能做;第二層是「分等級」,DEBUG/INFO/WARNING/ERROR;第三層是「結構化」,JSON 格式讓機器可解析;第四層是「上下文」,每一筆 log 都帶著 request id、user id 之類的脈絡。今天會把這四層一次說清楚,並用一個實際可跑的範例讓你立刻上手。
今天的範例同樣接續 Day 16-21 的專案。我們會做四件事:第一,介紹 Python 標準庫的 logging 模組與它的核心元件;第二,用 FastAPI middleware 把 request id 注入到每一筆 log;第三,用 structlog 25.x 把 log 改成 JSON 格式;第四,整理常見踩雷並展示如何把日誌接到檔案或外部系統。
Python logging 模組:handler、formatter、logger
Python 標準庫的 logging 模組有三個核心元件:
- Logger:你呼叫
logger.info(...)的物件,背後會決定要把訊息送到哪裡。 - Handler:實際決定 log 寫到哪裡的物件(標準輸出、檔案、HTTP endpoint 都可以是 handler)。
- Formatter:決定 log 的格式(純文字、JSON、CSV 等)。
這三個元件的關係是「Logger 收到訊息 → 送給所有 Handler → 每個 Handler 用自己的 Formatter 渲染」。一個 Logger 可以有多個 Handler,所以你可以同時把 log 印到終端機與寫進檔案。
最基本的設定:
# app/logging_config.py
# 最簡單的 logging 設定
import logging
import sys
def configure_logging():
# 取得 root logger
root = logging.getLogger()
root.setLevel(logging.INFO)
# 一個 StreamHandler:把 log 寫到 stderr
handler = logging.StreamHandler(sys.stderr)
formatter = logging.Formatter(
"%(asctime)s [%(levelname)s] %(name)s: %(message)s",
datefmt="%Y-%m-%dT%H:%M:%S%z",
)
handler.setFormatter(formatter)
# 把現有的 handler 清掉再加新的,避免重複設定
root.handlers.clear()
root.addHandler(handler)
這段程式把 log 寫到標準錯誤輸出(stderr),格式是「時間 [等級] 模組: 訊息」。root.handlers.clear() 是必要的,否則 uvicorn 與 FastAPI 預設已經裝了一些 handler,會出現重複輸出的狀況。
用 dictConfig 可以把整個設定寫成 YAML 或 JSON,方便統一管理:
# app/logging_config.py(dictConfig 版本)
import logging.config
LOGGING_CONFIG = {
"version": 1,
"disable_existing_loggers": False,
"formatters": {
"default": {
"format": "%(asctime)s [%(levelname)s] %(name)s: %(message)s",
},
},
"handlers": {
"stderr": {
"class": "logging.StreamHandler",
"level": "INFO",
"formatter": "default",
"stream": "ext://sys.stderr",
},
},
"loggers": {
"app": {"level": "INFO", "handlers": ["stderr"], "propagate": False},
"uvicorn.access": {"level": "INFO", "handlers": ["stderr"], "propagate": False},
},
}
def configure_logging():
logging.config.dictConfig(LOGGING_CONFIG)
disable_existing_loggers=False 保留 uvicorn、SQLAlchemy 等第三方套件的 logger;"propagate": False 避免 log 重複輸出。實務上這個寫法比純程式碼設定更容易管理,因為它是一個資料結構,可以從環境變數或設定檔載入(Web Day 29 會展開)。
完整實作:request id 與 middleware
沒有 request id 的 log 就像沒有日期的日記:當你看到一行錯誤,想知道「這是哪個請求造成的」,只能對著時間戳猜測。request id 是「這次請求的唯一識別碼」,通常放在 HTTP header 或自動產生,會在 middleware 裡被加進每一筆 log。
# app/middleware.py
# 把 request id 注入 context、並放進 HTTP 回應 header
import uuid
from starlette.middleware.base import BaseHTTPMiddleware
REQUEST_ID_CTX_KEY = "request_id"
def install_request_context() -> dict:
return {REQUEST_ID_CTX_KEY: str(uuid.uuid4())}
class RequestIdMiddleware(BaseHTTPMiddleware):
async def dispatch(self, request, call_next):
# 優先用 client 傳進來的 X-Request-ID,沒有就自動產生
request_id = request.headers.get("X-Request-ID", str(uuid.uuid4()))
request.state.request_id = request_id
response = await call_next(request)
response.headers["X-Request-ID"] = request_id
return response
BaseHTTPMiddleware 是 Starlette 提供的中介層基底類別;dispatch 接收請求、呼叫下一個、處理回應。我們把 request_id 放進 request.state,這是 Starlette 提供的「請求內可附加任意屬性」的位置。
接著用 logging 的 filter 把 request_id 注入到每一筆 log:
# app/logging_filters.py
# 用 context 把 request_id 自動放進每一筆 log
import logging
import contextvars
request_id_var: contextvars.ContextVar[str] = contextvars.ContextVar("request_id", default="-")
class RequestIdFilter(logging.Filter):
def filter(self, record: logging.LogRecord) -> bool:
record.request_id = request_id_var.get()
return True
contextvars 是 Python 3.7 引入的「非同步安全 context」,在 async 環境下也能正確傳遞。我們把 request_id 存在 context 裡,filter 在 log 被寫入時讀出來、附加到 LogRecord。配合前面的 middleware,就可以保證同一個請求裡的所有 log 都帶著同一個 request id。
把這些串起來:
# app/main.py
# 完整的日誌與 request id 設定
from contextlib import asynccontextmanager
import contextvars
import logging
from fastapi import FastAPI, Request
from app.logging_filters import RequestIdFilter, request_id_var
from app.logging_config import configure_logging
configure_logging()
logger = logging.getLogger("app")
@asynccontextmanager
async def lifespan(app: FastAPI):
logger.info("應用啟動")
try:
yield
finally:
logger.info("應用關閉")
app = FastAPI(title="Web Day 22 範例", version="0.22.0", lifespan=lifespan)
@app.middleware("http")
async def add_request_id(request: Request, call_next):
import uuid
request_id = request.headers.get("X-Request-ID") or str(uuid.uuid4())
request.state.request_id = request_id
token = request_id_var.set(request_id)
try:
response = await call_next(request)
response.headers["X-Request-ID"] = request_id
logger.info(
"%s %s -> %s",
request.method,
request.url.path,
response.status_code,
)
return response
finally:
request_id_var.reset(token)
@app.get("/hello/{name}")
def hello(name: str):
logger.info("處理 /hello 請求,name=%s", name)
return {"message": f"hello, {name}"}
這個版本用 @app.middleware("http")(FastAPI 的中介層寫法,比 BaseHTTPMiddleware 更直接)把 request id 注入到 context,並在回應時印一行 access log。request_id_var.set(...) 回傳的 token 用 reset 還原,避免污染下一個請求。
啟動後的輸出會長這樣:
# 命令列:啟動服務並呼叫
uv run uvicorn app.main:app --reload --port 8000
# 在另一個終端機:
curl -H "X-Request-ID: my-trace-001" http://127.0.0.1:8000/hello/world
# 輸出:{"message":"hello, world"}
# uvicorn 那邊會印出:
# 2025-08-06 12:00:00 [INFO] app: 處理 /hello 請求,name=world
# 2025-08-06 12:00:00 [INFO] app: GET /hello/world -> 200
兩行 log 雖然還沒帶 request id(因為 filter 還沒接上 formatter),但已經足夠說明 access log 的概念。接下來我們把它升級成 JSON 格式。
JSON 格式:structlog 25.x
純文字 log 對人類友善、對機器不友善。當你想用 grep、awk、jq 分析 log 時,JSON 格式會方便非常多。Python 標準庫的 logging 不直接支援 JSON formatter,但 structlog 25.x 把這件事做得很好。
# 命令列:安裝 structlog
uv add "structlog==25.1"
# app/logging_config.py(structlog 版本)
import logging
import logging.config
import structlog
def configure_logging():
timestamper = structlog.processors.TimeStamper(fmt="iso")
# 預處理鏈:把 context 變數、時間、log level 加進去
pre_chain = [
structlog.contextvars.merge_contextvars,
structlog.stdlib.add_logger_name,
structlog.stdlib.add_log_level,
timestamper,
structlog.processors.StackInfoRenderer(),
]
structlog.configure(
processors=[
structlog.stdlib.filter_by_level,
*pre_chain,
structlog.processors.JSONRenderer(),
],
wrapper_class=structlog.stdlib.BoundLogger,
logger_factory=structlog.stdlib.LoggerFactory(),
cache_logger_on_first_use=True,
)
# 把標準 logging 也設成同樣的 formatter
handler = logging.StreamHandler()
handler.setFormatter(logging.Formatter("%(message)s"))
root = logging.getLogger()
root.handlers.clear()
root.addHandler(handler)
root.setLevel(logging.INFO)
structlog 的 merge_contextvars 會自動把 context 變數(包括我們設的 request_id)併入每一筆 log。JSONRenderer 把結果輸出成 JSON。cache_logger_on_first_use=True 是效能最佳化,避免每次 log 都重建 processor chain。
使用方式:
# app/main.py(用 structlog)
import structlog
logger = structlog.get_logger("app")
@app.get("/hello/{name}")
def hello(name: str):
logger.info("處理 hello 請求", name=name, extra="value")
return {"message": f"hello, {name}"}
輸出會是這樣:
# 終端機輸出(每行一個 JSON)
{"event": "處理 hello 請求", "name": "world", "extra": "value", "level": "info", "timestamp": "2025-08-06T12:00:00+08:00", "logger": "app", "request_id": "..."}
JSON 格式讓你可以用 jq 直接篩選:
# 用 jq 篩選某個 request id 的所有 log
tail -f app.log | jq 'select(.request_id == "my-trace-001")'
# 或統計每個端點的呼叫次數
cat app.log | jq -r '.path' | sort | uniq -c
這是純文字 log 做不到的。
常見錯誤與踩雷
第一個雷是「log 太多」。很多新手會把每個變數、每個判斷都寫進 log,結果一天下來 log 量暴增。原則是「INFO 給正常事件、DEBUG 給除錯細節、ERROR 給真的錯誤」。當 log 量爆炸時,先調高等級到 WARNING 或 ERROR,再把重要的 INFO 留下來。
第二個是「log 太少」。另一個極端是「只在出錯時 log」,於是「正常運作時什麼都沒記」。等你出問題想追溯,發現根本沒有「昨天那個請求是誰發的」這種資訊。實務上至少要記錄:access log(誰、什麼時候、打了什麼)、業務事件(「建立預約」、「寄通知」、「快取失效」)、錯誤(含堆疊追蹤)。
第三個是「在 log 裡放敏感資料」。千萬不要把密碼、token、信用卡號碼寫進 log。FastAPI 內建了一些自動 log,可能會把 Authorization header 印出來;記得在 formatter 裡過濾掉,或用 structlog 的 processor 把特定欄位遮罩。實務上把所有「使用者輸入」當成敏感資料,預設不寫進 log。
第四個是「log 沒帶 request id」。沒有 request id 的 access log 在多行程部署下會變得很難除錯:你看到一行 ERROR,但不知道是哪個請求造成的。我們今天的範例把 request id 注入到 context 與每一筆 log,正是為了解決這個問題。
日誌等級怎麼選:從日常到緊急的優先順序
很多人寫 log 時等級亂用,把所有訊息都設成 INFO,於是等級變得沒有意義。Python logging 定義了五個等級,預設的優先順序是 DEBUG < INFO < WARNING < ERROR < CRITICAL。我們的範例用的是 INFO 當最低等級,但在正式環境可以再調高:
- DEBUG:每個函式呼叫、每個變數的值。除錯時開啟,正式環境關閉。
- INFO:重要的業務事件。「使用者登入」、「預約成立」、「快取失效」。
- WARNING:「不影響運作但需要關注」。例如「重試第三次」、「磁碟空間剩 10%」。
- ERROR:「這次請求失敗」。例如「資料庫連線失敗」、「使用者輸入驗證錯誤」。
- CRITICAL:「整個應用有危險」。例如「設定檔讀不到」、「資料庫完全無法連線」。
實務上「INFO 太多會蓋過 ERROR」的問題可以靠等級過濾解決:CI 環境把等級設成 WARNING 讓測試輸出乾淨;正式環境把等級設成 INFO 保留業務事件;除錯時用環境變數把等級降到 DEBUG 一次。
log rotation:當檔案長太大怎麼辦
當 log 寫到檔案而不是集中式系統,檔案會一直長大。Linux 用 logrotate、Windows 用 Serilog Sink 的 rollingFile;Python 標準庫提供 RotatingFileHandler 與 TimedRotatingFileHandler:
# app/logging_config.py(log rotation)
import logging.handlers
def configure_logging():
handler = logging.handlers.TimedRotatingFileHandler(
"app.log",
when="midnight", # 每天午夜輪替
interval=1,
backupCount=14, # 保留 14 天的 log
encoding="utf-8",
)
handler.setFormatter(logging.Formatter("%(asctime)s %(message)s"))
root = logging.getLogger()
root.handlers.clear()
root.addHandler(handler)
root.setLevel(logging.INFO)
TimedRotatingFileHandler 會在每天午夜把 app.log 改名為 app.log.2025-08-06,然後重新開一個新的 app.log。backupCount=14 表示保留 14 天的歷史,超過的會自動刪除。這對磁碟空間管理與除錯(你可以打開「昨天的 log」對照)都非常實用。
自訂欄位:把業務資訊加進 log
當一個請求涉及多個步驟時,你會想把「使用者 id」、「預約 id」、「金額」這些業務欄位附加到 log 上。structlog 提供 bind 與 new 兩種方式:
# app/main.py(bind 版本)
import structlog
logger = structlog.get_logger("app")
@app.post("/bookings")
def create_booking(booking: BookingIn):
# 建立一個帶著 context 的 logger
log = logger.bind(user_id=booking.user_id, service=booking.service)
booking_id = hash((booking.user_id, booking.service)) % 10_000
log.info("預約成立", booking_id=booking_id)
# 之後所有 log 都會自動帶 user_id、service、booking_id
return {"booking_id": booking_id}
logger.bind(...) 回傳一個新的 logger,所有欄位會自動併入每一筆 log。後續的 log.info(...) 不需要再重複寫 user_id 與 service,輸出會長這樣:
# 終端機輸出
{"event": "預約成立", "booking_id": 7821, "user_id": 42, "service": "攝影", "level": "info", "timestamp": "2025-08-06T12:00:00+08:00"}
這是結構化日誌的威力:當你想查「user 42 在 8 月 6 號做了什麼」,只要 jq 篩 user_id == 42 與 timestamp 範圍 即可。
效能與實務提醒
第一個提醒是「同步寫檔會卡住應用」。預設的 StreamHandler 同步寫到 stderr,正式部署時若把 stderr 重導到檔案,整個 log 流程就是同步的。當 log 量大的時候,這個 I/O 會讓應用變慢。解法是用 QueueHandler 把 log 放進 queue、由另一個 thread 寫檔,主流的 logging 函式庫都支援。
第二個是「log 格式的選擇」。本地開發用純文字(直接讀最快);正式環境用 JSON(grep 友善)。實務上我們會透過環境變數切換:
# app/logging_config.py(依環境切換)
import structlog
def configure_logging():
import os
json_format = os.getenv("LOG_FORMAT", "text") == "json"
renderer = (
structlog.processors.JSONRenderer()
if json_format
else structlog.dev.ConsoleRenderer()
)
structlog.configure(
processors=[
structlog.contextvars.merge_contextvars,
structlog.stdlib.add_log_level,
structlog.processors.TimeStamper(fmt="iso"),
renderer,
],
wrapper_class=structlog.stdlib.BoundLogger,
logger_factory=structlog.stdlib.LoggerFactory(),
cache_logger_on_first_use=True,
)
structlog.dev.ConsoleRenderer 是 structlog 提供的彩色終端機輸出,開發體驗非常好;正式環境透過 LOG_FORMAT=json 環境變數切到 JSON。
第三個是「log 收容與保留」。正式環境的 log 通常會送到 Splunk、Elasticsearch、Datadog 等系統做集中儲存。這些服務接收 log 的方式各有不同:Splunk 用 HTTP 或 syslog;Elasticsearch 用 Filebeat;Datadog 用自家 agent。我們的設定只要輸出 JSON 結構,這三個系統都能解析。
日誌的「黃金三欄」:誰、何時、做了什麼
好的日誌系統應該回答三個問題:誰(who)發起、何時(when)發生、做了什麼(what)。這個原則貫穿所有後端系統的觀察性設計。今天的 request id 解決「誰」——把同一個請求的所有 log 串起來;timestamp 解決「何時」——每一筆 log 都有時間;事件名稱(event name)解決「做了什麼」——明確標示「使用者登入」、「預約成立」這種語意化的事件。
實務上你可以把黃金三欄做成標準化模板:每一筆業務 log 都帶 event、user_id、timestamp,需要時再加額外欄位。這是 12-Factor App 與 Google SRE 書裡都提到的做法。當除錯時遇到「昨晚 9 點有人說預約失敗」,你可以直接 grep 「timestamp between 20:50 and 21:10」、filter 「event=預約失敗」、追到對應的 user_id,這比從純文字 log 翻找快上百倍。
今晚的練習:把昨天的排程任務加上 log
如果昨天 (Day 21) 的排程任務還在你專案裡,今天最快的練習是「把每個任務的開始與結束印一行 INFO」。例如:
# app/scheduler.py(加日誌版本)
import logging
logger = logging.getLogger(__name__)
def cleanup_expired_cache():
logger.info("cleanup_expired_cache 開始")
keys = redis_client.keys("web_day_20:*")
if keys:
redis_client.delete(*keys)
logger.info("cleanup_expired_cache 結束,清掉 %d 個 key", len(keys))
def daily_booking_digest():
logger.info("daily_booking_digest 開始")
# 真實的寄信邏輯
logger.info("daily_booking_digest 結束")
加上日誌後你可以驗證:任務真的跑了、跑了多久、有沒有錯誤。今天寫的 structlog 設定已經把所有 log 都加上時間戳記,等你跑 uvicorn 時就可以看到這些訊息。這也是 Day 34「健康檢查與監控」的基礎:沒有日誌就沒有監控、沒有監控就沒有「系統現在到底怎麼了」的可見性。
從單機日誌到分散式追蹤:OpenTelemetry 的角色
當你的服務變得更大(一個請求經過 5 個微服務、3 個資料庫查詢、2 個外部 API),純粹的 log 已經不夠用:你需要追蹤「這個請求在每個服務裡花多少時間」。OpenTelemetry(OTel)是 2025 年的標準分散式追蹤框架,提供 trace、metric、log 三種訊號。
Python 端可以用 opentelemetry-instrumentation-fastapi 自動把 FastAPI 端點包成 span;用 opentelemetry-instrumentation-sqlalchemy 把 SQLAlchemy 查詢包成 span。所有 span 會組成一個 trace,trace id 就是我們今天的 request id。把 log 跟 trace 接起來,每一筆 log 都帶著 trace id,你就能在 Splunk 看到「這個請求的所有 log」、在 Jaeger 看到「這個請求的時間軸」。
這對 Web Day 22 來說稍微進階,先記得這個方向。今天的範例把 request id 注入到每一筆 log,未來要升級到 OpenTelemetry 只需要把「request id」換成「trace id」、把 context 換成 OTel 的 span context,其他結構都一樣。
怎麼讓 log 在容器環境正確寫入
當你把 FastAPI 打包成 Docker 容器(Web Day 30 會做這件事),log 預設會寫到 stdout 與 stderr;Docker 會把這些輸出收集起來,可以用 docker logs 查看。這是 12-Factor App 的標準做法:log 走 stdout、收集交給外部系統。
但有一個常見的踩雷:容器內的時區與主機不同。當你在 log 寫 datetime.now(),容器會用 UTC 而不是 Asia/Taipei。解法有兩個方向:第一,用 structlog 的 TimeStamper(fmt="iso", utc=True) 強制寫 UTC,前端解析時再換算。第二,在 Docker 啟動時加 -e TZ=Asia/Taipei 環境變數或把 /etc/timezone mount 進去。前者比較穩定,後者比較直觀。
另外一個容器環境的議題是 log rotation 在容器內不太有意義:容器重啟 log 就清空、磁碟滿了整個容器死掉。實務上你會把 log 輸出到 stdout、讓 Docker daemon 收集、傳到雲端 log 服務(CloudWatch、Stackdriver、ELK)。Docker 對單一容器的 log 大小有限制(預設 10 MB),搭配 --log-driver=json-file --log-opt max-size=10m 設定自動輪替。
今晚的練習:把昨天的排程任務加上 log
如果昨天 (Day 21) 的排程任務還在你專案裡,今天最快的練習是「把每個任務的開始與結束印一行 INFO」。
# app/scheduler.py(加日誌版本)
import logging
from datetime import datetime
logger = logging.getLogger(__name__)
def cleanup_expired_cache():
logger.info("cleanup_expired_cache 開始")
keys = redis_client.keys("web_day_20:*")
if keys:
redis_client.delete(*keys)
logger.info("cleanup_expired_cache 結束,清掉 %d 個 key", len(keys))
def daily_booking_digest():
logger.info("daily_booking_digest 開始")
# ... 真實的寄信邏輯
logger.info("daily_booking_digest 結束")
加上日誌後你可以驗證:任務真的跑了、跑了多久、有沒有錯誤。今天寫的 structlog 設定已經把所有 log 都加上時間戳記,等你跑 uvicorn 時就可以看到這些訊息。這也是 Day 34「健康檢查與監控」的基礎:沒有日誌就沒有監控、沒有監控就沒有「系統現在到底怎麼了」的可見性。
小結
今天把日誌從「print」升級到「結構化、可追蹤」。Python 標準庫的 logging 提供 handler、formatter、logger 三元件;FastAPI 的 middleware 把 request id 注入到 context;structlog 25.x 把 context 自動併入每一筆 log、並支援 JSON 輸出。我們也提醒了「log 太多 / 太少」、「敏感資料」、「同步寫檔」三個常見踩雷。今天結束時你的專案裡應該有一套完整的日誌系統:每一筆 access log 帶著 request id、業務事件有結構化欄位、錯誤有堆疊追蹤、正式環境能輸出 JSON 給集中式 log 系統使用。這是品質區塊的句點,也是上線區塊的起點。
結語
品質區塊七天結束了。從 Day 16 的 pytest 入門到今天的結構化日誌,我們把「怎麼讓程式在生產環境不出錯」這件事從單元測試、整合測試、測試資料庫、非同步、背景任務、快取、排程、日誌一次走完。明天開始 Web Day 23「前端整合的選擇:HTMX 與 SPA 的取捨」會把鏡頭轉向前端:怎麼把 FastAPI 的回應變成使用者能操作的畫面。後端是我們熟悉的戰場,前端會引入新的工具與觀念,但「結構化、可測試、有日誌」的原則不會變。
延伸資源
- Python logging 官方教學(3.13):
https://docs.python.org/3/library/logging.html - structlog 官方文件(25.1,2025):
https://www.structlog.org/en/stable/ - FastAPI middleware 官方教學(0.116,2025-07):
https://fastapi.tiangolo.com/tutorial/middleware/ - 12-Factor App Logs(2025):
https://12factor.net/logs - OpenTelemetry Python 入門(2025):
https://opentelemetry.io/docs/languages/python/
留言
張貼留言