Add QueryLogTags to Rails

Co-authored-by: Eileen M. Uchitelle <eileencodes@users.noreply.github.com>
Co-authored-by: Kasper Timm Hansen <kaspth@gmail.com>
This commit is contained in:
Keeran Raj Hawoldar 2021-03-08 10:51:29 +00:00
parent 843c0a3fcd
commit 2408615154
9 changed files with 782 additions and 0 deletions

View File

@ -86,5 +86,35 @@ module ActionController
ActionController::Metal.descendants.each(&:action_methods) if config.eager_load
end
end
initializer "action_controller.query_log_tags" do |app|
ActiveSupport.on_load(:action_controller_base) do
singleton_class.attr_accessor :log_query_tags_around_actions
self.log_query_tags_around_actions = true
end
ActiveSupport.on_load(:active_record) do
if app.config.active_record.query_log_tags_enabled && app.config.action_controller.log_query_tags_around_actions != false
ActiveRecord::QueryLogs.taggings.merge! \
controller: -> { context[:controller]&.controller_name },
action: -> { context[:controller]&.action_name },
namespaced_controller: -> { context[:controller]&.class&.name }
ActiveRecord::QueryLogs.tags << :controller << :action
context_extension = ->(controller) do
around_action :expose_controller_to_query_logs
private
def expose_controller_to_query_logs(&block)
ActiveRecord::QueryLogs.set_context(controller: self, &block)
end
end
ActionController::Base.class_eval(&context_extension)
ActionController::API.class_eval(&context_extension)
end
end
end
end
end

View File

@ -49,5 +49,28 @@ module ActiveJob
end
end
end
initializer "active_job.query_log_tags" do |app|
ActiveSupport.on_load(:active_job) do
singleton_class.attr_accessor :log_query_tags_around_perform
self.log_query_tags_around_perform = true
end
ActiveSupport.on_load(:active_record) do
if app.config.active_record.query_log_tags_enabled && app.config.active_job.log_query_tags_around_perform != false
ActiveRecord::QueryLogs.taggings[:job] = -> { context[:job]&.class&.name }
ActiveRecord::QueryLogs.tags << :job
ActiveJob::Base.class_eval do
around_perform :expose_job_to_query_logs
private
def expose_job_to_query_logs(&block)
ActiveRecord::QueryLogs.set_context(job: self, &block)
end
end
end
end
end
end
end

View File

@ -1,3 +1,47 @@
* Add `ActiveRecord::QueryLogs`.
Configurable tags can be automatically added to all SQL queries generated by Active Record.
```ruby
# config/application.rb
module MyApp
class Application < Rails::Application
config.active_record.query_log_tags_enabled = true
end
end
```
By default the application, controller and action details are added to the query tags:
```ruby
class BooksController < ApplicationController
def index
@books = Book.all
end
end
```
```ruby
GET /books
# SELECT * FROM books /*application:MyApp;controller:books;action:index*/
```
Custom tags containing static values and Procs can be defined in the application configuration:
```ruby
config.active_record.query_log_tags = [
:application,
:controller,
:action,
{
custom_static: "foo",
custom_dynamic: -> { Time.now }
}
]
```
*Keeran Raj Hawoldar*, *Eileen M. Uchitelle*, *Kasper Timm Hansen*
* Added support for multiple databases to `rails db:setup` and `rails db:reset`.
*Ryan Hall*

View File

@ -58,6 +58,7 @@ module ActiveRecord
autoload :Persistence
autoload :QueryCache
autoload :Querying
autoload :QueryLogs
autoload :ReadonlyAttributes
autoload :RecordInvalid, "active_record/validations"
autoload :Reflection
@ -322,6 +323,51 @@ module ActiveRecord
singleton_class.attr_accessor :verify_foreign_keys_for_fixtures
self.verify_foreign_keys_for_fixtures = false
##
# :singleton-method:
# Specify whether or not to enable adapter-level query comments.
# To enable:
#
# config.active_record.query_log_tags_enabled = true
#
# When included in +ActionController+, controller context is automatically updated via an
# +around_action+ filter. This behaviour can be disabled as follows:
#
# config.action_controller.log_query_tags_around_actions = false
#
# This behaviour can be disabled for +ActiveJob+ in a similar way:
#
# config.active_job.log_query_tags_around_perform = false
singleton_class.attr_accessor :query_log_tags_enabled
self.query_log_tags_enabled = false
##
# :singleton-method:
# An +Array+ specifying the key/value tags to be inserted in an SQL comment. Defaults to `[ :application ]`, a
# predefined tag returning the application name.
#
# Custom values can be passed in as a +Hash+:
#
# config.active_record.query_log_tags = [ :application, { custom: 'value' } ]
#
# See +ActiveRecord::QueryLogs+ for more details
# on predefined tags and defining new tag content.
singleton_class.attr_accessor :query_log_tags
self.query_log_tags = [ :application ]
##
# :singleton-method:
# Specify whether or not to enable caching of query log tags.
# For applications that have a large number of queries, caching query log tags can
# provide a performance benefit when the context does not change during the lifetime
# of the request or job execution.
#
# To enable:
#
# config.active_record.cache_query_log_tags = true
singleton_class.attr_accessor :cache_query_log_tags
self.cache_query_log_tags = false
def self.eager_load!
super
ActiveRecord::Locking.eager_load!

View File

@ -55,6 +55,10 @@ module ActiveRecord
configuration_hash[:host]
end
def socket # :nodoc:
configuration_hash[:socket]
end
def database
configuration_hash[:database]
end

View File

@ -0,0 +1,187 @@
# frozen_string_literal: true
require "active_support/core_ext/module/attribute_accessors_per_thread"
module ActiveRecord
# = Active Record Query Logs
#
# Automatically tag SQL queries with runtime information.
#
# Default tags available for use:
#
# * +application+
# * +pid+
# * +socket+
# * +db_host+
# * +database+
#
# _Action Controller and Active Job tags are also defined when used in Rails:_
#
# * +controller+
# * +action+
# * +job+
#
# The tags used in a query can be configured directly:
#
# ActiveRecord::QueryLogs.tags = [ :application, :controller, :action, :job ]
#
# or via Rails configuration:
#
# config.active_record.query_log_tags = [ :application, :controller, :action, :job ]
#
# To add new comment tags, add a hash to the tags array containing the keys and values you
# want to add to the comment. Dynamic content can be created by setting a proc or lambda value in a hash,
# and can reference any value stored in the +context+ object.
#
# Example:
#
# tags = [
# :application,
# { custom_tag: -> { context[:controller].controller_name } }
# ]
# ActiveRecord::QueryLogs.tags = tags
#
# The QueryLogs +context+ can be manipulated via +update_context+ & +set_context+ methods.
#
# Direct updates to a context value:
#
# ActiveRecord::QueryLogs.update_context(foo: Bar.new)
#
# Temporary updates limited to the execution of a block:
#
# ActiveRecord::QueryLogs.set_context(foo: Bar.new) do
# posts = Post.all
# end
#
# Tag comments can be prepended to the query:
#
# ActiveRecord::QueryLogs.prepend_comment = true
#
# For applications where the content will not change during the lifetime of
# the request or job execution, the tags can be cached for reuse in every query:
#
# ActiveRecord::QueryLogs.cache_query_log_tags = true
#
# This option can be set during application configuration or in a Rails initializer:
#
# config.active_record.cache_query_log_tags = true
module QueryLogs
mattr_accessor :taggings, instance_accessor: false, default: {}
mattr_accessor :tags, instance_accessor: false, default: [ :application ]
mattr_accessor :prepend_comment, instance_accessor: false, default: false
mattr_accessor :cache_query_log_tags, instance_accessor: false, default: false
thread_mattr_accessor :cached_comment, instance_accessor: false
class << self
# Updates the context used to construct tags in the SQL comment.
# Resets the cached comment if <tt>cache_query_log_tags</tt> is +true+.
def update_context(**options)
context.merge!(**options.symbolize_keys)
self.cached_comment = nil
end
# Updates the context used to construct tags in the SQL comment during
# execution of the provided block. Resets provided values to nil after
# the block is executed.
def set_context(**options)
update_context(**options)
yield if block_given?
ensure
update_context(**options.transform_values! { nil })
end
# Temporarily tag any query executed within `&block`. Can be nested.
def with_tag(tag, &block)
inline_tags.push(tag)
yield if block_given?
ensure
inline_tags.pop
end
def add_query_log_tags_to_sql(sql) # :nodoc:
comments.each do |comment|
unless sql.include?(comment)
sql = prepend_comment ? "#{comment} #{sql}" : "#{sql} #{comment}"
end
end
sql
end
private
# Returns an array of comments which need to be added to the query, comprised
# of configured and inline tags.
def comments
[ comment, inline_comment ].compact
end
# Returns an SQL comment +String+ containing the query log tags.
# Sets and returns a cached comment if <tt>cache_query_log_tags</tt> is +true+.
def comment
if cache_query_log_tags
self.cached_comment ||= uncached_comment
else
uncached_comment
end
end
def uncached_comment
content = tag_content
if content.present?
"/*#{escape_sql_comment(content)}*/"
end
end
# Returns a +String+ containing any inline comments from +with_tag+.
def inline_comment
return nil unless inline_tags.present?
"/*#{escape_sql_comment(inline_tag_content)}*/"
end
# Return the set of active inline tags from +with_tag+.
def inline_tags
context[:inline_tags] ||= []
end
def context
Thread.current[:active_record_query_log_tags_context] ||= {}
end
def escape_sql_comment(content)
content.to_s.gsub(%r{ (/ (?: | \g<1>) \*) \+? \s* | \s* (\* (?: | \g<2>) /) }x, "")
end
def tag_content
tags.flat_map { |i| [*i] }.filter_map do |tag|
key, value_input = tag
val = case value_input
when nil then instance_exec(&taggings[key]) if taggings.has_key? key
when Proc then instance_exec(&value_input)
else value_input
end
"#{key}:#{val}" unless val.nil?
end.join(",")
end
def inline_tag_content
inline_tags.join
end
end
module ExecutionMethods
def execute(sql, *args, **kwargs)
super(ActiveRecord::QueryLogs.add_query_log_tags_to_sql(sql), *args, **kwargs)
end
def exec_query(sql, *args, **kwargs)
super(ActiveRecord::QueryLogs.add_query_log_tags_to_sql(sql), *args, **kwargs)
end
end
end
end
ActiveSupport.on_load(:active_record) do
ActiveRecord::QueryLogs.taggings.merge! \
socket: -> { ActiveRecord::Base.connection_db_config.socket },
db_host: -> { ActiveRecord::Base.connection_db_config.host },
database: -> { ActiveRecord::Base.connection_db_config.database }
end

View File

@ -339,5 +339,29 @@ To keep using the current cache store, you can turn off cache versioning entirel
end
end
end
initializer "active_record.query_log_tags_config" do |app|
config.after_initialize do
if app.config.active_record.query_log_tags_enabled
ActiveRecord::QueryLogs.taggings.merge! \
application: -> { @application_name ||= Rails.application.class.name.split("::").first },
pid: -> { Process.pid }
if app.config.active_record.query_log_tags.present?
ActiveRecord::QueryLogs.tags = app.config.active_record.query_log_tags
end
if app.config.active_record.cache_query_log_tags
ActiveRecord::QueryLogs.cache_query_log_tags = true
end
ActiveSupport.on_load(:active_record) do
ConnectionAdapters::AbstractAdapter.descendants.each do |klass|
klass.prepend(QueryLogs::ExecutionMethods) if klass.descendants.empty?
end
end
end
end
end
end
end

View File

@ -0,0 +1,261 @@
# frozen_string_literal: true
require "cases/helper"
require "models/dashboard"
class QueryLogsTest < ActiveRecord::TestCase
fixtures :dashboards
ActiveRecord::QueryLogs.taggings[:application] = -> {
"active_record"
}
def setup
@original_enabled = ActiveRecord.query_log_tags_enabled
ActiveRecord.query_log_tags_enabled = true
if @original_enabled == false
# if we haven't enabled the feature, the execution methods need to be prepended at run time
ActiveRecord::Base.connection.class_eval do
prepend(ActiveRecord::QueryLogs::ExecutionMethods)
end
end
@original_prepend = ActiveRecord::QueryLogs.prepend_comment
ActiveRecord::QueryLogs.prepend_comment = false
ActiveRecord::QueryLogs.cache_query_log_tags = false
ActiveRecord::QueryLogs.cached_comment = nil
end
def teardown
ActiveRecord.query_log_tags_enabled = @original_enabled
ActiveRecord::QueryLogs.prepend_comment = @original_prepend
ActiveRecord::QueryLogs.tags = []
end
def test_escaping_good_comment
assert_equal "app:foo", ActiveRecord::QueryLogs.send(:escape_sql_comment, "app:foo")
end
def test_escaping_bad_comments
assert_equal "; DROP TABLE USERS;", ActiveRecord::QueryLogs.send(:escape_sql_comment, "*/; DROP TABLE USERS;/*")
assert_equal "; DROP TABLE USERS;", ActiveRecord::QueryLogs.send(:escape_sql_comment, "**//; DROP TABLE USERS;/*")
end
def test_basic_commenting
ActiveRecord::QueryLogs.tags = [ :application ]
assert_sql(%r{select id from posts /\*application:active_record\*/$}) do
ActiveRecord::Base.connection.execute "select id from posts"
end
end
def test_add_comments_to_beginning_of_query
ActiveRecord::QueryLogs.tags = [ :application ]
ActiveRecord::QueryLogs.prepend_comment = true
assert_sql(%r{/\*application:active_record\*/ select id from posts$}) do
ActiveRecord::Base.connection.execute "select id from posts"
end
ensure
ActiveRecord::QueryLogs.prepend_comment = nil
end
def test_exists_is_commented
ActiveRecord::QueryLogs.tags = [ :application ]
assert_sql(%r{/\*application:active_record\*/}) do
Dashboard.exists?
end
end
def test_delete_is_commented
ActiveRecord::QueryLogs.tags = [ :application ]
record = Dashboard.first
assert_sql(%r{/\*application:active_record\*/}) do
record.destroy
end
end
def test_update_is_commented
ActiveRecord::QueryLogs.tags = [ :application ]
assert_sql(%r{/\*application:active_record\*/}) do
dash = Dashboard.first
dash.name = "New name"
dash.save
end
end
def test_create_is_commented
ActiveRecord::QueryLogs.tags = [ :application ]
assert_sql(%r{/\*application:active_record\*/}) do
Dashboard.create(name: "Another dashboard")
end
end
def test_select_is_commented
ActiveRecord::QueryLogs.tags = [ :application ]
assert_sql(%r{/\*application:active_record\*/}) do
Dashboard.all.to_a
end
end
def test_retrieves_comment_from_cache_when_enabled_and_set
ActiveRecord::QueryLogs.cache_query_log_tags = true
ActiveRecord::QueryLogs.tags = [ :application ]
assert_equal " /*application:active_record*/", ActiveRecord::QueryLogs.add_query_log_tags_to_sql("")
ActiveRecord::QueryLogs.stub(:cached_comment, "/*cached_comment*/") do
assert_equal " /*cached_comment*/", ActiveRecord::QueryLogs.add_query_log_tags_to_sql("")
end
ensure
ActiveRecord::QueryLogs.cached_comment = nil
ActiveRecord::QueryLogs.cache_query_log_tags = false
end
def test_resets_cache_on_context_update
ActiveRecord::QueryLogs.cache_query_log_tags = true
ActiveRecord::QueryLogs.update_context(temporary: "value")
ActiveRecord::QueryLogs.tags = [ temporary_tag: -> { context[:temporary] } ]
assert_equal " /*temporary_tag:value*/", ActiveRecord::QueryLogs.add_query_log_tags_to_sql("")
ActiveRecord::QueryLogs.update_context(temporary: "new_value")
assert_nil ActiveRecord::QueryLogs.cached_comment
assert_equal " /*temporary_tag:new_value*/", ActiveRecord::QueryLogs.add_query_log_tags_to_sql("")
ensure
ActiveRecord::QueryLogs.cached_comment = nil
ActiveRecord::QueryLogs.cache_query_log_tags = false
end
def test_ensure_context_has_symbol_keys
ActiveRecord::QueryLogs.tags = [ new_key: -> { context[:symbol_key] } ]
ActiveRecord::QueryLogs.update_context("symbol_key" => "symbolized")
assert_sql(%r{/\*new_key:symbolized}) do
Dashboard.first
end
ensure
ActiveRecord::QueryLogs.update_context(application_name: nil)
end
def test_inline_tags_only_affect_block
# disable regular comment tags
ActiveRecord::QueryLogs.tags = []
# confirm single inline tag
assert_sql(%r{/\*foo\*/$}) do
ActiveRecord::QueryLogs.with_tag("foo") do
Dashboard.first
end
end
# confirm different inline tag
assert_sql(%r{/\*bar\*/$}) do
ActiveRecord::QueryLogs.with_tag("bar") do
Dashboard.first
end
end
# confirm no tags are persisted
ActiveRecord::QueryLogs.tags = [ :application ]
assert_sql(%r{/\*application:active_record\*/$}) do
Dashboard.first
end
ensure
ActiveRecord::QueryLogs.tags = [ :application ]
end
def test_nested_inline_tags
assert_sql(%r{/\*foobar\*/$}) do
ActiveRecord::QueryLogs.with_tag("foo") do
ActiveRecord::QueryLogs.with_tag("bar") do
Dashboard.first
end
end
end
end
def test_bad_inline_tags
assert_sql(%r{/\*; DROP TABLE USERS;\*/$}) do
ActiveRecord::QueryLogs.with_tag("*/; DROP TABLE USERS;/*") do
Dashboard.first
end
end
assert_sql(%r{/\*; DROP TABLE USERS;\*/$}) do
ActiveRecord::QueryLogs.with_tag("**//; DROP TABLE USERS;//**") do
Dashboard.first
end
end
end
def test_inline_tags_are_deduped
ActiveRecord::QueryLogs.tags = [ :application ]
assert_sql(%r{select id from posts /\*foo\*/ /\*application:active_record\*/$}) do
ActiveRecord::QueryLogs.with_tag("foo") do
ActiveRecord::Base.connection.execute "select id from posts /*foo*/"
end
end
end
def test_empty_comments_are_not_added
original_tags = ActiveRecord::QueryLogs.tags
ActiveRecord::QueryLogs.tags = [ empty: -> { nil } ]
assert_sql(%r{select id from posts$}) do
ActiveRecord::Base.connection.execute "select id from posts"
end
ensure
ActiveRecord::QueryLogs.tags = original_tags
end
def test_custom_basic_tags
original_tags = ActiveRecord::QueryLogs.tags
ActiveRecord::QueryLogs.tags = [ :application, { custom_string: "test content" } ]
assert_sql(%r{/\*application:active_record,custom_string:test content\*/$}) do
Dashboard.first
end
ensure
ActiveRecord::QueryLogs.tags = original_tags
end
def test_custom_proc_tags
original_tags = ActiveRecord::QueryLogs.tags
ActiveRecord::QueryLogs.tags = [ :application, { custom_proc: -> { "test content" } } ]
assert_sql(%r{/\*application:active_record,custom_proc:test content\*/$}) do
Dashboard.first
end
ensure
ActiveRecord::QueryLogs.tags = original_tags
end
def test_multiple_custom_tags
original_tags = ActiveRecord::QueryLogs.tags
ActiveRecord::QueryLogs.tags = [ :application, { custom_proc: -> { "test content" }, another_proc: -> { "more test content" } } ]
assert_sql(%r{/\*application:active_record,custom_proc:test content,another_proc:more test content\*/$}) do
Dashboard.first
end
ensure
ActiveRecord::QueryLogs.tags = original_tags
end
def test_custom_proc_context_tags
original_tags = ActiveRecord::QueryLogs.tags
ActiveRecord::QueryLogs.update_context(foo: "bar")
ActiveRecord::QueryLogs.tags = [ :application, { custom_context_proc: -> { context[:foo] } } ]
assert_sql(%r{/\*application:active_record,custom_context_proc:bar\*/$}) do
Dashboard.first
end
ensure
ActiveRecord::QueryLogs.update_context(foo: nil)
ActiveRecord::QueryLogs.tags = original_tags
end
end

View File

@ -0,0 +1,163 @@
# frozen_string_literal: true
require "isolation/abstract_unit"
require "rack/test"
module ApplicationTests
class QueryLogsTest < ActiveSupport::TestCase
include ActiveSupport::Testing::Isolation
include Rack::Test::Methods
def setup
build_app
app_file "app/models/user.rb", <<-RUBY
class User < ActiveRecord::Base
end
RUBY
app_file "app/controllers/users_controller.rb", <<-RUBY
class UsersController < ApplicationController
def index
render inline: ActiveRecord::QueryLogs.add_query_log_tags_to_sql("")
end
def dynamic_content
Time.now.to_f
end
end
RUBY
app_file "app/jobs/user_job.rb", <<-RUBY
class UserJob < ActiveJob::Base
def perform
ActiveRecord::QueryLogs.add_query_log_tags_to_sql("")
end
def dynamic_content
Time.now.to_f
end
end
RUBY
app_file "config/routes.rb", <<-RUBY
Rails.application.routes.draw do
get "/", to: "users#index"
end
RUBY
end
def teardown
teardown_app
end
def app
@app ||= Rails.application
end
test "does not modify the query execution path by default" do
boot_app
assert_equal ActiveRecord::Base.connection.method(:execute).owner, ActiveRecord::ConnectionAdapters::SQLite3::DatabaseStatements
end
test "prepends the query execution path when enabled" do
add_to_config "config.active_record.query_log_tags_enabled = true"
boot_app
assert_equal ActiveRecord::Base.connection.method(:execute).owner, ActiveRecord::QueryLogs::ExecutionMethods
end
test "controller and job tags are defined by default" do
add_to_config "config.active_record.query_log_tags_enabled = true"
boot_app
assert_equal ActiveRecord::QueryLogs.tags, [ :application, :controller, :action, :job ]
end
test "controller actions have tagging filters enabled by default" do
add_to_config "config.active_record.query_log_tags_enabled = true"
boot_app
get "/"
comment = last_response.body.strip
assert_includes comment, "controller:users"
end
test "controller actions tagging filters can be disabled" do
add_to_config "config.active_record.query_log_tags_enabled = true"
add_to_config "config.action_controller.log_query_tags_around_actions = false"
boot_app
get "/"
comment = last_response.body.strip
assert_not_includes comment, "controller:users"
end
test "job perform method has tagging filters enabled by default" do
add_to_config "config.active_record.query_log_tags_enabled = true"
boot_app
comment = UserJob.new.perform_now
assert_includes comment, "UserJob"
end
test "job perform method tagging filters can be disabled" do
add_to_config "config.active_record.query_log_tags_enabled = true"
add_to_config "config.active_job.log_query_tags_around_perform = false"
boot_app
comment = UserJob.new.perform_now
assert_not_includes comment, "UserJob"
end
test "query cache is cleared between requests" do
add_to_config "config.active_record.query_log_tags_enabled = true"
add_to_config "config.active_record.cache_query_log_tags = true"
add_to_config "config.active_record.query_log_tags = [ { dynamic: -> { context[:controller].dynamic_content } } ]"
boot_app
get "/"
first_tags = last_response.body
get "/"
second_tags = last_response.body
assert_not_equal first_tags, second_tags
end
test "query cache is cleared between job executions" do
add_to_config "config.active_record.query_log_tags_enabled = true"
add_to_config "config.active_record.cache_query_log_tags = true"
add_to_config "config.active_record.query_log_tags = [ { dynamic: -> { context[:job].dynamic_content } } ]"
boot_app
first_tags = UserJob.new.perform_now
second_tags = UserJob.new.perform_now
assert_not_equal first_tags, second_tags
end
private
def boot_app(env = "production")
ENV["RAILS_ENV"] = env
require "#{app_path}/config/environment"
ensure
ENV.delete "RAILS_ENV"
end
end
end