Background job is not re-executed #8894

peopleteq created 4 years ago

I have issue with Background job tries. Job are created in AbpBackgroundJobs table and executed once. After job failed, job record in the table is not updated: NextTryTime is still equesl to CreationTime and TryCount is 0. Even 1 day after failed jobs are in db and not updated.

Log:

WARN  2020-04-20 16:45:17,272 [14   ] Abp.BackgroundJobs.BackgroundJobManager  - Database operation expected to affect 1 row(s) but actually affected 0 row(s). Data may have been modified or deleted since entities were loaded. See http://go.microso$
Abp.Domain.Uow.AbpDbConcurrencyException: Database operation expected to affect 1 row(s) but actually affected 0 row(s). Data may have been modified or deleted since entities were loaded. See http://go.microsoft.com/fwlink/?LinkId=527962 for inform$
 ---> Microsoft.EntityFrameworkCore.DbUpdateConcurrencyException: Database operation expected to affect 1 row(s) but actually affected 0 row(s). Data may have been modified or deleted since entities were loaded. See http://go.microsoft.com/fwlink/?$
   at Microsoft.EntityFrameworkCore.Update.AffectedCountModificationCommandBatch.ThrowAggregateUpdateConcurrencyException(Int32 commandIndex, Int32 expectedRowsAffected, Int32 rowsAffected)
   at Microsoft.EntityFrameworkCore.Update.AffectedCountModificationCommandBatch.ConsumeResultSetWithoutPropagation(Int32 commandIndex, RelationalDataReader reader)
   at Microsoft.EntityFrameworkCore.Update.AffectedCountModificationCommandBatch.Consume(RelationalDataReader reader)
   at Microsoft.EntityFrameworkCore.Update.ReaderModificationCommandBatch.Execute(IRelationalConnection connection)
   at Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.Execute(DbContext _, ValueTuple`2 parameters)
   at Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerExecutionStrategy.Execute[TState,TResult](TState state, Func`3 operation, Func`3 verifySucceeded)
   at Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.Execute(IEnumerable`1 commandBatches, IRelationalConnection connection)
   at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.SaveChanges(IList`1 entriesToSave)
   at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.SaveChanges(Boolean acceptAllChangesOnSuccess)
   at Microsoft.EntityFrameworkCore.DbContext.SaveChanges(Boolean acceptAllChangesOnSuccess)
   at Abp.EntityFrameworkCore.AbpDbContext.SaveChanges()
   --- End of inner exception stack trace ---
   at Abp.EntityFrameworkCore.AbpDbContext.SaveChanges()
   at Abp.Zero.EntityFrameworkCore.AbpZeroCommonDbContext`3.SaveChanges()
   at Abp.EntityFrameworkCore.Uow.EfCoreUnitOfWork.SaveChangesInDbContext(DbContext dbContext)
   at Abp.EntityFrameworkCore.Uow.EfCoreUnitOfWork.SaveChanges()
   at Abp.EntityFrameworkCore.Uow.EfCoreUnitOfWork.CompleteUow()
   at Abp.Domain.Uow.UnitOfWorkBase.Complete()
   at Abp.Domain.Uow.UnitOfWorkInterceptor.PerformSyncUow(IInvocation invocation, UnitOfWorkOptions options)
   at Castle.DynamicProxy.AbstractInvocation.Proceed()
   at Castle.DynamicProxy.AbstractInvocation.Proceed()
   at Castle.DynamicProxy.AbstractInvocation.Proceed()
   at Abp.BackgroundJobs.BackgroundJobManager.TryProcessJob(BackgroundJobInfo jobInfo)
DEBUG 2020-04-20 16:45:17,274 [14   ] HttpRequestEntityChangeSetReasonProvider - Unable to get URL from HttpRequest, fallback to null
WARN  2020-04-20 16:45:17,275 [14   ] Abp.BackgroundJobs.BackgroundJobManager  - Abp.Domain.Uow.AbpDbConcurrencyException: Database operation expected to affect 1 row(s) but actually affected 0 row(s). Data may have been modified or deleted since e$
 ---> Microsoft.EntityFrameworkCore.DbUpdateConcurrencyException: Database operation expected to affect 1 row(s) but actually affected 0 row(s). Data may have been modified or deleted since entities were loaded. See http://go.microsoft.com/fwlink/?$
   at Microsoft.EntityFrameworkCore.Update.AffectedCountModificationCommandBatch.ThrowAggregateUpdateConcurrencyException(Int32 commandIndex, Int32 expectedRowsAffected, Int32 rowsAffected)
   at Microsoft.EntityFrameworkCore.Update.AffectedCountModificationCommandBatch.ConsumeResultSetWithoutPropagation(Int32 commandIndex, RelationalDataReader reader)
   at Microsoft.EntityFrameworkCore.Update.AffectedCountModificationCommandBatch.Consume(RelationalDataReader reader)
   at Microsoft.EntityFrameworkCore.Update.ReaderModificationCommandBatch.Execute(IRelationalConnection connection)
   at Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.Execute(DbContext _, ValueTuple`2 parameters)
   at Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerExecutionStrategy.Execute[TState,TResult](TState state, Func`3 operation, Func`3 verifySucceeded)
   at Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.Execute(IEnumerable`1 commandBatches, IRelationalConnection connection)
   at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.SaveChanges(IList`1 entriesToSave)
   at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.SaveChanges(Boolean acceptAllChangesOnSuccess)
   at Microsoft.EntityFrameworkCore.DbContext.SaveChanges(Boolean acceptAllChangesOnSuccess)
   at Abp.EntityFrameworkCore.AbpDbContext.SaveChanges()
   --- End of inner exception stack trace ---
   at Abp.EntityFrameworkCore.AbpDbContext.SaveChanges()
   at Abp.Zero.EntityFrameworkCore.AbpZeroCommonDbContext`3.SaveChanges()
   at Abp.EntityFrameworkCore.Uow.EfCoreUnitOfWork.SaveChangesInDbContext(DbContext dbContext)
   at Abp.EntityFrameworkCore.Uow.EfCoreUnitOfWork.SaveChanges()
   at Abp.EntityFrameworkCore.Uow.EfCoreUnitOfWork.CompleteUow()
   at Abp.Domain.Uow.UnitOfWorkBase.Complete()
   at Abp.Domain.Uow.UnitOfWorkInterceptor.PerformSyncUow(IInvocation invocation, UnitOfWorkOptions options)
   at Castle.DynamicProxy.AbstractInvocation.Proceed()
   at Castle.Proxies.IRepository`2Proxy_1.Update(BackgroundJobInfo entity)
   at Castle.Proxies.BackgroundJobStoreProxy.Update_callback(BackgroundJobInfo jobInfo)
   at Castle.DynamicProxy.AbstractInvocation.Proceed()
   at Castle.DynamicProxy.AbstractInvocation.Proceed()
   at Abp.BackgroundJobs.BackgroundJobManager.TryUpdate(BackgroundJobInfo jobInfo)
   Abp.Domain.Uow.AbpDbConcurrencyException: Database operation expected to affect 1 row(s) but actually affected 0 row(s). Data may have been modified or deleted since entities were loaded. See http://go.microsoft.com/fwlink/?LinkId=527962 for inform$
   ---> Microsoft.EntityFrameworkCore.DbUpdateConcurrencyException: Database operation expected to affect 1 row(s) but actually affected 0 row(s). Data may have been modified or deleted since entities were loaded. See http://go.microsoft.com/fwlink/?$
   at Microsoft.EntityFrameworkCore.Update.AffectedCountModificationCommandBatch.ThrowAggregateUpdateConcurrencyException(Int32 commandIndex, Int32 expectedRowsAffected, Int32 rowsAffected)
   at Microsoft.EntityFrameworkCore.Update.AffectedCountModificationCommandBatch.ConsumeResultSetWithoutPropagation(Int32 commandIndex, RelationalDataReader reader)
   at Microsoft.EntityFrameworkCore.Update.AffectedCountModificationCommandBatch.Consume(RelationalDataReader reader)
   at Microsoft.EntityFrameworkCore.Update.ReaderModificationCommandBatch.Execute(IRelationalConnection connection)
   at Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.Execute(DbContext _, ValueTuple`2 parameters)
   at Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerExecutionStrategy.Execute[TState,TResult](TState state, Func`3 operation, Func`3 verifySucceeded)
   at Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.Execute(IEnumerable`1 commandBatches, IRelationalConnection connection)
   at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.SaveChanges(IList`1 entriesToSave)
   at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.SaveChanges(Boolean acceptAllChangesOnSuccess)
   at Microsoft.EntityFrameworkCore.DbContext.SaveChanges(Boolean acceptAllChangesOnSuccess)
   at Abp.EntityFrameworkCore.AbpDbContext.SaveChanges()
   --- End of inner exception stack trace ---
   at Abp.EntityFrameworkCore.AbpDbContext.SaveChanges()
   at Abp.Zero.EntityFrameworkCore.AbpZeroCommonDbContext`3.SaveChanges()
   at Abp.EntityFrameworkCore.Uow.EfCoreUnitOfWork.SaveChangesInDbContext(DbContext dbContext)
   at Abp.EntityFrameworkCore.Uow.EfCoreUnitOfWork.SaveChanges()
   at Abp.EntityFrameworkCore.Uow.EfCoreUnitOfWork.CompleteUow()
   at Abp.Domain.Uow.UnitOfWorkBase.Complete()
   at Abp.Domain.Uow.UnitOfWorkInterceptor.PerformSyncUow(IInvocation invocation, UnitOfWorkOptions options)
   at Castle.DynamicProxy.AbstractInvocation.Proceed()
   at Castle.Proxies.IRepository`2Proxy_1.Update(BackgroundJobInfo entity)
   at Castle.Proxies.BackgroundJobStoreProxy.Update_callback(BackgroundJobInfo jobInfo)
   at Castle.DynamicProxy.AbstractInvocation.Proceed()
   at Castle.DynamicProxy.AbstractInvocation.Proceed()
   at Abp.BackgroundJobs.BackgroundJobManager.TryUpdate(BackgroundJobInfo jobInfo)

You can see 2 exceptions there. They are AbpDbConcurrencyException. First occured during job precessing. The second - TryUpdate background job.

Code of Execute method of Background Job

    public override async void Execute(DefectPhotoUploaderBackgroundJobArgs args)
        {
            using (var unitOfWork = UnitOfWorkManager.Begin())
            {

                string photoUrl = await _cloudStorage.UploadFileAsync(args.Image, "image_123.jpg");

                await _backgroundJobManager.EnqueueAsync<DefectPhotoUrlSaverBackgroundJob, DefectPhotoUrlSaverBackgroundJobArgs>(     <<< I think first exception occured because of this operation. There is one more backgroud job created
                    new DefectPhotoUrlSaverBackgroundJobArgs()
                    {
                        InspectionGuid = args.InspectionGuid,
                        DefectId = args.ProductInstanceInspectionDefect.DefectId,
                        PhotoUrl = photoUrl
                    });

                unitOfWork.Complete();                                                                                                                                                                                <<< SaveChanges called. it is failed with the exception
            }
        }                                                                                                                                                                                                                             <<< Job Manager tryes to update status of failed job and gets the exception.

it is important to mention that AbpBackgroudJobs table contains many of records (1000+).

Can you please to help with the issue?

Also can you please answer on questions about manager:

How often do Manager look for job ready be executed?
How many jobs executed in one loop?

ANZ version: 8.0.0

Thanks

6 Answer(s)

0

ismcagdas created 4 years ago
Support Team

Hi,

Could you chante unitOfWork.Complete(); to await unitOfWork.CompleteAsync(); and try again ?

Next try time is calculated here https://github.com/aspnetboilerplate/aspnetboilerplate/blob/dev/src/Abp/BackgroundJobs/BackgroundJobManager.cs#L159. If ABP couldn't update the Job info, there must be a warning in the log files about this.
0

peopleteq created 4 years ago

Hi @ismcagdas ,

I applyed your change, but that did not help. Also I realsied that sometimes a job is abandoned immediatly right after it's created. The job on the picture was not called. I checked this during debug.

Can you please say why that happens?
0

ismcagdas created 4 years ago
Support Team

Hi,

IsAbandoned is set to true in two places in this class https://github.com/aspnetboilerplate/aspnetboilerplate/blob/dev/src/Abp/BackgroundJobs/BackgroundJobManager.cs. In both cases, there must be a warning log written to your log file. Did you find such warning message in server side Log file ?

peopleteq created 4 years ago

Hi,

There was no warning. But I will try to repeat test case again.

Now I am getting TryUpdate job warning again

WARN  2020-04-24 14:38:53,917 [35   ] Abp.BackgroundJobs.BackgroundJobManager  - Abp.Domain.Uow.AbpDbConcurrencyException: Database operation expected to affect 1 row(s) but actually affected 0 row(s). Data may have been modified or deleted since entities were loaded. See http://go.microsoft.com/fwlink/?LinkId=527962 for information on understanding and handling optimistic concurrency exceptions.
 ---> Microsoft.EntityFrameworkCore.DbUpdateConcurrencyException: Database operation expected to affect 1 row(s) but actually affected 0 row(s). Data may have been modified or deleted since entities were loaded. See http://go.microsoft.com/fwlink/?LinkId=527962 for information on understanding and handling optimistic concurrency exceptions.
   at Microsoft.EntityFrameworkCore.Update.AffectedCountModificationCommandBatch.ThrowAggregateUpdateConcurrencyException(Int32 commandIndex, Int32 expectedRowsAffected, Int32 rowsAffected)
   at Microsoft.EntityFrameworkCore.Update.AffectedCountModificationCommandBatch.ConsumeResultSetWithoutPropagation(Int32 commandIndex, RelationalDataReader reader)
   at Microsoft.EntityFrameworkCore.Update.AffectedCountModificationCommandBatch.Consume(RelationalDataReader reader)
   at Microsoft.EntityFrameworkCore.Update.ReaderModificationCommandBatch.Execute(IRelationalConnection connection)
   at Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.Execute(DbContext _, ValueTuple`2 parameters)
   at Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerExecutionStrategy.Execute[TState,TResult](TState state, Func`3 operation, Func`3 verifySucceeded)
   at Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.Execute(IEnumerable`1 commandBatches, IRelationalConnection connection)
   at Microsoft.EntityFrameworkCore.Storage.RelationalDatabase.SaveChanges(IList`1 entries)
   at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.SaveChanges(IList`1 entriesToSave)
   at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.SaveChanges(Boolean acceptAllChangesOnSuccess)
   at Microsoft.EntityFrameworkCore.DbContext.SaveChanges(Boolean acceptAllChangesOnSuccess)
   at Abp.EntityFrameworkCore.AbpDbContext.SaveChanges()
   --- End of inner exception stack trace ---
   at Abp.EntityFrameworkCore.AbpDbContext.SaveChanges()
   at Abp.Zero.EntityFrameworkCore.AbpZeroCommonDbContext`3.SaveChanges()
   at Abp.EntityFrameworkCore.Uow.EfCoreUnitOfWork.SaveChangesInDbContext(DbContext dbContext)
   at Abp.EntityFrameworkCore.Uow.EfCoreUnitOfWork.SaveChanges()
   at Abp.EntityFrameworkCore.Uow.EfCoreUnitOfWork.CompleteUow()
   at Abp.Domain.Uow.UnitOfWorkBase.Complete()
   at Abp.Domain.Uow.UnitOfWorkInterceptor.PerformSyncUow(IInvocation invocation, UnitOfWorkOptions options)
   at Castle.DynamicProxy.AbstractInvocation.Proceed()
   at Castle.Proxies.IRepository`2Proxy_1.Update(BackgroundJobInfo entity)
   at Abp.BackgroundJobs.BackgroundJobStore.Update(BackgroundJobInfo jobInfo)
   at Castle.Proxies.BackgroundJobStoreProxy.Update_callback(BackgroundJobInfo jobInfo)
   at Castle.Proxies.Invocations.IBackgroundJobStore_Update.InvokeMethodOnTarget()
   at Castle.DynamicProxy.AbstractInvocation.Proceed()
   at Castle.DynamicProxy.AbstractInvocation.Proceed()
   at Castle.Proxies.BackgroundJobStoreProxy.Update(BackgroundJobInfo jobInfo)
   at Abp.BackgroundJobs.BackgroundJobManager.TryUpdate(BackgroundJobInfo jobInfo)

What can be a probem?

peopleteq created 4 years ago

Has got the issue with abadoned job again

The log

INFO  2020-04-24 14:55:06,344 [20   ] Microsoft.AspNetCore.Hosting.Diagnostics - Request starting HTTP/1.1 POST http://localhost:5000/api/services/FTT/Delasting/CreateDelastedShoes application/json-patch+json 244
INFO  2020-04-24 14:55:06,344 [20   ] ft.AspNetCore.Routing.EndpointMiddleware - Executing endpoint 'DigitalFactory.Ftt.Delasting.DelastingAppService.CreateDelastedShoes (DigitalFactory.Ftt.Application)'
INFO  2020-04-24 14:55:06,347 [20   ] c.Infrastructure.ControllerActionInvoker - Route matched with {area = "FTT", action = "CreateDelastedShoes", controller = "Delasting"}. Executing controller action with signature System.Threading.Tasks.Task CreateDelastedShoes(System.Collections.Generic.List`1[DigitalFactory.Ftt.Delasting.Dto.DelastedShoeInputDto]) on controller DigitalFactory.Ftt.Delasting.DelastingAppService (DigitalFactory.Ftt.Application).
INFO  2020-04-24 14:55:10,936 [20   ] .Mvc.Infrastructure.ObjectResultExecutor - Executing ObjectResult, writing value of type 'Abp.Web.Models.AjaxResponse'.
INFO  2020-04-24 14:55:10,936 [20   ] c.Infrastructure.ControllerActionInvoker - Executed action DigitalFactory.Ftt.Delasting.DelastingAppService.CreateDelastedShoes (DigitalFactory.Ftt.Application) in 4588.988ms
INFO  2020-04-24 14:55:10,936 [20   ] ft.AspNetCore.Routing.EndpointMiddleware - Executed endpoint 'DigitalFactory.Ftt.Delasting.DelastingAppService.CreateDelastedShoes (DigitalFactory.Ftt.Application)'
INFO  2020-04-24 14:55:10,937 [20   ] Microsoft.AspNetCore.Hosting.Diagnostics - Request finished in 4593.3567ms 200 application/json; charset=utf-8
INFO  2020-04-24 14:55:10,948 [20   ] Microsoft.AspNetCore.Hosting.Diagnostics - Request starting HTTP/1.1 POST http://localhost:5000/api/services/FTT/Delasting/CreateDelastedShoes application/json-patch+json 244
INFO  2020-04-24 14:55:10,949 [20   ] ft.AspNetCore.Routing.EndpointMiddleware - Executing endpoint 'DigitalFactory.Ftt.Delasting.DelastingAppService.CreateDelastedShoes (DigitalFactory.Ftt.Application)'
INFO  2020-04-24 14:55:10,952 [20   ] c.Infrastructure.ControllerActionInvoker - Route matched with {area = "FTT", action = "CreateDelastedShoes", controller = "Delasting"}. Executing controller action with signature System.Threading.Tasks.Task CreateDelastedShoes(System.Collections.Generic.List`1[DigitalFactory.Ftt.Delasting.Dto.DelastedShoeInputDto]) on controller DigitalFactory.Ftt.Delasting.DelastingAppService (DigitalFactory.Ftt.Application).
DEBUG 2020-04-24 14:55:12,395 [20   ] HttpRequestEntityChangeSetReasonProvider - Unable to get URL from HttpRequest, fallback to null
INFO  2020-04-24 14:55:12,483 [19   ] .Mvc.Infrastructure.ObjectResultExecutor - Executing ObjectResult, writing value of type 'Abp.Web.Models.AjaxResponse'.
INFO  2020-04-24 14:55:12,483 [19   ] c.Infrastructure.ControllerActionInvoker - Executed action DigitalFactory.Ftt.Delasting.DelastingAppService.CreateDelastedShoes (DigitalFactory.Ftt.Application) in 1531.3894ms
INFO  2020-04-24 14:55:12,483 [19   ] ft.AspNetCore.Routing.EndpointMiddleware - Executed endpoint 'DigitalFactory.Ftt.Delasting.DelastingAppService.CreateDelastedShoes (DigitalFactory.Ftt.Application)'
INFO  2020-04-24 14:55:12,487 [19   ] Microsoft.AspNetCore.Hosting.Diagnostics - Request finished in 1538.6284ms 200 application/json; charset=utf-8
DEBUG 2020-04-24 14:55:18,539 [20   ] HttpRequestEntityChangeSetReasonProvider - Unable to get URL from HttpRequest, fallback to null
DEBUG 2020-04-24 14:55:24,687 [19   ] HttpRequestEntityChangeSetReasonProvider - Unable to get URL from HttpRequest, fallback to null
DEBUG 2020-04-24 14:55:30,824 [19   ] HttpRequestEntityChangeSetReasonProvider - Unable to get URL from HttpRequest, fallback to null
DEBUG 2020-04-24 14:55:37,082 [19   ] HttpRequestEntityChangeSetReasonProvider - Unable to get URL from HttpRequest, fallback to null
DEBUG 2020-04-24 14:55:43,234 [20   ] HttpRequestEntityChangeSetReasonProvider - Unable to get URL from HttpRequest, fallback to null
DEBUG 2020-04-24 14:55:49,374 [22   ] HttpRequestEntityChangeSetReasonProvider - Unable to get URL from HttpRequest, fallback to null

The job

On the picture you can check time of the job and compare that with time on log (+7 timezone). As you can see the log does not have any messages regarding the job. Also my job writed debug line into log, to check that the job was executed. The line is missing in the log too.

0

ismcagdas created 4 years ago
Support Team

Hi @peopleteq,

Do you know exactly when this happens ? If so, we can reproduce it on our side. If you can share your background job class and where you initiate it with [email protected] we can also try to reproduce it.

Thanks,

Have an answer to this question? Log in and write your answer.