Structured logging in een .NET applicatie

it-rockstar vincent hendriks

Als er 1 ding is wat in vrijwel iedere applicatie aanwezig is dan is het wel logging. Als er iets mis gaat is dit ook vaak 1 van de eerste dingen waar we naar kijken.

Na redelijk wat jaren bezig te zijn met het ontwikkelen van diverse applicaties en daarbij verschillende vormen van logging te hebben gezien is het dan ook wel leuk om te zien dat logging echt wel beter kan. Logging? Hoeveel kan dit nu beter geworden zijn? Als jij al bekend bent met gestructureerde logging (“Structured logging” / “Semantic logging”) dan is dit artikel wellicht niet voor jou, maar als jij dit nog niet kent… Lees door…

Waarom loggen we eigenlijk?

Voordat we verder gaan, waarom loggen we eigenlijk?

Hoe ik er in ieder geval tegen aan kijk is dat we vaak ons best doen om een applicatie zo robuust mogelijk te ontwikkelen, maar er toch altijd iets mis zal gaan. Als dit gebeurt willen we eigenlijk altijd de logs er bij kunnen pakken om te gaan kijken wat er nu precies gebeurt, toch?

Vragen die je jezelf zult stellen zijn o.a.:

  • Wat was nou precies de foutmelding?
  • Wat gebeurde er voordat dit probleem optrad?
  • Hadden meerdere gebruikers hier last van?
  • etc

In dit geval gebruiken we de logs als een diagnostische tool.

Een andere reden om logging toe te passen is bijvoorbeeld t.b.v. monitoring/analytics:

  • Hoeveel requests per seconde zijn er nu?
  • Wat is de gemiddelde response tijd?
  • Hoeveel orders per minuut zijn er nu?
  • etc

Vervolgens kunnen we deze logging weer gebruiken om alerts af te laten gaan als er bijvoorbeeld enkele van die bovenstaande waardes boven/ onder een bepaalde grens komen (Denk bijvoorbeeld aan Azure Monitor i.c.m. Application Insights)

Wat de reden ook is, je zult vast ook wel weten hoe lastig dat soms kan zijn als je dit allemaal uit pure tekst zou moeten halen, toch? Dit is waar gestructureerde logging van pas komt.

Gestructureerde logging

Gestructureerde logging (soms ook semantische logging genoemd) doet eigenlijk precies wat de naam al zegt. Het zorgt er voor dat je niet alleen een platte tekst logt, maar gestructureerde data.

In dit artikel maak ik qua voorbeelden gebruik van Serilog i.c.m. Microsoft’s abstractie laag t.b.v. logging, maar dit kan natuurlijk ook op andere manieren ofwel talen/ontwikkelomgevingen. De demo applicatie die ik aan het einde deel is gemaakt d.m.v. ASP.NET Core, maar dit zou net zo goed met het full .NET Framework gemaakt kunnen worden.

Laten we eerst eens kijken naar een simpel voorbeeld waarbij er een foutmelding wordt gelogd:

_logger.LogError(exception, $"An error occurred trying to save order: {order.Id}")

Dit is overigens hoe het niet moet, maar daar komen we zometeen op terug.

Wat voor data zien wij hier als we dit naar een simpel log bestand zouden wegschrijven?
Typisch zal dit dan het tijdstip, de log level, de foutmelding met stacktrace zijn en een tekst regel met daarin een order id verwerkt. Als we in hetzelfde log bestand zouden gaan zoeken naar een specifieke order id dan is er een grote kans dat we deze zullen gaan vinden, maar wat nou als we iets anders hadden dan het order id? Bijvoorbeeld een klant id of nog beter een error id die we als response melding hebben gegeven.
We kunnen natuurlijk deze ontbrekende informatie toevoegen aan deze log actie, maar daar hebben we op dat moment niks aan. We weten nou eenmaal niet altijd wat we precies nodig gaan hebben totdat we ergens tegen aan lopen en het blijkt dat we iets missen. Overigens verdwijnt dit probleem natuurlijk nooit helemaal, maar we kunnen het wel zo veel mogelijk proberen te voorkomen. Los daarvan denk ik ook dat niemand heel erg vrolijk wordt op het moment dat we ellenlange log acties in onze code gaan schrijven alleen maar omdat we allerlei extra data willen gaan loggen, toch?

Een ander probleem wat we hier zien is dat als we de data willen verwerken/doorzoeken dat we de tekst moeten gaan parsen.

Om deze 2 punten te gaan verbeteren gaan we als eerste deze log actie een klein beetje herschrijven naar:

_logger.LogError(exception, "An error occurred trying to save order: {orderId}", order.Id)

Er zijn nu een aantal dingen die veranderd zijn:

  1. Op het moment dat de configuratie zegt dat we alleen Critical logging willen wegschrijven dan zal er geen string concatenatie plaats vinden, omdat deze log actie een lagere level heeft.
  2. Een log provider kan de eventuele parameters apart verwerken. In dit geval zou de orderId dus, naast de tekst weergave van de logregel, apart opgeslagen kunnen worden.

Wanneer we bijvoorbeeld Serilog gebruiken dan geeft Serilog alle parameters door naar de onderliggende “log sinks”/ log providers. Een “sink” bepaald hoe en waarheen een log weggeschreven gaat worden. Je kunt hier denken aan de Console, Files, SQL Server, etc.

Dit lost, afhankelijk van de gekozen sink, in ieder geval het probleem op van het tekst parsen. We kunnen alleen nog een stapje verder:

_logger.LogError(exception, "An error occurred trying to save order: {@order}", order)

Er is eigenlijk, qua code, maar 1 klein verschil: In plaats van een order id hebben we het gehele order object meegegeven. Normaliter zou dit dan d.m.v. een ToString call omgezet worden naar een string wat standaard een type naam zal opleveren, maar door een @ toe te voegen geven we richting Serilog aan dat we dit object als een gestructureerd object willen opslaan.
Zodra je dit dan bijvoorbeeld in de Console/ File logging voorbij ziet komen krijg je typisch de JSON representatie van de order te zien.

Wat er nu alleen nog ontbreekt is dat je niet eenvoudig door je logs heen kunt zoeken. Dit is waar een “Structured Log Server” van pas komt…

Structured log servers

Wanneer je gebruik maakt van een logging library die gestructureerde logging ondersteund, maar dit dan wegschrijft naar een formaat waar deze data als platte tekst opgeslagen wordt dan maak je nog niet optimaal gebruik van gestructureerde logging. Een “structured log server” zorgt ervoor dat de volledige data opgeslagen wordt en maakt het gebruikers mogelijk om hier door heen te zoeken, filteren en te visualiseren. Ook zijn er log servers die het alerting deel kunnen overnemen t.b.v. monitoring. Er zijn diverse cloud oplossingen, maar ook oplossingen die je zelf kunt hosten. Welke je gebruikt ligt vooral aan eigen voorkeuren, het bedrijfsbeleid en/ of eventuele wetgevingen waar je je aan moet houden.

Hieronder een voorbeeld van een logging server genaamd seq:
image

Seq bied een eenvoudige interface aan waarmee je via queries door de logs heen kunt zoeken. Vervolgens kun je de data van een logregel eenvoudig bekijken en vervolgens met enkele muiskliks andere logregels zoeken met vergelijkbare eigenschappen.

Om terug te komen op het ‘order’ voorbeeld. Je zou dus kunnen zoeken op order Id, maar ook op basis van alle aanwezige properties binnen het order object.

Scoping

We weten nu dat we hele objecten kunnen loggen, maar stel je zou bijvoorbeeld alle logs willen zien gedurende het uitvoeren van 1 specifieke API call / request? In een traditionele aanpak zou je dan voor iedere log regel een bepaald kenmerk moeten wegschrijven zodat je dit kunt volgen, maar met een moderne aanpak zoals we hier beschrijven kan dit d.m.v. “log scoping”. Bij het aanmaken van een nieuwe log scope voeg je data toe aan alle log acties die binnen deze scope worden uitgevoerd.

ASP.NET Core maakt automatisch al een nieuwe scope voor ieder request en voegt hier o.a. een unieke request id aan toe. Zou je van 1 foutmelding willen weten wat er nog meer gedurende dezelfde request is gebeurt dan hoef je alleen maar te filteren op de request id die bij deze specifieke foutmelding aanwezig is en je krijgt alle log regels te zien die gelogd zijn gedurende de afhandeling van deze request.

Los van het feit dat ASP.NET Core zelf scopes aanmaakt, kun je dit ook zelf doen. Als voorbeeld zou je een taak kunnen hebben draaien binnen je applicatie en een nieuwe scope voor iedere taak run kunnen aanmaken.

Een voorbeeld hoe je zelf een scope aanmaakt:

using (_logger.BeginScope("Running task {task}. Task Run Id: {taskRunId}", typeof(TTask), taskRunId))
{
    ...
}

In bovenstaand voorbeeld zou dit betekenen dat je op basis van een taskRunId alle bijbehorende log regels kan opzoeken.

Gevoelige informatie

Hopelijk ben je tot nu toe enthousiast, maar voordat je overal volledige objecten gaat loggen moet je wel even bewust worden van een risico wat hierbij komt kijken:
Let goed op wat je naar je logs wegschrijft!

Het is al heel wat keren voorgekomen dat een bedrijf in het nieuws komt, omdat er wachtwoorden zijn gelekt via logbestanden. Uiteraard wil je geen wachtwoorden en/ of gevoelige informatie wegschrijven!

Eigenlijk is dit risico altijd al wel aanwezig geweest, maar met meer data betekent dat dit risico alleen maar groter wordt

Gelukkig zijn er wel een aantal dingen die je kunt doen om dit te voorkomen. Je kunt simpelweg ervoor zorgen dat deze objecten met gevoelige informatie niet gelogd worden of je gaat deze data maskeren/wegpoetsen voordat ze weggeschreven worden.

Als voorbeeld hoe je dit zou kunnen doen kijken we naar hoe een open source library dit doet d.m.v. attributes die je boven je properties/ fields kunt plaatsen:

public Guid Id { get; }

[NotLogged]
public string Name { get; }

[LogMasked(ShowFirst = 3)]
public string SocialSecurityNumber { get; }

Zodra dit object vervolgens gelogd wordt dan zal er geen “Name” aanwezig zijn en zal er maar een gedeelte van het “SocialSecurityNumber” zichtbaar zijn.

Voorbeeld:
image

Een demo applicatie

Hopelijk is het nu een beetje duidelijk wat gestructureerd loggen nou precies is en hoe je hier je voordeel uit kunt halen.

Is het verhaal toch nog niet helemaal duidelijk en wil je graag wat meer zien? Ik heb een demo applicatie gemaakt waarin ik bovenstaande punten laat zien.

Het enige wat je hiervoor nodig hebt is Docker/Docker-Compose die ik hiervoor gebruik om een volledig werkende solution i.c.m. seq te demonstreren.

De applicatie zelf is vrij klein en bied een API (Inclusief NSwag UI) waarmee fictieve Rockstars opgehaald kunnen worden en er een fictief berichtje naartoe gestuurd kan worden. Bij het versturen heb ik een bewuste “random optredende foutmelding” gezet zodat de log regelmatig met foutmeldingen gevuld zal worden.

Ook draait er een eenvoudige taak die iedere 10 seconden een willekeurige Rockstar kiest en er ook een fictief berichtje naar toe probeert te sturen.

Zowel het uitvoeren van een van de api endpoints als de taken zorgen voor wat logging die het principe duidelijk zouden moeten maken.

Je kunt de demo applicatie hier vinden:
https://github.com/vhendriks81/structuredloggingdemo

Have fun!

Vincent Hendriks - Team Rockstars IT
LinkedIn: https://www.linkedin.com/in/vhendriks/