Aggiungere un CorrelationId in NLog
08 marzo 2023
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.
e modificare la proprietà layout aggiungendo la proprietà ${activityId}
nel file di log verrà scritta una cosa simile
Va creata una classe che implementa l'interfaccia IHttpModule
e poi registrata nel web.config
a questo punto va commentato il set del guid nel singolo metodo
che richiamiamo dal controller
in questo caso viene scritto un file di log simile a questo
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.ActivityIdC#: TestController.cs
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");
...
}
}
XML: 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">
<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>
Text: Log
2023-03-09 23:16:24.6856|TRACE|WebApplication1.Controllers.TestController.Get 24|START (58abde92-7ea0-40e1-b4aa-af1a9c69f0dc)
In questo caso il guid va impostato all'inizio di ogni nuova chiamata, poco pratico.
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#
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() { }
}
}
XML: web.config
<?xml version="1.0" encoding="utf-8"?>
<configuration>
...
<system.webServer>
...
<modules>
<add name="CorrelationIdHttpModule" type="WebApplication1.HttmModules.CorrelationIdHttpModule, WebApplication1"/>
</modules>
...
</system.webServer>
...
</configuration>
C#: TestController.cs
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 questaC#: TestService.cs
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;
}
}
}
C#: TestController.cs
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");
}
}
}
Text: Log
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)
Notare il CorrelationId tra parentesi alla fine di ogni riga di log.
La stessa chiamata ha lo stesso CorrealtionId in tutte le righe della richiesta.
La stessa chiamata ha lo stesso CorrealtionId in tutte le righe della richiesta.