Deletes failing and cache not expiring on one particular model/association

[brandonweiss]

I've got a weird issue with deletes failing when expiring. We use identity_cache in lots of places and it mostly works fine, except on this one particular model's association we're having problems. Here's an example from the console:

[2] (console)> app.fetch_forward_mail_setup_attempts.count
   (0.4ms)  SELECT `forward_mail_setup_attempts`.id FROM `forward_mail_setup_attempts`  WHERE `forward_mail_setup_attempts`.`app_id` = 41
Cache read_multi: ["IDC:5:blob:ForwardMailSetupAttempt:9118014673441475248:73", "IDC:5:blob:ForwardMailSetupAttempt:9118014673441475248:74", "IDC:5:blob:ForwardMailSetupAttempt:9118014673441475248:75", "IDC:5:blob:ForwardMailSetupAttempt:9118014673441475248:76", "IDC:5:blob:ForwardMailSetupAttempt:9118014673441475248:77"]
Dalli::Server#connect localhost:11211
[IdentityCache] (backend) cache hit for IDC:5:blob:ForwardMailSetupAttempt:9118014673441475248:73 (multi)
[IdentityCache] (backend) cache hit for IDC:5:blob:ForwardMailSetupAttempt:9118014673441475248:74 (multi)
[IdentityCache] (backend) cache hit for IDC:5:blob:ForwardMailSetupAttempt:9118014673441475248:75 (multi)
[IdentityCache] (backend) cache hit for IDC:5:blob:ForwardMailSetupAttempt:9118014673441475248:76 (multi)
[IdentityCache] (backend) cache hit for IDC:5:blob:ForwardMailSetupAttempt:9118014673441475248:77 (multi)
=> 5
[3] (console)> app.forward_mail_setup_attempts.create!(
[3] (console)*   forwarding_email_address: "[email protected]",  
[3] (console)*   started_at: Time.now,  
[3] (console)*   expired_at: Time.now + 1.day  
[3] (console)* )  
   (0.4ms)  BEGIN
  SQL (6.6ms)  INSERT INTO `forward_mail_setup_attempts` (`app_id`, `created_at`, `expired_at`, `forwarding_email_address`, `started_at`, `updated_at`) VALUES (41, '2015-05-29 18:08:09', '2015-05-30 18:08:09', '[email protected]', '2015-05-29 18:08:09', '2015-05-29 18:08:09')
   (11.3ms)  COMMIT
[IdentityCache] expiring=App expiring_id=41 expiring_last_updated_at=2015-05-28 23:25:03 UTC
Cache delete: IDC:5:blob:App:18240036282024875059:41
[IdentityCache] delete failed for IDC:5:blob:App:18240036282024875059:41
[IdentityCache] expiring=ForwardMailSetupAttempt expiring_id=78 expiring_last_updated_at=
Cache delete: IDC:5:blob:ForwardMailSetupAttempt:9118014673441475248:78
[IdentityCache] delete failed for IDC:5:blob:ForwardMailSetupAttempt:9118014673441475248:78
=> #<ForwardMailSetupAttempt id: 78, app_id: 41, forwarding_email_address: "[email protected]", provider: nil, started_at: "2015-05-29 18:08:09", expired_at: "2015-05-30 18:08:09", created_at: "2015-05-29 18:08:09", updated_at: "2015-05-29 18:08:09">
[4] (console)> app.fetch_forward_mail_setup_attempts.count
=> 5

When I create a new record the deletes fail and the cache doesn't expire. I tailed memcached logs and see messages like Writing an error: Not found.

Any idea what might be going wrong?

[trobrock]

I am seeing this as well, I cannot speak to the specific model issue as right now I'm just getting started using this and only have this on one model.

Here are the related logs:

D, [2015-08-18T18:53:33.974000 #67474] DEBUG -- : [IdentityCache] (cache_backend) cache hit for IDC:5:index:Romulan::Target::Entry:entry_external_id:15877618461403334186
D, [2015-08-18T18:53:33.979000 #67474] DEBUG -- : [IdentityCache] (cache_backend) cache hit for IDC:5:blob:Romulan::Target::Entry:11746851456754189513:1
D, [2015-08-18T18:53:33.990000 #67474] DEBUG -- : [IdentityCache] expiring=Romulan::Target::Entry expiring_id=371 expiring_last_updated_at=2015-08-19 01:03:18 UTC
D, [2015-08-18T18:53:33.993000 #67474] DEBUG -- : [IdentityCache] delete failed for IDC:5:blob:Romulan::Target::Entry:11746851456754189513:371
D, [2015-08-18T18:53:33.998000 #67474] DEBUG -- : [IdentityCache] delete failed for IDC:5:index:Romulan::Target::Entry:entry_external_id:15063439743944374623

memcached

Deleting IDC:5:blob:Romulan::Target::Entry:11746851456754189513:371
>28 Writing an error: Not found
>28 Writing bin response:
>28   0x81 0x04 0x00 0x00
>28   0x00 0x00 0x00 0x01
>28   0x00 0x00 0x00 0x09
>28   0x00 0x00 0x00 0x00
>28   0x00 0x00 0x00 0x00
>28   0x00 0x00 0x00 0x00
<28 Read binary protocol data:
<28    0x80 0x04 0x00 0x49
<28    0x00 0x00 0x00 0x00
<28    0x00 0x00 0x00 0x49
<28    0x00 0x00 0x00 0x00
<28    0x00 0x00 0x00 0x00
<28    0x00 0x00 0x00 0x00
Deleting IDC:5:index:Romulan::Target::Entry:entry_external_id:15063439743944374623
>28 Writing an error: Not found
>28 Writing bin response:
>28   0x81 0x04 0x00 0x00
>28   0x00 0x00 0x00 0x01
>28   0x00 0x00 0x00 0x09
>28   0x00 0x00 0x00 0x00
>28   0x00 0x00 0x00 0x00
>28   0x00 0x00 0x00 0x00

[trobrock]

A little more info...

If I manually run (what I think is) the delete command, something like: c.write('IDC:5:index:Romulan::Target::Entry:entry_external_id:15877618461403334186', :idc_cached_deleted, :expires_in => 1000.seconds)

This actually sets the key correctly, then if I touch the record (to bust the cache), then the logs look like:

D, [2015-08-18T20:47:32.233000 #34346] DEBUG -- : [IdentityCache] expiring=Romulan::Target::Entry expiring_id=1 expiring_last_updated_at=2015-08-19 03:47:32 UTC
D, [2015-08-18T20:47:32.237000 #34346] DEBUG -- : [IdentityCache] delete failed for IDC:5:blob:Romulan::Target::Entry:11746851456754189513:1
D, [2015-08-18T20:47:32.240000 #34346] DEBUG -- : [IdentityCache] delete recorded for IDC:5:index:Romulan::Target::Entry:entry_external_id:15877618461403334186

So two things

1. I am confused why running the write command manually works, I must not be constructing it exactly the same.
2. This almost seems like its not a failure, it seems like the key just isnt found.

[trobrock]

Ok, figured out the issue with manually running the command, this is because the fetcher the code is using is the fallback fetcher. The command it is actually trying to run is a @cache_backend.delete(key), then memcache is saying the key is not found. This seems like identity cache is just not handling a not found key in the fallback fetcher properly.

It seems like both the MemCacheStore and the DalliStore do not respond to 'cas', so it seems like the fallback fetcher is correct?

[dylanahsmith]

It looks like the cache backends are inconsistent with what is returned by a delete

ActiveSupport::Cache::MemCacheStore#delete returns:

• true if a key was deleted from the cache
• nil if the key wasn't present in the cache
• false if the delete request failed (e.g. failed to connect)

ActiveSupport::Cache::MemoryStore#delete returns:

• true if the key was deleted from the cache
• false if the key wasn't present in the cache

ActiveSupport::Cache::MemcachedStore#delete seems to always return true

Memcached::Rails#delete returns:

• true if the key was deleted from the cache
• false if the key wasn't present in the cache or if the delete request failed

so I'm not sure what the best way is to log actual request errors. The key not being found is not an actual error, it just means it tried to expire a record that wasn't cached or was already removed from the cache.

[dylanahsmith]

Should we just move the delete failed log message to the CacheFetcher where it is more reliable so that it doesn't cause any confusion when using the FallbackFetcher? Or should we have the FallbackFetcher write the special :idc_cached_deleted deleted marker, which it can ignore when reading, so that it can portably detect write failures?

[camilo]

This seems old enough to be stale, I'll close. If someone objects plz re-open.

[brandonweiss]

I'm not sure it's stale? I was waiting for someone who understood the problem well enough to fix it. We basically worked around it by just not using identity cache anywhere we hit this bug 😢

[dylanahsmith]

@bradonweiss it is just a logging issue as explained in #211 (comment), it was just that the cache backends aren't consistent with the value they return from their delete methods.

I think we could just remove that log line to avoid that confusion. It isn't even doing anything for us at Shopify, since we are using ActiveSupport::Cache::MemcachedStore which just returns true on a delete.

[brandonweiss]

I don't think it was just a logging issue. There may be an issue with logging, but the cache was definitely not being busted. Or are you saying the logging issue was causing the cache busting to fail?

[dylanahsmith]

It sounds like you are just getting that [IdentityCache] delete failed error when the key isn't found in the cache. You even mentioned that the memcached logs are saying Writing an error: Not found and the not found indicates that it just wasn't cached, which just means there is no cache to bust. Identity cache so you need to fetch the record before the cache is filled.

Also, I would suggest that you use ActiveSupport::Cache::MemcachedStore to avoid cache consistency issues, since CAS support is needed to avoid race conditions.