ASP.NET Core – Logging & Serilog

前言

以前就寫過了 Asp.net core 學習筆記 (Logging 日志), 只是有點亂, 這篇作為整理版.

 

參考：

docs – Logging in .NET Core and ASP.NET Core

Github – Serilog.AspNetCore

Setting up Serilog in .NET 6

 

ASP.NET Core Build-in Logging

ASP.NET Core 提供了 Logging 的抽象接口, third party 都會依據抽象來做實現. ASP.NET Core 自己也實現了一套簡單的 log, 它只能 log to console. 不能 log to file.

所以絕大部分項目都會搭配一個 third party library, 比如 Serilog.

我們先看看 ASP.NET Core build-in 的 log.

Quick Example

dotnet new webapp -o TestLog

自帶的模板首頁就有 inject logger 了, 在 OnGet 使用它就可以了.

打開 Visual Studio > View > Output, F5 run 就可以看見了

VS Code 

Log Category

每個 log 都有 category 的概念, 在 appsetting.json 可以為每個 category 設置 min level

比如某 category 在 production 的時候 min level 是 warning, 在 dev 的時候是 info.

像上面的注入方式, 它的 category name 是 namespace + class "TestLog.Pages.IndexModel"

如果想自定義的話可以用 factory 來創建 logger

 在 appsetting.json 聲明 min level

level 的順序是 Trace = 0, Debug = 1, Information = 2, Warning = 3, Error = 4, Critical = 5, and None = 6.

Serilog level 的順序是 Verbose = 0, Debug = 1, Information = 2, Warning = 3, Error = 4, Fatal = 5

None 就是不要 log. Trace 就類似 track 追蹤的意思

 

Serilog 安裝

dotnet add package Serilog.AspNetCore

program.cs

var builder = WebApplication.CreateBuilder(args);
builder.Host.UseSerilog();

Log.Logger = new LoggerConfiguration()
            .MinimumLevel.Override("Microsoft", LogEventLevel.Information)
            .Enrich.FromLogContext()
            .WriteTo.Console()
            .CreateLogger();
try
{
    Log.Information("Starting web host");
    app.Run(); // 把 app.Run(); 放進來
    return 0;
}
catch (Exception ex)
{
    Log.Fatal(ex, "Host terminated unexpectedly");
    return 1;
}
finally
{
    Log.CloseAndFlush();
}

Serilog 的 config 不是通過 appsetting 設置的, 如果想用 appsetting 來管理可以另外安裝一個 DLL, 下面會介紹. 

appsetting 里的 log config 是給 ASP.NET Core build-in log 的哦, Serilog 不會讀取它來用.

 

Formatting Output

參考: Github serilog – Formatting Output

Log.Information 只是填寫了 message, 但最終的 log 需要具備其它的資料比如時間, 而這些就有 output template 來完成.

下面這個是 ConsoleLogger 的默認模板

parameters definition: 

我們可以通過 config 去調整它.

Log.Logger = new LoggerConfiguration()
    .WriteTo.Console(outputTemplate: "[{Timestamp:HH:mm:ss} {Level:u3}] {Message:lj}{NewLine}{Exception}")
    .CreateLogger();

serilog-sinks-console 和 serilog-sinks-file 都支持 outputTemplate 設定. 但如果我們看源碼會發現它們的實現方式不太一樣.

console 源碼顯示, 它有自己實現一套 ITextFormatter

 

而 file 源碼顯示, 它用了 Serilog.Formatting.Display 的 MessageTemplateTextFormatter

 

 

Request Log

Serilog 有一個 build-in 的 request log 取代 ASP.NET Core build-in 的, 因為 ASP.NET Core log 太多了.

先關掉 ASP.NET Core 的

Log.Logger = new LoggerConfiguration()
    .MinimumLevel.Override("Microsoft", LogEventLevel.Warning)
    .MinimumLevel.Override("Microsoft.AspNetCore", LogEventLevel.Warning)

然后

app.UseSerilogRequestLogging(options =>
{
    options.MessageTemplate = "HTTP {RequestMethod} {RequestPath} responded {StatusCode} in {Elapsed:0} ms";
    options.GetLevel = (httpContext, elapsed, ex) => LogEventLevel.Information;
    options.EnrichDiagnosticContext = (diagnosticContext, httpContext) =>
    {
　　　　　// 這里可以加一點料, 加了 template 就可以用 {RequestHost} 這樣
        // diagnosticContext.Set("RequestHost", httpContext.Request.Host.Value);
        // diagnosticContext.Set("RequestScheme", httpContext.Request.Scheme);
    };
});

通過這個 middleware 每個請求都會被記入下來. middleware 放在 static file middleware 下面, 不然 static file 也會被 log 就不好了.

想更 customize 一下可以參考這個 Adding Useful Information to ASP.NET Core Web API Serilog Logs

 

Write to File

安裝

dotnet add package Serilog.Sinks.File

設置

Log.Logger = new LoggerConfiguration()
    .WriteTo.File("log.txt", rollingInterval: RollingInterval.Day)

write to file 是馬上執行的, 這對 IO 性能不太好.

 

Async Write to File

所以 Serilog 推出了一個 async 版本. 它會先寫入 ram, 等一定量之后才寫入 file.

dotnet add package Serilog.Sinks.Async

設置

Log.Logger = new LoggerConfiguration()
 .WriteTo.Async(a => a.File("log.txt", rollingInterval: RollingInterval.Day, buffered: true), bufferSize: 500)

wrap 起來就可以了, buffered = true, buffer size 默認是 10,000 items 那是多少我也不清楚.

然后在 app 結束前一定要釋放哦

try
{
    CreateHostBuilder(args).Build().Run();
}
catch (Exception ex)
{
    Log.Fatal(ex, "Host terminated unexpectedly");
}
finally
{
    Log.CloseAndFlush(); // 重要
}

 

Use appsetting.json as Config

安裝

dotnet add package Serilog.Settings.Configuration

設置

Log.Logger = new LoggerConfiguration()
    .ReadFrom.Configuration(builder.Configuration) 

appsetting.json

 "Serilog": {
    "Using": [ "Serilog.Sinks.File" ], // 這個在 dotnet core project 下是多余的，可以拿掉哦
    "MinimumLevel": {
      "Default": "Information",
      "Override": {
        "Microsoft": "Warning",
        "Microsoft.AspNetCore": "Warning",
        "System": "Warning"
      }
    },
    "WriteTo": [
      {
        "Name": "File",
        "Args": {
          "path": "log.txt",
          "rollingInterval": "Day",
          "outputTemplate": "[{Timestamp:hh:mm:ss tt} {Level:u3}] {Message:lj} {Properties:j}{NewLine}{Exception}"
        }
      },
      {
        "Name": "Async",
        "Args": {
          "configure": [
            {
              "Name": "File",
              "Args": {
                "path": "log-async.txt",
                "rollingInterval": "Day",
                "outputTemplate": "[{Timestamp:hh:mm:ss tt} {Level:u3}] {Message:lj} {Properties:j}{NewLine}{Exception}",
                "buffered": true
              }
            }
          ]
        }
      }
    ],
    "Enrich": [ "FromLogContext" ]
  }

 

Send Email on Error

如果程序不經常出錯的話, 每天查看 log 是挺浪費時間的, 這時就可以改用 Email 通知. 當出現 error 時, 把 error log 發送到我們電郵.

Serilog 有一個插件可以完成這個事兒. 它叫 serilog-sinks-email

很遺憾的是, 我在試用的時候遇到了 SSL 的問題. 可能是它太久沒有更新了吧. 它底層依賴 MailKit

而設定 SSL 的方式是 useSsl

這個是比較古老的 way 了. 在我之前寫的教程中, 調用 MailKit 應該是下面這樣的

所以只好放棄這個插件了. 不開 SSL 倒是可以正常發送, 代碼如下

dotnet add package Serilog.Sinks.Email

program.cs

Log.Logger = new LoggerConfiguration()
    .WriteTo.Email(
            connectionInfo: new EmailConnectionInfo
            {
                EmailSubject = "System Error",
                EnableSsl = false,
                FromEmail = "[e-mail]",
                Port = 587,
                ToEmail = "[e-mail]",
                MailServer = "smtp.office365.com",
                NetworkCredentials = new NetworkCredential
                {
                    UserName = "[e-mail]",
                    Password = "dada"
                },
                ServerCertificateValidationCallback = (sender, certificate, chain, sslPolicyErrors) => true
            },
        restrictedToMinimumLevel: LogEventLevel.Error
    )
    .CreateLogger();

相關 issues: 

Stack Overflow – Serilog.Sinks.Email - No Indication of Failure?

Github – Serilog Email sink is not sending emails

Stack Overflow – SslHandshakeException: An error occurred while attempting to establish an SSL or TLS connection

Stack Overflow – Serilog Email sink enableSSL false checks

Github – Serilog Email Sink not working with .NET Core 5

 

Debug Sink

參考: Github – Debugging and Diagnostics

WriteTo File, Console, Email, Database 都好, by right 是不應該出現 error 的. 因為這個已經是 final 了. 但是在開發階段任何會有 bug 的可能.

比如上面的 send email 就因為 SSL 報錯了. 要 debug 它的話需要開啟 

Serilog.Debugging.SelfLog.Enable(Console.WriteLine);

這樣它就會把 send email 時的錯誤寫入 Console 里. then 用 VS Code DEBUG CONSOLE 就可以看見 Exception 了.

 

自定義 Sink

既然 serilog-sinks-email 滿足不到我們的需求, 那就自己寫一個吧.

參考: Developing a sink 

首先定義 2 個 class

public class MySink : ILogEventSink
{
    public void Emit(LogEvent logEvent)
    {
        var message = logEvent.RenderMessage();
        var level = logEvent.Level;
        var now = logEvent.Timestamp.UtcDateTime;
        var exception = logEvent.Exception;
    }
}

public static class MySinkExtensions
{
    public static LoggerConfiguration MySink(this LoggerSinkConfiguration loggerConfiguration) => loggerConfiguration.Sink(new MySink());
}

然后調用

Log.Logger = new LoggerConfiguration()
    .WriteTo.MySink()
    .CreateLogger();

當 log 發生時 Emit 就會被調用了. 通過 logEvent 可以拿到 message, level, timespan, exception (如果 throw Exception 的話就有), 等等.

有了這些, 我們可以寫入 file, 寫入 Database, 發電子郵件等等. 

但它有幾個點要注意

1. Emit 不支持 async

Github – Asynchronous support throughout Serilog

Github – Changed sinks and loggers to async

C#同步方法中調用異步方法

How to call asynchronous method from synchronous method in C#?

2. 每一次 log 發生都會被調用 (過於頻密).

所以, serilog-sinks-email 里面還依賴了 serilog-sinks-periodicbatching, 它的功能是把 log 搜集起來一次觸發, 同時也支持了 async 寫法.

主要就是替代掉了 ILogEventSink, 然后設定 config

3. 支持 Formatting Output, 可以參考上面的 Console 和 File 是如何支持 Formatting Output 的.

4. Emit 是會被並發調用的

所以參考, ConsoleSink.cs 和 RollingFileSink.cs 的實現. Emit 里面都加了 lock 來確保線程安全.

 

 

自定義 Sink for Send Email on Error

dotnet add package MailKit
dotnet add package Serilog.AspNetCore
dotnet add package Serilog.Sinks.PeriodicBatching

program.cs

using System.Security.Authentication;
using MailKit.Net.Smtp;
using MimeKit;
using Serilog;
using Serilog.Configuration;
using Serilog.Events;
using Serilog.Formatting;
using Serilog.Formatting.Display;
using Serilog.Sinks.PeriodicBatching;

namespace TestLogMySinkEmail;

class MyEmailSink : IBatchedLogEventSink
{
    private readonly ITextFormatter _textFormatter;
    public MyEmailSink(ITextFormatter textFormatter)
    {
        _textFormatter = textFormatter;
    }

    public async Task EmitBatchAsync(IEnumerable<LogEvent> logEvents)
    {
        var logEvent = logEvents.Single();
        var outputWriter = new StringWriter();
        _textFormatter.Format(logEvent, outputWriter);
        var output = outputWriter.ToString();

        using var client = new SmtpClient();
        await client.ConnectAsync(
            host: "smtp.office365.com",
            port: 587,
            options: MailKit.Security.SecureSocketOptions.StartTls
        );
        await client.AuthenticateAsync("[e-mail]", "dada");
        client.SslProtocols = SslProtocols.Tls12 | SslProtocols.Tls13;

        var message = new MimeMessage();
        message.From.Add(new MailboxAddress("dada", "[e-mail]"));
        message.To.Add(new MailboxAddress("dada87", "[e-mail]"));
        var builder = new BodyBuilder
        {
            HtmlBody = $@"
        <!DOCTYPE html>
        <html lang=""en"" xmlns=""http://www.w3.org/1999/xhtml"" xmlns:o=""urn:schemas-microsoft-com:office:office"">
        <head>
            <meta charset=""UTF-8"">
            <meta name=""viewport"" content=""width=device-width,initial-scale=1"">
            <meta name=""x-apple-disable-message-reformatting"">
            <title></title>
            </head>
        <body style=""color:red"">
            <p>{output}</p>
        </body>
        </html>",
        };
        message.Subject = "Website Error Log";
        message.Body = builder.ToMessageBody();
        await client.SendAsync(message);
        await client.DisconnectAsync(quit: true);
    }

    public Task OnEmptyBatchAsync()
    {
        return Task.CompletedTask;
    }
}

public static class LoggerSinkConfigurationExtensions
{
    public static LoggerConfiguration MyEmailSink(
        this LoggerSinkConfiguration loggerSinkConfiguration,
        LogEventLevel restrictedToMinimumLevel = LogEventLevel.Error,
        string outputTemplate = "[{Timestamp:HH:mm:ss} {Level:u3}] {Message:lj}{NewLine}{Exception}"
    )
    {
        var formatter = new MessageTemplateTextFormatter(outputTemplate);
        var myEmailSink = new MyEmailSink(formatter);
        var batchingOptions = new PeriodicBatchingSinkOptions
        {
            BatchSizeLimit = 100,
            Period = TimeSpan.FromSeconds(2),
            EagerlyEmitFirstEvent = true,
            QueueLimit = 10000,
        };

        var batchingSink = new PeriodicBatchingSink(myEmailSink, batchingOptions);
        return loggerSinkConfiguration.Sink(batchingSink, restrictedToMinimumLevel);
    }
}

public class Program
{
    public static void Main(string[] args)
    {
        var builder = WebApplication.CreateBuilder(args);
        builder.Host.UseSerilog();

        Log.Logger = new LoggerConfiguration()
            .MinimumLevel.Override("Microsoft", LogEventLevel.Information)
            .Enrich.FromLogContext()
            .WriteTo.Console(outputTemplate: "[{Timestamp:HH:mm:ss} {Level:u3}] {Message:lj}{NewLine}{Exception}")
            .WriteTo.MyEmailSink(LogEventLevel.Error)
            .CreateLogger();

        builder.Services.AddRazorPages();

        var app = builder.Build();

        if (!app.Environment.IsDevelopment())
        {
            app.UseExceptionHandler("/Error");
            app.UseHsts();
        }

        app.UseHttpsRedirection();
        app.UseStaticFiles();

        app.UseRouting();

        app.UseAuthorization();

        app.MapRazorPages();

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

index.cshtml.cs

using Microsoft.AspNetCore.Mvc.RazorPages;

namespace TestLogMySinkEmail.Pages;

public class IndexModel : PageModel
{
    private readonly ILogger<IndexModel> _logger;

    public IndexModel(ILogger<IndexModel> logger)
    {
        _logger = logger;
    }

    public void OnGet()
    {
        throw new Exception("Error");
    }
}