Day17_怎麼回溯之前發生的事？談 Log 的重要性

前言

Day16 把到期提醒交給 Hangfire 定時執行。白天測試時一切正常，真正到了凌晨一點，卻可能因為資料庫斷線、Email 服務沒回應，或某一筆 Task 的資料異常而失敗。等到隔天上班，現場早已過去。

如果程式沒有留下紀錄，面對一句「昨晚的提醒沒寄出去」，就只能猜測。到底是工作沒有啟動，還是啟動後停在某一封信？沒人知道。

Log（日誌）就像系統自己寫的值班筆記。它會記下什麼時候收到請求、正在處理哪一筆工作，以及錯誤發生在哪裡。Log 不會自動修好 Bug，它的工作是留下線索，讓開發者從紀錄判斷程式停在哪一步。

完整範例放在 SerilogSample。這是一個可以獨立啟動的 ASP.NET Core Web API，會將 Log 同時寫到 Console 與每日輪替的檔案。接下來會實際送出 HTTP Request，觀察成功、找不到資料與發生例外時，各自會留下什麼紀錄。

Log 要記什麼？

監視器拍得再清楚，如果沒有時間，還是很難找到某件事。Log 也一樣。單純寫下「處理失敗」，通常幫不上忙。至少要讓調查的人能回答這幾個問題：

• 什麼時候發生？
• 發生在哪一個功能？
• 這次處理的資料編號是什麼？
• 同一次請求還經過了哪些步驟？
• 如果失敗，例外類型是什麼？錯誤一路經過哪些程式位置？

其中 Trace ID 很像報案編號。可以把一次 HTTP Request 想成一張送進公司的工作單：Middleware 是門口的收件人，Endpoint 負責分派工作，Service 處理規則，Repository 則到資料庫讀寫資料。工作單經過每一站時都可能留下紀錄，只要帶著同一個 Trace ID，就能確認這些紀錄屬於同一次操作。

Log Level 像事件的音量

不是每件事都需要拉響警報。Information 可以記錄正常進度，Warning 表示有些狀況需要注意，但不一定已經壞掉。真正讓這次操作失敗的問題，才記成 Error。

如果每一行都是 Error，畫面會一片紅，真正的異常反而被淹沒。Log Level 的用途是替事件選擇合適的音量，不是讓每件事都大聲喊叫。

ILogger<T>、NLog 與 Serilog 是什麼關係？

ASP.NET Core 通常讓 Service 依賴 ILogger<T>。它像一張統一格式的值班紀錄表，商業邏輯只要填入「記一筆 Information」與事件內容，不必知道這張紀錄最後會送到 Console、檔案或雲端平台。

NLog 和 Serilog 是實際整理、加工並送出日誌的系統。NLog 使用 Target 決定輸出目的地，再用 Rule 安排不同等級的日誌。Serilog 也有類似概念，輸出目的地稱為 Sink，可以先把它理解成日誌的「收件地址」。

這篇使用 Serilog 說明「結構化日誌」。一般文字日誌像把所有資訊寫成一句話；結構化日誌則像填表格，時間、Trace ID 與 WorkItemId 都有自己的欄位。需要調查問題時，可以直接依工作項目編號查詢，不必逐行閱讀整份文字。

下載並啟動完整專案

電腦需要先安裝 .NET 10 SDK。開啟終端機後執行：

git clone https://github.com/JJDing-Louis/SerilogSample.git
cd SerilogSample

Clone 完成後，可以用 IDE 或終端機啟動，選自己習慣的方式就好。

以下使用 Rider 示範。開啟專案後，先確認右上角的執行設定是 SerilogSample.Api: http，再按下綠色執行按鈕：

下方 Console 出現 Now listening on: http://localhost:5044，表示 Web API 已經開始監聽連線。先不要急著關掉這個視窗，稍後送出 Request 時，Log 會繼續顯示在這裡。

如果不使用 IDE，也可以在專案根目錄執行同一個啟動指令：

dotnet run --project src/SerilogSample.Api/SerilogSample.Api.csproj \
  --urls http://localhost:5044

專案把 API 進入點、Endpoint、Service 與資料存取分開：

SerilogSample/
├── src/SerilogSample.Api/
│   ├── Endpoints/
│   ├── Models/
│   ├── Repositories/
│   ├── Services/
│   ├── Program.cs
│   └── appsettings.json
└── tests/SerilogSample.Api.Tests/

本文實測的主要套件版本如下：

先決定 Log 要去哪裡

appsettings.json 設定了 Console 與 File 兩個 Sink：

{
  "Serilog": {
    "Using": [
      "Serilog.Sinks.Console",
      "Serilog.Sinks.File"
    ],
    "MinimumLevel": {
      "Default": "Information",
      "Override": {
        "Microsoft": "Warning",
        "Microsoft.Hosting.Lifetime": "Information"
      }
    },
    "WriteTo": [
      {
        "Name": "Console",
        "Args": {
          "outputTemplate": "[{Timestamp:HH:mm:ss} {Level:u3}] {Message:lj} {Properties:j}{NewLine}{Exception}"
        }
      },
      {
        "Name": "File",
        "Args": {
          "path": "logs/log-.txt",
          "rollingInterval": "Day",
          "retainedFileCountLimit": 14,
          "outputTemplate": "{Timestamp:O} [{Level:u3}] {Message:lj} {Properties:j}{NewLine}{Exception}"
        }
      }
    ],
    "Enrich": ["FromLogContext"],
    "Properties": {
      "Application": "SerilogSample"
    }
  }
}

Default 設成 Information，代表一般事件從 Information 開始記錄。Microsoft 開頭的類別改成 Warning，可以減少框架訊息，避免商業事件被大量細節蓋住。Microsoft.Hosting.Lifetime 另外保留 Information，因為服務的啟動與停止時間仍有查閱價值。

檔案每天輪替，最多保留 14 份。這只是適合本機學習的簡單上限；正式系統還要依日誌量、稽核需求與儲存費用定保存政策。

在 Program.cs 接上 Serilog

Program.cs 的主要設定如下：

using Serilog;
using Serilog.Context;

Log.Logger = new LoggerConfiguration()
    .WriteTo.Console()
    .CreateBootstrapLogger();

try
{
    Log.Information("正在啟動 SerilogSample");

    WebApplicationBuilder builder = WebApplication.CreateBuilder(args);

    builder.Services.AddSerilog((services, configuration) => configuration
        .ReadFrom.Configuration(builder.Configuration)
        .ReadFrom.Services(services)
        .Enrich.FromLogContext());

    WebApplication app = builder.Build();

    app.Use(async (httpContext, next) =>
    {
        using (LogContext.PushProperty("TraceId", httpContext.TraceIdentifier))
        {
            await next(httpContext);
        }
    });

    app.UseSerilogRequestLogging();

    // 其他 Endpoint 的註冊要放在 Request Logging 後面。
    await app.RunAsync();
}
catch (Exception exception)
{
    Log.Fatal(exception, "SerilogSample 意外停止");
}
finally
{
    await Log.CloseAndFlushAsync();
}

Bootstrap Logger 是提早到班的值班人員。正式設定還沒讀取完成時，如果應用程式啟動失敗，它能先把問題寫到 Console。等設定檔與 Dependency Injection 準備完成，也就是系統已經把需要的工具交給各個類別後，再由 AddSerilog 接手完整設定。

UseSerilogRequestLogging() 像門口的登記人員，會替每次 HTTP Request 留下一筆摘要，包括使用的 Method、請求路徑、回應狀態碼與處理時間。它只能記錄排在後面的處理流程，所以必須在 Endpoint 註冊之前加入。

LogContext.PushProperty 會替當次 Request 貼上 Trace ID，這段處理流程產生的每筆日誌都會帶著相同編號。之後查看 Request Log 與 Service Log，就能知道它們是否來自同一次操作。

寫下可以查詢的事件

WorkItemService 依賴 ILogger<WorkItemService>，沒有直接依賴 Serilog 的靜態 Log 類別：

public sealed class WorkItemService : IWorkItemService
{
    private readonly IWorkItemRepository _repository;
    private readonly ILogger<WorkItemService> _logger;

    public WorkItemService(
        IWorkItemRepository repository,
        ILogger<WorkItemService> logger)
    {
        ArgumentNullException.ThrowIfNull(repository);
        ArgumentNullException.ThrowIfNull(logger);

        _repository = repository;
        _logger = logger;
    }

    public async Task<WorkItemResponse?> CompleteAsync(
        long workItemId,
        CancellationToken cancellationToken)
    {
        _logger.LogInformation(
            "開始完成工作項目 {WorkItemId}",
            workItemId);

        try
        {
            WorkItem? workItem = await _repository.CompleteAsync(
                workItemId,
                cancellationToken);

            if (workItem is null)
            {
                _logger.LogWarning(
                    "找不到工作項目 {WorkItemId}",
                    workItemId);
                return null;
            }

            _logger.LogInformation(
                "工作項目 {WorkItemId} 已完成",
                workItemId);

            return new WorkItemResponse(
                workItem.Id,
                workItem.Title,
                workItem.Status,
                workItem.UpdatedAt);
        }
        catch (OperationCanceledException)
            when (cancellationToken.IsCancellationRequested)
        {
            throw;
        }
        catch (Exception exception)
        {
            _logger.LogError(
                exception,
                "完成工作項目 {WorkItemId} 時發生錯誤",
                workItemId);
            throw;
        }
    }
}

這裡有三個細節很容易被忽略。

第一，請使用訊息範本，不要先用字串插值把所有資料黏成一句話。訊息範本裡的 {WorkItemId} 就像表格欄位名稱，Serilog 會把傳入的值放進對應欄位：

// 建議：WorkItemId 會成為獨立屬性。
_logger.LogInformation(
    "工作項目 {WorkItemId} 已完成",
    workItemId);

// 不建議：只留下組好的字串。
_logger.LogInformation($"工作項目 {workItemId} 已完成");

第二，記錄錯誤時要把 exception 物件傳給 LogError。只寫 exception.Message，通常只會留下「連線失敗」這類簡短訊息。完整的 exception 還會保留 Stack Trace，也就是錯誤經過哪些方法、最後從哪一行程式碼拋出。

第三，catch 後仍然 throw。Log 只是留下紀錄，不等於問題已經處理完。如果把例外吞掉，上層可能誤以為 Task 已完成，這比直接失敗更難追。

當中止是由呼叫端取消所造成時，範例會直接將 OperationCanceledException 往外傳，不記成 Error。使用者離開頁面與資料庫故障是兩種不同的狀況，不該在日誌裡混在一起。

不用等凌晨，直接送出請求

專案啟動後，另開一個終端機執行：

curl -i http://localhost:5044/health
curl -i -X POST http://localhost:5044/work-items/1001/complete
curl -i -X POST http://localhost:5044/work-items/9999/complete
curl -i -X POST http://localhost:5044/work-items/5000/complete

下圖是實際送出三個 Work Item Request 的結果。先看每段回應的第一行：200 是成功、404 是找不到資料，500 則表示處理途中發生例外。先從狀態碼判斷結果，再回頭對照 Log，會比直接在一大串訊息裡找錯誤快得多。

範例預先準備了一筆編號 1001 的 Task；5000 則專門用來模擬儲存失敗，方便觀察 Error Log。這是教學用設計，不是正式系統應該使用的特殊編號規則。

本次測試環境為 macOS 與 .NET SDK 10.0.201，實際執行結果如下：

送完 Request 後回到 IDE，可以在 Console 看到每次操作留下的紀錄。畫面中的 1001 成功完成，所以是 INF；5000 模擬儲存失敗，因此出現 ERR 與完整的 Stack Trace。

為了方便閱讀，成功完成 Task 的紀錄縮短如下：

[INF] 開始完成工作項目 1001
      {"WorkItemId": 1001, "TraceId": "0HNO...:00000001"}
[INF] 工作項目 1001 已完成
      {"WorkItemId": 1001, "TraceId": "0HNO...:00000001"}
[INF] HTTP POST /work-items/1001/complete responded 200
      {"TraceId": "0HNO...:00000001"}

同一批紀錄也會寫進 src/SerilogSample.Api/logs/。檔名包含日期，例如圖中的 log-20260916.txt。打開檔案後，可以看到完整時間、Log Level、事件屬性與例外堆疊；就算 Console 已經被關掉，仍能回頭查看。

文章為了排版縮短了時間與其他屬性，實際輸出會更完整。重點是三筆紀錄具有同一個 Trace ID，WorkItemId 也是可以單獨取得的屬性。

查詢不存在的 9999 時，API 仍然正常回應 404，所以 Service 寫下 Warning。5000 所模擬的儲存錯誤則讓這次操作中斷，因此會看到 Error 與 InvalidOperationException。這也說明了 Log Level 應該根據處理結果選擇，不是看訊息字面上有沒有「錯」這個字。

Development 環境還可以開啟 http://localhost:5044/openapi/v1.json。本次實測時，這個 Endpoint 回傳 200 OK，代表描述 API 路徑與回應格式的 OpenAPI 文件已經產生。

用 NUnit 檢查「記得對不對」

日誌也是可以測試的行為。範例不會在單元測試中真的寫檔案，而是使用記憶體 Logger 收集事件，然後檢查：

• 成功時會回傳完整的 Task，並留下開始與完成紀錄。
• 查無資料時回傳 null，同時留下含 WorkItemId 的 Warning。
• Repository 拋出例外時，Error Log 會保留原本例外與 WorkItemId，例外也會繼續向外傳。
• 呼叫端取消操作時，不會把正常的取消誤記成 Error。

完整測試可以執行：

dotnet test SerilogSample.slnx --configuration Release

實際執行結果為：

已通過! - 失敗: 0，通過: 11，略過: 0，總計: 11

Release 非增量建置的結果是 0 個警告、0 個錯誤。這 11 個測試都不會連資料庫、寫真實 Log 檔或開啟網路連線。

單元測試證明 Service 選擇了正確的等級與屬性；前一節的 HTTP 實測則證明應用程式真的能啟動，Request Log 與檔案 Sink 也會工作。兩者檢查的層次不同，不能只跑其中一個就當成全部都沒問題。

別把秘密寫進 Log

Log 往往活得比一次 Request 久。它可能被備份、上傳到集中式平台，還可能開放給多位維運人員查詢。因此，下列資料不應該直接寫入：

• 密碼、JWT、Refresh Token 與 Cookie
• 完整的 Request Body，因為裡面可能有個資
• 信用卡號、身分證號與其他敏感資料
• 資料庫連線字串或第三方 API Key

真的需要辨識使用者時，優先記錄系統內部 ID，而不是 Email 或其他個人資料。日誌平台也要有存取權限、保存期限與刪除流程。

範例可以執行，但還不是正式環境

SerilogSample 使用記憶體資料，程式重啟後狀態就會消失。File Sink 也是為了讓讀者在本機直接找到結果。如果應用程式放在 Container 裡，實務上通常會把 Log 寫到標準輸出，再交給部署平台收集，否則 Container 被替換時，裡面的檔案也可能一起消失。

日誌量變大後，還要處理集中查詢、告警、容量上限與保存政策。如果一個失敗流程在 Service、Request Middleware 與全域例外處理各記一次 Error，也要確認這些紀錄各自有沒有用途，免得同一個問題連續發出多次告警。

Log 不是越多越好。能讓人用時間、Trace ID 與業務編號找回現場，同時不洩漏秘密，才是可以信任的紀錄。

小結

Day16 讓 Hangfire 成為凌晨值班的工作人員，這一篇再把 Log 變成它的交班筆記。當到期提醒失敗，不必重演昨晚的每一步。先循著 Trace ID 與 WorkItemId 查看紀錄，就能把時間花在真正出錯的位置。

問題找到後，程式碼一定會繼續修改。接著的 Day18 會談 Git，看看如何保留這些修改紀錄，並在改錯時找得回前一個版本。

參考資料

• SerilogSample 完整範例
• Microsoft Learn：Logging in C# and .NET
• Serilog.AspNetCore 官方說明
• Serilog：Writing Log Events
• Serilog.Settings.Configuration 官方說明
• Serilog.Sinks.File 官方說明
• NLog 官方 Repository