Unclear error when database can't be reached

[clementf]

Hi @bensheldon, first of all, thanks for the great library 🙌

I've recently been trying good job in a setup where my database connections are quite limited, and I was encountering an error from time to time, which I could not place. Here's the stacktrace:

2021-11-24T15:04:11.772Z: E, [2021-11-24T15:04:07.099188 #2887] ERROR -- : [GoodJob] GoodJob error: undefined method `perform_with_advisory_lock' for nil:NilClass
2021-11-24T15:04:11.772Z: [
2021-11-24T15:04:11.772Z: E, [2021-11-24T15:04:07.099188 #2887] ERROR -- : [GoodJob] GoodJob error: undefined method `perform_with_advisory_lock' for nil:NilClass
2021-11-24T15:04:11.772Z: [
"/home/bas/app/vendor/bundle/ruby/3.0.0/gems/good_job-2.3.1/lib/good_job/job_performer.rb:30:in `next'", 
"/home/bas/app/vendor/bundle/ruby/3.0.0/gems/good_job-2.3.1/lib/good_job/scheduler.rb:234:in `block (2 levels) in create_task'", 
"/home/bas/app/vendor/bundle/ruby/3.0.0/gems/activesupport-6.1.4.1/lib/active_support/execution_wrapper.rb:88:in `wrap'", 
"/home/bas/app/vendor/bundle/ruby/3.0.0/gems/activesupport-6.1.4.1/lib/active_support/reloader.rb:72:in `block in wrap'", 
"/home/bas/app/vendor/bundle/ruby/3.0.0/gems/activesupport-6.1.4.1/lib/active_support/execution_wrapper.rb:88:in `wrap'", 
"/home/bas/app/vendor/bundle/ruby/3.0.0/gems/activesupport-6.1.4.1/lib/active_support/reloader.rb:71:in `wrap'", 
"/home/bas/app/vendor/bundle/ruby/3.0.0/gems/good_job-2.3.1/lib/good_job/scheduler.rb:233:in `block in create_task'", 
"/home/bas/app/vendor/bundle/ruby/3.0.0/gems/concurrent-ruby-1.1.9/lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb:24:in `block in execute'", 
"/home/bas/app/vendor/bundle/ruby/3.0.0/gems/concurrent-ruby-1.1.9/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:47:in `block in synchronize'", 
"/home/bas/app/vendor/bundle/ruby/3.0.0/gems/concurrent-ruby-1.1.9/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:47:in `synchronize'", 
"/home/bas/app/vendor/bundle/ruby/3.0.0/gems/concurrent-ruby-1.1.9/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:47:in `synchronize'", 
"/home/bas/app/vendor/bundle/ruby/3.0.0/gems/concurrent-ruby-1.1.9/lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb:19:in `execute'", 
"/home/bas/app/vendor/bundle/ruby/3.0.0/gems/concurrent-ruby-1.1.9/lib/concurrent-ruby/concurrent/ivar.rb:169:in `safe_execute'", 
"/home/bas/app/vendor/bundle/ruby/3.0.0/gems/concurrent-ruby-1.1.9/lib/concurrent-ruby/concurrent/scheduled_task.rb:285:in `process_task'", 
"/home/bas/app/vendor/bundle/ruby/3.0.0/gems/concurrent-ruby-1.1.9/lib/concurrent-ruby/concurrent/executor/timer_set.rb:98:in `block in ns_post_task'", 
"/home/bas/app/vendor/bundle/ruby/3.0.0/gems/concurrent-ruby-1.1.9/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:363:in `run_task'", 
"/home/bas/app/vendor/bundle/ruby/3.0.0/gems/concurrent-ruby-1.1.9/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:352:in `block (3 levels) in create_worker'", 
"/home/bas/app/vendor/bundle/ruby/3.0.0/gems/concurrent-ruby-1.1.9/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:335:in `loop'", 
"/home/bas/app/vendor/bundle/ruby/3.0.0/gems/concurrent-ruby-1.1.9/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:335:in `block (2 levels) in create_worker'", 
"/home/bas/app/vendor/bundle/ruby/3.0.0/gems/concurrent-ruby-1.1.9/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:334:in `catch'", 
"/home/bas/app/vendor/bundle/ruby/3.0.0/gems/concurrent-ruby-1.1.9/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:334:in `block in create_worker'"]

]

My setup

Good job v2.3.1
Ruby v3.0.0
Rails v6.1.4.1

After some digging, I found that this is because I'm exhausting the max allowed connections of the pg instance I'm using.

When this happens, the pg adapter will raise an exception. In job_performer.rb, Concurrent::Delay is used @job_query = Concurrent::Delay.new { GoodJob::Execution.queue_string(queue_string) }

If an exception happens during the execution of the block above, the value returned when calling @job_query.value will simply be nil, and the exception will be available at @job_query.reason.

This is also reproducible locally by shutting down your postgres db, and starting good_job from the CLI.
Another issue related to that is that if I turn the db back on, it won't recover by itself (while the Notifier will reconnect I believe).

Potential solution

Just poking around locally it seems that something like the following could log the right reason for not being able to connect, as well as handle reconnections:

# job_performer.rb
def job_query
  return @job_query.value if @job_query.value

  if @job_query.reason
    exception = @job_query.reason
    @job_query = Concurrent::Delay.new { GoodJob::Execution.queue_string(queue_string) }

    raise exception
  end
end

I haven't read any of the code of this gem before this, so feel free to let me know if this doesn't make sense, or if I'm missing some other bits.

Thanks for reading!

[bensheldon]

@clementf This is fantastic research. Thank you for digging into this; documenting what's happening and helping me reproduce it 🙌

I will do some more testing myself; and it's very topical given that I'm currently working on #454. I'm constantly learning new and interesting things that can trip up ActiveRecord during initialization.

[clementf]

@bensheldon I've taken a look at #454 and indeed that sounds like it could all be related.

Let me know if you need anything from my side, I'd be happy to help out.

[bensheldon]

@clementf I just released v2.7.1 which contains a fix for this. Thank you so much for reporting the issue! 🙏

[clementf]

That was fast! Thanks a lot @bensheldon 🙌 Going to try this new release.