NoMethodError: undefined method `<' for nil (process.rb:125 in stale?)

[rgaufman]

Since doing a recent bundle update I am getting these exceptions randomly from random servers:

/gems/good_job-3.29.2/app/models/good_job/process.rb:125 in stale?
/gems/good_job-3.29.2/app/models/good_job/process.rb:113 in refresh_if_stale
/gems/good_job-3.29.2/lib/good_job/capsule_tracker.rb:147 in block in renew
/gems/good_job-3.29.2/app/models/good_job/base_record.rb:39 in with_logger_silenced
/gems/good_job-3.29.2/lib/good_job/capsule_tracker.rb:146 in renew
/gems/good_job-3.29.2/lib/good_job/notifier/process_heartbeat.rb:27 in block (3 levels) in refresh_process
vendor/cache/semantic_logger-7f57034695ec/lib/semantic_logger/semantic_logger.rb:463 in silence
vendor/cache/semantic_logger-7f57034695ec/lib/semantic_logger/base.rb:236 in silence
/gems/good_job-3.29.2/app/models/good_job/base_record.rb:37 in with_logger_silenced
/gems/good_job-3.29.2/lib/good_job/notifier/process_heartbeat.rb:26 in block (2 levels) in refresh_process
/gems/good_job-3.29.2/lib/good_job/overridable_connection.rb:26 in override_connection
/gems/good_job-3.29.2/lib/good_job/notifier/process_heartbeat.rb:25 in block in refresh_process
/gems/activesupport-7.1.3.3/lib/active_support/execution_wrapper.rb:88 in wrap
/gems/good_job-3.29.2/lib/good_job/notifier/process_heartbeat.rb:24 in refresh_process
/gems/activesupport-7.1.3.3/lib/active_support/callbacks.rb:403 in block in make_lambda
/gems/activesupport-7.1.3.3/lib/active_support/callbacks.rb:202 in block (2 levels) in halting
/gems/activesupport-7.1.3.3/lib/active_support/callbacks.rb:707 in block (2 levels) in default_terminator
/gems/activesupport-7.1.3.3/lib/active_support/callbacks.rb:706 in catch
/gems/activesupport-7.1.3.3/lib/active_support/callbacks.rb:706 in block in default_terminator
/gems/activesupport-7.1.3.3/lib/active_support/callbacks.rb:203 in block in halting
/gems/activesupport-7.1.3.3/lib/active_support/callbacks.rb:598 in block in invoke_before
/gems/activesupport-7.1.3.3/lib/active_support/callbacks.rb:598 in each
/gems/activesupport-7.1.3.3/lib/active_support/callbacks.rb:598 in invoke_before
/gems/activesupport-7.1.3.3/lib/active_support/callbacks.rb:109 in run_callbacks
/gems/good_job-3.29.2/lib/good_job/notifier.rb:217 in block (3 levels) in create_listen_task
/gems/activesupport-7.1.3.3/lib/active_support/execution_wrapper.rb:92 in wrap
/gems/good_job-3.29.2/lib/good_job/notifier.rb:217 in block (2 levels) in create_listen_task
/gems/good_job-3.29.2/lib/good_job/notifier.rb:260 in with_connection
/gems/good_job-3.29.2/lib/good_job/notifier.rb:201 in block in create_listen_task
/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb:24 in block in execute
/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48 in block in synchronize
/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48 in synchronize
/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48 in synchronize
/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb:22 in execute
/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/ivar.rb:170 in safe_execute
/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/scheduled_task.rb:298 in process_task
/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/timer_set.rb:98 in block in ns_post_task
/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:359 in run_task
/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:350 in block (3 levels) in create_worker
<internal:kernel>:187 in loop
/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:341 in block (2 levels) in create_worker
/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:340 in catch
/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:340 in block in create_worker

Any ideas what could be causing this?

[bensheldon]

Thanks for the bug report! That's strange. Here's the line in question:

good_job/app/models/good_job/process.rb

Line 125 in 923778d

updated_at < STALE_INTERVAL.ago

...the exception would imply that the Process record hasn't been persisted. Which is unexpected!

I'll dig into what might be happening here. That's weird!

[pozzer]

I'm experiencing the same issue. Here are some details about my setup:

GoodJob version: 3.29.2
Rails version: 7.0.8
Ruby version: 3.3.0

[bensheldon]

Quick question, are you seeing these exceptions all come from the same place in the stacktrace? Particularly these first 6 lines?

/gems/good_job-3.29.2/app/models/good_job/process.rb:125 in stale?
/gems/good_job-3.29.2/app/models/good_job/process.rb:113 in refresh_if_stale
/gems/good_job-3.29.2/lib/good_job/capsule_tracker.rb:147 in block in renew
/gems/good_job-3.29.2/app/models/good_job/base_record.rb:39 in with_logger_silenced
/gems/good_job-3.29.2/lib/good_job/capsule_tracker.rb:146 in renew
/gems/good_job-3.29.2/lib/good_job/notifier/process_heartbeat.rb:27 in block (3 levels) in refresh_process

[pozzer]

Yes, same stacktrace.

stale?(/usr/local/bundle/gems/good_job-3.29.2/app/models/good_job/process.rb:125)
refresh_if_stale(/usr/local/bundle/gems/good_job-3.29.2/app/models/good_job/process.rb:113)
block in renew(/usr/local/bundle/gems/good_job-3.29.2/lib/good_job/capsule_tracker.rb:147)
with_logger_silenced(/usr/local/bundle/gems/good_job-3.29.2/app/models/good_job/base_record.rb:39)
renew(/usr/local/bundle/gems/good_job-3.29.2/lib/good_job/capsule_tracker.rb:146)
block (3 levels) in refresh_process(/usr/local/bundle/gems/good_job-3.29.2/lib/good_job/notifier/process_heartbeat.rb:27)

[rgaufman]

It seems to be happening with any version good_job-3.29.0 and newer.

[bensheldon]

Oh wow. That is much more exceptions than I was imagining! 😦

Are you by chance using a forking webserver (like Puma with multiple WEB_CONCURRENCY)? I'm just wondering because I'm not seeing this on any of my production applications and my only idea is that things are being initialized differently before the process forks.

I just made a PR that I think could solve this problem but I'm not 100% sure. I'll release that this evening and hopefully it fixes it: #1369

[bensheldon]

I just released https://github.com/bensheldon/good_job/releases/tag/v3.29.3