Updates fail with concurrent query / updates

[saernz]

Describe the bug Hi I believe I have found a bug which appears to rear its head when queries and updates happen at the same time, I have also identified an area on the code which may be causing this problem and a simple fix which seems to prevent this behaviour and may also help save up to 50% of memory storage in redis. This is potentially loosely related to #201 and may suggest behaviour described in this issue is not intended.

I found when polling a certain resource on my server that if I do an update to that resource the cache will fail to update 100% of the time even though the database field clearly has changed. When polling is disabled the cache works as expected.

I found the problem exists in GeneaLabs\LaravelModelCaching\Traits\Buildable in the retrieveCachedValue(...) function. It appears a race condition can happen in this function if a query and update are performed at the same time. The problem happens when a first() query is performed which calls cachedValue() > retrieveCachedValue(). This actually results in two results being stored in the cache. When the cache is found to be empty at rememberForever() the parent::{$method}(...$arguments) function is called which resolves to the first() method in Illuminate\Database\Concerns\BuildsQueries as intended. The breakdown happens here as the first() method in this class actually runs $this->take(1)->get($columns)->first(), which unintentionally calls back GeneaLabs\LaravelModelCaching\Traits\Buildable::get() as the CachedBuilder is overriding the get() method. This actually results in an additional call to retrieveCachedValue() which adds in another key/val pair to redis, but most dangerously this tries to recall the cache when we actually intended it to skip the cache and call the database. Because of this recursive behaviour a dirty read from the cache can happen at exactly the same time as a flush and the dirty read ends up becoming the new value instead of the updated value in the database.

This problem can be fixed by simply adding $this->disableModelCaching(); to the anonymous function in the retrieveCachedValue() method as below:

return $this->cache($cacheTags)
    ->rememberForever(
        $hashedCacheKey,
        function () use ($arguments, $cacheKey, $method) {
            $this->disableModelCaching();
            return [
                "key" => $cacheKey,
                "value" => parent::{$method}(...$arguments),
            ];
        }
    );

This prevents any recursive calls back to the CachedBuilder, or at least causes the calls to fall back to the EloquentBuilder instead. As a result of adding this it also prevents the extra get() query from being unintentionally cached saving some space in redis.

Stack Trace A stack trace of the recursive behaviour as explained above:

[0] => Array
(
    [file] => /srv/application/vendor/laravel/framework/src/Illuminate/Cache/Repository.php
    [line] => 422
    [function] => GeneaLabs\LaravelModelCaching\Traits\{closure}
    [class] => GeneaLabs\LaravelModelCaching\CachedBuilder
    [type] => ->
)

[1] => Array
(
    [file] => /srv/application/vendor/genealabs/laravel-model-caching/src/Traits/Buildable.php
    [line] => 300
    [function] => rememberForever
    [class] => Illuminate\Cache\Repository
    [type] => ->
)

[2] => Array
(
    [file] => /srv/application/vendor/genealabs/laravel-model-caching/src/Traits/Buildable.php
    [line] => 231
    [function] => retrieveCachedValue
    [class] => GeneaLabs\LaravelModelCaching\CachedBuilder
    [type] => ->
)

[3] => Array
(
    [file] => /srv/application/vendor/genealabs/laravel-model-caching/src/Traits/Buildable.php
    [line] => 100
    [function] => cachedValue
    [class] => GeneaLabs\LaravelModelCaching\CachedBuilder
    [type] => ->
)

[4] => Array
(
    [file] => /srv/application/vendor/laravel/framework/src/Illuminate/Database/Concerns/BuildsQueries.php
    [line] => 77
    [function] => get
    [class] => GeneaLabs\LaravelModelCaching\CachedBuilder
    [type] => ->
)

[5] => Array
(
    [file] => /srv/application/vendor/genealabs/laravel-model-caching/src/Traits/Buildable.php
    [line] => 293
    [function] => first
    [class] => Illuminate\Database\Eloquent\Builder
    [type] => ->
)

[6] => Array
(
    [file] => /srv/application/vendor/laravel/framework/src/Illuminate/Cache/Repository.php
    [line] => 422
    [function] => GeneaLabs\LaravelModelCaching\Traits\{closure}
    [class] => GeneaLabs\LaravelModelCaching\CachedBuilder
    [type] => ->
)

[7] => Array
(
    [file] => /srv/application/vendor/genealabs/laravel-model-caching/src/Traits/Buildable.php
    [line] => 300
    [function] => rememberForever
    [class] => Illuminate\Cache\Repository
    [type] => ->
)

[8] => Array
(
    [file] => /srv/application/vendor/genealabs/laravel-model-caching/src/Traits/Buildable.php
    [line] => 231
    [function] => retrieveCachedValue
    [class] => GeneaLabs\LaravelModelCaching\CachedBuilder
    [type] => ->
)

[9] => Array
(
    [file] => /srv/application/vendor/genealabs/laravel-model-caching/src/Traits/Buildable.php
    [line] => 79
    [function] => cachedValue
    [class] => GeneaLabs\LaravelModelCaching\CachedBuilder
    [type] => ->
)

[10] => Array
(
    [file] => /srv/application/vendor/cloudcreativity/laravel-json-api/src/Eloquent/AbstractAdapter.php
    [line] => 218
    [function] => first
    [class] => GeneaLabs\LaravelModelCaching\CachedBuilder
    [type] => ->
)

[11] => Array
(
    [file] => /srv/application/vendor/cloudcreativity/laravel-json-api/src/Store/Store.php
    [line] => 245
    [function] => find
    [class] => CloudCreativity\LaravelJsonApi\Eloquent\AbstractAdapter
    [type] => ->
)

[12] => Array
(
    [file] => /srv/application/vendor/cloudcreativity/laravel-json-api/src/Store/Store.php
    [line] => 257
    [function] => find
    [class] => CloudCreativity\LaravelJsonApi\Store\Store
    [type] => ->
)

[13] => Array
(
    [file] => /srv/application/vendor/cloudcreativity/laravel-json-api/src/Routing/Route.php
    [line] => 93
    [function] => findOrFail
    [class] => CloudCreativity\LaravelJsonApi\Store\Store
    [type] => ->
)

Environment

• PHP: 7.3.9
• OS: Alpine
• Laravel: 5.8.19
• Model Caching: 0.7.0

Hope this isn't too lengthy. Thanks for your help.

[mikebronner]

@saernz Thanks for this detailed report! Very interesting find, indeed! I will implement the fix you suggest and run it against the unit tests and report back. Please give me a few days to get back to you on this, I will try to get to it on Friday at the latest.

[saernz]

@mikebronner Thanks man. Hopefully I'm not wrong, though I'll leave it up to the experts to decide :)

[saernz]

Unfortunately I don't think my fix has worked as I ran into the same problem again. I believe my DB lock is not working some how and when the cache updates after a flush it does a dirty read of the DB some how as it ends up caching the old value. I think the bug I described above still exists, though I'm not sure if it's causing the race condition or not. From looking at the code and stack traces I believe the recursive call may still be a bug but I'm not sure how it's all relating to the race condition I'm having, will need to investigate this next week to know for sure.

[saernz]

I've looked into this a bit more now and I believe I understand the problem a lot better. There isn't a race condition as I initially described in my original post, though I believe stopping that recursive behaviour will still help stop an intermediate value being stored in the cache caused by the eloquent builders call to get().

I have found I'm getting the wrong value returned from cache after an update if I use transactions. What seems to happen is when my update is performed in a transaction the value is correctly updated in the DB, and the cache gets flushed, but if I don't commit the transaction quick enough before the next read the cache will still get the old DB value as the transaction has not committed.

I was a bit confused before as I saw the cache was flushed only after the DB had been changed and what I was seeing should technically not be possible, though because I'm also using transactions technically the flush can happen before the transaction has been committed to the database. This mainly happens because I have to dispatch an event after my record has been updated, unfortunately the framework I'm using only provides a hook to update events within the database transaction, as a result dispatching the event delayed the commit of the transaction so a read could sneak in between the database flush and the transaction being committed.

The workaround for this was to perform another flush by using $myModel->flushCache() either after the transaction or as close as you can get to the transaction being closed. I'm not sure if a more permanent fix for this library would be to somehow run a flush after a transaction has been committed, though I'm not sure how easy this will be. Possibly just documenting how to use the library with transactions might be enough.

[mikebronner]

@saernz Thanks for the follow-up. I will update the documentation to explain the work-around with transactions.

Also, I was unable to implement your suggested fix in your first post, as it breaks unit tests. It might have worked well for you specific use-case, but it seems to break other areas.