HangfireIO / HangfireIO/Hangfire

Multiple workers executing the same job

Open
#1,183 3 comments 4 reactions 0 assignees View on GitHub
Dominant language
C#
Stars
10.1k
Forks
1.8k
Avg merge
1h 19m
Merged PRs (30d)
1

Description

We are performing robustness testing before deploying a new solution which is based on Hangfire 1.6.19. We have identified a troublesome issue when testing database outage (we are using SQL Server).

**Background**
5 worker threads.
A recurring job periodically checks a inbox folder for subfolders.
Each subfolder is enqueued as a new job, which is to safely move (first copy then delete source) the subfolder to a "processing" folder. In our test case there are 7 such subfolders, and some of them are very large (copying takes > 1 minute).
When the safe move is completed, a "ContinueWith" job is registered for processing of the moved subfolder.
Automatic Retry (5 times) is enabled for the methods.

**Test**
The recurring job starts and enqueues 7 jobs. 5 of those start processing.
Take the Hangfire databas offline. After about 30 seconds take it back online.

**Result**
The 2 large safe move jobs keep processing (lets call these A and B). 3 smaller safe move jobs complete so 3 worker threads are free. Now, 2 of those worker threads start processing the jobs A and B, despite that 2 other worker threads are already processing them. We get mulitple Processing entries on those jobs in the dashboard, and the jobs fail miserably (but they state Success). This is because the copy and delete operations conflict with each other.

We have strived to make the job methods reentrant. But they are not safe for multiple workers executing the very same job simultaneously! And we do not believe that this is intended behavior from Hangfire.

**Workaround**
We made a temporary solution where we reduced the number of worker threads to 1, but would rather like to see a proper fix.

**Analysis**
From looking at detailed logging of the events, our best guess is that this occurs when the fast jobs finish but the SQL Server is not available, so the state change from Processing to Succeeded cannot be stored in the database. We get the following logs:

> 16 May 2018 21:07:10.092 Job 59 state was changed from Enqueued to Processing
> 16 May 2018 21:07:10.092 Job 59 state Enqueued was unapplied
> 16 May 2018 21:07:10.092 Job 58 state was changed from Processing to Processing
> 16 May 2018 21:07:10.092 Job 58 state Processing was unapplied
> 16 May 2018 21:07:10.091 Job 57 state was changed from Processing to Processing
> 16 May 2018 21:07:10.090 Job 57 state Processing was unapplied
> 16 May 2018 21:07:10.085 Error occurred during execution of 'Worker #07364b25' process. Execution will be retried (attempt #1) in 00:00:00 seconds.
> 16 May 2018 21:07:10.084 Failed to immediately re-queue the background job '55'. Next invocation may be delayed, if invisibility timeout is used
> 16 May 2018 21:07:10.084 An exception occurred while processing a job. It will be re-queued.
> 16 May 2018 21:07:10.084 Error occurred during execution of 'Worker #44996087' process. Execution will be retried (attempt #1) in 00:00:00 seconds.
> 16 May 2018 21:07:10.083 Failed to immediately re-queue the background job '54'. Next invocation may be delayed, if invisibility timeout is used
> 16 May 2018 21:07:10.083 An exception occurred while processing a job. It will be re-queued.
> 16 May 2018 21:07:10.082 Error occurred during execution of 'Worker #442517b2' process. Execution will be retried (attempt #1) in 00:00:00 seconds.
> 16 May 2018 21:07:10.082 Failed to immediately re-queue the background job '56'. Next invocation may be delayed, if invisibility timeout is used
> 16 May 2018 21:07:10.080 An exception occurred while processing a job. It will be re-queued.
> 16 May 2018 21:07:10.061 Job 55 state was changed from Processing to Succeeded
> 16 May 2018 21:07:10.060 Job 55 state Processing was unapplied
> 16 May 2018 21:07:10.014 Job 56 state was changed from Processing to Succeeded
> 16 May 2018 21:07:10.013 Job 56 state Processing was unapplied
> 16 May 2018 21:07:10.008 Job 54 state was changed from Processing to Succeeded
> 16 May 2018 21:07:10.008 Job 54 state Processing was unapplied

Job 57 and 58 are the slower jobs, and we see that state changes from Processing to Processing for those. Since new jobs cannot be fetched from the database, is there some local cache in play here that tricks the workers into starting jobs that are already processing?

I have seen multiple issues here related to jobs executing multiple times (#1025, #590), and I think it occurs more frequently than "very rarely" as in the documentation. Hopefully the above logs might help to find the root cause.

If you need more logging, just let me know.

Contributor guide

Open the contributing guide

Research direction

Start with the worker processing flow and the state changes described in the logs, then reproduce the outage against SQL Server with multiple workers and long-running jobs. Done means a database outage does not cause the same job to execute concurrently or report an incorrect final state.

Written by the indexing model from the issue text.

Assessment

Tech stack
csharp, sql
Domain
backend, databases, distributed-systems
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Mostly clear
Newbie friendliness
28/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.