iT邦幫忙

2026 iThome 鐵人賽

DAY 22
0
AI Engineering

Backend 工程師的 Azure GenAI 實戰系列 第 22

Day 22:Audit Log——一筆終端事件、四條 exit path,還有兩條刻意不發

  • 分享至 

  • xImage
  •  

到 Day 21 為止,這個 backend 有了身分(Day 19)、預算(Day 9)、內容層的安全邊界(Day 21),但「誰在什麼時候做了什麼、結果如何」,散在一堆 diagnostic log 行裡,要人肉 join 才拼得回來。這篇把它收成終端 audit 事件,每個走到合約內終態的已驗證請求恰好一筆——聽起來像個格式決定,做下去才發現每條 exit path 都在逼你回答同一個問題:這筆事件會不會說謊? 讀完你會得到一套把 audit log 當裁決集合來設計的方法,從 schema 一路到最難的 streaming 出口。

先把幾條裁決的形狀擺出來:成功事件結構上就沒有 error_code 欄位可以填;斷線記的是 commit 真相,不是 delivery 真相;還有兩條路,正確答案是一筆都不發——server 端真 bug 與 malformed JSON,不發的理由恰好相反;bug 這條的零 event 規則在 /chat/chat/stream/rag 精確,/agent 有一個框架層例外,後面會講。

刻意遲到二十一天的 schema

audit log 的 schema 是我從系列第一天就掛在「延後決定」清單上的東西。不是忘了,是它有先決條件:要等 endpoint 長齊、身分定案(Day 19)、工具定形(Day 17–18)、安全邊界劃完(Day 21),你才知道要記什麼——更重要的,什麼絕對不能記。Day 15 的「group ids 永不進 log」和 Day 21 的 redaction 紀律,就是現成的輸入。

動手前先做了三個裁決。

Reference-only。 事件裡每個欄位都是 id、count、hash、布林或 enum,沒有任何欄位承載使用者或模型寫的自由文字。內容已經有 system of record——conversation store——log 再存一份,就是第二個真相來源加第二個外洩面。audit 事件的工作是能用 id join 回去,不是把對話再印一份。

終端事件,不是 per-stage log。 每個走到合約內終態的已驗證請求恰好一筆:chat.turnrag.queryagent.run,外加一種 auth.rejected。預算 429 不是獨立的事件型別,它是 chat.turnagent.runoutcome="rejected"error_code="token_budget_exceeded"——rejection 是 outcome,不是另一種事件。

「恰好一筆」的好處是能用測試強制:每個 endpoint 的每條合約內 exit path 都有測試斷言 exactly one,而合約外 bug 的「零 event」同樣有反例測試釘著——不變量的邊界跟不變量本身一樣是測出來的。既有的 diagnostic 行(Day 8 的 prompt attribution、Day 9 的 usage、Day 14 的 stage latency)一行不動,audit 是疊上去的第二個 channel。

一筆一行 JSON,schema 匯出+CI drift check。 core/audit.py 的 pydantic schema 匯出成 docs/audit/audit-events.json,CI 比對零 drift——跟 OpenAPI、index schema 同型,是這個 repo 的第三個 drift check。

把「記什麼」變成型別問題

Schema 本體是 frozen pydantic model,長成兩層 nested discriminated union:每個事件族內層用 outcome 分流(success/rejected/error),外層再用 event 分流四個族。

這不是我的第一選擇。第一選擇是 composite discriminator——Field(discriminator=("event", "outcome")) 一次分完——但 pydantic 不支援 tuple discriminator,直接丟 PydanticUserError。這是 spec review 時在 venv 裡實測出來的,不是查文件查到的;查文件你會一直以為自己只是還沒找到寫法。

兩層 union 換來的東西值得多打幾行字:presence 變成結構error_code 在 success variant 上不是 nullable——是這個欄位不存在。 想發一筆帶著 error_code 的成功事件,validation 直接拒絕,因為 extra="forbid" 之下那是一個未知欄位。spentbudget 只存在於 rejected variant。型別系統驗得動的,就不必靠人記得。

型別驗不動的(attempted 與 attribution 的連動、spentbudget 必須成對、401 不得帶身分),走 runtime validator。而且六條 constraint 的原文以常數形式(ATTEMPTED_CONSTRAINT 等六個)掛進 Field(description=...)——匯出的 JSON Schema 裡讀得到跟測試強制的一模一樣那句話,不是散落在註解裡的口頭約定。

但 schema 寫得再嚴,也只在有人「經過」它的時候有效。所以發射函式長這樣(core/audit.py @ day-22):

def emit_audit_event(event: AuditEventModel) -> None:
    """The emission boundary: whatever reaches the log line has passed the
    audit schema. A foreign model raises before anything is written — the
    never-log guarantee is enforced here, not by a type hint."""
    validated = AUDIT_EVENT_ADAPTER.validate_python(event)
    payload = AUDIT_EVENT_ADAPTER.dump_python(validated, mode="json")
    _audit_logger.info(json.dumps(payload, sort_keys=True, ensure_ascii=False))

Type hint 不是邊界——它只活在 mypy 眼裡,一個 caller 手工組出來的物件照樣能塞進來。有一個測試反向證明了這件事:把 validate 拿掉改成直接 dump,一個 schema 之外的 model 會安靜地序列化出去。邊界要在 runtime 攔得住東西,才算邊界。

Never-log 也是同一個思路。禁止入 log 的東西——message 文字、chunk 內容、tool 參數、group ids、token、claims、exception message、validation 錯誤訊息——用「欄位不存在」強制,不是 write-time 的 redaction filter。 配一個遞迴走訪所有 variant 欄位(含 nested model)的測試,比對一張禁用欄位名清單:

message, question, content, chunk_content, text, answer, task, arguments,
detail, claims, token, raw_token, group_ids, groups, ...

未來有人加一個內容形狀的欄位,測試先紅,不用等 code review 有人眼尖。redaction filter 是「記了再擦」——要記得擦、擦得對、每條路都擦;欄位不存在是「沒地方可記」,一次把整類問題關掉。

provider_call_attempted:一個布林的兩份工作

事件裡有個布林值得單獨講:provider_call_attempted。它的定義是「provider adapter 的邊界被呼叫過」,不是「真的打了 Azure」——fake 模式下這個邊界就是 deterministic fake adapter,所以 fake 的成功事件照樣 true,配 deployment="fake"model_version="fake" 的 sentinel。欄位不宣稱它證明不了的事。

它的第二份工作比較隱蔽:解掉 storage_error 的歧義。同一個 error code 可能發生在兩個位置——載入 conversation 失敗(還沒碰 provider,attempted=false),或 commit 失敗(provider 跑完了、寫入才掛,attempted=true,而且那次呼叫的 usage 是真的產生了)。單看 error_code,兩者長得一模一樣。

分法是 typed commit errorscore/errors.pyStorageCommitError 繼承 StorageError,再往下 ChatStorageCommitErrorAgentStorageCommitError 各自把 audit_snapshot 設成必填建構參數——commit 路徑丟例外時,必須把已知的 terminal 資料(usage、status、model_version)帶在身上,事件不因為寫入失敗而丟掉它們。

Finalizer 拿到例外,由 subtype 判定兩態,並明文禁止兩種替代方案:挖 __cause__,或比對 exception message。後者是那種「今天能動、哪天有人改個措辭就壞」的隱性耦合——而且壞的時候不會有任何測試紅給你看。

四條 exit path:streaming 是最難的那條

先看整張出口地圖——每個被分類的請求恰好落在一個出口;兩個灰色出口的正確答案是零筆,後面會分別講到。圖分類的是 outcome,不代表 emission 位置:

Audit 事件出口地圖:HTTP request 先問 body 是不是合法 JSON,不是就零 event(身分從未驗證,發了就是捏造);是就進 require_principal 驗證身分,401/403 發 auth.rejected 恰好一筆;通過後欄位驗證不過(422)發 rejected 恰好一筆;進 endpoint/service 執行後,2xx 發 success、4xx envelope(400/404/429)發 rejected、5xx envelope 發 error,各恰好一筆;consumer 關閉/取消(streaming)看 StreamDone 觀察到了沒——是(commit 已完成)記 success、否記 error;合約外例外=真 bug 則零 event、原例外原樣傳播(/agent 框架層例外見文)。圖例:本圖分類 outcome,不代表 emission 位置

audit 的 producer 一共六類:/chat 的 endpoint finalizer、/chat/stream(它自己再拆成 pre-stream finalizer 與 post-transfer observer 兩個互斥 owner——所以按 owning function 算,整個系統是七個)、/rag 的 service 層終端、/agent 的 finalizer、require_principalauth.rejected,加上 422 handler。

/chat 是最簡單的形狀,值得先看,因為它示範了「exactly one」怎麼寫出來:一個 try 配三個 except(各自 emit 完再 raise),沒進任何 except 就落到 try 之後唯一的成功發射點。沒有 finally——這不是疏漏,是裁決,原因就在下面。

/rag 特別一點:它從 service 層發射(RagService.answer() 的三個終端出口),因為那裡才看得到 pipeline 的 stage。但 answer() 也會被單元測試在沒有 request 的情況下直接呼叫,所以發射前先過 has_audit_context() guard——沒有 request context 就不發、不捏造、行為與從前完全一致。

/ragattempted 直接由 status 導出:answered 必為 trueno_answer 必為 false。Day 14 的結構性 no-answer 是「零命中就不呼叫 LLM」,這條不變量現在也是 schema validator 的一部分。

真正難的是 /chat/stream。200 送出去之後,HTTP status 已經覆水難收,terminal 的所有權也得跟著搬家:pre-stream 失敗(404、429、stream 建立前的 upstream 失敗)還是普通的 HTTP 錯誤,歸 endpoint finalizer;iterator 一旦交付給 StreamingResponse,terminal 就歸包在外面的 observer generator _audit_observed。兩階段互斥,一個請求恰好落在其中一邊。

Observer 的 except 是三分流,這段值得整段引(api/streaming.py @ day-22):

    except UpstreamError as exc:
        outcome, code, attempted, snapshot = chat_upstream_audit_args(exc)
        emit_audit_event(chat_failure_event(
            base=base, duration_ms=duration_since(audit_start), outcome=outcome,
            error_code=code, provider_call_attempted=attempted,
            attribution=attribution, snapshot=snapshot,
        ))
        raise
    except (GeneratorExit, asyncio.CancelledError):
        if seen_done is not None:
            emit_audit_event(_terminal_success())
        else:
            emit_audit_event(chat_failure_event(
                base=base, duration_ms=duration_since(audit_start), outcome="error",
                error_code="client_disconnect", provider_call_attempted=True,
                attribution=attribution,
            ))
        raise

第一流是 Day 6 就定義過的 mid-stream upstream 失敗:emit、raise,SSE error 事件照舊。第二流是 stream 被取消,下面細講。

第三流是沒寫出來的那一流:任何不在上面兩類的例外——一個真正的程式 bug——零 event,原例外原樣傳播。 這條規則在 /chat/chat/stream/rag 是精確的;/agent 有一個已知例外,收在誠實邊界。

它也是 /chat 沒有 finally 的原因:用 finally 或一個過寬的 except Exception 收尾,一個 server 端的 ValueError 會被分類進「斷線」或「成功」——audit log 裡的謊。 bug 應該大聲地死,不該被安靜地重新分類。

這條有專門的反例測試,而且測試刻意用「iteration 中途真的 raise」,不是在 yield 點 throw——不然測試會因為錯的理由通過。

再看第二流的兩態。 這一流接的是 GeneratorExitasyncio.CancelledError——最常見的來源是 client 斷線,但 CancelledError 也可能來自 server 端(shutdown、task 取消),所以 client_disconnect 這個 error code 記的是最常見的原因,不是經過證明的歸因。

conversation store 的 commit 發生在 terminal frame yield 給 serializer 之前(Day 7 的 _commit_on_done),所以被切斷時要看 cutoff 在哪:

Cutoff 事件
terminal 之前被取消 outcome="error"error_code="client_disconnect"committed=falseusage=null
StreamDone 已被觀察到之後才被取消 照 terminal 建正常事件——committed、真 usage、真 status 全保留

第二態乍看違反直覺。拿最常見的來源當例子:client 都斷了,憑什麼記成功?因為 commit 的決定在斷線前已經完成,store 裡那個 turn 就在那裡;message.done 有沒有送到 client,server 端無法證明

一律記 committed=false 的替代方案,會讓 audit log 聲稱一個 turn 沒落庫、而 store 裡它明明存在——比現在這個設計接受的不可知,更糟的謊。audit 記的是 commit 真相,不是 delivery 真相。

刻意不發的另一條路

合約外 bug 是第一條刻意零 event 的路——不分類,讓它大聲地死。第二條不發的理由正好倒過來:malformed JSON。 body 連 JSON 都不是的時候,解析失敗發生在 FastAPI 跑 dependency 之前——require_principal 從未執行,身分從未建立。這個請求該發什麼事件?帶身分?我們沒有。不帶身分?auth.rejected 也輪不到它——它不是被拒絕的驗證,是根本沒發生過的驗證。

從未驗證過身分的請求若發出 audit event,那筆事件是捏造的。

所以 422 handler 的 guard 是這樣分的:require_principal 成功時會把 principal stash 在 request.state(它存在的目的就是這個),handler 用 getattr(request.state, "principal", None) 分辨兩種 422。

已驗證身分、但 body 壞了——發一筆 outcome="rejected"error_code="validation_error" 的事件:身分與 correlation、duration 這些 envelope 欄位照記,request 沒走到的 route/provider 欄位才是 null;從未驗證——零筆。validation 錯誤訊息本身一個字都不進事件,那是 caller 的 body 內容,never-log 管到它。

Live smoke:honest absence 在真的壞掉的基礎設施上

Schema 規則裡還有一條沒講:拿不到就是 null,不是 00 是「什麼都沒發生」的正面主張,跟「我不知道」是兩回事。

這條規則最好的證據不是我寫的任何測試,而是 live smoke(2026-08-09,japaneast,真 Azure OpenAI)當場撞出來的。當時 Search service 不在線上(本系列 ephemeral-by-default,不用就砍),/rag 回 500,事件長這樣:

{"event":"rag.query","outcome":"error","error_code":"search_unavailable",
 "failed_stage":"retrieve","status":"error","provider_call_attempted":false,
 "hit_count":null,"selected_chunk_ids":null,
 "deployment":null,"model_version":null,"prompt_name":null,
 "prompt_version":null,"prompt_sha256":null,"usage":null,
 "duration_ms":30529.95,"correlation_id":"8927d8d8-…"}

Pipeline 沒走到的每一個欄位都是 nullprovider_call_attemptedfalse 因為 generation 根本沒跑。

分段的契約各有單元測試釘著——503/連線失敗轉 SearchUnavailableErrorsearch_unavailable 的 audit 對映、retrieve 失敗的 honest nulls——但沒有任何一個測試把「真 Azure Search adapter 到 audit event」這條鏈從頭串到尾。live smoke 的價值就在這裡:真基礎設施當場壞掉,把分段契約一次串成完整的整合觀測,而規則撐住了。

同一輪 smoke 也對真 server 觀測到 malformed JSON 的零 event 行為;成功事件的 correlation_id 則各接回一行 Day 9 的 llm usage 與一行 Day 8 的 prompt attribution——terminal 看 audit 事件、細節 join diagnostic 行。

smoke 還帶回一個值得記的觀察:成功事件的 model_version"chat-mini"——deployment 名,不是 gpt-5-mini-2025-08-07 這種上游 model 版本。 欄位定義是「provider 回報的值」(response.model),在 Azure OpenAI 上那就是 deployment 名。

斷言 != null and != "fake" 仍然分得出真假呼叫,這是它存在的目的;但沒有人該把這個欄位讀成上游 model 識別碼。單次觀測、這個 deployment、這個日期,不外推——Day 13 的紀律。

13 個 task review 都過了,然後有人問:正常成功的時候,誰在發?

這個 milestone 由 14 個 task 組成,13 個 task review 全數通過,branch 準備開 PR。final whole-branch review 跑完,回報唯一一個 merge blocker——是一段文件

問題出在 streaming 成功路徑。回頭看 _render_sse(SSE serializer):它 yield 完 message.done 之後立刻 return——Day 6 的「terminal 之後不得再有事件」就是這樣強制的。但這代表它不會再從 _audit_observed 拉下一個值。

於是一個完全健康的 200 結束時,observer 還懸在自己的 yield 上,async for 迴圈從未自然跑完——上面那段 code 的 else: 分支(迴圈正常結束時發成功事件的那條),經這個 endpoint 根本不可達。 成功事件實際上是從 except (GeneratorExit, asyncio.CancelledError) 分支發出來的:asyncio 的 async-generator finalizer 事後關掉這個懸著的 generator 時,跟斷線走同一個出口。

Reviewer 沒有靠讀 code 下這個結論。它寫了一個不動 repo 的 scratch harness,在發射點抓 frame stack:render 迴圈跑完,零 events;把 observer 釋放、event loop 再 tick 一次,事件才出現,發射當下的呼叫鏈結尾是 asyncio 的 finalizer 進到 _audit_observed。「誰在發」這個問題,是用跑的答的,不是用讀的。

值得寫下來的是判定本身:code 是對的——test_stream_success_exactly_one_event 端到端證明事件恰好一筆、內容正確。錯的是我們自己寫的文件:docs/audit-logging.md 把 asyncgen finalizer 依賴寫成只跟 disconnect 有關,讀者會合理推論成功路徑是同步的。

實際上正常 200 的成功事件是在 response body 完成之後才發的;硬砍 process 時,streaming 成功事件跟斷線事件一樣會掉。13 個 review 各自檢查自己那塊、全部說沒問題——因為每一塊真的都沒問題。漏掉的是一個垂直的問題:「這幾塊接起來之後,正常成功的時候,到底是誰在發?」

https://ithelp.ithome.com.tw/upload/images/20260822/20168288VGmxqr0VzB.png
忍喵:你以為成功的 log 行跟 response 一起出門?它是散場後 finalizer 掃地才掃出來的。拿 audit log 的時序當 delivery 證據的人,今天學到一課。

修法是補文件(known-gap 節),並在那個經 endpoint 不可達的 else: 分支上加註解說明它為什麼留著。

留著的理由:直接把 generator iterate 到自然耗盡的呼叫者(generator 層的測試就是)走得到它,而且萬一 endpoint 的消費模式哪天改了,它是正確的 fallback。

分支不刪:離 merge 太近,動它的風險大於留它的成本。

這天的誠實邊界

  • agent.run 與 streaming 的 terminal 沒有 live 驅動過。 smoke 當天 Search 離線壓縮了可達路徑,這兩族只有 unit/BDD 覆蓋。evidence 表格明列,不含混。
  • 真實 socket 斷線的 GeneratorExit 要穿過三層 generator chain 才到 observer,這段端到端沒有獨立證明。 generator 層有精準的 aclose() 測試,但「OS 發現 socket 關了」到「這個 generator 的 finally 跑了」中間是 ASGI/Starlette 的機器,本 repo 沒有東西證明它。而且如上一節——正常 200 的成功事件走的是同一條機制
  • client_disconnect 記的是最常見的原因,不是證明。 那個分支同時接 GeneratorExitasyncio.CancelledError,而 CancelledError 也可能來自 server 端(shutdown、task 取消)。事件證明 stream 在終端前被切斷;證明不了是哪一邊切的。
  • streaming observer 在第一次 iteration 之前被關掉,是一個零 event 的窄窗。 async generator 的 body(連同它的 except)要到第一次 iteration 才開始執行;ownership 交付後、server 拉第一個 frame 之前就被放棄的請求,一筆都不會發。這個窗會漏一筆,永遠不會發錯一筆。
  • 「合約外 bug 零 event」對 /agent 是 route 邊界規則,不是整條 stack 的。 framework adapter(Day 17 的設計)用 except Exception 把 run 範圍內的任何例外——包括真 bug——包成 AgentRunError,到 endpoint 變成合約內的 502 加恰好一筆事件;adapter 範圍之外的 bug 仍是零 event。/chat/chat/stream/rag 沒有這個例外。
  • conversation_idcorrelation_id 是 caller 可控的文字,原樣回寫進事件。 欄位名測試抓的是「欄位」,抓不到「值」;json.dumps 有跳脫所以壞不了 log 行的 JSON 結構,但讀 log 的人不該假設 reference-only 欄位下的每個值都是 server 產生的。刻意不在 merge 前加長度限制——那是行為與契約變更,不搭 audit log 的便車。
  • 這不是 durable、也不是 tamper-evident 的 sink。 它是寫到 process log stream(stderr,所以消費指令是 2>&1 | grep '^{' | jq)的 JSON 行。process crash 在 outcome 與 flush 之間會掉事件;沒有任何機制偵測事後的竄改或遺失。retention 是 hosting log pipeline 的屬性,本 repo 不控制也不假設——這是 Day 27 Application Insights 的伏筆,不是這裡假裝解掉的問題。

https://ithelp.ithome.com.tw/upload/images/20260822/20168288fAvFClEG1x.png
忍喵:reference-only 不代表值是 server 生的——caller 塞什麼你記什麼。你的 dashboard 拿 conversation_id 當分組 key 之前,想過它可能是 4MB 的小說嗎?

下一篇

安全與身分的四篇(Day 19–22)到這裡收束:進來的身分、出去的憑證、內容層的注入,和一份記錄誰做了什麼的 audit log。但上面誠實邊界的最後一條就是下一段旅程的起點——audit log 現在只是 stderr 上的 JSON 行,它要變成一份真的留得下來的紀錄,靠的是部署環境的 log pipeline。Day 23 開始部署鏈:把這個 backend Docker 化,讓 stderr 有個正經的去處。

完整程式碼在 day-22 tag,CI 綠(1436 unit tests、三個 schema export 零 drift):

工程需求 Azure / Microsoft 對應服務 本篇怎麼用
LLM 推論(live smoke) Azure OpenAI(chat-mini=gpt-5-mini,japaneast,常駐純 token 計費) 一筆留有完整證據的 Responses API completion(88 tokens)驗 audit event 真值;未新增任何計費資源

本文由作者規劃與撰寫,AI(Claude)協助草稿整理與程式碼驗證;技術內容與觀點由作者確認並負責。


上一篇
Day 21:Prompt Injection 與 Tool Abuse——把安全防線拆進三欄記帳,才知道自己守不守得住
系列文
Backend 工程師的 Azure GenAI 實戰22
圖片
  熱門推薦
圖片
{{ item.channelVendor }} | {{ item.webinarstarted }} |
{{ formatDate(item.duration) }}
直播中

尚未有邦友留言

立即登入留言