Job runner process enters a loop on create_listen_task - stale check fails #1649
Description
Ran into a very weird situation today - good_job process was stuck on LISTEN / failure / UNLISTEN loop.
It looks like updated_at value was nil on a good_job_processes instance. Which should not be possible - the table has a NOT NULL constraint on updated_at.
The only place that seems to nullify updated_at is Process#refresh rescue block - but that should not be a one-time thing, reset after next DB lookup? In my case the loop persisted for multiple hours.
I'm honestly very puzzled on how this could have happened. Some issue with activerecord cache maybe? One-in-a-very-large-number cosmic ray bit flip? Unfortunately I restarted the process (and therefore deleted the row) before looking at what the process entry actually looked like in the database.
Stack trace sample - this went on repeating:
E, [2025-06-12T09:31:27.483661 #1] ERROR -- : [GoodJob] Notifier errored: NoMethodError: undefined method `<' for nil
"/usr/local/bundle/ruby/3.3.0/gems/good_job-4.3.0/app/models/good_job/process.rb:124:in `stale?'"
"/usr/local/bundle/ruby/3.3.0/gems/good_job-4.3.0/app/models/good_job/process.rb:112:in `refresh_if_stale'"
"/usr/local/bundle/ruby/3.3.0/gems/good_job-4.3.0/lib/good_job/capsule_tracker.rb:148:in `block (2 levels) in renew'"
"/usr/local/bundle/ruby/3.3.0/gems/good_job-4.3.0/app/models/good_job/base_record.rb:40:in `with_logger_silenced'"
"/usr/local/bundle/ruby/3.3.0/gems/good_job-4.3.0/lib/good_job/capsule_tracker.rb:147:in `block in renew'"
"/usr/local/bundle/ruby/3.3.0/gems/good_job-4.3.0/lib/good_job/capsule_tracker.rb:225:in `synchronize'"
"/usr/local/bundle/ruby/3.3.0/gems/good_job-4.3.0/lib/good_job/capsule_tracker.rb:225:in `synchronize'"
"/usr/local/bundle/ruby/3.3.0/gems/good_job-4.3.0/lib/good_job/capsule_tracker.rb:146:in `renew'"
"/usr/local/bundle/ruby/3.3.0/gems/good_job-4.3.0/lib/good_job/notifier/process_heartbeat.rb:28:in `block (3 levels) in refresh_process'"
"/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.2.2.1/lib/active_support/logger_silence.rb:18:in `block in silence'"
"/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.2.2.1/lib/active_support/logger_thread_safe_level.rb:37:in `log_at'"
"/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.2.2.1/lib/active_support/logger_silence.rb:18:in `silence'"
"/usr/local/bundle/ruby/3.3.0/gems/good_job-4.3.0/app/models/good_job/base_record.rb:38:in `with_logger_silenced'"
"/usr/local/bundle/ruby/3.3.0/gems/good_job-4.3.0/lib/good_job/notifier/process_heartbeat.rb:27:in `block (2 levels) in refresh_process'"
"/usr/local/bundle/ruby/3.3.0/gems/good_job-4.3.0/lib/good_job/overridable_connection.rb:26:in `override_connection'"
"/usr/local/bundle/ruby/3.3.0/gems/good_job-4.3.0/lib/good_job/notifier/process_heartbeat.rb:26:in `block in refresh_process'"
"/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.2.2.1/lib/active_support/execution_wrapper.rb:87:in `wrap'"
"/usr/local/bundle/ruby/3.3.0/gems/good_job-4.3.0/lib/good_job/notifier/process_heartbeat.rb:25:in `refresh_process'"
"/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.2.2.1/lib/active_support/callbacks.rb:362:in `block in make_lambda'"
"/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.2.2.1/lib/active_support/callbacks.rb:179:in `block in call'"
"/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.2.2.1/lib/active_support/callbacks.rb:668:in `block (2 levels) in default_terminator'"
"/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.2.2.1/lib/active_support/callbacks.rb:667:in `catch'"
"/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.2.2.1/lib/active_support/callbacks.rb:667:in `block in default_terminator'"
"/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.2.2.1/lib/active_support/callbacks.rb:180:in `call'"
"/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.2.2.1/lib/active_support/callbacks.rb:559:in `block in invoke_before'"
"/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.2.2.1/lib/active_support/callbacks.rb:559:in `each'"
"/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.2.2.1/lib/active_support/callbacks.rb:559:in `invoke_before'"
"/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.2.2.1/lib/active_support/callbacks.rb:109:in `run_callbacks'"
"/usr/local/bundle/ruby/3.3.0/gems/good_job-4.3.0/lib/good_job/notifier.rb:220:in `block (3 levels) in create_listen_task'"
"/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.2.2.1/lib/active_support/execution_wrapper.rb:91:in `wrap'"
"/usr/local/bundle/ruby/3.3.0/gems/good_job-4.3.0/lib/good_job/notifier.rb:220:in `block (2 levels) in create_listen_task'"
"/usr/local/bundle/ruby/3.3.0/gems/good_job-4.3.0/lib/good_job/notifier.rb:263:in `with_connection'"
"/usr/local/bundle/ruby/3.3.0/gems/good_job-4.3.0/lib/good_job/notifier.rb:204:in `block in create_listen_task'"
"/usr/local/bundle/ruby/3.3.0/gems/concurrent-ruby-1.3.4/lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb:24:in `block in execute'"
"/usr/local/bundle/ruby/3.3.0/gems/concurrent-ruby-1.3.4/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48:in `block in synchronize'"
"/usr/local/bundle/ruby/3.3.0/gems/concurrent-ruby-1.3.4/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48:in `synchronize'"
"/usr/local/bundle/ruby/3.3.0/gems/concurrent-ruby-1.3.4/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48:in `synchronize'"
"/usr/local/bundle/ruby/3.3.0/gems/concurrent-ruby-1.3.4/lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb:22:in `execute'"
"/usr/local/bundle/ruby/3.3.0/gems/concurrent-ruby-1.3.4/lib/concurrent-ruby/concurrent/ivar.rb:170:in `safe_execute'"
"/usr/local/bundle/ruby/3.3.0/gems/concurrent-ruby-1.3.4/lib/concurrent-ruby/concurrent/scheduled_task.rb:298:in `process_task'"
"/usr/local/bundle/ruby/3.3.0/gems/concurrent-ruby-1.3.4/lib/concurrent-ruby/concurrent/executor/timer_set.rb:98:in `block in ns_post_task'"
"/usr/local/bundle/ruby/3.3.0/gems/newrelic_rpm-9.14.0/lib/new_relic/agent/tracer.rb:434:in `block (2 levels) in thread_block_with_current_transaction'"
"/usr/local/bundle/ruby/3.3.0/gems/newrelic_rpm-9.14.0/lib/new_relic/agent/tracer.rb:357:in `capture_segment_error'"
"/usr/local/bundle/ruby/3.3.0/gems/newrelic_rpm-9.14.0/lib/new_relic/agent/tracer.rb:433:in `block in thread_block_with_current_transaction'"
"/usr/local/bundle/ruby/3.3.0/gems/concurrent-ruby-1.3.4/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:359:in `run_task'"
"/usr/local/bundle/ruby/3.3.0/gems/concurrent-ruby-1.3.4/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:350:in `block (3 levels) in create_worker'"
"<internal:kernel>:187:in `loop'"
"/usr/local/bundle/ruby/3.3.0/gems/concurrent-ruby-1.3.4/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:341:in `block (2 levels) in create_worker'"
"/usr/local/bundle/ruby/3.3.0/gems/concurrent-ruby-1.3.4/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:340:in `catch'"
"/usr/local/bundle/ruby/3.3.0/gems/concurrent-ruby-1.3.4/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:340:in `block in create_worker'"
"/usr/local/bundle/ruby/3.3.0/gems/newrelic_rpm-9.14.0/lib/new_relic/agent/tracer.rb:434:in `block (2 levels) in thread_block_with_current_transaction'"
"/usr/local/bundle/ruby/3.3.0/gems/newrelic_rpm-9.14.0/lib/new_relic/agent/tracer.rb:357:in `capture_segment_error'"
"/usr/local/bundle/ruby/3.3.0/gems/newrelic_rpm-9.14.0/lib/new_relic/agent/tracer.rb:433:in `block in thread_block_with_current_transaction'"
I, [2025-06-12T09:31:27.490935 #1] INFO -- : [GoodJob] Notifier subscribed with LISTEN
I, [2025-06-12T09:31:27.535584 #1] INFO -- : [GoodJob] Notifier unsubscribed with UNLISTEN