✏️【本日實作紀錄：結構化日誌 Trace ID 與觀測性效能監控】

今天我們將為 PrescriptionVLM 系統導入 X-Request-ID 中介軟體、結構化 JSON 日誌格式，以及 API 處理時長（Latency）分段追蹤機制。完成項目包含：

• Request-ID 全域追蹤（Trace ID） — 每個 API 請求自動配發 UUID，並將 Trace ID 帶入 Response Header。
• 結構化 JSON 日誌格式 — 將 Python logger 改寫為 JSON 格式，方便日後 Log 收集工具（如 ELK / Grafana Loki）自動解析。
• 分段效能觀測（Latency Metrics） — 精準紀錄 Gemini VLM 圖像解析與 LINE Flex Message 推播各自消耗的毫秒數。

一、系統可觀測性（Observability）的需求

在維護包含多模態 AI API 的後端服務時，我們經常面臨以下問題：

• 請求無法關聯：當多個使用者同時發送藥單照片時，Terminal 日誌交錯，無法判定某行 Exception 隸屬於哪一次上傳。
• 純文字日誌難以搜尋：無法在集中式日誌平台中依照欄位（例如 latency_ms > 2000 或 status_code = 500）進行精準篩選與自動告警。
• 瓶頸定位困難：當 API 總耗時增加時，無法直觀得知是 Gemini VLM 模型回應慢，還是 LINE Webhook API 的推播延遲。

透過 Trace ID 與結構化 JSON 日誌，我們能更快速地定位問題與監控系統表現。

二、打造結構化日誌模組（logger.py）

我們首先建立獨立的日誌處理模組，將所有 Log 轉為標準 JSON 格式。

請在專案根目錄下建立 logger.py 檔案：

import logging
import json
from flask import g
from datetime import datetime

class JSONFormatter(logging.Formatter):
    """自訂 JSON 格式日誌輸出器"""
    def format(self, record: logging.LogRecord) -> str:
        log_data = {
            "timestamp": datetime.utcnow().isoformat() + "Z",
            "level": record.levelname,
            "logger": record.name,
            "message": record.getMessage(),
            "request_id": getattr(g, "request_id", "N/A"),
        }
        
        # 紀錄額外傳入的 extra 欄位資訊
        if hasattr(record, "extra_data"):
            log_data["extra"] = record.extra_data
            
        return json.dumps(log_data, ensure_ascii=False)

def setup_logger():
    """初始化並回傳設定好的 Structured Logger"""
    logger = logging.getLogger("PrescriptionVLM")
    logger.setLevel(logging.INFO)
    
    # 避免重複 addHandler 導致日誌重複列印
    if not logger.handlers:
        handler = logging.StreamHandler()
        handler.setFormatter(JSONFormatter())
        logger.addHandler(handler)
        
    return logger

logger = setup_logger()

三、在 Flask 中掛載 Request-ID 中介軟體與分段監控（app.py）

接著開啟 app.py，利用 Flask 的 @app.before_request 與 @app.after_request 鉤子，實現全域 Request-ID 注入與 HTTP 效能紀錄。

1. 匯入 logger 模組與時間工具

在 app.py 頂部新增：

import time
import uuid
from flask import g, request
from logger import logger

2. 注入 Middleware 鉤子

在 app.py 中新增 before_request 與 after_request 處理函式：

@app.before_request
def before_request():
    """請求進入前：紀錄開始時間並注入 Trace ID"""
    g.start_time = time.time()
    # 若前端或 Gateway 帶有 X-Request-ID 則沿用，否則自動生成全新的 UUID
    g.request_id = request.headers.get("X-Request-ID", str(uuid.uuid4()))

@app.after_request
def after_request(response):
    """請求結束後：將 X-Request-ID 帶回 Response Header，並印出結構化日誌"""
    elapsed_time = round((time.time() - getattr(g, "start_time", time.time())) * 1000, 2)
    
    # 將 Trace ID 寫入回應標頭
    response.headers["X-Request-ID"] = getattr(g, "request_id", "N/A")
    
    log_extra = {
        "method": request.method,
        "path": request.path,
        "status_code": response.status_code,
        "latency_ms": elapsed_time,
        "ip": request.remote_addr
    }
    
    logger.info(
        f"HTTP {request.method} {request.path} {response.status_code} - {elapsed_time}ms",
        extra={"extra_data": log_extra}
    )
    
    return response

3. 更新 /analyze-prescription 分段效能紀錄

修改 analyze_prescription 路由，紀錄 VLM 模型與 LINE 推播的各階段耗時：

@app.route("/analyze-prescription", methods=["POST"])
def analyze_prescription():
    req_id = getattr(g, "request_id", "N/A")
    logger.info(f"收到藥單解析請求 [ReqID: {req_id}]")
    
    # ── 階段 1: VLM 圖像解析 ──
    vlm_start = time.time()
    
    # ... (執行原本 Day 17 包含 Pydantic Schema 校驗與重試機制的 Gemini 呼叫) ...
    
    vlm_latency = round((time.time() - vlm_start) * 1000, 2)
    logger.info(f"Gemini VLM 耗時: {vlm_latency}ms")

    # ── 階段 2: LINE Flex Message 推播 ──
    line_start = time.time()
    
    # 呼叫 Day 16 的 send_line_notification 推播大字卡片
    send_line_notification(
        summary=result_data.get("spoken_summary", ""),
        medicines_count=len(result_data.get("medicines", [])),
        safety_warnings=result_data.get("safety_warnings", []),
        audio_url=""
    )
    
    line_latency = round((time.time() - line_start) * 1000, 2)
    logger.info(f"LINE 訊息推播耗時: {line_latency}ms")

    return jsonify({
        "status": "success",
        "request_id": req_id,
        "metrics": {
            "vlm_latency_ms": vlm_latency,
            "line_latency_ms": line_latency
        },
        "data": result_data
    }), 200

四、測試與成果驗證

1. 重新構建並啟動 Docker 容器

在 Terminal 執行：

docker rm -f prescription_service
docker build -t prescription-vlm:v1.0 .
docker run -d -p 5000:5000 --env-file .env --name prescription_service prescription-vlm:v1.0

2. 帶有 Trace ID 標頭的 API 測試

使用 curl -i 觀察回傳的 Header 與內文：

curl -i -X POST http://127.0.0.1:5000/analyze-prescription \
  -H "X-Request-ID: test-trace-88888" \
  -F "image=@test_rx.jpg"

預期驗收成果：

1. Header 含有 Trace ID：Response Header 成功出現 X-Request-ID: test-trace-88888。
2. Terminal 輸出 JSON 日誌：輸出呈現標準 JSON 格式：{"timestamp": ..., "level": "INFO", "request_id": "test-trace-88888", ...}。
3. API 回應包含 Metrics：JSON 成果中列出 vlm_latency_ms 與 line_latency_ms 的分段耗時。

五、版本控制與提交 GitHub

測試通過後，將 Day 18 的修改提交至 GitHub：

git add .

git commit -m "保留雙引號 改填寫自己要記錄的標記 ex.鐵人賽第十八天"

git push

六、本日小結與明日預告

今天我們為 PrescriptionVLM 補齊了生產環境需要的可觀測性基礎設施，包含全域 Trace ID 追蹤、JSON 格式化日誌以及 API 階段效能監控。有了這套系統，當問題發生時，我們能更快速地從日誌中找到對應的請求與定位瓶頸。

明天（Day 19），我們將針對整體架構導入 Redis 快取與限流機制，防止重複圖片重複呼叫 Gemini 造成 API 額度浪費與頻率限制！