.NET5 Logging with Serilog and SQL Server

好文章留存。

引言

ASP.NET Core Logging with Serilog and SQL Server. 原文寫的很好。謹作重點摘錄。非入門文章。

請參考原文

ASP.NET Core Logging with Serilog and SQL Serverwww.carlrippon.com

Serilog.Sinks.MSSqlServer 使用範例

GitHub - serilog-mssql/serilog-sinks-mssqlserver: A Serilog sink that writes events to Microsoft SQL Server and Azure SQLGitHub

Serilog.Sinks.MSSqlServer 官網

重點摘錄/程式碼紀錄

前置技能：基本的 Serilog 建置與組態能力。

Serilog 導入紀錄 for ASP.NET Core | 取之於網路 - GitBook | 取之於網路 用之於網路rely-ky.gitbook.io

基本的 Serilog 建置與組態

First we need to bring in the following nuget packages:

• Serilog.AspNetCore

• Serilog.Settings.Configuration (option)

• Serilog.Formatting.Compact

• Serilog.Sinks.MSSqlServer

• Serilog.Sinks.Async

• Serilog.Sinks.File

Create the Log table

Serilog.table.sql

CREATE TABLE [dbo].[Serilog](
	[Id] [int] IDENTITY(1,1) NOT NULL,
	[TimeStamp] [datetimeoffset](7) NOT NULL,
	[Level] [nvarchar](128) NULL,
	[Message] [nvarchar](max) NULL,
	[AuthUser] [nvarchar](128) NULL,   -- 延伸欄位
	[ClassName] [nvarchar](128) NULL,  -- 延伸欄位
	[MethodName] [nvarchar](128) NULL, -- 延伸欄位
	[Exception] [nvarchar](max) NULL,
	[LogEvent] [nvarchar](max) NULL,
	
	CONSTRAINT [PK_Serilog] PRIMARY KEY CLUSTERED ([Id] DESC)
)

-- ## 一些欄位說明
-- [LogEvent]   放LOG明細,為json格式。取代[Properties]欄位。新的 StandardColumn。
-- [Properties] 放LOG明細,為xml格式。已無效用的 StandardColumn。。
-- [MessageTemplate] 已無效用的 StandardColumn。
-- [AuthUser] 延伸欄位，放登入使用者。
-- [ClassName] 延伸欄位，放執行點的Class名稱。
-- [MethodName] 延伸欄位，放執行點的Method名稱。

由 appSettings.json 設定 Serilog 組態

appSettings.json

{
  "ConnectionStrings": {
    "YOURLOGDB": "<your connection string>"
  },
  "Serilog": {
    "Using": [ "Serilog.Sinks.Async", "Serilog.Sinks.File", "Serilog.Sinks.MSSqlServer" ],
    "MinimumLevel": {
      "Default": "Information",
      "Override": {
        "Microsoft.AspNetCore.SignalR": "Information",
        "Microsoft.AspNetCore.Http.Connections": "Information",
        "Microsoft": "Warning",
        "System": "Warning"
      }
    },
    "WriteTo": [
      {
        "Name": "Async", // 非同步寫入log
        "Args": {
          "configure": [
            {
              // log to file
              "Name": "File",
              "Args": {
                "path": "Log/myapp.json",
                "formatter": "Serilog.Formatting.Json.JsonFormatter",
                "rollingInterval": "Day"
              }
            },
            {
              // log to SQL Server
              "Name": "MSSqlServer",
              "Args": {
                "connectionString": "YOURLOGDB", //※連線字串或連線名稱
                "tableName": "Serilog", //※Log table name
                "columnOptionsSection": {
                  "addStandardColumns": [ "LogEvent" ], // 加入新的StandardColumn。
                  "removeStandardColumns": [ "MessageTemplate", "Properties" ] // 移除無效用的StandardColumn。 
                }
              }
            }
          ]
        }
      }
    ],
    "Enrich": [ "FromLogContext", "WithMachineName", "WithThreadId" ], // 尚不知此段設定的用途為何？
    "Properties": {
      "Application": "<your application name>" 
    }
  },
  "AllowedHosts": "*"
}

或直接用程式設定 Serilog 組態

GitHub - serilog-mssql/serilog-sinks-mssqlserver: A Serilog sink that writes events to Microsoft SQL Server and Azure SQLGitHub

AuditTo 取代 WriteTo

注意：對於MSSqlServer 用 AuditTo 取代 WriteTo。 若用 WriteTo 寫 Log 會暫在緩存區，等待一段時間才會整批寫入 DB。實測寫入LOG的時間非常不固定，常等了數分鐘還是沒動作，偶而整批瞬間寫入，實在很不穩定。 固改用 AudioTo 會直接送入DB，這才穩定。

Program.cs

using Microsoft.AspNetCore.Hosting;
using Microsoft.Extensions.Configuration;
using Microsoft.Extensions.Hosting;
using System;
using System.Collections.Generic;
using System.Linq;
using Serilog;
using Serilog.Sinks.MSSqlServer;
using System.Collections.ObjectModel;
using System.Data

namespace YourProject
{
    public class Program
    {
        public static void Main(string[] args)
        {
            #region Serilog configuration.

            const string SerilogConnectionString = "Data Source=localhost;Initial Catalog=LogDB;Integrated Security=True";

            var columnOptions = new ColumnOptions();
            columnOptions.Store.Remove(StandardColumn.Properties);
            columnOptions.Store.Remove(StandardColumn.MessageTemplate);
            columnOptions.Store.Add(StandardColumn.LogEvent);
            
            // 加入額外欄位，其值將會自『Properties』對應填入。
            columnOptions.AdditionalColumns = new Collection<SqlColumn>
            {
                new SqlColumn{ColumnName = "ClassName", DataType = SqlDbType.NVarChar, DataLength = 128},
                new SqlColumn{ColumnName = "MethodName", DataType = SqlDbType.NVarChar, DataLength = 128},
                new SqlColumn{ColumnName = "AuthUser", DataType = SqlDbType.NVarChar, DataLength = 128},
            };

            Log.Logger = new LoggerConfiguration()
                .MinimumLevel.Information()
                .MinimumLevel.Override("Microsoft", Serilog.Events.LogEventLevel.Warning)
                .MinimumLevel.Override("System", Serilog.Events.LogEventLevel.Warning)
                .MinimumLevel.Override("Vista.Biz.AOP", Serilog.Events.LogEventLevel.Debug)
                .Enrich.FromLogContext()
                .WriteTo.Async(cfg =>
                {
                    //# 文字檔
                    cfg.File("Log/applog.txt", 
                        rollingInterval: RollingInterval.Day,
                        restrictedToMinimumLevel: Serilog.Events.LogEventLevel.Information);
                    //# JSON 檔
                    cfg.File(new Serilog.Formatting.Json.JsonFormatter(), "Log/applog.json", 
                        rollingInterval: RollingInterval.Day,
                        restrictedToMinimumLevel: Serilog.Events.LogEventLevel.Information);
                })
                //# SQL Server 
                //※ 注意：用 AuditTo 取代 WriteTo 對象是 MSSqlServer。         
                .AuditTo.MSSqlServer(
                    connectionString: SerilogConnectionString,
                    ///※正式版由安全模組取得連線字串
                    sinkOptions: new MSSqlServerSinkOptions() { TableName = "Serilog" },
                    columnOptions: columnOptions,
                    restrictedToMinimumLevel: Serilog.Events.LogEventLevel.Information);
                ).CreateLogger();
            #endregion

            try
            {
                Log.Information("Web host start.");
                CreateHostBuilder(args).Build().Run();
                Log.Information("Web host exit.");
            }
            catch (Exception ex)
            {
                Log.Fatal(ex, "Web host terminated unexpectedly");
            }
            finally
            {
                Log.CloseAndFlush();
            }
        }

        public static IHostBuilder CreateHostBuilder(string[] args) =>
            Host.CreateDefaultBuilder(args)
                .UseSerilog()
                .ConfigureWebHostDefaults(webBuilder =>
                {
                    webBuilder.UseStartup<Startup>();
                });

        /// <summary>
        /// used by Serilog to read appsettings.json
        /// </summary>
        public static IConfiguration Configuration => new ConfigurationBuilder()
            .SetBasePath(System.IO.Directory.GetCurrentDirectory())
            .AddJsonFile("appsettings.json", optional: false, reloadOnChange: true)
            .AddJsonFile($"appsettings.{Environment.GetEnvironmentVariable("ASPNETCORE_ENVIRONMENT") ?? "Production"}.json", optional: true)
            .AddJsonFile($"appsettings.{Environment.MachineName}.json", optional: true)
            .AddEnvironmentVariables()
            .Build();        
    }
}

進階應用

使用 Middleware

撰寫Middleeare取得現在登入使用者與環境資訊，並經由PushProperty指令寫入Log的『Properties』。

CustomMiddleware.cs

using Microsoft.AspNetCore.Http;
using Serilog.Context;
using System;
using System.Collections.Generic;
using System.Linq;
using System.Threading.Tasks;

namespace YourProject.Models
{
    /// <summary>
    /// 中介軟體(ASP.NET Core middleware)
    /// </summary>
    /// <see cref="ASP.NET Core 中介軟體(https://docs.microsoft.com/zh-tw/aspnet/core/fundamentals/middleware/?view=aspnetcore-3.1)"/>
    public class CustomMiddleware
    {
        private readonly RequestDelegate _next;

        public CustomMiddleware(RequestDelegate next)
        {
            _next = next;
        }

        [System.Diagnostics.DebuggerHidden]
        public async Task Invoke(HttpContext context)
        {
            IDisposable t1 = null;
            try
            {
                //string userName = null;
                //var claimsIdentity = context.User.Identity as System.Security.Claims.ClaimsIdentity;
                //if (claimsIdentity != null)
                //{
                //    userName = claimsIdentity.FindFirst(System.Security.Claims.ClaimTypes.GivenName)?.Value;
                //}
            
                string userId = context.User.Identity.Name;
                if(!String.IsNullOrWhiteSpace(userId))
                    t1 = LogContext.PushProperty("AuthUser", userId);

                using (LogContext.PushProperty("ClientIp", GetIPAddress(context)))
                using (LogContext.PushProperty("UserAgent", context.Request.Headers["User-Agent"].FirstOrDefault()))
                using (LogContext.PushProperty("DomainUserName", $"{Environment.UserDomainName}\\{Environment.UserName}"))
                using (LogContext.PushProperty("MachineName", Environment.MachineName))
                {
                    // Do work that doesn't write to the Response.
                    await _next.Invoke(context);
                    // Do logging or other work that doesn't write to the Response.
                }
            }
            catch (Exception ex)
            {
                throw new ApplicationException("CustomMiddleware.Invoke 出現例外！", ex);
            }
            finally
            {
                t1?.Dispose();
            }
        }

        string GetIPAddress(HttpContext context)
        {
            return context.GetServerVariable("HTTP_CLIENT_IP") ??
                context.GetServerVariable("HTTP_X_FORWARDED_FOR") ??
                context.GetServerVariable("HTTP_X_FORWARDED") ??
                context.GetServerVariable("HTTP_X_CLUSTER_CLIENT_IP") ??
                context.GetServerVariable("HTTP_FORWARDED_FOR") ??
                context.GetServerVariable("HTTP_FORWARDED") ??
                context.GetServerVariable("REMOTE_ADDR") ??
                context.GetServerVariable("HTTP_VIA") ??
                string.Empty;

            //return ipaddr;
            //return ipaddr.Split(',')[0]; // 若有多個IP，或經過多個IP，則取第1個。

            /// 另一種取法
            //string ipAddress = context.GetServerVariable("HTTP_X_FORWARDED_FOR");
            //if (!string.IsNullOrEmpty(ipAddress))
            //    return ipAddress;
            //    //return ipAddress.Split(',')[0];

            //return context.GetServerVariable("REMOTE_ADDR");
        }
    }
}

搭配 AOP 模組

利用 AOP/Aspect 實作填入制式的其他欄位。

CatchAndLog.cs

using AspectInjector.Broker;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Logging;
using Serilog.Context;
using System;
using System.Collections.Generic;
using System.Linq;
using System.Text;
using System.Threading.Tasks;

namespace Vista.Biz.AOP
{
    /// <summary>
    /// 掛在類別上的AOP。將針對類別內的 Method 加掛 Catch-And-Log 。
    /// </summary>
    [AttributeUsage(AttributeTargets.Class)]
    [Injection(typeof(CatchAndLogAspect))]
    public class CatchAndLogAttribute : Attribute
    {
        public string Title { get; init; }
    }

    /// <summary>
    /// 抬頭屬性，將被用於 CatchAndLogAspect。
    /// </summary>
    public class LogTitle : Attribute
    {
        public string Title { get; init; }

        public LogTitle(string Title)
        {
            this.Title = Title;
        }
    }

    [Aspect(Scope.Global)]
    public class CatchAndLogAspect
    {
        readonly ILogger<CatchAndLogAspect> _logger;

        public CatchAndLogAspect()
        {
            using (var serviceScope = ServiceActivator.GetScope())
            {
                var services = serviceScope.ServiceProvider;
                _logger = services.GetRequiredService<ILogger<CatchAndLogAspect>>();
            }
        }

        /// <summary>
        /// 一般不需要[Before]。
        /// </summary>
        //[Advice(Kind.Before, Targets = Target.Method)] // you can have also After (async-aware), and Around(Wrap/Instead) kinds
        //public void Begore([Argument(Source.Name)] string name,
        //    [Argument(Source.Triggers)] Attribute[] triggers,
        //    [Argument(Source.Type)] Type cls,
        //    [Argument(Source.Metadata)] System.Reflection.MethodBase meta,
        //    [Argument(Source.Arguments)] object[] args)
        //{
        //    var attr1 = triggers.FirstOrDefault(c => c is CatchAndLogAttribute) as CatchAndLogAttribute;
        //    var attr2 = meta.GetCustomAttributes(typeof(LogTitle), false).FirstOrDefault() as LogTitle;
        //
        //    if (name == "ShowMeTheMoney")
        //    {
        //        System.Diagnostics.Debugger.Break();
        //    }
        //
        //    //※ log before
        //    using (LogContext.PushProperty("ClassName", cls.Name))
        //    using (LogContext.PushProperty("MethodName", name))
        //    {
        //        _logger.Log(LogLevel.Debug, $"[Before] {cls.Name}.{name} {attr1?.Title} {attr2?.Title} => args[{args.Length}]");
        //    }
        //}

        ///// <summary>
        ///// 經測試正常完成才會觸發此函式。 --- 合併到[Around]以簡化。
        ///// </summary>
        //[Advice(Kind.After, Targets = Target.Method)]
        //public void After([Argument(Source.Name)] string name,
        //    [Argument(Source.Triggers)] Attribute[] triggers,
        //    [Argument(Source.Type)] Type cls,
        //    [Argument(Source.Metadata)] System.Reflection.MethodBase meta,
        //    [Argument(Source.Arguments)] object[] args,
        //    [Argument(Source.ReturnType)] Type retType,
        //    [Argument(Source.ReturnValue)] object retValue)
        //{
        //    var attr1 = triggers.FirstOrDefault(c => c is CatchAndLogAttribute) as CatchAndLogAttribute;
        //    var attr2 = meta.GetCustomAttributes(typeof(LogTitle), false).FirstOrDefault() as LogTitle;
        //
        //    //※ log after:經測試正常完成才會觸發此函式。
        //    using (LogContext.PushProperty("ClassName", cls.Name))
        //    using (LogContext.PushProperty("MethodName", name))
        //    using (LogContext.PushProperty("E_Method_Label", "After"))
        //    using (LogContext.PushProperty("E_Method_Args", args))
        //    using (LogContext.PushProperty("E_Method_ReturnValue", retValue))
        //    using (LogContext.PushProperty("E_Method_ReturnType", retType))
        //    {
        //        /// Log → [After] {method-name} = (args) => {result};
        //        _logger.Log(LogLevel.Information, $"[After] {attr1?.Title ?? cls.Name}.{attr2?.Title ?? name} = " +
        //            $"({String.Join(",", args.Select(c => c.ToString()))}) => " +
        //            $"{retValue}:{retType.Name}");                                
        //    }
        //}

        [System.Diagnostics.DebuggerHidden]
        [Advice(Kind.Around, Targets = Target.Method)]
        public object Around([Argument(Source.Name)] string name,
            [Argument(Source.Triggers)] Attribute[] triggers,
            [Argument(Source.Type)] Type cls,
            [Argument(Source.Metadata)] System.Reflection.MethodBase meta,
            [Argument(Source.Target)] Func<object[], object> func,
            [Argument(Source.Instance)] object instance,
            [Argument(Source.Arguments)] object[] args,
            [Argument(Source.ReturnType)] Type retType)
        {
            var attr1 = triggers.FirstOrDefault(c => c is CatchAndLogAttribute) as CatchAndLogAttribute;
            var attr2 = meta.GetCustomAttributes(typeof(LogTitle), false).FirstOrDefault() as LogTitle;
            var page = instance?.GetType().GetCustomAttributes(typeof(PageAttribute), false).FirstOrDefault() as PageAttribute;

            using (LogContext.PushProperty("ClassName", cls.Name))
            using (LogContext.PushProperty("MethodName", name))
            {
                try
                {
                    ///※ 可以在這裡 catch, retry, authenticate, .... 

                    //※ around begin
                    _logger.Log(LogLevel.Debug, $"[Around BEGIN] {attr1?.Title ?? cls.Name}.{attr2?.Title ?? name} " +
                        $"args[{args.Length}]:{{{String.Join(",", args.Select(c => c.ToString()))}}}");

                    var ret = func.Invoke(args);

                    ////※ around end
                    //_logger.Log(LogLevel.Debug, $"[Around END] {attr1?.Title ?? cls.Name}.{attr2?.Title ?? name}");

                    using (LogContext.PushProperty("E_Method_Label", "Around DONE"))
                    using (LogContext.PushProperty("E_Method_Args", args))
                    using (LogContext.PushProperty("E_Method_ReturnValue", ret)) // retValue))
                    using (LogContext.PushProperty("E_Method_ReturnType", retType)) // retType))
                    {
                        /// Log → [After] {method-name} = (args) => {result};
                        _logger.Log(LogLevel.Information, $"[Around DONE] {attr1?.Title ?? $"@page:{page.FuncName}" ?? cls.Name}.{attr2?.Title ?? name} = " +
                            $"({String.Join(",", args.Select(c => c.ToString()))}) => " +
                            $"{ret}:{retType.Name}");
                    }

                    return ret; //※ 可以改變處理結果。
                }
                catch (Exception ex)
                {
                    //※ catch exception
                    _logger.Log(LogLevel.Critical, $"[Around CATCH] => {attr1?.Title ?? cls.Name}.{attr2?.Title ?? name} => Exception:{ex.Message}");
                    throw;
                }
                //finally //<--- 簡化無效益的訊息。
                //{
                //    //※ around leave
                //    _logger.Log(LogLevel.Debug, $"[Around LEAVE] {attr1?.Title ?? cls.Name}.{attr2?.Title ?? name}");
                //}
            }
        }
    }
}

EOF