ActiveRecordのissueで再現コードを書くときに発行されたSQLを確認する方法

rails/rails#36895 の挙動を確認してみようかなーと思ったけど、発行されるSQLを確認する方法が分からなかったので調べた。

Rails本体のテストコードだと assert_no_queries が使えるけど、これは外で使えないので。

動いたコード

assert_no_queriesの定義されている場所を git grep 'def assert_no_queries' すると、実装はrails/activerecord/test/cases/test_case.rb に書かれていた。

必要なのはSQLCounterのクラスぐらいなので、これを再現コードにコピペする。

# frozen_string_literal: true

require "bundler/inline"

gemfile(true) do
  source "https://rubygems.org"
  gem "rails", "5.2.3"
  gem "sqlite3"
end

require "active_record"
require "minitest/autorun"
require "logger"

puts
puts "Ruby = #{RUBY_VERSION}"
puts "ActiveRecord.version = #{ActiveRecord.version}"
puts

# This connection will do for database-independent bug reports.
ActiveRecord::Base.establish_connection(adapter: "sqlite3", database: ":memory:")
ActiveRecord::Base.logger = Logger.new(STDOUT)

ActiveRecord::Schema.define do
  create_table(:users, force: true)
  create_table(:posts, force: true) do |t|
    t.references :user
    t.timestamps
  end
end

class User < ActiveRecord::Base
  has_many :posts
  has_many :new_posts,
    -> { where("posts.created_at > ?", 1.week.ago) },
   class_name: "Post"
end

class Post < ActiveRecord::Base
  belongs_to :user
end

require "active_support/notifications"

# refs: activerecord/test/cases/test_case.rb
class SQLCounter
  class << self
    attr_accessor :ignored_sql, :log, :log_all
    def clear_log; self.log = []; self.log_all = []; end
  end

  clear_log

  self.ignored_sql = [/^PRAGMA/, /^SELECT currval/, /^SELECT CAST/, /^SELECT @@IDENTITY/, /^SELECT @@ROWCOUNT/, /^SAVEPOINT/, /^ROLLBACK TO SAVEPOINT/, /^RELEASE SAVEPOINT/, /^SHOW max_identifier_length/, /^BEGIN/, /^COMMIT/]

  # FIXME: this needs to be refactored so specific database can add their own
  # ignored SQL, or better yet, use a different notification for the queries
  # instead examining the SQL content.
  oracle_ignored     = [/^select .*nextval/i, /^SAVEPOINT/, /^ROLLBACK TO/, /^\s*select .* from all_triggers/im, /^\s*select .* from all_constraints/im, /^\s*select .* from all_tab_cols/im, /^\s*select .* from all_sequences/im]
  mysql_ignored      = [/^SHOW FULL TABLES/i, /^SHOW FULL FIELDS/, /^SHOW CREATE TABLE /i, /^SHOW VARIABLES /, /^\s*SELECT (?:column_name|table_name)\b.*\bFROM information_schema\.(?:key_column_usage|tables)\b/im]
  postgresql_ignored = [/^\s*select\b.*\bfrom\b.*pg_namespace\b/im, /^\s*select tablename\b.*from pg_tables\b/im, /^\s*select\b.*\battname\b.*\bfrom\b.*\bpg_attribute\b/im, /^SHOW search_path/i, /^\s*SELECT\b.*::regtype::oid\b/im]
  sqlite3_ignored =    [/^\s*SELECT name\b.*\bFROM sqlite_master/im, /^\s*SELECT sql\b.*\bFROM sqlite_master/im]

  [oracle_ignored, mysql_ignored, postgresql_ignored, sqlite3_ignored].each do |db_ignored_sql|
    ignored_sql.concat db_ignored_sql
  end

  attr_reader :ignore

  def initialize(ignore = Regexp.union(self.class.ignored_sql))
    @ignore = ignore
  end

  def call(name, start, finish, message_id, values)
    return if values[:cached]

    sql = values[:sql]
    self.class.log_all << sql
    self.class.log << sql unless ignore.match?(sql)
  end
end

ActiveSupport::Notifications.subscribe("sql.active_record", SQLCounter.new)

def capture_sql
  SQLCounter.clear_log
  yield
  SQLCounter.log.dup
end

require "active_support/testing/time_helpers"

class BugTest < Minitest::Test
  include ActiveSupport::Testing::TimeHelpers

  def test_to_reproduce
    travel_to Time.new(2019, 8, 10)
    User.create

    log = capture_sql { User.includes(:new_posts).to_a }
    assert_equal 'SELECT "users".* FROM "users"', log[0]
    assert_equal 'SELECT "posts".* FROM "posts" WHERE (posts.created_at > \'2019-08-02 15:00:00\') AND "posts"."user_id" = ?', log[1]
  end
end

includes に関する挙動は to_sql だと確認できないので、そういうバグを踏んだときに使えるようにメモしておく。