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