Occasional Errors after Implementing Redis Cache #3569

jackmcelhinney created 2 years ago

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:

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

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

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

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:

&lt;properties&gt;&lt;property key=&#39;contextType&#39;&gt;Volo.Abp.SettingManagement.EntityFrameworkCore.SettingManagementDbContext&lt;/property&gt;&lt;property key=&#39;newline&#39;&gt;  &lt;/property&gt;&lt;property key=&#39;error&#39;&gt;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()&lt;/property&gt;&lt;property key=&#39;EventId&#39;&gt;&lt;structure type=&#39;&#39;&gt;&lt;property key=&#39;Id&#39;&gt;10100&lt;/property&gt;&lt;property key=&#39;Name&#39;&gt;Microsoft.EntityFrameworkCore.Query.QueryIterationFailed&lt;/property&gt;&lt;/structure&gt;&lt;/property&gt;&lt;property key=&#39;SourceContext&#39;&gt;Microsoft.EntityFrameworkCore.Query&lt;/property&gt;&lt;property key=&#39;ActionId&#39;&gt;15fe26d2-905e-451e-956e-9273e2ee2f29&lt;/property&gt;&lt;property key=&#39;ActionName&#39;&gt;Volo.Abp.AspNetCore.Mvc.ApplicationConfigurations.AbpApplicationConfigurationScriptController.Get (Volo.Abp.AspNetCore.Mvc)&lt;/property&gt;&lt;property key=&#39;RequestId&#39;&gt;0HMJE86AB1IHV:00000063&lt;/property&gt;&lt;property key=&#39;RequestPath&#39;&gt;/Abp/ApplicationConfigurationScript&lt;/property&gt;&lt;property key=&#39;ConnectionId&#39;&gt;0HMJE86AB1IHV&lt;/property&gt;&lt;property key=&#39;CorrelationId&#39;&gt;50d2b898ed494793b23a9d6d5f6f5da3&lt;/property&gt;&lt;/properties&gt;

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)