Aggiungere un CorrelationId in NLog

In una applicazione web tipicamente è difficile leggere un file di log in quanto le righe non sono in sequenza ma mischiate tra le varie richieste.
In patica c'è un fattore di contemporaneità sulle chiamate che contemporaneamente scrivono nello stesso log.

Usando il pacchetto NGet NLog in C# .NET 4.8 è possibile aggiungere un CorrelationId, ovvero un guid univoco che permette di raggruppare tutte le scritture legate alla stessa richiesta HTTP.

Primo metodo

Il primo approccio è quello di impostare un nuovo guid all'inizio della singola richiesta tramite System.Diagnostics.Trace.CorrelationManager.ActivityId

C#: TestController.csCopia

public class TestController : ApiController
{
    NLog.Logger _logger = NLog.LogManager.GetCurrentClassLogger();

    public async Task<IEnumerable<string>> Get()
    {
        System.Diagnostics.Trace.CorrelationManager.ActivityId = Guid.NewGuid();

        _logger.Trace("START");

        ...
    }
}

e modificare la proprietà layout aggiungendo la proprietà ${activityId}

XML: nlog.configCopia

<?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">
  <targets>
    <!-- https://nlog-project.org/config/?tab=layout-renderers -->
      <target xsi:type="File"
         name="allfile"
         fileName="${basedir}\log\all-${shortdate}.log"
         layout="${longdate}|${uppercase:${level}}|${callsite} ${callsite-linenumber}|${message} ${exception:format=tostring} (${activityId})"
       />
       <target xsi:type="Console"
         name="lifetimeConsole"
         layout="${level:truncate=4:tolower=true}\: ${logger}[0] ${message} ${exception:format=tostring}"
       />
  </targets>
  <rules>
    <logger name="*" minlevel="Trace" writeTo="allfile" />
  </rules>
</nlog>

nel file di log verrà scritta una cosa simile

Text: LogCopia

2023-03-09 23:16:24.6856|TRACE|WebApplication1.Controllers.TestController.Get 24|START  (58abde92-7ea0-40e1-b4aa-af1a9c69f0dc)

Secondo metodo

Un metodo alternativo è quello di aggiungere un HttpModule che intercetta tutte le chiamate e setta in automatico un nuovo guid.

Va creata una classe che implementa l'interfaccia IHttpModule

C#Copia

namespace WebApplication1.HttmModules
{
    public class CorrelationIdHttpModule : IHttpModule
    {
        public void Init(HttpApplication context)
        {
            context.BeginRequest += (object sender, EventArgs e) =>
            {
                if (System.Diagnostics.Trace.CorrelationManager.ActivityId == Guid.Empty) {
                    // sovrascrivo solo se non era già impostato
                    System.Diagnostics.Trace.CorrelationManager.ActivityId = Guid.NewGuid();
                }
            };
        }

        public void Dispose() { }
    }
}

e poi registrata nel web.config

XML: web.configCopia

<?xml version="1.0" encoding="utf-8"?>
<configuration>
  ...
  <system.webServer>
    ...
    <modules>
      <add name="CorrelationIdHttpModule" type="WebApplication1.HttmModules.CorrelationIdHttpModule, WebApplication1"/>
    </modules>
    ...
  </system.webServer>
  ...
</configuration>

a questo punto va commentato il set del guid nel singolo metodo

C#: TestController.csCopia

public class TestController : ApiController
{
    NLog.Logger _logger = NLog.LogManager.GetCurrentClassLogger();

    public async Task<IEnumerable<string>> Get()
    {
        // il set in questo punto non serve più
        // System.Diagnostics.Trace.CorrelationManager.ActivityId = Guid.NewGuid();

        _logger.Trace("START");

Esempio di log

Per fare un test, aggiungiamo una classe di esempio come questa

C#: TestService.csCopia

namespace WebApplication1.Services
{
    public class TestService
    {
        NLog.Logger _logger = NLog.LogManager.GetCurrentClassLogger();

        public async Task<string> WebGetContent(string url)
        {
            _logger.Trace("BEGIN");
            string html = null;
            try
            {
                using (HttpClient httpClient = new HttpClient())
                {
                    html = await httpClient.GetStringAsync(url);
                }
            }
            catch (Exception ex)
            {
                _logger.Error(ex);
                html = ex.ToString();
            }
            finally
            {
                _logger.Trace("END");
            }

            return html;
        }
    }
}

che richiamiamo dal controller

C#: TestController.csCopia

public class TestController : ApiController
{
    NLog.Logger _logger = NLog.LogManager.GetCurrentClassLogger();

    // GET api/values
    public async Task<IEnumerable<string>> Get()
    {
        // System.Diagnostics.Trace.CorrelationManager.ActivityId = Guid.NewGuid();
        _logger.Trace("START");
        try
        {
            string url = "https://www.sgart.it";

            var svc = new TestService();
            string html = await svc.WebGetContent(url);

            return new string[] { url, html };
        }
        catch (Exception ex)
        {
            _logger.Error(ex);
            throw;
        }
        finally
        {
            _logger.Trace("STOP");
        }
    }
}

in questo caso viene scritto un file di log simile a questo

Text: LogCopia

2023-03-09 23:16:24.6856|TRACE|WebApplication1.Controllers.TestController.Get 24|START  (58abde92-7ea0-40e1-b4aa-af1a9c69f0dc)
2023-03-09 23:16:32.6577|TRACE|WebApplication1.Services.TestService.WebGetContent 16|BEGIN  (58abde92-7ea0-40e1-b4aa-af1a9c69f0dc)
2023-03-09 23:16:32.8608|TRACE|WebApplication1.Services.TestService.WebGetContent 0|END  (58abde92-7ea0-40e1-b4aa-af1a9c69f0dc)
2023-03-09 23:16:32.8608|TRACE|WebApplication1.Controllers.TestController.Get 0|STOP  (58abde92-7ea0-40e1-b4aa-af1a9c69f0dc)
2023-03-09 23:38:24.4098|TRACE|WebApplication1.Controllers.TestController.Get 24|START  (90b14ff1-6a3f-4514-ad3a-bd1f03bf7ae3)
2023-03-09 23:38:24.4705|TRACE|WebApplication1.Services.TestService.WebGetContent 16|BEGIN  (90b14ff1-6a3f-4514-ad3a-bd1f03bf7ae3)
2023-03-09 23:38:24.5518|ERROR|WebApplication1.Services.TestService.WebGetContent 22|System.Net.Http.HttpRequestException: Si è verificato un errore durante l'invio della richiesta. System.Net.Http.HttpRequestException: Si è verificato un errore durante l'invio della richiesta. ---> System.Net.WebException: Impossibile risolvere il nome remoto.: 'www.sgart.ita'
   in System.Net.HttpWebRequest.EndGetResponse(IAsyncResult asyncResult)
   in System.Net.Http.HttpClientHandler.GetResponseCallback(IAsyncResult ar)
   --- Fine della traccia dello stack dell'eccezione interna ---
   in System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   in System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   in System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()
   in WebApplication1.Services.TestService.<WebGetContent>d__1.MoveNext() in C:\Users\alber\source\repos\WebApplication1\WebApplication1\Services\TestService.cs:riga 22 (90b14ff1-6a3f-4514-ad3a-bd1f03bf7ae3)
2023-03-09 23:38:24.5594|TRACE|WebApplication1.Services.TestService.WebGetContent 0|END  (90b14ff1-6a3f-4514-ad3a-bd1f03bf7ae3)
2023-03-09 23:38:24.5594|TRACE|WebApplication1.Controllers.TestController.Get 0|STOP  (90b14ff1-6a3f-4514-ad3a-bd1f03bf7ae3)