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

Mysql2::Error: This connection is still waiting for a result, try again once you have the result #99

Closed
ghazel opened this issue Dec 16, 2010 · 121 comments
Labels

Comments

@ghazel
Copy link
Collaborator

ghazel commented Dec 16, 2010

Easy to reproduce. From a console, run a query and Ctrl-C it while it's running. Then try to submit a second query:

>> client
=> #<Mysql2::Client:0x40254f0>
>> client.query("select sleep(5);")
IRB::Abort: abort then interrupt!!
      from /usr/local/ruby-enterprise-1.8.7-2010.01/lib/ruby/1.8/irb.rb:89:in `irb_abort'
      from /usr/local/ruby-enterprise-1.8.7-2010.01/lib/ruby/1.8/irb.rb:255:in `signal_handle'
      from /usr/local/ruby-enterprise-1.8.7-2010.01/lib/ruby/1.8/irb.rb:66
      from (irb):2:in `call'
      from (irb):2:in `query'
      from (irb):2
>> client.query("select sleep(2);")
Mysql2::Error: This connection is still waiting for a result, try again once you have the result
      from (irb):3:in `query'
      from (irb):3

The client object remains broken forever - long after the initial query would have returned.

@sheuer
Copy link

sheuer commented Dec 21, 2010

I'm also having this problem.

@ghazel
Copy link
Collaborator Author

ghazel commented Dec 21, 2010

This also happens when using Timeout:

>> Timeout.timeout(1) { client.query("select sleep(5);"); }
Timeout::Error: execution expired
        from /usr/local/ruby-enterprise-1.8.7-2010.01/lib/ruby/1.8/timeout.rb:60
        from (irb):17
>> Timeout.timeout(1) { client.query("select sleep(5);"); }
Mysql2::Error: This connection is still waiting for a result, try again once you have the result
        from (irb):18:in `query'
        from (irb):18
        from /usr/local/ruby-enterprise-1.8.7-2010.01/lib/ruby/1.8/timeout.rb:62:in `timeout'
        from (irb):18

@cpg
Copy link

cpg commented Dec 31, 2010

Same here, I had to press ctrl-c as things were becoming way too slow (we were doing some load testing). This is a reliability issue, as sooner or later things can get interrupted under load, etc. An app that needs to be available reliably cannot afford to have something like this lurking. Let us know how we can help fix this. The repro above with Timeout looks like a great start!

I am on RoR 3.0.3 with rack 1.2.1, ruby ruby-1.8.7.302-2.fc14.i686 and mysql2 0.2.6

@schugabe
Copy link

schugabe commented Jan 7, 2011

I have a similar problem.
I'm sending out a bunch of emails and during the generation of those I get a "Exception ActiveRecord::StatementInvalid -> : execution expired" error. This happen every time but not on the same records.

After this error occurred all following queries fail with "Exception ActiveRecord::StatementInvalid -> Mysql2::Error: This connection is still waiting for a result, try again once you have the result"

RoR 3.0.3 in a Stalker background process, ruby 1.9.2; mysql2 0.2.6

@iGEL
Copy link

iGEL commented Jan 11, 2011

I've run into this problem in production. I'm using Timeout, so a query could have been interrupted.

Rails 3.0.3, Ruby 1.8.7, mysql2 0.2.6

@conorh
Copy link

conorh commented Jan 14, 2011

Using the Mysql2::EM::Client.new class and running into this too. Ruby 1.9.2, Rails 2.3.9, EventMachine 0.12.10.

@ponny
Copy link

ponny commented Jan 29, 2011

Same. Rails3/1.9.2.

@JoshMcKin
Copy link

Same time. Rails 3 (threadsafe), 1.9.2

@deltadd
Copy link

deltadd commented Apr 7, 2011

Same. Rails3.0.6/1.9.2.

@jlecour
Copy link

jlecour commented Apr 26, 2011

Same here ; Rails 3.0.6, Ruby 1.8.7

@jlecour
Copy link

jlecour commented Apr 26, 2011

When used in Rails with ActiveRecord, it's possible to recover from this exception.

# This is just to abort a query
Timeout.timeout(1) { MyModel.connection.execute("select sleep(5);"); }

# This is the recovering hack
begin
  # Any query on a model
  MyModel.first
rescue ActiveRecord::StatementInvalid => ex
  # Since all Mysql2 errors are wrapped into ActiveRecord::StatementInvalid
  # we have to retry only for this kind of error
  if ex.message["Mysql2::Error: This connection is still waiting for a result"]
    @retries ||= 0
    # Retry only 3 times
    puts @retries
    if @retries < 3
      @retries += 1
      MyModel.connection.reconnect!
      retry
    else
      raise
    end
  else
    raise
  end
else
  @retries = 0
end

@ghazel
Copy link
Collaborator Author

ghazel commented Apr 27, 2011

Here's a monkey-patch to auto-reconnect when this occurs:

module ActiveRecord
  module ConnectionAdapters
    class Mysql2Adapter

      def query_with_reconnect(sql)
        @connection.query(sql)
      rescue Mysql2::Error => exception
        if exception.message.starts_with? "This connection is still waiting for a result"
          reconnect!
          retry
        end
        raise
      end

      # Executes the SQL statement in the context of this connection.
      def execute(sql, name = nil)
        # make sure we carry over any changes to ActiveRecord::Base.default_timezone that have been
        # made since we established the connection
        @connection.query_options[:database_timezone] = ActiveRecord::Base.default_timezone
        if name == :skip_logging
          query_with_reconnect(sql)
        else
          log(sql, name) { query_with_reconnect(sql) }
        end
      rescue ActiveRecord::StatementInvalid => exception
        if exception.message.split(":").first =~ /Packets out of order/
          raise ActiveRecord::StatementInvalid, "'Packets out of order' error was received from the database. Please update your mysql bindings (gem install mysql) and read http://dev.mysql.com/doc/mysql/en/password-hashing.html for more information.  If you're on Windows, use the Instant Rails installer to get the updated mysql bindings."
        else
          raise
        end
      end
    end
  end
end

@ramsingla
Copy link

Please have a look at #168. Does this solve the issue you guys are facing? Looking for your feedback.

@ghazel
Copy link
Collaborator Author

ghazel commented May 11, 2011

@ramsingla: I think you've addressed a different issue with the same error message. I'm using mysql2_adapter.rb not em_mysql2_adapter.rb so any EM related solution doesn't apply.

@mhoran
Copy link

mhoran commented May 18, 2011

This is also an issue if you set read_timeout in database.yml, as the connection is closed but still waiting for a result. This is with the non-EM client.

@phuongnd08
Copy link

With mysql2 0.2.7, I'm also running into this problem today when upgrade to ruby 1.9.2. Never encountered before in ruby 1.8.7

@aka47
Copy link

aka47 commented May 31, 2011

the hotfix made by @ghazel fixed the problem for us. Thanks and hope this bug gets solved .. we run into that error with lots of data in a table (sessions), it just popped up after some time without a problem.
We use mysql2 0.2.7 on ruby enterprise 1.8.7 and rails 3.0.5

@loe
Copy link
Contributor

loe commented Jun 15, 2011

I suspect people using Unicorn do not notice this as they kill the entire worker process which causes a new one to be spawned. The new worker reconnects when starting up. We use a timeout in the application to kill long running requests, and it causes queries to die in this state.

loe added a commit to loe/mysql2 that referenced this issue Jun 15, 2011
loe added a commit to loe/mysql2 that referenced this issue Jun 15, 2011
@loe
Copy link
Contributor

loe commented Jun 15, 2011

I'm thinking rb_mysql_client_query should be wrapped in an rb_rescue and the callback should reset the connection.

@brianmario
Copy link
Owner

I just pushed a fix for this in the 0.2.x and master branches, would you guys mind giving it a try? I'll push another release if it fixes it for you guys.

@loe
Copy link
Contributor

loe commented Jun 16, 2011

This causes another test to fail. I've amended my test to use :reconnect => true, you can pull it in as a test for this.

Failures:

  1) Mysql2::Result should raise a Mysql2::Error exception upon a bad query
     Failure/Error: lambda {
       expected no Mysql2::Error, got #<Mysql2::Error: closed MySQL connection>
     # ./spec/mysql2/result_spec.rb:26:in `block (2 levels) in <top (required)>'

@brianmario
Copy link
Owner

Ah good catch, lemme get a fix pushed for that

@loe
Copy link
Contributor

loe commented Jun 16, 2011

Sent a pull request for each branch, you can just pull one and merge/cherry-pick.

@brianmario
Copy link
Owner

Ok just pushed another patch, try again?

@loe
Copy link
Contributor

loe commented Jun 16, 2011

Yay:

Finished in 5.56 seconds 137 examples, 0 failures, 1 pending

brianmario added a commit that referenced this issue Jun 16, 2011
@brianmario
Copy link
Owner

@ghzel - summary of the changes to fix this issue:

The problem: if a signal interrupted the rb_thread_select call, the connection would never get marked as "inactive" (meaning, ready for another command to be sent) and would permanently be stuck in that state.

The fix: Wrap the rb_thread_select code in an rb_rescue2 call. If an exception is raised and caught, mark the connection closed and inactive, then manually shutdown the socket (not mysql_close). Since the MySQL protocol is asynchronous- if we're interrupted after the query has been sent but before we were able to process the result the protocol is essentially in a bad state and the next command would be sent out of order. If :reconnect => true is set, the next command sent would force a reconnect transparently.

This should fix the issue, but I'd like to hear back from at least another person that it has before closing the issue.

@loe
Copy link
Contributor

loe commented Jun 16, 2011

I will ship this into production on 3 well trafficked applications.

@gnufied
Copy link

gnufied commented Dec 2, 2011

This problem is alive and well on mysql2 master unfortunately:

Mysql2::Error: This connection is still waiting for a result, try again once you have the result: SELECT @@FOREIGN_KEY_CHECKS (ActiveRecord::StatementInvalid)
[04:36:01]: [Step 2/2]       /home/ubuntu/.rvm/gems/ruby-1.9.3-rc1/gems/activerecord-3.1.1/lib/active_record/connection_adapters/mysql2_adapter.rb:687:in `query'
[04:36:01]: [Step 2/2]       /home/ubuntu/.rvm/gems/ruby-1.9.3-rc1/gems/activerecord-3.1.1/lib/active_record/connection_adapters/mysql2_adapter.rb:687:in `block in exec_query'
[04:36:01]: [Step 2/2]       /home/ubuntu/.rvm/gems/ruby-1.9.3-rc1/gems/activerecord-3.1.1/lib/active_record/connection_adapters/abstract_adapter.rb:244:in `block in log'
[04:36:01]: [Step 2/2]       /home/ubuntu/.rvm/gems/ruby-1.9.3-rc1/gems/activesupport-3.1.1/lib/active_support/notifications/instrumenter.rb:21:in `instrument'
[04:36:01]: [Step 2/2]       /home/ubuntu/.rvm/gems/ruby-1.9.3-rc1/gems/activerecord-3.1.1/lib/active_record/connection_adapters/abstract_adapter.rb:239:in `log'
[04:36:01]: [Step 2/2]       /home/ubuntu/.rvm/gems/ruby-1.9.3-rc1/gems/activerecord-3.1.1/lib/active_record/connection_adapters/mysql2_adapter.rb:685:in `exec_query'
[04:36:01]: [Step 2/2]       /home/ubuntu/.rvm/gems/ruby-1.9.3-rc1/gems/activerecord-3.1.1/lib/active_record/connection_adapters/mysql2_adapter.rb:679:in `select'
[04:36:01]: [Step 2/2]       /home/ubuntu/.rvm/gems/ruby-1.9.3-rc1/gems/activerecord-3.1.1/lib/active_record/connection_adapters/abstract/database_statements.rb:18:in `select_all'
[04:36:01]: [Step 2/2]       /home/ubuntu/.rvm/gems/ruby-1.9.3-rc1/gems/activerecord-3.1.1/lib/active_record/connection_adapters/abstract/query_cache.rb:61:in `block in select_all'
[04:36:01]: [Step 2/2]       /home/ubuntu/.rvm/gems/ruby-1.9.3-rc1/gems/activerecord-3.1.1/lib/active_record/connection_adapters/abstract/query_cache.rb:75:in `cache_sql'
[04:36:01]: [Step 2/2]       /home/ubuntu/.rvm/gems/ruby-1.9.3-rc1/gems/activerecord-3.1.1/lib/active_record/connection_adapters/abstract/query_cache.rb:61:in `select_all'
[04:36:01]: [Step 2/2]       /home/ubuntu/.rvm/gems/ruby-1.9.3-rc1/gems/activerecord-3.1.1/lib/active_record/connection_adapters/abstract/database_statements.rb:24:in `select_one'
[04:36:01]: [Step 2/2]       /home/ubuntu/.rvm/gems/ruby-1.9.3-rc1/gems/activerecord-3.1.1/lib/active_record/connection_adapters/abstract/database_statements.rb:30:in `select_value'
[04:36:01]: [Step 2/2]       /home/ubuntu/.rvm/gems/ruby-1.9.3-rc1/gems/activerecord-3.1.1/lib/active_record/connection_adapters/mysql2_adapter.rb:198:in `disable_referential_integrity'
[04:36:01]: [Step 2/2]       /home/ubuntu/.rvm/gems/ruby-1.9.3-rc1/gems/database_cleaner-0.6.7/lib/database_cleaner/active_record/truncation.rb:113:in `each_table'
[04:36:01]: [Step 2/2]       /home/ubuntu/.rvm/gems/ruby-1.9.3-rc1/gems/database_cleaner-0.6.7/lib/database_cleaner/active_record/truncation.rb:106:in `clean'
[04:36:01]: [Step 2/2]       /home/ubuntu/.rvm/gems/ruby-1.9.3-rc1/gems/database_cleaner-0.6.7/lib/database_cleaner/base.rb:77:in `clean'
[04:36:01]: [Step 2/2]       /home/ubuntu/.rvm/gems/ruby-1.9.3-rc1/gems/database_cleaner-0.6.7/lib/database_cleaner/configuration.rb:56:in `block in clean'
[04:36:01]: [Step 2/2]       /home/ubuntu/.rvm/gems/ruby-1.9.3-rc1/gems/database_cleaner-0.6.7/lib/database_cleaner/configuration.rb:56:in `each'
[04:36:01]: [Step 2/2]       /home/ubuntu/.rvm/gems/ruby-1.9.3-rc1/gems/database_cleaner-0.6.7/lib/database_cleaner/configuration.rb:56:in `clean'
[04:36:01]: [Step 2/2]       /home/ubuntu/.rvm/gems/ruby-1.9.3-rc1/gems/cucumber-rails-1.1.1/lib/cucumber/rails/hooks/database_cleaner.rb:9:in `After'

@rilian
Copy link

rilian commented Dec 2, 2011

putting sleep 1 into AfterStep in support/env.rb dramatically reduces number of such errors

AfterStep("@with_mysql2_failures") do
  sleep 1
end

@dmitriy-kiriyenko
Copy link

@rilian, no kidding.

@brianmario
Copy link
Owner

new versions pushed, would you guys mind giving them a try? Make sure you've removed all other versions of mysql2 from your system first - just so we're certain you're using the new version

@dmitriy-kiriyenko
Copy link

@brianmario, worked for me! Cool. Maybe you've just decreased the probability of the bug occurrence, but I'll give it a try.

@ares
Copy link

ares commented Dec 7, 2011

@brianmario still no luck, using AfterStep workaround mentioned by @rilian does the trick for me for "Mysql2::Error: This connection is still waiting for a result"

@robvandijk
Copy link

Also for me still no luck with the latest version... The error only occurs for longer scenarios though.

@dimsuz
Copy link

dimsuz commented Jan 11, 2012

Unable to run my capybara request specs in rails app because of this bug... It happens whenever I create some test which invokes 'submit' action in some form element on page - this causes a db save action to be performed, and then everything just hangs...

@theleoborges
Copy link

Just so this doesn't get forgotten ... .it still happens in my test suite. Particularly when switching to capybara-webkit, given the tests run a lot faster in that setting.

@mborromeo
Copy link

Adding my 2c here, because i'm experiencing this issue when running my test suites.
I started a new goliath-based api, with em_mysql2 + em-syncrony, and i'm getting this error:

Failure/Error: FactoryGirl.create(:user)
ActiveRecord::StatementInvalid:
Mysql2::Error: This connection is still waiting for a result, try again once you have the result: SAVEPOINT active_record_1

Tested every kind of workaround but still no luck...
Does this impacts only test suites? Or people here have issues in production too?

@ares
Copy link

ares commented Mar 22, 2012

Does this impacts only test suites? Or people here have issues in production too?

Only tests in my app.

@johnf
Copy link

johnf commented Apr 2, 2012

I'm seeing this in production. This is not a rails app, I'm using active record and rufu-scheduler to schedule jobs and put them on a beanstalk queue for other workers. So I have threads a plenty. Interestingly I've only really noticed it since adding ar-octopus into the mix. But I suppose that could be causing other threads to die. Just upgrading from 0.3.10 to 0.3.11 now to see if that makes a difference

@nickhammond
Copy link

Just wanted to highlight why most people are having issues with capybara-webkit and on Javascript tests only. If you look at the capybara readme there's a suggestion to have ActiveRecord use the same thread and connection. The reason for this is so you can share the same data in your database across multiple tests, Cucumber patches this in a similar fashion too. Still working on a solution but hoping this will help to debug if it wasn't obvious at first.

class ActiveRecord::Base
  mattr_accessor :shared_connection
  @@shared_connection = nil

  def self.connection
    @@shared_connection || retrieve_connection
  end
end
ActiveRecord::Base.shared_connection = ActiveRecord::Base.connection

@mperham
Copy link
Contributor

mperham commented Jul 4, 2012

Please see my explanation of the problem and the solution I came up with:

https://gist.github.com/3049152

Could someone else confirm the fix works for them?

@ares
Copy link

ares commented Jul 5, 2012

I got following error using you code https://gist.github.com/3051701, maybe I just set it wrong. I put you after.rb code in features/support/env.rb which is loaded before any test being run. I thought it would monkey patch AR. Using Active record 3.2.6

@rogercampos
Copy link

This fixed our test suite, thanks @mperham ! @ares if you put this code in that file, then it gets loaded only in the client (which is running the tests). The server also needs to load it. Require it from config/environments/test.rb

@ares
Copy link

ares commented Jul 5, 2012

@rogercampos thx for the hint, I put it in config/environments/test.rb config block but I got ActiveRecord::ConnectionNotEstablished (ActiveRecord::ConnectionNotEstablished) error. Where did you put this after.rb code excatly? I also tried to put it outside of config block, but same result. I tried to put it into initializer where AR should be already initialized but then I receieved well known Mysql2::Error

@vitobotta
Copy link

Same as for ares here... where exactly should we put that code?
Thanks

@gdelfino
Copy link

I get this same issue with a web scrapping script that I wrote that use threads. So in my case it is unrelated to testing or activerecord. When the exception happens, I am handling it by waiting 1 sec and trying again. So far it works fine this way.

@sodabrew
Copy link
Collaborator

sodabrew commented Dec 3, 2012

@mperham should this be a PR against rails then?
https://gist.github.com/3049152#file_after.rb

@matt-hwy1
Copy link

@ares, @vitabotta, I'm using RSpec and put the code into my spec_helper.rb file in the RSpec config block. I added the connection_pool gem to my test group. This seems to have fixed my problems in my capybara/selenium specs. They seem to be related to me using delayed_job with Delayed::Worker.delay_jobs = false when in test mode, causing the delayed code to apparently be executed in parallel in another thread. My guess is that this trips up mysql2 with the above error. The code from @mperham (thank you!) appears to fix it by controlling access to the DB connections. So far so good but I need to test this some more.

@sodabrew
Copy link
Collaborator

Closing this. The linked issues and various merged fixes to connection pool implementations resolve this issue.

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

No branches or pull requests