ApplicationInsights-dotnet icon indicating copy to clipboard operation
ApplicationInsights-dotnet copied to clipboard

Flush/Wait at the end of the process

Open drauch opened this issue 2 years ago • 11 comments

In https://docs.microsoft.com/en-us/azure/azure-monitor/app/worker-service#net-corenet-framework-console-application it says that console applications should use a combination of Flush/Wait at the end of the program to ensure all log statements have been properly sent to the server.

Two questions regarding this:

  1. This is only necessary for console applications? Hosted services and ASP.NET Core web apps do not need to do this?
  2. Is there no better way than the Flush/Wait combination? It looks like it is a) flaky, because sometimes the 5 seconds might not be enough time and b) unnecessary long in most cases where the remaining HTTP requests might only take some milliseconds.

Best regards, D.R.

drauch avatar Mar 28 '22 08:03 drauch

We're working on doc improvements to clearly describe flushing recommendations.

If you're using the latest version of the SDK, you can await FlushAsync()

TimothyMothra avatar Mar 28 '22 17:03 TimothyMothra

So you're saying in console applications we should use FlushAsync() instead and it waits just as much as it absolutely needs to?

What about other types of applications, do we need any manual code for ASP.NET Core web apps as well or does it happen automagically if you use the correct registration techniques for ASP.NET Core web apps? And "hosted services"?

drauch avatar Mar 28 '22 17:03 drauch

Ping, any more on this? Do we need to call FlushAsync also in non-console applications? ASP.NET Core web apps or ASP.NET core hosted services?

drauch avatar Apr 26 '22 12:04 drauch

Current guidance: https://docs.microsoft.com/en-us/azure/azure-monitor/app/api-custom-events-metrics#flushing-data

pizzaz93 avatar May 03 '22 17:05 pizzaz93

It's a pity that this doesn't happen automagically somehow.

drauch avatar May 05 '22 09:05 drauch

This issue is stale because it has been open 300 days with no activity. Remove stale label or this will be closed in 7 days. Commenting will instruct the bot to automatically remove the label.

github-actions[bot] avatar Mar 02 '23 00:03 github-actions[bot]

Is this something that could be taken into consideration as a feature request for a future version?

Best regards, D.R.

drauch avatar Mar 02 '23 07:03 drauch

This issue is stale because it has been open 300 days with no activity. Remove stale label or this will be closed in 7 days. Commenting will instruct the bot to automatically remove the label.

github-actions[bot] avatar Dec 29 '23 00:12 github-actions[bot]

Not stale. Thanks for pointing to the improved docs, but can't this mechanism be improved? And what about the OP's question about whether this is also necessary in ASP.NET Core applications and hosted services?

fschmied avatar Dec 29 '23 15:12 fschmied

I've now learned that the ApplicationInsightsLoggerProvider will automatically flush on Dispose, but without the sleeping (link): image

So if this was changed to DisposeAsync and FlushAsync (or if Flush could itself wait until the flushing is done), I guess it would solve the problem in all applications that use the Application Insights/Microsoft.Extensions.Logging integration (i.e., most .NET Core applications, unless they use a custom logging solution).

fschmied avatar Jan 12 '24 10:01 fschmied

Hey everybody,

yesterday, I also stumbled upon this problem that apps, no matter whether they are ASP.NET Core based or not, will not send out all telemetry messages that are held in the buffer during shutdown. At the time of writing, we need to explicitly call TelemetryClient.FlushAsync during shutdown to not lose data (especially log messages).

Reproducing the issue

For a Minimal Complete Verifiable Example (MCVE), I created this small ASP.NET Core 8 app:

<Project Sdk="Microsoft.NET.Sdk.Web">

    <PropertyGroup>
        <TargetFramework>net8.0</TargetFramework>
        <Nullable>enable</Nullable>
    </PropertyGroup>
    
    <ItemGroup>
        <PackageReference Include="Microsoft.ApplicationInsights.AspNetCore" Version="2.22.0" />
    </ItemGroup>

</Project>
using System.Threading.Tasks;
using Microsoft.AspNetCore.Builder;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Logging;

namespace AppInsightsTest;

public sealed class Program
{
    public static async Task Main(string[] args)
    {
        var builder = WebApplication.CreateBuilder(args);
        builder
           .Services
           .AddApplicationInsightsTelemetry();
        var app = builder.Build();

        await app.StartAsync();
        try
        {
            var logger = app.Services.GetRequiredService<ILogger<Program>>();
            logger.LogDebug("Test Debug");
            logger.LogInformation("Test Info");
            logger.LogWarning("Test Warning");
            logger.LogError("Test Error");
            logger.LogCritical("Test Critical");
        }
        finally
        {
            await app.StopAsync();
            await app.DisposeAsync();
        }
    }
}
{
    "Logging": {
        "LogLevel": {
            "Default": "Information"
        },
        "ApplicationInsights": {
            "LogLevel": {
                "Default": "Information"
            }
        }
    },
    "AllowedHosts": "*"
}

The App Insights Connection string is specified via user secrets or environment variables.

According to this setup, the LogDebug call should be completely omitted, but I should see the Information, Warning, Error, and Critical messages (besides some additional Microsoft.Hosting.Lifetime log messages) both on the console and on App Insights.

What I observed

Testing this several times, I see the following behavior:

Inconsistent delivery of log messages to App Insights

  • When you run the app for the first time, usually all log messages go through. This is problematic because devs that only test this behavior once will think that it just works.
  • On subsequent executions, I observed that no log messages were actually transmittted, unless WebApplication.DisposeAsync is called. This makes sense because the logging provider for App Insights flushes synchronously during dispose but doesn't wait. However, I still lose messages in this scenario because of this and by default, apps don't call DisposeAsync on the WebApplication project.
  • Only introducing await app.Services.GetRequiredService<TelemetryClient>().FlushAsync(default); ensures that all messages are transmitted to App Insights.

A possible solution?

Is it possible that we introduce an ASP.NET Core Hosted Service which simply calls TelemetryClient.FlushAsync? An implementation could look like this:

public sealed class FlushTelemetryClientHostedService : IHostedService
{
    private readonly TelemetryClient _telemetryClient;

    public FlushTelemetryClientHostedService(TelemetryClient telemetryClient)
    {
        _telemetryClient = telemetryClient;
    }
    
    public Task StartAsync(CancellationToken cancellationToken) => Task.CompletedTask;

    public Task StopAsync(CancellationToken cancellationToken) =>
        _telemetryClient.FlushAsync(cancellationToken);
}

When the app is shut down, this hosted service could simply flush the telemetry client. Maybe we would want to add some error handling to the StopAsync method, but this could solve the issue in my opinion. This hosted service could be registered with the DI container when AddApplicationInsightsTelemetry executes.

feO2x avatar Apr 03 '24 06:04 feO2x