Applikationslogning

Applikationslogning

Præambel

Logning har altid været en essentiel del af et hvert professionelt setup. Man har, lige siden det første system gik i online, været intresseret i hvordan systemet reagerede på forskellige input. Over tid har selve kunsten at logge udviklet sig til det håndværk vi har i dag. I dag er disciplinen, logning, nærmest en uddannelse i sig selv, en selvlært uddannelse jeg i en serie af indlæg her på bloggen, vil prøve at belyse.

Udgangspunkt

Jeg tager i dette indlæg udgangspunkt i det velkendte Application Insights SDK, som kan nugetteres (installeres, hentes, downloades; kært barn har mange navne), når man enten laver:

  • en almindelig consol applikation

  • en .NET Core web applikation

  • en Azure Function

  • eller noget helt fjerde

Det er et SDK som kan bistå udvikleren, ninjaen, krigeren, i kampens hede, ved at give indsigt i det binære maskinerum, som er blevet formuleret, komplieret, releaset og startet; enten i Azure, på en onprem lokation, eller i en galakse, ikke fjernt fra dette sted.

Jeg vil derefter wrappe den velkendte Serilog omkring bæstet, og se hvordan dyret tæmmes anderledes. Er det bedre? Lettere, eller er det bare endnu et lag til den teknologiske lagkage, man har fået stablet på benene udfra devicen om "at gutten på nettet sagde at alt blev bedre".

Jeg vil lave mit ikke-kliniske-forsøg, på to applikationer:

  1. en .NET Core konsol applikation - i Microsoft regi kaldes dette en "non-HTTP application"

  2. et .NET Core web api

let's get rolling!!

TelemetryConfiguration

TelemetryConfigration er selve kernen i hele Application InsightsSDK'et. Konfigurationen indeholder mange forskellige entiteter, dog er der specielt to (fatisk tre, da en given sink sådan set også er meget vigtig - dog vil jeg kun snakke om to her i indlægget) som jeg finder vigtigst, og mest spændende:

  1. TelemetryInitializer

  2. TelemertryProcessor

begge tilhører TelemetrySink som er en property ved navn DefaultSinkTelemetryConfiguration (faktisk kan der være mange sinks, men i denne artikel har vi kun fokus på default konfigurationen, og DefaultSink, som er at finde på TelemetryConfiguration klassen).

Grunden til at jeg meget gerne vil fremhæve konfigurationen og TelemetryInitializer samt TelemetryProcessor er at disse to entiteter er meget vigtige i forhold til:

  1. Prisen på Application Insights ressourcen i Azure

  2. Telemetri data sendt over linjen, brugt til debugging

  3. Aggregeringsdata brugt til generel overvågning

Fejler man opsætningen, så kommer man højest sandsynlig ud for enten:

  1. En meget høj pris i Application Insights, eller

  2. skævvridning af indsamlet data, som enten bruges til debugging eller generel overvågning

Det kan man meget nemt komme til, specielt hvis man gør brug af Serilog, da 2/3 af alle artikler på nettet:

  • er skrevet før adaptiv sampling er indført, eller

  • ikke nævner at man skal være opmærksom på det er vigtigt at man sørger for at få konfigureret TelemetryClient=/før/ den sættes sammen med ens =Serilog lag

Et kig

For at tage et kig på en default konfiguration, kan man oprette et ASP.NET Core web api, og køre følgende i Startup.cs:

    var config = TelemetryConfiguration.CreateDefault();

Husk at lave en packet reference til seneste version af Application Insights i din csproj fil:

    <PackageReference Include="Microsoft.ApplicationInsights.AspNetCore" Version="2.12.0" />

og smid følgende i services:

    services.AddApplicationInsightsTelemetry();

Laver man et debug breakpoint efter CreateDefault kaldet, og starter API'et i debug mode, vil man se følgende i config objektet:

  1. DefaultSink propertien vil indeholde en TelemetryProcessor ved navn Microsoft.ApplicationInsights.Extensibility.Implementation.TransmissionProcessor

  2. TelemetryInitializers listen på selve config objektet vil indeholde en initializer ved navn Microsoft.ApplicationInsights.Extensibility.OperationCorrelationTelemetryInitializer

TransmissionProcessor sender data, gennem den TelemetryChannel som er defineret på TelemetryConfiguration (default er en Microsoft.ApplicationInsights.Channel.InMemoryChannel, som sender hvert 30 sekund, eller når en buffer er fyldt, gennem en InMemoryTransmitter), og OperationCorrelationTelemetryInitializer sørger for at korrelere alle operationer i konteksten, så disse har samme tilhøringsforhold (jeg mener at der generes et unikt id, som påsættes alt event data).

Sinks vil jeg ikke komme ind på, hverken nu, eller i fremtiden.

Men hvad er processors, og initializers? De kan (næsten) det samme, that is, de kan undersøge, modificere og filtrere på det telemetri, som skal sendes gennem den konfigurerede channel og transmitter, dog bruges de til forskellige ting:

  1. Initializers bruges til at berige telemetri (by convention smider de ikke data i properties, som allerede er sat)

  2. Processors bruges til filtrere telemetri

Man kan altid være sikker på at:

  1. Alle initializers bliver kaldt, mindst en gang

  2. Initializers kaldes før processors

  3. Du er garanteret at den første processor altid bliver kaldt

TelemetryInitializer(s)

Man kan lave en TelemetryInitializer ved at implementere ITelemetryInitializer. Husk reglen ovenover: en initializer skal typisk kun bruges til at berige telemetri. Jeg har derfor lavet følgende initializer, som smider tallet 42 på hvis vi har at gøre med et request:

    public class AnAnswerTelemetryInitializer : ITelemetryInitializer
    {
        public void Initialize(ITelemetry telemetry)
        {
            var requestTelemetry = telemetry as RequestTelemetry;

            if (requestTelemetry == null) return;
            int code;
            bool parsed = Int32.TryParse(requestTelemetry.ResponseCode, out code);
            if (!parsed) return;
            if (code >= 200 && code < 243)
            {
                requestTelemetry.Properties["TheAnswer"] = "42";
            }      
        }
    }

En initializer kan tilføjes til pipelinen således (for et web api er det i Startup.cs filen i metoden public void ConfigureServices(IServiceCollection services)):

    services.AddApplicationInsightsTelemetry();
    services.AddSingleton<ITelemetryInitializer, AnAnswerTelemetryInitializer>();
    //og så fremdeles

Fyrer man op for et web api, laver et request (husk at koble Application Insights på API'et), så kan man se at 42 kommer op under Custom Properties:

/images/customprops.png

TelemetryProcessor(s)

På samme måde kan man rent faktisk også implementere en TelemetryProcessor. Dog hedder det interface man implementerer ITelemetryProcessor:

    public class TheAsnwerToProcessor : ITelemetryProcessor
    {
        private ITelemetryProcessor _next { get; }
        public TheAsnwerToProcessor(ITelemetryProcessor next)
        {
            _next = next;
        }

        public void Process(ITelemetry item)
        {
            var request = item as RequestTelemetry;

            if(request != null &&
                request.ResponseCode.Equals("42"))
            {
                return;
            }

            _next.Process(item);
        }
    }

Her filtreres alle requests fra som har en HTTP respons status kode på 42 :)

Jeg kan af gode grunde ikke vise mit application insights resultat her, som med min initializer, da requestet aldrig når Application Insights.

En processor kan tilføjes til pipelinen således (for et web api er det i Startup.cs filen i metoden public void ConfigureServices(IServiceCollection services)):

    services.AddApplicationInsightsTelemetry();
    services.AddApplicationInsightsTelemetryProcessor<TheAsnwerToProcessor>();
    //og så fremdeles

Tilfælles: konsol eller web api

For at tilføje en processor eller en initializer, bruger man blot AddApplicationInsightsTelemetryProcessor eller AddSingleton<ITelemetryInitializer, DinInitializer>. Det bliver ikke skulet til om det er en non-HTTP applikation eller et web api man er igang med at sætte op.

Konsol - (non-HTTP applikation)

Vil man bruge ILogger og Application Insights i en konsol applikation, har Microsoft udgivet et nyt SDK, som de anbefaler man bruger.

Jeg har forsøgt at klemme et mini eksempel sammen i et eksempel:

    public class Worker : BackgroundService
    {
        public Worker(ILogger<Worker> logger)
        {
            Logger = logger;
        }

        public ILogger<Worker> Logger { get; }

        protected override Task ExecuteAsync(CancellationToken stoppingToken)
        {
            Logger.LogInformation("Working");

            return Task.CompletedTask;
        }
    }
    public class Program
    {
        public static void Main(string[] args)
        {
            CreateHostBuilder(args).Build().Run();
        }

    public static IHostBuilder CreateHostBuilder(string[] args) =>
            Host.CreateDefaultBuilder(args)
                .ConfigureServices((hostContext, services) =>
                {
                    services.AddHostedService<Worker>();
                    services.AddApplicationInsightsTelemetryWorkerService();
                });
    }

Da de i .NET Core 3.0 har lavet lidt om på den Generic Host, som bruges, skal man foruden Microsoft.ApplicationInsights.WorkerService også huske at smide en reference til Microsoft.Extensions.Hosting, ellers vil Host ikke kunne forfindes i konteksten, og man vil få en compile fejl. Den fulde liste af nuget pakker er som følger:

    <PackageReference Include="Microsoft.ApplicationInsights.WorkerService" Version="2.13.1" />
    <PackageReference Include="Microsoft.Extensions.Hosting" Version="3.1.2" />
    <PackageReference Include="Microsoft.Extensions.Hosting.Abstractions" Version="3.1.2" />

Husk at opdatere til seneste version!

Man kan nu smide ens Application Insights nøgle i en appsettings.json fil,

    {
      "Logging": {
        "ApplicationInsights": {
          "LogLevel": {
            "*.Worker": "Information"
          }
        },
        "LogLevel": {
          "Default": "Information",
          "Microsoft": "Warning",
          "Microsoft.Hosting.Lifetime": "Information"
        }
      },
      "ApplicationInsights": {
        "InstrumentationKey": "dinapplikationsnøgleher"
      }
    }

HUSK at fortælle kompileren at appsettings.json skal kopieres med over når der bygges, ellers får man ikke meget logning i ens Application Insights:

/images/aitrace.png

Web API

Vil man gerne have ILogger og Application Insights i ens web applikation, så er det næsten indbygget. Microsoft beskriver mere om det her.

Kort fortalt, skal du blot lave en reference til denne nuget:

    <PackageReference Include="Microsoft.ApplicationInsights.AspNetCore" Version="2.13.1" />

Husk at opdatere til seneste version! Derefter skal du koble ILogger op mod Application Insights således:

    services.AddApplicationInsightsTelemetry();

I ConfigureServices metoden i Startup.cs. Man kan nu smide ens Application Insights nøgle i appsettings.json, som ved konsol eksemplet. For at få ILogger til at udskrive logs til Application Insights, fra fx en Controller kan man blot referer den i konstruktøren:

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

Og en ILogger vil herefter bliver givet videre til MyController når kontrolleren rammes, og man dermed bruge _logger til at logge til Application Insights.

Prædefinerede initializers og processors

Hvis man nærstuderer de to overstående opsætninger af Application Insights, vil man se at vi aldrig på noget tidspunkt:

  1. kalder TelemetryConfiguration.CreateDefault() - og derved opsætter en TelemetryConfiguration

  2. laver nogen processors,

  3. eller initializers

Alt dette bliver sat op for os når vi tilføjer Application Insights ved enten at

  1. services.AddApplicationInsightsTelemetry(); i en .NET Core web app, eller

  2. services.AddApplicationInsightsTelemetryWorkerService(); i en konsol app (teknisk set kalder Microsoft det for en non-HTTP applikation)

eller, næsten. De gør ikke brug af TelemetryConfiguration.CreateDefault(), da de new'er en konfiguration op og tilføjer alt muligt godt til den af initializers og processors, som kan hjælpe med:

  1. Aggregering af data til overvågning

  2. Minimering af cost i Application Insights

  3. Tracking af dependencies

  4. Korrelation af events

Refererer vi en TelemetryConfiguration i konstruktøren i enten vores webapp eller konsol app, smider et breakpoint i enten Worker eller MyController og inspicerer konfigurationen vil vi se følgende af initializers og processors, som er sat op for os uden at vi skal røre en finger:

Web app - Initializers

  1. Microsoft.ApplicationInsights.Extensibility.OperationCorrelationTelemetryInitializer

  2. Microsoft.ApplicationInsights.AspNetCore.TelemetryInitalizers.AzureAppServiceRoleNameFromHostNameHeaderInitializer

  3. Microsoft.ApplicationInsights.AspNetCore.TelemetryInitalizers.ClientIpHeaderTelemetryInitializer

  4. Microsoft.ApplicationInsights.AspNetCore.TelemetryInitalizers.OperationNameTelemetryInitializer

  5. Microsoft.ApplicationInsights.AspNetCore.TelemetryInitalizers.SyntheticTelemetryInitializer

  6. Microsoft.ApplicationInsights.AspNetCore.TelemetryInitalizers.WebSessionTelemetryInitializer

  7. Microsoft.ApplicationInsights.AspNetCore.TelemetryInitalizers.WebUserTelemetryInitializer

  8. Microsoft.ApplicationInsights.AspNetCore.TelemetryInitalizers.AspNetCoreEnvironmentTelemetryInitializer

  9. Microsoft.ApplicationInsights.AspNetCore.TelemetryInitalizers.DomainNameRoleInstanceTelemetryInitializer

  10. Microsoft.ApplicationInsights.DepenedencyCollector.HttpDependenciesParsingTelemetryInitializer

  11. Microsoft.ApplicationInsights.AspNetCore.TelemetryInitalizers.ComponentVersionTelemetryInitializer

Web app - Processors

  1. Microsoft.ApplicationInsights.Extensibility.AutocollectedMetricsExtractor

  2. Microsoft.ApplicationInsights.Extensibility.PerfCounterCollector.QuickPulse.QuickPulseTelemetryProcessor

  3. Microsoft.ApplicationInsights.WindowsServer.TelemetryChannel.AdaptiveSamplingTelemetryProcessor

  4. Microsoft.ApplicationInsights.WindowsServer.TelemetryChannel.AdaptiveSamplingTelemetryProcessor

  5. Microsoft.ApplicationInsights.Extensibility.Implementation.TransmissionProcessor

Konsol - Initializers

  1. Microsoft.ApplicationInsights.Extensability.OperationCorrelationTelemetryInitializer

  2. Microsoft.ApplicationInsights.WindowsServer.AzureWebAppRoleEnvironmentTelemetryInitializer

  3. Microsoft.ApplicationInsights.WorkerService.TelemetryInitializers.DomainNameRoleInstanceTelemetryInitializer

  4. Microsoft.ApplicationInsights.DepenedencyCollector.HttpDependenciesParsingTelemetryParsingTelemetryInitializer

  5. Microsoft.ApplicationInsights.WorkerService.TelemetryInitializers.ComponentVersionTelemetryInitializer

Konsol - Processors

  1. Microsoft.ApplicationInsights.Extensibility.AutocollectedMetricsExtractor

  2. Microsoft.ApplicationInsights.Extensibility.PerfCounterCollector.QuickPulse.QuickPulseTelemetryProcessor

  3. Microsoft.ApplicationInsights.WindowsServer.TelemetryChannel.AdaptiveSamplingTelemetryProcessor

  4. Microsoft.ApplicationInsights.WindowsServer.TelemetryChannel.AdaptiveSamplingTelemetryProcessor

  5. Microsoft.ApplicationInsights.Extensibility.Implementation.TransmissionProcessor

Overstående er meget udpenslet. Navnene giver for det meste, sig selv. Vi har initializers som smider domæne navnet på, session telemetri eller web app rollen i Azure. Der er processors til quick pulse, så man kan få nær real tids CPU, requests etc i portalen på en given webapp. forbrug for ens webapps, og vigtigst af alt: adaptiv sampling processor'en!

Sammenlignet med den konfiguration vi får ved at kalde TelemetryConfiguration.CreateDefault(), så får man rigtig meget ud af boksen, da man med CreateDefault() kun får:

  1. En Initializer: Microsoft.ApplicationInsights.Extensability.OperationCorrelationTelemetryInitializer

  2. En Processor: Microsoft.ApplicationInsights.Extensibility.Implementation.TransmissionProcessor

I bund og grund: ikke så meget. Ingen quick pulse, ingen ekstra information på ens telemetri, og ingen adaptiv sampling: Man opfordres derfor altid til at hente TelemetryClient eller TelemetryConfiguration ud af IoC'en, hvis man skal gøre brug af det, enten til ens eget hjemmebyggede telemetri storage client, til en tredjeparts aggregerings lognings klient eller noget helt tredje. Hvilket bringer mig til mit næste emne. Serilog.

Quick recap: Adaptiv logning

Jeg har nævnt det flere gange, men hvis du ikke ved hvad adaptiv logning er, så vil jeg prøve at opridse det her, hurtigt: Adaptiv logning er noget som sker på klient siden, altså ikke oppe i Application Insights, hvor den processor, som står for adaptiv logning kigger på strømmen af events, hvis strømmen af events, i en tidsramme, overstiger en grænseværdi, så vil processoren begynde at filtrer disse events fra. Den er dog smart nok til bibeholde dependencies kald osv, så man kan få en god debugging oplevelse, men bemærk dog: den vil begynde at smide exceptions og fejl væk, hvis den begynder: det er alle events den smider væk. Teknisk set begynder den at sample (sampling er det der sker når adaptive logning træder i kraft) de events den smider videre til Application Insights, hvilket er fint: det er volumen af data den adaptive logning skærer ned på. Man sparer penge. Det kan i første omgang godt lyde dumt at smide exceptions og fejl væk, da det er dem man prøver at finde, dog vil man stadig få aggregerede data med, så disse fejl vil fremgå (om man kan forøvrigt stadig fortælle processor'en at den skal se bort fra exceptions og smide alle med, men pas på, for man kan komme ud for at noget fejlen noget så grusomt, og oversvømmer din Application Insights med exceptions, og så er man kommet lige vidt - det koster penge). Sker en fejl nok gange, skal den nok komme med over, så man rent fysisk kan se et event med den i loggen, og det er tit de fejl man rigtig gerne vil rette: dem som sker ofte, da det er en indikation for at der vitterligt eksisterer en fejl, og det ikke bare er netværket der er langsomt, en bot som sender underlig data, eller noget helt tredje obskurt, som kun sker når solen står i zenit, 6. søndag efter trinitatis på ulige uger i skudår, som går lige op med Christians Xs fødselsdag^2.

Grænseværdien er pr default sat til 5 events pr sekund. Husk: det er pr. webapp, så har man 20 microservices, så vil hver af disse arbejde parallelt. Det er der ikke pr Application Insights instans. Det man typisk gør, er at man justerer denne værdi efter man er gået live med første version af ens applikation, hvis 5 events pr sekund ikke er nok. For at se om sampling træder i kraft, kan man køre denne kusto query:

    union requests,dependencies,pageViews,browserTimings,exceptions,traces
    | where timestamp > ago(1d)
    | summarize RetainedPercentage = 100/avg(itemCount) by bin(timestamp, 1h), itemType

/images/ailog.png

Her ligger alle RetainedPercentage på 100, hvilket betyder at alle events bliver sendt fra klienten (din webapp eller non-HTTP applikation og til Application Insights ressourcen i Azure). Træder sampling i kraft, vil RetainedPercentage være < 100. Man kan køre denne query på Application Insights instansen, selvom sampling sker på "den anden siden", nemlig klienten, da TelemetryClient med dens prædefinerede initializers og processors, nok skal sørge for at fortælle Application Insights instansen, hvor mange events den (klienten) har modtaget, og sendt videre.

Lader vi vores konsol applikation kører med Serilog i 10 minutter, så ser det således ud:

/images/ailog2.png

Jeg har blot kørt en while(true) loop med en Task.Delay(100) og sender ca. 30-40 logs afsted i sekundet. De første par minutter sker der ingenting, men der sker et drop til 5%. Overstående viser adaptiv logning i fuld flor: den venter, træder i kraft, og skærer ned.

Min kusto query har jeg ændret lidt:

    union requests,dependencies,pageViews,browserTimings,exceptions,traces
    | where timestamp > ago(20m)
    | summarize RetainedPercentage = 100/avg(itemCount) by bin(timestamp, 1m), itemType
    | order by timestamp asc

Så den kigger 20 minutter tilbage, og deler resutatet op med et minuts mellemrum.

Serilog

Først en meget lang opsang: 3/4 af alle de artikler der flyder rundt på nettet, som viser hvordan man sammenkobler Serilog og Application Insights, siger man enten skal bruge:

  1. TelemetryConfiguration.CreateDefault(), eller

  2. TelemetryConfiguration.Active

Den første, bringer intet ekstra til bordet af berigelse (initializers) eller filtrering (processors), mens nummer to rent teoretisk giver dig de initializers og processors som frameworket har sat op, så er den deprecated og bliver snart afskaffet helt, ifølge Microsoft. Det er derfor forkert at bruge disse hvis man gerne vil koble Serilog på, og have alt den funktionalitet, som man ellers vil have, hvis man blot brugte en almindelige "rå logger", men hvordan gør man så? Det vil jeg beskrive i dette afsnit. Dog vil jeg gerne lige udpensle, hvorfor det er godt at have den indbyggede funktionalitet med, hvis man beslutter sig for at bruge Serilog.

But why?

Vil man gerne bruge Serilog, og læser man en "getting started" artikel, vil man højest sandsynlig blive opfordret til at bruge TelemetryConfiguration.CreateDefault(), hvilket kan have vidtrækkende konsekvenser for den månedtlige pris i Azure, da:

  1. Application Insights fødes normalt med en 100 GB daily cap, hvilket betyder, at når man har logget for 100 GB, så cappes data - man får besked når der er lige ved at være fyldt op

  2. Smider man TelemetryConfiguration.CreateDefault() med ens Serilog, får man ikke adaptiv sampling processors med

en adaptiv processor sørger for at filtrer data fra når flowet af telemetri data rammer et bestemt antal pr. sekund. Default er det 5 pr sekund i en periode. Denne processor er lidt smart, så den sørger for at man stadig kan spore dependencies, og tilhørende events, men hvis man har brugt TelemetryConfiguration.CreateDefault(), så får man ikke denne funktionalitet ud af boksen, hvilket vil sige at man kan ende ud med at event data kan koste dig:

  • 18 kr * 100 GB = 1800 kr

Om dagen, eller 54000 kr om måneden. Har man ikke overvågning på ens forbrug, kan det godt komme til at gøre ondt. Alt dette fordi man ikke har slået adaptiv logning til (som kan redde at prisen stikker helt af - jeg vil dog stadig anbefale at ændre daily cap)! Man kan reducere ens cost væsentligt ved at:

  1. sørger for at have adaptiv filtrering slået til, og

  2. sætter en daily cap til det acceptabel niveau, fx hvis man ved at man får 2,5 gb ind om dagen, så kan man sætte det til 3,5 eller 4 gb

Jeg vil anbefale dig allerede nu at tjekke om disse ting er slået til. Husk at det er pr webapp i Azure. Har du flere microservices, så er det 5 events pr sekund pr microservice. Har man flere microservices, kan man stadig godt ramme 100 GB om dagen, og det er derfor en god idé at sætter daily cap ned til et niveau der er acceptabel, og ikke blot defaulter til 100 GB (medmindre man har brug ford det).

Længere nede beskriver jeg lidt mere i detaljer, hvorfor Serilog måske er bedre end standard loggeren, som følger med frameworket, men først vil jeg beskrive hvordan man sætter det korrekt op, både for konsollen (non-HTTP applikationerne), og for et web api.

Summa summarum: det er godt at have disse standard initializers og processors, også selvom man bruger Serilog, man skal dog have den korrekte TelemetryConfiguration med ud af IoC'en, og ikke bare lave en ny.

Web API

For at få Serilog koblet sammen med Application Insights, installer da følgende nuget pakker

    <PackageReference Include="Serilog" Version="2.9.0" />
    <PackageReference Include="Serilog.AspNetCore" Version="3.2.0" />
    <PackageReference Include="Serilog.Sinks.ApplicationInsights" Version="3.0.4" />
    <PackageReference Include="Serilog.Sinks.Console" Version="3.1.1" />
    <PackageReference Include="Microsoft.ApplicationInsights.AspNetCore" Version="2.12.0" />

Husk at opgrader til seneste verion, hvis det er muligt. Efterfølgende, gå ind i Program.cs, og smid .UseSerilog() i røven på Host.CreateDefaultBuilder(args), så det ser således ud

    public static IHostBuilder CreateHostBuilder(string[] args) =>
        Host.CreateDefaultBuilder(args)
            .ConfigureWebHostDefaults(webBuilder =>
            {
                 webBuilder.UseStartup<Startup>();
            })
        .UseSerilog();

Åbn Startup.cs, og konfigurer din Serilog i public void Configure(IApplicationBuilder app, IWebHostEnvironment env) metoden, fx således:

    var client = app.ApplicationServices.GetService<TelemetryClient>();
    Log.Logger = new LoggerConfiguration()
        .MinimumLevel.Debug()
        .MinimumLevel.Override("Microsoft", LogEventLevel.Information)
        .Enrich.FromLogContext()
        .WriteTo.Console()
        .WriteTo
        .ApplicationInsights(client, TelemetryConverter.Traces)
        .CreateLogger();

læg mærke til første linje var client = app.ApplicationServices.GetService<TelemetryClient>();, det er her alt magien sker: vi henter TelemetryClient, som er konfigureret af frameworket med en TelemetryConfiguration, som indeholder alle anbefalede processors og initializers INKLUSIV ADAPTIV LOGNING!! Få alle dine sinks med, overstående er blot et eksempel. Det vigtige er anden sidste linje .ApplicationInsights(client, TelemetryConverter.Traces). Du kan nu smide din Application Insights key i launchsettings.json "APPINSIGHTS_INSTRUMENTATIONKEY": "41f43984-e0c5-4caf-a1f4-e97cf407053c" som en environmentVariables, eller i appsettings.json (husk ikke at commit koden):

    {
      "Logging": {
        "ApplicationInsights": {
          "LogLevel": {
            "*.Worker": "Information"
          }
        },
      "ApplicationInsights": {
        "InstrumentationKey": "dineapplicationinsightskeyher"
      }
    }

Du har nu:

  1. Serilog, som kan skrive til flere forskellige datakilder

  2. de korrekte og anbefalede initializers og processors INKLUSIV ADAPTIV LOGNING med i din Serilog!

Jeg siger det lige igen: de korrekte og anbefalede initializers og processors INKLUSIV ADAPTIV LOGNING med i din Serilog!

Med andre ord: det bedste af begge verdener. Længere nede i artiklen forklarer jeg hvordan man i bruger Serilog (der skal ikke mange ændringer til). Men først viser jeg lige hvordan man gør for konsol applikationen først (non-HTTP applikationen that is).

Konsol (non-HTTP applikationer)

Du skal starte med at smide disse nuget pakker ind

    <PackageReference Include="Serilog" Version="2.9.0" />
    <PackageReference Include="Serilog.Sinks.ApplicationInsights" Version="3.1.0" />
    <PackageReference Include="Serilog.Sinks.Console" Version="3.1.1" />
    <PackageReference Include="Serilog.AspNetCore" Version="3.2.0" />

Du skal selvfølgelig huske at opgradere til seneste versioner, hvis du kan. Efterfølgende kan du konfigurere Serilog i CreateHostBuilder(string[] args):

    public static IHostBuilder CreateHostBuilder(string[] args) =>
        Host.CreateDefaultBuilder(args)
            .ConfigureServices((hostContext, services) =>
            {
                var provider = services.BuildServiceProvider();

                var client = provider.GetService<TelemetryClient>();

                services.AddHostedService<Worker>();
                services.AddApplicationInsightsTelemetryWorkerService();
                services.AddSingleton<ITelemetryInitializer, AnAnswerTelemetryInitializer>();
                        services.AddApplicationInsightsTelemetryProcessor<TheAsnwerToProcessor>();

            }).UseSerilog();

I din public static void Main(string[] args) smider du følgende:

    public static void Main(string[] args)
    {
         var host = CreateHostBuilder(args).Build();
         var client = host.Services.GetService<TelemetryClient>();

         Log.Logger = new LoggerConfiguration()
             .MinimumLevel.Debug()
             .MinimumLevel.Override("Microsoft", LogEventLevel.Debug)
             .Enrich.FromLogContext()
             .WriteTo.Console()
             .WriteTo
             .ApplicationInsights(client, TelemetryConverter.Traces)
             .CreateLogger();

        host.Run();
    }

Læg mærke til .UseSerilog() som overskriver den indbyggede ILogger factory til at bruge Serilogs factory tilsidst, og var provider = services.BuildServiceProvider();, så vi kan hente den TelemetryClient ud som frameworket har opsat for os. Vi gør selvfølgelig stadig brug af Microsoft.ApplicationInsights.WorkerService nuget pakken, som jeg har fortalt om tidligere.

Du kan nu smide din Application Insights key ind, fx i appsettings.json, for at teste at det virker:

    {
      "Logging": {
        "ApplicationInsights": {
          "LogLevel": {
            "*.Worker": "Information"
          }
        },
      "ApplicationInsights": {
        "InstrumentationKey": "dineapplicationinsightskeyher"
      }
    }

Init af Serilog

Du kan rent faktisk også gøre det som med non-HTTP applikationen i en ASP.NET Core applikation, og smide Serilog på efter hosten er bygget. Dog skal du i så fald åbne Program.cs og gøre følgende (i stedet for det der står ovenover):

    public static void Main(string[] args)
    {
        var host = CreateHostBuilder(args).Build();

        var client = (TelemetryClient) host.Services.GetService(typeof(TelemetryClient));

        Log.Logger = new LoggerConfiguration()
        .MinimumLevel.Debug()
        .MinimumLevel.Override("Microsoft", LogEventLevel.Information)
        .Enrich.FromLogContext()
        .WriteTo.Console()
        .WriteTo
        .ApplicationInsights(client, TelemetryConverter.Traces)
        .CreateLogger();

        host.Run();
    }

Hvad forskellen er ved jeg ikke på stående fod. Måske har det indvirkning på opstart og logning (Læs mere om det her på denne issue). Det kunne godt ligne at man skal defaulte til at bruge TelemetryConfiguration.Active hvis man gerne vil logge opstarts exceptions med Serilog. Vil man det skal man lade være med at angive client når man konfigurerer Serilog med .ApplicationInsights:

        Log.Logger = new LoggerConfiguration()
        .MinimumLevel.Debug()
        .MinimumLevel.Override("Microsoft", LogEventLevel.Information)
        .Enrich.FromLogContext()
        .WriteTo.Console()
        .WriteTo
        .ApplicationInsights(TelemetryConverter.Traces)
        .CreateLogger();

Den defaulter derved til at kalde TelemetryConfiguration.Active i stedet for, og man kan flytte ens Serilog init helt op i starten til fx ConfigureServices:

    public void ConfigureServices(IServiceCollection services)
    {
        services.AddApplicationInsightsTelemetry();

        Log.Logger = new LoggerConfiguration()
        .MinimumLevel.Debug()
        .MinimumLevel.Override("Microsoft", LogEventLevel.Information)
        .Enrich.FromLogContext()
        .WriteTo.Console()
        .WriteTo
        .ApplicationInsights(TelemetryConverter.Traces)
        .CreateLogger();

        //removed
    }

TelemetryConfiguration.Active vil derved indeholde det samme som man vil få gennem IoC'en. Dette er den bedste fix, indtil Serilog (eller Microsoft) kommer op med en bedre måde. Skal man ikke fange exceptions i opstarten, så vil jeg stadig vælge af få mine ting fra IoC'en, og undgå TelemetryConfiguration.Active. Brug derfor kun TelemetryConfiguration.Active hvis du virkelig har brug for det, da TelemetryConfiguration.Active som sagt er deprecated. Faktisk anbefaler Serilog i dens readme at smide konfigurationen i Program.cs Du benytter dig derved af TelemetryConfiguration.Active. Det er et svært valg:

  1. Skal man følge Microsofts anbefalinger, og flytte væk fra TelemetryConfiguration.Active, eller

  2. Skal man gøre brug af TelemetryConfiguration.Active og følge Serilogs anbefalinger

Det er helt op til ens temperment. Jeg gør følgende:

  1. Skal man bruge opstarts logning, så følger jeg Serilogs anbefalinger

  2. SKal jeg derimod ikke bruge opstartslogning, så følger jeg Microsofts anbefalinger

(indtil videre).

Serilog vs rå ILogger

Hvad er forskellen egentlig? Jeg vil give en kort intro her, og fremhæve nogle ting, som er meget godt at vide, da man meget hurtig kan blive grebet af Serilogs "we can do structured logging, and it is going to save the world"-tankegang. Det kan i nogle henseender være super fedt at man kan køre Serilog indover, og logge fx alt information til en datakilde, mens man kører alle errors over i en anden datakilde, men er det egentlig lettere at søge i, når man kan lave structured logging?

Syntaks

Når man går fra den rå application insights logning og til Serilogs logning, så skal man faktisk ikke lave særlig meget om, andet end at tilføje et snabela

  1. Rå ILogger: _logger.LogInformation("Working {object}", new Hello { Name = "Hello World" });

  2. Serilog: _logger.LogInformation("Working {@object}", new Hello { Name = "Hello World" });

Faktisk viser overstående eksempel hvad hele forskellen er:

  • outputtet til konsollen fra 1) vil være "Working Namespace.Hello"

  • outputtet til konsollen fra 2) vil være "Working {"Name":"Hello World","$type":"Hello"}"

Quick tip: fjerner man @ fra Serilog versionen, så vil den opføre sig som den rå ILogger

Dette vil også vise sig i Application Insights. Ens parametre, det vil sige object i _logger.LogInformation("Working {object}", new Hello { Name = "Hello World" }); vil custom properties vises som:

Rå ILogger /images/rawlog.png

Serilog /images/serilog.png

Quick tip: fjerner man @ fra serilog, så vil data stå i Application Insights, som var det en normal rå ILogger

@ i Serilog regi betyder slet og ret: bryd mit objekt op i json og smid det med ud i de sinks man har tilknyttet. I Application Insights betyder det at man får ens objekter som json i Custom Dimensions.

Det er dog vigtigt at understrege: Man behøver ikke @. Fatisk beviser overstående at man ikke behøver røre ens logning, hvis man blot vil smide Serilog på, men have flere sinks tilknyttet (igen: forstil dig at du vil logge information ned i en datakilde som er billig pr. GB, mens errors skal smides ned i en datakilde, som har lidt mere avanceret fremsøgningsmuligheder, så som Application Insights, men som også er lidt mere dyr på GB). Man kobler Serilog på, og derefter er det business as usual. Det er det, fordi man under alle omstændigheder benytter sig af ILogger interfacet. Smart, og enkelt!

Tip: hvis du vil query efter bestemte entiteter

Ved første øjekast er det egentlig mega fedt at man får ens custom dimensions fyldt ud med hvad der i Application Insights UI'et ligner noget man kan søge ned i, fx med følgende kusto query:

    traces | where customDimensions.object.Name == "Hello World"

Dog forholder sig ikke helt sådan, da det blot er UI'et der giver utryk for at den forstår at det er json, feltet object indeholder, og derfor laver så man kan dykke ned i det data der nu en gang er. Vil man gerne søge i det, skal man ud i følgende kusto query:

    traces
    | where parse_json(tostring(customDimensions.object)).Name == "Hello World"

Jeg er ikke Application Insights specialist på nogen måde, men jeg kunne forstille mig at overstående kræver væsentlig mere processeringskraft, da den skal folde vores json ud, og mappe det. Har man nok data, kan det godt blive en tung sag. Jeg anbefaler (der er der også nogle få andre der gør på det store internet) derfor at man laver initializers som kan berige ens Cusom Dimensions, så man fx kan lave følgende kusto query

    traces | where customDimensions.ObjectName == "Hello World"

I teorien kan det godt være store mængder data man smider med ned, så man skal passe på hvad man @'er ud. Det er bedre at holde logningsdata til et mimimum, og lave initializers til resten, som kan berige de events man smider videre med data så det er lettere og hurtigere at fremsøge events, hvis man sidder og skal debugge en applikation.

/images/batmanslap.png

Research it ## Hvad har vi lært?

  • brug den TelemetryClient som frameworket stiller til rådighed, når du bruger Serilog

  • Pas på med Serilogs @ - det kan blive dyrt hvis der er meget data (1 GB koster 18 kr i Azure når vi snakker Application Insights)

  • Lav din egne initializers hvis du vil have data i custom dimensions, som du ved skal bruges til fremsøgning/debugging i Application Insights

  • Brug adaptiv logning: det sparer dig for penge

  • Adaptiv logning skærer ned på volumen af data sendt fra klient til Application Insights, og det er godt

  • Brug kun den implicitte TelemetryConfiguration.Active hvis du skal bruge opstartslogning. Smid Serilog konfiugrationen ude i Program.cs (for en ASP.NET Core applikation)

comments powered by Disqus