Easy log per asp.net core: Serilog

E’ inutile spiegare perchè loggare sia un punto chiave nello sviluppo di un’applicazione. E’ altrettanto inutile dire quanto oggi sia inutile sviluppare un framework custom che lo faccia: ci sono mille plugin che lo fanno (e spesso anche molto bene) per cui c’è davvero l’imbarazzo della scelta. Non tutti però sono semplici da configurare (alcuni sono un vero incubo). La mia scelta dopo vari tentativi è ricaduta su SeriLog. Sul web trovate parecchia documentazione in merito ve ne suggerisco un paio sotto.

Nello specifico queste sono le azioni che ho condotto per installarlo e configurarlo:

  • Scaricare con NuGet Packages Manager il pacchetto Serilog.AspNetCore
  • Ho inizializzato il Logger all’interno del Program.cs
var logger = new LoggerConfiguration()
    .ReadFrom.Configuration(builder.Configuration)
    .Enrich.FromLogContext()
    .CreateLogger();

builder.Logging.ClearProviders();
builder.Logging.AddSerilog(logger);
  • Ho aggiunto nel file appsettings.js le configurazioni di scrittura, tra cui il nome del file dov’è posizionato etc…
"Serilog": {
  "Using": [ "Serilog.Sinks.File" ],
  "MinimumLevel": {
    "Default": "Information"
  },
  "WriteTo": [
    {
      "Name": "File",
      "Args": {
        "path": "../APIlogs/webapi-WebAPICoreAuthBearer.log",
        "rollingInterval": "Day",
        "outputTemplate": "[{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} {CorrelationId} {Level:u3}] {Username} {Message:lj}{NewLine}{Exception}"
      }
    }
  ]
}

Con queste semplici azioni il vostro sistema già loggerà in automatico. Qualora vi servisse esplicitamente loggare all’interno dei vostri controller nel caso di un API naturalmente basta utilizzare la solita modalità “iniettiva”.

 private readonly ILogger<InfoAPIController> _logger;
 private readonly IConfiguration _configuration;

 public InfoAPIController(ILogger<InfoAPIController> logger, IConfiguration iConfig)
 {
     _logger = logger;
     _configuration = iConfig;
 }

 [HttpGet(Name = "GetInfo")] ]
 public InfoAPI Get()
 {
     _logger.Log(LogLevel.Information, "GetInfo");
....

[1] https://www.claudiobernasconi.ch/2022/01/28/how-to-use-serilog-in-asp-net-core-web-api/

[2] https://www.youtube.com/watch?v=QjO2Jac1uQw

[3] https://www.milanjovanovic.tech/blog/5-serilog-best-practices-for-better-structured-logging

Aggiungere i Log in una Web API

Una delle cose fondamentali che serve per debuggare un applicazione sono i Logs. Avere un sistemi di log efficiente accorcia le tempistiche e favorisce un troubleshooting benfatto. In questo post mostro, brevemente, cosa si deve fare per utilizzare NLog a tal fine. Non voglio essere troppo noioso analizzando tutte le varie casistiche (nel caso vi consiglio questa lettura [1]) ma, voglio arrivare dritto al punto. Quello che a me serve è qualcosa che ad ogni eccezione venga correttamente loggata indipendentemente dal fatto che sia gestita e scriva in un file tutto quello che è successo.

A questo scopo installiamo i seguenti package NuGet:

Install-Package NLog.Web.AspNetCore
Install-Package NLog

Ed inseriremo nella root del progetto il seguente file config:

<?xml version="1.0" encoding="utf-8"?>
<configuration>
	<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}\internal-nlog.txt">
		<!-- enable asp.net core layout renderers -->
		<extensions>
			<add assembly="NLog.Web.AspNetCore"/>
		</extensions>
		<variable name="basedir" value="${aspnet-appbasepath}\wwwroot\logs" />
		<targets>
			<target xsi:type="AsyncWrapper" name="AllAsyncWrapper" queueLimit="10000" batchSize="1000">
				<target xsi:type="File"
						name="allfile"
						fileName="${var:basedir}\nlog-all-${shortdate}-${environment:ASPNETCORE_ENVIRONMENT}.log"
						archiveFileName="${var:basedir}\archives\nlog-all-${shortdate}-${environment:ASPNETCORE_ENVIRONMENT}.archive-{#}.zip"
						archiveEvery="Day"
						maxArchiveDays="7"
						archiveNumbering="DateAndSequence"
						enableArchiveFileCompression="True"
						layout="${longdate}|${aspnet-traceidentifier}|${uppercase:${level}}|${threadid}|${logger}|${message} ${exception:format=ToString}|${aspnet-request-method}|${aspnet-request-url}|${aspnet-mvc-action}|${aspnet-request-posted-body}" />
			</target>
		</targets>
		<!-- rules to map from logger name to target -->
		<rules>
			<logger name="*" minlevel="Error" writeTo="AllAsyncWrapper" />
		</rules>
	</nlog>
</configuration>

Questo file fornisce le indicazioni su come comporre il file, dove metterlo come mantenerlo… Come detto non mi dilungo troppo ma vi pongo l’accento su un paio di punti:

<variable name="basedir" value="${aspnet-appbasepath}\wwwroot\logs" />

Questa riga sopra la utilizzo per definire come cartella dove salvare i files una cartella della www root, comoda se siete in una farm dove non avete controllo completo del file system. Per le Web API invece io uso questa dato che non esiste una wwwroot:

<variable name="basedir" value="${aspnet-appbasepath}\logs" />

Questa parte invece definisce tutte le proprità del file di log: da cosa deve contenere ed in che formato, alla dimensione massima, al nome, alla rotation… Insomma tutto quello che serve per meglio definire come loggare. Non dimenticate di flaggare il Copy del file nell’output.

				<target xsi:type="File"
						name="allfile"
						fileName="${var:basedir}\nlog-all-${shortdate}-${environment:ASPNETCORE_ENVIRONMENT}.log"
						archiveFileName="${var:basedir}\archives\nlog-all-${shortdate}-${environment:ASPNETCORE_ENVIRONMENT}.archive-{#}.zip"
						archiveEvery="Day"
						maxArchiveDays="7"
						archiveNumbering="DateAndSequence"
						enableArchiveFileCompression="True"
						layout="${longdate}|${aspnet-traceidentifier}|${uppercase:${level}}|${threadid}|${logger}|${message} ${exception:format=ToString}|${aspnet-request-method}|${aspnet-request-url}|${aspnet-mvc-action}|${aspnet-request-posted-body}" />

Fatto questo resta un unico punto: fare in modo che NLog venga correttamente lanciato nel Program.cs

	public class Program
	{
		public static void Main(string[] args)
		{
            var logger = NLogBuilder.ConfigureNLog("nlog.config").GetCurrentClassLogger();
            try
            {
                logger.Debug("init main");
                CreateWebHostBuilder(args).Build().Run();
                //webhost.RunAsync();
            }
            catch (Exception exception)
            {
                //NLog: catch setup errors
                logger.Error(exception, "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 IHostBuilder CreateWebHostBuilder(string[] args) =>
            Host.CreateDefaultBuilder(args)
        .ConfigureWebHostDefaults(webBuilder =>
        {
            webBuilder.UseStartup<Startup>();
        })
        .ConfigureLogging(logging =>
        {
            logging.ClearProviders();
            logging.SetMinimumLevel(LogLevel.Trace);
        })
            .UseNLog();
    }

Un piccola nota: il codice del Main è strutturato per loggare l’errore nel caso l’inizializzazione non vada a buon fine.

A questo punto il più è fatto: lanciando l’applicazione è possibile trovare il logs nella cartella specificata:

File di log

Naturalmente è possibile utilizzare il logger in manier customizzata semplicemente iniettandolo all’interno del Controller e richiamandolo a piacere:

	public class HomeController : Controller
	{
		private readonly ILogger<HomeController> _logger;

		public HomeController(ILogger<HomeController> logger)
		{
			_logger = logger;
		}

		public IActionResult Index()
		{
			_logger.LogInformation("Home");
			return View();
		}

		public IActionResult Privacy()
		{
			return View();
		}

	}

[1] https://programmingcsharp.com/nlog-net-core/

XinLog 1.1 – Rendiamolo configurabile

Ormai ci ho preso gusto dopo le ultime puntate continuo a lavorare sul migliorare lo script di Log. Per cominciare vorrei dare l’opportunità a chi lo utilizza di decidere dove loggare. Come ricordate infatti al momento tutti i logs finiscono nella stessa cartella in cui c’è lo script e questo è limitante. Sarebbe figo invece che chi lo usa possa decidere di volta in volta dove loggare. Creeremo dunque una funzione Open-Log a cui dire come inizializzare dei parametri che poi si applichino.

# Get the current Directory
$_StoragePath = Split-Path -Parent $MyInvocation.MyCommand.Path
#Set the file log name
$_Logfile = "_StoragePath\XinLog_$($env:computername)_$((Get-Date).toString("yyyyMMdd_HHmmss")).log"

function Open-Log{
    Param (   
        [string]$StoragePath
    )
    #set the folder name
    $_StoragePath = $StoragePath
    #Set the file log name
    $_Logfile = "$_StoragePath\XinLog_$($env:computername)_$((Get-Date).toString("yyyyMMdd_HHmmss")).log"
}

Se invochiamo quindi questa Open-Log prima di utilizzarla, l’idea è che si inizializzi la variabile $_StoragePath e da lì in poi essa venga richiamata ogni volta nella Write-Log. Se però lo fate scoprirete che non funziona. Perchè? In pratica per come sono dichiarate le variabili sopra hanno un contesto limitato allo script che quindi cessa di esistere aldifuori del fil XinLog. Questo ovviamente non ci piace perchè se dobbiamo inizializzare ogni volta il file tutto perde di senso.

E’ il caso invece di giocare un pochino con le variabili e qui [1] trovate un articolo interessante in merito. E’ il caso che dichiari Global queste variabili così da riuscire a mantenere il valore nel contesto del thread lanciato e non solo del singolo file XinLog: Funziona!

# Get the current Directory
$global:_StoragePath = Split-Path -Parent $MyInvocation.MyCommand.Path
#Set the file log name
$global:_Logfile = "$global:_StoragePath\XinLog_$($env:computername)_$((Get-Date).toString("yyyyMMdd_HHmmss")).log"

function Open-Log{
    Param (   
        [string]$StoragePath
    )
    #set the folder name
    $global:_StoragePath = $StoragePath
    #Set the file log name
    $global:_Logfile = "$global:_StoragePath\XinLog_$($env:computername)_$((Get-Date).toString("yyyyMMdd_HHmmss")).log"
}

Come potete ben vedere l’unica accortezza è di utilizzare il prefisso $global: per tutte le variabili che vogliamo mantengano un valore che esuli dal singolo contesto di File e persistano anche nel Thread.

Infine aggiungiamo un po’ di try-catch per evitare che log (utilizzato anche per loggare gli errori) possa a sua volta bloccarsi per qualche eccezzione inattesa ed il gioco è fatto: la versione XinLog 1.1 è servita (GitHub [2])

[1] https://www.varonis.com/blog/powershell-variable-scope

[2] https://github.com/stepperxin/XinLog

XinLog 1.0

Dopo aver cominciato il thread [1] delle scorse settimane, ho pensato fosse opportuno spendere qualche minuto in più per produrre una libreria separata per il logging con l’opportunità che essa possa essere riutilizzata anche in altri contesti. Essendo infatti il logging concettualmente un’azione riutilizzabile più e più volte in mille contesti distinti sarebbe bello che questa funzionalità stesse in un file separato e che fosse richiamabile semplicemente includendola nel contesto in cui mi serve.

Per questa ragione creo un un file ps1 separato che chiamerò XinLog in cui isolerò tutte le logiche relative al logging:

################# XinLog 1.0 ######################
# Use this library to log easely on file and screen
# In Parameters MANDATORY
#   - $LogString [STRING] Message to log
# The log on file will create file a file in the same directory of the caller
###################################################

# Get the current Directory
$myDir = Split-Path -Parent $MyInvocation.MyCommand.Path
#Set the file log name
$Logfile = "$myDir\XinLog_$($env:computername)_$((Get-Date).toString("yyyyMMdd_HHmmss")).log"

#begin FUNCTIONS
function Write-Log
{
    Param (
        [Parameter(Mandatory)]    
        [string]$LogString
    )
    $Stamp = (Get-Date).toString("yyyy/MM/dd HH:mm:ss")
    $LogMessage = "$Stamp - $LogString"
    Add-content $LogFile -value $LogMessage
    Write-Host $LogString -ForegroundColor White
}

#end FUNCTIONS

Non ho fatto granchè in realtà, ho semplicemente esportato le righe relative al logging dal file precedente così che il file contenga solo la funzione Write-Log (che scrive effettivamente il log) ed i settaggi che servono ad indivuare dove scrivere il log. Al momento questi settaggi non sono modificabili, ma chissà, in futuro…

A questo punto però come posso utilizzare la Write-Log se sta in un file separato? La risposta è ovviamente semplicissima, come in tutti i linguaggi è possibile includere uno script in un altro script, nella fattispecie in PowerShell questo si fa con la “dot source notation” descritta qui [2] in cui basta sostanzialmente includere il il file con il path specifico. Nel nostro caso il file Conto2.3 cambierà nel modo seguente:

########### CONTO 2.3.1 ############
# First test
####################################

##### Inclueded Libraries ##########
# Get the current Directory
$myDir = Split-Path -Parent $MyInvocation.MyCommand.Path
# Files included 
. "$myDir\XinLog.ps1"  # Include the file logs
####################################


#begin BODY

Write-Log "Text to write"

#end BODY

Per chi fosse interessato potete trovare anche uno progetto Git dedicato [3].

[1] https://www.beren.it/2022/01/07/conto2-3-logging-with-powershell-get-started/

[2] https://docs.microsoft.com/en-us/powershell/module/microsoft.powershell.core/about/about_scopes?view=powershell-5.1#using-dot-source-notation-with-scope

[3] https://github.com/stepperxin/XinLog

Conto2.3 – Loggare con PowerShell

Come detto in fase di design [1], le logiche di ET andranno implementate in PowerShell script. Per chi non ha idea di che cosa si tratti niente paura: è semplicemente un linguaggio di scripting disponibile anzitutto su sistemi Microsoft (che lo ha sviluppato) ma installabile anche su Linux (non credo che abbia senso ma nel caso trovate qualche info qui [2]). L’idea è quella di avere un linguaggio un po’ più elaborato della semplice linea di comando mantenendo l’agilità e l’austerità della stessa.

Per cominciare a codificare in PowerShell vi serve davvero poco, praticamente solo un editor di testo. Io vi consiglio ad ogni modo di utilizzare Visual Studio Code [3] che è un editor gratuito, leggero e che supporta molti linguaggi di programmazione e dunque è in grado di supportarvi in maniera efficiente e anche di fornirvi una modalità debug che vi aiuta nel troubleshooting.

Tornando al nostro obbiettivo: è fondamentale definire una modalità per loggare, sia a schermo che su file le azioni effettuate. Per farlo creeremo una funzione ad-hoc chiamata WriteLog che avrà il doppio compito di scrivere su file ed a schermo le info che verranno passate.

  • La scrittura a schermo sarà effettuata tramite il comando Write-Host “stringa da scrivere”
  • La scrittura su file avverrà attraverso Add-content File -value “stringa da scrivere”

Inoltre nella scrittura su file aggiungiamo anche un timestamp che dica quando quel log è stato scritto.

function WriteLog
{
    Param (
       [Parameter(Mandatory)]    
       [string]$LogString
    )

    $Stamp = (Get-Date).toString("yyyy/MM/dd HH:mm:ss")
    $LogMessage = "$Stamp - $LogString"
    Add-content $LogFile -value $LogMessage
    Write-Host $LogString -ForegroundColor White
}

Attenzione alla prima riga dove c’è la scritta Param: questo indica che tra parentesi si trovano i parametri che si possono passare alla funzione. Nel nostro caso è la stringa da loggare che, come vedete ha una dicitura Mandatory perché non avrebbe senso chiamare un log senza un messaggio da loggare.

Proviamo dunque ad invocare la funzione con un valore di test

WriteLog "Text to write"

Eseguendo lo script da linea di comando (oppure in debug dall’IDE di Visual Studio Code) ci troveremo a schermo esattamente la scritta che volevamo.

Esempio di WriteLog

Questo però non è sufficiente a scrivere su file perché in effetti dobbiamo in qualche modo definire qual’è il file da scrivere. Per farlo definiamolo come variabile il nome di un file generico da collocare nella stessa cartella del file Powershell.

$myDir = Split-Path -Parent $MyInvocation.MyCommand.Path
$Logfile = "$myDir\log_$($env:computername)_$((Get-Date).toString("yyyyMMdd_HHmmss")).log"

La prima riga memorizza in $myDir il path relativo della cartella corrente. La seconda invece definisce il path del file di log aggiungendo il nome della macchina fisica aggiungendo un timestamp per evitare problemi di sovrascrittura generando di fatto un nuovo file di log ad ogni run. Se ora rilanciamo lo script troveremo un file di log nella cartella con questo contenuto

File di log generato
Contenuto del file di log

Una cosa molto interessante di PowerShell è come sia semplice comporre delle stringhe sfruttando i valori delle variabili: $LogMessage = “$Stamp – $LogString” semplicemente introduce i valori delle variabili nel testo senza altri comandi. Davvero veloce e pratico.

Ricapitolando: abbiamo creato una prima versione del nostro PowerShell script che in questo momento logga su file ed a schermo un testo. Il dettaglio dello script lo trovate sotto. Per maggior facilità di lettura la funzione WriteLog è dichiarata nella prima parte dello script mentre verrà richiamata nella seconda parte dello script. Non è una necessità, lo script funziona uguale anche se la funzione è dichiarata a valle, è semplicemente una convenzione mia.

#begin FUNCTIONS
function WriteLog
{
    Param (
        [Parameter(Mandatory)]    
        [string]$LogString
    )
    $Stamp = (Get-Date).toString("yyyy/MM/dd HH:mm:ss")
    $LogMessage = "$Stamp - $LogString"
    Add-content $LogFile -value $LogMessage
    Write-Host $LogString -ForegroundColor White
}

#end FUNCTIONS

# Get the current Directory
$myDir = Split-Path -Parent $MyInvocation.MyCommand.Path
#Set the file log name
$Logfile = "$myDir\log_$($env:computername)_$((Get-Date).toString("yyyyMMdd_HHmmss")).log"

WriteLog "Text to write"

Trovate qui [4] lo zip con il file per provare a vostra volta.

[1] https://www.beren.it/2021/12/30/conto2-3-il-design/

[2] https://docs.microsoft.com/it-it/powershell/scripting/install/installing-powershell-on-linux?view=powershell-7.2

[3] https://code.visualstudio.com/download

[4] https://www.beren.it/wp-content/uploads/2022/01/CONTO2.3-01.zip

Conto2.3 – Il design

Se siete giunti al secondo capitolo, significa che probabilmente qualcosa vi interessa dell’argomento e conseguentemente una volta espressi i requisiti (se ve li siete persi sono qui) possiamo passare alla parte più di concetto vale a dire definire almeno sulla carta come dovrà funzionare tutto il processo. In particolare:

  1. definire come strutturare la parte di input / output identificando dove saranno implementate le parti operative (chi fa cosa)
  2. impostare una configurabilità delle parti sopra che ci consenta la riusabilità e la flessibilità che ci servono
  3. impostare un sistema di logging che ci permetta di verificare con facilità se ci sono problemi, anomalie o semplicemente verificare nel dettaglio che cosa il sistema abbia realizzato

1) Definire come strutturare la parte di input / output

Come dicevamo l’idea è che sia necessario gestire tipologie di files diversi a seconda del tipo di sorgente: estratto conto della banca o della carta di credito e di chi appartengono questo perché se io e mia moglie abbiamo due banca distinte normalmente anche la sorgente sarà differente ed è dunque necessario prevedere che possano essere due caricamenti differenti.

Configurazione cartelle di source

L’idea di base è che volendo potrei aggiungere quanti owner io voglia tenendo al di sotto una struttura che consenta di identificare anzi tutto la banca e poi altre fonti. Nelle cartelle sopra dovranno essere caricati tutti i files sorgente così come sono senza tendenzialmente effettuare nessuna manipolazione.

A questo punto uno script PowerShell che risiederà nella root acquisirà questi files e li deve normalizzare. Che cosa si intende per normalizzare? Sostanzialmente ricercare un insieme di colonne che siano necessarie ad estrarre le informazioni che servono:

  • Data Operazione: la data in cui la spesa o l’entrata è avvenuta o contabilizzata (scegliete voi quale delle due preferite)
  • Causale: dovrebbe dare un’indicazione di massima dell’operazione
  • Descrizione: indica con più dettagli la motivazione della stessa operazione
  • Ammontare: indica la somma monetaria dell’operazione
  • Accredito: per esperienza alcune banche posizionano l’accredito in una colonna separata invece di includerlo con un segno differente nell’ammontare

Una volta acquisite queste info andranno quindi esportate in un folder OUTPUT anche questo suddiviso in in due principali cartelle che però conterrà le info degli stessi file originali ma senza più distinzioni di owner e soprattutto nel medesimo formato al fine, come vedremo di rendere la vita più semplice ad Excel.

Configurazione Cartelle di output

L’ultimo miglio riguarda proprio Excel che dovrà andare a leggere questi files e caricarli all’interno dei suoi fogli in modo da poter rendere fruibile una pivot che li aggreghi.

All’appello manca però ancora una parte importante che è il mapping. Chi fa il mapping e da dove lo attinge. Questa purtroppo è la parte più dolorosa, infatti il mio obbiettivo è quello di gestire il mapping in un file excel separato adibito solo a quello in cui sia possibile dire che determinate descrizioni sia catalogabili in un modo piuttosto che in un altro. Questa possibilità purtroppo è assai costosa ed è il motivo principale per cui Excel da solo non basta e serve Powershell. In pratica, appena lanciato Powershell si caricherà in pancia le informazioni presenti nel file di mapping e le utilizzarà per mappare le spese in un maniera coerente cosicchè in OUTPUT mi troverò già dei files con le info che mi serviranno a categorizzarli a dovere.

2) Impostare la configurabilità

Tutto ciò che è stato definito sopra ha senso ma perché sia facilmente estendibile e riadattabile necessita che sia presente un file di configurazione che dica al processo che tipo di info servono e dove reperirle così che se qualcuno o qualcosa cambia le carte in tavola non serva mettere mano allo script ma solo rivedere le configurazioni impostate. E’ un elemento fondamentale al fine di rendere l’applicazione utilizzabile.

3) Definire come loggare

Infine al fine di avere un’informazione più di dettaglio su cosa è accaduto e quali sono state le azioni per verificare sia tutto ok serve anche che il sistema logghi tutto su un file che possa essere utilizzato a valle di ogni singolo run

Root Folder

Insomma ricapitolando:

  • Config.xml: sarà il file che contiene le configurazioni
  • Conto2.3.ps1: sarà il file dove verranno implementate le logiche di ET
  • Conto2.3.xlsx: sarà il file Excel che effettuerà la parte di L e genererà la pivot
  • MasterCategories.xlsx: sarà il file dobe risiedono i mapping per la categorizzazione usato dunque nella fase di ET