Intermittent PQsocket error

[ryan-secondsight]

Hello! Thank you for your work on this gem — it’s a lifesaver for those who want to avoid the complexity of other background job services. However, I’m encountering a small issue that I’m unsure how to diagnose further.

I have a website with fairly low traffic, using a couple of cron jobs to monitor its health and a single queue, which is also not particularly busy.

We’ve been using GoodJob for a couple of months without any issues, but twice in the past week, the jobs have stopped running for about 15 minutes. After this stoppage, the Notifier unsubscribes due to a PQsocket() error, and about 40 AdvisoryLock errors are thrown while the Notifier attempts to resubscribe. Less than a minute later, the Notifier successfully resubscribes, and the scheduled jobs/cron jobs start performing without any user intervention. This has happened once in the middle of the night when there was no activity and once during the day.

Here’s a screenshot of the logs and errors at the time:

Is it a simple thread/pool issue or could it be something else? I'm not sure where to go from here.

[bensheldon]

Nuts, sorry this fell through the cracks on me replying.

That's weird! It definitely looks like there is some lifecycle problem happening in the Notifier in regards to the Process record.

If you still have them, would you be able to share the stacktraces of the RecordAlreadyAdvisoryLockedError and the RecordInvalid error?

[ryan-secondsight]

No worries at all. Congratulations on launching 4.0!

As far as I can tell it hasn't happened since. Here are the stack traces.

Notifier errored: ActiveRecord::RecordInvalid: Record invalid
["/usr/local/bundle/gems/good_job-3.29.4/app/models/concerns/good_job/advisory_lockable.rb:137:in `block (2 levels) in <module:AdvisoryLockable>'",
"/usr/local/bundle/gems/activesupport-7.1.3/lib/active_support/callbacks.rb:448:in `instance_exec'",
"/usr/local/bundle/gems/activesupport-7.1.3/lib/active_support/callbacks.rb:448:in `block in make_lambda'",
"/usr/local/bundle/gems/activesupport-7.1.3/lib/active_support/callbacks.rb:239:in `block in halting_and_conditional'",
"/usr/local/bundle/gems/activesupport-7.1.3/lib/active_support/callbacks.rb:602:in `block in invoke_after'",
"/usr/local/bundle/gems/activesupport-7.1.3/lib/active_support/callbacks.rb:602:in `each'",
"/usr/local/bundle/gems/activesupport-7.1.3/lib/active_support/callbacks.rb:602:in `invoke_after'",
"/usr/local/bundle/gems/activesupport-7.1.3/lib/active_support/callbacks.rb:111:in `run_callbacks'",
"/usr/local/bundle/gems/activesupport-7.1.3/lib/active_support/callbacks.rb:952:in `_run_create_callbacks'",
"/usr/local/bundle/gems/activerecord-7.1.3/lib/active_record/callbacks.rb:445:in `_create_record'",
"/usr/local/bundle/gems/activerecord-7.1.3/lib/active_record/timestamp.rb:114:in `_create_record'",
"/usr/local/bundle/gems/activerecord-7.1.3/lib/active_record/persistence.rb:1221:in `create_or_update'",
"/usr/local/bundle/gems/activerecord-7.1.3/lib/active_record/callbacks.rb:441:in `block in create_or_update'",
"/usr/local/bundle/gems/activesupport-7.1.3/lib/active_support/callbacks.rb:121:in `block in run_callbacks'",
"/usr/local/bundle/gems/activerecord-7.1.3/lib/active_record/autosave_association.rb:375:in `around_save_collection_association'",
"/usr/local/bundle/gems/activesupport-7.1.3/lib/active_support/callbacks.rb:130:in `block in run_callbacks'",
"/usr/local/bundle/gems/activesupport-7.1.3/lib/active_support/callbacks.rb:141:in `run_callbacks'",
"/usr/local/bundle/gems/activesupport-7.1.3/lib/active_support/callbacks.rb:952:in `_run_save_callbacks'",
"/usr/local/bundle/gems/activerecord-7.1.3/lib/active_record/callbacks.rb:441:in `create_or_update'",
"/usr/local/bundle/gems/activerecord-7.1.3/lib/active_record/timestamp.rb:125:in `create_or_update'",
"/usr/local/bundle/gems/activerecord-7.1.3/lib/active_record/persistence.rb:751:in `save!'",
"/usr/local/bundle/gems/activerecord-7.1.3/lib/active_record/validations.rb:55:in `save!'",
"/usr/local/bundle/gems/activerecord-7.1.3/lib/active_record/transactions.rb:313:in `block in save!'",
"/usr/local/bundle/gems/activerecord-7.1.3/lib/active_record/transactions.rb:365:in `block in with_transaction_returning_status'",
"/usr/local/bundle/gems/activerecord-7.1.3/lib/active_record/connection_adapters/abstract/transaction.rb:535:in `block in within_new_transaction'",
"/usr/local/bundle/gems/activesupport-7.1.3/lib/active_support/concurrency/null_lock.rb:9:in `synchronize'",
"/usr/local/bundle/gems/activerecord-7.1.3/lib/active_record/connection_adapters/abstract/transaction.rb:532:in `within_new_transaction'",
"/usr/local/bundle/gems/activerecord-7.1.3/lib/active_record/connection_adapters/abstract/database_statements.rb:344:in `transaction'",
"/usr/local/bundle/gems/activerecord-7.1.3/lib/active_record/transactions.rb:361:in `with_transaction_returning_status'",
"/usr/local/bundle/gems/activerecord-7.1.3/lib/active_record/transactions.rb:313:in `save!'",
"/usr/local/bundle/gems/activerecord-7.1.3/lib/active_record/suppressor.rb:56:in `save!'",
"/usr/local/bundle/gems/newrelic_rpm-9.10.2/lib/new_relic/agent/instrumentation/active_record_prepend.rb:36:in `block in save!'",
"/usr/local/bundle/gems/newrelic_rpm-9.10.2/lib/new_relic/agent.rb:884:in `with_database_metric_name'",
"/usr/local/bundle/gems/newrelic_rpm-9.10.2/lib/new_relic/agent/instrumentation/active_record_prepend.rb:35:in `save!'",
"/usr/local/bundle/gems/activerecord-7.1.3/lib/active_record/persistence.rb:55:in `create!'",
"/usr/local/bundle/gems/good_job-3.29.4/app/models/good_job/process.rb:81:in `create_record'",
"/usr/local/bundle/gems/good_job-3.29.4/lib/good_job/capsule_tracker.rb:92:in `block in register'",
"/usr/local/bundle/gems/good_job-3.29.4/lib/good_job/capsule_tracker.rb:225:in `synchronize'",
"/usr/local/bundle/gems/good_job-3.29.4/lib/good_job/capsule_tracker.rb:225:in `synchronize'",
"/usr/local/bundle/gems/good_job-3.29.4/lib/good_job/capsule_tracker.rb:81:in `register'",
"/usr/local/bundle/gems/good_job-3.29.4/lib/good_job/notifier/process_heartbeat.rb:19:in `block in register_process'",
"/usr/local/bundle/gems/good_job-3.29.4/lib/good_job/overridable_connection.rb:26:in `override_connection'",
"/usr/local/bundle/gems/good_job-3.29.4/lib/good_job/notifier/process_heartbeat.rb:17:in `register_process'",
"/usr/local/bundle/gems/activesupport-7.1.3/lib/active_support/callbacks.rb:403:in `block in make_lambda'",
"/usr/local/bundle/gems/activesupport-7.1.3/lib/active_support/callbacks.rb:274:in `block in simple'",
"/usr/local/bundle/gems/activesupport-7.1.3/lib/active_support/callbacks.rb:602:in `block in invoke_after'",
"/usr/local/bundle/gems/activesupport-7.1.3/lib/active_support/callbacks.rb:602:in `each'",
"/usr/local/bundle/gems/activesupport-7.1.3/lib/active_support/callbacks.rb:602:in `invoke_after'",
"/usr/local/bundle/gems/activesupport-7.1.3/lib/active_support/callbacks.rb:111:in `run_callbacks'",
"/usr/local/bundle/gems/good_job-3.29.4/lib/good_job/notifier.rb:206:in `block (3 levels) in create_listen_task'",
"/usr/local/bundle/gems/activesupport-7.1.3/lib/active_support/execution_wrapper.rb:92:in `wrap'",
"/usr/local/bundle/gems/good_job-3.29.4/lib/good_job/notifier.rb:205:in `block (2 levels) in create_listen_task'",
"/usr/local/bundle/gems/good_job-3.29.4/lib/good_job/notifier.rb:260:in `with_connection'",
"/usr/local/bundle/gems/good_job-3.29.4/lib/good_job/notifier.rb:201:in `block in create_listen_task'",
"/usr/local/bundle/gems/concurrent-ruby-1.3.3/lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb:24:in `block in execute'",
"/usr/local/bundle/gems/concurrent-ruby-1.3.3/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48:in `block in synchronize'",
"/usr/local/bundle/gems/concurrent-ruby-1.3.3/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48:in `synchronize'",
"/usr/local/bundle/gems/concurrent-ruby-1.3.3/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48:in `synchronize'",
"/usr/local/bundle/gems/concurrent-ruby-1.3.3/lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb:22:in `execute'",
"/usr/local/bundle/gems/concurrent-ruby-1.3.3/lib/concurrent-ruby/concurrent/ivar.rb:170:in `safe_execute'",
"/usr/local/bundle/gems/concurrent-ruby-1.3.3/lib/concurrent-ruby/concurrent/scheduled_task.rb:298:in `process_task'",
"/usr/local/bundle/gems/concurrent-ruby-1.3.3/lib/concurrent-ruby/concurrent/executor/timer_set.rb:98:in `block in ns_post_task'",
"/usr/local/bundle/gems/newrelic_rpm-9.10.2/lib/new_relic/agent/tracer.rb:434:in `block (2 levels) in thread_block_with_current_transaction'",
"/usr/local/bundle/gems/newrelic_rpm-9.10.2/lib/new_relic/agent/tracer.rb:357:in `capture_segment_error'",
"/usr/local/bundle/gems/newrelic_rpm-9.10.2/lib/new_relic/agent/tracer.rb:433:in `block in thread_block_with_current_transaction'",
"/usr/local/bundle/gems/concurrent-ruby-1.3.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:359:in `run_task'",
"/usr/local/bundle/gems/concurrent-ruby-1.3.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:350:in `block (3 levels) in create_worker'",
"/usr/local/bundle/gems/concurrent-ruby-1.3.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:341:in `loop'",
"/usr/local/bundle/gems/concurrent-ruby-1.3.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:341:in `block (2 levels) in create_worker'",
"/usr/local/bundle/gems/concurrent-ruby-1.3.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:340:in `catch'",
"/usr/local/bundle/gems/concurrent-ruby-1.3.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:340:in `block in create_worker'",
"/usr/local/bundle/gems/newrelic_rpm-9.10.2/lib/new_relic/agent/tracer.rb:434:in `block (2 levels) in thread_block_with_current_transaction'",
"/usr/local/bundle/gems/newrelic_rpm-9.10.2/lib/new_relic/agent/tracer.rb:357:in `capture_segment_error'",
"/usr/local/bundle/gems/newrelic_rpm-9.10.2/lib/new_relic/agent/tracer.rb:433:in `block in thread_block_with_current_transaction'"]

Notifier errored: GoodJob::AdvisoryLockable::RecordAlreadyAdvisoryLockedError: GoodJob::AdvisoryLockable::RecordAlreadyAdvisoryLockedError
["/usr/local/bundle/gems/good_job-3.29.4/app/models/concerns/good_job/advisory_lockable.rb:338:in `advisory_lock!'",
"/usr/local/bundle/gems/good_job-3.29.4/lib/good_job/capsule_tracker.rb:86:in `block (2 levels) in register'",
"/usr/local/bundle/gems/activerecord-7.1.3/lib/active_record/connection_adapters/abstract/transaction.rb:535:in `block in within_new_transaction'",
"/usr/local/bundle/gems/activesupport-7.1.3/lib/active_support/concurrency/null_lock.rb:9:in `synchronize'",
"/usr/local/bundle/gems/activerecord-7.1.3/lib/active_record/connection_adapters/abstract/transaction.rb:532:in `within_new_transaction'",
"/usr/local/bundle/gems/activerecord-7.1.3/lib/active_record/connection_adapters/abstract/database_statements.rb:344:in `transaction'",
"/usr/local/bundle/gems/activerecord-7.1.3/lib/active_record/transactions.rb:212:in `transaction'",
"/usr/local/bundle/gems/good_job-3.29.4/lib/good_job/capsule_tracker.rb:85:in `block in register'",
"/usr/local/bundle/gems/good_job-3.29.4/lib/good_job/capsule_tracker.rb:225:in `synchronize'",
"/usr/local/bundle/gems/good_job-3.29.4/lib/good_job/capsule_tracker.rb:225:in `synchronize'",
"/usr/local/bundle/gems/good_job-3.29.4/lib/good_job/capsule_tracker.rb:81:in `register'",
"/usr/local/bundle/gems/good_job-3.29.4/lib/good_job/notifier/process_heartbeat.rb:19:in `block in register_process'",
"/usr/local/bundle/gems/good_job-3.29.4/lib/good_job/overridable_connection.rb:26:in `override_connection'",
"/usr/local/bundle/gems/good_job-3.29.4/lib/good_job/notifier/process_heartbeat.rb:17:in `register_process'",
"/usr/local/bundle/gems/activesupport-7.1.3/lib/active_support/callbacks.rb:403:in `block in make_lambda'",
"/usr/local/bundle/gems/activesupport-7.1.3/lib/active_support/callbacks.rb:274:in `block in simple'",
"/usr/local/bundle/gems/activesupport-7.1.3/lib/active_support/callbacks.rb:602:in `block in invoke_after'",
"/usr/local/bundle/gems/activesupport-7.1.3/lib/active_support/callbacks.rb:602:in `each'",
"/usr/local/bundle/gems/activesupport-7.1.3/lib/active_support/callbacks.rb:602:in `invoke_after'",
"/usr/local/bundle/gems/activesupport-7.1.3/lib/active_support/callbacks.rb:111:in `run_callbacks'",
"/usr/local/bundle/gems/good_job-3.29.4/lib/good_job/notifier.rb:206:in `block (3 levels) in create_listen_task'",
"/usr/local/bundle/gems/activesupport-7.1.3/lib/active_support/execution_wrapper.rb:92:in `wrap'",
"/usr/local/bundle/gems/good_job-3.29.4/lib/good_job/notifier.rb:205:in `block (2 levels) in create_listen_task'",
"/usr/local/bundle/gems/good_job-3.29.4/lib/good_job/notifier.rb:260:in `with_connection'",
"/usr/local/bundle/gems/good_job-3.29.4/lib/good_job/notifier.rb:201:in `block in create_listen_task'",
"/usr/local/bundle/gems/concurrent-ruby-1.3.3/lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb:24:in `block in execute'",
"/usr/local/bundle/gems/concurrent-ruby-1.3.3/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48:in `block in synchronize'",
"/usr/local/bundle/gems/concurrent-ruby-1.3.3/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48:in `synchronize'",
"/usr/local/bundle/gems/concurrent-ruby-1.3.3/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48:in `synchronize'",
"/usr/local/bundle/gems/concurrent-ruby-1.3.3/lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb:22:in `execute'",
"/usr/local/bundle/gems/concurrent-ruby-1.3.3/lib/concurrent-ruby/concurrent/ivar.rb:170:in `safe_execute'",
"/usr/local/bundle/gems/concurrent-ruby-1.3.3/lib/concurrent-ruby/concurrent/scheduled_task.rb:298:in `process_task'",
"/usr/local/bundle/gems/concurrent-ruby-1.3.3/lib/concurrent-ruby/concurrent/executor/timer_set.rb:98:in `block in ns_post_task'",
"/usr/local/bundle/gems/newrelic_rpm-9.10.2/lib/new_relic/agent/tracer.rb:434:in `block (2 levels) in thread_block_with_current_transaction'",
"/usr/local/bundle/gems/newrelic_rpm-9.10.2/lib/new_relic/agent/tracer.rb:357:in `capture_segment_error'",
"/usr/local/bundle/gems/newrelic_rpm-9.10.2/lib/new_relic/agent/tracer.rb:433:in `block in thread_block_with_current_transaction'",
"/usr/local/bundle/gems/concurrent-ruby-1.3.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:359:in `run_task'",
"/usr/local/bundle/gems/concurrent-ruby-1.3.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:350:in `block (3 levels) in create_worker'",
"/usr/local/bundle/gems/concurrent-ruby-1.3.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:341:in `loop'",
"/usr/local/bundle/gems/concurrent-ruby-1.3.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:341:in `block (2 levels) in create_worker'",
"/usr/local/bundle/gems/concurrent-ruby-1.3.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:340:in `catch'",
"/usr/local/bundle/gems/concurrent-ruby-1.3.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:340:in `block in create_worker'",
"/usr/local/bundle/gems/newrelic_rpm-9.10.2/lib/new_relic/agent/tracer.rb:434:in `block (2 levels) in thread_block_with_current_transaction'",
"/usr/local/bundle/gems/newrelic_rpm-9.10.2/lib/new_relic/agent/tracer.rb:357:in `capture_segment_error'",
"/usr/local/bundle/gems/newrelic_rpm-9.10.2/lib/new_relic/agent/tracer.rb:433:in `block in thread_block_with_current_transaction'"]