Feedback for GoodJob Cron

[bensheldon]

I've published a short deep-dive into how GoodJob's Cron works, and this is the place to connect and discuss how it is (or isn't!) working for you 💖

[mtomov]

GoodJob is absolutely perfect! We're using it in with Renalware in one hospital for 6+ months - no issues, just works! Its cron capability has saved us a whole lot of DevOps trouble with Azure, as we have little control over the host environment.

Have used it with personal projects as well, with a simple Capistrano deployment - all great. I think the capistrano config for it should be something I need to contributete back .. on me.

Thank you so much 🙌 ! My go to choice for background jobs in Ruby!

[bensheldon]

Thank you for sharing! It makes me happy to know how you're using GoodJob! 💖

[mtomov]

https://github.com/mtomov/capistrano-good-job

Let me know of any feedback, especially on the systemd service.

There, I'm not sure about the signal for reload - not sure that's needed at all. I've set the restart to be the default command after deploy anyhow.

Thanks again for the great great library 🙌

[thomasdziedzic]

I've been using it for both personal and professional work, and it just works!

My only complaint right now is that the duplicate jobs created aren't silenced and show up as PG::UniqueViolation errors in my monitoring service. Is there a best practice for silencing those errors?

Thank you for the wonderfully engineered software!

[bensheldon]

Yay!

That's annoying about the exception though. Could you share the stacktrace that you're seeing?

GoodJob does rescue from ActiveRecord::RecordNotUnique when enqueuing, so I'm curious where the PG::UniqueViolation is coming from:

good_job/app/models/good_job/cron_entry.rb

Lines 110 to 113 in 994ecff

	kwargs_value.present? ? configured_job.perform_later(*args_value, **kwargs_value) : configured_job.perform_later(*args_value)
	end
	end
	rescue ActiveRecord::RecordNotUnique

[thomasdziedzic-calmwave]

It's coming from Datadog's ddtrace gem:

I'm not sure anything can be done with it without either disabling monitoring the postgres service or ignoring the error in datadog.

PG::UniqueViolation: ERROR:  duplicate key value violates unique constraint "index_good_jobs_on_cron_key_and_cron_at"
DETAIL:  Key (cron_key, cron_at)=(REDACTED, REDACTED) already exists.

/usr/local/bundle/gems/ddtrace-1.8.0/lib/datadog/tracing/contrib/pg/instrumentation.rb:31:in `exec_params': ERROR:  duplicate key value violates unique constraint "index_good_jobs_on_cron_key_and_cron_at"
DETAIL:  Key (cron_key, cron_at)=(REDACTED, REDACTED) already exists.
 (PG::UniqueViolation)
	from /usr/local/bundle/gems/ddtrace-1.8.0/lib/datadog/tracing/contrib/pg/instrumentation.rb:31:in `block in exec_params'
	from /usr/local/bundle/gems/ddtrace-1.8.0/lib/datadog/tracing/contrib/pg/instrumentation.rb:104:in `block in trace'
	from /usr/local/bundle/gems/ddtrace-1.8.0/lib/datadog/tracing/trace_operation.rb:194:in `block in measure'
	from /usr/local/bundle/gems/ddtrace-1.8.0/lib/datadog/tracing/span_operation.rb:152:in `measure'
	from /usr/local/bundle/gems/ddtrace-1.8.0/lib/datadog/tracing/trace_operation.rb:194:in `measure'
	from /usr/local/bundle/gems/ddtrace-1.8.0/lib/datadog/tracing/tracer.rb:382:in `start_span'
	from /usr/local/bundle/gems/ddtrace-1.8.0/lib/datadog/tracing/tracer.rb:162:in `block in trace'
	from /usr/local/bundle/gems/ddtrace-1.8.0/lib/datadog/tracing/context.rb:45:in `activate!'
	from /usr/local/bundle/gems/ddtrace-1.8.0/lib/datadog/tracing/tracer.rb:161:in `trace'
	from /usr/local/bundle/gems/ddtrace-1.8.0/lib/datadog/tracing.rb:18:in `trace'
	from /usr/local/bundle/gems/ddtrace-1.8.0/lib/datadog/tracing/contrib/pg/instrumentation.rb:83:in `trace'
	from /usr/local/bundle/gems/ddtrace-1.8.0/lib/datadog/tracing/contrib/pg/instrumentation.rb:30:in `exec_params'
	from /usr/local/bundle/gems/activerecord-7.0.4.1/lib/active_record/connection_adapters/postgresql_adapter.rb:768:in `block (2 levels) in exec_no_cache'
	from /usr/local/bundle/gems/activesupport-7.0.4.1/lib/active_support/concurrency/share_lock.rb:187:in `yield_shares'
	from /usr/local/bundle/gems/activesupport-7.0.4.1/lib/active_support/dependencies/interlock.rb:41:in `permit_concurrent_loads'
	from /usr/local/bundle/gems/activerecord-7.0.4.1/lib/active_record/connection_adapters/postgresql_adapter.rb:767:in `block in exec_no_cache'
	from /usr/local/bundle/gems/activesupport-7.0.4.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `handle_interrupt'
	from /usr/local/bundle/gems/activesupport-7.0.4.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `block in synchronize'
	from /usr/local/bundle/gems/activesupport-7.0.4.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'
	from /usr/local/bundle/gems/activesupport-7.0.4.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'
	from /usr/local/bundle/gems/activerecord-7.0.4.1/lib/active_record/connection_adapters/abstract_adapter.rb:765:in `block in log'
	from /usr/local/bundle/gems/activesupport-7.0.4.1/lib/active_support/notifications/instrumenter.rb:24:in `instrument'
	from /usr/local/bundle/gems/activerecord-7.0.4.1/lib/active_record/connection_adapters/abstract_adapter.rb:756:in `log'
	from /usr/local/bundle/gems/activerecord-7.0.4.1/lib/active_record/connection_adapters/postgresql_adapter.rb:766:in `exec_no_cache'
	from /usr/local/bundle/gems/activerecord-7.0.4.1/lib/active_record/connection_adapters/postgresql_adapter.rb:745:in `execute_and_clear'
	from /usr/local/bundle/gems/activerecord-7.0.4.1/lib/active_record/connection_adapters/postgresql/database_statements.rb:54:in `exec_query'
	from /usr/local/bundle/gems/activerecord-7.0.4.1/lib/active_record/connection_adapters/abstract/database_statements.rb:132:in `exec_insert'
	from /usr/local/bundle/gems/activerecord-7.0.4.1/lib/active_record/connection_adapters/postgresql/database_statements.rb:92:in `exec_insert'
	from /usr/local/bundle/gems/activerecord-7.0.4.1/lib/active_record/connection_adapters/abstract/database_statements.rb:167:in `insert'
	from /usr/local/bundle/gems/activerecord-7.0.4.1/lib/active_record/connection_adapters/abstract/query_cache.rb:22:in `insert'
	from /usr/local/bundle/gems/activerecord-7.0.4.1/lib/active_record/persistence.rb:496:in `_insert_record'
	from /usr/local/bundle/gems/activerecord-7.0.4.1/lib/active_record/persistence.rb:1096:in `_create_record'
	from /usr/local/bundle/gems/activerecord-7.0.4.1/lib/active_record/counter_cache.rb:166:in `_create_record'
	from /usr/local/bundle/gems/activerecord-7.0.4.1/lib/active_record/locking/optimistic.rb:79:in `_create_record'
	from /usr/local/bundle/gems/activerecord-7.0.4.1/lib/active_record/attribute_methods/dirty.rb:222:in `_create_record'
	from /usr/local/bundle/gems/activerecord-7.0.4.1/lib/active_record/callbacks.rb:461:in `block in _create_record'
	from /usr/local/bundle/gems/activesupport-7.0.4.1/lib/active_support/callbacks.rb:107:in `run_callbacks'
	from /usr/local/bundle/gems/activesupport-7.0.4.1/lib/active_support/callbacks.rb:929:in `_run_create_callbacks'
	from /usr/local/bundle/gems/activerecord-7.0.4.1/lib/active_record/callbacks.rb:461:in `_create_record'
	from /usr/local/bundle/gems/activerecord-7.0.4.1/lib/active_record/timestamp.rb:108:in `_create_record'
	from /usr/local/bundle/gems/activerecord-7.0.4.1/lib/active_record/persistence.rb:1067:in `create_or_update'
	from /usr/local/bundle/gems/activerecord-7.0.4.1/lib/active_record/callbacks.rb:457:in `block in create_or_update'
	from /usr/local/bundle/gems/activesupport-7.0.4.1/lib/active_support/callbacks.rb:107:in `run_callbacks'
	from /usr/local/bundle/gems/activesupport-7.0.4.1/lib/active_support/callbacks.rb:929:in `_run_save_callbacks'
	from /usr/local/bundle/gems/activerecord-7.0.4.1/lib/active_record/callbacks.rb:457:in `create_or_update'
	from /usr/local/bundle/gems/activerecord-7.0.4.1/lib/active_record/timestamp.rb:126:in `create_or_update'
	from /usr/local/bundle/gems/activerecord-7.0.4.1/lib/active_record/persistence.rb:648:in `save!'
	from /usr/local/bundle/gems/activerecord-7.0.4.1/lib/active_record/validations.rb:53:in `save!'
	from /usr/local/bundle/gems/activerecord-7.0.4.1/lib/active_record/transactions.rb:302:in `block in save!'
	from /usr/local/bundle/gems/activerecord-7.0.4.1/lib/active_record/transactions.rb:354:in `block in with_transaction_returning_status'
	from /usr/local/bundle/gems/activerecord-7.0.4.1/lib/active_record/connection_adapters/abstract/transaction.rb:319:in `block in within_new_transaction'
	from /usr/local/bundle/gems/activesupport-7.0.4.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `handle_interrupt'
	from /usr/local/bundle/gems/activesupport-7.0.4.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `block in synchronize'
	from /usr/local/bundle/gems/activesupport-7.0.4.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'
	from /usr/local/bundle/gems/activesupport-7.0.4.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'
	from /usr/local/bundle/gems/activerecord-7.0.4.1/lib/active_record/connection_adapters/abstract/transaction.rb:317:in `within_new_transaction'
	from /usr/local/bundle/gems/activerecord-7.0.4.1/lib/active_record/connection_adapters/abstract/database_statements.rb:316:in `transaction'
	from /usr/local/bundle/gems/activerecord-7.0.4.1/lib/active_record/transactions.rb:350:in `with_transaction_returning_status'
	from /usr/local/bundle/gems/activerecord-7.0.4.1/lib/active_record/transactions.rb:302:in `save!'
	from /usr/local/bundle/gems/activerecord-7.0.4.1/lib/active_record/suppressor.rb:54:in `save!'
	from /usr/local/bundle/gems/good_job-3.7.4/app/models/good_job/execution.rb:275:in `block in enqueue'
	from /usr/local/bundle/gems/activesupport-7.0.4.1/lib/active_support/notifications.rb:208:in `instrument'
	from /usr/local/bundle/gems/good_job-3.7.4/app/models/good_job/execution.rb:252:in `enqueue'
	from /usr/local/bundle/gems/good_job-3.7.4/lib/good_job/adapter.rb:52:in `enqueue_at'
	from /usr/local/bundle/gems/good_job-3.7.4/lib/good_job/adapter.rb:40:in `enqueue'
	from /usr/local/bundle/gems/activejob-7.0.4.1/lib/active_job/enqueuing.rb:67:in `block in enqueue'
	from /usr/local/bundle/gems/activesupport-7.0.4.1/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
	from /usr/local/bundle/gems/good_job-3.7.4/lib/good_job/active_job_extensions/concurrency.rb:59:in `block (3 levels) in <module:Concurrency>'
	from /usr/local/bundle/gems/good_job-3.7.4/app/models/good_job/lockable.rb:201:in `advisory_lock_key'
	from /usr/local/bundle/gems/good_job-3.7.4/lib/good_job/active_job_extensions/concurrency.rb:51:in `block (2 levels) in <module:Concurrency>'
	from /usr/local/bundle/gems/activesupport-7.0.4.1/lib/active_support/callbacks.rb:127:in `instance_exec'
	from /usr/local/bundle/gems/activesupport-7.0.4.1/lib/active_support/callbacks.rb:127:in `block in run_callbacks'
	from /usr/local/bundle/gems/activejob-7.0.4.1/lib/active_job/instrumentation.rb:25:in `block in instrument'
	from /usr/local/bundle/gems/activesupport-7.0.4.1/lib/active_support/notifications.rb:206:in `block in instrument'
	from /usr/local/bundle/gems/activesupport-7.0.4.1/lib/active_support/notifications/instrumenter.rb:24:in `instrument'
	from /usr/local/bundle/gems/activesupport-7.0.4.1/lib/active_support/notifications.rb:206:in `instrument'
	from /usr/local/bundle/gems/activejob-7.0.4.1/lib/active_job/instrumentation.rb:35:in `instrument'
	from /usr/local/bundle/gems/activejob-7.0.4.1/lib/active_job/instrumentation.rb:9:in `block (2 levels) in <module:Instrumentation>'
	from /usr/local/bundle/gems/activesupport-7.0.4.1/lib/active_support/callbacks.rb:127:in `instance_exec'
	from /usr/local/bundle/gems/activesupport-7.0.4.1/lib/active_support/callbacks.rb:127:in `block in run_callbacks'
	from /usr/local/bundle/gems/activesupport-7.0.4.1/lib/active_support/tagged_logging.rb:99:in `block in tagged'
	from /usr/local/bundle/gems/activesupport-7.0.4.1/lib/active_support/tagged_logging.rb:37:in `tagged'
	from /usr/local/bundle/gems/activesupport-7.0.4.1/lib/active_support/tagged_logging.rb:99:in `tagged'
	from /usr/local/bundle/gems/activejob-7.0.4.1/lib/active_job/logging.rb:25:in `tag_logger'
	from /usr/local/bundle/gems/activejob-7.0.4.1/lib/active_job/logging.rb:14:in `block (2 levels) in <module:Logging>'
	from /usr/local/bundle/gems/activesupport-7.0.4.1/lib/active_support/callbacks.rb:127:in `instance_exec'
	from /usr/local/bundle/gems/activesupport-7.0.4.1/lib/active_support/callbacks.rb:127:in `block in run_callbacks'
	from /usr/local/bundle/gems/activesupport-7.0.4.1/lib/active_support/callbacks.rb:138:in `run_callbacks'
	from /usr/local/bundle/gems/activejob-7.0.4.1/lib/active_job/enqueuing.rb:63:in `enqueue'
	from /usr/local/bundle/gems/activejob-7.0.4.1/lib/active_job/configured_job.rb:15:in `perform_later'
	from /usr/local/bundle/gems/good_job-3.7.4/app/models/good_job/cron_entry.rb:110:in `block (2 levels) in enqueue'
	from /usr/local/bundle/gems/i18n-1.12.0/lib/i18n.rb:322:in `with_locale'
	from /usr/local/bundle/gems/good_job-3.7.4/app/models/good_job/cron_entry.rb:109:in `block in enqueue'
	from /usr/local/bundle/gems/good_job-3.7.4/lib/good_job/current_thread.rb:84:in `within'
	from /usr/local/bundle/gems/good_job-3.7.4/app/models/good_job/cron_entry.rb:104:in `enqueue'
	from /usr/local/bundle/gems/good_job-3.7.4/lib/good_job/cron_manager.rb:92:in `block (2 levels) in create_task'
	from /usr/local/bundle/gems/activesupport-7.0.4.1/lib/active_support/execution_wrapper.rb:92:in `wrap'
	from /usr/local/bundle/gems/good_job-3.7.4/lib/good_job/cron_manager.rb:91:in `block in create_task'
	from /usr/local/bundle/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb:24:in `block in execute'
	from /usr/local/bundle/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:47:in `block in synchronize'
	from /usr/local/bundle/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:47:in `synchronize'
	from /usr/local/bundle/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:47:in `synchronize'
	from /usr/local/bundle/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb:22:in `execute'
	from /usr/local/bundle/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/ivar.rb:169:in `safe_execute'
	from /usr/local/bundle/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/scheduled_task.rb:298:in `process_task'
	from /usr/local/bundle/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/timer_set.rb:165:in `block (2 levels) in process_tasks'
	from /usr/local/bundle/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:352:in `run_task'
	from /usr/local/bundle/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:343:in `block (3 levels) in create_worker'
	from /usr/local/bundle/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:334:in `loop'
	from /usr/local/bundle/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:334:in `block (2 levels) in create_worker'
	from /usr/local/bundle/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:333:in `catch'
	from /usr/local/bundle/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:333:in `block in create_worker'

[bensheldon]

oh yeah, that's a bummer that Datadog is reporting the exception where it's emitted. I guess that makes sense from an "all exceptions should be exceptional / don't use exceptions for control flow", but is also very aggressive when one doesn't have control over the entire stack.

I think that instrumentation is problematic because there's plenty of completely normal collisions (e.g. Rails find_or_create_by) that rely upon failed inserts to function because of a lack of atomicity.

...for those reasons, if it's possible to silence just that exception at that level of tracing, I'd recommend that because I would expect either Active Record or your application to ultimately capture/re-raise or fail higher up because of it.

[blocknotes]

Hey 👋
We had the same error (duplicate key value violates unique constraint) in one of our project.
At the end we found out that we were using execution_mode option set to async. We have 2 containers for the web server and 1 for the jobs so it was trying to execute the same job on 2 different containers.
Setting execution_mode back to external for production solved the issue.

[bensheldon]

@blocknotes thanks for the comment. That's the other way to address this error: narrow down the configuration so truly only one cron process is running. I wish it wasn't necessary though because the PG::UniqueViolation is expected/okay behavior when running more than one process: that's intended to be how duplicate cron runs are prevented. It seems like ddtrace-rb is the one who is making more of a stink about it than it actually requires 😞

[coorasse]

I am currently facing a simular issue. I have two nodes, running cron jobs. Every minute every this code fails on one of the two nodes.

Failed enqueuing MyCronJob to GoodJob(cron_jobs): ActiveRecord::RecordNotUnique (PG::UniqueViolation: ERROR: duplicate key value violates unique constraint "index_good_jobs_on_cron_key_and_cron_at" DETAIL: Key (cron_key, cron_at)=(my_cron_jobs, 2024-01-08 13:52:00) already exists. )