Timeout while creating tenant #4453

jlavallet created one year ago

ABP Framework version: v 5.3.5
UI type: MVC
DB provider: EF Core
Tiered (MVC) or Identity Server Separated (Angular): yes
Exception message and stack trace:

NOTE: SQL query omitted because Cloudflare thinks I am doing SQL injection and keeps blocking my post!

2023-01-30 13:33:20.755 -06:00 [ERR] Failed executing DbCommand (30,014ms) [Parameters=[@__ef_filter__p_0='?' (DbType = Boolean), @__id_0='?' (DbType = Guid)], CommandType='"Text"', CommandTimeout='30']
*[Omitted SQL was querying the SaasTenants table]*
2023-01-30 13:33:20.781 -06:00 [ERR] An exception occurred while iterating over the results of a query for context type 'Volo.Saas.EntityFrameworkCore.SaasDbContext'.
Microsoft.Data.SqlClient.SqlException (0x80131904): Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding.
 ---> System.ComponentModel.Win32Exception (258): The wait operation timed out.
   at Microsoft.Data.SqlClient.SqlCommand.<>c.<ExecuteDbDataReaderAsync>b__188_0(Task`1 result)
   at System.Threading.Tasks.ContinuationResultTaskFromResultTask`2.InnerInvoke()
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location ---
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)
--- End of stack trace from previous location ---
   at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)
   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()
ClientConnectionId:76fa3bd3-3eac-4581-93ee-466bddd36e60
Error Number:-2,State:0,Class:11
Microsoft.Data.SqlClient.SqlException (0x80131904): Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding.
 ---> System.ComponentModel.Win32Exception (258): The wait operation timed out.
   at Microsoft.Data.SqlClient.SqlCommand.<>c.<ExecuteDbDataReaderAsync>b__188_0(Task`1 result)
   at System.Threading.Tasks.ContinuationResultTaskFromResultTask`2.InnerInvoke()
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location ---
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)
--- End of stack trace from previous location ---
   at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)
   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.Query.ShapedQueryCompilingExpressionVisitor.SingleOrDefaultAsync[TSource](IAsyncEnumerable`1 asyncEnumerable, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.Query.ShapedQueryCompilingExpressionVisitor.SingleOrDefaultAsync[TSource](IAsyncEnumerable`1 asyncEnumerable, CancellationToken cancellationToken)
   at Volo.Abp.Domain.Repositories.EntityFrameworkCore.EfCoreRepository`3.FindAsync(TKey id, Boolean includeDetails, 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 Volo.Abp.Castle.DynamicProxy.CastleAsyncAbpInterceptorAdapter`1.InterceptAsync[TResult](IInvocation invocation, IInvocationProceedInfo proceedInfo, Func`3 proceed)
ClientConnectionId:76fa3bd3-3eac-4581-93ee-466bddd36e60
Error Number:-2,State:0,Class:11
2023-01-30 13:33:20.784 -06:00 [ERR] Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding.
Microsoft.Data.SqlClient.SqlException (0x80131904): Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding.
 ---> System.ComponentModel.Win32Exception (258): The wait operation timed out.
   at Microsoft.Data.SqlClient.SqlCommand.<>c.<ExecuteDbDataReaderAsync>b__188_0(Task`1 result)
   at System.Threading.Tasks.ContinuationResultTaskFromResultTask`2.InnerInvoke()
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location ---
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)
--- End of stack trace from previous location ---
   at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)
   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.Query.ShapedQueryCompilingExpressionVisitor.SingleOrDefaultAsync[TSource](IAsyncEnumerable`1 asyncEnumerable, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.Query.ShapedQueryCompilingExpressionVisitor.SingleOrDefaultAsync[TSource](IAsyncEnumerable`1 asyncEnumerable, CancellationToken cancellationToken)
   at Volo.Abp.Domain.Repositories.EntityFrameworkCore.EfCoreRepository`3.FindAsync(TKey id, Boolean includeDetails, 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 Volo.Abp.Castle.DynamicProxy.CastleAsyncAbpInterceptorAdapter`1.InterceptAsync[TResult](IInvocation invocation, IInvocationProceedInfo proceedInfo, Func`3 proceed)
   at Volo.Saas.Tenants.TenantStore.GetCacheItemAsync(Nullable`1 id, String name)
   at Volo.Saas.Tenants.TenantStore.FindAsync(Guid id)
   at BlueSpot.Data.BlueSpotTenantDatabaseMigrationHandler.MigrateAndSeedForTenantAsync(Guid tenantId, String adminEmail, String adminPassword) in D:\Century\Internal\BlueSpot\BlueSpot\src\BlueSpot.Domain\Data\BlueSpotTenantDatabaseMigrationHandler.cs:line 107
ClientConnectionId:76fa3bd3-3eac-4581-93ee-466bddd36e60
Error Number:-2,State:0,Class:11
2023-01-30 13:33:20.788 -06:00 [ERR] ---------- Exception Data ----------
HelpLink.ProdName = Microsoft SQL Server
HelpLink.ProdVer = 15.00.2095
HelpLink.EvtSrc = MSSQLServer
HelpLink.EvtID = -2
HelpLink.BaseHelpUrl = https://go.microsoft.com/fwlink
HelpLink.LinkId = 20476

Steps to reproduce the issue:"

I am getting the above exception when I attempt to create a tenant. From the UI perspective, the tenant is created successfully - no error messages and the new tenant appears in the list - but the tenant admin account is not created. Strangely, this works just fine on my development machine.

Given that the problem seems to be a command timeout, I have tried setting the command timeout to something like 5 minutes using the connection string:

{
 "ConnectionStrings": {
   "Default": "Server=SQL-SERVER-VM;Initial Catalog=BlueSpot;Uid=BlueSpotUser;Pwd=######;Command Timeout=300"
 },
 ...
}

That does increase the command timeout - the log error message shows a command timeout of '300' instead of '30' - but the result is the same, albeit very delayed.

2023-01-30 14:56:08.000 -06:00 [ERR] Failed executing DbCommand (300,037ms) [Parameters=[@__ef_filter__p_0='?' (DbType = Boolean), @__id_0='?' (DbType = Guid)], CommandType='"Text"', CommandTimeout='300']

During this long delay I tried to query the [SaasTenants] table. The query did not complete until the original request timed out.

That was strange. I thought maybe I needed to configure MARS. So I gave that a try:

{
  "ConnectionStrings": {
    "Default": "Server=SQL-SERVER-NDR;Initial Catalog=BlueSpot.Dev;Uid=BlueSpotUser;Pwd=#BS#bs#;Command Timeout=300;MultipleActiveResultSets=True"
  },
  ...
}

Same result. No difference. What could be happening? Why does it work when I run locally?

FYI - I do have some tenant data seeding code.

Here is my SaasDataSeedContributor:

namespace BlueSpot.Saas;

public class SaasDataSeedContributor : IDataSeedContributor, ITransientDependency
{
  private readonly ICurrentTenant _currentTenant;
  private readonly IEditionDataSeeder _editionDataSeeder;
  private readonly IOrganizationUnitDataSeeder _ouDataSeeder;
  private readonly ITenantDataSeeder _tenantDataSeeder;

  public SaasDataSeedContributor(
    IEditionDataSeeder editionDataSeeder,
    IOrganizationUnitDataSeeder ouDataSeeder,
    ITenantDataSeeder tenantDataSeeder,
    ICurrentTenant currentTenant)
  {
    _editionDataSeeder = editionDataSeeder;
    _ouDataSeeder = ouDataSeeder;
    _tenantDataSeeder = tenantDataSeeder;
    _currentTenant = currentTenant;
  }

  [UnitOfWork]
  public virtual async Task SeedAsync(DataSeedContext context)
  {
    using (_currentTenant.Change(context?.TenantId))
    {
      await _editionDataSeeder.CreateStandardEditionsAsync();
      await _ouDataSeeder.CreateOrganizationUnitsAsync();
      await _tenantDataSeeder.CreateTenantAsync();
    }
  }
}

And here is my ITenantDataSeeder implementation:

namespace BlueSpot.Saas;

public class TenantDataSeeder : ITenantDataSeeder, ITransientDependency
{
  private readonly ICurrentTenant _currentTenant;
  private readonly ILocalityDataSeeder _localityDataSeeder;
  private readonly ILogger&lt;TenantDataSeeder&gt; _logger;
  private readonly IPhotoDataSeeder _photoDataSeeder;
  private readonly IRejectionReasonDataSeeder _reasonDataSeeder;

  private readonly IRoleDataSeeder _roleDataSeeder;
  private readonly IStateDataSeeder _stateDataSeeder;
  private readonly IViolationStatusDataSeeder _statusDataSeeder;
  private readonly IUserDataSeeder _userDataSeeder;
  private readonly IViolationDataSeeder _violationDataSeeder;

  public TenantDataSeeder(
    IStateDataSeeder stateDataSeeder,
    IRejectionReasonDataSeeder reasonDataSeeder,
    IViolationStatusDataSeeder statusDataSeeder,
    IRoleDataSeeder roleDataSeeder,
    IUserDataSeeder userDataSeeder,
    IPhotoDataSeeder photoDataSeeder,
    IViolationDataSeeder violationDataSeeder,
    ILocalityDataSeeder localityDataSeeder,
    ICurrentTenant currentTenant,
    ILogger&lt;TenantDataSeeder&gt; logger)
  {
    _stateDataSeeder = stateDataSeeder;
    _reasonDataSeeder = reasonDataSeeder;
    _statusDataSeeder = statusDataSeeder;
    _roleDataSeeder = roleDataSeeder;
    _userDataSeeder = userDataSeeder;
    _photoDataSeeder = photoDataSeeder;
    _violationDataSeeder = violationDataSeeder;
    _localityDataSeeder = localityDataSeeder;
    _currentTenant = currentTenant;
    _logger = logger;
  }

  public async Task CreateTenantAsync()
  {
    try
    {
      await _stateDataSeeder.CreateStatesAsync();
      await _reasonDataSeeder.CreateRejectionReasonsAsync();
      await _statusDataSeeder.CreateViolationStatusesAsync();
      await _roleDataSeeder.CreateRolesAsync();
      await _userDataSeeder.CreateUsersAsync();
      await _photoDataSeeder.CreatePhotosAsync();
      await _violationDataSeeder.CreateViolationsAsync();
      await _localityDataSeeder.CreateLocalitiesAsync();
    }
    catch (ApplicationException e)
    {
      _logger.LogException(e, LogLevel.Warning);
    }
  }
}

As you can see, there's a lot going on when a tenant is created. But I do not understand why it is timing out. Please advise. Do you see something wrong?

2 Answer(s)