使用Serilog和Seq紀錄Log

以往使用 ELK 來記錄資訊，是一件非常複雜繁瑣的事情，與 ELK 還有一堆 beat 打交道，首先要面對的是不熟悉的 linux 系統，接著是聽都沒聽過的一堆設定方式跟眉眉角角，太久沒用我連 SSL 都忘記怎麼用，更別提複雜的設定語法。而使用 Serilog + Seq 就相對簡單很多，查詢語法也比 Kibana 友善。

本次練習專案:Github:serilog-seq-demo

使用 serilog 和 seq 紀錄 log

參考連結

學習過程中下面這幾篇文章幫助很大，特別是Logging MVC properties with Serilog.AspNetCore系列文，介紹的非常詳細。

  1. .NET 6.0 如何使用 Serilog 對應用程式事件進行結構化紀錄
  2. Serilog 2.1 MinimumLevel.Override()
  3. Logging MVC properties with Serilog.AspNetCore

使用 Docker 架設 Seq

# create volume folder
mkdir -p D:\docker-volumes\seq

# docker-cli
docker run --name seq -d --restart unless-stopped -e ACCEPT_EULA=Y -v D:\docker-volumes\seq:/data -p 8090:80 -p 5341:5341 datalust/seq

# docker-compose
version: "3"
services:
  seq_server:
    image: datalust/seq
    restart: always
    container_name: seq
    hostname: seq
    environment:
      - ACCEPT_EULA=Y
    ports:
      - 8090:80
      - 5341:5341
    volumes:
      - d:/docker-volumes/seq/data:/data

使用 Serilog 搭配 Seq

Serilog 能夠解決什麼問題

在 dotnet core 範本預設的日誌設定下，development環境下光是一個頁面請求就會輸出非常多的 Log，但在Production環境下又完全不輸出日誌，雖然可以透過自訂過濾器來精簡日誌，但仍舊是各自獨立的 Log

Serilog.RequestLoggingMiddleware不是為了請求中的每個步驟建立單獨的 Log 紀錄，而是建立一個包含所有相關資訊的摘要 Log，也正是因為它是一個 middleware，所以可以將之後所需要紀錄的資訊都統整在一起，對於檢視、查詢會很有幫助

安裝套件

dotnet add package Serilog.AspNetCore
dotnet add package Serilog.Sinks.Console
dotnet add package Serilog.Sinks.Seq

將預設 Log 替換為 Serilog

// 指定 LOG 輸出到 Console 及 Seq
Log.Logger = new LoggerConfiguration()
    .Enrich.FromLogContext()
    .WriteTo.Console()
    .WriteTo.Seq("http://localhost:5341")
    .CreateLogger();

// 使用 Serilog
builder.Host.UseSerilog();


// 使用 Serilog RequestLoggingMiddleware
app.UseSerilogRequestLogging(options =>
{
    // 自訂紀錄的訊息範本格式，修改後並不會影響結構化記錄的屬性
    options.MessageTemplate = "Handled  {RequestPath}";

    // 附加資訊到每一次的請求完成事件，可以從 httpContext 取得 HttpContext 下所有可以取得的資訊
    options.EnrichDiagnosticContext = (diagnosticContext, httpContext) =>
    {
        diagnosticContext.Set("RequestHost", httpContext.Request.Host.Value);
        diagnosticContext.Set("RequestScheme", httpContext.Request.Scheme);
        diagnosticContext.Set("UserID", httpContext.User.Identity?.Name);
    };
});

記錄範例

LogLevel

在 Serilog 共計有六種，列舉值高表示越重要

namespace Serilog.Events
{
    /// <summary>
    /// Specifies the meaning and relative importance of a log event.
    /// </summary>
    public enum LogEventLevel
    {
        /// <summary>
        /// Anything and everything you might want to know about
        /// a running block of code.
        /// </summary>
        Verbose,

        /// <summary>
        /// Internal system events that aren't necessarily
        /// observable from the outside.
        /// </summary>
        Debug,

        /// <summary>
        /// The lifeblood of operational intelligence - things
        /// happen.
        /// </summary>
        Information,

        /// <summary>
        /// Service is degraded or endangered.
        /// </summary>
        Warning,

        /// <summary>
        /// Functionality is unavailable, invariants are broken
        /// or data is lost.
        /// </summary>
        Error,

        /// <summary>
        /// If you have a pager, it goes off when one of these
        /// occurs.
        /// </summary>
        Fatal
    }
}

紀錄額外資訊

public class HomeController : Controller
{
    private readonly ILogger<HomeController> _logger;
    public HomeController(ILogger<HomeController> logger)
    {
        _logger = logger;
    }

    public IActionResult Index()
    {
        _logger.LogInformation("使用者資訊 , {@user}", new { Name = "art", Role = "Developer" });
        return View();
    }
}

使用logger可記錄複雜型別物件資訊，

Serilog middleware 全站附加的範例

於program.cs內設定如下

// 設置 Serilog
app.UseSerilogRequestLogging(options =>
{
    // 自訂紀錄的訊息範本格式，修改後並不會影響結構化記錄的屬性
    options.MessageTemplate = "Handled  {RequestPath}";

    // 附加資訊到每一次的請求完成事件，可以從 httpContext 取得 HttpContext 下所有可以取得的資訊
    options.EnrichDiagnosticContext = (diagnosticContext, httpContext) =>
    {
        diagnosticContext.Set("RequestHost", httpContext.Request.Host.Value);
        diagnosticContext.Set("RequestScheme", httpContext.Request.Scheme);
        diagnosticContext.Set("UserID", httpContext.User.Identity?.Name);
    };
});

Serilog middleware 手動附加的範例

於要附加的地方透過 DI 注入的 IDiagnosticContext 實體附加資訊

public class HomeController : Controller
{
    private readonly ILogger<HomeController> _logger;
    private readonly IDiagnosticContext _diagnosticContext;
    public HomeController(ILogger<HomeController> logger, IDiagnosticContext diagnosticContext)
    {
        _logger = logger;
        _diagnosticContext = diagnosticContext;
    }

    public IActionResult Index()
    {
        _diagnosticContext.Set("Params", new[] { 1, 2, 3 });
        return View();
    }
}

若沒有使用自訂訊息範本，預設顯示範本格式為:HTTP {RequestMethod} {RequestPath} responded {StatusCode} in {Elapsed:0.0000} ms

至此先前 dotnet core 預設各自獨立 LOG 紀錄已經被整合在同一筆 LOG 中，而需要特別記錄下來的資訊也可以透過手動的方式另外建立

額外紀錄 Serilog 缺少的資訊 - Request / Response

改用 Serilog 之後，原本有的一些資訊也可以透過附加的方式補上

  // 設置 Serilog
    app.UseSerilogRequestLogging(options =>
    {
        // 自訂紀錄的訊息模板
        // options.MessageTemplate = "Handled  {RequestPath}";

        // 附加資訊到每一次的請求完成事件
        options.EnrichDiagnosticContext = (diagnosticContext, httpContext) =>
        {
            var request = httpContext.Request;

            // Set all the common properties available for every request
            diagnosticContext.Set("Host", request.Host);
            diagnosticContext.Set("Protocol", request.Protocol);
            diagnosticContext.Set("Scheme", request.Scheme);

            // Only set it if available. You're not sending sensitive data in a querystring right?!
            if(request.QueryString.HasValue)
            {
                diagnosticContext.Set("QueryString", request.QueryString.Value);
            }

            // Set the content-type of the Response at this point
            diagnosticContext.Set("ContentType", httpContext.Response.ContentType);

            // Retrieve the IEndpointFeature selected for the request
            var endpoint = httpContext.GetEndpoint();
            if (endpoint is object) // endpoint != null
            {
                diagnosticContext.Set("EndpointName", endpoint.DisplayName);
            }
        };
    });

額外紀錄 Serilog 缺少的資訊 - MVC

在 MVC 框架下，相關資訊可以透過 ActionFilter的 OnActionExecuting()去取得 context物件

public class SerilogLoggingActionFilter : IActionFilter
{
    private readonly IDiagnosticContext _diagnosticContext;
    public SerilogLoggingActionFilter(IDiagnosticContext diagnosticContext)
    {
        _diagnosticContext = diagnosticContext;
    }

    public void OnActionExecuting(ActionExecutingContext context)
    {
        _diagnosticContext.Set("RouteData", context.ActionDescriptor.RouteValues);
        _diagnosticContext.Set("ActionName", context.ActionDescriptor.DisplayName);
        _diagnosticContext.Set("ActionId", context.ActionDescriptor.Id);
        _diagnosticContext.Set("ValidationState", context.ModelState.IsValid);
    }

    // Required by the interface
    public void OnActionExecuted(ActionExecutedContext context){}
}

註冊 action filter

    // Add services to the container.
    builder.Services.AddControllersWithViews(config =>
    {
        // 註冊 serilog action filter
        config.Filters.Add(typeof(SerilogLoggingActionFilter));
    });

過濾不需要的訊息

原本 dotnet core 會產生大量的 Log 事件，在使用 Serilog 之後，回顧所有事件會發現有很多類似的事件一直被記錄下來，這個時候可以透過MinimumLevel.Override來過濾掉這類事件

MinimumLevel.Override("Microsoft.AspNetCore", LogEventLevel.Warning)

上述程式碼表示:只有在命名空間Microsoft.AspNetCore所發出的Warning層級，或以上層級的事件才會被記錄下來，因此我們可以在設定的部分改寫如下

Log.Logger = new LoggerConfiguration()
    .MinimumLevel.Debug()
    .MinimumLevel.Override("Microsoft", LogEventLevel.Information)
    // Filter out ASP.NET Core infrastructre logs that are Information and below
    .MinimumLevel.Override("Microsoft.AspNetCore", LogEventLevel.Warning)
    .Enrich.FromLogContext()
    .WriteTo.Console()
    .WriteTo.Seq("http://localhost:5341")
    .CreateLogger();

紀錄兩份層級不同的 Log

有的時候可能會希望記錄兩份不同層級的 LOG 紀錄，例如一份比較精簡的放到 Console，另外一份比較詳細的則輸出到 File

所有的接收器都提供了restrictedToMinimumLevel可用來至指定層級，參考設定的方式如下

Log.Logger = new LoggerConfiguration()
    .MinimumLevel.Debug()
    .WriteTo.File("log.txt")
    .WriteTo.Console(restrictedToMinimumLevel: LogEventLevel.Information)
    .CreateLogger();

情境:不想記錄非必要的請求

像是 healthy check 的請求，也會被記錄下來，但是這對我們是沒有意義的，所以我們可以透過調整先前所學過的設定方式來指定我們想要紀錄的東西

關鍵程式碼如下

    app.UseSerilogRequestLogging(opts => {
        opts.EnrichDiagnosticContext = LogHelper.EnrichFromRequest;
        opts.GetLevel = LogHelper.ExcludeHealthChecks; // Use the custom level
    });

public static class LogHelper
{
    public static LogEventLevel ExcludeHealthChecks(HttpContext ctx, double _, Exception ex) =>
        ex != null
            ? LogEventLevel.Error
            : ctx.Response.StatusCode > 499
                ? LogEventLevel.Error
                : IsHealthCheckEndpoint(ctx) // Not an error, check if it was a health check
                    ? LogEventLevel.Verbose // Was a health check, use Verbose
                    : LogEventLevel.Information;

    private static bool IsHealthCheckEndpoint(HttpContext ctx)
    {
        var endpoint = ctx.GetEndpoint();
        if (endpoint is object) // same as !(endpoint is null)
        {
            return string.Equals(
                endpoint.DisplayName,
                "Health checks",
                StringComparison.Ordinal);
        }
        // No endpoint, so not a health check endpoint
        return false;
    }
}

完整範例

// program.cs
using seq_demo.Filters;
using seq_demo.Helper;
using Serilog;
using Serilog.Events;

// 指定 LOG 輸出到 Console 及 Seq
Log.Logger = new LoggerConfiguration()
    .MinimumLevel.Debug()
    .MinimumLevel.Override("Microsoft", LogEventLevel.Information)
    // Filter out ASP.NET Core infrastructre logs that are Information and below
    .MinimumLevel.Override("Microsoft.AspNetCore", LogEventLevel.Warning)
    .Enrich.FromLogContext()
    .WriteTo.Console()
    .WriteTo.Seq("http://localhost:5341")
    .CreateLogger();

try
{
    var builder = WebApplication.CreateBuilder(args);
    // 使用 Serilog
    builder.Host.UseSerilog();

    // Add services to the container.
    builder.Services.AddControllersWithViews(config =>
    {
        // 註冊 serilog action filter
        config.Filters.Add(typeof(SerilogLoggingActionFilter));
    });

    var app = builder.Build();

    // Configure the HTTP request pipeline.
    if (!app.Environment.IsDevelopment())
    {
        app.UseExceptionHandler("/Home/Error");
        // The default HSTS value is 30 days. You may want to change this for production scenarios, see https://aka.ms/aspnetcore-hsts.
        app.UseHsts();
    }

    app.UseHttpsRedirection();

    app.UseStaticFiles();
    // 設置 Serilog
    app.UseSerilogRequestLogging(options =>
    {
        // 自訂紀錄的訊息模板
        // options.MessageTemplate = "Handled  {RequestPath}";

        // 附加資訊到每一次的請求完成事件
        options.EnrichDiagnosticContext = (diagnosticContext, httpContext) =>
        {
            var request = httpContext.Request;

            // Set all the common properties available for every request
            diagnosticContext.Set("Host", request.Host);
            diagnosticContext.Set("Protocol", request.Protocol);
            diagnosticContext.Set("Scheme", request.Scheme);

            // Only set it if available. You're not sending sensitive data in a querystring right?!
            if(request.QueryString.HasValue)
            {
                diagnosticContext.Set("QueryString", request.QueryString.Value);
            }

            // Set the content-type of the Response at this point
            diagnosticContext.Set("ContentType", httpContext.Response.ContentType);

            // Retrieve the IEndpointFeature selected for the request
            var endpoint = httpContext.GetEndpoint();
            if (endpoint is object) // endpoint != null
            {
                diagnosticContext.Set("EndpointName", endpoint.DisplayName);
            }
        };

        options.GetLevel = LogHelper.CustomGetLevel;
    });

    app.UseRouting();
    app.UseAuthorization();
    app.MapControllerRoute(name: "default", pattern: "{controller=Home}/{action=Index}/{id?}");

    app.Run();
}
catch (Exception e)
{
    Log.Fatal(e, "Host terminated unexpectedly");
}
finally
{
    Log.CloseAndFlush();
}

// LogHelper.cs
using Serilog.Events;

namespace seq_demo.Helper;
public static class LogHelper
{
    public static LogEventLevel CustomGetLevel(HttpContext ctx, double _, Exception? ex) =>
        ex != null
            ? LogEventLevel.Error
            : ctx.Response.StatusCode > 499
                ? LogEventLevel.Error
                : LogEventLevel.Debug;
}

// SerilogLoggingActionFilter.cs
public class SerilogLoggingActionFilter : IActionFilter
{
    private readonly IDiagnosticContext _diagnosticContext;
    public SerilogLoggingActionFilter(IDiagnosticContext diagnosticContext)
    {
        _diagnosticContext = diagnosticContext;
    }

    public void OnActionExecuting(ActionExecutingContext context)
    {
        _diagnosticContext.Set("RouteData", context.ActionDescriptor.RouteValues);
        _diagnosticContext.Set("ActionName", context.ActionDescriptor.DisplayName);
        _diagnosticContext.Set("ActionId", context.ActionDescriptor.Id);
        _diagnosticContext.Set("ValidationState", context.ModelState.IsValid);
    }

    public void OnActionExecuted(ActionExecutedContext context){}
}

補充

在之後的練習，我採用的是透過 zipKin 做分散式追蹤

REF: NET6 Core distributed tracing

也因此不需要在 Seq 的介面中自行先過濾資料，只需要給定一個時間範圍就可以看到那段期間的請求，查看詳細就可以看到每一個 traceId 底下各個 spanId 的資訊，而 Seq 則是想知道更詳細的其他資訊，再透過語法查詢其他資料，像是將一些查詢條件設定成 Signal，如下所示