Stale record retrieved via garnered_find

[dblock]

Trying to track a cache invalidation issue. A garnered_find of a record returns a stale result and no saving/invalidating of the original is clearing anything.

gravity:production> Profile.garnered_find('andrea-meislin-gallery')
fetch: {:strategy=>Garner::Strategies::Binding::Key::BindingIndex, :proxied_binding=>"Garner::Mixins::Mongoid::Identity/klass=Profile,handle=andrea-meislin-gallery"}
fetch: {:strategy=>Garner::Strategies::Binding::Key::BindingIndex, :proxied_binding=>"Profile/id=51120ae9d0c2eb4545004a16"}
fetch: {:binding_keys=>["831181d39281d48a71f76e43"], :context_keys=>{:garnered_find_args=>["andrea-meislin-gallery"]}}
=> #<Profile _id: 54188b287261692d7acf0200, created_at: 2014-09-16 19:10:32 UTC, updated_at: 2014-10-13 16:13:25 UTC, handle: "andrea-meislin-gallery", _slugs: ["andrea-meislin-gallery"], published: true, published_at: 2014-10-13 15:57:55 UTC, published_changed_at: 2014-10-13 15:57:55 UTC, locked_at: nil, locked_until: nil, short_description: nil, bio: "Andrea Meislin Gallery focuses on internationally recognized artists whose work contributes to the diasporic-based dialogue domestically and abroad.", website: "", location: "", default_icon_version: :square, subtype: nil, menu_color_class: nil, private: false, follows_count: 0, owner_type: "PartnerGallery", owner_id: BSON::ObjectId('54188b287261692d7acd0200')>

The proxy record is pointing to a stale record, which has the wrong ID 51120ae9d0c2eb4545004a16 (this profile belongs to a user), while the real record has an ID of 54188b287261692d7acf0200 (this profile belongs to a gallery). At some point the profile belonged to the user, and then it had to be renamed (handle changed), then the partner's profile was renamed to the same handle. The repro code however didn't exhibit this problem, this spec passed:

profile = Fabricate(:profile)
partner = Fabricate(:partner, given_name: 'gallery')
expect(partner.profile.handle).to_not eq 'gallery'
profile.update_attributes!(handle: 'not-gallery')
partner.profile.update_attributes!(handle: 'gallery')
expect(Profile.garnered_find('gallery').id).to eq partner.profile.id

How did we get here?

A save of the profile that is supposed to invalidate the above:

gravity:production> profile = Profile.find('andrea-meislin-gallery')
=> #<Profile _id: 54188b287261692d7acf0200, created_at: 2014-09-16 19:10:32 UTC, updated_at: 2014-10-14 19:02:38 UTC, handle: "andrea-meislin-gallery", _slugs: ["andrea-meislin-gallery"], published: true, published_at: 2014-10-13 15:57:55 UTC, published_changed_at: 2014-10-13 15:57:55 UTC, locked_at: nil, locked_until: nil, short_description: nil, bio: "Andrea Meislin Gallery focuses on internationally recognized artists whose work contributes to the diasporic-based dialogue domestically and abroad.", website: "", location: "", default_icon_version: :square, subtype: nil, menu_color_class: nil, private: false, follows_count: 0, owner_type: "PartnerGallery", owner_id: BSON::ObjectId('54188b287261692d7acd0200')>
gravity:production> profile.save!
write: {:strategy=>Garner::Strategies::Binding::Key::BindingIndex, :proxied_binding=>"Profile/id=54188b287261692d7acf0200"} => String
write: {:strategy=>Garner::Strategies::Binding::Key::BindingIndex, :proxied_binding=>"Profile/id=54188b287261692d7acf0200"} => String
write: {:strategy=>Garner::Strategies::Binding::Key::BindingIndex, :proxied_binding=>"Profile"} => String
write: {:strategy=>Garner::Strategies::Binding::Key::BindingIndex, :proxied_binding=>"Profile"} => String

Had to manually clear it:

Garner.config.cache.delete(:binding_keys=>["831181d39281d48a71f76e43"], :context_keys=>{:garnered_find_args=>["andrea-meislin-gallery"]})

This could be a total red herring. In https://github.com/artsy/garner/blob/1292b59a961e7f6dbfc9580b7cdb0a6a5956afc4/lib/garner/cache.rb#L16:

result = Garner.config.cache.fetch(compound_key, options_hash) do
    yield
end
Garner.config.cache.delete(compound_key) unless result

Note the fetch here is by compound key with options, but the delete is without the options. Was this intentional?

[dblock]

To see what is being read/written to/from cache:

module StoreEx
  def read(key, options = nil)
    puts "read: #{key}, options=#{options}"
    rc = super
    puts " => #{rc || 'nil'}"
    rc
  end

  def write(key, value, options = nil)
    puts "write: #{key} => #{value.class}, options=#{options}"
    super
  end

  def fetch(key, options = nil)
    puts "fetch: #{key}, options=#{options}"
    rc = super
    puts " => #{rc || 'nil'}"
    rc
  end

  def delete(key, options = nil)
    puts "delete: #{key}, options=#{options}"
    rc = super
    puts " => #{rc}"
    rc
  end
end

Garner.config.cache.extend StoreEx

[dblock]

@fancyremarker I could really use some help on this, we see it pretty frequently.

[dylanfareed]

We saw this today with another model.

> show_id = '543d61ab7261693216230700'
> show_slug = 'show-slug'
> garnered_show_by_slug = PartnerShow.garnered_find show_slug
> garnered_show_by_id = PartnerShow.garnered_find show_id
> show = PartnerShow.find '543d61ab7261693216230700'

> garnered_show_by_slug.artworks_count
=> 15
> garnered_show_by_id.artworks_count
=> 15
> show.artworks_count
=> 30

Using @dblock's monkeypatch

module StoreEx
  def read(key, options = nil)
    puts "read: #{key}"
    super
  end

  def read_multi(*names)
    puts "read_multi: #{names}"
    super
  end

  def write(key, value, options = nil)
    puts "write: #{key} => #{value.class}"
    super
  end

  def fetch(name, options = nil)
    puts "fetch: #{name}"
    super
  end
end

Garner.config.cache.extend StoreEx

Provided the following output

> garnered_show_by_slug = PartnerShow.garnered_find show_slug
fetch: {:strategy=>Garner::Strategies::Binding::Key::BindingIndex, :proxied_binding=>"Garner::Mixins::Mongoid::Identity/klass=PartnerShow,handle=555-gallery-devils-promenade"}
fetch: {:strategy=>Garner::Strategies::Binding::Key::BindingIndex, :proxied_binding=>"PartnerShow/id=543d3fb87261692e99a80500"}
fetch: {:binding_keys=>["b94e26209586db496f7b1f03"], :context_keys=>{:garnered_find_args=>["555-gallery-devils-promenade"]}}
=> #<PartnerShow _id: 543d61ab7261693216230700, created_at: 2014-10-14 17:47:23 UTC, updated_at: 2014-10-14 18:00:15 UTC, name: "Devil's Promenade", start_at: 2014-10-10 00:00:00 UTC, end_at: 2014-11-08 23:59:00 UTC, all_day: true, version: 17, updated_by_id: BSON::ObjectId('5310d943a09a672c5800017f'), _type: "PartnerShow", coordinates: [-71.055692, 42.340103], _slugs: ["555-gallery-6", "555-gallery-devils-promenade"], description: "", press_release: "", publish_at: nil, featured: false, eligible_artworks_count: 0, artworks_count: 15, images_count: 0, displayable: false, partner_id: BSON::ObjectId('5310d893a09a67091a0001aa'), partner_location_id: BSON::ObjectId('5339e1851a1e868ea600013c'), fair_id: nil, active_start_at: nil, active_end_at: nil>

Deleted the stale object here:

> Garner.config.cache.delete(:binding_keys=>["b94e26209586db496f7b1f03"], :context_keys=>{:garnered_find_args=>["555-gallery-devils-promenade"]})
=> true

All was right again with the world.

[dblock]

One of the simpler and important questions is why doesn't a Partner.find('555-gallery-devils-promenade').invalidate_garner_caches invalidate all this stuff.

[fancyremarker]

@dblock:

Note the fetch here is by compound key with options, but the delete is without the options. Was this intentional?

Nope, that can be fixed. I don't think that will affect this bug though, unless the :race_condition_ttl or :namespace options are being set in Garner's global_cache_options.

One of the simpler and important questions is why doesn't a Partner.find('555-gallery-devils-promenade') invalidate all this stuff.

I think that would make for a good feature. It should be configurable, since it's a bit opinionated/dangerous to be interfering with the default .find behavior of ActiveRecord and Mongoid, but it would make for a better library for most use cases.

[dblock]

@fancyremarker I meant to say Partner.find('555-gallery-devils-promenade').invalidate_garner_caches for above, not just find. Updated.

[fancyremarker]

I'll take a closer look at this, but in the meantime, it looks like it may be specific to the BindingIndex strategy. Have you tested using the SafeCacheKey strategy? That's what I'm currently using.

I'd still like to fix this, but switching strategies may be the quicker solution.

[dblock]

Thanks @fancyremarker. I opened #81 for the unrelated delete issue and fixed it in https://github.com/artsy/garner/pull/82.

Will take a look in switching strategies. What are the downsides? Also note that SafeCacheKey + Touch doesn't pass spec/integration/mongoid_spec.rb. Opened https://github.com/artsy/garner/issues/83.

[dblock]

Back to this. The common thread is that you have two records and the second one gets the slug of the first one at some point. Then what we get is that garnered_find is finding the other, stale record when looked up by slug.

I tried switching strategies, but ended up with a bunch of spec failures around caching when retrieving by id vs. slug. I think this is #83, going to take a look.

Spent a lot of time trying to write a spec that would get me into this state, at no avail. Could really use some help.