[.NETCore] ASP.NET Core - 使用 NLog 紀錄日誌資訊 ~ m@rcus 學習筆記

前言
在開發 .NET Framework 時候，一提到紀錄日誌的函式庫大家都會聯想到 NLog 與 Log4Net 兩種 library，兩者都是免費、OpenSource 且各有喜好者，各自提供簡單好使用的方式讓我們輕鬆地可以將需要的資訊生成相關日誌內容，從 .NET Framework 進入到 .Net Core 時代，紀錄 Application Log 勢必也是重要的功能之一，今天就要分享的是在 .NET Core 中如何使用老牌日誌 Library NLog，若有問題歡迎提出一起討論

開始前的小建議
如果對 .NET Core Logging 不熟悉，建議先服用下列兩篇文章效果會更好 ^_^
[.NETCore] ASP.NET Core - Logging 日誌初體驗 (一)
[.NETCore] ASP.NET Core - Logging 日誌初體驗 (二)

1. 安裝 NLog
首先新增一個 .Net Core API 專案對 NLog 進行 Demo，專案取名為 NetCoreNLogLab，專案選擇 API

專案建立完成後，進到 Nuget 介面下載 NLog 及 NLog.Web.AspNetCore

下載完畢之後，到專案 Dependencies 查看是否有 NLog 與 NLog.Web.AspNetCore

或是確認專案檔是否有存在下載 package reference

<PackageReference Include="NLog.Web.AspNetCore" Version="4.8.0" />
<PackageReference Include="NLog" Version="4.5.11" />

2. 新增 NLog.config
在專案根目錄底下新增 nlog.config 檔案，內容如下

<?xml version="1.0" encoding="utf-8" ?>
<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
      autoReload="true"
      internalLogLevel="Info"
      internalLogFile="c:\temp\internal-nlog.txt">

  <!-- enable asp.net core layout renderers -->
  <extensions>
    <add assembly="NLog.Web.AspNetCore"/>
  </extensions>

  <!-- the targets to write to -->
  <targets>
    <!-- write logs to file  -->
    <target xsi:type="File" name="allfile" fileName="c:\temp\nlog-all-${shortdate}.log"
            layout="${longdate}|${event-properties:item=EventId_Id}|${uppercase:${level}}|${logger}|${message} ${exception:format=tostring}" />

    <!-- another file log, only own logs. Uses some ASP.NET core renderers -->
    <target xsi:type="File" name="ownFile-web" fileName="c:\temp\nlog-own-${shortdate}.log"
            layout="${longdate}|${event-properties:item=EventId_Id}|${uppercase:${level}}|${logger}|${message} ${exception:format=tostring}|url: ${aspnet-request-url}|action: ${aspnet-mvc-action}" />
  </targets>

  <!-- rules to map from logger name to target -->
  <rules>
    <!--All logs, including from Microsoft-->
    <logger name="*" minlevel="Trace" writeTo="allfile" />

    <!--Skip non-critical Microsoft logs and so log only own logs-->
    <logger name="Microsoft.*" maxlevel="Info" final="true" /> <!-- BlackHole without writeTo -->
    <logger name="*" minlevel="Trace" writeTo="ownFile-web" />
  </rules>
</nlog>

這裡可以看見在設定檔中
- log 檔位寫入位置 fileName 是在 c:\temp 目錄下
- log 資訊開頭 layout 是日期時間當作開頭
詳細的 config file 內容介紹可以參考官網說明 : 傳送門

設定 nlog.config 檔案 copy 方式
設定 config 檔案 copy to output direct 為 copy if newer，已確保執行時能找到 nlog.config 檔案

預設為 Do not copy，在預設情況下執行會遇到 exception Unhandled : System.IO.FileNotFoundException: 'Could not find file 'bin\Debug\netcoreapp2.1\nlog.config'.' 的錯誤訊息發生，因此需要調整 nlog.config 設定資訊，或是手動的方式編輯 csproj 檔案

 < ItemGroup >
    < Content  Update = “ nlog.config ”  CopyToOutputDirectory = “ PreserveNewest ” />
 </ ItemGroup >

3. 更新 program.cs

using NLog.Web;
using Microsoft.Extensions.Logging;

public static void Main(string[] args)
{
    // NLog: setup the logger first to catch all errors
    var logger = NLog.Web.NLogBuilder.ConfigureNLog("nlog.config").GetCurrentClassLogger();
    try
    {
        logger.Debug("init main");
        BuildWebHost(args).Build().Run(); 
    }
    catch (Exception ex)
    {
        //NLog: catch setup errors
        logger.Error(ex, "Stopped program because of exception");
        throw;
    }
    finally
    {
        // Ensure to flush and stop internal timers/threads before application-exit (Avoid segmentation fault on Linux)
        NLog.LogManager.Shutdown();
    }
}

public static IWebHostBuilder BuildWebHost(string[] args) =>
    WebHost.CreateDefaultBuilder(args)
        .UseStartup<Startup>()
        .ConfigureLogging(logging =>
        {
            logging.ClearProviders();
            logging.SetMinimumLevel(Microsoft.Extensions.Logging.LogLevel.Trace);
        })
        .UseNLog();  // NLog: setup NLog for Dependency injection

修改 appsettings.json
調整 appsettings.json，否則 appsettings.json 會被 SetMinimumLevel 設定覆蓋掉

 {
     “ Logging ”：{
         “ LogLevel ”：{
             “ Default ”：“ Trace ”，
             “ Microsoft ”：“ Information ”
        }
    }
}

4. 撰寫 Log
在 API 預設的 controller 注入 ILogger覆蓋掉，接著我們在 get function 中輸入 _logger.Loginformation (內建的 logging API )

[Route("api/[controller]")]
[ApiController]
public class ValuesController : ControllerBase
{
    private readonly ILogger<ValuesController> _logger;

    public ValuesController(ILogger<ValuesController> logger)
    {
        _logger = logger;
    }
        
    // GET api/values
    [HttpGet]
    public ActionResult<IEnumerable<string>> Get()
    {
        _logger.LogInformation("Value page says hello");
        return new string[] { "value1", "value2" };
    }
}

5. 確認日誌
上面有提到 log 檔位置是在 c:\temp 底下，到該目錄底下發現已經有兩個 log 檔案內容分別如下

nlog-own-2019-03-05.log

2019-03-05 23:56:10.3993||DEBUG|NetCoreNLogLab.Program|init main |url: |action: 
2019-03-05 23:56:16.6200||INFO|NetCoreNLogLab.Controllers.ValuesController|Value page says hello |url: http://localhost/api/values|action: Get

nlog-all-2019-03-05.log

2019-03-05 23:56:10.3993||DEBUG|NetCoreNLogLab.Program|init main 
2019-03-05 23:56:14.3724||INFO|Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager|User profile is available. Using 'C:\Users\marcustung\AppData\Local\ASP.NET\DataProtection-Keys' as key repository and Windows DPAPI to encrypt keys at rest. 
2019-03-05 23:56:15.8142|1|INFO|Microsoft.AspNetCore.Hosting.Internal.WebHost|Request starting HTTP/1.1 GET http://localhost:5012/api/values   
2019-03-05 23:56:15.8142|1|INFO|Microsoft.AspNetCore.Hosting.Internal.WebHost|Request starting HTTP/1.1 DEBUG http://localhost:5012/  0 
2019-03-05 23:56:15.8907|2|INFO|Microsoft.AspNetCore.Hosting.Internal.WebHost|Request finished in 59.6151ms 200  
2019-03-05 23:56:16.4635|1|INFO|Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker|Route matched with {action = "Get", controller = "Values"}. Executing action NetCoreNLogLab.Controllers.ValuesController.Get (NetCoreNLogLab) 
2019-03-05 23:56:16.6200|1|INFO|Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker|Executing action method NetCoreNLogLab.Controllers.ValuesController.Get (NetCoreNLogLab) - Validation state: Valid 
2019-03-05 23:56:16.6200||INFO|NetCoreNLogLab.Controllers.ValuesController|Value page says hello 
2019-03-05 23:56:16.6384|2|INFO|Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker|Executed action method NetCoreNLogLab.Controllers.ValuesController.Get (NetCoreNLogLab), returned result Microsoft.AspNetCore.Mvc.ObjectResult in 9.57ms. 
2019-03-05 23:56:16.6545|1|INFO|Microsoft.AspNetCore.Mvc.Infrastructure.ObjectResultExecutor|Executing ObjectResult, writing value of type 'System.String[]'. 
2019-03-05 23:56:16.7148|2|INFO|Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker|Executed action NetCoreNLogLab.Controllers.ValuesController.Get (NetCoreNLogLab) in 245.7545ms 
2019-03-05 23:56:16.7148|2|INFO|Microsoft.AspNetCore.Hosting.Internal.WebHost|Request finished in 907.213ms 200 application/json; charset=utf-8 
2019-03-05 23:56:16.8795|1|INFO|Microsoft.AspNetCore.Hosting.Internal.WebHost|Request starting HTTP/1.1 GET http://localhost:5012/favicon.ico   
2019-03-05 23:56:16.8795|2|INFO|Microsoft.AspNetCore.Hosting.Internal.WebHost|Request finished in 1.1443ms 404

紀錄成功 !!!

後記
這篇簡單分享 NLog 在.NET Core 的使用方式，在 NLog 中還是有很多細節根應用可以再繼續學習下去，比如說 NLog 之中的 logger、target 使用方式，根據不同 log level 輸出 title 也不相同，在之後的時間可以在整理出來讓大家更容易了解，謝謝

參考
Getting-started-with-ASP.NET-Core-2

m@rcus 學習筆記

只有累積，沒有奇蹟

2019年3月5日星期二