Jobs end up in inconsistent state both completed and with a failed execution when completed during a graceful worker shutdown

[doctomarculescu]

Each time a solid queue supervisor receives a TERM signal the supervisor initiates graceful termination. By doing so, it sends a TERM signal to every worker process it supervises. This triggers the shutdown of the worker process :

• before_shutdown
• shutdown
• after_shutdown

Any Registrable process (workers are Registrable processes) execute stop_heartbeat in the shutdown hook before_shutdown
Only after that the worker shuts down the executor pool and waits for the shutdown_timeout for a graceful exits. This means workers stop heartbeating before shutting down. So during the graceful termination, they try to complete claimed jobs in flight, but other supervisors see them as dead and initiate pruning of a dead process, therefore failing jobs claimed by the worker.

The visible consequence of this bug is that we end up with completed jobs which also have an entry in failed executions. The occurrences can be easily detected by the following query in a rails console:

SolidQueue::Job.joins(:failed_execution)
               .where.not(finished_at: nil)
               .where.not(failed_execution: nil)

The fix seems very simple, move stop_heartbeat from the before_shutdown hook to after_shutdown. We validated the fix in our deployments by patching the module Registrable.

I can push the PR if this is acknowledged as the correct solution. Not entirely sure how to test it because there are no tests for the heartbeat functionality, I am thinking to add a test in the integration process_lifecycle_test.

[doctomarculescu]

@rosa are you comfortable with the suggested change?

[rosa]

Hey @doctomarculescu, sorry for the delay! I'm finally catching up on issues and PRs here.

What values are you setting for shutdown_timeout and process_heartbeat_interval to see this behaviour? I ask because with the defaults, it'd be very strange to see this. The process_heartbeat_interval is 60 seconds, and the shutdown_timeout is 5 seconds, so it'd be impossible for workers to miss the heartbeat and be considered dead. I think the shutdown timeout should always be smaller than the heartbeat interval to consider processes dead.

[doctomarculescu]

hey @rosa thank you for catching up on this!

our shutdown_timeout heavily depends on the job duration. To give you two examples: we have a pool where jobs run in less than 2 minutes, in this set of workers we set shutdown_timeout to 110 seconds. We have a pool where jobs run in less than...48 hours, where we set the timeout to a high number of seconds close to the number of seconds in 48 hours. We redeploy our worker pools 3 times a day so our worker pods almost always get signaled while they are processing jobs.

Therefore it is very hard to make sure the shutdown_timeout is always shorter than the process_heartbeat_interval.

This is why I suggested the fix : it handles gracefully all the possible cases of configuration.

What do you think?

[rosa]

Ahh, got it! I understand! I hadn't imagined this use case as you'd be potentially running outdated code for 48 hours, so you'd have to account for that. This makes sense, thanks for explaining!

[rosa]

Fixed by #569, thanks again @doctomarculescu!