Payload names for 'sql.active_record' instrumentation

[jagthedrummer]

Steps to reproduce

Here's an executable test case:

# frozen_string_literal: true

begin
  require "bundler/inline"
rescue LoadError => e
  $stderr.puts "Bundler version 1.10 or later is required. Please update your Bundler"
  raise e
end

gemfile(true) do
  source "https://rubygems.org"
  # Activate the gem you are reporting the issue against.
  gem "activerecord", "5.1.0"
  gem "sqlite3"
end

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

# Ensure backward compatibility with Minitest 4
Minitest::Test = MiniTest::Unit::TestCase unless defined?(Minitest::Test)

# 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 :posts, force: true do |t|
    t.string :name
  end
end

class Post < ActiveRecord::Base
  has_many :comments
end

class BugTest < Minitest::Test
  def setup
    ActiveSupport::Notifications.unsubscribe("sql.active_record")
  end

  def test_payload_name_for_post_load
    post = Post.create!

    ActiveSupport::Notifications.subscribe "sql.active_record" do |*args|
      event = ActiveSupport::Notifications::Event.new *args
      if event.payload[:sql].match  "SELECT"
        assert_equal "Post Load", event.payload[:name]
      end
    end

    Post.first
  end

  def test_payload_name_for_post_create
    ActiveSupport::Notifications.subscribe "sql.active_record" do |*args|
      event = ActiveSupport::Notifications::Event.new *args
      if event.payload[:sql].match  "INSERT"
        assert_equal "Post Create", event.payload[:name]
      end
    end

    post = Post.create!
  end

  def test_payload_name_for_post_update
    post = Post.create!

    ActiveSupport::Notifications.subscribe "sql.active_record" do |*args|
      event = ActiveSupport::Notifications::Event.new *args
      if event.payload[:sql].match  "UPDATE"
        assert_equal "Post Update", event.payload[:name]
      end
    end

    post.update_attribute(:name, 'new name')
  end

  def test_payload_name_for_post_destroy
    post = Post.create!

    ActiveSupport::Notifications.subscribe "sql.active_record" do |*args|
      event = ActiveSupport::Notifications::Event.new *args
      if event.payload[:sql].match  "DELETE"
        assert_equal "Post Destroy", event.payload[:name]
      end
    end

    post.destroy
  end
end

Running it produces this output:

$ ruby active_record_gem.rb 
Fetching gem metadata from https://rubygems.org/..........
Fetching version metadata from https://rubygems.org/.
Resolving dependencies...
Using concurrent-ruby 1.0.5
Using i18n 0.8.6
Using minitest 5.10.3
Using thread_safe 0.3.6
Using arel 8.0.0
Using sqlite3 1.3.13
Using bundler 1.13.2
Using tzinfo 1.2.3
Using activesupport 5.1.4
Using activemodel 5.1.4
Using activerecord 5.1.4
-- create_table(:posts, {:force=>true})
D, [2017-09-12T23:17:47.771478 #84520] DEBUG -- :    (0.1ms)  DROP TABLE IF EXISTS "posts"
D, [2017-09-12T23:17:47.773772 #84520] DEBUG -- :    (1.6ms)  SELECT sqlite_version(*)
D, [2017-09-12T23:17:47.775034 #84520] DEBUG -- :    (1.1ms)  CREATE TABLE "posts" ("id" INTEGER PRIMARY KEY AUTOINCREMENT NOT NULL, "name" varchar)
   -> 0.0165s
D, [2017-09-12T23:17:47.806888 #84520] DEBUG -- :    (0.2ms)  CREATE TABLE "ar_internal_metadata" ("key" varchar NOT NULL PRIMARY KEY, "value" varchar, "created_at" datetime NOT NULL, "updated_at" datetime NOT NULL)
D, [2017-09-12T23:17:47.821714 #84520] DEBUG -- :   ActiveRecord::InternalMetadata Load (0.2ms)  SELECT  "ar_internal_metadata".* FROM "ar_internal_metadata" WHERE "ar_internal_metadata"."key" = ? LIMIT ?  [["key", "environment"], ["LIMIT", 1]]
D, [2017-09-12T23:17:47.826489 #84520] DEBUG -- :    (0.1ms)  begin transaction
D, [2017-09-12T23:17:47.827568 #84520] DEBUG -- :   SQL (0.1ms)  INSERT INTO "ar_internal_metadata" ("key", "value", "created_at", "updated_at") VALUES (?, ?, ?, ?)  [["key", "environment"], ["value", "default_env"], ["created_at", "2017-09-13 04:17:47.826848"], ["updated_at", "2017-09-13 04:17:47.826848"]]
D, [2017-09-12T23:17:47.827804 #84520] DEBUG -- :    (0.1ms)  commit transaction
Run options: --seed 19963

# Running:

FFF.

Finished in 0.011526s, 347.0415 runs/s, 347.0415 assertions/s.

  1) Failure:
BugTest#test_payload_name_for_post_create [active_record_gem.rb:59]:
Expected: "Post Create"
  Actual: "SQL"

  2) Failure:
BugTest#test_payload_name_for_post_update [active_record_gem.rb:72]:
Expected: "Post Update"
  Actual: "SQL"

  3) Failure:
BugTest#test_payload_name_for_post_destroy [active_record_gem.rb:85]:
Expected: "Post Destroy"
  Actual: "SQL"

4 runs, 4 assertions, 3 failures, 0 errors, 0 skips

Expected behavior

When I subscribe to sql.active_record when a Post is loaded the payload name is "Post Load", which is great and seems to set a pattern on payload naming. Following that pattern:

• When a Post is created I would expect the payload name to be "Post Create" (or something similar).
• When a Post is updated I would expect the payload name to be "Post Update" (or something similar).
• When a Post is deleted I would expect the payload name to be "Post Delete" (or something similar).

Actual behavior

• When a Post is created the payload name is "SQL".
• When a Post is updated the payload name is "SQL".
• When a Post is deleted the payload name is "SQL".

System configuration

Rails version: 5.1.4

Ruby version: 2.3.1

[rafaelfranca]

Thank you so much for the issue but we don't take feature request on the issue tracker. We recommend you to try to implement the feature and send us a pull request or if you are in doubt if the feature will be accepts ask in Rails Core mailing list for feedback.