ActiveSupport::Cache.expand_cache_key sometimes returns falsely same key in parallel tests #51399
Comments
|
Can you use one of the bug report templates to provide something reproducible? Otherwise its not really possible to figure out what's happening |
skipkayhil
added
the
more-information-needed
|
Can you post the output of |
|
Meanwhile broke it down to a testcase where it is getting even stranger. When i run all tests in parallel, the cache key assertion on it "changes the key when touched" do
user = users(:one)
assert_same_elements tickets(:single, :multi), user.tickets.visible
assert_changes ->{ ActiveSupport::Cache.expand_cache_key User.find(user.id).tickets.visible } do
sleep 1; travel 1.second
tickets(:single).tap do |ticket|
assert_changes -> { ticket.reload.updated_at } do
ticket.touch
end
end
end
assert_changes ->{ ActiveSupport::Cache.expand_cache_key User.find(user.id).tickets.visible } do
sleep 1; travel 1.second
tickets(:multi).tap do |ticket|
assert_changes -> { ticket.reload.updated_at } do
ticket.touch
end
end
end
endThe output of And for the sake of completeness here the complete implementation of the scopes in use: class Ticket < ApplicationRecord
scope :visible, -> { joins(:admittances).where(tickets: {hidden: false}).merge(Admittance.visible).group("tickets.id")}
end
class Admittance < ApplicationRecord
scope :visible, -> { where(hidden: false).where.not(match_id: nil) }
endThe sql query generated by the Btw, the database in use is postgres:16.1 I still suspect the |
rails-bot
bot
removed
the
more-information-needed
|
The |
Sure, here it is |
skipkayhil
added
the
more-information-needed
|
You are not reloading the association inside of the You're hitting the cache the second time around. Still can't figure out why you're getting flakes though 🤔 |
|
@JoeDupuis ive already checked it beforehand. That would be visible in the log next to the db queries. Its not! The queries are executed twice without any "Cache" prefix. If this would be the cause, it also would produce the same issue by changing the query from "group by" to "distinct" imho. But to make sure ive changed it as you proposed. The result is still the same: it "changes the key when touched" do
user = users(:one)
assert_same_elements tickets(:single, :multi), user.tickets.visible
assert_changes ->{ ActiveSupport::Cache.expand_cache_key User.find(user.id).reload.tickets.visible } do
sleep 1; travel 1.second
tickets(:single).tap do |ticket|
assert_changes -> { ticket.reload.updated_at } do
ticket.touch
end
end
end
assert_changes ->{ ActiveSupport::Cache.expand_cache_key User.find(user.id).reload.tickets.visible } do
sleep 1; travel 1.second
tickets(:multi).tap do |ticket|
assert_changes -> { ticket.reload.updated_at } do
ticket.touch
end
end
end
end |
rails-bot
bot
removed
the
more-information-needed
|
oh @JoeDupuis, isnt the Looking at the sql query: Wouldnt that mean that |
|
Now that i have spent some more time onto this i believe its even worse. If i use the "distinct on" query, the result size shall be scope :visible, -> { joins(:admittances).where(tickets: {hidden: false}).merge(Admittance.visible).select("distinct on (#{table_name}.id) #{table_name}.*") }Calling it produced this query with 2 tickets being returned as expected. One ticket has 2 admittances attached but we want it being returned once. But executing resulting in the following cache key: notice the That means the cache key can change even when the result doesnt! Probably not that big of a deal because its an edge case but surely its still a flaw to me. The safest way handling this would be that the What do you think? |
|
Oh good catch! Now I have a repro! # frozen_string_literal: true
require "bundler/inline"
gemfile(true) do
source "https://rubygems.org"
git_source(:github) { |repo| "https://github.com/#{repo}.git" }
gem "rails"
# If you want to test against edge Rails replace the previous line with this:
# gem "rails", github: "rails/rails", branch: "main"
gem "sqlite3"
gem "debug"
end
require "active_record"
require "minitest/autorun"
require "logger"
require "active_support/testing/assertions"
require "active_support/testing/time_helpers"
# 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 do |t|
t.timestamps
end
create_table :tickets, force: true do |t|
t.integer :user_id
t.string :name
t.timestamps
end
end
class User < ActiveRecord::Base
has_many :tickets
end
class Ticket < ActiveRecord::Base
belongs_to :user
has_many :admittances
end
class BugTest < Minitest::Test
include ActiveSupport::Testing::Assertions
include ActiveSupport::Testing::TimeHelpers
def test_association_stuff
user = User.create!
other_ticket = Ticket.create!(user:, name: :other)
single = Ticket.create!(user:, name: :single)
multi = Ticket.create!(user:, name: :multi)
assert_changes -> { pp ActiveSupport::Cache.expand_cache_key(user.tickets.group("tickets.id")) } do
travel 1.second
single.tap do |ticket|
assert_changes -> { ticket.reload.updated_at } do
ticket.touch
end
end
end
end
end |
|
@JoeDupuis i wanted to add the "distinct on" issue as a separate test but then realized that its not possible with sqlite. Its definitely a second issue there. |
Steps to reproduce
Thats the hard part here! I still didnt figure out how to reproduce it safely.
What i can tell is that this does not happen when i execute a single testcase. It also doesnt happen when i set parallel workers to
1.When parallel workers is set to
processorsand all tests are executed viarails test, the following test is breaking repeatedly:The etag header is calculated basically via this line of code which i also found out to return the same wrong key. The
updated_aton the recordtickets(:multi)changes, but the underlying query fetching themax(tickets.updated_at)seem to return an older timestamp? At least the timestamp in the key remains the same.The visible scope:
Expected behavior
The etag header should change in the same way whether i execute a single test or all together without flakiness.
Actual behavior
The etag header remains equal which is wrong. But this happens only when executing all tests parallelized which is kinda flaky.
Notes
I found out that changing the scope implementation from
grouptodistinctfixes it:System configuration
Rails version: 7.1.2
Ruby version: 3.2.2
The text was updated successfully, but these errors were encountered: