SJH SJH - 10 months ago 42
Ruby Question

Blocks and call scope in irb behaving inconsistantly

I've been experimenting with some of the internal rails code in Rails 4.2.7 with spring preloader and found some odd behavior of stack dumps in irb.

Consider the following code

def run_block

class Vehicle < ActiveRecord::Base
def self.instantiate(*args)
puts caller_locations

def self.test_stack
run_block {Vehicle.all}

notice that I'm extending the functionality of the instantiate function ( to print out the call stack.

When I open a rails c console and run

run_block {puts caller_locations}

I get the stack trace

test_irb/app/models/vehicle.rb:2:in `run_block'
(irb):4:in `irb_binding'
.rvm/rubies/ruby-head/lib/ruby/2.4.0/irb/workspace.rb:87:in `eval'
.rvm/rubies/ruby-head/lib/ruby/2.4.0/irb/workspace.rb:87:in `evaluate'
.rvm/rubies/ruby-head/lib/ruby/2.4.0/irb/context.rb:380:in `evaluate'
.rvm/rubies/ruby-head/lib/ruby/2.4.0/irb.rb:489:in `block (2 levels) in eval_input'
.rvm/rubies/ruby-head/lib/ruby/2.4.0/irb.rb:623:in `signal_status'
.rvm/rubies/ruby-head/lib/ruby/2.4.0/irb.rb:486:in `block in eval_input'
.rvm/rubies/ruby-head/lib/ruby/2.4.0/irb/ruby-lex.rb:246:in `block (2 levels) in each_top_level_statement'
.rvm/rubies/ruby-head/lib/ruby/2.4.0/irb/ruby-lex.rb:232:in `loop'
.rvm/rubies/ruby-head/lib/ruby/2.4.0/irb/ruby-lex.rb:232:in `block in each_top_level_statement'
.rvm/rubies/ruby-head/lib/ruby/2.4.0/irb/ruby-lex.rb:231:in `catch'
.rvm/rubies/ruby-head/lib/ruby/2.4.0/irb/ruby-lex.rb:231:in `each_top_level_statement'
.rvm/rubies/ruby-head/lib/ruby/2.4.0/irb.rb:485:in `eval_input'
.rvm/rubies/ruby-head/lib/ruby/2.4.0/irb.rb:395:in `block in start'
.rvm/rubies/ruby-head/lib/ruby/2.4.0/irb.rb:394:in `catch'
.rvm/rubies/ruby-head/lib/ruby/2.4.0/irb.rb:394:in `start'

But running (assuming I have some rows in the db)

run_block {Vehicle.all}

I get the stack trace

.rvm/gems/ruby-head/gems/activerecord-4.2.7/lib/active_record/querying.rb:50:in `block (2 levels) in find_by_sql'
.rvm/gems/ruby-head/gems/activerecord-4.2.7/lib/active_record/result.rb:51:in `block in each'
.rvm/gems/ruby-head/gems/activerecord-4.2.7/lib/active_record/result.rb:51:in `each'
.rvm/gems/ruby-head/gems/activerecord-4.2.7/lib/active_record/result.rb:51:in `each'
.rvm/gems/ruby-head/gems/activerecord-4.2.7/lib/active_record/querying.rb:50:in `map'
.rvm/gems/ruby-head/gems/activerecord-4.2.7/lib/active_record/querying.rb:50:in `block in find_by_sql'
.rvm/gems/ruby-head/gems/activesupport-4.2.7/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
.rvm/gems/ruby-head/gems/activerecord-4.2.7/lib/active_record/querying.rb:49:in `find_by_sql'
.rvm/gems/ruby-head/gems/activerecord-4.2.7/lib/active_record/relation.rb:639:in `exec_queries'
.rvm/gems/ruby-head/gems/activerecord-4.2.7/lib/active_record/relation.rb:515:in `load'
.rvm/gems/ruby-head/gems/activerecord-4.2.7/lib/active_record/relation.rb:243:in `to_a'
.rvm/gems/ruby-head/gems/activerecord-4.2.7/lib/active_record/relation.rb:630:in `inspect'
.rvm/rubies/ruby-head/lib/ruby/2.4.0/irb/inspector.rb:109:in `block in <module:IRB>'
.rvm/rubies/ruby-head/lib/ruby/2.4.0/irb/inspector.rb:102:in `inspect_value'
.rvm/rubies/ruby-head/lib/ruby/2.4.0/irb/context.rb:384:in `inspect_last_value'
.rvm/rubies/ruby-head/lib/ruby/2.4.0/irb.rb:661:in `output_value'
.rvm/rubies/ruby-head/lib/ruby/2.4.0/irb.rb:490:in `block (2 levels) in eval_input'
.rvm/rubies/ruby-head/lib/ruby/2.4.0/irb.rb:623:in `signal_status'

which does not show that the block was nested in the
method anywhere in the trace. Running
run_block {puts Vehicle.all}
however does show the run_block function in the stack trace. As well, running
in the block shows the expected stack trace. Yet
defined above shows neither the
method nor the
method in the stack trace. Can anybody explain this inconsistency? Is this a result of ruby language constructs or something with the implementation of the
method? Thanks all!

Answer Source

This is a tricky one. The instantiate stack trace doesn't show run_block because instantiate isn't called from within run_block.

Here's the deal: when you call Vehicle.all, it doesn't return an array of Vehicle objects, each of which has been instantiated; it just returns an ActiveRecord::Relation object that represents the query yet to be run. Since that's the last expression in the block passed to run_block, it's the return value of the block, and since yield is the last statement in run_block, the ActiveRecord::Relation object is also the return value of that method.

However, when you call a method from IRB, it prints what was returned, in the form of the the results of calling Object#inspect on it, and when you call inspect on an ActiveRecord::Relation object, it tries to include in the output the strings that represent each object in the relation. In order to do that, it has to actually run the query and instantiate the Model objects, so it does, and your instantiate override is finally called. But that's after the run_block block has already exited!

Indeed, if you ran (in IRB) run_block {Vehicle.all} ; nil on a single line, IRB would print nil as the result of evaluating that, and your instantiate method would never be called at all.

When you use run_block { puts Vehicle.all }, then the Relation object has be actual realized for the puts, which takes place inside the block so in that case you do see run_block in the stack trace.