NLog Logowanie działania aplikacji. Jak wiedzieć w końcu, gdy coś nie działa. Mój blog jest napisany w C# i działa po ASP.NET CORE. Jak to jednak bywa z napisaną przez siebie aplikacją pojawiają się błędy więc do bloga dodałem mechanizm logowania błędów. W taki sposób znalazłem wiele dziwnych przypadków uszkodzonych wpisów w formacie XML, które rozwalały Parser. Znalazłem też złe zbudowane przez ze mnie lista kursów. 

Poza tym w logach też widziałem jak ktoś próbował się nie raz włamać na bloga o 4 rano.

Logi są potrzebne nawet do taki projektów. W kontekście aplikacji produkcyjnych logi często są ostatnią deską ratunku, aby stwierdzić co nie działa dla pewnego dziwnego przypadku.

W tym wpisie pokaże ci jak szybko dodać ten mechanizm logowania przy pomocy NLog do swojej aplikacji ASP.NET CORE.

W NuGet możesz znaleźć mnóstwo paczek NLog w przypadku ASP.NET Core interesuje Cię paczka "NLog.Web.AspNetCore".

NLog.Web.AspNetCore

Paczkę też można zainstalować przy pomocy konsoli:

Install-Package NLog.Web.AspNetCore

Aplikacja ASP.NET Core w wyniku błędów może się resetować. Tak miałem przypadki pisząc bloga w ASP.NET Core, w którym nie mogłem złapać wyjątku, który resetował cały serwer aplikacji. Z tego, co pamiętam to był jakiś problem z serializacją przez System.Text.JSON, ale tak to bym tego nigdy nie odkrył.

Zresztą kto wiem może masz już jakiś błąd, zanim twoja aplikacja ASP.NET Core zacznie działać.

Dlatego warto logować już same uruchomienie serwera aplikacji. Robimy to w klasie Program.

public class Program
{
    public static void Main(string[] args)
    {
        var logger = NLogBuilder.ConfigureNLog("nlog.config").GetCurrentClassLogger();
        try
        {
            logger.Debug("init main function");
            CreateHostBuilder(args).Build().Run();
        }
        catch (Exception ex)
        {
            logger.Error(ex, "Error in init");
            throw;
        }
        finally
        {
            NLog.LogManager.Shutdown();
        }
    }

Przy budowaniu host-u warto zaznaczyć, że będziesz korzystał z NLog.

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

Istnieje wiele stylów tworzenia logów. Jak jestem fanem posiadania plików rozdzielonych po dacie. Dla mnie jest to bardziej czytelne i łatwiej jest tak znaleźć konkretny błąd, zwłaszcza że wiesz, że coś ciekawego możesz znaleźć, gdy plik jest większy danego dnia.

Logi utworzone przez NLOG

Największy problem NLog leży w tym pliku "nlog.config".  To on definiuje jak błędy mają być zapisane : do jakiego pliku, w jakim formacie tekstowym.

Poza tym, kto powiedział, że błędy muszą być zapisywane do pliku. Możesz logować informacje do bazy danych.

Aby Ci pokazać jak z tego mechnizm logowania jak najlepiej rozbiłem go na dwie części. Jeden format tekstowy będzie zapisywał wyjątki, czyli błędy i będzie tam mnóstwo przestrzeni, żeby wszystko przeczytać. Inny format będzie zapisywał "ostrzeżenia,debug,informacje" w formie pojedynczej linijki tekstu.

Poza tym mamy także wewnątrz log ("InnerLog.text"), który będzie mnie informował czy host w ogóle się uruchomił.

<?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="${basedir}\Log\InnerLog.txt">
  <extensions>
    <add assembly="NLog.Web.AspNetCore" />
  </extensions>
  <targets>
    <target xsi:type="File" name="errorFile-web" fileName="${basedir}\log\${shortdate}.log"
            layout=${newline}-------------- ${level} (${longdate}) --------------${newline}${newline}
Call Site: ${callsite}${newline}
Exception Type: ${exception:format=Type}${newline}
Exception Message: ${exception:format=Message}${newline}
Stack Trace: ${exception:format=StackTrace}${newline}
Additional Info: ${message}${newline}" />

    <target xsi:type="File" name="otherFile-web" fileName="${basedir}\log\${shortdate}.log"
          layout="->(${longdate}) : ${level} : ${message}" />
  </targets>
  <!-- rules to map from logger name to target -->
  <rules>
    <!--Skip non-critical Microsoft logs and so log only own logs-->
    <logger name="Microsoft.*" maxLevel="Info" final="true" />
    <logger name="*" minlevel="Error" writeTo="errorFile-web" />
    <logger name="*" maxLevel="Warn" writeTo="otherFile-web" />
  </rules>
</nlog>

W tagach "rules/logger" definiujemy, do jakiego targetu one się odnoszą po jego nazwie. Określamy tu też poziom maksymalny lub minimalny logowania.  Dla jednego formatu minimum będzie poziom błędów. A dla drugiego formatu maksymalny poziom to "ostrzeżenia" czyli będzie logował wszystko tylko nie błędy.

<logger name="*" minlevel="Error" writeTo="errorFile-web" />
<logger name="*" maxLevel="Warn" writeTo="otherFile-web" />

Oto definicja zapisu dla "ostrzeżeń,debug,informacji". Jak widzisz podajemy tu ścieżkę do pliku. Określamy tu też, że wszystkie informację będą zawarte w jednej linijce.

<target xsi:type="File" name="otherFile-web" fileName="${basedir}\log\${shortdate}.log"
      layout="->(${longdate}) : ${level} : ${message}" />

Dla błędów dodamy dużo znaków nowej linii. Zapiszemy to wszystko do tego samego pliku co wcześniej, ale możesz to zmienić.

<target xsi:type="File" name="errorFile-web" fileName="${basedir}\log\${shortdate}.log"
        layout="${newline}-------------- ${level} (${longdate}) --------------${newline}
        ${newline}
        Call Site: ${callsite}${newline}
        Exception Type: ${exception:format=Type}${newline}
        Exception Message: ${exception:format=Message}${newline}
        Stack Trace: ${exception:format=StackTrace}${newline}
        Additional Info: ${message}${newline}" />

Konfiguracje mamy już gotową. Pora dla dobrych praktyk opakować NLog w swój własny Logger. Oto jego Interfejs. Specjalnie nazwałem go ICezLog aby nie mylił się zbudowanym mechanizmami, które podobnie się nazywają.

public interface ICezLog
{
     void Info(string message);
     void Warn(string message);
     void Debug(string message);
     void Error(string message);
void Error(Exception exp); }

Oto jego implementacja. 

public class LogNLog : ICezLog
{
    private static readonly NLog.ILogger logger = LogManager.GetCurrentClassLogger();

    public LogNLog()
    {
    }

    public void Info(string message)
    {
        logger.Info(message);
    }

    public void Warn(string message)
    {
        logger.Warn(message);
    }

    public void Debug(string message)
    {
        logger.Debug(message);
    }

    public void Error(string message)
    {
        logger.Error(message);
    }

public void Error(Exception exp) { logger.Error(exp); } }

W klasie startup trzeba zarejestrować wstrzykiwanie zależności tak aby kontrolery mogły z niego korzystać.

services.AddSingleton<ICezLog, LogNLog>();

Stworzyłem kontroler, aby przetestować działanie swoich ustawień.

[ApiController]
[Route("[controller]")]
public class TestLogController : ControllerBase
{
    private readonly ICezLog _logger;
    public TestLogController(ICezLog logger)
    {
        _logger = logger;
    }
[HttpGet] public IEnumerable<string> Get() { _logger.Info("Here is info message from the controller."); _logger.Debug("Here is debug message from the controller."); _logger.Warn("Here is warn message from the controller."); try { int b = 0; int a = 100 / b; } catch (Exception ex) { _logger.Error(ex); } return new string[] { "aaa", "bbb" }; } }

Zaglądam do folderu "Log" i mam dwa pliki logujące.

Logi w folderze

Jak widzisz wszystko zapisało się według formatów, które podałem wcześniej.

->(2021-01-11 22:56:49.2144) : Info : Here is info message from the controller.
->(2021-01-11 22:56:49.2144) : Debug : Here is debug message from the controller.
->(2021-01-11 22:56:49.2144) : Warn : Here is warn message from the controller.

-------------- Error (2021-01-11 22:56:49.2144) -------------- Call Site: WebApplication9.LogNLog.Error Exception Type: System.DivideByZeroException Exception Message: Attempted to divide by zero. Stack Trace: at WebApplication9.Controllers.TestLogController.Get() in C:\Users\PanNiebieski\source\repos\WebApplication9\Controllers\TestLogController.cs:line 28 Additional Info: System.DivideByZeroException: Attempted to divide by zero. at WebApplication9.Controllers.TestLogController.Get() in C:\Users\PanNiebieski\source\repos\WebApplication9\Controllers\TestLogController.cs:line 28

Jeśli chodzi o plik "InnerLog.txt" to on tylko zawiera informacje o tym, że host ASP.NET CORE uruchomił się poprawnie oraz plik "nlog.config" jest poprawny.

2021-01-11 22:56:38.2533 Info Message Template Auto Format enabled
2021-01-11 22:56:38.2806 Info Loading assembly: NLog.Web.AspNetCore
2021-01-11 22:56:38.3752 Info Adding target FileTarget(Name=errorFile-web)
2021-01-11 22:56:38.3912 Info Adding target FileTarget(Name=otherFile-web)
2021-01-11 22:56:38.4390 Info Validating config: TargetNames=errorFile-web, otherFile-web, ConfigItems=36, FilePath=C:\Users\PanNiebieski\source\repos\WebApplication9\bin\Debug\net5.0\nlog.config

To wszystko. Jak widzisz dodanie logowania do swojej aplikacji nie jest takie trudne.