Applikationslogning

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

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:

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

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

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

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

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.

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.

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).

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"
      }
    }

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).

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

Serilog

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!

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.

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)