_README.md

Summary:

One would expect the before and after checkout callback would wrap checkout or the undlying code that creates a new adapter and assigns it to a pool or assigns an existing one from the pool. The before and after checkout callback actually wraps verify.

Note, the behavior is the same in 5.1.x, 5.2.x, 6.0.x, 6.1.x but the code snippets come from: https://github.com/rails/rails/blob/v6.0.4/activerecord/lib/active_record/connection_adapters/abstract/connection_pool.rb

Therefore, there is no way to instrument diagnostic code BEFORE the actual checkout occurs.

checkout method

def checkout(checkout_timeout = @checkout_timeout)
  checkout_and_verify(acquire_connection(checkout_timeout))
end

checkout callbacks wrap verify!

def checkout_and_verify(c)
  c._run_checkout_callbacks do
    c.verify!
  end
  c
rescue
  remove c
  c.disconnect!
  raise
end

checkout ACTUALLY occurs in try_to_checkout_new_connection from acquire_connection

def acquire_connection(checkout_timeout)
  # NOTE: we rely on <tt>@available.poll</tt> and +try_to_checkout_new_connection+ to
  # +conn.lease+ the returned connection (and to do this in a +synchronized+
  # section). This is not the cleanest implementation, as ideally we would
  # <tt>synchronize { conn.lease }</tt> in this method, but by leaving it to <tt>@available.poll</tt>
  # and +try_to_checkout_new_connection+ we can piggyback on +synchronize+ sections
  # of the said methods and avoid an additional +synchronize+ overhead.
  if conn = @available.poll || try_to_checkout_new_connection
    conn
  else
    reap
    @available.poll(checkout_timeout)
  end
end

def try_to_checkout_new_connection
  # first in synchronized section check if establishing new conns is allowed
  # and increment @now_connecting, to prevent overstepping this pool's @size
  # constraint
  do_checkout = synchronize do
    if @threads_blocking_new_connections.zero? && (@connections.size + @now_connecting) < @size
      @now_connecting += 1
    end
  end
  if do_checkout
    begin
      # if successfully incremented @now_connecting establish new connection
      # outside of synchronized section
      conn = checkout_new_connection
    ensure
      synchronize do
        if conn
          adopt_connection(conn)
          # returned conn needs to be already leased
          conn.lease
        end
        @now_connecting -= 1
      end
    end
  end
end

before_checkout_ar_callback_bug.rb

# frozen_string_literal: true

require "bundler/inline"

gemfile(true) do
  source "https://rubygems.org"

  git_source(:github) { |repo| "https://github.com/#{repo}.git" }

  # Activate the gem you are reporting the issue against.
  gem "activerecord", "~> 5.1.0"
  gem "rails"
  gem "pg"
end

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

class TestApp < Rails::Application
  config.root = __dir__
  config.session_store :cookie_store, key: "cookie_store_key"
  secrets.secret_key_base = "secret_key_base"

  config.logger = Logger.new($stdout)
end

ActiveRecord::ConnectionAdapters::AbstractAdapter.set_callback :checkout, :before, ->(_conn) {
  puts "--- BEFORE CHECKOUT Base#connected?: #{ActiveRecord::Base.connected?}"
  puts "--- BEFORE CHECKOUT Pool#connected?: #{ActiveRecord::Base.connection_pool.connected?}"
  puts "--- BEFORE CHECKOUT stat: #{ActiveRecord::Base.connection_pool.stat.inspect}" if Rails::VERSION::STRING >= "5.1.0"
}

ActiveRecord::ConnectionAdapters::AbstractAdapter.set_callback :checkout, :after, ->(_conn) {
  puts "--- AFTER CHECKOUT Base#connected?: #{ActiveRecord::Base.connected?}"
  puts "--- AFTER CHECKOUT Pool#connected?: #{ActiveRecord::Base.connection_pool.connected?}"
  puts "--- AFTER CHECKOUT stat: #{ActiveRecord::Base.connection_pool.stat.inspect}" if Rails::VERSION::STRING >= "5.1.0"
}

# This connection will do for database-independent bug reports.
ActiveRecord::Base.establish_connection(adapter: "postgresql", database: "test_checkout_callbacks")
puts "--- START: Base#connected?: #{ActiveRecord::Base.connected?}"
ActiveRecord::Base.connection
puts "--- END: Base#connected?: #{ActiveRecord::Base.connected?}"

output_various_rails_versions.txt

$ ruby test_before_checkout_callback.rb | grep -E "activerecord|---"
Using activerecord 6.1.4.1
--- START: Base#connected?: false
--- BEFORE CHECKOUT Base#connected?: true
--- BEFORE CHECKOUT Pool#connected?: true
--- BEFORE CHECKOUT stat: {:size=>5, :connections=>1, :busy=>1, :dead=>0, :idle=>0, :waiting=>0, :checkout_timeout=>5.0}
--- AFTER CHECKOUT Base#connected?: true
--- AFTER CHECKOUT Pool#connected?: true
--- AFTER CHECKOUT stat: {:size=>5, :connections=>1, :busy=>1, :dead=>0, :idle=>0, :waiting=>0, :checkout_timeout=>5.0}
--- END: Base#connected?: true

$ ruby test_before_checkout_callback.rb | grep -E "activerecord|---"
Using activerecord 6.0.4.1
--- START: Base#connected?: false
--- BEFORE CHECKOUT Base#connected?: true
--- BEFORE CHECKOUT Pool#connected?: true
--- BEFORE CHECKOUT stat: {:size=>5, :connections=>1, :busy=>1, :dead=>0, :idle=>0, :waiting=>0, :checkout_timeout=>5}
--- AFTER CHECKOUT Base#connected?: true
--- AFTER CHECKOUT Pool#connected?: true
--- AFTER CHECKOUT stat: {:size=>5, :connections=>1, :busy=>1, :dead=>0, :idle=>0, :waiting=>0, :checkout_timeout=>5}
--- END: Base#connected?: true

$ ruby test_before_checkout_callback.rb | grep -E "activerecord|---"
Using activerecord 5.2.6
--- START: Base#connected?: false
--- BEFORE CHECKOUT Base#connected?: true
--- BEFORE CHECKOUT Pool#connected?: true
--- BEFORE CHECKOUT stat: {:size=>5, :connections=>1, :busy=>1, :dead=>0, :idle=>0, :waiting=>0, :checkout_timeout=>5}
--- AFTER CHECKOUT Base#connected?: true
--- AFTER CHECKOUT Pool#connected?: true
--- AFTER CHECKOUT stat: {:size=>5, :connections=>1, :busy=>1, :dead=>0, :idle=>0, :waiting=>0, :checkout_timeout=>5}
--- END: Base#connected?: true

$ ruby test_before_checkout_callback.rb | grep -E "activerecord|---"
Using activerecord 5.1.7
--- START: Base#connected?: false
--- BEFORE CHECKOUT Base#connected?: true
--- BEFORE CHECKOUT Pool#connected?: true
--- BEFORE CHECKOUT stat: {:size=>5, :connections=>1, :busy=>1, :dead=>0, :idle=>0, :waiting=>0, :checkout_timeout=>5}
--- AFTER CHECKOUT Base#connected?: true
--- AFTER CHECKOUT Pool#connected?: true
--- AFTER CHECKOUT stat: {:size=>5, :connections=>1, :busy=>1, :dead=>0, :idle=>0, :waiting=>0, :checkout_timeout=>5}
--- END: Base#connected?: true