I have a .Net Core 2.2 web app that uses the out-of-the-box ILogger to log information about the application. When debugging locally the information is logged as expected in the debug console. However, when the application is deployed to Azure as an App Service, the log entries are duplicated when viewed in the Azure LogStream.
On the Azure portal, Asp.Net Core Logging Extensions (v 2.2.0) is installed
This is the code(c#) where the logging is done in my web app
public class MyService : BackgroundService
{
private readonly ILogger<MyService> _logger;
public MyService(ILogger<MyService> logger)
{
_logger = logger;
}
protected override Task ExecuteAsync(CancellationToken stoppingToken)
{
_logger.Log(LogLevel.Information, "The service task is starting.");
var count = 0;
while (!stoppingToken.IsCancellationRequested)
{
_logger.Log(LogLevel.Information, $"The service task is doing background work. count is: {count}. Hashcode is: {_logger.GetHashCode()} on thread: {Thread.CurrentThread.ManagedThreadId}");
// some background work
count++;
Task.Delay(60000, stoppingToken).GetAwaiter().GetResult();
}
_logger.Log(LogLevel.Information, "The service task is terminating.");
return (Task.FromResult<object>(null));
}
}
The logging is configured like this in program.cs file
public static IWebHost BuildWebHost(string[] args)
{
return WebHost.CreateDefaultBuilder(args)
.CaptureStartupErrors(true)
.UseSetting(WebHostDefaults.DetailedErrorsKey, "true")
.ConfigureLogging((logging) =>
{
logging.AddAzureWebAppDiagnostics();
})
.UseStartup<Startup>()
.Build();
}
This is the backgroundservice from the nuget package: microsoft.extensions.hosting.abstractions\2.1.0
namespace Microsoft.Extensions.Hosting
{
public abstract class BackgroundService : IHostedService, IDisposable
{
protected BackgroundService();
public virtual void Dispose();
// more methods
}
}
Adding MyService to the Services collection
public class Startup
{
private readonly ILoggerFactory _loggerFactory;
private readonly ILogger _logger;
private readonly ILogger _startupLogger;
public Startup(IConfiguration configuration, ILoggerFactory loggerFactory)
{
Configuration = configuration;
_loggerFactory = loggerFactory;
_logger = _loggerFactory.CreateLogger("GlobalException");
_startupLogger = _loggerFactory.CreateLogger(typeof(Startup));
}
public IConfiguration Configuration { get; }
public void ConfigureServices(IServiceCollection services)
{
_startupLogger.LogInformation($"Adding common services");
services.AddCommonServices(Configuration, _logger);
}
}
public static class ServiceCollectionExtensions
{
public static IServiceCollection AddCommonServices(this IServiceCollection services, IConfiguration configuration, ILogger logger)
{
services.AddMvc(options =>
{
options.Filters.Add(new ExceptionFilter(logger));
})
services.AddSingleton<IHostedService, MyService>();
return services;
}
}
This is the exception filter
public class ExceptionFilter : ExceptionFilterAttribute
{
private readonly ILogger _logger;
public ExceptionFilter(ILogger logger)
{
_logger = logger;
}
public override void OnException(ExceptionContext context)
{
_logger.LogInformation("There was an error processing your request.");
base.OnException(context);
}
}
In the Azure LogStream I was expecting a single line of output per task cycle like this: 2019-06-27 08:36:25.488 +00:00 [Information] MyService: Deferred background service task is doing background work. count is: 3. Hashcode is: 61705107 on thread: 1
But I am getting three duplicates like this:
2019-06-27 08:36:25.488 +00:00 [Information] MyService: The service task is doing background work. count is: 3. Hashcode is: 61705107 on thread: 1
2019-06-27 08:36:25.482 +00:00 [Information] MyService: The service task is doing background work. count is: 3. Hashcode is: 61705107 on thread: 1
2019-06-27 08:36:25.224 +00:00 [Information] MyService: The service task is doing background work. count is: 3. Hashcode is: 61705107 on thread: 1
