Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Server hangs after #1297 #1301

Closed
arashm opened this issue Mar 27, 2024 · 3 comments
Closed

Server hangs after #1297 #1301

arashm opened this issue Mar 27, 2024 · 3 comments

Comments

@arashm
Copy link

arashm commented Mar 27, 2024 •
edited

After updating to 3.27.1, when I run the Rails server, it immediately hangs for me and won't respond to any requests. Upon pressing CTRL+c it raises a PG::ConnectionBad exception and then shutdown after 10-20 seconds. Here's the output I get:

─$ bin/rails server -b 0.0.0.0                                                                                                                                                   
=> Booting Puma                                                                                                                                                                   
=> Rails 7.0.8.1 application starting in development                                                                                                                              
=> Run `bin/rails server --help` for more startup options                                                                                                                         
   (0.5ms)  SET application_name = 'GoodJob::Notifier'                                                                                                                            
   (0.1ms)  LISTEN good_job                                                                                                                                                       
[GoodJob] Notifier subscribed with LISTEN                                                                                                                                         
[13856] Puma starting in cluster mode...                                                                                                                                          
[13856] * Puma version: 6.4.2 (ruby 3.2.3-p157) ("The Eagle of Durango")                                                                                                          
[13856] *  Min threads: 5                                                                                                                                                         
[13856] *  Max threads: 5                                                                                                                                                         
[13856] *  Environment: development                                                                                                                                               
[13856] *   Master PID: 13856                                                                                                                                                     
[13856] *      Workers: 2                                                                                                                                                         
[13856] *     Restarts: (✔) hot (✖) phased                                                                                                                                        
[13856] * Preloading application                                                                                                                                                  
[13856] * Listening on http://0.0.0.0:3000                                                                                                                                        
[13856] Use Ctrl-C to stop                                                                                                                                                        
[13856] - Worker 0 (PID: 13929) booted in 0.0s, phase: 0                                                                                                                          
[13856] - Worker 1 (PID: 13933) booted in 0.0s, phase: 0                                                                                                                          
  GoodJob::Execution Pluck (1.4ms)  SELECT "good_jobs"."scheduled_at", "good_jobs"."created_at" FROM "good_jobs" LEFT JOIN pg_locks ON pg_locks.locktype = 'advisory' AND pg_locks
.objsubid = 1 AND pg_locks.classid = ('x' || substr(md5('good_jobs' || '-' || "good_jobs"."active_job_id"::text), 1, 16))::bit(32)::int AND pg_locks.objid = (('x' || substr(md5('
good_jobs' || '-' || "good_jobs"."active_job_id"::text), 1, 16))::bit(64) << 32)::bit(32)::int WHERE "pg_locks"."locktype" IS NULL AND "good_jobs"."finished_at" IS NULL AND (sche
duled_at > '2024-03-27 23:25:34.008457' OR "good_jobs"."scheduled_at" IS NULL AND (created_at > '2024-03-27 23:25:34.008457')) ORDER BY COALESCE("good_jobs"."scheduled_at", "good
_jobs"."created_at") ASC LIMIT $1  [["LIMIT", 10000]]                                                                                                                             
  GoodJob::Execution Pluck (0.2ms)  SELECT "good_jobs"."scheduled_at", "good_jobs"."created_at" FROM "good_jobs" LEFT JOIN pg_locks ON pg_locks.locktype = 'advisory' AND pg_locks
.objsubid = 1 AND pg_locks.classid = ('x' || substr(md5('good_jobs' || '-' || "good_jobs"."active_job_id"::text), 1, 16))::bit(32)::int AND pg_locks.objid = (('x' || substr(md5('
good_jobs' || '-' || "good_jobs"."active_job_id"::text), 1, 16))::bit(64) << 32)::bit(32)::int WHERE "pg_locks"."locktype" IS NULL AND "good_jobs"."finished_at" IS NULL AND (sche
duled_at < '2024-03-27 23:25:34.012516' OR "good_jobs"."scheduled_at" IS NULL) ORDER BY COALESCE("good_jobs"."scheduled_at", "good_jobs"."created_at") ASC LIMIT $1  [["LIMIT", 5]
]                                                                                                                                                                                 
  GoodJob::Execution Load (0.3ms)  SELECT "good_jobs".* FROM "good_jobs" WHERE "good_jobs"."id" IN (WITH "rows" AS  MATERIALIZED (SELECT "good_jobs"."id", "good_jobs"."active_job
_id" FROM "good_jobs" WHERE "good_jobs"."finished_at" IS NULL AND ("good_jobs"."scheduled_at" <= $1 OR "good_jobs"."scheduled_at" IS NULL) ORDER BY priority DESC NULLS LAST, "goo
d_jobs"."created_at" ASC) SELECT "rows"."id" FROM "rows" WHERE pg_try_advisory_lock(('x' || substr(md5('good_jobs' || '-' || "rows"."active_job_id"::text), 1, 16))::bit(64)::bigi
nt) LIMIT $2) ORDER BY priority DESC NULLS LAST, "good_jobs"."created_at" ASC  [["scheduled_at", "2024-03-27 23:25:34.018788"], ["LIMIT", 1]]                                     

  GoodJob::Process Delete All (5.7ms)  DELETE FROM "good_job_processes" WHERE "good_job_processes"."id" IN (SELECT "good_job_processes"."id" FROM "good_job_proc23:26:21 [222/391]
g_locks ON pg_locks.locktype = 'advisory' AND pg_locks.objsubid = 1 AND pg_locks.classid = ('x' || substr(md5('good_job_processes' || '-' || "good_job_processes"."id"::text), 1, 
16))::bit(32)::int AND pg_locks.objid = (('x' || substr(md5('good_job_processes' || '-' || "good_job_processes"."id"::text), 1, 16))::bit(64) << 32)::bit(32)::int WHERE "pg_locks
"."locktype" IS NULL)                                                                                                                                                             
  TRANSACTION (0.0ms)  BEGIN                                                                                                                                                      
  GoodJob::Process Create (0.2ms)  INSERT INTO "good_job_processes" ("id", "created_at", "updated_at", "state") VALUES ($1, $2, $3, $4) RETURNING "id"  [["id", "6ea30993-a35c-483
3-b56a-f16a4f632b0f"], ["created_at", "2024-03-27 23:25:34.027015"], ["updated_at", "2024-03-27 23:25:34.027015"], ["state", "{\"id\":\"6ea30993-a35c-4833-b56a-f16a4f632b0f\",\"h
ostname\":\"aria-pc\",\"pid\":13856,\"proctitle\":\"bin/rails\",\"preserve_job_records\":true,\"retry_on_unhandled_error\":false,\"schedulers\":[{\"name\":\"GoodJob::Scheduler(qu
eues=* max_threads=5)\",\"queues\":\"*\",\"max_threads\":5,\"active_threads\":0,\"available_threads\":5,\"max_cache\":10000,\"active_cache\":0,\"available_cache\":10000,\"empty_e
xecutions_count\":1,\"errored_executions_count\":0,\"succeeded_executions_count\":0,\"total_executions_count\":0,\"execution_at\":null,\"check_queue_at\":\"2024-03-27T23:25:34Z\"
}],\"cron_enabled\":false,\"total_succeeded_executions_count\":0,\"total_errored_executions_count\":0,\"total_executions_count\":0,\"total_empty_executions_count\":1,\"database_c
onnection_pool\":{\"size\":10,\"active\":0}}"]]                                                                                                                                   
  GoodJob::Lockable Advisory Lock (0.3ms)  SELECT pg_try_advisory_lock(('x'||substr(md5($1::text), 1, 16))::bit(64)::bigint) AS locked  [["key", "good_job_processes-6ea30993-a35c
-4833-b56a-f16a4f632b0f"]]                                                                                                                                                        
  TRANSACTION (8.9ms)  COMMIT                                                                                                                                                     
^C[13856] - Gracefully shutting down workers...                                                                                                                                   
   (0.2ms)  UNLISTEN *                                                                                                                                                            
[GoodJob] Notifier unsubscribed with UNLISTEN                                                                                                                                     
[GoodJob] Notifier errored: ActiveRecord::StatementInvalid: PG::ConnectionBad: PQsocket() can't get socket descriptor                                                             
 ["/home/arash/.rbenv/versions/3.2.3/lib/ruby/gems/3.2.0/gems/activerecord-7.0.8.1/lib/active_record/connection_adapters/postgresql/database_statements.rb:48:in `exec'", "/home/a
rash/.rbenv/versions/3.2.3/lib/ruby/gems/3.2.0/gems/activerecord-7.0.8.1/lib/active_record/connection_adapters/postgresql/database_statements.rb:48:in `block (2 levels) in execut
e'", "/home/arash/.rbenv/versions/3.2.3/lib/ruby/gems/3.2.0/gems/activesupport-7.0.8.1/lib/active_support/concurrency/share_lock.rb:187:in `yield_shares'", "/home/arash/.rbenv/ve
rsions/3.2.3/lib/ruby/gems/3.2.0/gems/activesupport-7.0.8.1/lib/active_support/dependencies/interlock.rb:41:in `permit_concurrent_loads'", "/home/arash/.rbenv/versions/3.2.3/lib/
ruby/gems/3.2.0/gems/activerecord-7.0.8.1/lib/active_record/connection_adapters/postgresql/database_statements.rb:47:in `block in execute'", "/home/arash/.rbenv/versions/3.2.3/li
b/ruby/gems/3.2.0/gems/activesupport-7.0.8.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `handle_interrupt'", "/home/arash/.rbenv/versions/3.2.3/lib/ruby
/gems/3.2.0/gems/activesupport-7.0.8.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `block in synchronize'", "/home/arash/.rbenv/versions/3.2.3/lib/ruby/g
ems/3.2.0/gems/activesupport-7.0.8.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'", "/home/arash/.rbenv/versions/3.2.3/lib/ruby/gems/3.
2.0/gems/activesupport-7.0.8.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'", "/home/arash/.rbenv/versions/3.2.3/lib/ruby/gems/3.2.0/gems/ac
tiverecord-7.0.8.1/lib/active_record/connection_adapters/abstract_adapter.rb:752:in `block in log'", "/home/arash/.rbenv/versions/3.2.3/lib/ruby/gems/3.2.0/gems/activesupport-7.0
.8.1/lib/active_support/notifications/instrumenter.rb:24:in `instrument'", "/home/arash/.rbenv/versions/3.2.3/lib/ruby/gems/3.2.0/gems/activerecord-7.0.8.1/lib/active_record/conn
ection_adapters/abstract_adapter.rb:743:in `log'", "/home/arash/.rbenv/versions/3.2.3/lib/ruby/gems/3.2.0/gems/activerecord-7.0.8.1/lib/active_record/connection_adapters/postgres
ql/database_statements.rb:46:in `execute'", "/home/arash/.rbenv/versions/3.2.3/lib/ruby/gems/3.2.0/gems/good_job-3.27.1/lib/good_job/notifier.rb:236:in `block (5 levels) in creat
e_listen_task'", "/home/arash/.rbenv/versions/3.2.3/lib/ruby/gems/3.2.0/gems/activesupport-7.0.8.1/lib/active_support/notifications.rb:206:in `block in instrument'", "/home/arash
/.rbenv/versions/3.2.3/lib/ruby/gems/3.2.0/gems/activesupport-7.0.8.1/lib/active_support/notifications/instrumenter.rb:24:in `instrument'", "/home/arash/.rbenv/versions/3.2.3/lib
/ruby/gems/3.2.0/gems/activesupport-7.0.8.1/lib/active_support/notifications.rb:206:in `instrument'", "/home/arash/.rbenv/versions/3.2.3/lib/ruby/gems/3.2.0/gems/good_job-3.27.1/
lib/good_job/notifier.rb:234:in `block (4 levels) in create_listen_task'", "/home/arash/.rbenv/versions/3.2.3/lib/ruby/gems/3.2.0/gems/activesupport-7.0.8.1/lib/active_support/ca
llbacks.rb:107:in `run_callbacks'", "/home/arash/.rbenv/versions/3.2.3/lib/ruby/gems/3.2.0/gems/good_job-3.27.1/lib/good_job/notifier.rb:232:in `block (3 levels) in create_listen
_task'", "/home/arash/.rbenv/versions/3.2.3/lib/ruby/gems/3.2.0/gems/activesupport-7.0.8.1/lib/active_support/execution_wrapper.rb:92:in `wrap'", "/home/arash/.rbenv/versions/3.2
.3/lib/ruby/gems/3.2.0/gems/good_job-3.27.1/lib/good_job/notifier.rb:231:in `ensure in block (2 levels) in create_listen_task'", "/home/arash/.rbenv/versions/3.2.3/lib/ruby/gems/
3.2.0/gems/good_job-3.27.1/lib/good_job/notifier.rb:231:in `block (2 levels) in create_listen_task'", "/home/arash/.rbenv/versions/3.2.3/lib/ruby/gems/3.2.0/gems/good_job-3.27.1/
lib/good_job/notifier.rb:257:in `with_connection'", "/home/arash/.rbenv/versions/3.2.3/lib/ruby/gems/3.2.0/gems/good_job-3.27.1/lib/good_job/notifier.rb:198:in `block in create_l
isten_task'", "/home/arash/.rbenv/versions/3.2.3/lib/ruby/gems/3.2.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb:24:in `block in exec
ute'", "/home/arash/.rbenv/versions/3.2.3/lib/ruby/gems/3.2.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48:in `block in s
ynchronize'", "/home/arash/.rbenv/versions/3.2.3/lib/ruby/gems/3.2.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48:in `syn
chronize'", "/home/arash/.rbenv/versions/3.2.3/lib/ruby/gems/3.2.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48:in `synch
ronize'", "/home/arash/.rbenv/versions/3.2.3/lib/ruby/gems/3.2.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb:22:in `execute'", "/home
/arash/.rbenv/versions/3.2.3/lib/ruby/gems/3.2.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/ivar.rb:170:in `safe_execute'", "/home/arash/.rbenv/versions/3.2.3/lib/
ruby/gems/3.2.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/scheduled_task.rb:298:in `process_task'", "/home/arash/.rbenv/versions/3.2.3/lib/ruby/gems/3.2.0/gems/co
ncurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/timer_set.rb:98:in `block in ns_post_task'", "/home/arash/.rbenv/versions/3.2.3/lib/ruby/gems/3.2.0/gems/concurrent-ru
by-1.2.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:359:in `run_task'", "/home/arash/.rbenv/versions/3.2.3/lib/ruby/gems/3.2.0/gems/concurrent-ruby-1.2.
3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:350:in `block (3 levels) in create_worker'", "/home/arash/.rbenv/versions/3.2.3/lib/ruby/gems/3.2.0/gems/co
ncurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:341:in `loop'", "/home/arash/.rbenv/versions/3.2.3/lib/ruby/gems/3.2.0/gems/concurrent-ru
by-1.2.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:341:in `block (2 levels) in create_worker'", "/home/arash/.rbenv/versions/3.2.3/lib/ruby/gems/3.2.0/
gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:340:in `catch'", "/home/arash/.rbenv/versions/3.2.3/lib/ruby/gems/3.2.0/gems/concu
rrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:340:in `block in create_worker'"]                                                           
^C   (0.1ms)  SET application_name = 'GoodJob::Notifier'                                                                                                                          
   (0.0ms)  LISTEN good_job                                                                                                                                                       
[GoodJob] Notifier subscribed with LISTEN                                                                                                                                         
  GoodJob::Process Delete All (12.7ms)  DELETE FROM "good_job_processes" WHERE "good_job_processes"."id" IN (SELECT "good_job_processes"."id" FROM "good_job_processes" LEFT JOIN 
pg_locks ON pg_locks.locktype = 'advisory' AND pg_locks.objsubid = 1 AND pg_locks.classid = ('x' || substr(md5('good_job_processes' || '-' || "good_job_processes"."id"::text), 1,
 16))::bit(32)::int AND pg_locks.objid = (('x' || substr(md5('good_job_processes' || '-' || "good_job_processes"."id"::text), 1, 16))::bit(64) << 32)::bit(32)::int WHERE "pg_lock
s"."locktype" IS NULL)                                                                                                                                                            
  TRANSACTION (0.0ms)  BEGIN                                                                                                                                                      
  GoodJob::Process Create (0.1ms)  INSERT INTO "good_job_processes" ("id", "created_at", "updated_at", "state") VALUES ($1, $2, $3, $4) RETURNING "id"  [["id", "6ea30993-a35c-483
3-b56a-f16a4f632b0f"], ["created_at", "2024-03-27 23:25:50.999868"], ["updated_at", "2024-03-27 23:25:50.999868"], ["state", "{\"id\":\"6ea30993-a35c-4833-b56a-f16a4f632b0f\",\"h
ostname\":\"aria-pc\",\"pid\":13856,\"proctitle\":\"bin/rails\",\"preserve_job_records\":true,\"retry_on_unhandled_error\":false,\"schedulers\":[{\"name\":\"GoodJob::Scheduler(qu
eues=* max_threads=5)\",\"queues\":\"*\",\"max_threads\":5,\"active_threads\":0,\"available_threads\":5,\"max_cache\":10000,\"active_cache\":0,\"available_cache\":10000,\"empty_e
xecutions_count\":1,\"errored_executions_count\":0,\"succeeded_executions_count\":0,\"total_executions_count\":0,\"execution_at\":null,\"check_queue_at\":\"2024-03-27T23:25:34Z\"
}],\"cron_enabled\":false,\"total_succeeded_executions_count\":0,\"total_errored_executions_count\":0,\"total_executions_count\":0,\"total_empty_executions_count\":1,\"database_c
onnection_pool\":{\"size\":10,\"active\":0}}"]]                                                                                                                                   
  GoodJob::Lockable Advisory Lock (0.3ms)  SELECT pg_try_advisory_lock(('x'||substr(md5($1::text), 1, 16))::bit(64)::bigint) AS locked  [["key", "good_job_processes-6ea30993-a35c
-4833-b56a-f16a4f632b0f"]]                                                                                                                                                        
  TRANSACTION (3.8ms)  COMMIT                                                                                                                                                     
^C^C^C[13856] === puma shutdown: 2024-03-27 23:26:16 +0000 ===                                                                                                                    
[13856] - Goodbye!                                                                                                                                                                
Exiting                                                                                                                                                                           
   (0.1ms)  UNLISTEN *                                                                                                                                                            
[GoodJob] Notifier unsubscribed with UNLISTEN                                                                                                                                     
  GoodJob::Lockable Owns Advisory Lock? (0.4ms)  SELECT 1 AS one FROM pg_locks WHERE pg_locks.locktype = 'advisory' AND pg_locks.objsubid = 1 AND pg_locks.classid = ('x' || subst
r(md5($1::text), 1, 16))::bit(32)::int AND pg_locks.objid = (('x' || substr(md5($2::text), 1, 16))::bit(64) << 32)::bit(32)::int AND pg_locks.pid = pg_backend_pid() LIMIT 1  [["k
ey", "good_job_processes-6ea30993-a35c-4833-b56a-f16a4f632b0f"], ["key", "good_job_processes-6ea30993-a35c-4833-b56a-f16a4f632b0f"]]                                              
  GoodJob::Lockable Owns Advisory Lock? (0.2ms)  SELECT 1 AS one FROM pg_locks WHERE pg_locks.locktype = 'advisory' AND pg_locks.objsubid = 1 AND pg_locks.classid = ('x' || subst
r(md5($1::text), 1, 16))::bit(32)::int AND pg_locks.objid = (('x' || substr(md5($2::text), 1, 16))::bit(64) << 32)::bit(32)::int AND pg_locks.pid = pg_backend_pid() LIMIT 1  [["k
ey", "good_job_processes-6ea30993-a35c-4833-b56a-f16a4f632b0f"], ["key", "good_job_processes-6ea30993-a35c-4833-b56a-f16a4f632b0f"]]                                              
  TRANSACTION (0.0ms)  BEGIN                                                                                                                                                      
  GoodJob::Process Destroy (0.1ms)  DELETE FROM "good_job_processes" WHERE "good_job_processes"."id" = $1  [["id", "6ea30993-a35c-4833-b56a-f16a4f632b0f"]]                       
  TRANSACTION (0.0ms)  ROLLBACK                                                                                                                                                   
  GoodJob::Lockable Advisory Unlock (0.1ms)  SELECT pg_advisory_unlock(('x'||substr(md5($1::text), 1, 16))::bit(64)::bigint) AS unlocked  [["key", "good_job_processes-6ea30993-a3
5c-4833-b56a-f16a4f632b0f"]]

After downgrading the gem to 3.27.0 the issue was gone. I also tried to increase DB pool from 5 to 10, but it didn't fix the issue. I'm using Rails 7.0.8.1.
@bensheldon
Copy link
Owner

That's not good!

Are you using the configuration for Puma described in this section?

https://github.com/bensheldon/good_job?tab=readme-ov-file#execute-jobs-async--in-process

Also, could you try setting the worker count to zero?

@bensheldon bensheldon mentioned this issue Mar 29, 2024
Merged
@bensheldon
Copy link
Owner

I just reverted the change in 3.27.1: https://github.com/bensheldon/good_job/releases/tag/v3.27.3

@arashm
Copy link
Author

arashm commented Mar 29, 2024

Sorry for the late response. I added the Puma hooks configurations and it seems working fine now with versions 3.27.1 and 3.27.2.

before_fork do
  GoodJob.shutdown
end

on_worker_boot do
  GoodJob.restart
end

on_worker_shutdown do
  GoodJob.shutdown
end

MAIN_PID = Process.pid
at_exit do
  GoodJob.shutdown if Process.pid == MAIN_PID
end

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
GoodJob Backlog v2
Status: Done
Milestone
No milestone
Development

No branches or pull requests
2 participants
@bensheldon @arashm