This project is archived and is in readonly mode.
ActiveRecord::StatementInvalid: Mysql::Error: MySQL server has gone away
Reported by Alex Le | July 29th, 2010 @ 07:06 PM | in 3.0.2
I deployed a Rails 3 RC app last night to my Linode server, running CentOS, Nginx and Passenger, RVM with 1.8.7. Then this morning I connected to it again to and got error with "MySQL has gone away":
I'm not sure if this is a Rails 3 RC issue or not, but when the
app was running on Rails 3b4, I never run into this issue. Here's
the stacktrace.
[GEM_ROOT]/gems/activerecord-3.0.0.rc/lib/active_record/connection_adapters/abstract_adapter.rb:202:in
log_without_newrelic_instrumentation'
vendor/plugins/newrelic_rpm/lib/new_relic/agent/instrumentation/active_record_instrumentation.rb:65:in
log'
vendor/plugins/newrelic_rpm/lib/new_relic/agent/method_tracer.rb:141:in
trace_execution_scoped'
vendor/plugins/newrelic_rpm/lib/new_relic/agent/instrumentation/active_record_instrumentation.rb:62:in
log'
[GEM_ROOT]/gems/activerecord-3.0.0.rc/lib/active_record/connection_adapters/mysql_adapter.rb:286:in
execute'
[GEM_ROOT]/gems/activerecord-3.0.0.rc/lib/active_record/connection_adapters/mysql_adapter.rb:616:in
select'
[GEM_ROOT]/gems/activerecord-3.0.0.rc/lib/active_record/connection_adapters/abstract/database_statements.rb:7:in
select_all'
[GEM_ROOT]/gems/activerecord-3.0.0.rc/lib/active_record/connection_adapters/abstract/query_cache.rb:54:in
select_all'
[GEM_ROOT]/gems/activerecord-3.0.0.rc/lib/active_record/connection_adapters/abstract/query_cache.rb:76:in
cache_sql'
[GEM_ROOT]/gems/activerecord-3.0.0.rc/lib/active_record/connection_adapters/abstract/query_cache.rb:54:in
select_all'
[GEM_ROOT]/gems/activerecord-3.0.0.rc/lib/active_record/base.rb:427:in
find_by_sql_without_trace_ActiveRecord_self_name_find_by_sql'
vendor/plugins/newrelic_rpm/lib/new_relic/agent/method_tracer.rb:319:in
find_by_sql'
vendor/plugins/newrelic_rpm/lib/new_relic/agent/method_tracer.rb:141:in
trace_execution_scoped'
vendor/plugins/newrelic_rpm/lib/new_relic/agent/method_tracer.rb:314:in
find_by_sql'
[GEM_ROOT]/gems/activerecord-3.0.0.rc/lib/active_record/relation.rb:64:in
to_a'
[GEM_ROOT]/gems/activerecord-3.0.0.rc/lib/active_record/relation/finder_methods.rb:324:in
find_first'
[GEM_ROOT]/gems/activerecord-3.0.0.rc/lib/active_record/relation/finder_methods.rb:117:in
first'
[GEM_ROOT]/gems/activerecord-3.0.0.rc/lib/active_record/relation/finder_methods.rb:227:in
send'
[GEM_ROOT]/gems/activerecord-3.0.0.rc/lib/active_record/relation/finder_methods.rb:227:in
find_by_attributes'
[GEM_ROOT]/gems/activerecord-3.0.0.rc/lib/active_record/base.rb:942:in
send'
[GEM_ROOT]/gems/activerecord-3.0.0.rc/lib/active_record/base.rb:942:in
method_missing'
app/controllers/app/users_controller.rb:52:in
check_for_valid_coupon'
app/controllers/app/users_controller.rb:23:in
create'
[GEM_ROOT]/gems/actionpack-3.0.0.rc/lib/action_controller/metal/implicit_render.rb:4:in
send_action'
[GEM_ROOT]/gems/actionpack-3.0.0.rc/lib/action_controller/metal/implicit_render.rb:4:in
send_action'
[GEM_ROOT]/gems/actionpack-3.0.0.rc/lib/abstract_controller/base.rb:136:in
process_action'
[GEM_ROOT]/gems/actionpack-3.0.0.rc/lib/action_controller/metal/rendering.rb:11:in
process_action'
[GEM_ROOT]/gems/actionpack-3.0.0.rc/lib/abstract_controller/callbacks.rb:18:in
process_action'
[GEM_ROOT]/gems/activesupport-3.0.0.rc/lib/active_support/callbacks.rb:434:in
_run__514234185__process_action__1623385099__callbacks'
[GEM_ROOT]/gems/activesupport-3.0.0.rc/lib/active_support/callbacks.rb:404:in
send'
[GEM_ROOT]/gems/activesupport-3.0.0.rc/lib/active_support/callbacks.rb:404:in
_run_process_action_callbacks'
[GEM_ROOT]/gems/activesupport-3.0.0.rc/lib/active_support/callbacks.rb:93:in
send'
[GEM_ROOT]/gems/activesupport-3.0.0.rc/lib/active_support/callbacks.rb:93:in
run_callbacks'
[GEM_ROOT]/gems/actionpack-3.0.0.rc/lib/abstract_controller/callbacks.rb:17:in
process_action'
[GEM_ROOT]/gems/actionpack-3.0.0.rc/lib/action_controller/metal/instrumentation.rb:30:in
process_action'
[GEM_ROOT]/gems/activesupport-3.0.0.rc/lib/active_support/notifications.rb:52:in
instrument'
[GEM_ROOT]/gems/activesupport-3.0.0.rc/lib/active_support/notifications/instrumenter.rb:21:in
instrument'
[GEM_ROOT]/gems/activesupport-3.0.0.rc/lib/active_support/notifications.rb:52:in
instrument'
[GEM_ROOT]/gems/actionpack-3.0.0.rc/lib/action_controller/metal/instrumentation.rb:29:in
process_action'
[GEM_ROOT]/gems/actionpack-3.0.0.rc/lib/action_controller/metal/rescue.rb:17:in
process_action'
vendor/plugins/newrelic_rpm/lib/new_relic/agent/instrumentation/rails3/action_controller.rb:28:in
process_action'
vendor/plugins/newrelic_rpm/lib/new_relic/agent/instrumentation/controller_instrumentation.rb:251:in
perform_action_with_newrelic_trace'
vendor/plugins/newrelic_rpm/lib/new_relic/agent/method_tracer.rb:141:in
trace_execution_scoped'
vendor/plugins/newrelic_rpm/lib/new_relic/agent/instrumentation/controller_instrumentation.rb:246:in
perform_action_with_newrelic_trace'
vendor/plugins/newrelic_rpm/lib/new_relic/agent/instrumentation/rails3/action_controller.rb:27:in
process_action'
[GEM_ROOT]/gems/actionpack-3.0.0.rc/lib/abstract_controller/base.rb:105:in
process'
[GEM_ROOT]/gems/actionpack-3.0.0.rc/lib/abstract_controller/rendering.rb:40:in
process'
[GEM_ROOT]/gems/actionpack-3.0.0.rc/lib/action_controller/metal.rb:133:in
dispatch'
[GEM_ROOT]/gems/actionpack-3.0.0.rc/lib/action_controller/metal/rack_delegation.rb:14:in
dispatch'
[GEM_ROOT]/gems/actionpack-3.0.0.rc/lib/action_controller/metal.rb:173:in
action'
[GEM_ROOT]/gems/actionpack-3.0.0.rc/lib/action_dispatch/routing/route_set.rb:62:in
call'
[GEM_ROOT]/gems/actionpack-3.0.0.rc/lib/action_dispatch/routing/route_set.rb:62:in
dispatch'
[GEM_ROOT]/gems/actionpack-3.0.0.rc/lib/action_dispatch/routing/route_set.rb:27:in
call'
[GEM_ROOT]/gems/rack-mount-0.6.9/lib/rack/mount/route_set.rb:148:in
call'
[GEM_ROOT]/gems/rack-mount-0.6.9/lib/rack/mount/code_generation.rb:89:in
recognize'
[GEM_ROOT]/gems/rack-mount-0.6.9/lib/rack/mount/code_generation.rb:73:in
optimized_each'
[GEM_ROOT]/gems/rack-mount-0.6.9/lib/rack/mount/code_generation.rb:88:in
recognize'
[GEM_ROOT]/gems/rack-mount-0.6.9/lib/rack/mount/route_set.rb:139:in
call'
[GEM_ROOT]/gems/actionpack-3.0.0.rc/lib/action_dispatch/routing/route_set.rb:489:in
call'
[GEM_ROOT]/gems/warden-0.10.7/lib/warden/manager.rb:35:in
call'
[GEM_ROOT]/gems/warden-0.10.7/lib/warden/manager.rb:34:in
catch'
[GEM_ROOT]/gems/warden-0.10.7/lib/warden/manager.rb:34:in
call'
[GEM_ROOT]/gems/actionpack-3.0.0.rc/lib/action_dispatch/middleware/head.rb:14:in
call'
[GEM_ROOT]/gems/rack-1.2.1/lib/rack/methodoverride.rb:24:in
call'
[GEM_ROOT]/gems/actionpack-3.0.0.rc/lib/action_dispatch/middleware/params_parser.rb:21:in
call'
[GEM_ROOT]/gems/actionpack-3.0.0.rc/lib/action_dispatch/middleware/flash.rb:177:in
call'
[GEM_ROOT]/gems/actionpack-3.0.0.rc/lib/action_dispatch/middleware/session/abstract_store.rb:149:in
call'
[GEM_ROOT]/gems/actionpack-3.0.0.rc/lib/action_dispatch/middleware/cookies.rb:268:in
call'
[GEM_ROOT]/gems/activerecord-3.0.0.rc/lib/active_record/query_cache.rb:32:in
call'
[GEM_ROOT]/gems/activerecord-3.0.0.rc/lib/active_record/connection_adapters/abstract/query_cache.rb:28:in
cache'
[GEM_ROOT]/gems/activerecord-3.0.0.rc/lib/active_record/query_cache.rb:12:in
cache'
[GEM_ROOT]/gems/activerecord-3.0.0.rc/lib/active_record/query_cache.rb:31:in
call'
[GEM_ROOT]/gems/actionpack-3.0.0.rc/lib/action_dispatch/middleware/callbacks.rb:46:in
call'
[GEM_ROOT]/gems/activesupport-3.0.0.rc/lib/active_support/callbacks.rb:410:in
_run_call_callbacks'
[GEM_ROOT]/gems/actionpack-3.0.0.rc/lib/action_dispatch/middleware/callbacks.rb:44:in
call'
[GEM_ROOT]/gems/rack-1.2.1/lib/rack/sendfile.rb:107:in
call'
[GEM_ROOT]/gems/actionpack-3.0.0.rc/lib/action_dispatch/middleware/remote_ip.rb:48:in
call'
[GEM_ROOT]/gems/actionpack-3.0.0.rc/lib/action_dispatch/middleware/show_exceptions.rb:48:in
call'
[GEM_ROOT]/gems/railties-3.0.0.rc/lib/rails/rack/logger.rb:13:in
call'
[GEM_ROOT]/gems/rack-1.2.1/lib/rack/runtime.rb:17:in
call'
[GEM_ROOT]/gems/rack-1.2.1/lib/rack/lock.rb:11:in
call'
[GEM_ROOT]/gems/rack-1.2.1/lib/rack/lock.rb:11:in
synchronize'
[GEM_ROOT]/gems/rack-1.2.1/lib/rack/lock.rb:11:in
call'
[GEM_ROOT]/gems/railties-3.0.0.rc/lib/rails/application.rb:168:in
call'
[GEM_ROOT]/gems/railties-3.0.0.rc/lib/rails/application.rb:77:in
send'
[GEM_ROOT]/gems/railties-3.0.0.rc/lib/rails/application.rb:77:in
method_missing'
[GEM_ROOT]/gems/passenger-2.2.13/lib/phusion_passenger/rack/request_handler.rb:92:in
process_request'
[GEM_ROOT]/gems/passenger-2.2.13/lib/phusion_passenger/abstract_request_handler.rb:207:in
main_loop'
[GEM_ROOT]/gems/passenger-2.2.13/lib/phusion_passenger/rack/application_spawner.rb:120:in
run'
[GEM_ROOT]/gems/passenger-2.2.13/lib/phusion_passenger/rack/application_spawner.rb:65:in
spawn_application'
[GEM_ROOT]/gems/passenger-2.2.13/lib/phusion_passenger/utils.rb:252:in
safe_fork'
[GEM_ROOT]/gems/passenger-2.2.13/lib/phusion_passenger/rack/application_spawner.rb:58:in
spawn_application'
[GEM_ROOT]/gems/passenger-2.2.13/lib/phusion_passenger/rack/application_spawner.rb:41:in
spawn_application'
[GEM_ROOT]/gems/passenger-2.2.13/lib/phusion_passenger/spawn_manager.rb:159:in
spawn_application'
[GEM_ROOT]/gems/passenger-2.2.13/lib/phusion_passenger/spawn_manager.rb:287:in
handle_spawn_application'
[GEM_ROOT]/gems/passenger-2.2.13/lib/phusion_passenger/abstract_server.rb:352:in
__send__'
[GEM_ROOT]/gems/passenger-2.2.13/lib/phusion_passenger/abstract_server.rb:352:in
main_loop'
[GEM_ROOT]/gems/passenger-2.2.13/lib/phusion_passenger/abstract_server.rb:196:in
start_synchronously'
[GEM_ROOT]/gems/passenger-2.2.13/bin/passenger-spawn-server:61
Comments and changes to this ticket
-
Mike Riley July 29th, 2010 @ 07:56 PM
- State changed from new to invalid
- Importance changed from to Low
Hello,
This more then likely is not a bug with Rails. The error "MySQL has gone away" is quite common. You can find a list of causes here:
http://blog.taragana.com/index.php/archive/mysql-tip-mysql-server-h...
From my experience it is typically caused by the server timing out and closing the connection. A workaround for the time out/connection issue is to include the line 'reconnect: true' in your database.yml. Here is more information in the Ruby on Rails Guides:
http://guides.rubyonrails.org/2_3_release_notes.html#reconnecting-m...
If a connection closes it will be restarted automatically when the application attempts to use it. I am going to mark this as invalid, but if you are still seeing this as a problem feel free to update this ticket.
Mike Riley
-
Alex Le July 29th, 2010 @ 09:12 PM
Mike, thanks for the thorough explanation. I really appreciate it.
Please go ahead and close the ticket. I have added the "reconnect: true" to the database.yml file, and I'll update the ticket if this is still an issue.
Regards,
Alex
-
Mike Riley July 29th, 2010 @ 09:29 PM
- State changed from invalid to resolved
Hello Alex,
You are quite welcome. Marking this ticket as closed as requested.
Mike Riley
-
iain July 30th, 2010 @ 09:23 AM
Not be freaking anybody out, but I'm having this problem since I upgraded Rails 3.0.0.beta4 to 3.0.0.rc. It never happened before I upgraded, and now it happened at least twice.
I don't have enough data to conclude anything about it, but just letting you know...
-
Alex Le July 30th, 2010 @ 10:01 AM
- Assigned user set to Mike Riley
Mike,
Even when I added it the line "reconnect: true" to the database.yml, I still ran into this issue again (after haven't accessed the site for a few hours). With iain's report, maybe this is a real bug in the new ActiveRecord.
I suggest we re-open this ticket so that it can be further examined.
Thanks,
Alex
-
Mike Riley July 30th, 2010 @ 09:49 PM
- Assigned user cleared.
- State changed from resolved to open
Hello Alex,
I am reopening this as requested so this can be investigated further.
Mike Riley
-
Andre Lewis July 31st, 2010 @ 01:51 AM
Chiming in on this -- I also have an app that ran without issues on all the Rails betas, but starting throwing the "MySQL has gone away" error with the RC. The error happens after the app has been dormant for a few hours. I haven't tried the reconnect:true in database.yml yet.
Ubuntu 10, Mysql 5.1.41, Rais 3Rc1, REE ruby 1.8.7 (2009-12-24 patchlevel 248), mysql gem 2.8.1, Passenger 2.2.11
-
mirza July 31st, 2010 @ 06:21 AM
I had the same problem. It was solved by setting reconnect:true in database.yml.
ruby: 1.9.2
mysql: 5.0.51a
passenger: 2.2.15
rails: 3RC1 -
James August 2nd, 2010 @ 04:28 AM
Same issue here, and setting reconnect:true in database.yml did not solve it over an extended period of time.
Need to restart unicorn workers to get it all up and running again.
This is an app which is in development, so it is sitting idle for extended periods of time - if that is of any assistance to tracking the bug down.
Ubuntu 8.04, mysql 5.0.51, Rails 3RC1, REE ruby 1.8.7 (2010-04-19 patchlevel 253), Unicorn 1.1.2, nginx/0.7.67.
-
Jeff Lawson August 2nd, 2010 @ 02:57 PM
Alex Le or James: please provide sample code that illustrates the problem, i.e. the code that invokes the ActiveRecord method that results in the error.
-
MikeF August 2nd, 2010 @ 03:56 PM
Not sure if "me too" helps at all, but I am in the same situation. App was running fine for months on previous Rails betas, after upgrading to Rails 3.0.0.rc I get "Mysql::Error (MySQL server has gone away)" for all requests after its been running for a little while.
apache
passenger (2.2.15)
rails (3.0.0.rc)
mysql gem (2.8.1)From the production.log, it runs for a while, and just breaks. Here's a successful request:
Started GET "/" for 71.178.241.200 at Sun Aug 01 20:58:51 -0400 2010
Processing by HomepageController#show as HTML Rendered players/hidden_players.html.haml (0.2ms)
Rendered unlocks/unlocks.html.haml (345.3ms)
Rendered homepage/show.html.haml within layouts/application (433.0ms)
Completed 200 OK in 707ms (Views: 433.6ms | ActiveRecord: 74.2ms)Then, the next request (admittedly 9 hours later, it's a low-traffic site) fails:
Started GET "/" for 68.87.42.115 at Mon Aug 02 08:08:09 -0400 2010
Processing by HomepageController#show as HTML Completed in 4msMysql::Error (MySQL server has gone away):
app/controllers/homepage_controller.rb:9:inshow'
I'll try the "reconnect" option mentioned above, but never had this problem until moving from beta4 to rc.
-
Alex Le August 2nd, 2010 @ 05:46 PM
@Jeff,
My Rails app is pretty standard so I'm not sure what code I should provide. So far the issue occurs when we have a long running app (maybe after a few hours) got disconnected from MySQL and couldn't reconnect.
My setting in production is Nginx, Passenger, stock MySQL installation from yum (I'm using CentOS), and the database.yml config file is:
development:
adapter: mysql database: marrily_development pool: 5 timeout: 5000 username: root host: 127.0.0.1Warning: The database defined as "test" will be erased and
re-generated from your development database when you run "rake".
Do not set this db to the same as development or production.
test:
adapter: mysql database: marrily_test pool: 5 host: 127.0.0.1 username: rootstaging:
adapter: mysql database: marrily_staging pool: 5 timeout: 5000 username: #REDACTED# password: #REDACTED# host: 127.0.0.1 reconnect: trueproduction:
adapter: mysql database: marrily_production pool: 5 timeout: 5000 username: #REDACTED# password: #REDACTED# host: 127.0.0.1 reconnect: trueHope this helps. Nonetheless, I'll take a look into the ActiveRecord code to see what's going on as well.
Alex.
-
Jeff Lawson August 2nd, 2010 @ 06:11 PM
Alex,
I was wondering what check_for_valid_coupon in:
app/controllers/app/users_controller.rb
looked like.
Jeff
-
Alex Le August 2nd, 2010 @ 06:18 PM
Jess, check_for_valid_coupon is a utility method in the controller to help me check for a valid coupon before letting user proceed with the registration (Marrily.com is still under alpha so I don't want to let people freely register, but just a few people with a correct coupon code can)
Here's the code from my app with the relevant methods:
class App::UsersController < BaseController
include ApplicationHelper include App::UsersHelperbefore_filter :authenticate_user!, :except => [ :new, :create ]
layout 'app'
def create
@user = User.new params[:user] @user.account_id = -1 # set a temporary account_id to pass the validation before actually creating the account check_for_valid_coupon return unless @coupon # for alpha @account = Account.new params[:account] if @account.valid? and @user.valid? @account.save! @user.account_id = @account.id @user.save! track_user # assign the main user id to the account @account.update_attribute :account_holder_id, @user.id # sign in for new, un-confirmed users. sign_in @user if @user.class.confirm_within > 0 flash[:notice] = "Account created successfully" redirect_to :controller => "app/events", :action => 'setup_event' else # logger.error ex render :action => 'new', :layout => 'app_registration' end
end
def check_for_valid_coupon
@coupon = nil unless params[:coupon].nil? @coupon = AppCoupon.find_by_code params[:coupon].upcase if @coupon and @coupon.active? # mark coupon as used @coupon.used! else @coupon = nil end end if @coupon.nil? flash[:error] = 'Marrily is currently in closed-alpha testing at the moment. Please enter the coupon code if you have one.' render :action => 'new', :layout => 'app_registration' and return end
end
end
-
Jeff Lawson August 2nd, 2010 @ 07:50 PM
Alex,
Completely remove New Relic RPM and see if you still have the problem.
Jeff
-
MikeF August 2nd, 2010 @ 09:25 PM
FWIW, I don't have New Relic RPM installed in my app (never did), and I'm having the same problems (see my comment above).
-
Jeff Lawson August 3rd, 2010 @ 10:11 AM
Alex's stack trace looks like this at the top:
[GEM_ROOT]/gems/activerecord-3.0.0.rc/lib/active_record/connection_adapters/abstract_adapter.rb:202:in log_without_newrelic_instrumentation' vendor/plugins/newrelic_rpm/lib/new_relic/agent/instrumentation/active_record_instrumentation.rb:65:in log' vendor/plugins/newrelic_rpm/lib/new_relic/agent/method_tracer.rb:141:in trace_execution_scoped' vendor/plugins/newrelic_rpm/lib/new_relic/agent/instrumentation/active_record_instrumentation.rb:62:in log' [GEM_ROOT]/gems/activerecord-3.0.0.rc/lib/active_record/connection_adapters/mysql_adapter.rb:286:in execute'
i.e. when @connection#query(sql) is called in ConnectionAdapters#execute, the execution path jumps into New Relic RPM and when it comes out it is in AbstractAdapter#log's exception handler where it does raise translate_exception(e, message). Clearly, the effect of @connection#query(sql) is being lost in the new Relic RPM world :-)
If Alex has the same problem without New Relic RPM then the new stack trace could shed more light on the problem.
-
Rolf Bjaanes August 11th, 2010 @ 09:39 AM
Also seeing this problem on both mysql and mysql2 adapters with 3.0RC.
Not using New Relic. Only thing special with my setup is Nginx and Unicorn.I think this should have high priority.
-
Rolf Bjaanes August 11th, 2010 @ 08:38 PM
Did those of you experiencing this use the gem or bundle rails from github?
Trying to limit the time scope.
-
Rolf Bjaanes August 12th, 2010 @ 04:39 PM
Added reconnect to my setup with mysql2 adapter.
Seems to work this far. -
Jeremy Kemper August 15th, 2010 @ 07:07 PM
- Milestone cleared.
- Assigned user set to Aaron Patterson
- Importance changed from Low to High
-
Trotter Cashion August 16th, 2010 @ 02:26 PM
Maybe "reconnect: true" should be the default? It may just be me, but I kind of like it when my application will reopen a dead connection automatically. It sure beats me having to go in and kick things. My guess is that most people just assume Rails does this by default.
-
Aaron Patterson August 16th, 2010 @ 09:23 PM
"reconnect: true" should fix the problem. Here is a sample program to reproduce the error (this script assumes a database called "activerecord_unittest" that has a "toys" table):
require 'rubygems' require 'mysql' require 'active_support' require 'active_record' p ActiveRecord::VERSION::STRING options = { :adapter => 'mysql', :database => 'activerecord_unittest', ## Uncomment the following line to watch the database reconnect #:reconnect => true } ActiveRecord::Base.establish_connection options class Toy < ActiveRecord::Base; end p Toy.count ActiveRecord::Base.connection.execute('SET wait_timeout = 10') sleep(11) p Toy.count
Note that if you uncomment the "reconnect" line, the database will reconnect. The error is reproducible on 2.3.x as well as 3.0.
I agree with Trotter that "reconnection: true" should be default. Unless anyone objects, I will change AR to have reconnect set to true by default.
-
Jeremy Kemper August 17th, 2010 @ 05:22 PM
reconnect: true
bypasses the additional config we do to the connection, like setting the encoding. We probably shouldn't expose it as an option.The regression here is that the connection manager is checking out an idle connection. Or something is hanging on to a connection instance rather than checking it out from the manager. Either way, the connection is idling out and not getting verified before use.
-
Aaron Patterson August 17th, 2010 @ 05:37 PM
After talking to @bitsweat, it sounds like setting
reconnect: true
as default is bad news. I need to do more investigation, so:@Rolf, @Alex: a few questions,
1) Are you running your application with cache_classes turned off?
2) If you turn cache_classes off, does the problem go away?
3) Can you provide a small app that shows the same behavior?
The reason I'm asking about the class cache is that I suspect the bug is here:
http://github.com/rails/rails/blob/master/activerecord/lib/active_r...
I'm not sure why we would only add this code in the case that classes are not cached.
-
Rolf Bjaanes August 17th, 2010 @ 06:00 PM
@Aaron:
1) Running with cache_classes = true
Regarding 2, I need some advice on testing this reliably in the app env.
Only noticed it when I left the app running overnight and there was no activity.Unicorn establishes db connections as well, which might come into play.
# unicorn.rb config after_fork do |server, worker| # the following is required for Rails + "preload_app true", defined?(ActiveRecord::Base) and ActiveRecord::Base.establish_connection end
-
Aaron Patterson August 17th, 2010 @ 07:42 PM
@Rolf, (and everyone :-) ),
I'll try to explain what I think is going wrong. MySQL has a wait_timeout set to 28800 seconds (8hrs). What that means is that if a connection is idle for more than 8hrs, MySQL closes the connection. You can speed up reproducing the error by setting the wait_timeout to a lower value.
Here is my hypothesis: When connections are checked out from the pool, they are automatically verified to be open. Calling
ActiveRecord::Base.connection
will check out a connection and cache it in the @reserved_connections hash. Unless the connection is checked back in, callingconnection
on the connection pool will happily return a stale connection that was cached in @reserved_connections.I think there are two ways to solve this.
1) Fix this code so that clear_reloadable_connections! is called even if we're caching classes.
2) Modify this code to verify the connection after pulling it from the @reserved_connections hash.
I like the first solution best, but I don't know the history for this code. It requires research.
Also, before I make any modifications I need to write a failing test to prove my hypothesis. Stay tuned. :-)
-
Aaron Patterson August 19th, 2010 @ 02:19 AM
@Rolf establishing the connection shouldn't do anything. From reading the source, it doesn't look like it actually establishes a connection but rather creates a connection pool. Also, can you upload the output of "SHOW variables"?
I have bad news. :'(
I can't reproduce this bug. :'(
I created a minimal rails application, set the wait timeout on the mysql side to 10 seconds, and everything worked fine (even without reconnect set).
I need more information because I feel like I'm shooting in the dark. I'll keep messing around, but without a better repro, I'm not sure what to do.
-
Jeremy Kemper August 19th, 2010 @ 07:22 AM
Do you have
config.cache_classes = true
in the minimal app? -
Rolf Bjaanes August 19th, 2010 @ 09:00 AM
@Aaron
Output from "SHOW variables" in mysql below.
(if you need the output queried from Rails, let me know)To sum it up:
Error happened on both the mysql and mysql2 adapter without reconnect.
The error most likely raised it's head between the b4 release, and RC release.The ruby version was ruby-1.8.7-p299. (updated to 1.9.2-p0 now)
Setup is Nginx with Unicorn.I'll turn reconnect off today, to see if the error rears it head again tomorrow.
Is there any code you'd want me to put in my ApplicationController to log the status of
the connection pool?mysql> show variables; +-----------------------------------------+-------------------------------------------------------------------------------------------+ | Variable_name | Value | +-----------------------------------------+-------------------------------------------------------------------------------------------+ | auto_increment_increment | 1 | | auto_increment_offset | 1 | | autocommit | ON | | automatic_sp_privileges | ON | | back_log | 50 | | basedir | /usr/ | | big_tables | OFF | | binlog_cache_size | 32768 | | binlog_direct_non_transactional_updates | OFF | | binlog_format | STATEMENT | | bulk_insert_buffer_size | 8388608 | | character_set_client | utf8 | | character_set_connection | utf8 | | character_set_database | utf8 | | character_set_filesystem | binary | | character_set_results | utf8 | | character_set_server | utf8 | | character_set_system | utf8 | | character_sets_dir | /usr/share/mysql/charsets/ | | collation_connection | utf8_general_ci | | collation_database | utf8_general_ci | | collation_server | utf8_general_ci | | completion_type | 0 | | concurrent_insert | 1 | | connect_timeout | 10 | | datadir | /var/lib/mysql/ | | date_format | %Y-%m-%d | | datetime_format | %Y-%m-%d %H:%i:%s | | default_week_format | 0 | | delay_key_write | ON | | delayed_insert_limit | 100 | | delayed_insert_timeout | 300 | | delayed_queue_size | 1000 | | div_precision_increment | 4 | | engine_condition_pushdown | ON | | error_count | 0 | | event_scheduler | OFF | | expire_logs_days | 0 | | flush | OFF | | flush_time | 0 | | foreign_key_checks | ON | | ft_boolean_syntax | + -><()~*:""&| | | ft_max_word_len | 84 | | ft_min_word_len | 4 | | ft_query_expansion_limit | 20 | | ft_stopword_file | (built-in) | | general_log | OFF | | general_log_file | /var/lib/mysql/li144-225.log | | group_concat_max_len | 1024 | | have_community_features | YES | | have_compress | YES | | have_crypt | YES | | have_csv | YES | | have_dynamic_loading | YES | | have_geometry | YES | | have_innodb | YES | | have_ndbcluster | DISABLED | | have_openssl | DISABLED | | have_partitioning | YES | | have_query_cache | YES | | have_rtree_keys | YES | | have_ssl | DISABLED | | have_symlink | YES | | hostname | li144-225 | | identity | 0 | | ignore_builtin_innodb | OFF | | init_connect | | | init_file | | | init_slave | | | innodb_adaptive_hash_index | ON | | innodb_additional_mem_pool_size | 1048576 | | innodb_autoextend_increment | 8 | | innodb_autoinc_lock_mode | 1 | | innodb_buffer_pool_size | 8388608 | | innodb_checksums | ON | | innodb_commit_concurrency | 0 | | innodb_concurrency_tickets | 500 | | innodb_data_file_path | ibdata1:10M:autoextend | | innodb_data_home_dir | | | innodb_doublewrite | ON | | innodb_fast_shutdown | 1 | | innodb_file_io_threads | 4 | | innodb_file_per_table | OFF | | innodb_flush_log_at_trx_commit | 1 | | innodb_flush_method | | | innodb_force_recovery | 0 | | innodb_lock_wait_timeout | 50 | | innodb_locks_unsafe_for_binlog | OFF | | innodb_log_buffer_size | 1048576 | | innodb_log_file_size | 5242880 | | innodb_log_files_in_group | 2 | | innodb_log_group_home_dir | ./ | | innodb_max_dirty_pages_pct | 90 | | innodb_max_purge_lag | 0 | | innodb_mirrored_log_groups | 1 | | innodb_open_files | 300 | | innodb_rollback_on_timeout | OFF | | innodb_stats_on_metadata | ON | | innodb_support_xa | ON | | innodb_sync_spin_loops | 20 | | innodb_table_locks | ON | | innodb_thread_concurrency | 8 | | innodb_thread_sleep_delay | 10000 | | innodb_use_legacy_cardinality_algorithm | ON | | insert_id | 0 | | interactive_timeout | 28800 | | join_buffer_size | 131072 | | keep_files_on_create | OFF | | key_buffer_size | 16777216 | | key_cache_age_threshold | 300 | | key_cache_block_size | 1024 | | key_cache_division_limit | 100 | | language | /usr/share/mysql/english/ | | large_files_support | ON | | large_page_size | 0 | | large_pages | OFF | | last_insert_id | 0 | | lc_time_names | en_US | | license | GPL | | local_infile | ON | | locked_in_memory | OFF | | log | OFF | | log_bin | OFF | | log_bin_trust_function_creators | OFF | | log_bin_trust_routine_creators | OFF | | log_error | /var/lib/mysql/li144-225.err | | log_output | FILE | | log_queries_not_using_indexes | OFF | | log_slave_updates | OFF | | log_slow_queries | OFF | | log_warnings | 1 | | long_query_time | 10.000000 | | low_priority_updates | OFF | | lower_case_file_system | OFF | | lower_case_table_names | 0 | | max_allowed_packet | 1048576 | | max_binlog_cache_size | 18446744073709547520 | | max_binlog_size | 1073741824 | | max_connect_errors | 10 | | max_connections | 151 | | max_delayed_threads | 20 | | max_error_count | 64 | | max_heap_table_size | 16777216 | | max_insert_delayed_threads | 20 | | max_join_size | 18446744073709551615 | | max_length_for_sort_data | 1024 | | max_prepared_stmt_count | 16382 | | max_relay_log_size | 0 | | max_seeks_for_key | 18446744073709551615 | | max_sort_length | 1024 | | max_sp_recursion_depth | 0 | | max_tmp_tables | 32 | | max_user_connections | 0 | | max_write_lock_count | 18446744073709551615 | | min_examined_row_limit | 0 | | multi_range_count | 256 | | myisam_data_pointer_size | 6 | | myisam_max_sort_file_size | 9223372036853727232 | | myisam_mmap_size | 18446744073709551615 | | myisam_recover_options | OFF | | myisam_repair_threads | 1 | | myisam_sort_buffer_size | 8388608 | | myisam_stats_method | nulls_unequal | | myisam_use_mmap | OFF | | ndb_autoincrement_prefetch_sz | 1 | | ndb_cache_check_time | 0 | | ndb_connectstring | | | ndb_extra_logging | 0 | | ndb_force_send | ON | | ndb_index_stat_cache_entries | 32 | | ndb_index_stat_enable | OFF | | ndb_index_stat_update_freq | 20 | | ndb_report_thresh_binlog_epoch_slip | 3 | | ndb_report_thresh_binlog_mem_usage | 10 | | ndb_use_copying_alter_table | OFF | | ndb_use_exact_count | ON | | ndb_use_transactions | ON | | net_buffer_length | 16384 | | net_read_timeout | 30 | | net_retry_count | 10 | | net_write_timeout | 60 | | new | OFF | | old | OFF | | old_alter_table | OFF | | old_passwords | OFF | | open_files_limit | 1024 | | optimizer_prune_level | 1 | | optimizer_search_depth | 62 | | optimizer_switch | index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on | | pid_file | /var/lib/mysql/li144-225.pid | | plugin_dir | /usr/lib/mysql/plugin | | port | 3306 | | preload_buffer_size | 32768 | | profiling | OFF | | profiling_history_size | 15 | | protocol_version | 10 | | pseudo_thread_id | 96 | | query_alloc_block_size | 8192 | | query_cache_limit | 1048576 | | query_cache_min_res_unit | 4096 | | query_cache_size | 0 | | query_cache_type | ON | | query_cache_wlock_invalidate | OFF | | query_prealloc_size | 8192 | | rand_seed1 | | | rand_seed2 | | | range_alloc_block_size | 4096 | | read_buffer_size | 131072 | | read_only | OFF | | read_rnd_buffer_size | 262144 | | relay_log | | | relay_log_index | | | relay_log_info_file | relay-log.info | | relay_log_purge | ON | | relay_log_space_limit | 0 | | report_host | | | report_password | | | report_port | 3306 | | report_user | | | rpl_recovery_rank | 0 | | secure_auth | OFF | | secure_file_priv | | | server_id | 1 | | skip_external_locking | ON | | skip_name_resolve | OFF | | skip_networking | ON | | skip_show_database | OFF | | slave_compressed_protocol | OFF | | slave_exec_mode | STRICT | | slave_load_tmpdir | /tmp | | slave_net_timeout | 3600 | | slave_skip_errors | OFF | | slave_transaction_retries | 10 | | slow_launch_time | 2 | | slow_query_log | OFF | | slow_query_log_file | /var/lib/mysql/li144-225-slow.log | | socket | /var/run/mysqld/mysqld.sock | | sort_buffer_size | 524288 | | sql_auto_is_null | ON | | sql_big_selects | ON | | sql_big_tables | OFF | | sql_buffer_result | OFF | | sql_log_bin | ON | | sql_log_off | OFF | | sql_log_update | ON | | sql_low_priority_updates | OFF | | sql_max_join_size | 18446744073709551615 | | sql_mode | | | sql_notes | ON | | sql_quote_show_create | ON | | sql_safe_updates | OFF | | sql_select_limit | 18446744073709551615 | | sql_slave_skip_counter | | | sql_warnings | OFF | | ssl_ca | | | ssl_capath | | | ssl_cert | | | ssl_cipher | | | ssl_key | | | storage_engine | MyISAM | | sync_binlog | 0 | | sync_frm | ON | | system_time_zone | EDT | | table_definition_cache | 256 | | table_lock_wait_timeout | 50 | | table_open_cache | 64 | | table_type | MyISAM | | thread_cache_size | 0 | | thread_handling | one-thread-per-connection | | thread_stack | 262144 | | time_format | %H:%i:%s | | time_zone | SYSTEM | | timed_mutexes | OFF | | timestamp | 1282204061 | | tmp_table_size | 16777216 | | tmpdir | /tmp | | transaction_alloc_block_size | 8192 | | transaction_prealloc_size | 4096 | | tx_isolation | REPEATABLE-READ | | unique_checks | ON | | updatable_views_with_limit | YES | | version | 5.1.47 | | version_comment | Source distribution | | version_compile_machine | x86_64 | | version_compile_os | unknown-linux-gnu | | wait_timeout | 28800 | | warning_count | 0 | +-----------------------------------------+-------------------------------------------------------------------------------------------+
-
Aaron Patterson August 19th, 2010 @ 05:11 PM
@Jeremy yes, and I'm running in production mode. I've attached my sample application (that doesn't break for me).
Here is my my.cnf:
[client] character_set = utf8 [mysqld] character-set-server = utf8 default-character-set = utf8 init-connect = 'SET NAMES utf8' wait_timeout = 10
Here is how I start my server:
$ RAILS_ENV=production RAILS=$HOME/git/rails bundle exec script/rails server
Here are the curl commands I use:
$ curl http://localhost:3000/foo; sleep 11; curl http://localhost:3000/foo
-
Rolf Bjaanes August 19th, 2010 @ 11:46 PM
Turned off the reconnect on my app now.
It'll be fun to see what it says tomorrow.Good night.
-
Fredrik Thuresson August 20th, 2010 @ 03:37 PM
I just ran in to this here this morning on rails 3.0.0.rc
My change yesterday was on Passenger where added PassengerPoolIdleTime 0 to remove the slow start ups (I like the fact that they die off, but the users don't). It sat idle all night and this morning. It was throwing 500's. It's running the default production config for internal testing, so no traffic outside business hours.
In the logs it says:
ActiveRecord::StatementInvalid (Mysql::Error: MySQL server has gone away: .....Ubuntu 10.04.1 LTS
Apache/2.2.14 (Ubuntu)
Mysql: 5.1.41-3ubuntu12.6-log (Ubuntu)
ruby 1.8.7 (2010-01-10 patchlevel 249) [x86_64-linux]
rails 3.0.0.rc
passenger 2.2.13restarting apache relived the issue. I've added the reconnect: true to the database.yml so we will see if that helps. It was mentioned that adding that statement was not a good idea. Why?
-
Rolf Bjaanes August 20th, 2010 @ 06:34 PM
The app was failing this morning as expected.
It saw some activity around 2.30 AM, hit a NameError in a controller.
22 minutes later, (with no db acitivity) the mysql connection is gone.
Mysql processlist showed zero connections this morning.I can't reproduce by taking the same steps.
The processlist in mysql shows 2 sleeping connections now.
Ideas?
-
Jeremy Kemper August 21st, 2010 @ 02:54 AM
Looks like the regression is http://github.com/rails/rails/commit/6b29dc876fe185881d46731c3ae170.... If you set
config.threadsafe!
in yourconfig/application.rb
, it will work around the problem. -
mixr August 23rd, 2010 @ 12:07 AM
Hi,
i wanted to add that i'm quite sure the problem also exists for a non-idle app. In my setup a cronjob calls a certain controller every minute and there are some sql queries triggered each time.
After switching to rails 3rc, the same problems appeared ca. 6-8 hours after restarting apache ("MySQL server has gone away", ruby 1.8.7, passenger 2.1.14 with apache, production app, cache_classes = true, config.threadsafe! not set )
After setting reconnect: true in database.yml, no errors since then.
-
iHiD August 23rd, 2010 @ 09:06 AM
I agree entirely with mixr. I added reconnect:true into my database.yml last night and have had my first 6hr period without an issue for a while.
-
Rolf Bjaanes August 23rd, 2010 @ 09:26 AM
@mixr
That could be attributed to caching of queries.
Using reconnect: true is not a good solution.
There is a regression which needs to be fixed and Aaron is looking into it. -
Aaron Patterson August 23rd, 2010 @ 04:39 PM
- State changed from open to resolved
Hey everyone! Jeremy and I discussed the problem, and he was able to find the commit where the regression occurred:
http://github.com/rails/rails/commit/6b29dc876fe185881d46731c3ae170...
Jeremy reverted the regression commit here:
http://github.com/rails/rails/commit/c211d904ba358d3d1ae85d56fa3a80...
So this ticket should be fixed, so I will mark it as fixed. :-)
Create your profile
Help contribute to this project by taking a few moments to create your personal profile. Create your profile »
<h2 style="font-size: 14px">Tickets have moved to Github</h2>
The new ticket tracker is available at <a href="https://github.com/rails/rails/issues">https://github.com/rails/rails/issues</a>