Unit test fails during cache region testing

[Herve Beraud]

Since few days oslo.cache unit tests fails when we run tox commands.

Example:
$ tox -e py36
...
Failed 1 tests - output below:
==============================

oslo_cache.tests.test_cache.CacheRegionTest.test_function_key_generator_with_kwargs
-----------------------------------------------------------------------------------

Captured traceback:
~~~~~~~~~~~~~~~~~~~
    b'Traceback (most recent call last):'
    b' File "/tmp/oslo.cache/oslo_cache/tests/test_cache.py", line 324, in test_function_key_generator_with_kwargs'
    b' value=self.test_value)'
    b' File "/tmp/oslo.cache/.tox/py37/lib/python3.7/site-packages/testtools/testcase.py", line 485, in assertRaises'
    b' self.assertThat(our_callable, matcher)'
    b' File "/tmp/oslo.cache/.tox/py37/lib/python3.7/site-packages/testtools/testcase.py", line 498, in assertThat'
    b' raise mismatch_error'
    b'testtools.matchers._impl.MismatchError: <function CacheRegionTest._get_cacheable_function.<locals>.cacheable_function at 0x7fec3f795400> returned <oslo_cache.tests.test_cache.TestProxyValue object at 0x7fec3f792550>'
    b''

======
Totals
======
Ran: 71 tests in 0.6956 sec.
 - Passed: 58
 - Skipped: 12
 - Expected Fail: 0
 - Unexpected Success: 0
 - Failed: 1
Sum of execute time for each test: 3.2200 sec.

==============
Worker Balance
==============
 - Worker 0 (1 tests) => 0:00:00.266985
 - Worker 1 (1 tests) => 0:00:00.446724
 - Worker 2 (1 tests) => 0:00:00.351152
 - Worker 3 (1 tests) => 0:00:00.277782
 - Worker 4 (4 tests) => 0:00:00.410551
 - Worker 5 (10 tests) => 0:00:00.401530
 - Worker 6 (25 tests) => 0:00:00.561800
 - Worker 7 (28 tests) => 0:00:00.560580
Test id Runtime (s)
-------------------------------------------------------------------------------------------------- -----------
oslo_cache.tests.test_cache_backend_mongo.MongoCache.test_backend_delete_data 0.447
oslo_cache.tests.test_cache_backend_mongo.MongoCache.test_backend_multi_set_get_with_blanks_none 0.415
oslo_cache.tests.test_cache_backend_mongo.MongoCache.test_correct_read_preference 0.396
oslo_cache.tests.test_cache_backend_mongo.MongoCache.test_backend_multi_get_data 0.351
oslo_cache.tests.test_cache_backend_mongo.MongoCache.test_backend_get_missing_data 0.340
oslo_cache.tests.test_cache_backend_mongo.MongoCache.test_backend_multi_set_data 0.328
oslo_cache.tests.test_cache_backend_mongo.MongoCache.test_additional_crud_method_arguments_support 0.278
oslo_cache.tests.test_cache_backend_mongo.MongoCache.test_backend_multi_delete_data 0.267
oslo_cache.tests.test_cache_backend_mongo.MongoCache.test_multiple_region_cache_configuration 0.049
oslo_cache.tests.test_cache_backend_mongo.MongoCache.test_cache_configuration_values_assertion 0.014
ERROR: InvocationError for command '/tmp/oslo.cache/.tox/py37/bin/stestr run --slowest' (exited with code 1)
______________________________________________________________________________________________________ summary ______________________________________________________________________________________________________
ERROR: py37: commands failed

I have try to find some clues and the error disapear when I revert the last commit:
https://github.com/openstack/oslo.cache/commit/62b53099861134859482656dc92db81243b88bd9

I suppose the dogpile.cache version used introduce issue.

Here is the installed dependencies during tox execution:
py37 installed: appdirs==1.4.3,asn1crypto==0.24.0,Babel==2.6.0,bandit==1.5.1,certifi==2018.11.29,cffi==1.12.1,chardet==3.0.4,Click==7.0,cliff==2.14.0,cmd2==0.8.9,cryptography==2.5,daiquiri==1.5.0,debtcollector==1.20.0,decorator==4.3.2,dogpile.cache==0.7.1,etcd3gw==0.2.4,extras==1.0.0,fixtures==3.0.0,flake8==2.5.5,future==0.17.1,futurist==1.8.0,gitdb2==2.0.5,GitPython==2.1.11,hacking==0.12.0,idna==2.8,iso8601==0.1.12,Jinja2==2.10,jmespath==0.9.3,jsonpatch==1.23,jsonpointer==2.0,keystoneauth1==3.11.2,linecache2==1.0.0,MarkupSafe==1.1.0,mccabe==0.2.1,mock==2.0.0,monotonic==1.5,mox3==0.26.0,msgpack==0.6.1,munch==2.3.2,netaddr==0.7.19,netifaces==0.10.9,openstack-requirements==1.2.0,openstacksdk==0.24.0,os-client-config==1.31.2,os-service-types==1.5.0,oslo.cache==1.33.0,oslo.config==6.8.0,oslo.context==2.22.0,oslo.i18n==3.23.0,oslo.log==3.42.2,oslo.serialization==2.28.1,oslo.utils==3.40.2,oslotest==3.7.0,packaging==19.0,Parsley==1.3,pbr==5.1.2,pep8==1.5.7,pifpaf==2.2.2,prettytable==0.7.2,psutil==5.5.1,pycparser==2.19,pyflakes==0.8.1,pyinotify==0.9.6,pymongo==3.7.2,pyparsing==2.3.1,pyperclip==1.7.0,python-dateutil==2.8.0,python-memcached==1.59,python-mimeparse==1.6.0,python-subunit==1.3.0,pytz==2018.9,PyYAML==3.13,requests==2.21.0,requestsexceptions==1.4.0,rfc3986==1.2.0,six==1.12.0,smmap2==2.0.5,stestr==2.2.0,stevedore==1.30.0,testtools==2.3.0,traceback2==1.4.0,unittest2==1.1.0,urllib3==1.24.1,voluptuous==0.11.5,wcwidth==0.1.7,wrapt==1.11.1,xattr==0.9.6
py37 run-test-pre: PYTHONHASHSEED='1717446419'

And the installed dogpile.cache version is : dogpile.cache==0.7.1

[Herve Beraud (herveberaud)]

When I revert this commit (https://github.com/openstack/oslo.cache/commit/62b53099861134859482656dc92db81243b88bd9) I obtain the following traceback:

Captured traceback:
~~~~~~~~~~~~~~~~~~~
    b'Traceback (most recent call last):'
    b' File "/tmp/oslo.cache/oslo_cache/tests/test_dict_backend.py", line 37, in setUp'
    b" 'oslo_cache.dict', arguments={'expiration_time': 0.5})"
    b' File "/tmp/oslo.cache/.tox/py37/lib/python3.7/site-packages/dogpile/cache/region.py", line 416, in configure'
    b' backend_cls = _backend_loader.load(backend)'
    b' File "/tmp/oslo.cache/.tox/py37/lib/python3.7/site-packages/dogpile/util/langhelpers.py", line 34, in load'
    b' return self.impls[name]()'
    b' File "/tmp/oslo.cache/.tox/py37/lib/python3.7/site-packages/pkg_resources/__init__.py", line 2410, in load'
    b' self.require(*args, **kwargs)'
    b' File "/tmp/oslo.cache/.tox/py37/lib/python3.7/site-packages/pkg_resources/__init__.py", line 2433, in require'
    b' items = working_set.resolve(reqs, env, installer, extras=self.extras)'
    b' File "/tmp/oslo.cache/.tox/py37/lib/python3.7/site-packages/pkg_resources/__init__.py", line 791, in resolve'
    b' raise VersionConflict(dist, req).with_context(dependent_req)'
    b"pkg_resources.VersionConflict: (dogpile.cache 0.7.1 (/tmp/oslo.cache/.tox/py37/lib/python3.7/site-packages), Requirement.parse('dogpile.cache<0.7.0,>=0.6.2'))"
    b''

[Herve Beraud (herveberaud)]

Discussed with dogpile maintainers the problem seem to come from:
https://gerrit.sqlalchemy.org/#/c/sqlalchemy/dogpile.cache/+/996/

openstacksdk seem to be also impacted by dogpile.cache version bump:
https://review.openstack.org/#/c/625370/4

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/638788

[Matthew Thode (prometheanfire)]

should we expect a fix from dogpile.cache, if so, when (we can mask bad known versions)

[Herve Beraud (herveberaud)]

See ML thread http://lists.openstack.org/pipermail/openstack-discuss/2019-February/003197.html

bnemec think this test is out of the oslo.scope and this an decorator side effect inside dogpile.cache so I don't think we should expect a fix from dogpile.cache.

Ben propose to simply remove this test.

https://review.openstack.org/#/c/638732/

[Mike Bayer (zzzeek)]

I've added https://github.com/sqlalchemy/dogpile.cache/issues/144 to review this behavior and while 0.7's behavior is different, I think it is better:

from dogpile.cache import make_region

region = make_region().configure(
    'dogpile.cache.memory',
)

def load_user_info(value=0):
    return "hi"

import inspect

print(inspect.getfullargspec(load_user_info))

load_user_info = region.cache_on_arguments()(load_user_info)

print(inspect.getfullargspec(load_user_info))

print(load_user_info(value=5))

the above script in 0.7.x prints:

FullArgSpec(args=['value'], varargs=None, varkw=None, defaults=(0,), kwonlyargs=[], kwonlydefaults=None, annotations={})
FullArgSpec(args=['value'], varargs=None, varkw=None, defaults=(0,), kwonlyargs=[], kwonlydefaults=None, annotations={})
hi

that is, the argument signature is preserved perfectly and we see our load_user_info function acting identically as its non-cached version.

The old behavior looked like this:

FullArgSpec(args=['value'], varargs=None, varkw=None, defaults=(0,), kwonlyargs=[], kwonlydefaults=None, annotations={})
FullArgSpec(args=[], varargs='arg', varkw='kw', defaults=None, kwonlyargs=[], kwonlydefaults=None, annotations={})
Traceback (most recent call last):
  File "test.py", line 21, in <module>
    print(load_user_info(value=5))
  File "/home/classic/dev/dogpile.cache/dogpile/cache/region.py", line 1262, in decorate
    key = key_generator(*arg, **kw)
  File "/home/classic/dev/dogpile.cache/dogpile/cache/util.py", line 37, in generate_key
    "dogpile.cache's default key creation "
ValueError: dogpile.cache's default key creation function does not accept keyword arguments.

this is because the argument signature was blown away so that the arg/kw were passed generically. you can still get the ValueError if you add `**kw` to the argument signature for load_user_info() and then add some extra keywords.

in short I think oslo.cache can remove the test case here as indicated in https://review.openstack.org/#/c/638732/, because you are not only testing dogpile, you're testing plain python / the decorator module.

[Herve Beraud (herveberaud)]

Oslo.cache fix that follow the way proposed by Mike in the dogpile.cache issue.

https://review.openstack.org/#/c/638788/8/

But feel free to choose the remove way

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/638788
Committed: https://git.openstack.org/cgit/openstack/oslo.cache/commit/?id=b1f231f642c240daa4f73effff6fc8a029d580af
Submitter: Zuul
Branch: master

commit b1f231f642c240daa4f73effff6fc8a029d580af
Author: Hervé Beraud <email address hidden>
Date: Tue Feb 26 19:21:48 2019 +0100

    fix dogpile.cache issue due to the new usage of decorate in the lib

    Since few months ago dogpile.cache start to use the 'decorator' module
    on dogpile cache region to preserve signatures[1] within decorated
    functions.

    Since these changes was introduced and since oslo.cache have
    removed dogpile.cache version restriction this feature is now in use on
    oslo.cache and they introduce an issue on unit test where we use
    decorator to test return values.

    This patch introduce `**kw` passed to the decorated function to prevent
    issue due to 'decorator' on region.

    Openstacksdk was also impacted[2] by the changes introduced in dogpile 0.7.0.

    An issue was also opened on dogpile.cache side[3]

    [1] https://gerrit.sqlalchemy.org/#/c/sqlalchemy/dogpile.cache/+/996/
    [2] https://review.openstack.org/#/c/625370/4
    [3] https://github.com/sqlalchemy/dogpile.cache/issues/144

    Change-Id: Ic9370f36b14c1420eace874dd322183eba8df171
    Closes-Bug: #1817032

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/oslo.cache 1.33.1 release.