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

Resque.enqueue failing on second run #1339

Closed
krzkrzkrz opened this issue May 26, 2011 · 45 comments
Closed

Resque.enqueue failing on second run #1339

krzkrzkrz opened this issue May 26, 2011 · 45 comments

Comments

@krzkrzkrz
Copy link

Its better if I provide the link to the problem description instead. Link contains error message and config files.

I suspect, this may be an issue with activerecord-3.1.0.rc1, since the error (described in stackoverflow link) is bringing it up. Had no problems running this exactly the same way in Rails 3.0.3.

http://stackoverflow.com/questions/6137570/resque-enqueue-failing-on-second-run

In summary:

In console, I do:

Resque.enqueue(EncodeSong, Song.find(20).id, Song.find(20).unencoded_url)

Everything works so far. Resque-web reports no failed jobs. And, I get the two 'puts' from module EncodeSong.

However, running Resque.enqueue(EncodeSong, Song.find(20).id, Song.find(20).unencoded_url) a second time will return the following error in resque-web (described in stackoverflow link). To make the error go away, I would have to close the process thats running: QUEUE=* rake environment resque:work and rerun it in the console window. But the problem comes back after trying to Resque.enqueue() after the first time.

@guilleiguaran
Copy link
Member

Looks like it might be a bug with Resque or Postgres gem than Rails 3.1 bug.
I migrate successfully an app from Rails 3.0.7 to Rails 3.1.0.rc1, I use Resque, Heroku and RedisToGo also. What version of postgres gem and resque are you using?

P.D: Please post the backtrace here, some people wouldn't go to StackOverflow to see the error :P

@krzkrzkrz
Copy link
Author

Bundle install says: Using pg (0.11.0), Using resque (1.16.1). Are you on ruby 1.9.2?

The backtrace as requested:

Class
    EncodeSong
Arguments

    20
    "https://bucket_name.s3.amazonaws.com/unencoded/users/1/songs/test.mp3"

Exception
    PGError
Error
    server closed the connection unexpectedly This probably means the server terminated abnormally before or while processing the request.

    /Users/Chris/.rvm/gems/ruby-1.9.2-p136@railspre/gems/activerecord-3.1.0.rc1/lib/active_record/connection_adapters/postgresql_adapter.rb:272:in `exec'
    /Users/Chris/.rvm/gems/ruby-1.9.2-p136@railspre/gems/activerecord-3.1.0.rc1/lib/active_record/connection_adapters/postgresql_adapter.rb:272:in `block in clear_cache!'
    /Users/Chris/.rvm/gems/ruby-1.9.2-p136@railspre/gems/activerecord-3.1.0.rc1/lib/active_record/connection_adapters/postgresql_adapter.rb:271:in `each_value'
    /Users/Chris/.rvm/gems/ruby-1.9.2-p136@railspre/gems/activerecord-3.1.0.rc1/lib/active_record/connection_adapters/postgresql_adapter.rb:271:in `clear_cache!'
    /Users/Chris/.rvm/gems/ruby-1.9.2-p136@railspre/gems/activerecord-3.1.0.rc1/lib/active_record/connection_adapters/postgresql_adapter.rb:299:in `disconnect!'
    /Users/Chris/.rvm/gems/ruby-1.9.2-p136@railspre/gems/activerecord-3.1.0.rc1/lib/active_record/connection_adapters/abstract/connection_pool.rb:191:in `block in disconnect!'
    /Users/Chris/.rvm/gems/ruby-1.9.2-p136@railspre/gems/activerecord-3.1.0.rc1/lib/active_record/connection_adapters/abstract/connection_pool.rb:190:in `each'
    /Users/Chris/.rvm/gems/ruby-1.9.2-p136@railspre/gems/activerecord-3.1.0.rc1/lib/active_record/connection_adapters/abstract/connection_pool.rb:190:in `disconnect!'
    /Users/Chris/.rvm/gems/ruby-1.9.2-p136@railspre/gems/activesupport-3.1.0.rc1/lib/active_support/core_ext/module/synchronization.rb:35:in `block in disconnect_with_synchronization!'
    /Users/Chris/.rvm/rubies/ruby-1.9.2-p136/lib/ruby/1.9.1/monitor.rb:201:in `mon_synchronize'
    /Users/Chris/.rvm/gems/ruby-1.9.2-p136@railspre/gems/activesupport-3.1.0.rc1/lib/active_support/core_ext/module/synchronization.rb:34:in `disconnect_with_synchronization!'
    /Users/Chris/.rvm/gems/ruby-1.9.2-p136@railspre/gems/activerecord-3.1.0.rc1/lib/active_record/connection_adapters/abstract/connection_pool.rb:407:in `remove_connection'
    /Users/Chris/.rvm/gems/ruby-1.9.2-p136@railspre/gems/activerecord-3.1.0.rc1/lib/active_record/connection_adapters/abstract/connection_specification.rb:116:in `remove_connection'
    /Users/Chris/.rvm/gems/ruby-1.9.2-p136@railspre/gems/activerecord-3.1.0.rc1/lib/active_record/connection_adapters/abstract/connection_specification.rb:79:in `establish_connection'
    /Users/Chris/.rvm/gems/ruby-1.9.2-p136@railspre/gems/activerecord-3.1.0.rc1/lib/active_record/connection_adapters/abstract/connection_specification.rb:60:in `establish_connection'
    /Users/Chris/.rvm/gems/ruby-1.9.2-p136@railspre/gems/activerecord-3.1.0.rc1/lib/active_record/connection_adapters/abstract/connection_specification.rb:55:in `establish_connection'
    /Users/Chris/Sites/site_name/lib/tasks/resque.rake:17:in `block (2 levels) in <top (required)>'
    /Users/Chris/.rvm/gems/ruby-1.9.2-p136@railspre/gems/resque-1.16.1/lib/resque/worker.rb:355:in `call'
    /Users/Chris/.rvm/gems/ruby-1.9.2-p136@railspre/gems/resque-1.16.1/lib/resque/worker.rb:355:in `run_hook'
    /Users/Chris/.rvm/gems/ruby-1.9.2-p136@railspre/gems/resque-1.16.1/lib/resque/worker.rb:162:in `perform'
    /Users/Chris/.rvm/gems/ruby-1.9.2-p136@railspre/gems/resque-1.16.1/lib/resque/worker.rb:130:in `block in work'
    /Users/Chris/.rvm/gems/ruby-1.9.2-p136@railspre/gems/resque-1.16.1/lib/resque/worker.rb:116:in `loop'
    /Users/Chris/.rvm/gems/ruby-1.9.2-p136@railspre/gems/resque-1.16.1/lib/resque/worker.rb:116:in `work'
    /Users/Chris/.rvm/gems/ruby-1.9.2-p136@railspre/gems/resque-1.16.1/lib/resque/tasks.rb:27:in `block (2 levels) in <top (required)>'
    /Users/Chris/.rvm/gems/ruby-1.9.2-p136@railspre/gems/rake-0.9.0/lib/rake/task.rb:205:in `call'
    /Users/Chris/.rvm/gems/ruby-1.9.2-p136@railspre/gems/rake-0.9.0/lib/rake/task.rb:205:in `block in execute'
    /Users/Chris/.rvm/gems/ruby-1.9.2-p136@railspre/gems/rake-0.9.0/lib/rake/task.rb:200:in `each'
    /Users/Chris/.rvm/gems/ruby-1.9.2-p136@railspre/gems/rake-0.9.0/lib/rake/task.rb:200:in `execute'
    /Users/Chris/.rvm/gems/ruby-1.9.2-p136@railspre/gems/rake-0.9.0/lib/rake/task.rb:158:in `block in invoke_with_call_chain'
    /Users/Chris/.rvm/rubies/ruby-1.9.2-p136/lib/ruby/1.9.1/monitor.rb:201:in `mon_synchronize'
    /Users/Chris/.rvm/gems/ruby-1.9.2-p136@railspre/gems/rake-0.9.0/lib/rake/task.rb:151:in `invoke_with_call_chain'
    /Users/Chris/.rvm/gems/ruby-1.9.2-p136@railspre/gems/rake-0.9.0/lib/rake/task.rb:144:in `invoke'
    /Users/Chris/.rvm/gems/ruby-1.9.2-p136@railspre/gems/rake-0.9.0/lib/rake/application.rb:112:in `invoke_task'
    /Users/Chris/.rvm/gems/ruby-1.9.2-p136@railspre/gems/rake-0.9.0/lib/rake/application.rb:90:in `block (2 levels) in top_level'
    /Users/Chris/.rvm/gems/ruby-1.9.2-p136@railspre/gems/rake-0.9.0/lib/rake/application.rb:90:in `each'
    /Users/Chris/.rvm/gems/ruby-1.9.2-p136@railspre/gems/rake-0.9.0/lib/rake/application.rb:90:in `block in top_level'
    /Users/Chris/.rvm/gems/ruby-1.9.2-p136@railspre/gems/rake-0.9.0/lib/rake/application.rb:129:in `standard_exception_handling'
    /Users/Chris/.rvm/gems/ruby-1.9.2-p136@railspre/gems/rake-0.9.0/lib/rake/application.rb:84:in `top_level'
    /Users/Chris/.rvm/gems/ruby-1.9.2-p136@railspre/gems/rake-0.9.0/lib/rake/application.rb:62:in `block in run'
    /Users/Chris/.rvm/gems/ruby-1.9.2-p136@railspre/gems/rake-0.9.0/lib/rake/application.rb:129:in `standard_exception_handling'
    /Users/Chris/.rvm/gems/ruby-1.9.2-p136@railspre/gems/rake-0.9.0/lib/rake/application.rb:59:in `run'
    /Users/Chris/.rvm/gems/ruby-1.9.2-p136@railspre/gems/rake-0.9.0/bin/rake:31:in `<top (required)>'
    /Users/Chris/.rvm/gems/ruby-1.9.2-p136@railspre/bin/rake:19:in `load'
    /Users/Chris/.rvm/gems/ruby-1.9.2-p136@railspre/bin/rake:19:in `<main>'

@krzkrzkrz
Copy link
Author

Guilleiguaran, can you also show me what you have in:

lib/tasks/resque.rake
config/initializers/resque.rb

In your module for one of your jobs, are you using active record to look up a record? For instance. Something like:

module EncodeSong
  @queue = :encode_song

  def self.perform(media_id, s3_file_url)
    media = Song.find(media_id)
  ....

Its interesting to know how you got this to work in Rails 3.1rc.

@guilleiguaran
Copy link
Member

I'm using Ruby 1.9.2 and I'm querying with ActiveRecord in my jobs. I'm using pg 0.11.0 and resque 1.16.1

config/initializers/resque.rb:

require 'resque/job_with_status'
require 'resque/failure/multiple'
require 'resque/failure/hoptoad'
require 'resque/failure/redis'
require 'resque/server'
require 'resque/status_server'

Resque::Server.use Rack::Auth::Basic do |username, password|
  password == "test-password"
end

redis_config = YAML.load_file(File.join(Rails.root, 'config', 'redis.yml'))[Rails.env]
redis_url = ENV["REDISTOGO_URL"] || redis_config['redis_url']

uri = URI.parse(redis_url)
Resque.redis = Redis.new(:host => uri.host, :port => uri.port, :password => uri.password)
Resque::Status.expire_in = (24 * 60 * 60)

lib/tasks/resque.rake:

require 'resque/tasks'

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

desc "Alias for resque:work (To run workers on Heroku)"
task "jobs:work" => "resque:work"

@krzkrzkrz
Copy link
Author

Do your jobs make any queries to any records?

Second, I did a fresh install of Rails 3.1rc on a new RVM gemset running 1.9.2. I don't think this should be a problem. I'm hoping I didn't miss out on any configurations.

@guilleiguaran
Copy link
Member

Yes, I make a lot of queries on all my jobs.

@krzkrzkrz
Copy link
Author

Guilleiguaran, is your app on Heroku running on a dedicated server (pgsql 9) or shared (pgsql 8)?

Are you on OSX?

Still can't seem to pinpoint the problem. If its running fine on your 3.1rc environment, I wonder why it isn't on mine.

@tom-kuca
Copy link

tom-kuca commented Jun 7, 2011

It seems I have just run into the same problem.

Backtrace:

[ pid=18421 thr=70134877964720 file=utils.rb:176 time=2011-06-08 01:21:06.693 ]: *** Exception PGError in application (server closed the connection unexpectedly
        This probably means the server terminated abnormally
        before or while processing the request.
) (process 18421, thread #<Thread:0x7f9318f99360>):
        from /usr/local/rvm/gems/ruby-1.8.7-p334/gems/activerecord-3.1.0.rc1/lib/active_record/connection_adapters/postgresql_adapter.rb:273:in `query'
        from /usr/local/rvm/gems/ruby-1.8.7-p334/gems/activerecord-3.1.0.rc1/lib/active_record/connection_adapters/postgresql_adapter.rb:273:in `clear_cache!'
        from /usr/local/rvm/gems/ruby-1.8.7-p334/gems/activerecord-3.1.0.rc1/lib/active_record/connection_adapters/postgresql_adapter.rb:272:in `each_value'
        from /usr/local/rvm/gems/ruby-1.8.7-p334/gems/activerecord-3.1.0.rc1/lib/active_record/connection_adapters/postgresql_adapter.rb:272:in `clear_cache!'
        from /usr/local/rvm/gems/ruby-1.8.7-p334/gems/activerecord-3.1.0.rc1/lib/active_record/connection_adapters/postgresql_adapter.rb:300:in `disconnect!'
        from /usr/local/rvm/gems/ruby-1.8.7-p334/gems/activerecord-3.1.0.rc1/lib/active_record/connection_adapters/abstract/connection_pool.rb:191:in `disconnect_without_synchronization!'
        from /usr/local/rvm/gems/ruby-1.8.7-p334/gems/activerecord-3.1.0.rc1/lib/active_record/connection_adapters/abstract/connection_pool.rb:190:in `each'
        from /usr/local/rvm/gems/ruby-1.8.7-p334/gems/activerecord-3.1.0.rc1/lib/active_record/connection_adapters/abstract/connection_pool.rb:190:in `disconnect_without_synchronization!'
        from /usr/local/rvm/gems/ruby-1.8.7-p334/gems/activesupport-3.1.0.rc1/lib/active_support/core_ext/module/synchronization.rb:35:in `disconnect!'
        from /usr/local/rvm/rubies/ruby-1.8.7-p334/lib/ruby/1.8/monitor.rb:242:in `synchronize'
        from /usr/local/rvm/gems/ruby-1.8.7-p334/gems/activesupport-3.1.0.rc1/lib/active_support/core_ext/module/synchronization.rb:34:in `disconnect!'
        from /usr/local/rvm/gems/ruby-1.8.7-p334/gems/activerecord-3.1.0.rc1/lib/active_record/connection_adapters/abstract/connection_pool.rb:374:in `clear_all_connections!'
        from /usr/local/rvm/gems/ruby-1.8.7-p334/gems/activerecord-3.1.0.rc1/lib/active_record/connection_adapters/abstract/connection_pool.rb:374:in `each_value'
        from /usr/local/rvm/gems/ruby-1.8.7-p334/gems/activerecord-3.1.0.rc1/lib/active_record/connection_adapters/abstract/connection_pool.rb:374:in `clear_all_connections!'
        from /usr/local/rvm/gems/ruby-1.8.7-p334/gems/activerecord-3.1.0.rc1/lib/active_record/connection_adapters/abstract/connection_specification.rb:123:in `__send__'
        from /usr/local/rvm/gems/ruby-1.8.7-p334/gems/activerecord-3.1.0.rc1/lib/active_record/connection_adapters/abstract/connection_specification.rb:123:in `clear_all_connections!'
        from /usr/local/rvm/gems/ruby-1.8.7-p334/gems/passenger-3.0.7/lib/phusion_passenger/utils.rb:398:in `before_handling_requests'
        from /usr/local/rvm/gems/ruby-1.8.7-p334/gems/passenger-3.0.7/lib/phusion_passenger/rack/application_spawner.rb:204:in `start_request_handler'
        from /usr/local/rvm/gems/ruby-1.8.7-p334/gems/passenger-3.0.7/lib/phusion_passenger/rack/application_spawner.rb:170:in `send'
        from /usr/local/rvm/gems/ruby-1.8.7-p334/gems/passenger-3.0.7/lib/phusion_passenger/rack/application_spawner.rb:170:in `handle_spawn_application'
        from /usr/local/rvm/gems/ruby-1.8.7-p334/gems/passenger-3.0.7/lib/phusion_passenger/utils.rb:479:in `safe_fork'
        from /usr/local/rvm/gems/ruby-1.8.7-p334/gems/passenger-3.0.7/lib/phusion_passenger/rack/application_spawner.rb:165:in `handle_spawn_application'
        from /usr/local/rvm/gems/ruby-1.8.7-p334/gems/passenger-3.0.7/lib/phusion_passenger/abstract_server.rb:357:in `__send__'
        from /usr/local/rvm/gems/ruby-1.8.7-p334/gems/passenger-3.0.7/lib/phusion_passenger/abstract_server.rb:357:in `server_main_loop'
        from /usr/local/rvm/gems/ruby-1.8.7-p334/gems/passenger-3.0.7/lib/phusion_passenger/abstract_server.rb:206:in `start_synchronously'
        from /usr/local/rvm/gems/ruby-1.8.7-p334/gems/passenger-3.0.7/lib/phusion_passenger/abstract_server.rb:180:in `start'
        from /usr/local/rvm/gems/ruby-1.8.7-p334/gems/passenger-3.0.7/lib/phusion_passenger/rack/application_spawner.rb:128:in `start'
        from /usr/local/rvm/gems/ruby-1.8.7-p334/gems/passenger-3.0.7/lib/phusion_passenger/spawn_manager.rb:253:in `spawn_rack_application'
        from /usr/local/rvm/gems/ruby-1.8.7-p334/gems/passenger-3.0.7/lib/phusion_passenger/abstract_server_collection.rb:132:in `lookup_or_add'
        from /usr/local/rvm/gems/ruby-1.8.7-p334/gems/passenger-3.0.7/lib/phusion_passenger/spawn_manager.rb:246:in `spawn_rack_application'
        from /usr/local/rvm/gems/ruby-1.8.7-p334/gems/passenger-3.0.7/lib/phusion_passenger/abstract_server_collection.rb:82:in `synchronize'
        from /usr/local/rvm/gems/ruby-1.8.7-p334/gems/passenger-3.0.7/lib/phusion_passenger/abstract_server_collection.rb:79:in `synchronize'
        from /usr/local/rvm/gems/ruby-1.8.7-p334/gems/passenger-3.0.7/lib/phusion_passenger/spawn_manager.rb:244:in `spawn_rack_application'
        from /usr/local/rvm/gems/ruby-1.8.7-p334/gems/passenger-3.0.7/lib/phusion_passenger/spawn_manager.rb:137:in `spawn_application'
        from /usr/local/rvm/gems/ruby-1.8.7-p334/gems/passenger-3.0.7/lib/phusion_passenger/spawn_manager.rb:275:in `handle_spawn_application'
        from /usr/local/rvm/gems/ruby-1.8.7-p334/gems/passenger-3.0.7/lib/phusion_passenger/abstract_server.rb:357:in `__send__'
        from /usr/local/rvm/gems/ruby-1.8.7-p334/gems/passenger-3.0.7/lib/phusion_passenger/abstract_server.rb:357:in `server_main_loop'
        from /usr/local/rvm/gems/ruby-1.8.7-p334/gems/passenger-3.0.7/lib/phusion_passenger/abstract_server.rb:206:in `start_synchronously'
        from /usr/local/rvm/gems/ruby-1.8.7-p334//gems/passenger-3.0.7//helper-scripts/passenger-spawn-server:99

This error starts to appear in my Rails application after upgrade from 2.3.11 to 3.1rc (I didn't try any 3.0.* version). The backtrace is from apache log file, there is no record in rails log file. About 1 of 20 requests results in Internal server error and the
apache log shows this message. The page where application fails seems to be random.

  • I do NOT use resque
  • the application uses PostgreSQL 7.4 database and pg (0.9.0) gem, passenger 3.0.7
  • same error both for ruby 1.8.7 and 1.9.2
  • it only occurs where there are concurrent requests, i.e. ab -n 100 -c 2 http://localhost/login fails while ab -n 100 -c 1 http://localhost/login passes.
  • more concurrency, more fails
  • no error if I comment out the line @connection.query "DEALLOCATE #{value}" at activerecord-3.1.0.rc1/lib/active_record/connection_adapters/postgresql_adapter.rb:273

@guilleiguaran
Copy link
Member

@krzkrzkrz I use OSX locally and shared database in Heroku

@tom-kuca
Copy link

Maybe I found the reason why thinks go wrong. Passenger spawner creates the first thread which works fine. As soon as some any threads is needed, it forks the first thread, try to reestabilish database connections since it's not allowed to use a database connection after fork (see http://www.postgresql.org/docs/9.0/static/libpq-connect.html). The problem part is clearing database connections - all prepared statements are deallocated by sending query to the database. Since the connection isn't valid because of forking it results in undefined behavior.

In previous versions of Rails it works because there weren't any prepared statements and clearing database connection doesn't perform any query. I'm not sure who is responsible for this issue. It seems active record doesn't allow to clear invalid database connection, but both passenger and resque do it.

@drogus
Copy link
Member

drogus commented Jun 28, 2011

The temporary fix is to use PassengerSpawnMethod conservative in passenger, which disables forking running processes.

@krzkrzkrz
Copy link
Author

As pointed out by carhartl: https://github.com/defunkt/resque/issues/306#issuecomment-1421034

Using before_fork instead of after_fork seems to work. Don't have Resque installed on our environment anymore, so I can't verify this solution. But might as well point this out as it may help anyone else who comes across the same issue.


While after_fork for me always caused the "closed connection" error, using before_fork fixed both that one as well as the "prepared statement already exists" error.

Resque.before_fork = Proc.new { ActiveRecord::Base.establish_connection }

Not yet sure about the implications of it.

ruby 1.9.2p136 (2010-12-25 revision 30365) [x86_64-darwin10.6.0]
Rails 3.1.0.rc4
resque 1.17.1

@iwarshak
Copy link
Contributor

iwarshak commented Jul 8, 2011

Having this same issue with:

ruby 1.8.7
Rails 3.0.8
Resque 1.10.0
Postgresql 8.4

I get the error: ActiveRecord::StatementInvalid: PGError: server closed the connection unexpectedly

Adding the before_fork lambda seemingly fixed this.

@gravis
Copy link

gravis commented Aug 3, 2011

Same problem here.

ruby 1.8.7
Rails 3.0.9
Postgresql 9.0

We fixed it in Resque by using the before_fork block, but it occurs as well in rails + passenger.

@sreid99
Copy link

sreid99 commented Aug 11, 2011

Same problem.

Was ok until I upgraded from Rails 3.0.x to rails 3.1.0rc5.

Before_fork didn't fix it. Only temporary fix so far is PassengerSpawnMethod conservative as mentioned above.

@mhuggins
Copy link

I'm experiencing this issue as well, Ruby 1.9.0 (p290), Rails 3.2.0-beta, Passenger 3.0.8.

$ uname -a
Linux li375-134 2.6.39.1-linode34 #1 SMP Tue Jun 21 10:29:24 EDT 2011 i686 GNU/Linux
$ gem list | grep passenger
passenger (3.0.8)
$ ruby --version
ruby 1.9.2p290 (2011-07-09 revision 32553) [i686-linux]
$ apache2 -v
Server version: Apache/2.2.19 (Debian)
Server built:   May 22 2011 08:32:52
$ free
             total       used       free     shared    buffers     cached
Mem:       1028684     919724     108960          0      25580     615576
-/+ buffers/cache:     278568     750116
Swap:       262140      61668     200472

@drogus - Thanks for the workaround using PassengerSpawnMethod conservative, hopefully this doesn't bring my server to a crawl. :/

@rsanheim
Copy link
Contributor

Is it possible to rename this issue to better describe the actual nature and impact of it? Prepared statements in ActiveRecord 3.1 + Postgres + Passenger basically blow up big time, and require the conservative spawn method which is undesirable.

@lxcid
Copy link

lxcid commented Sep 4, 2011

i am facing similar problem.

although setting passenger_spawn_method conservative; works.

It seems to end up premature closing my rails thread, it seems.

upstream prematurely closed connection while reading response header from upstream

might be a separate issue.

@krzkrzkrz
Copy link
Author

@rsanheim, I don't think that would be a suitable title for the issue. When I was experiencing this problem, I was not using Passenger. Although a lot of devs are coming across this issue with Passenger (so it seems), its not solely Passenger related.

@lxcid
Copy link

lxcid commented Sep 7, 2011

Just to inform you guys that I move my DB to MySQL and the problem is solved.

@krzkrzkrz
Copy link
Author

I can vouch for this too. I moved databases from PgSQL to MySql, and the problem seems to have gone away.

@MasterLambaster
Copy link
Contributor

Problem is that on connection reset PgSQL AR adapter is trying to deallocate all prepared statements. But for smart forks in passenger it makes no sense, because these statements are not valid for forked process.
Solution can be tricky because connection rest is triggered from passenger. And the AR reset connection clears statements cache. The problem is that the passenger calls reset connection before it's hooks got triggered.

I use following monkey patch to make smart spawn methods work with PostgreSQL.
WARNING: This is for 3.1 only, the later version may have this bug fixed and now in trunk statements caching mechanism differs form that this patch relay on

# Monkey pactch to prevent postgres prepared statements deallocation on fork
# Original file https://github.com/FooBarWidget/passenger/blob/master/lib/phusion_passenger/utils.rb
if defined?(PhusionPassenger)
module PhusionPassenger
  module Utils
    protected

    def before_handling_requests_with_pg(forked, options)
      if forked && defined?(::ActiveRecord::Base)
        begin
          if ::ActiveRecord::Base.respond_to?(:connection)
            if ::ActiveRecord::ConnectionAdapters::PostgreSQLAdapter::ADAPTER_NAME == ::ActiveRecord::Base.connection.adapter_name
              # Reset all prepared statements, they will be handled properly in donor thread
              ::ActiveRecord::Base.connection.instance_variable_set(:@statements, {})
            end
          end
        rescue Exception => e
          print_exception(self.class.to_s, e)
        end
      end
      before_handling_requests_without_pg(forked, options)
    end
    alias_method_chain :before_handling_requests, :pg
  end
end
end

@jiannis
Copy link

jiannis commented Sep 7, 2011

Mr. MasterLambaster, you are a star! Just in time, mate! Until a solution makes it into the postgres adapter, will give your monkey patch a shot.

@MasterLambaster
Copy link
Contributor

@jiannis Problem with the patch is that it's need to be made both in passenger and AR PostgreSQL adapter.

@yfeldblum
Copy link

Idea Boat: Rack+Rails Expose Fork Aspects

Perhaps Rails could expose before_fork, after_fork, and around_fork hooks?

Rails.configuration.configure do
  config.before_fork { close_all_connections }
  config.after_fork { open_all_connections }
  # or
  config.around_fork do |fork|
    close_all_connections
    fork.call
    open_all_connections
  end
end

Rack could potentially expose these hooks too (so rack-compatible servers could find them), and a Rails config.ru could forward the Rack hooks to the Rails hooks.

Passenger and Unicorn could then call the appropriate Rack hooks before, after, and around forking.

Note that in this example Rails would not actually implement the forking. Passenger and Unicorn would merely be able to discover and call the hooks when Passenger and Unicorn implement the forking.

Then you wouldn't need complicated cross-library patches. The ActiveRecord PosgreSql Adapter would, in the ActiveRecord railtie's initializiation, set up the hooks. Done.

This idea doesn't help the current state of affairs, where these hooks don't exist and where cross-library patches remain necessary. But this may help the future state of affairs.

@mhuggins
Copy link

mhuggins commented Sep 7, 2011

For those suggesting moving from MySQL to PostgreSQL, you are correct that the problem is only when using PostgreSQL. However, "just switching databases" is definitely not an acceptable solution by any means.

@jbarnette
Copy link
Contributor

I've threatened @tenderlove with bodily harm unless this is fixed in 3.1.1. He claims he's going to partition by PID in the cache, but he's historically untrustworthy.

@gravis
Copy link

gravis commented Sep 9, 2011

@MasterLambaster : Is this patch is only for rails 3.1.X ?
ActiveRecord doesn't seem to have a "statements" var:

::ActiveRecord::Base.connection.instance_variable_get(:@statements)                           
=> nil                  

thanks

@MasterLambaster
Copy link
Contributor

Yes, that's for 3.1.x, later versions have separate class for statements cache - StatementPool
But same variable is set after initialization. Are you sure your ::ActiveRecord::Base.connection.adapter_name == "PostgreSQL". And 3.x AFAIK have no prepared statements cache at all

@gravis
Copy link

gravis commented Sep 9, 2011

I have 3.0.10, I thought it could be a solution for us :)
We're having this issue and it's driving me crazy

@MasterLambaster
Copy link
Contributor

3.0 doesn't use a statement cache. It tends that you have other problem that this particular one

@krzkrzkrz
Copy link
Author

Just wondering why this issue has been closed. Has it been deemed resolved? I saw @tenderlove made a recent commit. Does this highlight / fix the issue at hand?

@gravis
Copy link

gravis commented Sep 9, 2011

for rails 3.1, it should be fixed. For rails 3.0, the truth is out there...

@MasterLambaster
Copy link
Contributor

@krzkrzkrz Yes, @tenderlove commit is fix for this issue. Prepared statements are stored with the process_id, so after fork the statements cache will be empty because proc id will change.
@gravis it cant be truth because there is NO statements cache in it. Post your error and rails version, may be we can find out what's the problem.

@krzkrzkrz
Copy link
Author

Awesome. Great job Rails team! Thumbs up!

@jiannis
Copy link

jiannis commented Sep 9, 2011

@MasterLambaster thanks again mate for the monkey patch, @tenderlove thanks for the ingenious fix! Love you both!

@lankz
Copy link

lankz commented Sep 19, 2011

Had no luck with the above fix for unicorn. Reducing the number of workers to 1 seems to make the problem go away.

@astjohn
Copy link

astjohn commented Sep 27, 2011

I also had no luck with unicorn until I used the before_fork approach mentioned by @krzkrzkrz. That seemed to do it.

@ghost
Copy link

ghost commented Dec 22, 2011

Everything was fine on Monday. Now I'm getting the problem.

Rails 3.1.3, Unicorn 4.1.1, PG 0.12.0, Postgresql 9.1

Happened when I did a bundle update on Tuesday to upgrade to Rails 3.1.3. I seen that Unicorn upgraded also. I downgraded everything but I still have the issue.

Just wanted to add my 2c here.

PS, switched to WEBrick for local development on my Mac to fix the problem. Only change was to remove Unicorn from my Gemfile.

PPS, works fine on my Debian server. Only broken on my Mac.

PPPS, Instead of using "rails s" to start my app, I used "unicorn" and it works fine. No more PG errors.

@brandonweiss
Copy link
Contributor

I'm having this problem as well.

Rails 3.1.3
pg 0.11.0
Postgresql 9.1.1

@bkimble
Copy link

bkimble commented Jan 6, 2012

I'm having a similar issue, sans Resque/PG, with:

Rails 3.1.3
Mongo 1.5.2
MongoMapper 0.10.1
Passenger 3.0.2
Nginx 0.8.54
Ubuntu 10.04 x86_64

After a few seconds of light load, the Rack processes that Passenger spawns begin to eat up large amounts of CPU/Memory and eventually the box becomes unusable. An strace on one of the errant processes looks like this, over and over again:

select(22, [], [20], [], {42, 971988}) = 1 (out [20], left {42, 971985})
sendto(20, "1\2\0\0#\t\0\0\0\0\0\0\324\7\0\0\4\0\0\0weeklyad_sta"..., 561, 0, NULL, 0) = 561
gettimeofday({1325811631, 89591}, NULL) = 0
clock_gettime(CLOCK_MONOTONIC, {173, 684154080}) = 0
clock_gettime(CLOCK_MONOTONIC, {173, 684226412}) = 0
select(0, [], [], [], {0, 0}) = 0 (Timeout)
clock_gettime(CLOCK_MONOTONIC, {173, 684494242}) = 0
select(21, [20], [], [], {29, 999659}) = 1 (in [20], left {29, 993908})
clock_gettime(CLOCK_MONOTONIC, {173, 690521306}) = 0
select(21, [20], [], [], {29, 993632}) = 1 (in [20], left {29, 993630})
read(20, "\244"\0\0\211\342\21\0#\t\0\0\1\0\0\0\10\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096) = 4096
clock_gettime(CLOCK_MONOTONIC, {173, 690851532}) = 0
select(0, [], [], [], {0, 0}) = 0 (Timeout)
clock_gettime(CLOCK_MONOTONIC, {173, 691390212}) = 0
select(0, [], [], [], {0, 0}) = 0 (Timeout)
gettimeofday({1325811631, 97286}, NULL) = 0
clock_gettime(CLOCK_MONOTONIC, {173, 691849901}) = 0
clock_gettime(CLOCK_MONOTONIC, {173, 691985528}) = 0
select(0, [], [], [], {0, 0}) = 0 (Timeout)
clock_gettime(CLOCK_MONOTONIC, {173, 692489629}) = 0
select(0, [], [], [], {0, 0}) = 0 (Timeout)
clock_gettime(CLOCK_MONOTONIC, {173, 692913229}) = 0
select(0, [], [], [], {0, 0}) = 0 (Timeout)
gettimeofday({1325811631, 98793}, NULL) = 0
clock_gettime(CLOCK_MONOTONIC, {173, 693355616}) = 0
clock_gettime(CLOCK_MONOTONIC, {173, 693427246}) = 0
select(0, [], [], [], {0, 0}) = 0 (Timeout)
clock_gettime(CLOCK_MONOTONIC, {173, 693694905}) = 0
select(0, [], [], [], {0, 0}) = 0 (Timeout)
clock_gettime(CLOCK_MONOTONIC, {173, 693924126}) = 0
select(0, [], [], [], {0, 0}) = 0 (Timeout)
gettimeofday({1325811631, 99715}, NULL) = 0

The issue is resolved by setting: passenger_spawn_method conservative;

@robdimarco
Copy link

We are seeing a similar issue with:

  • rails (3.1.3)
  • pg (0.11.0)
  • passenger (3.0.11)

We are connecting to postgresql using SSL This seems to happen sporadically, I suspect it is after a Passenger forking or , but I have not been able to come up with steps to reliably reproduce the issue..

Relevant stack trace on the error is

ActiveRecord::StatementInvalid: PGError: no connection to the server : SELECT "categories".* FROM "categories" LIMIT 1

[GEM_ROOT]/gems/activerecord-3.1.3/lib/active_record/connection_adapters/postgresql_adapter.rb:1021:in `async_exec'
[GEM_ROOT]/gems/activerecord-3.1.3/lib/active_record/connection_adapters/postgresql_adapter.rb:1021:in `exec_no_cache'
[GEM_ROOT]/gems/activerecord-3.1.3/lib/active_record/connection_adapters/postgresql_adapter.rb:602:in `block in exec_query'
[GEM_ROOT]/gems/activerecord-3.1.3/lib/active_record/connection_adapters/abstract_adapter.rb:244:in `block in log'
[GEM_ROOT]/gems/activesupport-3.1.3/lib/active_support/notifications/instrumenter.rb:21:in `instrument'
[GEM_ROOT]/gems/activerecord-3.1.3/lib/active_record/connection_adapters/abstract_adapter.rb:239:in `log'
[GEM_ROOT]/gems/activerecord-3.1.3/lib/active_record/connection_adapters/postgresql_adapter.rb:601:in `exec_query'
[GEM_ROOT]/gems/activerecord-3.1.3/lib/active_record/connection_adapters/postgresql_adapter.rb:1116:in `select'
[GEM_ROOT]/gems/activerecord-3.1.3/lib/active_record/connection_adapters/abstract/database_statements.rb:18:in `select_all'
[GEM_ROOT]/gems/activerecord-3.1.3/lib/active_record/connection_adapters/abstract/query_cache.rb:61:in `block in select_all'
[GEM_ROOT]/gems/activerecord-3.1.3/lib/active_record/connection_adapters/abstract/query_cache.rb:75:in `cache_sql'
[GEM_ROOT]/gems/activerecord-3.1.3/lib/active_record/connection_adapters/abstract/query_cache.rb:61:in `select_all'
[GEM_ROOT]/gems/activerecord-3.1.3/lib/active_record/base.rb:470:in `find_by_sql'
[GEM_ROOT]/gems/activerecord-3.1.3/lib/active_record/relation.rb:111:in `to_a'
[GEM_ROOT]/gems/activerecord-3.1.3/lib/active_record/relation/finder_methods.rb:376:in `find_first'
[GEM_ROOT]/gems/activerecord-3.1.3/lib/active_record/relation/finder_methods.rb:122:in `first'

@MasterLambaster
Copy link
Contributor

@robdimarco it's other issue. The connection had to be reset on fork, but the passenger reset connection on fork. So the problem may be in network connectivity or at some point pg server goes away.
Try to set reconnect: true in your database.yml file.
It might be PgSQL adapter issue, but most likely it's not.

@robdimarco
Copy link

@MasterLambaster thanks for the recommendation, will try.

@ghost
Copy link

ghost commented Mar 7, 2012

Quick note to others having the issues:

1: The Devise gem causes problems when running Rails with unicorn-rails (rails server). Clearance works fine.
2: The apn_sender (Apple Notification Sender) gem causes Resque to have the problem.

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

No branches or pull requests