SO - Unexpected behavior with ActiveRecord includes

includes_test_gist.rb

# create the 'test123' database on the Postgres DB and run this gist

require 'bundler'
Bundler.setup(:default)

require 'active_record'
require 'minitest/autorun'
require 'logger'

ActiveRecord::Base.establish_connection(adapter: 'postgresql', database: 'test123')
ActiveRecord::Base.logger = Logger.new(STDOUT)

ActiveRecord::Schema.define do
  create_table :users, force: true do |t|
    t.integer :residence_id
  end

  create_table :buildings, force: true do |t|
  end
end

class User < ActiveRecord::Base
  belongs_to :building, foreign_key: :residence_id
end

class Building < ActiveRecord::Base
end

class BugTest < Minitest::Test
  def test_include
    b1 = Building.create!
    b2 = Building.create!

    u1 = User.create!(residence_id: b1.id) # existing building
    u2 = User.create!(residence_id: b2.id) # existing building
    u3 = User.create!(residence_id: nil)   # no building
    u4 = User.create!(residence_id: 123)   # non-existent building

    users = User.includes(:building).references(:buildings)
    users.each do | user |
      if user.building
        puts "User #{user.id} has building"
      else
        puts "User #{user.id} has no building"
      end
    end
  end
end


## Running this on my system with Rails 4.2.6 shows NO additional queries:
##
## -- create_table(:users, {:force=>true})
## D, [2016-05-26T11:01:18.286123 #520] DEBUG -- :    (2.5ms)  DROP TABLE "users"
## D, [2016-05-26T11:01:18.291695 #520] DEBUG -- :    (5.3ms)  CREATE TABLE "users" ("id" serial primary key, "residence_id" integer) 
##    -> 0.0187s
## -- create_table(:buildings, {:force=>true})
## D, [2016-05-26T11:01:18.294255 #520] DEBUG -- :    (1.7ms)  DROP TABLE "buildings"
## D, [2016-05-26T11:01:18.299402 #520] DEBUG -- :    (5.0ms)  CREATE TABLE "buildings" ("id" serial primary key) 
##    -> 0.0077s
## Run options: --seed 62051
## ## 
## # Running:
## ## 
## D, [2016-05-26T11:01:18.330218 #520] DEBUG -- :    (0.1ms)  BEGIN
## D, [2016-05-26T11:01:18.332420 #520] DEBUG -- :   SQL (0.4ms)  INSERT INTO "buildings" DEFAULT VALUES RETURNING "id"
## D, [2016-05-26T11:01:18.334349 #520] DEBUG -- :    (1.4ms)  COMMIT
## D, [2016-05-26T11:01:18.334877 #520] DEBUG -- :    (0.2ms)  BEGIN
## D, [2016-05-26T11:01:18.336452 #520] DEBUG -- :   SQL (0.5ms)  INSERT INTO "buildings" DEFAULT VALUES RETURNING "id"
## D, [2016-05-26T11:01:18.338158 #520] DEBUG -- :    (1.2ms)  COMMIT
## D, [2016-05-26T11:01:18.341224 #520] DEBUG -- :    (0.2ms)  BEGIN
## D, [2016-05-26T11:01:18.344243 #520] DEBUG -- :   SQL (0.3ms)  INSERT INTO "users" ("residence_id") VALUES ($1) RETURNING "id"  [["residence_id", 1]]
## D, [2016-05-26T11:01:18.345869 #520] DEBUG -- :    (1.3ms)  COMMIT
## D, [2016-05-26T11:01:18.347477 #520] DEBUG -- :    (0.3ms)  BEGIN
## D, [2016-05-26T11:01:18.350376 #520] DEBUG -- :   SQL (0.8ms)  INSERT INTO "users" ("residence_id") VALUES ($1) RETURNING "id"  [["residence_id", 2]]
## D, [2016-05-26T11:01:18.353192 #520] DEBUG -- :    (1.7ms)  COMMIT
## D, [2016-05-26T11:01:18.353480 #520] DEBUG -- :    (0.1ms)  BEGIN
## D, [2016-05-26T11:01:18.353983 #520] DEBUG -- :   SQL (0.1ms)  INSERT INTO "users" DEFAULT VALUES RETURNING "id"
## D, [2016-05-26T11:01:18.355508 #520] DEBUG -- :    (1.3ms)  COMMIT
## D, [2016-05-26T11:01:18.355838 #520] DEBUG -- :    (0.1ms)  BEGIN
## D, [2016-05-26T11:01:18.356343 #520] DEBUG -- :   SQL (0.1ms)  INSERT INTO "users" ("residence_id") VALUES ($1) RETURNING "id"  [["residence_id", 123]]
## D, [2016-05-26T11:01:18.357753 #520] DEBUG -- :    (1.2ms)  COMMIT
## D, [2016-05-26T11:01:18.363311 #520] DEBUG -- :   SQL (0.4ms)  SELECT "users"."id" AS t0_r0, "users"."residence_id" AS t0_r1, "buildings"."id" AS t1_r0 FROM "users" LEFT OUTER JOIN "buildings" ON "buildings"."id" = "users"."residence_id"
## User 1 has building
## User 2 has building
## User 3 has no building
## User 4 has no building
## .
## ## 
## Finished in 0.042975s, 23.2695 runs/s, 0.0000 assertions/s.
## ## 
## 1 runs, 0 assertions, 0 failures, 0 errors, 0 skips