OpenIddict TokenProvider Concurrency Exception #7520

27 Answer(s)

• 

  0

  maliming created 3 months ago

  Support Team Fullstack Developer

  hi

  You can continue to observe, If it happens occasionally, you can ignore it.

  I have refunded your ticket.

  Thanks.

  Save Cancel
• 

  0

  naeem76 created 3 months ago

  Actually it's happening a lot, and is breaking the login flow for oauth.

  Any way to ignore it for now, this is quite urgent I have been trying to hijack the AbpOpenIddictTokenStore, but I don't think the service is being replaced.

  [Dependency(ReplaceServices = true)]
  [ExposeServices(typeof(IOpenIddictTokenStore<OpenIddictTokenModel>), typeof(AbpOpenIddictTokenStore))]
  public class CustomAbpOpenIddictTokenStore : AbpOpenIddictTokenStore
  {
      private readonly HelperUtility _helperUtility;
  
      public CustomAbpOpenIddictTokenStore(
          HelperUtility helperUtility,
          IOpenIddictTokenRepository repository,
          IUnitOfWorkManager unitOfWorkManager,
          IGuidGenerator guidGenerator,
          IOpenIddictApplicationRepository applicationRepository,
          IOpenIddictAuthorizationRepository authorizationRepository,
          AbpOpenIddictIdentifierConverter identifierConverter,
          IOpenIddictDbConcurrencyExceptionHandler concurrencyExceptionHandler,
          IOptions<AbpOpenIddictStoreOptions> storeOptions)
          : base(repository, unitOfWorkManager, guidGenerator, applicationRepository, authorizationRepository, identifierConverter, concurrencyExceptionHandler, storeOptions)
      {
          _helperUtility = helperUtility;
      }
  
      public override ValueTask DeleteAsync(OpenIddictTokenModel token, CancellationToken cancellationToken)
      {
          try
          {
              return base.DeleteAsync(token, cancellationToken);
          }
          catch (AbpDbConcurrencyException)
          {
              _ = _helperUtility.SendMsgToSlack("Caught abp Token ConcurrencyException");
              return default;
          }
          catch (OpenIddictExceptions.ConcurrencyException)
          {
              _ = _helperUtility.SendMsgToSlack("Caught Token ConcurrencyException");
              return default;
          }
      }
  
      public override ValueTask UpdateAsync(OpenIddictTokenModel token, CancellationToken cancellationToken)
      {
          try
          {
              _ = _helperUtility.SendMsgToSlack("called update");
              return base.UpdateAsync(token, cancellationToken);
          }
          catch (AbpDbConcurrencyException)
          {
              _ = _helperUtility.SendMsgToSlack("Caught abp Token ConcurrencyException");
              return default;
          }
          catch (OpenIddictExceptions.ConcurrencyException)
          {
              _ = _helperUtility.SendMsgToSlack("Caught Token ConcurrencyException");
              return default;
          }
      }
  }
  

  Save Cancel
• 

  0

  naeem76 created 3 months ago

  Actually now that I see it I may not have overridden the methods correctly, since they are async

  Save Cancel
• 

  0

  maliming created 3 months ago

  Support Team Fullstack Developer

  hi

  Thanks

  We have changed the code in new version

  https://github.com/abpframework/abp/issues/15530#issuecomment-1505182866 https://github.com/abpframework/abp/pull/16351

  Save Cancel
• 

  0

  naeem76 created 3 months ago

  hi

  Thanks

  We have changed the code in new version

  https://github.com/abpframework/abp/issues/15530#issuecomment-1505182866 https://github.com/abpframework/abp/pull/16351

  So sorry, I forgot to mention that I have migrated the project to 8.2 already. and this is currently on 8.2.

  EDIT: I have updated my initial question to mention 8.2

  Save Cancel
• 

  0

  maliming created 3 months ago

  Support Team Fullstack Developer

  hi

  Does this only happen with load-balanced?

  Can you share the logs.txt of all servers?

  https://wetransfer.com/ liming.ma@volosoft.com

  Thanks

  Save Cancel
• 

  0

  naeem76 created 3 months ago

  Based on my experience, I think only load-balanced, as it was not happening on dev, which had 1 instance, getting this on our staging side which has a minimum of 4 instances at all times. But I will confirm this now, by scaling down to 1 instance.

  Also emailing you logs at the moment.

  Save Cancel
• 

  0

  maliming created 3 months ago

  Support Team Fullstack Developer

  Many thanks. 👍

  Save Cancel
• 

  0

  naeem76 created 3 months ago

  Sorry sent you wrong logs, sending again

  Save Cancel
• 

  0

  maliming created 3 months ago

  Support Team Fullstack Developer

  ok

  Save Cancel
• 

  0

  naeem76 created 3 months ago

  Feel free to use both.

  1st set of logs are from main server - 7.1.1 2nd set of logs are from identical copy of main server but on 8.2 - for test purposes, this is better, as it only has logs for the logins. and been using it for the past hour.

  Save Cancel
• 

  0

  naeem76 created 3 months ago

  They are in web.stdout.log

  Save Cancel
• 

  0

  maliming created 3 months ago

  Support Team Fullstack Developer

  ok, Thanks

  Save Cancel
• 

  0

  naeem76 created 3 months ago

  Just scaled down to 1 instance, but still got the error, so not related to load balanced env.

  Save Cancel
• 

  0

  maliming created 3 months ago

  Support Team Fullstack Developer

  hi

  Can you try a new template project in your environment?

  Save Cancel
• 

  0

  maliming created 3 months ago

  Support Team Fullstack Developer

  Set the ef core log level to Debug

  .MinimumLevel.Override("Microsoft.EntityFrameworkCore", LogEventLevel.Debug)
  

  and EnableSensitiveDataLogging

  Configure<AbpDbContextOptions>(options =>
  {
      /* The main point to change your DBMS.
       * See also BookStoreMigrationsDbContextFactory for EF Core tooling. */
      options.UseSqlServer();
      options.Configure(configureOptions =>
      {
          configureOptions.DbContextOptions.EnableSensitiveDataLogging();
      });
  });
  

  Save Cancel
• 

  0

  naeem76 created 3 months ago

  Ok I will try now. Give me a bit of time as I will need to connect them to redis.

  Scratch my previous comment about not related to load balanced. error was gone eventually, and then immediately came back after scaling to 4 instances.

  More information. The login flow is using OIDC from a react app, which redirects to aBP login page - > then OAUTH. which returns this

  If i immediately go to the ABP dashboard, it seems like I have a login session correctly.

  For direct dashboard login, I have to test more, but seems like login works, but logout is giving 500 errors again.

  Edit : replacing log lines with urls.

  
  Jul 18 03:12:55 ip-172-31-1-32 web: 03:12:55 [INF] Saved 2 entities to in-memory store.
  Jul 18 03:12:55 ip-172-31-1-32 web: 03:12:55 [INF] Executing endpoint '/Account/Logout'
  Jul 18 03:12:55 ip-172-31-1-32 web: 03:12:55 [INF] Route matched with {page = "/Account/Logout", area = "", action = "", controller = ""}. Executing page /Account/Logout
  Jul 18 03:12:55 ip-172-31-1-32 web: 03:12:55 [INF] Skipping the execution of current filter as its not the most effective filter implementing the policy Microsoft.AspNetCore.Mvc.ViewFeatures.IAntiforgeryPolicy
  Jul 18 03:12:55 ip-172-31-1-32 web: 03:12:55 [INF] Executing handler method Volo.Abp.Account.Public.Web.Pages.Account.LogoutModel.OnGetAsync - ModelState is Valid
  Jul 18 03:12:56 ip-172-31-1-32 web: 03:12:56 [INF] Executed DbCommand (78ms) [Parameters=[@p0='?' (DbType = Guid), @p1='?' (Size = 96), @p2='?' (Size = 96), @p3='?' (Size = 512), @p4='?' (Size = 64), @p5='?' (Size = 64), @p6='?' (Size = 40), @p7='?' (Size = 64), @p8='?' (DbType = DateTime), @p9='?' (Size = 4000), @p10='?' (Size = 96), @p11='?' (DbType = Guid), @p12='?' (Size = 64), @p13='?' (DbType = Guid), @p14='?' (Size = 256)], CommandType='Text', CommandTimeout='30']
  Jul 18 03:12:56 ip-172-31-1-32 web: SET AUTOCOMMIT = 1;
  Jul 18 03:12:56 ip-172-31-1-32 web: INSERT INTO `AbpSecurityLogs` (`Id`, `Action`, `ApplicationName`, `BrowserInfo`, `ClientId`, `ClientIpAddress`, `ConcurrencyStamp`, `CorrelationId`, `CreationTime`, `ExtraProperties`, `Identity`, `TenantId`, `TenantName`, `UserId`, `UserName`)
  Jul 18 03:12:56 ip-172-31-1-32 web: VALUES (@p0, @p1, @p2, @p3, @p4, @p5, @p6, @p7, @p8, @p9, @p10, @p11, @p12, @p13, @p14);
  Jul 18 03:12:56 ip-172-31-1-32 web: 03:12:56 [INF] Executed DbCommand (18ms) [Parameters=[@__ef_filter__p_0='?' (DbType = Boolean), @__sessionId_0='?' (Size = 128)], CommandType='Text', CommandTimeout='30']
  Jul 18 03:12:56 ip-172-31-1-32 web: SELECT `a`.`Id`, `a`.`ClientId`, `a`.`Device`, `a`.`DeviceInfo`, `a`.`IpAddresses`, `a`.`LastAccessed`, `a`.`SessionId`, `a`.`SignedIn`, `a`.`TenantId`, `a`.`UserId`
  Jul 18 03:12:56 ip-172-31-1-32 web: FROM `AbpSessions` AS `a`
  Jul 18 03:12:56 ip-172-31-1-32 web: WHERE (@__ef_filter__p_0 OR (`a`.`TenantId` IS NULL)) AND (`a`.`SessionId` = @__sessionId_0)
  Jul 18 03:12:56 ip-172-31-1-32 web: LIMIT 1
  Jul 18 03:12:56 ip-172-31-1-32 web: 03:12:56 [INF] AuthenticationScheme: Identity.Application signed out.
  Jul 18 03:12:56 ip-172-31-1-32 web: 03:12:56 [INF] AuthenticationScheme: Identity.External signed out.
  Jul 18 03:12:56 ip-172-31-1-32 web: 03:12:56 [INF] AuthenticationScheme: Identity.TwoFactorUserId signed out.
  Jul 18 03:12:56 ip-172-31-1-32 web: 03:12:56 [INF] AuthenticationScheme: Abp.ConfirmUser signed out.
  Jul 18 03:12:56 ip-172-31-1-32 web: 03:12:56 [INF] Executed handler method OnGetAsync, returned result Microsoft.AspNetCore.Mvc.RedirectResult.
  Jul 18 03:12:56 ip-172-31-1-32 web: 03:12:56 [INF] Executed DbCommand (35ms) [Parameters=[@p0='?' (DbType = Guid)], CommandType='Text', CommandTimeout='30']
  Jul 18 03:12:56 ip-172-31-1-32 web: SET AUTOCOMMIT = 1;
  Jul 18 03:12:56 ip-172-31-1-32 web: DELETE FROM `AbpSessions`
  Jul 18 03:12:56 ip-172-31-1-32 web: WHERE `Id` = @p0;
  Jul 18 03:12:56 ip-172-31-1-32 web: SELECT ROW_COUNT();
  Jul 18 03:12:56 ip-172-31-1-32 web: 03:12:56 [WRN] There is an entry which is not saved due to concurrency exception:
  Jul 18 03:12:56 ip-172-31-1-32 web: IdentitySession {Id: 3a13d5fc-2c85-6bca-7052-31ee5a31cc29} Deleted
  Jul 18 03:12:56 ip-172-31-1-32 web: 03:12:56 [ERR] ---------- RemoteServiceErrorInfo ----------
  Jul 18 03:12:56 ip-172-31-1-32 web: {
  Jul 18 03:12:56 ip-172-31-1-32 web: "code": null,
  Jul 18 03:12:56 ip-172-31-1-32 web: "message": "The data you have submitted has already changed by another user/client. Please discard the changes you've done and try from the beginning.",
  Jul 18 03:12:56 ip-172-31-1-32 web: "details": null,
  Jul 18 03:12:56 ip-172-31-1-32 web: "data": null,
  Jul 18 03:12:56 ip-172-31-1-32 web: "validationErrors": null
  Jul 18 03:12:56 ip-172-31-1-32 web: }
  Jul 18 03:12:56 ip-172-31-1-32 web: 03:12:56 [ERR] The database operation was expected to affect 1 row(s), but actually affected 0 row(s); data may have been modified or deleted since entities were loaded. See https://go.microsoft.com/fwlink/?LinkId=527962 for information on understanding and handling optimistic concurrency exceptions.
  Jul 18 03:12:56 ip-172-31-1-32 web: Volo.Abp.Data.AbpDbConcurrencyException: The database operation was expected to affect 1 row(s), but actually affected 0 row(s); data may have been modified or deleted since entities were loaded. See https://go.microsoft.com/fwlink/?LinkId=527962 for information on understanding and handling optimistic concurrency exceptions.
  Jul 18 03:12:56 ip-172-31-1-32 web: ---> Microsoft.EntityFrameworkCore.DbUpdateConcurrencyException: The database operation was expected to affect 1 row(s), but actually affected 0 row(s); data may have been modified or deleted since entities were loaded. See https://go.microsoft.com/fwlink/?LinkId=527962 for information on understanding and handling optimistic concurrency exceptions.
  Jul 18 03:12:56 ip-172-31-1-32 web: at Microsoft.EntityFrameworkCore.Update.AffectedCountModificationCommandBatch.ThrowAggregateUpdateConcurrencyExceptionAsync(RelationalDataReader reader, Int32 commandIndex, Int32 expectedRowsAffected, Int32 rowsAffected, CancellationToken cancellationToken)
  
  

  Save Cancel

  1
• 

  0

  maliming created 3 months ago

  Support Team Fullstack Developer

  Thanks for your further info. I will wait to check your new logs.

  Save Cancel
• 

  0

  naeem76 created 3 months ago

  Still setting up sample template env, for now please check these new logs (emailed you just now) for the main 8.2 environment, but with the new debug identifier for EntityFrameworkCore, as well as sensitive data logging.

  Save Cancel
• 

  0

  maliming created 3 months ago

  Support Team Fullstack Developer

  ok, I wil check it asap. Thanks

  Save Cancel
• 

  0

  maliming created 3 months ago

  Support Team Fullstack Developer

  From the logs, it seems that a web request is forwarded to multiple servers at the same time.

  Can you confirm this?

  One success and another failed.

  

  Save Cancel
• 

  0

  naeem76 created 3 months ago

  Isn't one a /connect/login, and the other a /connect/authorize? Time is same you are right, and I can check, but pretty sure that would defeat the purpose of a load balancer. For context its an Elastic Load Balancer on AWS (Application Load Balancer) which is supposed to round robin, and definitely not duplicate requests.

  Also can you help me override the TokenStore, that would help me temporarily. I've tried various methods but no success. I see you used it here. https://github.com/abpframework/abp/issues/15530#issuecomment-1573187239

  Thank you for your help. Is there any other way I can help you debug?

  Save Cancel
• 

  0

  naeem76 created 3 months ago

  I was kind of losing my mind on why the database wasn't working on the sample template env (already had this format in main project)

  For sensitive data logging, the code needs to be

  Configure<AbpDbContextOptions>(options =>
  {
          /* The main point to change your DBMS.
           * See also ScoobyLoginTestDbContextFactory for EF Core tooling. */
      //options.UseMySQL();
  
      options.Configure(opts =>
      {
          opts.DbContextOptions.UseMySql(configuration.GetConnectionString("Default"), ServerVersion.Parse("8.0.32-mysql"));
          opts.DbContextOptions.EnableSensitiveDataLogging();
      });
  });
  

  Save Cancel
• 

  0

  naeem76 created 3 months ago

  I may have narrowed down the issue with Amazon RDS proxy. was able to reproduce the issue on a new sample template, just by using RDS proxy. Will be trying main api without proxy and testing more.

  RDS proxy pools connections automatically. Is there any way to have a distributed pooling system with ABP? I have a limit for maximum database connections, and that needs to be a sum for all active instances.

  Also not sure which mechanism of it is causing this issue.

  Save Cancel
• 

  0

  maliming created 3 months ago

  Support Team Fullstack Developer

  hi

  I'm not familiar with Amazon, but the problem is basically that a request is processed twice, so there is a concurrency exception.

  Save Cancel