Skip to content
This repository

Occasional `undefined method 'each' for nilclass` in mysql2_adapter.rb line 628 #66

Closed
nragaz opened this Issue September 27, 2010 · 68 comments
Nick Ragaz

I get periodic exceptions from line 628 of lib/active_record/connection_adapters/mysql2_adapter.rb, with the following backtrace:

NoMethodError: undefined method `each' for nil:NilClass

[GEM_ROOT]/bundler/gems/mysql2-ba41a5a24e51/lib/active_record/connection_adapters/mysql2_adapter.rb:628:in `select'
[GEM_ROOT]/bundler/gems/rails-268319c8baf4/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:7:in `select_all'
[GEM_ROOT]/bundler/gems/rails-268319c8baf4/activerecord/lib/active_record/connection_adapters/abstract/query_cache.rb:54:in `block in select_all'
[GEM_ROOT]/bundler/gems/rails-268319c8baf4/activerecord/lib/active_record/connection_adapters/abstract/query_cache.rb:68:in `cache_sql'
[GEM_ROOT]/bundler/gems/rails-268319c8baf4/activerecord/lib/active_record/connection_adapters/abstract/query_cache.rb:54:in `select_all'
[GEM_ROOT]/bundler/gems/rails-268319c8baf4/activerecord/lib/active_record/base.rb:467:in `find_by_sql'
[GEM_ROOT]/bundler/gems/rails-268319c8baf4/activerecord/lib/active_record/relation.rb:64:in `to_a'
[GEM_ROOT]/bundler/gems/rails-268319c8baf4/activerecord/lib/active_record/relation.rb:358:in `method_missing'

I'm running the rails 3.0.1-stable branch and the latest HEAD of mysql2.

This error seems to occur after Unicorn restarts following a deploy, so I wonder if something important is getting nulled during the restart process. It seems to resolve after a period of time. Only one query generates this error, though, so I tend to think it is also a bug in the adapter.

The query that generates the error is rather complex:

Report.
where('(reports.author_first_name IS NOT NULL AND reports.author_first_name != ?) OR (reports.location IS NOT NULL AND reports.location != ?)', "", "").
select((ATTRIBUTES+[:id,:account_id]).map { |c| "reports.#{c}" }.join(", ")).
group('CONCAT(lower(ifnull(author_first_name, "")), lower(ifnull(location, "")))')
Nick Ragaz

This seems to be related to the query cache somehow - I had to restart the server to get rid of it completely after deploying a new version of my app.

CaptainU

I get this too.

/mysql2-0.2.4/lib/active_record/connection_adapters/mysql2_adapter.rb:628:in `select'

It seems to happen randomly. The query is very simple that generates it.

Nick Ragaz

I am very optimistically thinking that I have resolved the issue by tweaking my Unicorn config per this gist: http://gist.github.com/534668

Specifically, adding the before_exec block at the bottom and Rails.cache.reset in the after_fork block.

I think the error was being caused by a funky Active Record connection in my Unicorn worker, and propagated by a caching problem.

CaptainU

I am having this issue with Passenger 3 beta in production env, so it is not Unicorn specific.

Also, I am not using the Rails.cache/memcache in my app currently, so I don't think it's related to that.

I don't understand how the before_exec stuff would be affecting this issue.

To me, it seems like the issue is that it loses a connection to the server and doesn't try to reconnect or something, hence the randomness.

Are you running with a mysql server on a separate machine from the app? I am.

CaptainU

After looking into this a bit, I'm fairly sure this is an issue with Mysql2.

The line that's failing expects execute / rb_mysql_client_query to return an array, but they are returning nil.

I've fixed this with something that I can't imagine is a good idea, but is working for me:

    def select(sql, name = nil)
      array = execute(sql, name)
      unless array
        connect
        array = execute(sql, name)
      end
      array.each(:as => :hash)
    end
Nick Ragaz

I agree that it's an issue with the adapter, because it shouldn't just fail out randomly at that point.

However, the environment that leads to that nil return probably shouldn't exist either.

I suspect that we have both found different ways of getting there, though.

CaptainU

BTW -- This was more than an 'occasional' issue. It happens about 1 in 4 times, which makes mysql2 unusable for me without the fix I posted above, since it's not feasible to have 1 in 4 requests fail in production.

Víctor Martínez

I'm also having this exception.

(NoMethodError) "undefined method `each' for nil:NilClass"

/usr/local/rvm/gems/ruby-1.9.2-p0/ruby/1.9.1/gems/mysql2-0.2.4/lib/active_record/connection_adapters/mysql2_adapter.rb:628:in `select'
/usr/local/rvm/gems/ruby-1.9.2-p0/ruby/1.9.1/gems/activerecord-3.0.0/lib/active_record/connection_adapters/abstract/database_statements.rb:7:in `select_all'
/usr/local/rvm/gems/ruby-1.9.2-p0/ruby/1.9.1/gems/activerecord-3.0.0/lib/active_record/connection_adapters/abstract/query_cache.rb:54:in `block in select_all'
/usr/local/rvm/gems/ruby-1.9.2-p0/ruby/1.9.1/gems/activerecord-3.0.0/lib/active_record/connection_adapters/abstract/query_cache.rb:68:in `cache_sql'
/usr/local/rvm/gems/ruby-1.9.2-p0/ruby/1.9.1/gems/activerecord-3.0.0/lib/active_record/connection_adapters/abstract/query_cache.rb:54:in `select_all'
/usr/local/rvm/gems/ruby-1.9.2-p0/ruby/1.9.1/gems/activerecord-3.0.0/lib/active_record/base.rb:467:in `find_by_sql'
/usr/local/rvm/gems/ruby-1.9.2-p0/ruby/1.9.1/gems/activerecord-3.0.0/lib/active_record/relation.rb:64:in `to_a'
/usr/local/rvm/gems/ruby-1.9.2-p0/ruby/1.9.1/gems/activerecord-3.0.0/lib/active_record/relation/finder_methods.rb:143:in `all'
Brian Lopez
Owner

Definitely seems like a bug down in mysql2 itself, nil shouldn't be getting returned there in any case.
Looking into it

Rouge Cardinal

I'm also having the error , seems like it's happening on slow queries :
http://gist.github.com/611575

Joshua Slayton

Also having this error, rolling back to 0.2.3 solved our issues.

Rouge Cardinal

When happening in console, we loose the connection to the database for next queries

Brian Lopez
Owner

interesting, do you have a test case or script you could send me to reproduce the issue?

Rouge Cardinal

Unfortunatly not... I've been having this bug a couple of time before finding the origin, but wasn't able to reproduce it.

Brian Lopez
Owner

I've been trying to reproduce this with no luck so far, could you guys give mysql2 master a try and see if it's any better?

CaptainU

I think the issue may involve using remote mysql servers. Is everyone else here getting this issue when connecting to a remote server?

I have the issue on a staging server on slicehost that is connecting to a db on a separate staging server on slicehost.

Joshua Slayton

We experienced the issue on a local mysql server (rails app and mysql on same box)

Víctor Martínez

Still having this issue using master branch. apache2 and mysql running on the same server.

Paul Rosen

I just started getting this error, too. It seems completely random when it happens. I can rerun the task and it works the second time, or at least gets farther before the error occurs. I don't have a simple example to post that I can extract, but the error seems to occur more often when calling active records's all(), so I was assuming that it is just not handling large data returns.

You have a nil object when you didn't expect it!
You might have expected an instance of Array.
The error occurred while evaluating nil.each
/usr/local/lib/ruby/gems/1.8/gems/mysql2-0.2.3/lib/active_record/connection_adapters/mysql2_adapter.rb:627:in select'
/usr/local/lib/ruby/gems/1.8/gems/activerecord-3.0.0/lib/active_record/connection_adapters/abstract/database_statements.rb:7:in
select_all'
/usr/local/lib/ruby/gems/1.8/gems/activerecord-3.0.0/lib/active_record/connection_adapters/abstract/query_cache.rb:56:in select_all'
/usr/local/lib/ruby/gems/1.8/gems/activerecord-3.0.0/lib/active_record/base.rb:467:in
find_by_sql'
/usr/local/lib/ruby/gems/1.8/gems/activerecord-3.0.0/lib/active_record/relation.rb:64:in to_a'
/usr/local/lib/ruby/gems/1.8/gems/activerecord-3.0.0/lib/active_record/relation/finder_methods.rb:143:in
all'
/usr/local/lib/ruby/gems/1.8/gems/activerecord-3.0.0/lib/active_record/base.rb:439:in __send__'
/usr/local/lib/ruby/gems/1.8/gems/activerecord-3.0.0/lib/active_record/base.rb:439:in
all'

Paul Rosen

I tried captainu's patch so that select() does a retry. That worked for me, I think, at least, so far.

CaptainU

Paul, that worked a little bit, but it still sometimes failed. I ended up switching to the original mysql gem and the problem is gone.

I'd like to use mysql2, but stuff was randomly breaking b/c of this issue.

Paul Rosen

Well, I moved away from mysql because of a utf-8 bug it had that mysql2 handles correctly. Your patch buys me a little time while this gets sorted out, anyway. Thanks!

Brian Lopez
Owner

Are you guys all using Unicorn or Passenger? If so, are you properly disconnecting/reconnecting in the before/after forking callbacks?

CaptainU

I'm using passenger. Where would I look to see if I'm doing this?

Brian Lopez
Owner

Try adding this in an initializer in your app:

if defined?(PhusionPassenger)
  PhusionPassenger.on_event(:starting_worker_process) do |forked|
    if forked
      # We're in smart spawning mode.
      ActiveRecord::Base.establish_connection
    else
      # We're in conservative spawning mode. We don't need to do anything.
    end
  end
end
Paul Rosen

I've seen it on my development machine using WEBrick, and also production using Passenger. And I don't understand the second part of the question, so unless that is something that happens automatically, I guess not. (captainu's patch is, so far, holding for me.)

I don't know if this is a clue or just coincidence, but where I saw it fail is in a task that completely reconstructs the database, so it is doing LOTS of activity. And it fails in one of a couple places, so it isn't completely random.

Nick Ragaz

FWIW, Brian, I turned off application preloading in Unicorn and haven't seen the issue since. I suspect that that is one of several possible causes for this error, though. Wish I could be more help - I just don't have time right now to do a proper investigation.

Brian Lopez
Owner

I'm doing some debugging on a server I was finally able to reproduce a similar error on, will post progress.

Brian Lopez
Owner

take a look at this example config file: http://shapado.com/questions/which-unicorn-rb-config-file-to-do-use

Notice the before_fork and after_fork blocks, specifically where the ActiveRecord connection is disconnected in before_fork, and reconnected in after_fork. You have to do this because the fork is a new process and needs it's own connection

Brian Lopez
Owner

Also are you guys running off master?

Rouge Cardinal

Here is my database.yml (the app was created with rails 3 beta 3 month ago and sqlite in production mod)

production:
adapter: mysql
database: db.example.com
username: "555"
password: jjj
pool: 5
timeout: 5000
socket: /var/run/mysqld/mysqld.sock

Just found that by default rails add two options :
encoding: utf8
reconnect: false

Sorry, but I don't have time right now to test these new options in production...

Cyrille Stepanyk

I've the same issue with master ref 7169649 and Passenger 3 RC. I'll try with the passenger initializer you recommend above

Brian Lopez
Owner

I just added the ability to set wait_timeout in database.yml (which defaults to a pretty high number). Could you all give master a try?

Brian Lopez
Owner

omg... I think I finally found and fixed the bug, could you all give master a try? :)

Cyrille Stepanyk

Just deployed ref 841ee2b but still the same error

[GEM_ROOT]/bundler/gems/mysql2-841ee2b/lib/active_record/connection_adapters/mysql2_adapter.rb, line 633

Is there something else to configure for wait_timeout ?

Cyrille Stepanyk

doesn't know if that helps but it's not always line 663 which is in error
I've also

[GEM_ROOT]/bundler/gems/mysql2-841ee2b/lib/active_record/connection_adapters/mysql2_adapter.rb, line 432

Brian Lopez
Owner

@cyrille - yeah the issue is actually down in the mysql2 driver itself, both of those lines call execute which uses the @connection instance var under the hood (which is a Mysql2::Client instance).
Strange that latest commit didn't fix it, I'm almost positive that was the fix.

I'll investigate some more

Nick Ragaz

Finally got a chance to try the latest master... everything works with app preloading off (in Unicorn), and then starts failing again with preloading on. Strangely, the fail is not consistent - the same query will work about every third time.

Brian Lopez
Owner

"try this" meaning master? I pushed a patch that should have hopefully fixed it

Brian Lopez
Owner

ok, I'm skeptical the latest patches will help much - but still curious nonetheless ;)
Would you mind giving master another try?

Really sorry to keep having you guys try these out, I'm still (and always have been) unable to reproduce any of these issues on my machine or in any of my VMs, or else I'd test it myself :)

Víctor Martínez

I've been running a8041fe today and no exceptions were thrown so far. However I had to rebuild the gemspec.

Brian Lopez
Owner

Oops, sorry about that - rebuilt. Glad it's working so far, please let me know if any issues pop up

Cyrille Stepanyk

Deployed 1 hour ago. So far so good no error ;)
I'll let you know if everything is ok tomorow.
Thanks anyway for your support

Cyrille Stepanyk

No more errors !
Thanks a lot

Víctor Martínez

yep, seems you finally got it fixed. thank you :)

Brian Lopez
Owner

awesome! closing for now, will push 0.2.5 very soon

Paul Rosen

It's baaaaaaack!

You have a nil object when you didn't expect it!
You might have expected an instance of Array.
The error occurred while evaluating nil.each
/.../gems/mysql2-0.2.6/lib/active_record/connection_adapters/mysql2_adapter.rb:635:in `select'

I don't know what is different, because I left this project for a month and just got back to it. I did upgrade Rails to 3.0.3 which has lots of ActiveRecord changes.

mysql2 (0.2.6)
activerecord (3.0.3)

Rouge Cardinal

If that's true, what a bad news.
Upgraded to 3.0.3 48 hours ago, not having any issue at the moment.

Paul Rosen

More info: I've only see this happen in one place: where I'm doing a really heavy pounding of the DB in a script. It is repeatable, it happened at the same place in the script twice. I put back in the patch above where you reconnect if the select fails and everything seems to work for the moment.

Brian Lopez brianmario reopened this June 15, 2011
Brian Lopez
Owner

Would you guys mind trying 0.2.8?

Nick Ragaz
nragaz commented June 15, 2011

I haven't seen this issue in ages - I've been running 0.2.8.

Víctor Martínez
knoopx commented June 16, 2011

yep me neither. it's been on production for months and never happened again.

Alex Southgate

We've seen this issue consistently using 0.2.11 (as well as previous versions of this gem, so perhaps this is an issue specific to our environment). We have a rake task that seeds our dev environment. It looks something like:

  task :reseed => 'environment' do
    Rake::Task['db:drop'].invoke
    Rake::Task['db:create'].invoke
    Rake::Task['db:migrate'].invoke
    Rake::Task['db:seed'].invoke
  end

We see the same undefined method 'each' for nilclass error coming from mysql_adapter when the db:seed task attempts to hit the database. If we insert a call to ActiveRecord::Base.verify_active_connections! in between db:migrate and db:seed, the error disappears.

Anyone else seen something like this?

Charlie Croom

also seeing this issue on 0.2.8, using passenger. Coming from mysql adapter. Really random so it's hard to replicate :( I saw this issue referenced on stackoverflow where the guy mentioned it might be related to mysql 5.5? (which is what my server is).

mysql2 (0.2.8) lib/active_record/connection_adapters/mysql2_adapter.rb:586:in `select'

Looks like the gem was probably compiled against:
libmysqlclient-dev 5.1.54-1ubuntu4 MySQL database development files
libmysqlclient16 5.1.54-1ubuntu4 MySQL database client library

Could the problem be hitting a 5.5 database with the gem being compiled against 5.1? Don't know how that stuff works, but let me know if there's any solutions I should try.

Links:
http://www.mysqldbahelp.com/2011/10/ruby-mysql2-gem-and-mysql-55-client.html
http://stackoverflow.com/questions/5265710/getting-random-nil-each-error-in-mysql2-gem-when-using-include-in-railss-find

Josiah Kiehl

On 0.2.13 I see this issue a good number of times per day. It's very sporadic and I can't find any reason why it happens some times and not others.

Seamus Roche

I am getting this issue on my remote server. Running Passenger and mysql2 0.2.7. I tried newer versions of mysql2 0.3.x. Same problem.

Woody Peterson

This problem is now technically occurring in ActiveRecord, since post-0.3.0 and Rails 3.1, AR now owns the Mysql2 connection adapter.

However, as I noted towards the end in this bug, @connection.query(sql) is returning nil, and it's unclear whether this is desired behavior or not. It's very suspicious that re-trying in a debugger afterwards returns a result; this makes me think the simplest answer is that it's a bug in Mysql2.

I tried looking for the documentation of Mysql2::Client#query and reading through the C, and didn't have much luck. From my very basic understanding of the C code, it looks like it supports returning nil sometimes; is this expected? When would you expect such a thing?

Brian Lopez
Owner

It should only return nil (on purpose) if :async => true was passed, in which case there isn't a result yet. Otherwise, I can really only guess that Ruby is doing something strange during an error and returning Qnil early? I need to do more research myself.

Josiah Kiehl

It appears in my case that nil is returned when the query has it's connection interrupted. When I forced a reconnect after forking, the problem has gone away (so far).

Woody Peterson

More info on my particular race condition, in case you have any ideas for investigation. From the AR adapter:

result = @connection.query(sql) # nil
if result.nil?
  again = @connection.query(sql) # #<Mysql2::Result>
  debugger;puts
end

I can consistently reproduce this, but I have to go to a particular page on my app, then go to another specific page, which has the following string of queries produced from a loop over a scope, the last of which fails:

(I know you don't know the data model, but maybe there's a pattern in the SQL?)

SELECT `rms_staff`.* FROM `rms_staff`  WHERE `rms_staff`.`staff_id` = 0 LIMIT 1
SELECT `rms_staff`.* FROM `rms_staff` INNER JOIN `managings` ON `rms_staff`.`staff_id` = `managings`.`staff_id` WHERE `managings`.`manager_id` = 63251 AND (kind = 'Code Manager' AND (deactivated_at IS NULL   OR NOW() BETWEEN activated_at AND deactivated_at))
SELECT  `rms_claimingunits`.* FROM `rms_claimingunits`  WHERE `rms_claimingunits`.`cu_id` = 80000 LIMIT 1
SELECT `rms_organizationalunits`.* FROM `rms_organizationalunits`  WHERE `rms_organizationalunits`.`ou_ruid` = 8
SELECT `rms_staff`.* FROM `rms_staff` INNER JOIN `rms_claimingunits` ON `rms_staff`.`staff_cuid` = `rms_claimingunits`.`cu_id` WHERE `rms_claimingunits`.`cu_ouid` = 804 AND (staff_status = 'active' OR staff_status = 'pending')
SELECT `rms_staff`.* FROM `rms_staff` INNER JOIN `rms_claimingunits` ON `rms_staff`.`staff_cuid` = `rms_claimingunits`.`cu_id` WHERE `rms_claimingunits`.`cu_ouid` = 803 AND (staff_status = 'active' OR staff_status = 'pending')

The final query results in this logic in client.c getting activated (starting at line 311, then result == NULL):

result = (MYSQL_RES *)rb_thread_blocking_region(nogvl_store_result, wrapper, RUBY_UBF_IO, 0);

if (result == NULL) {
  if (mysql_field_count(wrapper->client) != 0) {
    rb_raise_mysql2_error(wrapper);
  }
  return Qnil;
}

I'm going to keep digging, but it looks like it's a threading issue. Any suggestions are welcome, as I think it might become officially over my head.

Woody Peterson

see #224

With that, the app started bubbling up:

Mysql2::Error: Lost connection to MySQL server during query

Mysql docs say to get more info via --log-warnings=2 for mysql, and after enabling that I found this when the error happens:

111110 11:15:47 [Warning] Aborted connection 789 to db: 'my_staging_db' user: 'my_user' host: 'localhost' (Got an error writing communication packets)

And finally, googling led me to here:

I got rid of these errors by making sure I closed all threads propery before opening new ones.
Use the conn# in the error to check the query log to find what parts of your code that does not close threads properly. 

It is possible that it's a problem with my particular setup, as some other users experienced, but since I can reproduce it on two systems and it's 100% reproducable (although the steps to reproduce are odd), I still think it's worth investigating the mysql thread handling to make sure it's closing correctly.

I'm not sure I'm going to be able to do that, but I could be talked into trying it if someone's willing to walk me through some of the client.c code (since I can reproduce it so consistently, I think I'm in a position to fix it).

Brian Lopez
Owner

@woahdae damn, thanks a ton for the hard work!

Brian Lopez
Owner

Would you guys mind giving master a try?

Woody Peterson

Just caught this updating our staging server. Error shown to the user was Mysql2::Error: MySQL server has gone away:

https://gist.github.com/1365900

gist of gist:

  Symbol not found: _rb_wait_for_single_fd
  Referenced from: /Users/*/mysql2.bundle
  Expected in: flat namespace

Note that it appeared randomly, after a server instance restart, while clicking around. Could not repro.

Woody Peterson

Perhaps another ticket should be made, as the error shown isn't undef on nil anymore, and the underlying issues expressed here could vary quite a lot. Thoughts?

Woody Peterson

Other ticket or not, I figured out my particular error is directly correlated with a mixed MyISAM and InnoDB environment, namely going to from an InnoDB-heavy page to a MyISAM-heavy page causes an error, and it's unclear which side the error is on (seems like a mysql problem, but then what's that _rb_wait... stuff about?).

SO, that's good enough for me to call it my problem.

Aaron Patterson
Collaborator

I think this ticket contains multiple different problems. I suspect the original report is due to a connection being brought up in the parent unicorn process, and children sharing the same connection as the parent. Setting your unicorn config to disconnect from the database after forking should solve this problem. I've also made the connections per PID in Rails, so that should help too.

I'm going to close this ticket for now, but if people are still experiencing problems, please comment and we'll take it from there.

Thanks for using mysql2!

Aaron Patterson tenderlove closed this March 29, 2012
Víctor Martínez

I had this issue time ago and I was not using unicorn, but it has not reproduced again.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Something went wrong with that request. Please try again.