ABP is setting BackgroundJob to IsAbandoned = true without any logging or explanation #7024

jkrause created 8 months ago

ABP Framework version: v8.0.4
UI Type: Blazor Server
Database System: EF Core SQL Server
Tiered (for MVC) or Auth Server Separated (for Angular): no
Exception message and full stack trace: None produced
Steps to reproduce the issue: Impossible

Yes, not being able to reproduce this behavior, you could immediately conclude that you cannot do anything. However, you wrote the entire infrastructure and plumbing of the background component and related functionality, so we ask you to just please help us figuring out what is happening, why it is happening and how this hopefully can be addressed, as we are hard stuck.

In order to do our part, I will explain what we did and perhaps we can figure out together why this behavior is happening. Also, judging by the previous threads created on similar issues related to IsAbandoned being set without any logging output, it could perhaps be something nested very deep within ABP. Without any logging output from the underlying components it's incredibly hard to debug this. So here is what we did/tried (and yes perhaps we did it terribly wrong, but we are not ABP experts...yet):

Add setting to disable Background Job processing

        Configure<AbpBackgroundJobOptions>(options =>
        {
            options.IsJobExecutionEnabled = false; // Let's assume the configuration returned false
            options.AddJob<SendGridMailerJob>(); // This processes the emails needing to be send by SendGrid
            options.AddJob<UpdateTrackServiceJob>(); // This processes 'Tracking' information that needs to be forwarded to an external API
        });

Justification: We need the ability to completely disable background job processing. One major factor here is being able to process the jobs locally with debugging enabled in order to verify or troubleshoot in case we see anything going wrong on Production. The assumption is that at this moment "we/our code" is the only process that is working on the (pending) background jobs.

Behavior: Jobs are set to IsAbandoned = true no logging is produced, no exceptions are seemingly captured. Enabling output logging on our DbContext also shows no SQL responsible for performing the UPDATE, yet refreshing the table you can see that RetryCount = 1 and IsAbandoned = true.

Analysis: When an exception does occur, we can immediately see output logging, and the job is retried several tries before IsAbandoned = true is set. However on "these special occasions" it is set immediately after the first try. NextTryTime is not adjusted and the RetryCount is never increased afterwards.

Hypothesis: Are there other DbContext at play that are querying and writing to the **AbpBackgroundJobs** table? How can we verify this? What could we overwrite or configure to visualize this behavior with logging?

Conclusion: We are stumped, we cannot explain this behavior. Luckily the source code is on GitHub, so we figured it is time to start overriding some code or classes to see if we can learn anything about background behavior in ABP.

Remove all Interface and Concrete Types from Autofac/Services that we believe are relevant to Background processing.

This is being called in PostConfigureServices in our own module, which we believe is loaded and processed last in the chain. We are highly skeptical about having this code here, but we also are unable to verify if ReplaceServices and/or ReplaceContext is enough.

        context.Services.RemoveAll[IBackgroundWorker]();
        context.Services.RemoveAll[IBackgroundJobWorker]();
        context.Services.RemoveAll[IBackgroundJobManager]();

        context.Services.RemoveAll[BackgroundJobWorker]();
        context.Services.RemoveAll[BackgroundEmailSendingJob]();
        context.Services.RemoveAll[NullBackgroundJobManager]();
        context.Services.RemoveAll[DefaultBackgroundJobManager]();

Justification: We want to intercept all the calls being made so we can add logging output and observe behavior about background jobs being picked up. We also want to make sure that "our" worker is the only process actually processing background jobs (see next section).

Behavior: Jobs are still set to IsAbandoned = true and again no logging is produced when this occurs.

Conclusion: We need to implement our own BackgroundWorker and add more logging to understand what is happening.

Implement AcmeBackgroundWorker and register it

We created our own AcmeBackgroundWorker class and copied the BackgroundJobWorker class line by line to ensure we are compliant and also because I am not going to pretend to understand every bit of code in there (we do, but that's not the point). We've extended the ExecuteAsync method and added verbose logging.

This is how the class is currently defined:

[Dependency(ReplaceServices = true)]
public sealed class AcmeBackgroundWorker : AsyncPeriodicBackgroundWorkerBase, IBackgroundJobWorker, IBackgroundWorker
{
    // Implementation
}

        // In the same 'PostConfigureServices' block as shown above at the end we then added
        context.Services.AddTransient<IBackgroundWorker, AcmeBackgroundWorker>(); // Not sure if both is needed but we saw both in the ServiceCollection
        context.Services.AddTransient<IBackgroundJobWorker, AcmeBackgroundWorker>(); // Not sure if both is needed but we saw both in the ServiceCollection
        context.Services.AddTransient<IBackgroundJobManager, DefaultBackgroundJobManager>(); // This just queues the messages, so can be restored originally

Justification: We intially thought that the ReplaceServices would be enough to override everything, but since the jobs are still being processed by a ghost worker, we left it despite the fact we are already manually calling RemoveAll.

These are the parts were we added our own logging just to see what is happening, both when everything goes right, but especially when things go wrong (i.e. an Exception is thrown).

            var pendingJobs = await _acmeService.GetPendingBackgroundJobsAsync();

            // Let's output how many jobs are pending
            Logger.LogInformation("[AcmeBackgroundWorker] Retrieved '{jobCount}' pending background job(s).", pendingJobs.Count);

            if (pendingJobs.IsNullOrEmpty()) return;
            
            // <snip>
            
            // We will log which Job is being called to process the message
            Logger.LogInformation("[AcmeBackgroundWorker] Executing {jobType}.ExecuteAsync()...", currentJob.JobName);
            
            // <Execute the registered Job instance to process the job>

            // We will indicate when all is successful and thus the job will be removed from the table
            Logger.LogInformation("[AcmeBackgroundWorker] Deleting successfully executed '{jobType}' job.", currentJob.JobName);
            
            // <snip>
            
            // This is code where the Exceptions are 'caught' and IsAbandoned is set to 'true' by the Worker (2 occurences)
            Logger.LogWarning("[AcmeBackgroundWorker] Setting IsAbandoned = true for '{jobType}'.", currentJob.JobName);

Justification: We used LogInformation as we want to be able to see these messages on Production, normally this would be regarded as debug output. We also added these specific statements, almost to the point of over completeness, because we really wanted to have this verbose output whenever a job is being processed.

Behavior: When it "works normally" and if an exception is thrown logging output is shown as expected. But when the ghost worker has done something no output is produced, breakpoints inside our worker are never hit, but the result is still that IsAbandoned = true is written to the DB. Meanwhile in the logs we can see the following:

2024-04-10 11:59:43.856 +02:00 [INF] [AcmeBackgroundWorker] Retrieved '0' pending background job(s).
2024-04-10 11:59:48.869 +02:00 [INF] [AcmeBackgroundWorker] Retrieved '0' pending background job(s).

According to our worker instance there were no pending jobs, even when we set the BackgroundJob to IsAbandoned = 0 using SQL directly. When doing a SELECT right after the UPDATE we can see that IsAbandoned is 0. No breakpoints are triggered, and doing a SELECT right after shows that IsAbandoned is set to 1. All the while the logs are only showing our own custom added logging output, ABP by itself produces zero logging when background job processing seemingly fails.

Conclusion: We are completely flabbergasted what is processing the AbpBackgroundJobs table, considering we believe that we eliminated "everything" from the pipeline?

Update: Resetting 272 failed BackgroundJobs

We currently have 272 failed BackgroundJobs stored in the database. So we figured, why not execute a SQL script that will effectively reset all the jobs back to their initial state so they can be reprocessed by our worker.

The SQL we executed is as follows:

UPDATE [AbpBackgroundJobs]
SET LastTryTime = NULL, TryCount = 0, NextTryTime = GETDATE(), IsAbandoned = 0

272 row(s) affected

Then we wait and observe what the logfiles are telling us:

2024-04-10 13:25:08.255 +02:00 [INF] [AcmeBackgroundWorker] Retrieved '172' pending background job(s).

If we then look in the database we can see that exactly 100 BackgroundJob rows are IsAbandoned = true with RetryCount = 1 and these records thus never made it to our AcmeBackgroundWorker. So what has picked up this data? Why were they flagged as unprocesable?

We repeated this process several times and each time only a portion of background jobs is processed, the rest is abandoned. After about 4 retries the queue is now fully depleted and all messages are seemingly processed, resulting in an empty AbpBackgroundJobs table.

Prologue

What else can we do? Override the store? Create our own tables and completely disable ABP Background Job feature? We also did a ReplaceContext for the BackgroundJob module, but still we cannot see any SQL output in the console that involves doing an UPDATE on that table. Perhaps because we set that up wrong and our understanding of ABP plumbing is too underdeveloped at this stage.

I sincerely hope you are able to share some thoughts and insights to provide a direction for the next steps we can do to try to figure this out. We are probably going to make a small management page to see the current abandoned jobs and add a feature to retry them, so we can at least process the 'deadletter' queue this way, but we are still completely puzzled what part of ABP is querying this table, despite us believing that only our worker should be handling this table.

Add setting to disable Background Job processing

Remove all Interface and Concrete Types from Autofac/Services that we believe are relevant to Background processing.

Implement AcmeBackgroundWorker and register it

Update: Resetting 272 failed BackgroundJobs

Prologue

6 Answer(s)