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.ActivityIdpublic 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 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
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
IHttpModulenamespace 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 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
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
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
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
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.