Oct.17

De zwarte doos, tracen voor luilakken

Tracing is een manier om informatie te loggen over de werking van applicatiecode. Een soort van “zwarte doos” voor software. In de System.Diagnostics namespace zijn een aantal klassen opgenomen waarmee tracing en debugging informatie kan worden gelogd naar een bestand, eventlog of welke ander outputdevice of datasource ook. Dit gebeurd via zogenaamde listeners. Tracing is met name bedoeld voor applicaties die in release mode zijn gecompileerd. Debug wordt echter alleen gebruikt voor het loggen van gegevens in debug mode.

Bovenstaande code schrijft standaard alle debug regels naar het “output” venster van Visual Studio. Dit komt omdat er een default listener actief is voor het wegschrijven van deze informatie naar dit window.
output.png
Het is mogelijk een nieuwe listener te activeren die deze informatie naar (bijv.) een tekstbestand schrijft. Naast deze globale informatie waarover je veel meer kunt vinden op het web is het handig te weten dat tracemessages in 4 niveaus kunnen worden verdeeld:

  • Verbose (level: 4)
  • Info (level: 3)
  • Warning (level: 2)
  • Error (level: 1)

Verbose is het meest gedetaileerde niveau waarop wordt gelogd. Error is het minst gedetaileerde niveau. Je kunt voor een lopende applicatie bepalen welk soort tracemessages moeten worden gelogd. Kiezen we voor “Warning” dan worden zowel “Warning” als “Error” message gelogd. Kiezen we voor Verbose dan worden alle messages gelogd etc… Uiteraard wordt bij level 0 niets gelogd.

Automatiseren van de logging

Vooral bij tracing wil je een aantal standaardgegevens opnemen voor elk tracemessage. Praktische informatie die ik bij elke gelogde regel zou willen hebben is:

  • Datum/Tijd
  • Gebruikersnaam waaronder de applicatie draait.
  • Gegevens van de methode waarin de trace wordt weggeschreven.

.. en het logbericht natuurlijk. Het is natuurlijk onhandig als je bij elk logbericht al die gegevens keer op keer moet meegeven.

De oplossing hiervoor is de zelfbouw TraceManager class. Om deze te kunnen gebruiken moet er het volgende gebeuren. In de app.config of web.config van de applicatie moet de volgende Xml worden opgenomen:

Met deze switch wordt aangegeven op welk level moet worden gelogd. Vervolgens wordt met de volgende regel de TraceManager geinitialiseerd:

De tracemanager gaat alle logregels wegschrijven naar een bestand met de naam c:testtrace.log.
Met de volgende code loggen we een tracebericht:

Dit bericht resulteert in de volgende gegevens in het testtrace.log bestand:

Zie hier… er is een klein wondertje gebeurt. De applicatie heeft via een kijkje in de callstack en een stukje reflection de methode vastgesteld waarin de tracemessage is aangemaakt. Op deze manier is tracen een makkie geworden.

Maar hoe werkt deze “zwarte” TraceManager doos?

De datum en de gebruiker vaststellen is niet zo heel ingewikkeld. (Geen zorgen trouwens je kunt de code downloaden via de link onder aan dit artikel ;-).)Het vasstellen van de aanroepende methode heeft wat meer voeten in aarde. Het ophalen van deze gegevens heeft alles te maken met de callstack. De callstack is een hierarchische lijst van methodes die elkaar hebben aangeroepen. We hebben in de file program.cs de methode Main() deze roept een methode Print() aan en die roept weer de methode PrintFirstLine() aan. De callstack is bij het aanroepen van de methode PrintFirstLine() hierarchisch:
Main() (stackframe 2)
> Print() (stackframe 1)
> > PrintFirstLine() (stackframe 0)

MethodBase is een object uit de System.Reflection namespace en bevat informatie over een methode (metadata). Als we echter een TraceMessage.WriteVerbose(…) methode plaatsen binnen de PrintFirstLine() methode dan zal deze stackframe 0 worden en PrintFirstLine() stackframe 1 etc… Daarom willen we het eerste stackframe ophalen wat GEEN methode is van de TraceManager class. Dat doen we met de volgende code:

LET OP! Mocht je dus in de toekomst besluiten de naam van de TraceManager te veranderen. Dan moet je de hier niet vergeten mee te wijzigen anders werkt de code niet meer. (Dit is overigens intelligenter op te lossen met een stukje reflection maar daar ben ik nog niet aan toegekomen) Bovenstaande functie retourneert informatie over de methode die de (bijv.) TraceManager.WriteVerbose(…) methode aanroept.

Met onderstaande code kunnen vervolgens de gegevens als naam van de methode, parameters en return type worden opgehoest:

Kortom tracen voor luilakken. Je loopt nu tegen het probleem aan dat je eigenlijk niet meer weet wat je als daadwerkelijke message mee moet geven aangezien zo wat alles al wordt gelogd ;-).

Vooruit downloaden maar.. en veel plezier er mee!
TestApp.zip