Send til redaktion@dotnyt.dk hvis du har feedback, gode idéer, konstruktiv kritik eller svinere. Alt har interesse!
Nyheder til dig som udvikler softwareprodukter til skyen med Microsoft-teknologi
Ingen anvendt
7. juni 2022, du lytter til DotNyt
Det er ufatteligt let at tage Application Insights i brug. Du kan næsten ikke undgå det. Alle skabeloner til Azure Functions fødes allerede med et log-objekt som man bare skal begynde at skrive til. Det er et enkelt klik i Azure at aktivere det og det virker uden videre.
Så ingen har brug for hjælp til at komme i gang med Application Insights. Men hvis du udvikler en større applikation som skal vedligeholdes over længere tid er der brug for en gennemtænkt logging-strategi og jeg har et bud som jeg gerne vil dele med dig.
For 20 år siden brugte man Log4net og for 15 år siden skiftede mange til NLog. De fulgte samme mønster og det selvsamme mønster kan stadig spores til Application Insights i dag, men der er trods alt nogle ting som har ændret sig.
Man kunne logge på 6 niveauer og idéen med at logge på forskellige niveauer er at man kan slå logging til eller fra på de niveauer, så man f.eks. kan have et mere detaljeret logniveau på et testmiljø end man har i produktion. Årsagen er at det koster performance og plads at logge meget så derfor vil det måske ikke være en god ide at logge på et meget detaljeret niveau i produktion.
Det var dog muligt at slå mere detaljeret logging til i et enkelt namespace og det kunne man bruge til at troubleshoote et specifikt område i produktion hvis man havde brug for det.
De 6 niveauer var Trace, Debug, Info, Warn, Error og Fatal. De samme 6 niveauer er til stede i dag i Application Insights og det er nok af historiske årsager, da der ikke er brug for så mange niveauer i dag.
Det er der to årsager til.
Den ene er at vi nu har en fantastisk god debug mode hvor man lokalt kan se koden blive afviklet på en måde der er både god og stabil. Behovet for logging til udviklingsformål er derfor reduceret betragteligt.
Den anden ting som har ændret sig er Application Insights. Der er en masse faciliteter som helt eller delvist erstatter de gamle log-niveauer. Ikke mindst exception tracking som giver detaljerede oplysninger om alle uhåndterede fejl – inklusive konteksten hvor de skete! Så hvis der sker en fejl kan du finde den i Application Insights og du kan finde alle de loglinjer som hører til samme eksekvering og hvis du logger godt har du en god chance for at regne ud hvad der gik galt.
Så med det in mente, lad os tale om nogle gode måder man kan gribe logging an i dag.
Trace har du kort sagt ikke brug for. Du kan godt bruge Debug, men behovet er heller ikke stort. Info-niveauet, derimod, er meget brugbart. Det er det som skal give dig kontekst til dine kald og det er som udgangspunkt slået til i standardopsætningen af Application Insights når applikationen kører i produktion.
Så du kan f.eks. logge parametrene når en metode kaldes. Application Insights logger URL’en, men ikke evt. indhold i et POST, så det vil du være nødt til at logge selv med INFO. Hvis der er andet indhold som indgår i afvikling af metoden vil det måske være en god idé at logge det også som INFO. Hvis du f.eks. henter data hos en tredjepart, vil det være en god idé at logge det som INFO også.
En meget løs tommelfingerregel, bare for at give en fornemmelse af omfanget, kunne være at du logger 2-3 gange ved hvert metodekald. Det kan være mere hvis behovet er større og mindre hvis behovet enten er mindre eller hvis kaldet udføres meget, meget ofte – så kan du være nødt til at gå på kompromis med logging-niveauet pga. omkostningen. Så det afhænger af den konkrete situation, men tænk på det sådan her: Formålet med INFO-logging er, at hvis der sker en fejl, så giver INFO-logging kontekst til fejlen så du måske kan finde fejlen ud fra din logging.
WARN bruges til situationer hvor du har en uventet tilstand men ønsker at fortsætte alligevel. Det kan være en værdi som ikke burde være null. Hvis den så er det alligevel kan du logge det som WARN, men så sætte en standardværdi og lade brugeren fortsætte. Det er relativt sjældent at du har en situation hvor du er bevidst om muligheden for en UVENTET værdi. Altså hvis den er uventet, hvordan kan du så være så forudsigende at logge den? Derfor er WARN relativt sjældent brugt.
ERROR er logging af en fejl som gjorde at metodens afvikling måtte stoppe og hvis der er en bruger som eksekverer metoden vil de så opleve en fejl. Fordelen ved at logge som ERROR i stedet for bare at lade fejlen falde igennem og ud til Application Insights er kun det, at du som udvikler har mulighed for at skrive en lille tekst som hjælper dig selv eller en anden udvikler med at forstå hvad det var for en fejl som skete. Det kunne være “An unexpected error occurred when retrieving the RSS feed”.
Her skal du selvfølgelig bruge de forskellige exception-typer til at fange fejl af bestemte typer, så du kan lave mere sigende fejlbeskeder. F.eks. kan du se om det er en netværksfejl og så skrive “The RSS feed could not be fetched because of a network error”. Og du kan tjekke om statuskoden er 200 og hvis den ikke er det, kan du logge: “RSS feed could not be fetched because of HTTP Status code 400”
De oplysninger kan du måske udlede af Application Insights ved hjælp af exception tracking eller dependency tracking, men hvorfor ikke gøre det lidt mere brugervenligt – eller udviklervenligt – og dele ud af den indsigt du havde da du udviklede den kode som nu fejler?
Til sidst har vi FATAL. Den blev i sin tid brugt til uhåndterede fejl og den udgår da det er overtaget af exception tracking fra Application Insights.
Så nu har vi velstruktureret og konsistent logging som giver kontekst når der er fejl og også kan give indsigt i hvad der foregår i applikationen, men det der spørgsmål om “hvad der foregår” det har Application Insights faktisk også to helt fantastisk gode svar på.
Hvis man gerne vil tracke når noget sker på en konsistent måde som endda også er struktureret og søgbar, så kan man bruge det som hedder Custom Event. Det kan man f.eks. bruge til at logge hver gang en betaling gennemføres og så måske logge hvilket device brugeren brugte hvor meget de købte for.
Noget andet som er uhyggeligt godt er Metrics. Det bruges kort sagt til at logge tal. Her kunne man også logge noget jordnært, såsom hvor meget de købte for og vupti, så har du en graf der viser omsætning per dag. Det har du nok også i databasen, men det her er til dashboard-formål og det kræver én loglinje og så kan du følge med i det visuelt direkte fra Azure-portalen.
Noget andet som metrics kan bruges til er mere tekniske ting. Det kan klare rigtig meget aktivitet, så det kan være et kald der måske afvikles en million gange om dagen hvor du gerne vil følge nøje med i svartiderne hen over dagen. Igen har du nok den oplysning i Application Insights, men når det logges som Metrics har du det som et tal der er let at følge og det er bare en afgørende forskel hvis det er noget du gerne vil følge med i.
Så det var hele landskabet for logging her i 2022 med Application Insights. Så vi bruger kun INFO, WARN og ERROR til logging. De andre logniveauer er erstattet af bedre udviklingsmiljøer samt af Application Insights selv. Derudover skal man huske at gøre brug af både Custom Event og Metrics.
Logging er et område hvor der kan være mange rigtige svar og det jeg har givet i dag er et bud blandt mange gode alternativer. Jeg vil sætte pris på hvis du vil dele i kommentarerne på Linkedin, Facebook eller Twitter hvor I er enige eller uenige med den fremgangsmåde jeg har beskrevet her i dag.