Make fakeredis a time traveler

slothyrulez commented 11 months ago

I'd love that fakeredis could time travel.

We have been starting using fakeredis for our testing infrastructure, and is working nice, thank for it.

Today writing a test I've noticed that fakeredis seems not to be working ok with time-machine package.

CACHES_FAKEREDIS = {
    'default': {
        'BACKEND': 'django_redis.cache.RedisCache',
        'LOCATION': f'redis://localhost:6379/1',
        'OPTIONS': {
            'connection_class': FakeConnection,
            'CLIENT_CLASS': 'django_redis.client.DefaultClient',
        },
        'TIMEOUT': 3600,
    },
    'sessions': {
        'BACKEND': 'django_redis.cache.RedisCache',
        'LOCATION': f'redis://localhost:6379/2',
        'OPTIONS': {
            'connection_class': FakeConnection,
            'CLIENT_CLASS': 'django_redis.client.DefaultClient',
        },
    },
}

CACHE_TIEMOUT = 300

@override_settings(CACHES=CACHES_FAKEREDIS)
class TestViewDataIsCached(TestCase):
    def setUp(self) -> None:
        super().setUp()
        cache.clear()

    def test_cache_expiration(self,...):

        print('BEFORE time_machine.travel --')
        print(f'{datetime.datetime.now()=}')
        print(f'{time.time()=}')
        print(f'{cache.client.get_client().time()=}')
        print(f'{cache.has_key("XXXX")=}')
        print(f'{cache.pttl("XXXX")=}')

        frozen_time = pytz.UTC.localize(datetime.datetime(2023, 11, 23, 14, 52))
        with time_machine.travel(frozen_time, tick=False) as travel_time:            
            print('AFTER time_machine.travel --')
            print(f'{datetime.datetime.now()=}')
            print(f'{time.time()=}')
            print(f'{cache.client.get_client().time()=}')
            print(f'{cache.has_key("XXXX")=}')
            print(f'{cache.pttl("XXXX")=}')
            ...
            # some caching with django cache and fakeredis
            # some asserts...
            ...
            before_expire_delta = datetime.timedelta(seconds=(CACHE_TIEMOUT - 10))
            travel_time.shift(before_expire_delta)
            print('--')
            print(f'{datetime.datetime.now()=}')
            print(f'{time.time()=}')
            print(f'{cache.client.get_client().time()=}')
            print(f'{cache.has_key("XXXX")=}')
            print(f'{cache.pttl("XXXX")=}')
            ...
            # some asserts
            ...
            # TRAVEL 15s to the future
            # Here cache should have expired
            after_expire_delta = datetime.timedelta(seconds=15))
            travel_time.shift(after_expire_delta)
            print('--')
            print(f'{datetime.datetime.now()=}')
            print(f'{time.time()=}')
            print(f'{cache.client.get_client().time()=}')
            print(f'{cache.has_key("XXXX")=}')
            print(f'{cache.pttl("XXXX")=}')

BEFORE time_machine.travel --
datetime.datetime.now()=datetime.datetime(2023, 11, 24, 6, 1, 23, 8122)
time.time()=1700805683.0081432
cache.client.get_client().time()=(1700805683, 8477)
cache.has_key("XXXX")=False
cache.pttl("XXXX")=0

AFTER time_machine.travel --
datetime.datetime.now()=datetime.datetime(2023, 11, 23, 14, 52)
time.time()=1700751120.0
cache.client.get_client().time()=(1700805683, 16603)
cache.has_key("XXXX")=False
cache.pttl("XXXX")=0
--
CACHED DURING 300 secs (5min.)
--
TRAVEL 4m50s to the future
datetime.datetime.now()=datetime.datetime(2023, 11, 23, 14, 56, 50)
time.time()=1700751410.0
cache.client.get_client().time()=(1700805683, 38205)
cache.has_key("XXXX")=True
cache.pttl("XXXX")=299999
--
TRAVEL 15s to the future
datetime.datetime.now()=datetime.datetime(2023, 11, 23, 14, 57, 5)
time.time()=1700751425.0
cache.client.get_client().time()=(1700805683, 47826)
cache.has_key("XXXX")=True
cache.pttl("XXXX")=299989

There is a discrepancy between the server time and the time on the interpreter.

I started this discussion with @adamchainz at an old version of the repository, here

cunla commented 11 months ago

Hi,

I am not sure what is the issue, I tried writing a test with time-travel and it looks like it is working fine

def test_expire_should_expire_key(r: redis.Redis):
    with time_machine.travel(0, tick=False) as traveller:
        r.set('foo', 'bar')
        assert r.get('foo') == b'bar'
        r.expire('foo', 1)
        traveller.shift(timedelta(seconds=1.5))
        assert r.get('foo') is None
        assert r.expire('bar', 1) is False

Can you provide a test that fails?

slothyrulez commented 11 months ago

Hi, @cunla, Sorry for the delay, I've rewritten the tests to make it realistic and not a fake of what i was running.


CACHE_TIMEOUT = 300
CACHE_KEY = 'test_cache'

def test_cache(request: HttpRequest) -> JsonResponse:
    utc_now = pytz.UTC.localize(datetime.datetime.now())
    key = CACHE_KEY
    value = cache.get(key, None)
    if not value:
        cache.set(key=key, value=utc_now, timeout=CACHE_TIMEOUT)
        value = utc_now

    print(f'VIEW {datetime.datetime.now()=}')
    print(f'VIEW {time.time()=}')
    print(f'VIEW {cache.client.get_client().time()=}')
    print(f'VIEW {cache.has_key(CACHE_KEY)=}')
    print(f'VIEW {cache.pttl(CACHE_KEY)=}')

    return JsonResponse(value, safe=False)

from __future__ import annotations

import datetime
import time
from typing import TYPE_CHECKING

import pytz
import time_machine
from django.core.cache import cache
from django.test import override_settings
from django.urls import reverse

from app.testing import TestCase
from base.testing import CACHES_FAKEREDIS
from integrations.views import CACHE_KEY, CACHE_TIMEOUT

if TYPE_CHECKING:
    from django.test.client import Client

CACHES_FAKEREDIS = {
    'default': {
        'BACKEND': 'django_redis.cache.RedisCache',
        'LOCATION': f'redis://localhost:6379/1',
        'OPTIONS': {
            'connection_class': FakeConnection,
            'CLIENT_CLASS': 'django_redis.client.DefaultClient',
        },
        'TIMEOUT': 3600,
    },
    'sessions': {
        'BACKEND': 'django_redis.cache.RedisCache',
        'LOCATION': f'redis://localhost:6379/2',
        'OPTIONS': {
            'connection_class': FakeConnection,
            'CLIENT_CLASS': 'django_redis.client.DefaultClient',
        },
    },
}

@override_settings(CACHES=CACHES_FAKEREDIS)
class TestViewDataCache(TestCase):
    def setUp(self) -> None:
        super().setUp()
        cache.clear()

    def test_expire_should_expire_key(self):
        frozen_time = pytz.UTC.localize(datetime.datetime(2023, 11, 28, 7, 30))
        with time_machine.travel(frozen_time, tick=False) as travel_time:
            cache.set('TEST_CACHE', 'potato', 300)
            print('--')
            print(f'{datetime.datetime.now()=}')
            print(f'{time.time()=}')
            print(f'{cache.client.get_client().time()=}')
            print(f'{cache.has_key("TEST_CACHE")=}')
            print(f'{cache.pttl("TEST_CACHE")=}')
            assert cache.get('TEST_CACHE') == 'potato'

            travel_time.shift(datetime.timedelta(seconds=330))

            print('--')
            print(f'{datetime.datetime.now()=}')
            print(f'{time.time()=}')
            print(f'{cache.client.get_client().time()=}')
            print(f'{cache.has_key("TEST_CACHE")=}')
            print(f'{cache.pttl("TEST_CACHE")=}')
            assert cache.get('TEST_CACHE') is None

    def test_view_cached_expiration(self):
        self.url = reverse('integrations:test_cache')

        print('BEFORE time_machine.travel --')
        print(f'{datetime.datetime.now()=}')
        print(f'{time.time()=}')
        print(f'{cache.client.get_client().time()=}')
        print(f'{cache.has_key(CACHE_KEY)=}')
        print(f'{cache.pttl(CACHE_KEY)=}')

        frozen_time = pytz.UTC.localize(datetime.datetime(2023, 11, 28, 7, 30))
        with time_machine.travel(frozen_time, tick=False) as travel_time:
            print('AFTER time_machine.travel --')
            print(f'{datetime.datetime.now()=}')
            print(f'{time.time()=}')
            print(f'{cache.client.get_client().time()=}')
            print(f'{cache.has_key(CACHE_KEY)=}')
            print(f'{cache.pttl(CACHE_KEY)=}')

            self.client: Client
            response = self.client.get(self.url)
            assert response.json() == '2023-11-28T07:30:00Z'

            before_expire_delta = datetime.timedelta(seconds=(CACHE_TIMEOUT - 10))
            travel_time.shift(before_expire_delta)
            print('--')
            print(f'{datetime.datetime.now()=}')
            print(f'{time.time()=}')
            print(f'{cache.client.get_client().time()=}')
            print(f'{cache.has_key(CACHE_KEY)=}')
            print(f'{cache.pttl(CACHE_KEY)=}')

            response = self.client.get(self.url)
            assert response.json() == '2023-11-28T07:30:00Z'

            # TRAVEL 15s to the future
            # Here cache should have expired
            after_expire_delta = datetime.timedelta(seconds=15)
            travel_time.shift(after_expire_delta)
            print('--')
            print(f'{datetime.datetime.now()=}')
            print(f'{time.time()=}')
            print(f'{cache.client.get_client().time()=}')
            print(f'{cache.has_key(CACHE_KEY)=}')
            print(f'{cache.pttl(CACHE_KEY)=}')

            response = self.client.get(self.url)
            assert response.json() == '2023-11-28T07:35:05Z'

test_expire_should_expire_key (integrations.tests.test_views.TestViewDataCache.test_expire_should_expire_key) ... --                                                                                                                                                                                                                                                       
datetime.datetime.now()=datetime.datetime(2023, 11, 28, 7, 30)                                                                                                                                                                                                                                                                                                             
time.time()=1701156600.0                                                                                                                                                                                                                                                                                                                                                   
cache.client.get_client().time()=(1701155886, 522053)                                                                                                                                                                                                                                                                                                                      
cache.has_key("TEST_CACHE")=True                                                                                                                                                                                                                                                                                                                                           
cache.pttl("TEST_CACHE")=299999
--
datetime.datetime.now()=datetime.datetime(2023, 11, 28, 7, 35, 30)
time.time()=1701156930.0
cache.client.get_client().time()=(1701155886, 522758)
cache.has_key("TEST_CACHE")=True
cache.pttl("TEST_CACHE")=299998
FAIL
test_view_cached_expiration (integrations.tests.test_views.TestViewDataCache.test_view_cached_expiration) ... BEFORE time_machine.travel --
datetime.datetime.now()=datetime.datetime(2023, 11, 28, 7, 18, 6, 861215)
time.time()=1701155886.8612387
cache.client.get_client().time()=(1701155886, 861480)
cache.has_key(CACHE_KEY)=False
cache.pttl(CACHE_KEY)=0
AFTER time_machine.travel --
datetime.datetime.now()=datetime.datetime(2023, 11, 28, 7, 30)
time.time()=1701156600.0
cache.client.get_client().time()=(1701155886, 862100)
cache.has_key(CACHE_KEY)=False
cache.pttl(CACHE_KEY)=0
VIEW datetime.datetime.now()=datetime.datetime(2023, 11, 28, 7, 30)
VIEW time.time()=1701156600.0
VIEW cache.client.get_client().time()=(1701155886, 867036)
VIEW cache.has_key(CACHE_KEY)=True
VIEW cache.pttl(CACHE_KEY)=299999
--
datetime.datetime.now()=datetime.datetime(2023, 11, 28, 7, 34, 50)
time.time()=1701156890.0
cache.client.get_client().time()=(1701155886, 867763)
cache.has_key(CACHE_KEY)=True
cache.pttl(CACHE_KEY)=299998
VIEW datetime.datetime.now()=datetime.datetime(2023, 11, 28, 7, 34, 50)
VIEW time.time()=1701156890.0
VIEW cache.client.get_client().time()=(1701155886, 869195)
VIEW cache.has_key(CACHE_KEY)=True
VIEW cache.pttl(CACHE_KEY)=299997
--
datetime.datetime.now()=datetime.datetime(2023, 11, 28, 7, 35, 5)
time.time()=1701156905.0
cache.client.get_client().time()=(1701155886, 869891)
cache.has_key(CACHE_KEY)=True
cache.pttl(CACHE_KEY)=299996
VIEW datetime.datetime.now()=datetime.datetime(2023, 11, 28, 7, 35, 5)
VIEW time.time()=1701156905.0
VIEW cache.client.get_client().time()=(1701155886, 871121)
VIEW cache.has_key(CACHE_KEY)=True
VIEW cache.pttl(CACHE_KEY)=299995
FAIL

======================================================================
FAIL: test_expire_should_expire_key (integrations.tests.test_views.TestViewDataCache.test_expire_should_expire_key)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/vagrant/src/django/integrations/tests/test_views.py", line 47, in test_expire_should_expire_key
    assert cache.get('TEST_CACHE') is None
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
AssertionError

======================================================================
FAIL: test_view_cached_expiration (integrations.tests.test_views.TestViewDataCache.test_view_cached_expiration)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/vagrant/src/django/integrations/tests/test_views.py", line 96, in test_view_cached_expiration
    assert response.json() == '2023-11-28T07:35:05Z'
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
AssertionError

----------------------------------------------------------------------
Ran 2 tests in 0.370s

FAILED (failures=2)

What I see is that the server time is not modified, not sure if this is a missconfiguration or something related to time_machine not being able to patch the time on another thread.

cunla commented 11 months ago

I can't run your test as I don't have the entire setup.

But to be clear, does the test fail against the actual Redis server or against Fakeredis?

slothyrulez commented 11 months ago

I can't run your test as I don't have the entire setup.

I can do a little setup for for you, this is django

But to be clear, does the test fail against the actual Redis server or against Fakeredis?

I'd say is the fakeredis one, we set@override_settings(CACHES=CACHES_FAKEREDIS)to use fakeredis

cunla commented 11 months ago

Well, I don't know what cache.client.get_client().time() calls internally, I assume it is not redis.time() since otherwise it would have returned the same as time.time(). See tests here

slothyrulez commented 11 months ago

Well, I don't know what cache.client.get_client().time() calls internally, I assume it is not redis.time() since otherwise it would have returned the same as time.time(). See tests here

Ok, I have to apologize, after your suspects, I went down the rabbit hole and found that you where right, we are not using fakeredis at all with our current configuration.

To use fakeredis with django_redis, the django override must be set to:

CACHES_FAKEREDIS = {
    'default': {
        'BACKEND': 'django_redis.cache.RedisCache',
        'LOCATION': ...,
        'OPTIONS': {
            'CONNECTION_POOL_KWARGS': {
                'connection_class': FakeConnection,
            },
        },
    },

Now the test results are:

test_expire_should_expire_key (integrations.tests.test_views.TestViewDataCache.test_expire_should_expire_key) ... --
datetime.datetime.now()=datetime.datetime(2023, 11, 28, 7, 30)
time.time()=1701156600.0
cache.client.get_client().time()=(1701156600, 0)
cache.has_key("TEST_CACHE")=True
cache.pttl("TEST_CACHE")=300000
--
datetime.datetime.now()=datetime.datetime(2023, 11, 28, 7, 35, 30)
time.time()=1701156930.0
cache.client.get_client().time()=(1701156930, 0)
cache.has_key("TEST_CACHE")=False
cache.pttl("TEST_CACHE")=0
ok
test_view_cached_expiration (integrations.tests.test_views.TestViewDataCache.test_view_cached_expiration) ... BEFORE time_machine.travel --
datetime.datetime.now()=datetime.datetime(2023, 11, 29, 8, 28, 32, 883211)
time.time()=1701246512.883236
cache.client.get_client().time()=(1701246512, 883406)
cache.has_key(CACHE_KEY)=False
cache.pttl(CACHE_KEY)=0
AFTER time_machine.travel --
datetime.datetime.now()=datetime.datetime(2023, 11, 28, 7, 30)
time.time()=1701156600.0
cache.client.get_client().time()=(1701156600, 0)
cache.has_key(CACHE_KEY)=False
cache.pttl(CACHE_KEY)=0
VIEW datetime.datetime.now()=datetime.datetime(2023, 11, 28, 7, 30)
VIEW time.time()=1701156600.0
VIEW cache.client.get_client().time()=(1701156600, 0)
VIEW cache.has_key(CACHE_KEY)=True
VIEW cache.pttl(CACHE_KEY)=300000
--
datetime.datetime.now()=datetime.datetime(2023, 11, 28, 7, 34, 50)
time.time()=1701156890.0
cache.client.get_client().time()=(1701156890, 0)
cache.has_key(CACHE_KEY)=True
cache.pttl(CACHE_KEY)=10000
VIEW datetime.datetime.now()=datetime.datetime(2023, 11, 28, 7, 34, 50)
VIEW time.time()=1701156890.0
VIEW cache.client.get_client().time()=(1701156890, 0)
VIEW cache.has_key(CACHE_KEY)=True
VIEW cache.pttl(CACHE_KEY)=10000
--
datetime.datetime.now()=datetime.datetime(2023, 11, 28, 7, 35, 5)
time.time()=1701156905.0
cache.client.get_client().time()=(1701156905, 0)
cache.has_key(CACHE_KEY)=False
cache.pttl(CACHE_KEY)=0
VIEW datetime.datetime.now()=datetime.datetime(2023, 11, 28, 7, 35, 5)
VIEW time.time()=1701156905.0
VIEW cache.client.get_client().time()=(1701156905, 0)
VIEW cache.has_key(CACHE_KEY)=True
VIEW cache.pttl(CACHE_KEY)=300000
ok

----------------------------------------------------------------------
Ran 2 tests in 0.536s

OK

So, what can I say? Thanks for your time and ...

imagen

cc @adamchainz

adamchainz commented 11 months ago

👏 thanks for writing up the problem, enjoy time-machine.

cunla commented 11 months ago

Awesome! I was getting a bit worried I am loosing my touch :) On a different note, completely unrelated, I recommend migrating to django redis cache internal support (https://docs.djangoproject.com/en/4.2/topics/cache/#redis)

 CACHES = {
        'default': {
            'BACKEND': 'django.core.cache.backends.redis.RedisCache',
            "LOCATION": REDIS_CACHE_URL,
            "OPTIONS": {
            },
            "KEY_PREFIX": "cache",
        }
    }

slothyrulez commented 11 months ago

Awesome! I was getting a bit worried I am loosing my touch :) On a different note, completely unrelated, I recommend migrating to django redis cache internal support (https://docs.djangoproject.com/en/4.2/topics/cache/#redis)
 CACHES = {
        'default': {
            'BACKEND': 'django.core.cache.backends.redis.RedisCache',
            "LOCATION": REDIS_CACHE_URL,
            "OPTIONS": {
            },
            "KEY_PREFIX": "cache",
        }
    }

You are right, we are now having some troubles with all the clients, caches, internals caching if some test uses real redis. Sadly, we are still not django 4.0

cunla / fakeredis-py

Make fakeredis a time traveler #253