Explaining QueryCache queries throws an exception

[mschulkind]

I'm pretty sure I've narrowed this down to a real fix, but I figured I'd file a bug report instead of a pull request since I'm not super familiar with rails internals.

Here's the error I get, reproduced on 3.2.0 and 3.2.1:

#<NoMethodError: undefined method `empty?' for nil:NilClass>
/home/matt/.rvm/gems/ruby-1.9.2-p290@gojotter/gems/activerecord-3.2.0/lib/active_record/explain.rb:62:in `block (2 levels) in exec_explain'
/home/matt/.rvm/gems/ruby-1.9.2-p290@gojotter/gems/activerecord-3.2.0/lib/active_record/explain.rb:57:in `tap'
/home/matt/.rvm/gems/ruby-1.9.2-p290@gojotter/gems/activerecord-3.2.0/lib/active_record/explain.rb:57:in `block in exec_explain'
/home/matt/.rvm/gems/ruby-1.9.2-p290@gojotter/gems/activerecord-3.2.0/lib/active_record/explain.rb:56:in `map'
/home/matt/.rvm/gems/ruby-1.9.2-p290@gojotter/gems/activerecord-3.2.0/lib/active_record/explain.rb:56:in `exec_explain'
/home/matt/.rvm/gems/ruby-1.9.2-p290@gojotter/gems/activerecord-3.2.0/lib/active_record/explain.rb:32:in `logging_query_plan'

The problem seems to be here:
https://github.com/rails/rails/blob/master/activerecord/lib/active_record/explain.rb#L58
This line only checks if bind is empty?, but not for nil, so it barfs here.

It looks like these queries are generated in two places:
https://github.com/rails/rails/blob/master/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb#L274
https://github.com/rails/rails/blob/master/activerecord/lib/active_record/connection_adapters/abstract/query_cache.rb#L71

The latter doesn't always store a value for binds. This is what causes problems.

[fxn]

@mschulkind we could check if bind is nil in explain.rb, but I'd like first to make sure having a nil value is not telling us there's a bug somewhere else (which would remain covered by such edit). The bindings are in general a collection, and thus normally lack of bindings is expressed as an empty array.

Could you please provide a minimal app that reproduces the issue?

/cc @tenderlove

[mschulkind]

I'll see if I can come up with something if you're still not convinced, but take a look at:

https://github.com/rails/rails/blob/master/activerecord/lib/active_record/connection_adapters/abstract/query_cache.rb#L71

You'll see that the object that makes its way into the queries collection for exec_explain is created on that line. Never is the :bind key filled in. The bug is either here not including :binds or the explain stuff not checking for nil.

I'd guess this is because the cache only stories post-binded queries, so there are never any binds.

You'll find that the queries logged by:
https://github.com/rails/rails/blob/master/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb#L274
DO in fact fill in [] when there are no binds, which is why this doesn't barf on all queries.

Alternatively, I don't fully understand how the QueryCache works, but if the query is cached, why is the explainer ever even coming into play?

[fxn]

@mschulkind I see, yes I think that analysis is enough. Yes, I believe the payload should get the bindings as well, I am fixing it.

[mschulkind]

Awesome. Thanks for the fast fix.

[michaeleconomy]

Thanks! I noticed this, and monkey patched in the new code (while i wait on rails3.2.2).

[fxn]

Sure. Later we disabled EXPLAIN for cached queries. See 1e5cdbd.