Exception while emitting periodic batch from Serilog.Sinks.Seq.Durable.HttpLogShipper

[sspl-vssaini]

I'm not exactly sure if this is the right place to post or not. But it is an issue.

We have configured the Serilog logger below way in the main project -

using Microsoft.AspNetCore.Hosting;
using Microsoft.Extensions.Configuration;
using Microsoft.Extensions.Hosting;
using Serilog;
using Serilog.Debugging;
using System;
using System.Diagnostics;
using System.IO;

namespace AppNameHere
{
    public class Program
    {
        private static string _basePath;

        public static void Main(string[] args)
        {
            try
            {
                _basePath = Directory.GetCurrentDirectory();

                EnableSerilogSelfLogging();

                var aspNetCoreEnv = Environment.GetEnvironmentVariable("ASPNETCORE_ENVIRONMENT") ?? "Production";
                var configuration = new ConfigurationBuilder()
                    .SetBasePath(Directory.GetCurrentDirectory())
                    .AddJsonFile("appsettings.json", false, true)
                    .AddJsonFile($"appsettings.{aspNetCoreEnv}.json", optional: true)
                    .AddEnvironmentVariables()
                    .Build();

                Log.Logger = new LoggerConfiguration()
                    .ReadFrom.Configuration(configuration)
                    .Enrich.FromLogContext()
                    .Enrich.WithProperty("ApplicationName", typeof(Program).Assembly.GetName().Name)
                    .CreateLogger();

                Log.Information("Application starting up");
                CreateHostBuilder(args).Build().Run();
                Log.Information("Application shutting down");
            }
            catch (Exception exc)
            {
                // Log.Logger will likely be internal type "Serilog.Core.Pipeline.SilentLogger".
                if (Log.Logger == null || Log.Logger.GetType().Name == "SilentLogger")
                {
                    // Loading configuration or Serilog failed.
                    // This will create a logger that can be captured by Azure logger.
                    // To enable Azure logger, in Azure Portal:
                    // 1. Go to WebApp
                    // 2. App Service logs
                    // 3. Enable "Application Logging (Filesystem)", "Application Logging (Filesystem)" and "Detailed error messages"
                    // 4. Set Retention Period (Days) to 10 or similar value
                    // 5. Save settings
                    // 6. Under Overview, restart web app
                    // 7. Go to Log Stream and observe the logs

                    Log.Logger = new LoggerConfiguration()
                        .MinimumLevel.Debug()
                        .WriteTo.Console()
                        .CreateLogger();
                }

                Log.Fatal(exc, "The application failed to start correctly.");
            }
            finally
            {
                Log.CloseAndFlush();
            }
        }

        /// <summary>
        /// Enable self logging messages for Serilog internal failures.
        /// </summary>
        private static void EnableSerilogSelfLogging()
        {
            try
            {
                var seqPath = $"{_basePath}\\Serilog\\SerilogInternalErrors.log";

                // Ref - https://stackoverflow.com/a/52772077/1041457
                SelfLog.Enable(msg => File.AppendAllText(seqPath, msg));
            }
            catch (Exception exc)
            {
                // Error can be seen from Azure Log Stream
                Trace.TraceError(exc.Message);
            }
        }

        private static IHostBuilder CreateHostBuilder(string[] args)
        {
            return Host.CreateDefaultBuilder(args)
                .UseSerilog()
                .ConfigureWebHostDefaults(webBuilder =>
                {
                    // By default uses TLS 1.1 and TLS 1.2
                    webBuilder.UseStartup<Startup>();
                });
        }
    }
}

Below is the configuration in appsettings.json

 "Serilog": {
    "Using": [ "Serilog.Expressions" ],
    "LevelSwitches": {
      "$appLogLevel": "Information",
      "$seqSwitch": "Information",
      "$fileSwitch": "Information"
    },
    "MinimumLevel": {
      "ControlledBy": "$appLogLevel",
      "Override": {
        "System": "Warning",
        "Microsoft": "Warning",
        "Microsoft.EntityFrameworkCore": "Warning",
        "Microsoft.AspNetCore.SignalR": "Warning",
        "Microsoft.AspNetCore.Http.Connections": "Warning",
        "Hangfire": "Warning"
      }
    },
    "Enrich": [ "FromLogContext", "WithEnvironmentName", "WithMachineName", "WithThreadId", "WithClientIp" ],
    "WriteTo": [
      {
        "Name": "Seq",
        "Args": {
          "levelSwitch": "$seqSwitch",
          "apiKey": "someKeyHere",
          "serverUrl": "https://seqUrlOnAzure.azurewebsites.net",
          "bufferBaseFilename": "Serilog\\bufferFile",
          "outputTemplate": "{Timestamp:HH:mm:ss} [{Level:u3}] {Message}{NewLine}{Exception}"
        }
      },
      {
        "Name": "File",
        "Args": {
          "levelSwitch": "$fileSwitch",
          "path": "D:\\home\\LogFiles\\Application\\AppNameHereLog-.txt", // Write to Azure Diagnostics Log Stream
          "formatter": "Serilog.Formatting.Compact.CompactJsonFormatter, Serilog.Formatting.Compact",
          "rollingInterval": "Day",
          "rollOnFileSizeLimit": true,
          "shared": true,
          "flushToDiskInterval": "00:00:01"
        }
      }
    ],
    "Filter": [
      {
        "Name": "ByExcluding",
        "Args": {
          "expression": "RequestPath like '/syncProgress%'"
        }
      },
      {
        "Name": "ByExcluding",
        "Args": {
          "expression": "RequestPath like '/Hangfire%'"
        }
      },
      {
        "Name": "ByExcluding",
        "Args": {
          "expression": "RequestPath like '/hangfire%'"
        }
      }
    ]
  }

In another project, I am logging from various service classes and here is code -

public class LogService : ILogService
    {
        private readonly ILogger _logger;

        public LogService()
        {
            _logger = Log.Logger;
        }        

        public void LogInformation(string messageTemplate, Guid companyUid, Guid userUid, params object[] propertyValues)
        {
            using (LogContext.PushProperty("CompanyUid", companyUid))
            using (LogContext.PushProperty("UserUid", userUid))
            {
                _logger.Information(messageTemplate, propertyValues);
            }
        }
    }

So, a few of our logs frequently get skip. When I check the SerilogInternalErrors.log file as in the screenshot

,

I found the repetition of the below error logs with the file name being changed

Exception while emitting periodic batch from Serilog.Sinks.Seq.Durable.HttpLogShipper: System.IO.IOException: The process cannot access the file 'D:\home\site\wwwroot\Serilog\bufferFile-20211015.clef' because it is being used by another process.

Now, I believe I am using Serilog logger with a Singleton pattern. But I think for some reason the Serilog logger is being used by multiple threads and that's causing the issue.

Can you please suggest a solution for this or if I am doing something wrong?

[nblumhardt]

Hi @sspl-vssaini, thanks for dropping by.

I would guess that multiple independent processes are running concurrently; the durable log shipping mechanism requires that only one process at a time touches the file set. How are you deploying/hosting the app? Azure App Service?

[sspl-vssaini]

Hi @nblumhardt

Yes! I too believe that's happening. Since we are using Hangfire for creating jobs, and those jobs execute methods from services. These jobs can/will/might run in parallel or together at a time.

Here is a sample code to give an idea about our case -

public class PService : IPService
{
    private readonly ILogService _logService;        

    public PService(ILogService logService)
    {
        _logService = logService;
    }

    // Method that will be run by Hangfire job
    public async Task GetEmployees()
    {
        // Code removed for brevity

        var employees = GetEmployeesFromCompany("Company A");
    }

    // Method that will be run by another Hangfire job
    public async Task CreateEmployees()
    {
        // Code removed for brevity

        var employees = await CreateEmployeesInCompany("Company A");
    }

    private async Task<List<Employee>> GetEmployeesFromCompany(string companyName)
    {
        Guid companyUid= Guid.Empty;
        Guid userUid = Guid.Empty;

        _logService.LogInformation("Fetching employees from company {CompanyName}",companyUid, userUid, companyName);

        // Assume some long-running task here
    }

    private async Task<List<Employee>> CreateEmployeesInCompany(string companyName)
    {
        Guid companyUid= Guid.Empty;
        Guid userUid = Guid.Empty;        

        _logService.LogInformation("Creating employees in company {CompanyName}",companyUid, userUid, companyName);

        // Assume some long-running task here
    }
}

So what's the recommendation for such a case?

We are using Continuous Deployment for our Azure AppService.

[sspl-vssaini]

@nblumhardt

Can you please provide any hint or anything that I can look into for resolving this issue?

[nblumhardt]

Using direct HTTP, rather than buffering, seems like the more reliable option in the kind of hosting environment you're describing.

[sspl-vssaini]

Eventually, it was an issue caused by the Hangfire configuration.

I read from https://github.com/HangfireIO/Hangfire/issues/697#issuecomment-255574396 where the author suggested

I'd also like to highly discourage you from using static job managers (RecurringJob.AddOrUpdate, BackgroundJob.Enqueue) and GlobalConfiguration in .NET Core.

GlobalConfiguration methods excessively use static properties for storing configured values (e.g. JobActivator.Current, JobStorage.Current etc.). Static classes from above know nothing about DI, and create their own non-DI instances of clients. Which would only be half bad if Hangfire.AspNetCore bootstrapper not registered those static configuration properties as singletone services!

So some service instances could already be activated with configured values (for instance, JobActivator from your example), and then you call .UseActivator(new DotNetCoreActivator(serviceProvider)); and change JobActivator.Current for those non-DI instantiates, while DI ones will continue using the old one.

It is a mess :)

So you'd better avoid using those static methods at all, and better use IRecurringJobManager and IBackgroundJobClient from DI. And configure everything (including activator and database connection) inside AddHangfire() callback in ConfigureServices, while it hasn't started creating DI services yet.

And I was using these all static methods. So, I started using IBackgroundJobClient and IRecurringJobManager and the issue got resolved.