Open Closed

Occasional Errors after Implementing Redis Cache #3569


0
jackmcelhinney created
  • ABP Framework version: v5.3.3
  • UI type: Angular
  • DB provider: EF Core
  • Identity Server Separated (Angular): no

After configuring our project to use the Redis Cache, we are getting occasional errors (once or twice a day) logged in the background. Based on the traces, it appears this may be happening in the SettingManagement module after the cache tries to refresh.

Usually 1 warning and 3 errors get logged at the same time:

Warning: The operation was canceled. Exception:

System.OperationCanceledException: The operation was canceled.     at System.Threading.CancellationToken.ThrowOperationCanceledException()     at Volo.Abp.Caching.StackExchangeRedis.AbpRedisCache.GetAndRefreshManyAsync(IEnumerable`1 keys, Boolean getData, CancellationToken token)     at Volo.Abp.Caching.StackExchangeRedis.AbpRedisCache.GetManyAsync(IEnumerable`1 keys, CancellationToken token)     at Volo.Abp.Caching.DistributedCache`2.GetManyAsync(IEnumerable`1 keys, Nullable`1 hideErrors, Boolean considerUow, CancellationToken token)

Properties:

<properties><property key='SourceContext'>Volo.Abp.Caching.DistributedCache</property><property key='ActionId'>15fe26d2-905e-451e-956e-9273e2ee2f29</property><property key='ActionName'>Volo.Abp.AspNetCore.Mvc.ApplicationConfigurations.AbpApplicationConfigurationScriptController.Get (Volo.Abp.AspNetCore.Mvc)</property><property key='RequestId'>0HMJE86AB1IHV:00000063</property><property key='RequestPath'>/Abp/ApplicationConfigurationScript</property><property key='ConnectionId'>0HMJE86AB1IHV</property><property key='CorrelationId'>50d2b898ed494793b23a9d6d5f6f5da3</property></properties>

Error: An error occurred using the connection to database '{database}' on server '{server}'. Exception: NULL Properties:

<properties><property key='database'>test-web-db</property><property key='server'>tcp:redis-test.database.windows.net,1433</property><property key='EventId'><structure type=''><property key='Id'>20004</property><property key='Name'>Microsoft.EntityFrameworkCore.Database.Connection.ConnectionError</property></structure></property><property key='SourceContext'>Microsoft.EntityFrameworkCore.Database.Connection</property><property key='ActionId'>15fe26d2-905e-451e-956e-9273e2ee2f29</property><property key='ActionName'>Volo.Abp.AspNetCore.Mvc.ApplicationConfigurations.AbpApplicationConfigurationScriptController.Get (Volo.Abp.AspNetCore.Mvc)</property><property key='RequestId'>0HMJE86AB1IHV:00000063</property><property key='RequestPath'>/Abp/ApplicationConfigurationScript</property><property key='ConnectionId'>0HMJE86AB1IHV</property><property key='CorrelationId'>50d2b898ed494793b23a9d6d5f6f5da3</property></properties>

Error: An exception occurred while iterating over the results of a query for context type '{contextType}'.{newline}{error} Exception:

System.Threading.Tasks.TaskCanceledException: A task was canceled.     at Microsoft.EntityFrameworkCore.Storage.RelationalConnection.OpenInternalAsync(Boolean errorsExpected, CancellationToken cancellationToken)     at Microsoft.EntityFrameworkCore.Storage.RelationalConnection.OpenInternalAsync(Boolean errorsExpected, CancellationToken cancellationToken)     at Microsoft.EntityFrameworkCore.Storage.RelationalConnection.OpenAsync(CancellationToken cancellationToken, Boolean errorsExpected)     at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)     at Microsoft.EntityFrameworkCore.Query.Internal.SplitQueryingEnumerable`1.AsyncEnumerator.InitializeReaderAsync(AsyncEnumerator enumerator, CancellationToken cancellationToken)     at Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func`4 operation, Func`4 verifySucceeded, CancellationToken cancellationToken)     at Microsoft.EntityFrameworkCore.Query.Internal.SplitQueryingEnumerable`1.AsyncEnumerator.MoveNextAsync()

Properties:

<properties><property key='contextType'>Volo.Abp.SettingManagement.EntityFrameworkCore.SettingManagementDbContext</property><property key='newline'>  </property><property key='error'>System.Threading.Tasks.TaskCanceledException: A task was canceled.     at Microsoft.EntityFrameworkCore.Storage.RelationalConnection.OpenInternalAsync(Boolean errorsExpected, CancellationToken cancellationToken)     at Microsoft.EntityFrameworkCore.Storage.RelationalConnection.OpenInternalAsync(Boolean errorsExpected, CancellationToken cancellationToken)     at Microsoft.EntityFrameworkCore.Storage.RelationalConnection.OpenAsync(CancellationToken cancellationToken, Boolean errorsExpected)     at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)     at Microsoft.EntityFrameworkCore.Query.Internal.SplitQueryingEnumerable`1.AsyncEnumerator.InitializeReaderAsync(AsyncEnumerator enumerator, CancellationToken cancellationToken)     at Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func`4 operation, Func`4 verifySucceeded, CancellationToken cancellationToken)     at Microsoft.EntityFrameworkCore.Query.Internal.SplitQueryingEnumerable`1.AsyncEnumerator.MoveNextAsync()</property><property key='EventId'><structure type=''><property key='Id'>10100</property><property key='Name'>Microsoft.EntityFrameworkCore.Query.QueryIterationFailed</property></structure></property><property key='SourceContext'>Microsoft.EntityFrameworkCore.Query</property><property key='ActionId'>15fe26d2-905e-451e-956e-9273e2ee2f29</property><property key='ActionName'>Volo.Abp.AspNetCore.Mvc.ApplicationConfigurations.AbpApplicationConfigurationScriptController.Get (Volo.Abp.AspNetCore.Mvc)</property><property key='RequestId'>0HMJE86AB1IHV:00000063</property><property key='RequestPath'>/Abp/ApplicationConfigurationScript</property><property key='ConnectionId'>0HMJE86AB1IHV</property><property key='CorrelationId'>50d2b898ed494793b23a9d6d5f6f5da3</property></properties>

Error: An unhandled exception has occurred while executing the request. Exception:

System.Threading.Tasks.TaskCanceledException: A task was canceled.     at Microsoft.EntityFrameworkCore.Storage.RelationalConnection.OpenInternalAsync(Boolean errorsExpected, CancellationToken cancellationToken)     at Microsoft.EntityFrameworkCore.Storage.RelationalConnection.OpenInternalAsync(Boolean errorsExpected, CancellationToken cancellationToken)     at Microsoft.EntityFrameworkCore.Storage.RelationalConnection.OpenAsync(CancellationToken cancellationToken, Boolean errorsExpected)     at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)     at Microsoft.EntityFrameworkCore.Query.Internal.SplitQueryingEnumerable`1.AsyncEnumerator.InitializeReaderAsync(AsyncEnumerator enumerator, CancellationToken cancellationToken)     at Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func`4 operation, Func`4 verifySucceeded, CancellationToken cancellationToken)     at Microsoft.EntityFrameworkCore.Query.Internal.SplitQueryingEnumerable`1.AsyncEnumerator.MoveNextAsync()     at Microsoft.EntityFrameworkCore.EntityFrameworkQueryableExtensions.ToListAsync[TSource](IQueryable`1 source, CancellationToken cancellationToken)     at Microsoft.EntityFrameworkCore.EntityFrameworkQueryableExtensions.ToListAsync[TSource](IQueryable`1 source, CancellationToken cancellationToken)     at Volo.Abp.SettingManagement.EntityFrameworkCore.EfCoreSettingRepository.GetListAsync(String[] names, String providerName, String providerKey, CancellationToken cancellationToken)     at Castle.DynamicProxy.AsyncInterceptorBase.ProceedAsynchronous[TResult](IInvocation invocation, IInvocationProceedInfo proceedInfo)     at Volo.Abp.Castle.DynamicProxy.CastleAbpMethodInvocationAdapterWithReturnValue`1.ProceedAsync()     at Volo.Abp.Uow.UnitOfWorkInterceptor.InterceptAsync(IAbpMethodInvocation invocation)     at ...

Properties:

<properties><property key='EventId'><structure type=''><property key='Id'>1</property><property key='Name'>UnhandledException</property></structure></property><property key='SourceContext'>Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddleware</property><property key='RequestId'>0HMJE86AB1IHV:00000063</property><property key='RequestPath'>/Abp/ApplicationConfigurationScript</property><property key='ConnectionId'>0HMJE86AB1IHV</property></properties>

I am able to reproduce this issue in a fresh project:

  • Create new project
  • Update appsettings
  • Update Application module to configure caching
[DependsOn(
    ...
    typeof(AbpCachingModule),
    typeof(AbpCachingStackExchangeRedisModule)
)]

...

Configure<AbpDistributedCacheOptions>(options =>
{
    //options.KeyPrefix = configuration["Redis:KeyPrefix"];
});
  • Optionally log to db table

Domain object:

public class Log : Entity<int>
{
    public string Message { get; set; }
    public string MessageTemplate { get; set; }
    public string Level { get; set; }
    public DateTime? Timestamp { get; set; }
    public string Exception { get; set; }
    public string Properties { get; set; }
}

DbContext:

public DbSet<Log> Logs { get; set; }
...
builder.Entity<Log>(b =>
{
    b.ToTable(RedisTestConsts.DbTablePrefix + "Logs", RedisTestConsts.DbSchema);
    b.ConfigureByConvention();

    b.Property(x => x.Message);
    b.Property(x => x.MessageTemplate);
    b.Property(x => x.Level);
    b.Property(x => x.Timestamp);
    b.Property(x => x.Exception);
    b.Property(x => x.Properties);
});

Program.cs

...
builder.Host
    .AddAppSettingsSecretsJson()
    .UseAutofac()
    .UseSerilog(
    (hostingContext, services, loggerConfiguration) => loggerConfiguration

        .MinimumLevel.Debug()

        .MinimumLevel.Override("Microsoft", LogEventLevel.Information)
        .Enrich.FromLogContext()

        .WriteTo.Async(c => c.File("Logs/logs.txt"))


        .AuditTo.MSSqlServer(
            connectionString: hostingContext.Configuration["ConnectionStrings:Default"],
            sinkOptions: new MSSqlServerSinkOptions()
            {
                TableName = "AppLogs"
            },
            restrictedToMinimumLevel: LogEventLevel.Warning)
    );
...
  • Run the app, log in, and click around to get everything cached.
  • Leave the API project running and eventually these errors will be logged.

Other information:

  • DB: Azure SQL Server Database
  • Redis Cache: Azure Cache for Redis - Standard 250 MB

I'm not sure if there is impact on the user when this happens, but we have alerting on errors so we would like to resolve these even if there is no user impact. Please let me know if you have any ideas or need more information.


4 Answer(s)
  • 0
    maliming created
    Support Team

    hi

    Maybe some requests were canceled. Such as requesting a page and then closing it. Maybe some ajax or http requests were canceled

    You can ignore it and keep watching the logs.

  • 0
    jackmcelhinney created

    I don't think this is related to user requests cancelling, because this happens consistently every few hours even in the test project running locally with no user interaction and the API idling.

    I now believe there is an impact on users when this happens, as I was on our site and got a service unavailable error for a few seconds at the same time these errors were logged. The errors are always in SettingManagement so it seems like there's an issue in that module handling cancellation or cache refreshes.

  • 0
    jackmcelhinney created

    Possibly related to this? https://github.com/abpframework/abp/issues/4272

  • 0
    maliming created
    Support Team

    I still suggest you ignore it for now. We will do some review.