Unhandled GoodJob::AdvisoryLockable::RecordAlreadyAdvisoryLockedError errors

[JoeSouthan]

Hello!

We're seeing a high number of GoodJob::AdvisoryLockable::RecordAlreadyAdvisoryLockedError which seems to happen with one of our crons that runs every 10 minutes.

We run a few different queues under separate deployments with the --enable-cron flag set on all. As they're share the same cron config, I assume they all try to create the same cronjob and end up raising the exception.

Couple of questions

• Is this the right way to have our workers set up or should one worker group have the --enable-cron flag set?
• Should this exception be handled by GoodJob itself and ignored?

GoodJob::AdvisoryLockable::RecordAlreadyAdvisoryLockedError
good_job (4.1.0) app/models/concerns/good_job/advisory_lockable.rb in advisory_lock!

ActiveRecord::RecordInvalid: Record invalid (ActiveRecord::RecordInvalid)
  from good_job (4.1.0) app/models/concerns/good_job/advisory_lockable.rb:137:in `block (2 levels) in <module:AdvisoryLockable>'
  from activesupport (7.1.3.4) lib/active_support/callbacks.rb:448:in `instance_exec'
  from activesupport (7.1.3.4) lib/active_support/callbacks.rb:448:in `block in make_lambda'
  from activesupport (7.1.3.4) lib/active_support/callbacks.rb:239:in `block in halting_and_conditional'
  from activesupport (7.1.3.4) lib/active_support/callbacks.rb:602:in `block in invoke_after'
  from activesupport (7.1.3.4) lib/active_support/callbacks.rb:602:in `each'
  from activesupport (7.1.3.4) lib/active_support/callbacks.rb:602:in `invoke_after'
  from activesupport (7.1.3.4) lib/active_support/callbacks.rb:111:in `run_callbacks'
  from activesupport (7.1.3.4) lib/active_support/callbacks.rb:952:in `_run_create_callbacks'
  from activerecord (7.1.3.4) lib/active_record/callbacks.rb:445:in `_create_record'
  from activerecord (7.1.3.4) lib/active_record/timestamp.rb:114:in `_create_record'
  from activerecord (7.1.3.4) lib/active_record/persistence.rb:1221:in `create_or_update'
  from activerecord (7.1.3.4) lib/active_record/callbacks.rb:441:in `block in create_or_update'
  from activesupport (7.1.3.4) lib/active_support/callbacks.rb:121:in `block in run_callbacks'
  from activerecord (7.1.3.4) lib/active_record/autosave_association.rb:375:in `around_save_collection_association'
  from activesupport (7.1.3.4) lib/active_support/callbacks.rb:130:in `block in run_callbacks'
  from activesupport (7.1.3.4) lib/active_support/callbacks.rb:141:in `run_callbacks'
  from activesupport (7.1.3.4) lib/active_support/callbacks.rb:952:in `_run_save_callbacks'
  from activerecord (7.1.3.4) lib/active_record/callbacks.rb:441:in `create_or_update'
  from activerecord (7.1.3.4) lib/active_record/timestamp.rb:125:in `create_or_update'
  from activerecord (7.1.3.4) lib/active_record/persistence.rb:751:in `save!'
  from activerecord (7.1.3.4) lib/active_record/validations.rb:55:in `save!'
  from activerecord (7.1.3.4) lib/active_record/transactions.rb:313:in `block in save!'
  from activerecord (7.1.3.4) lib/active_record/transactions.rb:365:in `block in with_transaction_returning_status'
  from activerecord (7.1.3.4) lib/active_record/connection_adapters/abstract/transaction.rb:535:in `block in within_new_transaction'
  from activesupport (7.1.3.4) lib/active_support/concurrency/null_lock.rb:9:in `synchronize'
  from activerecord (7.1.3.4) lib/active_record/connection_adapters/abstract/transaction.rb:532:in `within_new_transaction'
  from activerecord (7.1.3.4) lib/active_record/connection_adapters/abstract/database_statements.rb:344:in `transaction'
  from activerecord (7.1.3.4) lib/active_record/transactions.rb:361:in `with_transaction_returning_status'
  from activerecord (7.1.3.4) lib/active_record/transactions.rb:313:in `save!'
  from activerecord (7.1.3.4) lib/active_record/suppressor.rb:56:in `save!'
  from activerecord (7.1.3.4) lib/active_record/persistence.rb:55:in `create!'
  from good_job (4.1.0) app/models/good_job/process.rb:68:in `create_record'
  from good_job (4.1.0) lib/good_job/capsule_tracker.rb:92:in `block in register'
  from good_job (4.1.0) lib/good_job/capsule_tracker.rb:225:in `synchronize'
  from good_job (4.1.0) lib/good_job/capsule_tracker.rb:225:in `synchronize'
  from good_job (4.1.0) lib/good_job/capsule_tracker.rb:81:in `register'
  from good_job (4.1.0) lib/good_job/notifier/process_heartbeat.rb:19:in `block in register_process'
  from good_job (4.1.0) lib/good_job/overridable_connection.rb:26:in `override_connection'
  from good_job (4.1.0) lib/good_job/notifier/process_heartbeat.rb:17:in `register_process'
  from activesupport (7.1.3.4) lib/active_support/callbacks.rb:403:in `block in make_lambda'
  from activesupport (7.1.3.4) lib/active_support/callbacks.rb:274:in `block in simple'
  from activesupport (7.1.3.4) lib/active_support/callbacks.rb:602:in `block in invoke_after'
  from activesupport (7.1.3.4) lib/active_support/callbacks.rb:602:in `each'
  from activesupport (7.1.3.4) lib/active_support/callbacks.rb:602:in `invoke_after'
  from activesupport (7.1.3.4) lib/active_support/callbacks.rb:111:in `run_callbacks'
  from good_job (4.1.0) lib/good_job/notifier.rb:209:in `block (3 levels) in create_listen_task'
  from activesupport (7.1.3.4) lib/active_support/execution_wrapper.rb:92:in `wrap'
  from good_job (4.1.0) lib/good_job/notifier.rb:208:in `block (2 levels) in create_listen_task'
  from good_job (4.1.0) lib/good_job/notifier.rb:263:in `with_connection'
  from good_job (4.1.0) lib/good_job/notifier.rb:204:in `block in create_listen_task'
  from concurrent-ruby (1.3.3) lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb:24:in `block in execute'
  from concurrent-ruby (1.3.3) lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48:in `block in synchronize'
  from concurrent-ruby (1.3.3) lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48:in `synchronize'
  from concurrent-ruby (1.3.3) lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48:in `synchronize'
  from concurrent-ruby (1.3.3) lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb:22:in `execute'
  from concurrent-ruby (1.3.3) lib/concurrent-ruby/concurrent/ivar.rb:170:in `safe_execute'
  from concurrent-ruby (1.3.3) lib/concurrent-ruby/concurrent/scheduled_task.rb:298:in `process_task'
  from concurrent-ruby (1.3.3) lib/concurrent-ruby/concurrent/executor/timer_set.rb:98:in `block in ns_post_task'
  from concurrent-ruby (1.3.3) lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:359:in `run_task'
  from concurrent-ruby (1.3.3) lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:350:in `block (3 levels) in create_worker'
  from <internal:kernel>:187:in `loop'
  from concurrent-ruby (1.3.3) lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:341:in `block (2 levels) in create_worker'
  from concurrent-ruby (1.3.3) lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:340:in `catch'
  from concurrent-ruby (1.3.3) lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:340:in `block in create_worker'

2024-07-21 13:30:00.009 UTC [1012601]: [4-1] db=foobar,user=foobar ERROR:  duplicate key value violates unique constraint "index_good_jobs_on_cron_key_and_cron_at_cond"	2024-07-21T13:30:00.013108Z
2024-07-21 13:30:00.009 UTC [990790]: [220-1] db=foobar,user=foobar ERROR:  duplicate key value violates unique constraint "index_good_jobs_on_cron_key_and_cron_at_cond"	2024-07-21T13:30:00.012784Z
2024-07-21 13:30:00.009 UTC [993687]: [214-1] db=foobar,user=foobar ERROR:  duplicate key value violates unique constraint "index_good_jobs_on_cron_key_and_cron_at_cond"	2024-07-21T13:30:00.012415Z
2024-07-21 13:30:00.009 UTC [980317]: [391-1] db=foobar,user=foobar ERROR:  duplicate key value violates unique constraint "index_good_jobs_on_cron_key_and_cron_at_cond"	2024-07-21T13:30:00.011862Z
2024-07-21 13:30:00.009 UTC [996295]: [199-1] db=foobar,user=foobar ERROR:  duplicate key value violates unique constraint "index_good_jobs_on_cron_key_and_cron_at_cond"	2024-07-21T13:30:00.011232Z
2024-07-21 13:30:00.009 UTC [972470]: [412-1] db=foobar,user=foobar ERROR:  duplicate key value violates unique constraint "index_good_jobs_on_cron_key_and_cron_at_cond"	2024-07-21T13:30:00.010226Z
2024-07-21 13:20:00.010 UTC [990790]: [217-1] db=foobar,user=foobar ERROR:  duplicate key value violates unique constraint "index_good_jobs_on_cron_key_and_cron_at_cond"	2024-07-21T13:20:00.013579Z
2024-07-21 13:20:00.009 UTC [993687]: [211-1] db=foobar,user=foobar ERROR:  duplicate key value violates unique constraint "index_good_jobs_on_cron_key_and_cron_at_cond"	2024-07-21T13:20:00.013265Z
2024-07-21 13:20:00.009 UTC [972470]: [409-1] db=foobar,user=foobar ERROR:  duplicate key value violates unique constraint "index_good_jobs_on_cron_key_and_cron_at_cond"	2024-07-21T13:20:00.012758Z
2024-07-21 13:20:00.009 UTC [980317]: [388-1] db=foobar,user=foobar ERROR:  duplicate key value violates unique constraint "index_good_jobs_on_cron_key_and_cron_at_cond"	2024-07-21T13:20:00.012437Z
2024-07-21 13:20:00.009 UTC [1012016]: [7-1] db=foobar,user=foobar ERROR:  duplicate key value violates unique constraint "index_good_jobs_on_cron_key_and_cron_at_cond"	2024-07-21T13:20:00.012121Z
2024-07-21 13:20:00.009 UTC [996295]: [196-1] db=foobar,user=foobar ERROR:  duplicate key value violates unique constraint "index_good_jobs_on_cron_key_and_cron_at_cond"	2024-07-21T13:20:00.011220Z

[bensheldon]

Thanks for opening this issue. And for sharing the stack traces! Super helpful 🙇

I think the GoodJob::AdvisoryLockable::RecordAlreadyAdvisoryLockedError is unrelated to the duplicate key value violates unique constraint.

• duplicate key value violates unique constraint is just how cron works. It's too bad they litter up the logs, but that's totally normal. That's how GoodJob prevents cron running in multiple instances from enqueuing duplicate jobs. If you're able to only enable Cron on a single process, you won't see them, but they are expected when running multiple processes and not indicative anything is wrong.
• GoodJob::AdvisoryLockable::RecordAlreadyAdvisoryLockedError is unexpected/exceptional. Though I think you're seeing it every 10 minutes because... well, I don't know exactly. But I strongly believe it's unrelated to cron.

From your stacktrace (very helpful!) the GoodJob::AdvisoryLockable::RecordAlreadyAdvisoryLockedError exception is happening when the heartbeat tries to register itself. It's weird that the record would already be advisory locked. Because that would indicate that the record was previously locked by this process, and the database connection that owns that lock is still connected, but it's just... a different database connection now. That shouldn't happen:

good_job/lib/good_job/notifier.rb

Lines 264 to 265 in fa3660d

	ensure
	connection&.disconnect!

I'm planning to remove that advisory lock in the heartbeat, because it is very unstable in production environments. That's tracked in #1447

[JoeSouthan]

Many thanks for taking a look at this, we'll track the other issue 👍