search

serilog-contrib / serilog-sinks-applicationinsights

A Serilog sink that writes events to Microsoft Azure Application Insights
Apache License 2.0
220 stars 71 forks source link

Duplicate Logs Using Serilog Logger in Azure Function #157

Open eldursi opened 3 years ago

eldursi commented 3 years ago

I need to use serilog to send message with custom properties to application insights on Azure Functions.

I'm using the code below in my startup and I'm getting duplicate logs in application insights. One log entry containing the custom properties that I've pushed to Serilog and the other doesn't

public override void Configure(IFunctionsHostBuilder builder) { var serilogLogger = new LoggerConfiguration() .Enrich.FromLogContext() .WriteTo .ApplicationInsights(TelemetryConfiguration.CreateDefault(), TelemetryConverter.Traces) .CreateLogger(); builder .Services .AddHttpClient() .AddLogging(l => l.AddSerilog(serilogLogger)) .AddSingleton(serilogLogger); }

Any thoughts on what might be going wrong here?

Note: I tried the following too: builder .Services .AddHttpClient() .AddLogging(l => { l.ClearProviders().AddSerilog(serilogLogger) })
.AddSingleton(serilogLogger);

And this fixed the "duplicate" issue but then I would have a log that contains my custom properties but is missing some key properties (e.g. operation id, cloud role name, etc)

davidferro91 commented 2 years ago

Any update on this?

GianLucaFinelli commented 2 years ago

any other solution? I have this same problem in the database

gradyal commented 2 years ago

I'm also experiencing this.

catsburg commented 2 years ago

Same issue here. Any solution or workaround available?

CrisZis01 commented 2 years ago

Ditto! I have same issue.

Here's my code. Using telemetryConfiguration since Microsoft has decided to drop support for using InstrumentationKey only. They will require the full Application Insights ConnectionString. We found that they already do require it in Gov Azure.

    var telemetryConfiguration = TelemetryConfiguration.CreateDefault();
     \\ ... 
     var loggerConfiguration = new LoggerConfiguration()
                .MinimumLevel.Is(logEventLevel)
                .MinimumLevel.Override("Microsoft", LogEventLevel.Information)
                .Enrich.WithProperty("ApplicationName", "OurAppName")
                .WriteTo.ApplicationInsights(telemetryConfiguration, TelemetryConverter.Traces, logEventLevel);

       Log.Logger = loggerConfiguration.CreateLogger();

       services.AddLogging(configure => configure.AddSerilog(dispose: true));

Note: In .net core/5/6 apps, TelemetryConfiguration will be auto populated with the App Insights connection string from your env var or appsettings.json if exists.

nblumhardt commented 2 years ago

Hi! We're currently switching maintenance teams and low on bandwidth; if anyone is able to help out by investigating this more deeply/proposing a solution, that would be much appreciated. Thanks!

zyofeng commented 2 years ago

Does it work if you Inject ILoggerProvider

builder.Services.AddSingleton<ILoggerProvider, MyLoggerProvider>();

https://docs.microsoft.com/en-us/azure/azure-functions/functions-dotnet-dependency-injection

ckarcz commented 2 years ago

also seeing this. we can't remove the default function logger providers (azure function checks it's expected runtime services) and when adding serilog we log duplicate traces :(

jefferyblessing commented 2 years ago

Any resolutions to this?

builder.Services.AddLogging(lb => { lb.ClearProviders().AddSerilog(Log.Logger); lb.AddSerilog(Log.Logger); });

Throws an error on start up in function app.
We use builder.Logging.ClearProviders().AddSerilog(); in an API but the above does not work and we are still getting duplicate logs.

We did add a TraceTelemetryConverter to set the CloudRoleName and did notice that 1 out of 2 of the duplicated logs reflects the name we set.

ckarcz commented 2 years ago

the marginal fix for this is to remove any AppInsights connection string / instrumentation key from the App/Function configuration section in Azure. with this connection string / instrumentation key removed, the app insights won't be set up for the app/function by default. you have to manually add/initialize it in the startup. then serilog logs will flow into AI as expected, without the duplicate Azure function runtime logger providers also logging to it.

unfortunately, doing this removes the operation_id type (End-to-end trasaction details view) grouping of the traces/requests/exceptions. 😢

jassent commented 2 years ago

the marginal fix for this is to remove any AppInsights connection string / instrumentation key from the App/Function configuration section in Azure. with this connection string / instrumentation key removed, the app insights won't be set up for the app/function by default. you have to manually add/initialize it in the startup.

unfortunately, doing this removes the operation_id type grouping of the traces/requests/exceptions. 😢

I was wondering about this and you just saved me a few hours of work. My conclusion is that with Azure Functions Net6 v4 in isolated mode that Serilog really isn't necessary. Application Insights will retain data for long enough time to debug and applications. This is good news and bad news. The bad news is that Serilog makes the logs more readable. And believe me, I have spent hours wiring up Serilog in several projects.

wkoeter commented 1 year ago

What we do is clear providers before adding Serilog.

That removed all my duplicates when using logger & lets me use Serilog with the A.I. registered TelemetryClient.

middiu commented 1 year ago

What we do is clear providers before adding Serilog.

  • Add A.I.
  • Clear all logging Providers
  • Add Serilog

That removed all my duplicates when using logger & lets me use Serilog with the A.I. registered TelemetryClient.

would you mind to share you code?

Thanks

lavindika commented 1 year ago

Im able to resolve this issue in the below approach.Its work form me. In my situation, I used Queuetrigger Function V4. I can put my logs into app insights without any duplicates

** you can remove the default provider and add Serilog like below

Startup.cs

public override void Configure(IFunctionsHostBuilder builder)
        {
ServiceDescriptor descriptor =
                builder.Services.FirstOrDefault(service => service.ImplementationType?.Name == "ApplicationInsightsLoggerProvider");

            if (descriptor != null)
            {
                builder.Services.Remove(descriptor);
            }

            builder.Services.AddSingleton<ILoggerProvider>((sp) =>
            {
                Log.Logger = new LoggerConfiguration()
                    .ReadFrom.Configuration(Configuration, sectionName: "AzureFunctionsJobHost:logging:serilog")
                    .WriteTo.ApplicationInsights(sp.GetRequiredService<TelemetryClient>(), TelemetryConverter.Traces)
                    .CreateLogger();
                return new SerilogLoggerProvider(Log.Logger, true);
            });
}

Logging sample

[FunctionName(nameof(abcrocessStarter))]
        public async Task Run([QueueTrigger("abctaprocess",Connection = "abcStorage")] 
            DataProcessQueueMessage abcProcessQueueMessage,
            [DurableClient] IDurableOrchestrationClient starter,
            ILogger log)
        {

            log.LogInformation("Serilog Retrieving projectId: {projectId}", 555555);
            log.LogInformation("Retrieving projectId: {projectId}", 333333);

            log.LogError("Retrieving projectId: {projectId}", 111111);
        }
fgheysels commented 1 year ago

Im able to resolve this issue in two ways.Its work form me. In my situation, I used Queuetrigger Function V4. I can put my logs into app insights without any duplicates

  1. You can disable the default logger in the host.json file the following way. Make it isEnabled = false "logging": { "applicationInsights": { "samplingSettings": { "isEnabled": false } },

That would be strange, as this is controlling the sampling settings for application insights. It is not removing or disabling the app insights logger. (see docs)

lavindika commented 1 year ago

@fgheysels Try the second approach mentioned in my comments. It works for me. Currently, I`m using it.

tleblanc159 commented 1 year ago

@eldursi @fgheysels @middiu

An instance of ApplicationInsightsLoggerProvider is registered and used by the In-Process Azure Function Host using the LoggerProvider pattern to log to App Insights. This works fine until you want to log custom things to App Insights (using Serilog, etc) because by registering your custom App Insights provider, your loggers will now write to App Insights twice; once through the Azure Host registered logger provider and once through your custom logger provider.

To fix this, you could completely remove the Azure Host registered logger provider, but this removes all the nice, default metric/request/correlation capturing capabilities of Az Funcs + App Insights.

The working solution I have found is to register a custom LoggerFactory instance that contains all the registered logger providers except the App Insights logger provider registered by the Azure Function Host that also contains any custom provider that I want to use to log to App Insights.

Then, you can inject this LoggerFactory instance into your Function App class and create an ILogger instance that logs to App Insights only through your custom provider and still logs to all other providers and does not require you to remove the default App Insights logger provider completely. This way, you get the best of both worlds.

In this model, you would not register your custom logger provider with the ILoggerProvider interface since this would cause all ILogger instances directly resolved from the container to use both App Insights providers, leading to duplicate logs.

Startup Configure method:

builder.Services.AddSingleton((sp) =>
{
    Log.Logger = new LoggerConfiguration()
        .Enrich.With<ThrowContextEnricher>()
        .Enrich.FromLogContext()
        .WriteTo.ApplicationInsights(sp.GetRequiredService<TelemetryClient>(), TelemetryConverter.Traces)
        .CreateLogger();

    List<ILoggerProvider> providers = new
    (
        sp.GetServices<ILoggerProvider>()
          .Where(lp => lp.GetType().Name != "ApplicationInsightsLoggerProvider")
    )
    {
        new SerilogLoggerProvider(Log.Logger, true)
    };

    return new LoggerFactory(providers);
});

Function code:

private readonly ILogger _logger;

public AzFunc(LoggerFactory loggerFactory)
{
    _logger = loggerFactory.CreateLogger<AzFunc>();
}

[FunctionName("FuncName")]
public async Task FuncName([ServiceBusTrigger(ConstantStrings.TOPIC_NAME,
                                                ConstantStrings.SUBSCRIPTION_NAME,
                                                Connection = ConstantStrings.SB_CONN_STRING_VARIABLE_NAME)]string queueItem)
{
    _logger.LogInformation("info");
}
fariz-huseynov commented 1 year ago

Duplicate logs issue occurs in Azure Functions when the following environment variables are used. These variables enable ApplicationInsights in the runtime host used by the Azure Functions service. The Azure Functions runtime builds upon the Azure WebJobs SDK to provide a hosting platform for functions. So you have to somehow bypass using these environment variables, if you want to use Serilog.Sinks.ApplicationInsights package with azure functions.

  1. If you set one of these variables on local machine => Azure Functions Core Tools will enable ApplicationInsights.

  2. If you set one of these variables in Azure cloud environment => Azure Functions Host will enable ApplicationInsights.

If you check SDK version property in AppInsights logs.

For isolated worker process

Solution 1

If you set connection string or instrumentation key in serilog config file, you won't get duplicate logs issue.

Example: { "Serilog": { ... "WriteTo": [ { "Name": "ApplicationInsights", "Args": { "connectionString": "[your connection string here]", "telemetryConverter": "Serilog.Sinks.ApplicationInsights.TelemetryConverters.TraceTelemetryConverter, Serilog.Sinks.ApplicationInsights" } } ], ... } Reference: https://github.com/serilog-contrib/serilog-sinks-applicationinsights#configuring-with-readfromconfiguration

Solution 2 (Serilog configuraion is in appsettings.json)

Reference: https://github.com/serilog/serilog-settings-configuration#serilogsettingsconfiguration--

1. Register SeriLog
.ConfigureAppConfiguration(builder =>
                {
                    var configuration = new ConfigurationBuilder()
                        .SetBasePath(Directory.GetCurrentDirectory())
                        .AddJsonFile("appsettings.json")
                        .AddEnvironmentVariables()
                        .Build();
                    Log.Logger = new LoggerConfiguration()
                        .ReadFrom.Configuration(configuration)
                        .CreateLogger();
                })
.UseSerilog();
  1. Set connection stringin local.settings.json file "SerilogWriteTo0ArgsconnectionString":"[your connection string here]"`

Solution 3

Create a cutom environment variable like CUSTOM_APPINSIGHTS_INSTRUMENTATIONKEY and use it with the following api.

services.AddApplicationInsightsTelemetryWorkerService("instrumentation key here");

Reference: https://learn.microsoft.com/en-us/azure/azure-monitor/app/worker-service#net-corenet-framework-console-application

For In-process

Solution 1

https://github.com/serilog/serilog-settings-configuration#azure-functions-v2-v3

References:

thatstatsguy commented 1 year ago

I've had a similar issue to what's been discussed above, but with Blazor application using the application insights sink.

Not sure where to post this, so posting here in the hope that someone else doesn't waste a couple hours.

Reproduction steps:

  1. Created a new application using dotnet new blazorserver
  2. As per the Serilog app insights README, I added the necessary details in Appsettings.Development.Json. 
    
{
"DetailedErrors": true,
"Logging": {
"LogLevel": {
  "Default": "Information",
  "Microsoft.AspNetCore": "Warning"
}
},
"Serilog": {
"Using": [
  "Serilog.Sinks.ApplicationInsights"
],
"MinimumLevel": {
  "Default": "Information",
  "Override": {
    "Microsoft": "Warning",
    "System": "Warning"
  }
},
"WriteTo": [
  {
    "Name": "Console"
  },
  {
    "Name": "File",
    "Args": {
      "path": "log.txt",
      "rollingInterval": "Day"
    }
  },
  {
    "Name": "ApplicationInsights",
    "Args": {
      "connectionString": "<INSERT CONNECTION STRING HERE>",
      "telemetryConverter":
      "Serilog.Sinks.ApplicationInsights.TelemetryConverters.TraceTelemetryConverter, Serilog.Sinks.ApplicationInsights"
    }
  }
],
"Enrich": [ "FromLogContext" ],
"Properties": {
  "Application": "Sample"
}
}

}


and added Serilog from configuration.
`builder.Host.UseSerilog((_, config) => config.ReadFrom.Configuration(builder.Configuration));`

3. It was at this point I first noticed the duplicate logs. In my scenario I was using the sample application to log an information trace each time the counter button was clicked.
4. Suggestions to remove the ILoggerProvider ([Link 1](https://stackoverflow.com/questions/74736764/im-getting-duplicate-traces-using-serilogs-application-insights-sink-and-appl) and corresponding [github issue](https://github.com/microsoft/ApplicationInsights-dotnet/issues/1310)) proved ineffective in resolving the issue.
5. A lot of trawling later and I stumbled on the [following issue](https://github.com/microsoft/ApplicationInsights-dotnet/issues/2509#issuecomment-1174864984). It turns out that certain diagnostic settings within the application insights can cause duplicates. This issue is further discussed [here](https://learn.microsoft.com/en-us/answers/questions/883344/application-insights-duplicate-telemetry) and [here](https://learn.microsoft.com/en-us/answers/questions/883344/application-insights-duplicate-telemetry).
6. The fix (for me) was switching switching off the `Send to Log Analytics workspace` diagnostic setting which can be found under `application insights > Monitoring > Diagnostic Settings > Standard Diagnostic Setting (the only option for me) > Edit Setting`. The details on the specific diagnostic setting to send were a bit hazy so I played around until I found what worked.

This is a non-code solution to my specific scenario, but hopefully this is an easy thing to rule out if you run into the same issues I have when trying to use Serilog in Azure!
renko7 commented 11 months ago

Duplicate logs issue occurs in Azure Functions when the following environment variables are used. These variables enable ApplicationInsights in the runtime host used by the Azure Functions service. The Azure Functions runtime builds upon the Azure WebJobs SDK to provide a hosting platform for functions. So you have to somehow bypass using these environment variables, if you want to use Serilog.Sinks.ApplicationInsights package with azure functions.

  • APPLICATIONINSIGHTS_CONNECTION_STRING
  • APPINSIGHTS_INSTRUMENTATIONKEY
  1. If you set one of these variables on local machine => Azure Functions Core Tools will enable ApplicationInsights.
  2. If you set one of these variables in Azure cloud environment => Azure Functions Host will enable ApplicationInsights.

If you check SDK version property in AppInsights logs.

For isolated worker process

Solution 1

If you set connection string or instrumentation key in serilog config file, you won't get duplicate logs issue.

Example: { "Serilog": { ... "WriteTo": [ { "Name": "ApplicationInsights", "Args": { "connectionString": "[your connection string here]", "telemetryConverter": "Serilog.Sinks.ApplicationInsights.TelemetryConverters.TraceTelemetryConverter, Serilog.Sinks.ApplicationInsights" } } ], ... } Reference: https://github.com/serilog-contrib/serilog-sinks-applicationinsights#configuring-with-readfromconfiguration

Solution 2 (Serilog configuraion is in appsettings.json)

Reference: https://github.com/serilog/serilog-settings-configuration#serilogsettingsconfiguration--

1. Register SeriLog
.ConfigureAppConfiguration(builder =>
                {
                    var configuration = new ConfigurationBuilder()
                        .SetBasePath(Directory.GetCurrentDirectory())
                        .AddJsonFile("appsettings.json")
                        .AddEnvironmentVariables()
                        .Build();
                    Log.Logger = new LoggerConfiguration()
                        .ReadFrom.Configuration(configuration)
                        .CreateLogger();
                })
.UseSerilog();
  1. Set connection stringin local.settings.json file"SerilogWriteTo0ArgsconnectionString":"[your connection string here]"`

Solution 3

Create a cutom environment variable like CUSTOM_APPINSIGHTS_INSTRUMENTATIONKEY and use it with the following api.

services.AddApplicationInsightsTelemetryWorkerService("instrumentation key here");

Reference: https://learn.microsoft.com/en-us/azure/azure-monitor/app/worker-service#net-corenet-framework-console-application

For In-process

Solution 1

https://github.com/serilog/serilog-settings-configuration#azure-functions-v2-v3

References:

This is a helpful solution, but it seems like if we remove the default host logger it prevents other telemetry types from being sent. Such as Request, Dependency, and Custom events. Do you have a workaround for that also?

renko7 commented 11 months ago

I seeing fixes where the recommendation is to remove the default Application Insights Logger but there are issues that can come with this. The biggest one that I can think of is that you no longer have the ability to send Request and Dependency events to AI. Is there really no way to tell the default Application Insights logger to stop sending trace events and leave that to serilog?

renko7 commented 11 months ago

@eldursi @fgheysels @middiu

An instance of ApplicationInsightsLoggerProvider is registered and used by the In-Process Azure Function Host using the LoggerProvider pattern to log to App Insights. This works fine until you want to log custom things to App Insights (using Serilog, etc) because by registering your custom App Insights provider, your loggers will now write to App Insights twice; once through the Azure Host registered logger provider and once through your custom logger provider.

To fix this, you could completely remove the Azure Host registered logger provider, but this removes all the nice, default metric/request/correlation capturing capabilities of Az Funcs + App Insights.

The working solution I have found is to register a custom LoggerFactory instance that contains all the registered logger providers except the App Insights logger provider registered by the Azure Function Host that also contains any custom provider that I want to use to log to App Insights.

Then, you can inject this LoggerFactory instance into your Function App class and create an ILogger instance that logs to App Insights only through your custom provider and still logs to all other providers and does not require you to remove the default App Insights logger provider completely. This way, you get the best of both worlds.

In this model, you would not register your custom logger provider with the ILoggerProvider interface since this would cause all ILogger instances directly resolved from the container to use both App Insights providers, leading to duplicate logs.

Startup Configure method:

builder.Services.AddSingleton((sp) =>
{
    Log.Logger = new LoggerConfiguration()
        .Enrich.With<ThrowContextEnricher>()
        .Enrich.FromLogContext()
        .WriteTo.ApplicationInsights(sp.GetRequiredService<TelemetryClient>(), TelemetryConverter.Traces)
        .CreateLogger();

    List<ILoggerProvider> providers = new
    (
        sp.GetServices<ILoggerProvider>()
          .Where(lp => lp.GetType().Name != "ApplicationInsightsLoggerProvider")
    )
    {
        new SerilogLoggerProvider(Log.Logger, true)
    };

    return new LoggerFactory(providers);
});

Function code:

private readonly ILogger _logger;

public AzFunc(LoggerFactory loggerFactory)
{
    _logger = loggerFactory.CreateLogger<AzFunc>();
}

[FunctionName("FuncName")]
public async Task FuncName([ServiceBusTrigger(ConstantStrings.TOPIC_NAME,
                                                ConstantStrings.SUBSCRIPTION_NAME,
                                                Connection = ConstantStrings.SB_CONN_STRING_VARIABLE_NAME)]string queueItem)
{
    _logger.LogInformation("info");
}

Interesting solution but this does not use Serilog for trace event logs