Resque is returning Mysql2::Error: closed MySQL connection: SHOW FIELDS FROM `users`

Question

Resque is returning Mysql2::Error: closed MySQL connection: SHOW FIELDS FROM users

Worker
    8608f362-819b-4c15-b42b-69c4df00d27b:1 on low at about 16 hours ago 
Class
    AddLiveView
Arguments

    4383
    {"remote_ip"=>"184.72.47.71", "expires"=>true}

Exception
    ActiveRecord::StatementInvalid
Error
    Mysql2::Error: closed MySQL connection: SHOW FIELDS FROM `users`

    /app/vendor/bundle/ruby/1.9.1/gems/activerecord-3.1.3/lib/active_record/connection_adapters/mysql2_adapter.rb:283:in `query'
    /app/vendor/bundle/ruby/1.9.1/gems/activerecord-3.1.3/lib/active_record/connection_adapters/mysql2_adapter.rb:283:in `block in execute'
    /app/vendor/bundle/ruby/1.9.1/gems/activerecord-3.1.3/lib/active_record/connection_adapters/abstract_adapter.rb:244:in `block in log'
    /app/vendor/bundle/ruby/1.9.1/gems/activesupport-3.1.3/lib/active_support/notifications/instrumenter.rb:21:in `instrument'
    /app/vendor/bundle/ruby/1.9.1/gems/activerecord-3.1.3/lib/active_record/connection_adapters/abstract_adapter.rb:239:in `log'
    /app/vendor/bundle/ruby/1.9.1/gems/activerecord-3.1.3/lib/active_record/connection_adapters/mysql2_adapter.rb:283:in `execute'
    /app/vendor/bundle/ruby/1.9.1/gems/activerecord-3.1.3/lib/active_record/connection_adapters/mysql2_adapter.rb:473:in `columns'
    /app/vendor/bundle/ruby/1.9.1/gems/activerecord-3.1.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:95:in `block (2 levels) in initialize'
    /app/vendor/bundle/ruby/1.9.1/gems/activerecord-3.1.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:185:in `with_connection'
    /app/vendor/bundle/ruby/1.9.1/gems/activerecord-3.1.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:92:in `block in initialize'
    /app/vendor/bundle/ruby/1.9.1/gems/activerecord-3.1.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:106:in `yield'
    /app/vendor/bundle/ruby/1.9.1/gems/activerecord-3.1.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:106:in `default'
    /app/vendor/bundle/ruby/1.9.1/gems/activerecord-3.1.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:106:in `block in initialize'
    /app/vendor/bundle/ruby/1.9.1/gems/activerecord-3.1.3/lib/active_record/base.rb:717:in `yield'
    /app/vendor/bundle/ruby/1.9.1/gems/activerecord-3.1.3/lib/active_record/base.rb:717:in `default'
    /app/vendor/bundle/ruby/1.9.1/gems/activerecord-3.1.3/lib/active_record/base.rb:717:in `columns_hash'
    /app/vendor/bundle/ruby/1.9.1/gems/activerecord-3.1.3/lib/active_record/locking/optimistic.rb:145:in `locking_enabled?'
    /app/vendor/bundle/ruby/1.9.1/gems/activerecord-3.1.3/lib/active_record/relation.rb:110:in `to_a'
    /app/vendor/bundle/ruby/1.9.1/gems/activerecord-3.1.3/lib/active_record/relation/finder_methods.rb:376:in `find_first'
    /app/vendor/bundle/ruby/1.9.1/gems/activerecord-3.1.3/lib/active_record/relation/finder_methods.rb:122:in `first'
    /app/vendor/bundle/ruby/1.9.1/gems/activerecord-3.1.3/lib/active_record/associations/singular_association.rb:42:in `find_target'
    /app/vendor/bundle/ruby/1.9.1/gems/activerecord-3.1.3/lib/active_record/associations/association.rb:146:in `load_target'
    /app/vendor/bundle/ruby/1.9.1/gems/activerecord-3.1.3/lib/active_record/associations/association.rb:56:in `reload'
    /app/vendor/bundle/ruby/1.9.1/gems/activerecord-3.1.3/lib/active_record/associations/singular_association.rb:9:in `reader'
    /app/vendor/bundle/ruby/1.9.1/gems/activerecord-3.1.3/lib/active_record/associations/builder/association.rb:41:in `block in define_readers'
    /app/app/workers/add_live_view.rb:24:in `block in perform'
    /usr/local/lib/ruby/1.9.1/timeout.rb:58:in `timeout'
    /app/app/workers/add_live_view.rb:13:in `perform'

My worker class looks like:

class AddLiveView
  @queue = :low

  def self.perform(song_id, options)
    begin
      song = Song.find(song_id)
      current_user = User.find(options['current_user_id']) if !options['expires']
    rescue
      puts "Error #{$!}"
    end

    begin
      Timeout.timeout(30.seconds) do
        if options['expires']
          # live_view = LiveView.add_live_view_that_expires(song, options['remote_ip'])
          ip_to_country = IpToCountry.where('ip_to_countries.ip_number_to >= INET_ATON(?)', options['remote_ip']).order('ip_number_to ASC').limit(1).first

          live_view = LiveView.new(:live_viewable => song, :live_viewable_category => 'View', :expires => true, :expires_at => 1.month.from_now, :ip => options['remote_ip'], :country_name => ip_to_country.country_name, :iso_two_letter_country_code => ip_to_country.iso_two_letter_country_code)

          if live_view.save
            Pusher["#{song.class.to_s.underscore}_#{song.id}"].trigger('live_view', {
              :user          => nil,
              :live_viewable => live_view.live_viewable,
              :artist        => live_view.live_viewable.user
            })

            # We do this in the worker, because we want the live_view object to exist when we push it to our notification service
            # Only keep data from last 30 days
            LiveView.where('live_views.expires = ? AND live_views.expires_at < ?', true, Date.today).destroy_all
          end
        else
          # ... do something else here ... 
        end
      end
    rescue Timeout::Error
    end
  end
end

In console, I tried doing it manually by doing:

song = Song.find(4383)
ip_to_country = IpToCountry.where('ip_to_countries.ip_number_to >= INET_ATON(?)', '184.72.47.71').order('ip_number_to ASC').limit(1).first
live_view = LiveView.new(:live_viewable => song, :live_viewable_category => 'View', :expires => true, :expires_at => 1.month.from_now, :ip => '184.72.47.71', :country_name => ip_to_country.country_name, :iso_two_letter_country_code => ip_to_country.iso_two_letter_country_code)
live_view.save
live_view.live_viewable.user

Everything works! Why does the error show up in production? Could this be that there are many connections hitting the db at the same time and the timeout limit is being reached?

Answer 1

Could this be that there are many connections hitting the db at the same time and the timeout limit is being reached?

That could be it. You can demonstrate something like it easily in Rails' console.

$ rails console
Loading development environment (Rails 3.2.2)
1.9.3-p125 :001 > require 'timeout'
 => true
1.9.3-p125 :002 > Timeout.timeout(1) { User.find_by_sql('SELECT sleep(2) FROM users;') }
  User Load (974.4ms)  SELECT sleep(2) FROM users;
: execution expired: SELECT sleep(2) FROM users;
ActiveRecord::StatementInvalid: : execution expired: SELECT sleep(2) FROM users;
        from /Users/sluukkonen/.rvm/gems/ruby-1.9.3-p125/gems/activerecord-3.2.2/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:243:in `query'
# Skip the rest of the backtrace...

After this, every query to the database will raise a Mysql2::Error, as the connection is closed.

1.9.3-p125 :003 > User.count
Mysql2::Error: closed MySQL connection: SHOW FULL FIELDS FROM `users`
ActiveRecord::StatementInvalid: Mysql2::Error: closed MySQL connection: SHOW FULL FIELDS FROM `users`
    from /Users/sluukkonen/.rvm/gems/ruby-1.9.3-p125/gems/activerecord-3.2.2/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:243:in `query'
# Again, skip the rest of the backtrace..

I'm not sure what the intended behavior is, so I can't say if there is a bug in Mysql2 or ActiveRecord, but using PostgreSQL with the pg gem doesn't exhibit similar behavior (subsequent queries are executed normally).

Adding reconnect: true to your database.yml should fix the problem, but note the caveats that adding it entails.