Resque: unexpected EOF on client connection

Created on 24 Aug 2011  Â·  38Comments  Â·  Source: resque/resque

Hello,

we have noticed a lot of :

2011-08-24 15:24:00 CEST LOG:  could not receive data from client: Connection reset by peer
2011-08-24 15:24:00 CEST LOG:  unexpected EOF on client connection

in our log. After some digging, the disconnections are coming from resque. Sounds like everytime a job is done, the worker doesn't close nicely the connection.

This issue is related to #306 : we have to establish a connection on forking.
I've tried to disconnect cleanly in done_working, but the working is dying when doing that.
Any idea ?

Bug
Source
picture gravis
👍1

All 38 comments

I was running into the same issue on Heroku and wrote a gem to fix it. Disconnecting from the db in Worker#done_working didn't work for me either, but it does work in an after_perform callback in the job. The reason is because after_perform is called inside the thread where done_working is back in the parent process.

Here's the gem...
https://github.com/simple10/resque-heroku

No more "unexpected EOF on client connection" after installing it.

simple10 picture simple10 on 12 Sep 2011
🎉1

@simple10 you say in the read me it's a Cedar centered fix, do you know if it also works with bamboo apps ?

mcansky picture mcansky on 5 Apr 2012

It should work with bamboo with some minor modifications. I forget which are the Cedar bits right off hand.

simple10 picture simple10 on 17 Apr 2012

I'm also seeing this with heroku and python.

desimone picture desimone on 21 Aug 2012

Without a way to reproduce this, it's not likely we can fix it. I'm going to close, but if someone can provide a reproduction, let's re-open.

steveklabnik picture steveklabnik on 27 Sep 2012

Was this resolved? I see a lot of these error on Heroku Cedar stack using resque with redistogo. The gem by simple10 did not resolve for me.

marclennox picture marclennox on 6 Oct 2012

If you can give me a small app that reproduces the problem, I can re-open and take a look at it. But without a way of seeing the error, there's no way I can try to fix it.

steveklabnik picture steveklabnik on 6 Oct 2012

understood.

Marc Lennox
Sent with Sparrow (http://www.sparrowmailapp.com/?sig)

On Saturday, 6 October, 2012 at 12:24 PM, Steve Klabnik wrote:

If you can give me a small app that reproduces the problem, I can re-open and take a look at it. But without a way of seeing the error, there's no way I can try to fix it.

—
Reply to this email directly or view it on GitHub (https://github.com/defunkt/resque/issues/367#issuecomment-9199610).

marclennox picture marclennox on 6 Oct 2012

I do have a Heroku account, so that's not a barrier. Does this always happen, or is it triggered by something?

steveklabnik picture steveklabnik on 6 Oct 2012

I'm pretty sure it's 100% because my Heroku log is filled with them constantly. Here's a sample.

2012-10-06T16:40:07+00:00 app[postgres]: [6-1] ub8f56dr4dsefv [IVORY] LOG: unexpected EOF on client connection
2012-10-06T16:40:07+00:00 app[postgres]: [6-1] ub8f56dr4dsefv [IVORY] LOG: unexpected EOF on client connection
2012-10-06T16:40:07+00:00 app[postgres]: [5-1] ub8f56dr4dsefv [IVORY] LOG: could not receive data from client: Connection reset by peer
2012-10-06T16:40:07+00:00 app[postgres]: [6-1] ub8f56dr4dsefv [IVORY] LOG: unexpected EOF on client connection
2012-10-06T16:40:07+00:00 app[postgres]: [5-1] ub8f56dr4dsefv [IVORY] LOG: could not receive data from client: Connection reset by peer
2012-10-06T16:40:08+00:00 heroku[api]: Deploy a3b8cc5 by [email protected]
2012-10-06T16:40:08+00:00 heroku[api]: Release v496 created by [email protected]
2012-10-06T16:40:08+00:00 heroku[web.1]: State changed from up to starting
2012-10-06T16:40:09+00:00 heroku[slugc]: Slug compilation finished
2012-10-06T16:40:09+00:00 app[postgres]: [6-1] ub8f56dr4dsefv [IVORY] LOG: unexpected EOF on client connection
2012-10-06T16:40:09+00:00 app[postgres]: [5-1] ub8f56dr4dsefv [IVORY] LOG: could not receive data from client: Connection reset by peer
2012-10-06T16:40:10+00:00 heroku[web.1]: State changed from starting to up
2012-10-06T16:40:10+00:00 heroku[web.1]: State changed from up to starting
2012-10-06T16:40:12+00:00 heroku[web.1]: Stopping all processes with SIGTERM
2012-10-06T16:40:13+00:00 app[postgres]: [5-1] ub8f56dr4dsefv [IVORY] LOG: could not receive data from client: Connection reset by peer
2012-10-06T16:40:13+00:00 app[postgres]: [6-1] ub8f56dr4dsefv [IVORY] LOG: unexpected EOF on client connection
2012-10-06T16:40:13+00:00 app[web.1]: I, [2012-10-06T16:40:13.624193 #2] INFO -- : reaped # worker=1
2012-10-06T16:40:15+00:00 app[postgres]: [5-1] ub8f56dr4dsefv [IVORY] LOG: could not receive data from client: Connection reset by peer
2012-10-06T16:40:15+00:00 app[postgres]: [5-1] ub8f56dr4dsefv [IVORY] LOG: could not receive data from client: Connection reset by peer
2012-10-06T16:40:15+00:00 app[postgres]: [6-1] ub8f56dr4dsefv [IVORY] LOG: unexpected EOF on client connection
2012-10-06T16:40:15+00:00 app[postgres]: [6-1] ub8f56dr4dsefv [IVORY] LOG: unexpected EOF on client connection
2012-10-06T16:40:15+00:00 app[web.1]: I, [2012-10-06T16:40:15.165541 #2] INFO -- : reaped # worker=0
2012-10-06T16:40:15+00:00 app[web.1]: I, [2012-10-06T16:40:15.174977 #2] INFO -- : master complete
2012-10-06T16:40:15+00:00 app[web.1]: I, [2012-10-06T16:40:15.165750 #2] INFO -- : reaped # worker=2
2012-10-06T16:40:16+00:00 heroku[web.1]: Process exited with status 0
2012-10-06T16:40:16+00:00 heroku[web.1]: Starting process with command bundle exec unicorn -p 39951 -c ./config/unicorn.rb
2012-10-06T16:40:18+00:00 app[web.1]: I, [2012-10-06T16:40:18.646990 #2] INFO -- : listening on addr=0.0.0.0:39951 fd=7
2012-10-06T16:40:18+00:00 app[web.1]: I, [2012-10-06T16:40:18.647338 #2] INFO -- : worker=0 spawning...
2012-10-06T16:40:18+00:00 app[web.1]: I, [2012-10-06T16:40:18.653235 #13] INFO -- : Refreshing Gem list
2012-10-06T16:40:18+00:00 app[web.1]: I, [2012-10-06T16:40:18.652197 #2] INFO -- : worker=1 spawning...
2012-10-06T16:40:18+00:00 app[web.1]: I, [2012-10-06T16:40:18.652973 #13] INFO -- : worker=0 spawned pid=13
2012-10-06T16:40:18+00:00 app[web.1]: I, [2012-10-06T16:40:18.654731 #2] INFO -- : worker=2 spawning...
2012-10-06T16:40:18+00:00 app[web.1]: I, [2012-10-06T16:40:18.655701 #16] INFO -- : worker=1 spawned pid=16
2012-10-06T16:40:18+00:00 app[web.1]: I, [2012-10-06T16:40:18.655977 #16] INFO -- : Refreshing Gem list
2012-10-06T16:40:18+00:00 app[web.1]: I, [2012-10-06T16:40:18.657573 #2] INFO -- : master process ready
2012-10-06T16:40:18+00:00 app[web.1]: I, [2012-10-06T16:40:18.658206 #19] INFO -- : worker=2 spawned pid=19
2012-10-06T16:40:18+00:00 app[web.1]: I, [2012-10-06T16:40:18.658394 #19] INFO -- : Refreshing Gem list
2012-10-06T16:40:19+00:00 heroku[web.1]: State changed from starting to up
2012-10-06T16:40:20+00:00 heroku[web.1]: Starting process with command bundle exec unicorn -p 13025 -c ./config/unicorn.rb
2012-10-06T16:40:22+00:00 app[web.1]: I, [2012-10-06T16:40:22.985838 #2] INFO -- : worker=1 spawning...
2012-10-06T16:40:22+00:00 app[web.1]: I, [2012-10-06T16:40:22.986871 #13] INFO -- : Refreshing Gem list
2012-10-06T16:40:22+00:00 app[web.1]: I, [2012-10-06T16:40:22.980781 #2] INFO -- : listening on addr=0.0.0.0:13025 fd=7
2012-10-06T16:40:22+00:00 app[web.1]: I, [2012-10-06T16:40:22.990788 #16] INFO -- : worker=1 spawned pid=16
2012-10-06T16:40:22+00:00 app[web.1]: I, [2012-10-06T16:40:22.981063 #2] INFO -- : worker=0 spawning...
2012-10-06T16:40:22+00:00 app[web.1]: I, [2012-10-06T16:40:22.991039 #16] INFO -- : Refreshing Gem list
2012-10-06T16:40:22+00:00 app[web.1]: I, [2012-10-06T16:40:22.986636 #13] INFO -- : worker=0 spawned pid=13
2012-10-06T16:40:22+00:00 app[web.1]: I, [2012-10-06T16:40:22.991952 #19] INFO -- : worker=2 spawned pid=19
2012-10-06T16:40:22+00:00 app[web.1]: I, [2012-10-06T16:40:22.988712 #2] INFO -- : worker=2 spawning...
2012-10-06T16:40:22+00:00 app[web.1]: I, [2012-10-06T16:40:22.991008 #2] INFO -- : master process ready
2012-10-06T16:40:22+00:00 app[web.1]: I, [2012-10-06T16:40:22.992165 #19] INFO -- : Refreshing Gem list
2012-10-06T16:40:27+00:00 app[web.1]: DEPRECATION WARNING: You have Rails 2.3-style plugins in vendor/plugins! Support for these plugins will be removed in Rails 4.0. Move them out and bundle them in your Gemfile, or fold them in to your app as lib/myplugin/* and config/initializers/myplugin.rb. See the release notes for more on this: http://weblog.rubyonrails.org/2012/1/4/rails-3-2-0-rc2-has-been-released. (called from 2012-10-06T16:40:27+00:00 app[web.1]: DEPRECATION WARNING: You have Rails 2.3-style plugins in vendor/plugins! Support for these plugins will be removed in Rails 4.0. Move them out and bundle them in your Gemfile, or fold them in to your app as lib/myplugin/* and config/initializers/myplugin.rb. See the release notes for more on this: http://weblog.rubyonrails.org/2012/1/4/rails-3-2-0-rc2-has-been-released. (called from 2012-10-06T16:40:27+00:00 app[web.1]: DEPRECATION WARNING: You have Rails 2.3-style plugins in vendor/plugins! Support for these plugins will be removed in Rails 4.0. Move them out and bundle them in your Gemfile, or fold them in to your app as lib/myplugin/* and config/initializers/myplugin.rb. See the release notes for more on this: http://weblog.rubyonrails.org/2012/1/4/rails-3-2-0-rc2-has-been-released. (called from 2012-10-06T16:40:27+00:00 app[web.1]: DEPRECATION WARNING: You have Rails 2.3-style plugins in vendor/plugins! Support for these plugins will be removed in Rails 4.0. Move them out and bundle them in your Gemfile, or fold them in to your app as lib/myplugin/* and config/initializers/myplugin.rb. See the release notes for more on this: http://weblog.rubyonrails.org/2012/1/4/rails-3-2-0-rc2-has-been-released. (called from 2012-10-06T16:40:27+00:00 app[web.1]: DEPRECATION WARNING: You have Rails 2.3-style plugins in vendor/plugins! Support for these plugins will be removed in Rails 4.0. Move them out and bundle them in your Gemfile, or fold them in to your app as lib/myplugin/* and config/initializers/myplugin.rb. See the release notes for more on this: http://weblog.rubyonrails.org/2012/1/4/rails-3-2-0-rc2-has-been-released. (called from 2012-10-06T16:40:27+00:00 app[web.1]: DEPRECATION WARNING: You have Rails 2.3-style plugins in vendor/plugins! Support for these plugins will be removed in Rails 4.0. Move them out and bundle them in your Gemfile, or fold them in to your app as lib/myplugin/* and config/initializers/myplugin.rb. See the release notes for more on this: http://weblog.rubyonrails.org/2012/1/4/rails-3-2-0-rc2-has-been-released. (called from 2012-10-06T16:40:28+00:00 heroku[web.1]: Stopping all processes with SIGTERM
2012-10-06T16:40:28+00:00 app[web.1]: ** [NewRelic][10/06/12 16:40:28 +0000 ab387c93-27c3-4aff-b270-cec34a8fdad6 (13)] INFO : New Relic Ruby Agent 3.4.2.1 Initialized: pid = 13
2012-10-06T16:40:28+00:00 app[web.1]: ** [NewRelic][10/06/12 16:40:28 +0000 ab387c93-27c3-4aff-b270-cec34a8fdad6 (13)] INFO : Application: openera-production
2012-10-06T16:40:28+00:00 app[web.1]: ** [NewRelic][10/06/12 16:40:28 +0000 ab387c93-27c3-4aff-b270-cec34a8fdad6 (13)] INFO : Dispatcher: thin
2012-10-06T16:40:28+00:00 app[web.1]: ** [NewRelic][10/06/12 16:40:28 +0000 ab387c93-27c3-4aff-b270-cec34a8fdad6 (19)] INFO : Dispatcher: thin
2012-10-06T16:40:28+00:00 app[web.1]: ** [NewRelic][10/06/12 16:40:28 +0000 ab387c93-27c3-4aff-b270-cec34a8fdad6 (19)] INFO : New Relic Ruby Agent 3.4.2.1 Initialized: pid = 19
2012-10-06T16:40:28+00:00 app[web.1]: ** [NewRelic][10/06/12 16:40:28 +0000 ab387c93-27c3-4aff-b270-cec34a8fdad6 (19)] INFO : Application: openera-production
2012-10-06T16:40:28+00:00 app[web.1]: ** [NewRelic][10/06/12 16:40:28 +0000 ab387c93-27c3-4aff-b270-cec34a8fdad6 (16)] INFO : Dispatcher: thin
2012-10-06T16:40:28+00:00 app[web.1]: ** [NewRelic][10/06/12 16:40:28 +0000 ab387c93-27c3-4aff-b270-cec34a8fdad6 (16)] INFO : New Relic Ruby Agent 3.4.2.1 Initialized: pid = 16
2012-10-06T16:40:28+00:00 app[web.1]: ** [NewRelic][10/06/12 16:40:28 +0000 ab387c93-27c3-4aff-b270-cec34a8fdad6 (16)] INFO : Application: openera-production
2012-10-06T16:40:29+00:00 app[web.1]: I, [2012-10-06T16:40:29.001895 #2] INFO -- : reaped # worker=0
2012-10-06T16:40:29+00:00 app[web.1]: I, [2012-10-06T16:40:29.110291 #2] INFO -- : reaped # worker=1
2012-10-06T16:40:29+00:00 app[web.1]: I, [2012-10-06T16:40:29.110425 #2] INFO -- : reaped # worker=2
2012-10-06T16:40:29+00:00 app[web.1]: I, [2012-10-06T16:40:29.110559 #2] INFO -- : master complete
2012-10-06T16:40:30+00:00 heroku[deployhooks]: Notified New Relic about the deploy
2012-10-06T16:40:30+00:00 heroku[web.1]: Process exited with status 0
2012-10-06T16:40:34+00:00 app[postgres]: [5-1] ub8f56dr4dsefv [IVORY] LOG: duration: 55.424 ms statement: SELECT "file_actions".* FROM "file_actions" WHERE (current_state NOT IN ('')) AND (started_at IS NOT NULL) AND (ended_at IS NULL) AND (now() > started_at + (300 * interval '1 second'))
2012-10-06T16:40:34+00:00 app[postgres]: [6-1] ub8f56dr4dsefv [IVORY] LOG: duration: 61.879 ms statement: SELECT "file_actions".* FROM "file_actions" WHERE (current_state NOT IN ('executing', 'processed')) AND (now() > next_at)
2012-10-06T16:40:34+00:00 app[postgres]: [7-1] ub8f56dr4dsefv [IVORY] LOG: could not receive data from client: Connection reset by peer
2012-10-06T16:40:34+00:00 app[postgres]: [8-1] ub8f56dr4dsefv [IVORY] LOG: unexpected EOF on client connection
2012-10-06T16:40:35+00:00 app[postgres]: [5-1] ub8f56dr4dsefv [IVORY] LOG: could not receive data from client: Connection reset by peer
2012-10-06T16:40:35+00:00 app[postgres]: [6-1] ub8f56dr4dsefv [IVORY] LOG: unexpected EOF on client connection
2012-10-06T16:40:37+00:00 app[web.1]: I, [2012-10-06T16:40:37.605326 #19] INFO -- : worker=2 ready
2012-10-06T16:40:37+00:00 app[web.1]: I, [2012-10-06T16:40:37.614676 #13] INFO -- : worker=0 ready
2012-10-06T16:40:37+00:00 app[web.1]: I, [2012-10-06T16:40:37.684254 #16] INFO -- : worker=1 ready
2012-10-06T16:40:39+00:00 app[web.1]: Connected to NewRelic Service at collector-9.newrelic.com
2012-10-06T16:40:39+00:00 app[web.1]: ** [NewRelic][10/06/12 16:40:39 +0000 ab387c93-27c3-4aff-b270-cec34a8fdad6 (13)] INFO : Reporting performance data every 60 seconds.
2012-10-06T16:40:39+00:00 app[web.1]: Connected to NewRelic Service at collector-9.newrelic.com
2012-10-06T16:40:39+00:00 app[web.1]: ** [NewRelic][10/06/12 16:40:39 +0000 ab387c93-27c3-4aff-b270-cec34a8fdad6 (19)] INFO : Reporting performance data every 60 seconds.
2012-10-06T16:40:39+00:00 app[web.1]: Connected to NewRelic Service at collector-9.newrelic.com
2012-10-06T16:40:39+00:00 app[web.1]: ** [NewRelic][10/06/12 16:40:39 +0000 ab387c93-27c3-4aff-b270-cec34a8fdad6 (16)] INFO : Reporting performance data every 60 seconds.

Marc Lennox
Sent with Sparrow (http://www.sparrowmailapp.com/?sig)

On Saturday, 6 October, 2012 at 12:39 PM, Steve Klabnik wrote:

I do have a Heroku account, so that's not a barrier. Does this always happen, or is it triggered by something?

—
Reply to this email directly or view it on GitHub (https://github.com/defunkt/resque/issues/367#issuecomment-9199781).

marclennox picture marclennox on 6 Oct 2012

I've re-opened this. I'm travelling for a few days, but on Monday I'll attempt to get an app that reproduces this. If you can get one up earlier, then I can get started fixing it earlier :)

steveklabnik picture steveklabnik on 6 Oct 2012

Thanks Steve, I'll see what I can do. I'm assuming this is not universal, so probably there's something unique about the environment that contributes to this.

Marc Lennox
Sent with Sparrow (http://www.sparrowmailapp.com/?sig)

On Saturday, 6 October, 2012 at 12:51 PM, Steve Klabnik wrote:

I've re-opened this. I'm travelling for a few days, but on Monday I'll attempt to get an app that reproduces this. If you can get one up earlier, then I can get started fixing it earlier :)

—
Reply to this email directly or view it on GitHub (https://github.com/defunkt/resque/issues/367#issuecomment-9199899).

marclennox picture marclennox on 6 Oct 2012

Hey we're experiencing this with Minefold on Heroku too. Happy to share our code-base to help diagnose the problem.

chrislloyd picture chrislloyd on 3 Dec 2012

Hey Chris,

Steve is looking for a simple heroku app that replicates the problem and that he can debug with. It's been on my "to do" list for a while now, but haven't got around to it.

marclennox picture marclennox on 4 Dec 2012

Ran into this today using the combination of Heroku (Cedar) + Sequel + Resque. The heroku-resque gem by @simple10 is not a workaround for us as it's for ActiveRecord.

I'll attempt to sidestep my "to do" list (i.e. /dev/null) and package a small app that reproduces the problem.

DevL picture DevL on 4 Dec 2012

I've updated the README for my gem to make it clear it only works with ActiveRecord.

simple10 picture simple10 on 4 Dec 2012

FWIW, we tried the heroku-resque gem - we use ActiveRecord - and we were still seing said EOF. If I can I'd like to help with the issue.

carhartl picture carhartl on 4 Dec 2012

Yeah the heroku-resque gem doesn't do anything for me either.

Marc Lennox
Sent with Sparrow (http://www.sparrowmailapp.com/?sig)

On Tuesday, 4 December, 2012 at 3:03 PM, Klaus Hartl wrote:

FWIW, we tried the heroku-resque gem - we use ActiveRecord - and we were still seing said EOF. If I can I'd like to help with the issue.

—
Reply to this email directly or view it on GitHub (https://github.com/defunkt/resque/issues/367#issuecomment-11013313).

marclennox picture marclennox on 4 Dec 2012

Well, after doing some more digging this certainly doesn't feel as a Resque issue.

Since Resque forks workers, placing any and all handling of the database in e.g. the perform method will make this issue go away. However, it does raise the following question:

_Given the case of a worker fetching jobs from Redis and storing something in e.g. a Postgres database, is it necessary to constantly open and close database connections rather than somehow keeping a connection pool around?_

To my understanding, the answer is 'yes', but please correct me if I'm wrong.

_Sidenote: Given this particular use case, Sidekiq might be a better fit as it's based on threads rather than forks?_

DevL picture DevL on 5 Dec 2012

So I'm having similar (but different) EOF errors on Heroku. I fully detailed it in a StackOverflow post.

http://stackoverflow.com/questions/14114405/resque-worker-causing-activerecordstatementinvalid-pgerror-ssl-syscall-err

Tried about everything under the run, without luck. Happening on two separate apps. Going to try that gem fix and report back.

tibbon picture tibbon on 1 Jan 2013

Awesome, thanks for the detail.

steveklabnik picture steveklabnik on 2 Jan 2013

I am seeing this issue on Heroku with sidekiq, postgres and redis. Wondering if it has to do with having too many dynos, workers, unicorn workers vs not enough database connections or a small pool.

seanrafferty picture seanrafferty on 17 Jan 2013

One thing to look for: if you have Resque.after_fork = ... or Resque.after_fork do ... end more than once in your code, you're overwriting that hook.

@steveklabnik -- would you accept a patch that changes it so that Resque.after_fork do ... end and related hooks would accept multiple callbacks so that you could do this?

Resque.after_fork do
  # stuff
end

Resque.after_fork do
  # more stuff that will also be executed
end
tysonmote picture tysonmote on 19 Jan 2013

@tysontate my understanding is that that functionality is already present in master; would be nice to have this in 1-x-stable, but that would probably be a major version bump change (and master will already be 2.0 at some point)

ecoffey picture ecoffey on 19 Jan 2013

Ah, I didn't even think to check 2.0. It's arguably a backwards incompatible change so it makes sense that it be in 2.0 rather than 1.x. Thanks for the heads up.

tysonmote picture tysonmote on 20 Jan 2013

So below is most of my unicorn config file, where the forking is happening. I'm getting some EOF problems. Is this right?:

before_fork do |server, worker|
  # Replace with MongoDB or whatever
  if defined?(ActiveRecord::Base)
    ActiveRecord::Base.connection.disconnect!
    Rails.logger.info('Disconnected from ActiveRecord')
  end

  # If you are using Redis but not Resque, change this
  if defined?(Resque)
    Resque.redis.quit
    Rails.logger.info('Disconnected from Redis')
    NewRelic::Agent.register_report_channel(worker.object_id) if ENV['NEW_RELIC_APP_NAME']
  end

  sleep 1
end

after_fork do |server, worker|
  if defined?(ActiveRecord::Base)
    ActiveRecord::Base.establish_connection
    Rails.logger.info('Connected to ActiveRecord')
  end

  if defined?(Resque)
    Resque.redis = ENV['OPENREDIS_URL'] || 'redis://localhost:6379'
    Rails.logger.info('Connected to Redis')
    NewRelic::Agent.after_fork(:report_to_channel => worker.object_id) if ENV['NEW_RELIC_APP_NAME']
  end
end

Also, my resque.rake file:
task "resque:setup" => :environment do
ENV['QUEUE'] = '*'

  if ENV['NEW_RELIC_APP_NAME']
    NewRelic::Agent.manual_start :app_name => ENV['NEW_RELIC_APP_NAME']
  end
  Resque.before_fork = Proc.new { ActiveRecord::Base.establish_connection }
end
tibbon picture tibbon on 25 Jan 2013

@tibbon Is the EOF message coming from worker or web in your Heroku logs?

A couple of notes on the code you pasted above:

  1. Keep in mind that your Unicorn before / after fork hooks wont get run in Resque (and your Resque hooks wont run in Unicorn). Unicorn and Resque have separate fork hooks.
  2. Resque manages its own Redis connection -- you don't need to do any reconnection on fork, etc. However, if you have a _separate_ Redis connection that is accessed from within your Resque jobs, you'll need to manage that connection in Resque's after_fork hook.
  3. Do you have a Resque and / or initializer file? Paste those here -- that might help.
  4. Keeping in mind #1 above, you could simplify your files a bit:

unicorn.rb:

``` ruby
before_fork do |server, worker|
# Replace with MongoDB or whatever
if defined?(ActiveRecord::Base)
ActiveRecord::Base.connection.disconnect!
Rails.logger.info('Disconnected from ActiveRecord')
end

 sleep 1

end

after_fork do |server, worker|
if defined?(ActiveRecord::Base)
ActiveRecord::Base.establish_connection
Rails.logger.info('Connected to ActiveRecord')
end
end
```

resque.rake:

``` ruby
task "resque:setup" => :environment do
ENV['QUEUE'] = '*'

 if ENV['NEW_RELIC_APP_NAME']
   NewRelic::Agent.manual_start :app_name => ENV['NEW_RELIC_APP_NAME']
 end
 Resque.before_fork = Proc.new { ActiveRecord::Base.establish_connection }
 # And assuming you don't have an initializer for Resque elsewhere:
 Resque.redis = ENV['OPENREDIS_URL'] || 'redis://localhost:6379'

end
```

tysonmote picture tysonmote on 25 Jan 2013

FWIW, we are seeing this in our application that is _not_ on Heroku and not using Sidekiq. However, it's also not a simple test case as it's the full app stack. I absolutely verified that this is happening when the resque worker finishes it's job just by watching the queue in development and tailing the postgres log simultaneously. There's a one-to-one correlation. That said, it could be that something else is hanging on to the db connection when resque fork ends which should have been closed.

jeremywadsack picture jeremywadsack on 20 Feb 2013

Hey everyone, not sure if this information will help in debugging this issue, but we are seeing similar errors in our logs and we are NOT using Resque. Or Sidekiq. The only background job we do run is a "Scheduler" that runs every 10 minutes to send out some notification emails. This is done via the Heroku Scheduler gem, which I believe simply uses a CRON job. We do use Redis, and the rake job that sends out the emails does connect to Redis and also makes some DB calls. Here is a few lines from our logs:

5 Mar 2013 18:00:50.523 » 2013-03-05 23:00:50+00:00 app web.7 - - E, [2013-03-05T23:00:50.459011 #2] ERROR -- : worker=2 PID:21 timeout (26s > 25s), killing Context
5 Mar 2013 18:00:50.550 » 2013-03-05 23:00:50+00:00 app postgres - - [12-1] ueko9fq9nikcrk [CRIMSON] LOG: could not receive data from client: Connection reset by peer Context
5 Mar 2013 18:00:50.625 » 2013-03-05 23:00:50+00:00 app web.7 - - E, [2013-03-05T23:00:50.484327 #2] ERROR -- : reaped #<Process::Status: pid 21 SIGKILL (signal 9)> worker=2 Context
5 Mar 2013 18:00:50.656 » 2013-03-05 23:00:50+00:00 app postgres - - [13-1] ueko9fq9nikcrk [CRIMSON] LOG: unexpected EOF on client connection Context
5 Mar 2013 18:00:50.802 » 2013-03-05 23:00:50+00:00 app postgres - - [5-1] ueko9fq9nikcrk [CRIMSON] LOG: could not receive data from client: Connection reset by peer Context

Just wanted to share that incase it helps with resolving this issue. It seems to happen at random times within our app. If we find out any more information, I will update this thread.

i8ramin picture i8ramin on 6 Mar 2013

Ugh. This has been open a long time. Without a reproduction, I can't help. :( If anyone can give me that, please do and let's re-open this, but leaving it sit here isn't helping anyone.

steveklabnik picture steveklabnik on 21 Mar 2013

FWIW, using Resque 2 pre from master fixed it for me. As did using 1.23.1/1-x-stable along with @simple10's gem (multiple hooks is probably the key here).

carhartl picture carhartl on 21 Mar 2013

Interesting. Well, that's good, then!

steveklabnik picture steveklabnik on 21 Mar 2013

What is the status of this? I'm getting these errors on a rails 4 project on Heroku running resque. I added this initializer suggested on the Heroku site:

config/initializers/resque.rb

Resque.before_fork do
  defined?(ActiveRecord::Base) and
    ActiveRecord::Base.connection.disconnect!
end

Resque.after_fork do
  defined?(ActiveRecord::Base) and
    ActiveRecord::Base.establish_connection
end

Specifically I'm seeing this:

2015-09-13T00:25:13Z app[postgres.16251]: [DATABASE] could not receive data from client: Connection reset by peer

Apparently after a resque job completes -- though I don't think I see it after all resque jobs complete. Also, it seems like the jobs are working fine.

Thank you.

kellyfelkins picture kellyfelkins on 13 Sep 2015

@kellyfelkins I also added the suggested code in an initializer. But I just solved this issue by removing some errant calls to ActiveRecord::Base.establish_connection in models that some of our Resque workers were persisting. Those workers were thus mishandling the connection, producing the exception

ActiveRecord::StatementInvalid: PG::ConnectionBad: PQconsumeInput() SSL SYSCALL error: EOF detected

in addition to the could not receive data from client: Connection reset by peer messages, even though the jobs were successful, as in your case.

So it might be obvious, but you may want make sure the database connection isn't being manipulated inappropriately by code your workers are running.

rg picture rg on 14 Oct 2015

I'm seeing the exact behavior @kellyfelkins describes after upgrading my PostgreSQL plan on Heroku. It's possible this was happening before as well, but wasn't getting logged - either way I'd love to know if anyone resolves it.

cyberhobo picture cyberhobo on 19 Dec 2015
👍1

:+1: as @kellyfelkins

nakhli picture nakhli on 22 Jan 2016

I've tried all the variations listed here and some that are not and still have this issue.

Aeramor picture Aeramor on 17 Feb 2016

We were having exactly this same problem... We solved it by adding this hook to the worker task:

def self.after_perform(*args)
    ActiveRecord::Base.connection.disconnect!
end

For the record, here's our resque.rake:

require "resque/tasks"
require "resque/pool/tasks"
require "#{Rails.root}/lib/eventprocessor"

task "resque:setup" => :environment do
  ENV['QUEUE'] ||= '*'
end

task "resque:pool:setup" do
  # close any sockets or files in pool manager
  ActiveRecord::Base.connection.disconnect!
  # and re-open them in the resque worker parent
  Resque::Pool.after_prefork do |job|
    ActiveRecord::Base.establish_connection
    Resque.redis.client.reconnect
  end
end
mkblackwell picture mkblackwell on 16 May 2016
Was this page helpful?
0 / 5 - 0 ratings

Related issues

rulloa picture rulloa  Â·  13Comments
hackervera picture hackervera  Â·  9Comments
itsmechlark picture itsmechlark  Â·  6Comments
ioquatix picture ioquatix  Â·  13Comments
pjammer picture pjammer  Â·  7Comments