using AddSeq forces async on all MVC methods

[clarity99]

This is kinda strange to describe, but what happens is the following. I configure my ef core 3.1 db context as follows:

    public ILoggerFactory GetLoggerFactory()
    {
        IServiceCollection serviceCollection = new ServiceCollection();
        serviceCollection.AddLogging(builder =>
               builder.AddConsole().AddSeq("http://localhost:5341")
                      .AddFilter(DbLoggerCategory.Database.Command.Name,
                                 LogLevel.Information));
        return serviceCollection.BuildServiceProvider()
                .GetService<ILoggerFactory>();
    }

    protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    {
        if (!optionsBuilder.IsConfigured)
        {
            optionsBuilder.UseLoggerFactory(GetLoggerFactory()).UseLazyLoadingProxies().UseMySql(ConfigurationManager.ConnectionStrings["robRezervacije"].ConnectionString);
        }
    }

when I then use this context in the MVC method, I get this error if the method is not async:

An asynchronous operation cannot be started at this time. Asynchronous operations may only be started within an asynchronous handler or module or during certain events in the Page lifecycle. If this exception occurred while executing a Page, ensure that the Page is marked <%@ Page Async="true" %>. This exception may also indicate an attempt to call an "async void" method, which is generally unsupported within ASP.NET request processing. Instead, the asynchronous method should return a Task, and the caller should await it.

The call stack is at the EF core query (not async).

If I turn off Just My Code, I end up in Logger.cs: void LoggerLog(LogLevel logLevel, EventId eventId, ILogger logger, Exception exception, Func<TState, Exception, string> formatter, ref List<Exception> exceptions, in TState state) { try { logger.Log(logLevel, eventId, state, exception, formatter); The callstack goes to

Seq.Extensions.Logging.dll!Serilog.Extensions.Logging.SerilogLogger.Log<Microsoft.Extensions.Logging.LoggerMessage.LogValues<string, string, string, string>>(Microsoft.Extensions.Logging.LogLevel logLevel, Microsoft.Extensions.Logging.EventId eventId, Microsoft.Extensions.Logging.LoggerMessage.LogValues<string, string, string, string> state, System.Exception exception, System.Func<Microsoft.Extensions.Logging.LoggerMessage.LogValues<string, string, string, string>, System.Exception, string> formatter) Unknown

Is this an expected behaviour?

If I change the MVC method to async, it works fine (even if I don't use any async ef core methods)

[nblumhardt]

Hi! I can find one possible place this might be triggered:

https://github.com/datalust/seq-extensions-logging/blob/dev/src/Seq.Extensions.Logging/Serilog/Sinks/PeriodicBatching/PeriodicBatchingSink.cs#L232

When the very first event passes through the Seq logger, it will kick of an async operation via PortableTimer.

To check whether this is the cause, when your application starts up (ideally immediately upon configuring logging) you can try sending an event through the logger (just a logger.LogInformation() (or warning) in Startup.cs, if there's a suitable place to do it.

If the problem is as I suspect, subsequent calls should succeed because the Seq logger will already be initialized and events will be enqueued for the background thread to process.

Keen to hear how you go!

[clarity99]

tried that, but does not seem to be helping. It is quite strange, the calls don't return this error on every call, but it does happen more often than not. Does this portabletimer start the async operation on every instance? or just once per lifetime of the app?

[nblumhardt]

Ah, I see how this would be a problem. The Seq logger should effectively be a singleton - constructing a new one for every DBContext will lead to new sinks, timers, etc. being created each time. This is relatively expensive and won't support load well, so it's a worthwhile change to make regardless of the async execution issue.

With the logger set up as a single instance, the workaround in the comment further above should have the desired effect.

[clarity99]

Hm, I'm not quite sure how to set up the logger as a single instance. What I have is the following:

   ```public ILoggerFactory GetLoggerFactory()
    {
        IServiceCollection serviceCollection = new ServiceCollection();
        serviceCollection.AddLogging(builder =>
               builder.AddConsole().AddSeq("http://seq:5341")
                      .AddFilter(DbLoggerCategory.Database.Command.Name,
                                 LogLevel.Information));
        return serviceCollection.BuildServiceProvider()
                .GetService<ILoggerFactory>();
    }
    public void ConfigureServices(IServiceCollection services)
    {

         services.AddLogging(loggingBuilder =>
        {
            loggingBuilder.SetMinimumLevel(LogLevel.Debug);
            loggingBuilder.AddSeq("http://seq:5341");
        });
        services.AddDbContext<robrezervacijeContext>(options =>options.UseLoggerFactory(GetLoggerFactory()).UseLazyLoadingProxies().EnableSensitiveDataLogging().UseMySql(ConfigurationManager.ConnectionStrings["robRezervacije"].ConnectionString)
        );

I guess LoggerFactory should somehow return the instance that is configured in ConfigureServices... I'm probably overcomplicating this a bit :)

[clarity99]

Ah, I've figured it out. This works just fine:

services.AddLogging(loggingBuilder =>
            {
                loggingBuilder.SetMinimumLevel(LogLevel.Debug);
                loggingBuilder.AddSeq("http://seq:5341").AddFilter(DbLoggerCategory.Database.Command.Name,
                                     LogLevel.Information);
            });
            services.AddDbContext<robrezervacijeContext>(options =>
              options.UseLazyLoadingProxies().EnableSensitiveDataLogging().UseMySql(ConfigurationManager.ConnectionStrings["robRezervacije"].ConnectionString)
            );