changes in ActiveModel::Dirty tracking during ActiveRecord lifecycle callbacks in rails 5.2

00_README.md

This script reports on how the behavior of ActiveModel::Dirty methods have changed during various lifecycle callbacks in ActiveRecord instances.

The report shows the output of various ActiveModel::Dirty methods within a number of different callbacks, under different versions of ActiveRecord.

The script used to create this output is below, and can be used/modified to get information on other dirty-state methods.

fun stuff

this script was kinda fun to put together. i got to poke in a few areas of ruby I don't typically touch.

1. IO.pipe is an easy way to allow a subprocess to report back to its parent.
2. Marshal.dump and Marshal.load can write directly to IO instances. (Again, this is really handy for inter-process communication.)
3. globals and eval are terrible code smells by any sane coding conventions, but they felt like good fits here. Look at me, I'm a rebel.

01_output.txt

during insert

  in before_save
    `attribute_change(:title)` output
       5.1.6.1: [nil, "initial"]
         5.2.2: [nil, "initial"]
    `changed` output
       5.1.6.1: ["title"]
         5.2.2: ["title"]
    `changed_attributes` output
       5.1.6.1: {"title"=>nil}
         5.2.2: {"title"=>nil}
    `changes` output
       5.1.6.1: {"title"=>[nil, "initial"]}
         5.2.2: {"title"=>[nil, "initial"]}
    `changes.keys` output
       5.1.6.1: ["title"]
         5.2.2: ["title"]
    `previous_changes` output
       5.1.6.1: {}
         5.2.2: {}
    `saved_change_to_title?` output
       5.1.6.1: false
         5.2.2: false
    `saved_changes` output
       5.1.6.1: {}
         5.2.2: {}
    `title_before_last_save` output
       5.1.6.1: nil
         5.2.2: nil
    `title_changed?` output
       5.1.6.1: true
         5.2.2: true

  in after_save

    `attribute_change(:title)` output   *** CHANGED***
       5.1.6.1: [nil, "initial"]
         5.2.2: nil

    `changed` output                    *** CHANGED***
       5.1.6.1: ["id", "title"]
         5.2.2: []

    `changed_attributes` output         *** CHANGED***
       5.1.6.1: {"id"=>nil, "title"=>nil}
         5.2.2: {}

    `changes` output                    *** CHANGED***
       5.1.6.1: {"id"=>[nil, 1], "title"=>[nil, "initial"]}
         5.2.2: {}

    `changes.keys` output               *** CHANGED***
       5.1.6.1: ["id", "title"]
         5.2.2: []

    `previous_changes` output           *** CHANGED***
       5.1.6.1: {}
         5.2.2: {"id"=>[nil, 1], "title"=>[nil, "initial"]}
    `saved_change_to_title?` output
       5.1.6.1: true
         5.2.2: true
    `saved_changes` output
       5.1.6.1: {"id"=>[nil, 1], "title"=>[nil, "initial"]}
         5.2.2: {"id"=>[nil, 1], "title"=>[nil, "initial"]}
    `title_before_last_save` output
       5.1.6.1: nil
         5.2.2: nil

    `title_changed?` output             *** CHANGED***
       5.1.6.1: true
         5.2.2: false

  in after_commit
    `attribute_change(:title)` output
       5.1.6.1: nil
         5.2.2: nil
    `changed` output
       5.1.6.1: []
         5.2.2: []
    `changed_attributes` output
       5.1.6.1: {}
         5.2.2: {}
    `changes` output
       5.1.6.1: {}
         5.2.2: {}
    `changes.keys` output
       5.1.6.1: []
         5.2.2: []
    `previous_changes` output
       5.1.6.1: {"id"=>[nil, 1], "title"=>[nil, "initial"]}
         5.2.2: {"id"=>[nil, 1], "title"=>[nil, "initial"]}
    `saved_change_to_title?` output
       5.1.6.1: true
         5.2.2: true
    `saved_changes` output
       5.1.6.1: {"id"=>[nil, 1], "title"=>[nil, "initial"]}
         5.2.2: {"id"=>[nil, 1], "title"=>[nil, "initial"]}
    `title_before_last_save` output
       5.1.6.1: nil
         5.2.2: nil
    `title_changed?` output
       5.1.6.1: false
         5.2.2: false


during update

  in before_save
    `attribute_change(:title)` output
       5.1.6.1: ["initial", "updated"]
         5.2.2: ["initial", "updated"]
    `changed` output
       5.1.6.1: ["title"]
         5.2.2: ["title"]
    `changed_attributes` output
       5.1.6.1: {"title"=>"initial"}
         5.2.2: {"title"=>"initial"}
    `changes` output
       5.1.6.1: {"title"=>["initial", "updated"]}
         5.2.2: {"title"=>["initial", "updated"]}
    `changes.keys` output
       5.1.6.1: ["title"]
         5.2.2: ["title"]
    `previous_changes` output
       5.1.6.1: {"id"=>[nil, 1], "title"=>[nil, "initial"]}
         5.2.2: {"id"=>[nil, 1], "title"=>[nil, "initial"]}
    `saved_change_to_title?` output
       5.1.6.1: true
         5.2.2: true
    `saved_changes` output
       5.1.6.1: {"id"=>[nil, 1], "title"=>[nil, "initial"]}
         5.2.2: {"id"=>[nil, 1], "title"=>[nil, "initial"]}
    `title_before_last_save` output
       5.1.6.1: nil
         5.2.2: nil
    `title_changed?` output
       5.1.6.1: true
         5.2.2: true

  in after_save

    `attribute_change(:title)` output   *** CHANGED***
       5.1.6.1: ["initial", "updated"]
         5.2.2: nil

    `changed` output                    *** CHANGED***
       5.1.6.1: ["title"]
         5.2.2: []

    `changed_attributes` output         *** CHANGED***
       5.1.6.1: {"title"=>"initial"}
         5.2.2: {}

    `changes` output                    *** CHANGED***
       5.1.6.1: {"title"=>["initial", "updated"]}
         5.2.2: {}

    `changes.keys` output               *** CHANGED***
       5.1.6.1: ["title"]
         5.2.2: []

    `previous_changes` output           *** CHANGED***
       5.1.6.1: {"id"=>[nil, 1], "title"=>[nil, "initial"]}
         5.2.2: {"title"=>["initial", "updated"]}
    `saved_change_to_title?` output
       5.1.6.1: true
         5.2.2: true
    `saved_changes` output
       5.1.6.1: {"title"=>["initial", "updated"]}
         5.2.2: {"title"=>["initial", "updated"]}
    `title_before_last_save` output
       5.1.6.1: "initial"
         5.2.2: "initial"

    `title_changed?` output             *** CHANGED***
       5.1.6.1: true
         5.2.2: false

  in after_commit
    `attribute_change(:title)` output
       5.1.6.1: nil
         5.2.2: nil
    `changed` output
       5.1.6.1: []
         5.2.2: []
    `changed_attributes` output
       5.1.6.1: {}
         5.2.2: {}
    `changes` output
       5.1.6.1: {}
         5.2.2: {}
    `changes.keys` output
       5.1.6.1: []
         5.2.2: []
    `previous_changes` output
       5.1.6.1: {"title"=>["initial", "updated"]}
         5.2.2: {"title"=>["initial", "updated"]}
    `saved_change_to_title?` output
       5.1.6.1: true
         5.2.2: true
    `saved_changes` output
       5.1.6.1: {"title"=>["initial", "updated"]}
         5.2.2: {"title"=>["initial", "updated"]}
    `title_before_last_save` output
       5.1.6.1: "initial"
         5.2.2: "initial"
    `title_changed?` output
       5.1.6.1: false
         5.2.2: false


during destroy

  in before_destroy
    `attribute_change(:title)` output
       5.1.6.1: nil
         5.2.2: nil
    `changed` output
       5.1.6.1: []
         5.2.2: []
    `changed_attributes` output
       5.1.6.1: {}
         5.2.2: {}
    `changes` output
       5.1.6.1: {}
         5.2.2: {}
    `changes.keys` output
       5.1.6.1: []
         5.2.2: []
    `previous_changes` output
       5.1.6.1: {"title"=>["initial", "updated"]}
         5.2.2: {"title"=>["initial", "updated"]}
    `saved_change_to_title?` output
       5.1.6.1: true
         5.2.2: true
    `saved_changes` output
       5.1.6.1: {"title"=>["initial", "updated"]}
         5.2.2: {"title"=>["initial", "updated"]}
    `title_before_last_save` output
       5.1.6.1: "initial"
         5.2.2: "initial"
    `title_changed?` output
       5.1.6.1: false
         5.2.2: false

  in after_destroy
    `attribute_change(:title)` output
       5.1.6.1: nil
         5.2.2: nil
    `changed` output
       5.1.6.1: []
         5.2.2: []
    `changed_attributes` output
       5.1.6.1: {}
         5.2.2: {}
    `changes` output
       5.1.6.1: {}
         5.2.2: {}
    `changes.keys` output
       5.1.6.1: []
         5.2.2: []
    `previous_changes` output
       5.1.6.1: {"title"=>["initial", "updated"]}
         5.2.2: {"title"=>["initial", "updated"]}
    `saved_change_to_title?` output
       5.1.6.1: true
         5.2.2: true
    `saved_changes` output
       5.1.6.1: {"title"=>["initial", "updated"]}
         5.2.2: {"title"=>["initial", "updated"]}
    `title_before_last_save` output
       5.1.6.1: "initial"
         5.2.2: "initial"
    `title_changed?` output
       5.1.6.1: false
         5.2.2: false

  in after_commit
    `attribute_change(:title)` output
       5.1.6.1: nil
         5.2.2: nil
    `changed` output
       5.1.6.1: []
         5.2.2: []
    `changed_attributes` output
       5.1.6.1: {}
         5.2.2: {}
    `changes` output
       5.1.6.1: {}
         5.2.2: {}
    `changes.keys` output
       5.1.6.1: []
         5.2.2: []
    `previous_changes` output
       5.1.6.1: {"title"=>["initial", "updated"]}
         5.2.2: {"title"=>["initial", "updated"]}
    `saved_change_to_title?` output
       5.1.6.1: true
         5.2.2: true
    `saved_changes` output
       5.1.6.1: {"title"=>["initial", "updated"]}
         5.2.2: {"title"=>["initial", "updated"]}
    `title_before_last_save` output
       5.1.6.1: "initial"
         5.2.2: "initial"
    `title_changed?` output
       5.1.6.1: false
         5.2.2: false

03_dirty_changes.rb

# frozen_string_literal: true
require 'erb'

# this is an ERB template of a test rails application.
#
# we'll use this script to evaluate how ActiveModel::Dirty methods have changed
# in various versions of ActiveRecord.
#
# based on https://github.com/rails/rails/blob/master/guides/bug_report_templates/active_record_gem.rb
source = '
require "bundler/inline"

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

  gem "activerecord", "<%= activerecord_version %>"
  gem "sqlite3", "~> 1.3.6"
end

require "active_record"

ActiveRecord::Base.establish_connection(adapter: "sqlite3", database: ":memory:")
ActiveRecord::Base.logger = Logger.new("/dev/null")

ActiveRecord::Schema.define do
  create_table :posts, force: true do |t|
    t.string :title
  end
end

class Post < ActiveRecord::Base
  def report_current_state_during(callback_name)
    # add any method calls you want. theyll be run/evald, and added to
    # the report payload which is sent back to the parent process.
    [
      "attribute_change(:title)",
      "changes",
      "changes.keys",
      "changed_attributes",
      "changed",
      "previous_changes",
      "saved_change_to_title?",
      "saved_changes",
      "title_before_last_save",
      "title_changed?"
    ].sort.each do |code|
      payload = {
        stage: $stage,
        callback_name: callback_name,
        version: ActiveRecord.gem_version.to_s,
        code: code,
        output: eval(code).inspect
      }
      Marshal.dump(payload, $writer)
    end
  end

  before_save do
    report_current_state_during("before_save")
  end

  after_save do
    report_current_state_during("after_save")
  end

  before_destroy do
    report_current_state_during("before_destroy")
  end

  after_destroy do
    report_current_state_during("after_destroy")
  end

  after_commit do
    report_current_state_during("after_commit")
  end
end

$stage = \'during insert\'
post = Post.create!(title: \'initial\')
puts

$stage = \'during update\'
post.title = \'updated\'
post.save!

$stage = \'during destroy\'
post.destroy
'

report = []
application_template = ERB.new(source)

# run the test application once for each of these versions of activerecord
activerecord_versions = ['~> 5.1.0', '~> 5.2.0']
activerecord_versions.each do |activerecord_version|
  # create a runnable script
  application_source = application_template.result_with_hash(
    activerecord_version: activerecord_version
  )

  # set up IOs for IPC
  reader, writer = IO.pipe

  # run our test script in a subprocess
  #
  # threads won't work because we can't activate multiple versions of
  # activerecord in the same process
  pid = Process.fork do
    reader.close
    # make writer global in subprocess, so any part of the test application can access it easily
    $writer = writer
    eval(application_source)
  end
  Process.wait(pid)

  writer.close

  # back in parent process, read everything the subprocess wrote
  loop do
    begin
      report << Marshal.load(reader)
    rescue EOFError
      break
    end
  end
end

# now build a report from all that data
final = {}
report.each do |item|
  # js destructuring would be handy here.
  stage = item[:stage]
  callback_name = item[:callback_name]
  code = item[:code]
  version = item[:version]
  output = item[:output]

  final[stage] ||= {}
  final[stage][callback_name] ||= {}
  final[stage][callback_name][code] ||= {}
  final[stage][callback_name][code][version] = output
end

# ansi color utils cribbed from
#   https://github.com/sickill/rainbow/blob/master/lib/rainbow/string_utils.rb
#   https://github.com/sickill/rainbow/blob/master/lib/rainbow/color.rb
def colorize(string, hex)
  r = hex[0..1].to_i(16)
  g = hex[2..3].to_i(16)
  b = hex[4..5].to_i(16)
  color = 16 + to_ansi_domain(r) * 36 + to_ansi_domain(g) * 6 + to_ansi_domain(b)
  "\e[38;5;#{color}m#{string}\e[0m"
end

def to_ansi_domain(value)
  (6 * (value / 256.0)).to_i
end

# and output it all nice & pretty
final.each do |stage, by_callback|
  puts stage
  puts
  by_callback.each do |callback_name, by_method|
    puts "  in #{callback_name}"
    by_method.each do |method_name, by_version|
      line = "    `#{method_name}` output"
      line_color = '229922'

      versions_differ = by_version.values.uniq.size > 1
      if versions_differ
        line_color = '992222'
        line = line.ljust(40) + "*** CHANGED***"
        puts
      end

      puts colorize(line, line_color)

      by_version.each do |version, output|
        puts "      #{version.rjust(8)}: #{output}"
      end
    end
    puts
  end
  puts
end