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.

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

ActiveRecord::StatementInvalid: PG::ConnectionBad: PQsocket() can't get socket descriptor every 30 minutes aprox. #579

Closed
bbonamin opened this issue Apr 21, 2022 · 12 comments · Fixed by #689

Comments

@bbonamin
Copy link

Hi there! thanks for this amazing gem.

Since going to production with an application that's very low traffic and mostly idle, with a few cron tasks scheduled (every 6 hours, 12 hours, and weekly respectively), I've started seeing the exception in the title every 30 minutes being reported to Rollbar.

We're running the "async" method in production since running more than one process is non-trivial (and the load is more than fine for now).

The application works fine, scheduled tasks work fine, but we get this annoying error reported.

I have no clue as to how to even start debugging this, any ideas?

FULL BACKTRACE HERE
PG::ConnectionBad: PQconsumeInput() server closed the connection unexpectedly
This probably means the server terminated abnormally
before or while processing the request.

1
File "/app/vendor/bundle/ruby/3.1.0/gems/good_job-2.12.1/lib/good_job/notifier.rb" line 209 in wait_for_notify
2
File "/app/vendor/bundle/ruby/3.1.0/gems/good_job-2.12.1/lib/good_job/notifier.rb" line 209 in wait_for_notify
3
File "/app/vendor/bundle/ruby/3.1.0/gems/good_job-2.12.1/lib/good_job/notifier.rb" line 167 in block (3 levels) in listen
4
File "/app/vendor/bundle/ruby/3.1.0/gems/activesupport-7.0.2.3/lib/active_support/concurrency/share_lock.rb" line 187 in yield_shares
5
File "/app/vendor/bundle/ruby/3.1.0/gems/activesupport-7.0.2.3/lib/active_support/dependencies/interlock.rb" line 41 in permit_concurrent_loads
6
File "/app/vendor/bundle/ruby/3.1.0/gems/good_job-2.12.1/lib/good_job/notifier.rb" line 165 in block (2 levels) in listen
7
File "/app/vendor/bundle/ruby/3.1.0/gems/good_job-2.12.1/lib/good_job/notifier.rb" line 200 in with_connection
8
File "/app/vendor/bundle/ruby/3.1.0/gems/good_job-2.12.1/lib/good_job/notifier.rb" line 156 in block in listen
9
File "/app/vendor/bundle/ruby/3.1.0/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb" line 24 in block in execute
10
File "/app/vendor/bundle/ruby/3.1.0/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb" line 47 in block in synchronize
11
File "/app/vendor/bundle/ruby/3.1.0/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb" line 47 in synchronize
12
File "/app/vendor/bundle/ruby/3.1.0/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb" line 47 in synchronize
13
File "/app/vendor/bundle/ruby/3.1.0/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb" line 22 in execute
14
File "/app/vendor/bundle/ruby/3.1.0/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/ivar.rb" line 169 in safe_execute
15
File "/app/vendor/bundle/ruby/3.1.0/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/scheduled_task.rb" line 298 in process_task
16
File "/app/vendor/bundle/ruby/3.1.0/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/timer_set.rb" line 165 in block (2 levels) in process_tasks
17
File "/app/vendor/bundle/ruby/3.1.0/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb" line 352 in run_task
18
File "/app/vendor/bundle/ruby/3.1.0/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb" line 343 in block (3 levels) in create_worker
19
File "/app/vendor/bundle/ruby/3.1.0/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb" line 334 in loop
20
File "/app/vendor/bundle/ruby/3.1.0/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb" line 334 in block (2 levels) in create_worker
21
File "/app/vendor/bundle/ruby/3.1.0/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb" line 333 in catch
22
File "/app/vendor/bundle/ruby/3.1.0/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb" line 333 in block in create_worker
PG::ConnectionBad: PQsocket() can't get socket descriptor
1
File "/app/vendor/bundle/ruby/3.1.0/gems/activerecord-7.0.2.3/lib/active_record/connection_adapters/postgresql/database_statements.rb" line 48 in exec
2
File "/app/vendor/bundle/ruby/3.1.0/gems/activerecord-7.0.2.3/lib/active_record/connection_adapters/postgresql/database_statements.rb" line 48 in block (2 levels) in execute
3
File "/app/vendor/bundle/ruby/3.1.0/gems/activesupport-7.0.2.3/lib/active_support/concurrency/share_lock.rb" line 187 in yield_shares
4
File "/app/vendor/bundle/ruby/3.1.0/gems/activesupport-7.0.2.3/lib/active_support/dependencies/interlock.rb" line 41 in permit_concurrent_loads
5
File "/app/vendor/bundle/ruby/3.1.0/gems/activerecord-7.0.2.3/lib/active_record/connection_adapters/postgresql/database_statements.rb" line 47 in block in execute
6
File "/app/vendor/bundle/ruby/3.1.0/gems/activesupport-7.0.2.3/lib/active_support/concurrency/load_interlock_aware_monitor.rb" line 25 in handle_interrupt
7
File "/app/vendor/bundle/ruby/3.1.0/gems/activesupport-7.0.2.3/lib/active_support/concurrency/load_interlock_aware_monitor.rb" line 25 in block in synchronize
8
File "/app/vendor/bundle/ruby/3.1.0/gems/activesupport-7.0.2.3/lib/active_support/concurrency/load_interlock_aware_monitor.rb" line 21 in handle_interrupt
9
File "/app/vendor/bundle/ruby/3.1.0/gems/activesupport-7.0.2.3/lib/active_support/concurrency/load_interlock_aware_monitor.rb" line 21 in synchronize
10
File "/app/vendor/bundle/ruby/3.1.0/gems/activerecord-7.0.2.3/lib/active_record/connection_adapters/abstract_adapter.rb" line 765 in block in log
11
File "/app/vendor/bundle/ruby/3.1.0/gems/activesupport-7.0.2.3/lib/active_support/notifications/instrumenter.rb" line 24 in instrument
12
File "/app/vendor/bundle/ruby/3.1.0/gems/activerecord-7.0.2.3/lib/active_record/connection_adapters/abstract_adapter.rb" line 756 in log
13
File "/app/vendor/bundle/ruby/3.1.0/gems/activerecord-7.0.2.3/lib/active_record/connection_adapters/postgresql/database_statements.rb" line 46 in execute
14
File "/app/vendor/bundle/ruby/3.1.0/gems/good_job-2.12.1/lib/good_job/notifier.rb" line 184 in block (4 levels) in listen
15
File "/app/vendor/bundle/ruby/3.1.0/gems/activesupport-7.0.2.3/lib/active_support/notifications.rb" line 206 in block in instrument
16
File "/app/vendor/bundle/ruby/3.1.0/gems/activesupport-7.0.2.3/lib/active_support/notifications/instrumenter.rb" line 24 in instrument
17
File "/app/vendor/bundle/ruby/3.1.0/gems/activesupport-7.0.2.3/lib/active_support/notifications.rb" line 206 in instrument
18
File "/app/vendor/bundle/ruby/3.1.0/gems/good_job-2.12.1/lib/good_job/notifier.rb" line 183 in block (3 levels) in listen
19
File "/app/vendor/bundle/ruby/3.1.0/gems/activesupport-7.0.2.3/lib/active_support/callbacks.rb" line 107 in run_callbacks
20
File "/app/vendor/bundle/ruby/3.1.0/gems/good_job-2.12.1/lib/good_job/notifier.rb" line 181 in ensure in block (2 levels) in listen
21
File "/app/vendor/bundle/ruby/3.1.0/gems/good_job-2.12.1/lib/good_job/notifier.rb" line 181 in block (2 levels) in listen
22
File "/app/vendor/bundle/ruby/3.1.0/gems/good_job-2.12.1/lib/good_job/notifier.rb" line 200 in with_connection
23
File "/app/vendor/bundle/ruby/3.1.0/gems/good_job-2.12.1/lib/good_job/notifier.rb" line 156 in block in listen
24
File "/app/vendor/bundle/ruby/3.1.0/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb" line 24 in block in execute
25
File "/app/vendor/bundle/ruby/3.1.0/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb" line 47 in block in synchronize
26
File "/app/vendor/bundle/ruby/3.1.0/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb" line 47 in synchronize
27
File "/app/vendor/bundle/ruby/3.1.0/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb" line 47 in synchronize
28
File "/app/vendor/bundle/ruby/3.1.0/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb" line 22 in execute
29
File "/app/vendor/bundle/ruby/3.1.0/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/ivar.rb" line 169 in safe_execute
30
File "/app/vendor/bundle/ruby/3.1.0/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/scheduled_task.rb" line 298 in process_task
31
File "/app/vendor/bundle/ruby/3.1.0/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/timer_set.rb" line 165 in block (2 levels) in process_tasks
32
File "/app/vendor/bundle/ruby/3.1.0/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb" line 352 in run_task
33
File "/app/vendor/bundle/ruby/3.1.0/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb" line 343 in block (3 levels) in create_worker
34
File "/app/vendor/bundle/ruby/3.1.0/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb" line 334 in loop
35
File "/app/vendor/bundle/ruby/3.1.0/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb" line 334 in block (2 levels) in create_worker
36
File "/app/vendor/bundle/ruby/3.1.0/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb" line 333 in catch
37
File "/app/vendor/bundle/ruby/3.1.0/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb" line 333 in block in create_worker
ActiveRecord::StatementInvalid: PG::ConnectionBad: PQsocket() can't get socket descriptor
1
File "/app/vendor/bundle/ruby/3.1.0/gems/activerecord-7.0.2.3/lib/active_record/connection_adapters/postgresql/database_statements.rb" line 48 in exec
2
File "/app/vendor/bundle/ruby/3.1.0/gems/activerecord-7.0.2.3/lib/active_record/connection_adapters/postgresql/database_statements.rb" line 48 in block (2 levels) in execute
3
File "/app/vendor/bundle/ruby/3.1.0/gems/activesupport-7.0.2.3/lib/active_support/concurrency/share_lock.rb" line 187 in yield_shares
4
File "/app/vendor/bundle/ruby/3.1.0/gems/activesupport-7.0.2.3/lib/active_support/dependencies/interlock.rb" line 41 in permit_concurrent_loads
5
File "/app/vendor/bundle/ruby/3.1.0/gems/activerecord-7.0.2.3/lib/active_record/connection_adapters/postgresql/database_statements.rb" line 47 in block in execute
6
File "/app/vendor/bundle/ruby/3.1.0/gems/activesupport-7.0.2.3/lib/active_support/concurrency/load_interlock_aware_monitor.rb" line 25 in handle_interrupt
7
File "/app/vendor/bundle/ruby/3.1.0/gems/activesupport-7.0.2.3/lib/active_support/concurrency/load_interlock_aware_monitor.rb" line 25 in block in synchronize
8
File "/app/vendor/bundle/ruby/3.1.0/gems/activesupport-7.0.2.3/lib/active_support/concurrency/load_interlock_aware_monitor.rb" line 21 in handle_interrupt
9
File "/app/vendor/bundle/ruby/3.1.0/gems/activesupport-7.0.2.3/lib/active_support/concurrency/load_interlock_aware_monitor.rb" line 21 in synchronize
10
File "/app/vendor/bundle/ruby/3.1.0/gems/activerecord-7.0.2.3/lib/active_record/connection_adapters/abstract_adapter.rb" line 765 in block in log
11
File "/app/vendor/bundle/ruby/3.1.0/gems/activesupport-7.0.2.3/lib/active_support/notifications/instrumenter.rb" line 24 in instrument
12
File "/app/vendor/bundle/ruby/3.1.0/gems/activerecord-7.0.2.3/lib/active_record/connection_adapters/abstract_adapter.rb" line 756 in log
13
File "/app/vendor/bundle/ruby/3.1.0/gems/activerecord-7.0.2.3/lib/active_record/connection_adapters/postgresql/database_statements.rb" line 46 in execute
14
File "/app/vendor/bundle/ruby/3.1.0/gems/good_job-2.12.1/lib/good_job/notifier.rb" line 184 in block (4 levels) in listen
15
File "/app/vendor/bundle/ruby/3.1.0/gems/activesupport-7.0.2.3/lib/active_support/notifications.rb" line 206 in block in instrument
16
File "/app/vendor/bundle/ruby/3.1.0/gems/activesupport-7.0.2.3/lib/active_support/notifications/instrumenter.rb" line 24 in instrument
17
File "/app/vendor/bundle/ruby/3.1.0/gems/activesupport-7.0.2.3/lib/active_support/notifications.rb" line 206 in instrument
18
File "/app/vendor/bundle/ruby/3.1.0/gems/good_job-2.12.1/lib/good_job/notifier.rb" line 183 in block (3 levels) in listen
19
File "/app/vendor/bundle/ruby/3.1.0/gems/activesupport-7.0.2.3/lib/active_support/callbacks.rb" line 107 in run_callbacks
20
File "/app/vendor/bundle/ruby/3.1.0/gems/good_job-2.12.1/lib/good_job/notifier.rb" line 181 in ensure in block (2 levels) in listen
21
File "/app/vendor/bundle/ruby/3.1.0/gems/good_job-2.12.1/lib/good_job/notifier.rb" line 181 in block (2 levels) in listen
22
File "/app/vendor/bundle/ruby/3.1.0/gems/good_job-2.12.1/lib/good_job/notifier.rb" line 200 in with_connection
23
File "/app/vendor/bundle/ruby/3.1.0/gems/good_job-2.12.1/lib/good_job/notifier.rb" line 156 in block in listen
24
File "/app/vendor/bundle/ruby/3.1.0/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb" line 24 in block in execute
25
File "/app/vendor/bundle/ruby/3.1.0/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb" line 47 in block in synchronize
26
File "/app/vendor/bundle/ruby/3.1.0/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb" line 47 in synchronize
27
File "/app/vendor/bundle/ruby/3.1.0/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb" line 47 in synchronize
28
File "/app/vendor/bundle/ruby/3.1.0/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb" line 22 in execute
29
File "/app/vendor/bundle/ruby/3.1.0/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/ivar.rb" line 169 in safe_execute
30
File "/app/vendor/bundle/ruby/3.1.0/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/scheduled_task.rb" line 298 in process_task
31
File "/app/vendor/bundle/ruby/3.1.0/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/timer_set.rb" line 165 in block (2 levels) in process_tasks
32
File "/app/vendor/bundle/ruby/3.1.0/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb" line 352 in run_task
33
File "/app/vendor/bundle/ruby/3.1.0/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb" line 343 in block (3 levels) in create_worker
34
File "/app/vendor/bundle/ruby/3.1.0/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb" line 334 in loop
35
File "/app/vendor/bundle/ruby/3.1.0/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb" line 334 in block (2 levels) in create_worker
36
File "/app/vendor/bundle/ruby/3.1.0/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb" line 333 in catch
37
File "/app/vendor/bundle/ruby/3.1.0/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb" line 333 in block in create_worker

Strangely enough this happens exactly every 30 minutes
image

@bensheldon
Copy link
Owner

@bbonamin thanks for reporting this! That's really strange that you're seeing these database errors, especially so regularly.

It's not unexpected that the Notifier would report a database connection error occassionally because it holds a long-running database connection. But it is unexpected that it would happen at regular intervals, which makes me think something else is going on.

Is there anything happening in your application that would be on a 30-minute interval? Things that I could imagine might break the database connection:

  • Something that forks. e.g. puma-worker-killer
  • Something that's manually touching/disconnecting ActiveRecord::ConnectionAdapters
  • Something on your database side that's closing connections or hitting a max-connection limit?

Aside: this also makes me wonder whether Connection-related errors shouldn't be always/immediately sent to the error reporter, so they only happen when there is a persistent/long-lasting inability to connect (or maybe that itself isn't even a valid error because it's dependency related?).

@bbonamin
Copy link
Author

hey @bensheldon thanks for your reply!

Something on your database side that's closing connections or hitting a max-connection limit?

I think this is the problem. I'm running a postgres database in fly.io and there's been another issue reporting similar behavior (but with SQLAlchemy). Apparently their default postgres configuration will kill idle connections after 30 mins, which matches the behavior I'm seeing (and the error message we're getting from ActiveRecord)

I'll follow up on that thread. Sorry for taking your time!

RE your aside: it's a tricky balance because I want to know about all unhandled exceptions happening in my application, but again there should probably be some kind of easy setting to mute them. There's a setting in Rollbar to ignore certain kind of exceptions, but in this case I'd prefer to fix it!

@bbonamin
Copy link
Author

hey @bensheldon sorry for reopening. Apparently ActiveRecord will recycle connections every 5 minutes according to the docs, by default? So perhaps as this is happening on idle connections we could add this error to

CONNECTION_ERRORS = %w[
?

@bbonamin bbonamin reopened this Apr 25, 2022
@bensheldon
Copy link
Owner

I did some more research on this. The CONNECTION_ERRORS value only controls whether GoodJob will sleep for a few seconds before trying to reconnect again.

What I think I want to do here is instead add additional behavior so that, if the error is a connection error, it will ignore 3 (?) consecutive errors before triggering on_thread_error (and maybe only trigger it once for the same consecutive error).

That would reduce the monitoring noise you're seeing, while still surfacing an error if the connection problem persists.

@brentgreeff
Copy link

I am seeing PG::ConnectionBad: PQsocket() can't get socket descriptor - on https://render.com

App, Postgres and GoodJob worker are on different instances.

It seems that I get one of these errors from Sentry, almost exactly - every 2 hours. - doing a deploy seems to refresh the clock, and an exception will normally appear with 2 minutes of a deploy.

  • database.yml - has
    pool: <%= ENV.fetch("RAILS_MAX_THREADS") { 5 } %> -

The db-connection-graph looks like a ecg machine - spiking between 2 & 9 connections.

I read : https://github.com/bensheldon/good_job#database-connections

pool: <%= ENV.fetch("RAILS_MAX_THREADS", 5).to_i + 3 + ENV.fetch("GOOD_JOB_MAX_THREADS", 5).to_i %>

I am not sure how to read this. - does this assume that RAILS_MAX_THREADS is for an app running on the same machine as good_job?

If I am running --max-threads=1 - then I need 2 total - so I guess 5 is enough?

execution_mode = :external - So I guess Puma config is not relevant?

If you need more details - or you can give me some tips on how to investigate further - I would appreciate it.

Logs below:

GoodJob Worker log

Aug 4 11:56:14 PM ==> Starting service with 'bundle exec good_job start --max-threads=1'
Aug 4 11:57:14 PM I, [2022-08-04T21:19:23.714799 #69] INFO -- : [GoodJob] [69] GoodJob started scheduler with queues=* max_threads=1.
Aug 4 11:57:14 PM I, [2022-08-04T21:19:23.750396 #69] INFO -- : [GoodJob] Notifier subscribed with LISTEN
Aug 4 11:57:14 PM I, [2022-08-04T21:57:14.046688 #69] INFO -- : [GoodJob] Notifier unsubscribed with UNLISTEN
Aug 4 11:57:14 PM E, [2022-08-04T21:57:14.050834 #69] ERROR -- : [GoodJob] Notifier errored: PG::ConnectionBad: PQconsumeInput() server closed the connection unexpectedly
Aug 4 11:57:14 PM This probably means the server terminated abnormally
Aug 4 11:57:14 PM before or while processing the request.
Aug 4 11:57:14 PM server closed the connection unexpectedly
Aug 4 11:57:14 PM This probably means the server terminated abnormally
Aug 4 11:57:14 PM before or while processing the request.
Aug 4 11:57:14 PM server closed the connection unexpectedly
Aug 4 11:57:14 PM This probably means the server terminated abnormally
Aug 4 11:57:14 PM before or while processing the request.


app-stack-trace

activerecord (7.0.3.1) lib/active_record/connection_adapters/postgresql/database_statements.rb in exec at line 48
activerecord (7.0.3.1) lib/active_record/connection_adapters/postgresql/database_statements.rb in block (2 levels) in execute at line 48
activesupport (7.0.3.1) lib/active_support/concurrency/share_lock.rb in yield_shares at line 187
activesupport (7.0.3.1) lib/active_support/dependencies/interlock.rb in permit_concurrent_loads at line 41
activerecord (7.0.3.1) lib/active_record/connection_adapters/postgresql/database_statements.rb in block in execute at line 47
activesupport (7.0.3.1) lib/active_support/concurrency/load_interlock_aware_monitor.rb in handle_interrupt at line 25
activesupport (7.0.3.1) lib/active_support/concurrency/load_interlock_aware_monitor.rb in block in synchronize at line 25
activesupport (7.0.3.1) lib/active_support/concurrency/load_interlock_aware_monitor.rb in handle_interrupt at line 21
activesupport (7.0.3.1) lib/active_support/concurrency/load_interlock_aware_monitor.rb in synchronize at line 21
activerecord (7.0.3.1) lib/active_record/connection_adapters/abstract_adapter.rb in block in log at line 765
activesupport (7.0.3.1) lib/active_support/notifications/instrumenter.rb in instrument at line 24
sentry-rails (5.3.1) lib/sentry/rails/tracing.rb in instrument at line 54
activerecord (7.0.3.1) lib/active_record/connection_adapters/abstract_adapter.rb in log at line 756
activerecord (7.0.3.1) lib/active_record/connection_adapters/postgresql/database_statements.rb in execute at line 46
good_job (3.3.0) lib/good_job/notifier.rb in block (4 levels) in listen at line 184
activesupport (7.0.3.1) lib/active_support/notifications.rb in block in instrument at line 206
activesupport (7.0.3.1) lib/active_support/notifications/instrumenter.rb in instrument at line 24
sentry-rails (5.3.1) lib/sentry/rails/tracing.rb in instrument at line 54
activesupport (7.0.3.1) lib/active_support/notifications.rb in instrument at line 206
good_job (3.3.0) lib/good_job/notifier.rb in block (3 levels) in listen at line 183
activesupport (7.0.3.1) lib/active_support/callbacks.rb in run_callbacks at line 107
good_job (3.3.0) lib/good_job/notifier.rb in ensure in block (2 levels) in listen at line 181
good_job (3.3.0) lib/good_job/notifier.rb in block (2 levels) in listen at line 181
good_job (3.3.0) lib/good_job/notifier.rb in with_connection at line 200
good_job (3.3.0) lib/good_job/notifier.rb in block in listen at line 156
concurrent-ruby (1.1.10) lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb in block in execute at line 24
concurrent-ruby (1.1.10) lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb in block in synchronize at line 47
concurrent-ruby (1.1.10) lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb in synchronize at line 47
1
concurrent-ruby (1.1.10) lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb in execute at line 22
concurrent-ruby (1.1.10) lib/concurrent-ruby/concurrent/ivar.rb in safe_execute at line 169
concurrent-ruby (1.1.10) lib/concurrent-ruby/concurrent/scheduled_task.rb in process_task at line 298
concurrent-ruby (1.1.10) lib/concurrent-ruby/concurrent/executor/timer_set.rb in block (2 levels) in process_tasks at line 165
concurrent-ruby (1.1.10) lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb in run_task at line 352
concurrent-ruby (1.1.10) lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb in block (3 levels) in create_worker at line 343
concurrent-ruby (1.1.10) lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb in loop at line 334
concurrent-ruby (1.1.10) lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb in block (2 levels) in create_worker at line 334
concurrent-ruby (1.1.10) lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb in catch at line 333
concurrent-ruby (1.1.10) lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb in block in create_worker at line 333

@bensheldon
Copy link
Owner

@brentgreeff thanks for the logs. You've convinced me to bump this up in priority.

I think the approach in my previous comment still sounds like the right one.

To your other question:

I am not sure how to read this. - does this assume that RAILS_MAX_THREADS is for an app running on the same machine as good_job?

Yes, that's configuration if you're running GoodJob async within the webserver process, when you need to account for both puma threads and GoodJob threads in the same Rails process and sharing the same ActiveRecord Connection Pool.

@brentgreeff
Copy link

Mine are happening every 2 hours - so I will have to ignore this in Sentry - but I wonder how rails / puma deals with this. - it must have the same problem to handle.

@bensheldon
Copy link
Owner

I wonder how rails / puma deals with this. - it must have the same problem to handle.

Rails does have this problem, I think it's just much, much more rare. Example: rails/rails#29189

It happens with GoodJob because GoodJob performs the equivalent of long-running queries for LISTENing; there's simply always an open and active connection.

I went to see how ActionCable's Postgres Adapter handles it, because that's what GoodJob's Notifier is based upon... and there is no error handling whatsoever 🤷🏻 It looks an exception will kill the adapter and it won't be restarted at all. Maybe an area for improvement in Rails, if anyone (other than me) actually uses the ActionCable Postgres Adapter.

@bensheldon
Copy link
Owner

I just released GoodJob v3.4.1 which contains a fix for this. Please let me know if you continue to see this error.

@brentgreeff
Copy link

Hi again

I am having issues on Render -
Goodjob didnt start the last deploy - I am using Sentry - whats the easiest way to get a slack notification if good_job doesnt start?

LOG

Aug 18 10:10:24 AM I, [2022-08-16T10:06:53.493704 #69] INFO -- : [GoodJob] Notifier unsubscribed with UNLISTEN
Aug 18 10:10:24 AM E, [2022-08-16T10:06:53.493998 #69] ERROR -- : [GoodJob] Notifier errored: PG::ConnectionBad: PQsocket() can't get socket descriptor
Aug 18 10:10:24 AM I, [2022-08-16T10:06:58.496095 #69] INFO -- : [GoodJob] Notifier subscribed with LISTEN
Aug 18 10:10:24 AM I, [2022-08-16T12:07:02.449598 #69] INFO -- : [GoodJob] Notifier unsubscribed with UNLISTEN
Aug 18 10:10:24 AM E, [2022-08-16T12:07:02.449842 #69] ERROR -- : [GoodJob] Notifier errored: PG::ConnectionBad: PQsocket() can't get socket descriptor
Aug 18 10:10:24 AM I, [2022-08-16T12:07:07.452063 #69] INFO -- : [GoodJob] Notifier subscribed with LISTEN
Aug 18 10:10:24 AM I, [2022-08-16T14:07:11.409778 #69] INFO -- : [GoodJob] Notifier unsubscribed with UNLISTEN
Aug 18 10:10:24 AM E, [2022-08-16T14:07:11.410093 #69] ERROR -- : [GoodJob] Notifier errored: PG::ConnectionBad: PQsocket() can't get socket descriptor
Aug 18 10:10:24 AM I, [2022-08-16T14:07:16.412238 #69] INFO -- : [GoodJob] Notifier subscribed with LISTEN
Aug 18 10:10:24 AM I, [2022-08-16T16:07:20.373541 #69] INFO -- : [GoodJob] Notifier unsubscribed with UNLISTEN
Aug 18 10:10:24 AM E, [2022-08-16T16:07:20.373757 #69] ERROR -- : [GoodJob] Notifier errored: PG::ConnectionBad: PQsocket() can't get socket descriptor
Aug 18 10:10:24 AM I, [2022-08-16T16:07:25.376346 #69] INFO -- : [GoodJob] Notifier subscribed with LISTEN
Aug 18 10:10:24 AM I, [2022-08-16T18:07:29.333577 #69] INFO -- : [GoodJob] Notifier unsubscribed with UNLISTEN
Aug 18 10:10:24 AM E, [2022-08-16T18:07:29.333800 #69] ERROR -- : [GoodJob] Notifier errored: PG::ConnectionBad: PQsocket() can't get socket descriptor
Aug 18 10:10:24 AM I, [2022-08-16T18:07:34.336065 #69] INFO -- : [GoodJob] Notifier subscribed with LISTEN
Aug 18 10:10:24 AM I, [2022-08-16T20:07:38.289546 #69] INFO -- : [GoodJob] Notifier unsubscribed with UNLISTEN
Aug 18 10:10:24 AM E, [2022-08-16T20:07:38.289899 #69] ERROR -- : [GoodJob] Notifier errored: PG::ConnectionBad: PQsocket() can't get socket descriptor
Aug 18 10:10:24 AM I, [2022-08-16T20:07:43.291913 #69] INFO -- : [GoodJob] Notifier subscribed with LISTEN
Aug 18 10:10:24 AM I, [2022-08-16T22:07:47.249710 #69] INFO -- : [GoodJob] Notifier unsubscribed with UNLISTEN
Aug 18 10:10:24 AM E, [2022-08-16T22:07:47.249979 #69] ERROR -- : [GoodJob] Notifier errored: PG::ConnectionBad: PQsocket() can't get socket descriptor
Aug 18 10:10:24 AM I, [2022-08-16T22:07:52.252104 #69] INFO -- : [GoodJob] Notifier subscribed with LISTEN
Aug 18 10:10:24 AM I, [2022-08-17T00:07:56.209586 #69] INFO -- : [GoodJob] Notifier unsubscribed with UNLISTEN
Aug 18 10:10:24 AM E, [2022-08-17T00:07:56.209790 #69] ERROR -- : [GoodJob] Notifier errored: PG::ConnectionBad: PQsocket() can't get socket descriptor
Aug 18 10:10:24 AM I, [2022-08-17T00:08:01.211815 #69] INFO -- : [GoodJob] Notifier subscribed with LISTEN
Aug 18 10:10:24 AM I, [2022-08-17T02:08:05.230185 #69] INFO -- : [GoodJob] Notifier unsubscribed with UNLISTEN
Aug 18 10:10:24 AM E, [2022-08-17T02:08:05.230557 #69] ERROR -- : [GoodJob] Notifier errored: PG::ConnectionBad: PQsocket() can't get socket descriptor
Aug 18 10:10:24 AM I, [2022-08-17T02:08:10.232760 #69] INFO -- : [GoodJob] Notifier subscribed with LISTEN
Aug 18 10:10:24 AM I, [2022-08-17T04:08:14.133524 #69] INFO -- : [GoodJob] Notifier unsubscribed with UNLISTEN
Aug 18 10:10:24 AM E, [2022-08-17T04:08:14.133768 #69] ERROR -- : [GoodJob] Notifier errored: PG::ConnectionBad: PQsocket() can't get socket descriptor
Aug 18 10:10:24 AM I, [2022-08-17T04:08:19.136107 #69] INFO -- : [GoodJob] Notifier subscribed with LISTEN
Aug 18 10:10:24 AM I, [2022-08-17T06:08:23.089710 #69] INFO -- : [GoodJob] Notifier unsubscribed with UNLISTEN
Aug 18 10:10:24 AM E, [2022-08-17T06:08:23.089924 #69] ERROR -- : [GoodJob] Notifier errored: PG::ConnectionBad: PQsocket() can't get socket descriptor
Aug 18 10:10:24 AM I, [2022-08-17T06:08:28.092292 #69] INFO -- : [GoodJob] Notifier subscribed with LISTEN
Aug 18 10:10:24 AM I, [2022-08-17T08:08:32.053681 #69] INFO -- : [GoodJob] Notifier unsubscribed with UNLISTEN
Aug 18 10:10:24 AM E, [2022-08-17T08:08:32.053922 #69] ERROR -- : [GoodJob] Notifier errored: PG::ConnectionBad: PQsocket() can't get socket descriptor
Aug 18 10:10:24 AM I, [2022-08-17T08:08:37.056119 #69] INFO -- : [GoodJob] Notifier subscribed with LISTEN
Aug 18 10:10:24 AM I, [2022-08-17T10:08:41.009722 #69] INFO -- : [GoodJob] Notifier unsubscribed with UNLISTEN
Aug 18 10:10:24 AM E, [2022-08-17T10:08:41.009986 #69] ERROR -- : [GoodJob] Notifier errored: PG::ConnectionBad: PQsocket() can't get socket descriptor
Aug 18 10:10:24 AM I, [2022-08-17T10:08:46.012161 #69] INFO -- : [GoodJob] Notifier subscribed with LISTEN
Aug 18 10:10:24 AM I, [2022-08-17T12:08:49.969915 #69] INFO -- : [GoodJob] Notifier unsubscribed with UNLISTEN
Aug 18 10:10:24 AM E, [2022-08-17T12:08:49.970127 #69] ERROR -- : [GoodJob] Notifier errored: PG::ConnectionBad: PQsocket() can't get socket descriptor
Aug 18 10:10:24 AM I, [2022-08-17T12:08:54.972115 #69] INFO -- : [GoodJob] Notifier subscribed with LISTEN
Aug 18 10:10:24 AM I, [2022-08-17T14:08:58.929510 #69] INFO -- : [GoodJob] Notifier unsubscribed with UNLISTEN
Aug 18 10:10:24 AM E, [2022-08-17T14:08:58.929730 #69] ERROR -- : [GoodJob] Notifier errored: PG::ConnectionBad: PQsocket() can't get socket descriptor
Aug 18 10:10:24 AM I, [2022-08-17T14:09:03.931875 #69] INFO -- : [GoodJob] Notifier subscribed with LISTEN
Aug 18 10:10:24 AM I, [2022-08-17T16:09:07.889745 #69] INFO -- : [GoodJob] Notifier unsubscribed with UNLISTEN
Aug 18 10:10:24 AM E, [2022-08-17T16:09:07.889983 #69] ERROR -- : [GoodJob] Notifier errored: PG::ConnectionBad: PQsocket() can't get socket descriptor
Aug 18 10:10:24 AM I, [2022-08-17T16:09:12.892113 #69] INFO -- : [GoodJob] Notifier subscribed with LISTEN
Aug 18 10:10:24 AM I, [2022-08-17T18:09:16.853337 #69] INFO -- : [GoodJob] Notifier unsubscribed with UNLISTEN
Aug 18 10:10:24 AM E, [2022-08-17T18:09:16.853536 #69] ERROR -- : [GoodJob] Notifier errored: PG::ConnectionBad: PQsocket() can't get socket descriptor
Aug 18 10:10:24 AM I, [2022-08-17T18:09:21.856238 #69] INFO -- : [GoodJob] Notifier subscribed with LISTEN
Aug 18 10:10:24 AM I, [2022-08-17T20:09:25.809551 #69] INFO -- : [GoodJob] Notifier unsubscribed with UNLISTEN
Aug 18 10:10:24 AM E, [2022-08-17T20:09:25.809991 #69] ERROR -- : [GoodJob] Notifier errored: PG::ConnectionBad: PQsocket() can't get socket descriptor
Aug 18 10:10:24 AM I, [2022-08-17T20:09:30.812221 #69] INFO -- : [GoodJob] Notifier subscribed with LISTEN
Aug 18 10:10:24 AM I, [2022-08-17T22:09:34.773612 #69] INFO -- : [GoodJob] Notifier unsubscribed with UNLISTEN
Aug 18 10:10:24 AM E, [2022-08-17T22:09:34.773833 #69] ERROR -- : [GoodJob] Notifier errored: PG::ConnectionBad: PQsocket() can't get socket descriptor
Aug 18 10:10:24 AM I, [2022-08-17T22:09:39.775978 #69] INFO -- : [GoodJob] Notifier subscribed with LISTEN
Aug 18 10:10:24 AM I, [2022-08-18T00:09:43.729474 #69] INFO -- : [GoodJob] Notifier unsubscribed with UNLISTEN
Aug 18 10:10:24 AM E, [2022-08-18T00:09:43.729692 #69] ERROR -- : [GoodJob] Notifier errored: PG::ConnectionBad: PQsocket() can't get socket descriptor
Aug 18 10:10:24 AM I, [2022-08-18T00:09:48.731770 #69] INFO -- : [GoodJob] Notifier subscribed with LISTEN
Aug 18 10:10:24 AM I, [2022-08-18T02:09:52.689470 #69] INFO -- : [GoodJob] Notifier unsubscribed with UNLISTEN
Aug 18 10:10:24 AM E, [2022-08-18T02:09:52.689674 #69] ERROR -- : [GoodJob] Notifier errored: PG::ConnectionBad: PQsocket() can't get socket descriptor
Aug 18 10:10:24 AM I, [2022-08-18T02:09:57.691695 #69] INFO -- : [GoodJob] Notifier subscribed with LISTEN
Aug 18 10:10:24 AM I, [2022-08-18T04:10:01.657577 #69] INFO -- : [GoodJob] Notifier unsubscribed with UNLISTEN
Aug 18 10:10:24 AM E, [2022-08-18T04:10:01.657928 #69] ERROR -- : [GoodJob] Notifier errored: PG::ConnectionBad: PQsocket() can't get socket descriptor
Aug 18 10:10:24 AM I, [2022-08-18T04:10:06.666428 #69] INFO -- : [GoodJob] Notifier subscribed with LISTEN
Aug 18 10:10:24 AM I, [2022-08-18T06:10:10.609676 #69] INFO -- : [GoodJob] Notifier unsubscribed with UNLISTEN
Aug 18 10:10:24 AM E, [2022-08-18T06:10:10.610010 #69] ERROR -- : [GoodJob] Notifier errored: PG::ConnectionBad: PQsocket() can't get socket descriptor
Aug 18 10:10:24 AM I, [2022-08-18T06:10:15.613040 #69] INFO -- : [GoodJob] Notifier subscribed with LISTEN
Aug 18 10:10:24 AM I, [2022-08-18T08:10:19.569507 #69] INFO -- : [GoodJob] Notifier unsubscribed with UNLISTEN
Aug 18 10:10:24 AM E, [2022-08-18T08:10:19.569722 #69] ERROR -- : [GoodJob] Notifier errored: PG::ConnectionBad: PQsocket() can't get socket descriptor
Aug 18 10:10:24 AM I, [2022-08-18T08:10:24.572050 #69] INFO -- : [GoodJob] Notifier subscribed with LISTEN
Aug 18 10:45:00 AM ==> Starting service with 'bundle exec good_job start --max-threads=1'
Aug 18 10:46:00 AM I, [2022-08-18T08:46:00.694745 #69] INFO -- : [GoodJob] Notifier unsubscribed with UNLISTEN
Aug 18 10:46:00 AM E, [2022-08-18T08:46:00.694951 #69] ERROR -- : [GoodJob] Notifier errored: PG::ConnectionBad: PQconsumeInput() server closed the connection unexpectedly
Aug 18 10:46:00 AM This probably means the server terminated abnormally
Aug 18 10:46:00 AM before or while processing the request.
Aug 18 10:46:00 AM server closed the connection unexpectedly
Aug 18 10:46:00 AM This probably means the server terminated abnormally
Aug 18 10:46:00 AM before or while processing the request.
Aug 18 10:46:00 AM server closed the connection unexpectedly
Aug 18 10:46:00 AM This probably means the server terminated abnormally
Aug 18 10:46:00 AM before or while processing the request.
Aug 18 10:46:00 AM
Aug 18 10:46:00 AM I, [2022-08-18T08:46:00.695706 #69] INFO -- : [GoodJob] [69] GoodJob shutting down scheduler...
Aug 18 10:46:00 AM I, [2022-08-18T08:46:00.696000 #69] INFO -- : [GoodJob] [69] GoodJob scheduler is shut down.
Aug 18 11:35:49 AM ==> Starting service with 'bundle exec good_job start --max-threads=1'
Aug 18 11:36:48 AM I, [2022-08-18T08:45:09.635120 #69] INFO -- : [GoodJob] [69] GoodJob started scheduler with queues=* max_threads=1.
Aug 18 11:36:48 AM I, [2022-08-18T08:45:09.719416 #69] INFO -- : [GoodJob] Notifier subscribed with LISTEN
Aug 18 11:36:48 AM I, [2022-08-18T09:36:48.825067 #69] INFO -- : [GoodJob] Notifier unsubscribed with UNLISTEN
Aug 18 11:36:48 AM E, [2022-08-18T09:36:48.825412 #69] ERROR -- : [GoodJob] Notifier errored: PG::ConnectionBad: PQconsumeInput() server closed the connection unexpectedly
Aug 18 11:36:48 AM This probably means the server terminated abnormally
Aug 18 11:36:48 AM before or while processing the request.
Aug 18 11:36:48 AM server closed the connection unexpectedly
Aug 18 11:36:48 AM This probably means the server terminated abnormally
Aug 18 11:36:48 AM before or while processing the request.
Aug 18 11:36:48 AM server closed the connection unexpectedly
Aug 18 11:36:48 AM This probably means the server terminated abnormally
Aug 18 11:36:48 AM before or while processing the request.
Aug 18 11:36:48 AM
Aug 18 11:36:48 AM I, [2022-08-18T09:36:48.826110 #69] INFO -- : [GoodJob] [69] GoodJob shutting down scheduler...
Aug 18 11:36:48 AM I, [2022-08-18T09:36:48.826519 #69] INFO -- : [GoodJob] [69] GoodJob scheduler is shut down.
Aug 18 12:03:47 PM ==> Starting service with 'bundle exec good_job start --max-threads=1'
Aug 18 12:04:47 PM I, [2022-08-18T09:35:58.747577 #69] INFO -- : [GoodJob] [69] GoodJob started scheduler with queues=* max_threads=1.
Aug 18 12:04:47 PM I, [2022-08-18T09:35:58.829444 #69] INFO -- : [GoodJob] Notifier subscribed with LISTEN
Aug 18 12:04:47 PM I, [2022-08-18T10:04:47.551823 #69] INFO -- : [GoodJob] Notifier unsubscribed with UNLISTEN
Aug 18 12:04:47 PM E, [2022-08-18T10:04:47.552097 #69] ERROR -- : [GoodJob] Notifier errored: PG::ConnectionBad: PQconsumeInput() server closed the connection unexpectedly
Aug 18 12:04:47 PM This probably means the server terminated abnormally
Aug 18 12:04:47 PM before or while processing the request.
Aug 18 12:04:47 PM server closed the connection unexpectedly
Aug 18 12:04:47 PM This probably means the server terminated abnormally
Aug 18 12:04:47 PM before or while processing the request.
Aug 18 12:04:47 PM server closed the connection unexpectedly
Aug 18 12:04:47 PM This probably means the server terminated abnormally
Aug 18 12:04:47 PM before or while processing the request.
Aug 18 12:04:47 PM
Aug 18 12:04:47 PM I, [2022-08-18T10:04:47.552681 #69] INFO -- : [GoodJob] [69] GoodJob shutting down scheduler...
Aug 18 12:04:47 PM I, [2022-08-18T10:04:47.552990 #69] INFO -- : [GoodJob] [69] GoodJob scheduler is shut down.

@bbonamin
Copy link
Author

I can confirm the latest release fixed this for me 👍 thank you very much!

@brentgreeff
Copy link

I just upgraded;

-    good_job (3.4.1)
+    good_job (3.4.3)

Will keep you updated.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
3 participants