test_auth_token_middleware fails when using latest keystoneclient

[Joshua Harlow]

Currently it appears there is some test failure that is happening when running the unit tests. Possibly something isn't mocked out correctly? Unsure how this passed CI...

Anvil test failure:

======================================================================
ERROR: test_memcache_set_expired (test_auth_token_middleware.AuthTokenMiddlewareTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/harlowja/openstack/keystone/app/tests/test_auth_token_middleware.py", line 636, in test_memcache_set_expired
    self.middleware(req.environ, self.start_fake_response)
  File "/home/harlowja/openstack/keystone-client/app/keystoneclient/middleware/auth_token.py", line 344, in __call__
    token_info = self._validate_user_token(user_token)
  File "/home/harlowja/openstack/keystone-client/app/keystoneclient/middleware/auth_token.py", line 579, in _validate_user_token
    self._cache_store_invalid(user_token)
  File "/home/harlowja/openstack/keystone-client/app/keystoneclient/middleware/auth_token.py", line 794, in _cache_store_invalid
    self._cache_store(token, 'invalid')
  File "/home/harlowja/openstack/keystone-client/app/keystoneclient/middleware/auth_token.py", line 771, in _cache_store
    timeout=self.token_cache_time)
TypeError: set() got an unexpected keyword argument 'timeout'
-------------------- >> begin captured logging << --------------------
keystoneclient.middleware.auth_token: INFO: Starting keystone auth_token middleware
keystoneclient.middleware.auth_token: INFO: Using /home/harlowja/openstack/keystone/app/examples/pki/certs as cache directory for signing certificate
keystoneclient.middleware.auth_token: DEBUG: Authenticating user token
keystoneclient.middleware.auth_token: DEBUG: Removing headers from request environment: X-Identity-Status,X-Tenant-Id,X-Tenant-Name,X-User-Id,X-User-Name,X-Roles,X-Service-Catalog,X-User,X-Tenant,X-Role
keystoneclient.middleware.auth_token: DEBUG: Cached Token f86032107074597fd03ad639b968bf6a seems expired
keystoneclient.middleware.auth_token: DEBUG: Storing f86032107074597fd03ad639b968bf6a token in memcache
keystoneclient.middleware.auth_token: DEBUG: Token validation failure.
Traceback (most recent call last):
  File "/home/harlowja/openstack/keystone-client/app/keystoneclient/middleware/auth_token.py", line 575, in _validate_user_token
    self._cache_put(token_id, data)
  File "/home/harlowja/openstack/keystone-client/app/keystoneclient/middleware/auth_token.py", line 787, in _cache_put
    self._cache_store(token, data, expires)
  File "/home/harlowja/openstack/keystone-client/app/keystoneclient/middleware/auth_token.py", line 771, in _cache_store
    timeout=self.token_cache_time)
TypeError: set() got an unexpected keyword argument 'timeout'
keystoneclient.middleware.auth_token: DEBUG: Marking token MIIHQAYJKoZIhvcNAQcCoIIHMTCCBy0CAQExCTAHBgUrDgMCGjCCBc4GCSqGSIb3DQEHAaCCBb8EggW7eyJhY2Nlc3MiOiB7InNlcnZpY2VDYXRhbG9nIjogW3siZW5kcG9pbnRzIjogW3siYWRtaW5VUkwiOiAiaHR0cDovLzEyNy4wLjAuMTo4Nzc2L3YxLzY0YjZmM2ZiY2M1MzQzNWU4YTYwZmNmODliYjY2MTdhIiwgInJlZ2lvbiI6ICJyZWdpb25PbmUiLCAiaW50ZXJuYWxVUkwiOiAiaHR0cDovLzEyNy4wLjAuMTo4Nzc2L3YxLzY0YjZmM2ZiY2M1MzQzNWU4YTYwZmNmODliYjY2MTdhIiwgInB1YmxpY1VSTCI6ICJodHRwOi8vMTI3LjAuMC4xOjg3NzYvdjEvNjRiNmYzZmJjYzUzNDM1ZThhNjBmY2Y4OWJiNjYxN2EifV0sICJlbmRwb2ludHNfbGlua3MiOiBbXSwgInR5cGUiOiAidm9sdW1lIiwgIm5hbWUiOiAidm9sdW1lIn0sIHsiZW5kcG9pbnRzIjogW3siYWRtaW5VUkwiOiAiaHR0cDovLzEyNy4wLjAuMTo5MjkyL3YxIiwgInJlZ2lvbiI6ICJyZWdpb25PbmUiLCAiaW50ZXJuYWxVUkwiOiAiaHR0cDovLzEyNy4wLjAuMTo5MjkyL3YxIiwgInB1YmxpY1VSTCI6ICJodHRwOi8vMTI3LjAuMC4xOjkyOTIvdjEifV0sICJlbmRwb2ludHNfbGlua3MiOiBbXSwgInR5cGUiOiAiaW1hZ2UiLCAibmFtZSI6ICJnbGFuY2UifSwgeyJlbmRwb2ludHMiOiBbeyJhZG1pblVSTCI6ICJodHRwOi8vMTI3LjAuMC4xOjg3NzQvdjEuMS82NGI2ZjNmYmNjNTM0MzVlOGE2MGZjZjg5YmI2NjE3YSIsICJyZWdpb24iOiAicmVnaW9uT25lIiwgImludGVybmFsVVJMIjogImh0dHA6Ly8xMjcuMC4wLjE6ODc3NC92MS4xLzY0YjZmM2ZiY2M1MzQzNWU4YTYwZmNmODliYjY2MTdhIiwgInB1YmxpY1VSTCI6ICJodHRwOi8vMTI3LjAuMC4xOjg3NzQvdjEuMS82NGI2ZjNmYmNjNTM0MzVlOGE2MGZjZjg5YmI2NjE3YSJ9XSwgImVuZHBvaW50c19saW5rcyI6IFtdLCAidHlwZSI6ICJjb21wdXRlIiwgIm5hbWUiOiAibm92YSJ9LCB7ImVuZHBvaW50cyI6IFt7ImFkbWluVVJMIjogImh0dHA6Ly8xMjcuMC4wLjE6MzUzNTcvdjIuMCIsICJyZWdpb24iOiAiUmVnaW9uT25lIiwgImludGVybmFsVVJMIjogImh0dHA6Ly8xMjcuMC4wLjE6MzUzNTcvdjIuMCIsICJwdWJsaWNVUkwiOiAiaHR0cDovLzEyNy4wLjAuMTo1MDAwL3YyLjAifV0sICJlbmRwb2ludHNfbGlua3MiOiBbXSwgInR5cGUiOiAiaWRlbnRpdHkiLCAibmFtZSI6ICJrZXlzdG9uZSJ9XSwidG9rZW4iOiB7ImV4cGlyZXMiOiAiMjAxMi0wNi0wMlQxNDo0NzozNFoiLCAiaWQiOiAicGxhY2Vob2xkZXIiLCAidGVuYW50IjogeyJlbmFibGVkIjogdHJ1ZSwgImRlc2NyaXB0aW9uIjogbnVsbCwgIm5hbWUiOiAidGVuYW50X25hbWUxIiwgImlkIjogInRlbmFudF9pZDEifX0sICJ1c2VyIjogeyJ1c2VybmFtZSI6ICJ1c2VyX25hbWUxIiwgInJvbGVzX2xpbmtzIjogWyJyb2xlMSIsInJvbGUyIl0sICJpZCI6ICJ1c2VyX2lkMSIsICJyb2xlcyI6IFt7Im5hbWUiOiAicm9sZTEifSwgeyJuYW1lIjogInJvbGUyIn1dLCAibmFtZSI6ICJ1c2VyX25hbWUxIn19fQ0KMYIBSTCCAUUCAQEwgaQwgZ4xCjAIBgNVBAUTATUxCzAJBgNVBAYTAlVTMQswCQYDVQQIEwJDQTESMBAGA1UEBxMJU3Vubnl2YWxlMRIwEAYDVQQKEwlPcGVuU3RhY2sxETAPBgNVBAsTCEtleXN0b25lMSUwIwYJKoZIhvcNAQkBFhZrZXlzdG9uZUBvcGVuc3RhY2sub3JnMRQwEgYDVQQDEwtTZWxmIFNpZ25lZAIBETAHBgUrDgMCGjANBgkqhkiG9w0BAQEFAASBgEWUF++cnK20YBvO8kcIsVkCsg3M+oVAHGleCQZr8ho2yvgQ06hlPYl95Ih6+wIHsUlO1EUxCmNBAdydGDzuonWvkHMN-KMv-PW4EbiuawpvqYYLxqRg3ADjIMNlfxcgEbY34WAe3dYs2IAGiN70jFbqTr3ltxWHRTeeAqeltio9 as unauthorized in memcache
--------------------- >> end captured logging << ---------------------

======================================================================
ERROR: test_memcache_set_invalid (test_auth_token_middleware.AuthTokenMiddlewareTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/harlowja/openstack/keystone/app/tests/test_auth_token_middleware.py", line 627, in test_memcache_set_invalid
    self.middleware(req.environ, self.start_fake_response)
  File "/home/harlowja/openstack/keystone-client/app/keystoneclient/middleware/auth_token.py", line 344, in __call__
    token_info = self._validate_user_token(user_token)
  File "/home/harlowja/openstack/keystone-client/app/keystoneclient/middleware/auth_token.py", line 579, in _validate_user_token
    self._cache_store_invalid(user_token)
  File "/home/harlowja/openstack/keystone-client/app/keystoneclient/middleware/auth_token.py", line 794, in _cache_store_invalid
    self._cache_store(token, 'invalid')
  File "/home/harlowja/openstack/keystone-client/app/keystoneclient/middleware/auth_token.py", line 771, in _cache_store
    timeout=self.token_cache_time)
TypeError: set() got an unexpected keyword argument 'timeout'
-------------------- >> begin captured logging << --------------------
keystoneclient.middleware.auth_token: INFO: Starting keystone auth_token middleware
keystoneclient.middleware.auth_token: INFO: Using /home/harlowja/openstack/keystone/app/examples/pki/certs as cache directory for signing certificate
keystoneclient.middleware.auth_token: DEBUG: Authenticating user token
keystoneclient.middleware.auth_token: DEBUG: Removing headers from request environment: X-Identity-Status,X-Tenant-Id,X-Tenant-Name,X-User-Id,X-User-Name,X-Roles,X-Service-Catalog,X-User,X-Tenant,X-Role
keystoneclient.middleware.auth_token: DEBUG: Keystone did not return json-encoded body
keystoneclient.middleware.auth_token: DEBUG: Marking token invalid-token as unauthorized in memcache
keystoneclient.middleware.auth_token: DEBUG: Token validation failure.
Traceback (most recent call last):
  File "/home/harlowja/openstack/keystone-client/app/keystoneclient/middleware/auth_token.py", line 574, in _validate_user_token
    data = self.verify_uuid_token(user_token, retry)
  File "/home/harlowja/openstack/keystone-client/app/keystoneclient/middleware/auth_token.py", line 824, in verify_uuid_token
    self._cache_store_invalid(user_token)
  File "/home/harlowja/openstack/keystone-client/app/keystoneclient/middleware/auth_token.py", line 794, in _cache_store_invalid
    self._cache_store(token, 'invalid')
  File "/home/harlowja/openstack/keystone-client/app/keystoneclient/middleware/auth_token.py", line 771, in _cache_store
    timeout=self.token_cache_time)
TypeError: set() got an unexpected keyword argument 'timeout'
keystoneclient.middleware.auth_token: DEBUG: Marking token invalid-token as unauthorized in memcache
--------------------- >> end captured logging << ---------------------

Slowest 5 tests took 5.03 secs:
    1.52 TokenExpirationTest.test_maintain_uuid_token_expiration
    0.90 IdentityTestCase.test_remove_user_from_group
    0.88 IdentityTestCase.test_delete_group_project_grant
    0.88 IdentityTestCase.test_list_users
    0.86 IdentityTestCase.test_list_domains
----------------------------------------------------------------------
Ran 520 tests in 61.878s

FAILED (SKIP=2, errors=2)
 ___________________
< Fetchez la vache! >
 -------------------
  \ || ||
    \ __ ||-----mm||
      \ ( )/_________)//
        (oo)/
        v--v
ProcessExecutionError: Unexpected error while running command.
Command: /home/harlowja/openstack/keystone/app/run_tests.sh -N --no-pep8 --exclude=test_swift_auth_middleware --exclude=test_s3_token_middleware --exclude=test_backend_memcache --exclude=test_nomemcache --exclude=test_backend_ldap -xintegration
Exit code: 1
Stdout: ''
Stderr: ''

System info:

$ lsb_release -a
LSB Version: :core-4.0-amd64:core-4.0-noarch:graphics-4.0-amd64:graphics-4.0-noarch:printing-4.0-amd64:printing-4.0-noarch
Distributor ID: RedHatEnterpriseServer
Description: Red Hat Enterprise Linux Server release 6.3 (Santiago)
Release: 6.3
Codename: Santiago

Pip packages:

$ pip-python freeze
Babel==0.9.6
Cheetah==2.4.4
Jinja2==2.2.1
Magic-file-extensions==0.1
Markdown==2.2.1
MySQL-python==1.2.3c1
PIL==1.1.6
Paste==1.7.4
PasteDeploy==1.5.0
PyYAML==3.10
Pygments==1.1.1
Routes==1.12.3
SQLAlchemy==0.7.9
Tempita==0.5.1
WebOb==1.2.3
WebTest==1.4.3
amqplib==1.0.2
anyjson==0.3.1
argparse==1.2.1
boto==2.5.2
cas==0.15
cliff==1.3
cliff-tablib==1.0
cloud-init==0.7.2
cmd2==0.6.4
colorama==0.2.4
configobj==4.6.0
coverage==3.6
decorator==3.4.0
discover==0.4.0
distribute==0.6.10
docutils==0.6
egenix-mx-base==3.1.1
eventlet==0.9.17
extras==0.0.3
feedparser==5.0.1
fixtures==0.3.12
-e git://github.com/openstack/glance.git@7feecf19eaeeaf19b68b2b4001e28759f8852788#egg=glance-2013.1.a50.g7feecf1-py2.6-dev
greenlet==0.3.1
hgtools==2.0.2
httplib2==0.7.7
iniparse==0.3.1
iotop==0.3.2
iso8601==0.1.4
jsonschema==0.2
keyring==1.2
-e git://github.com/openstack/keystone.git@5bc46d861e9c8f355d2bdd68912be3e64c2dc9e9#egg=keystone-2013.1-py2.6-dev
kombu==1.1.3
lockfile==0.8
logilab-astng==0.20.1
logilab-common==0.50.3
lxml==2.3.5
mock==0.8.0
mox==0.5.3
netaddr==0.7.5
netifaces==0.5
netsnmp-python==1.0a1
nose-exclude==0.1.9
nosehtmloutput==0.0.4
nosexcover==1.0.7
-e git://github.com/openstack/nova.git@a1072dd7da33243326c72256a7ee72f8a815ffd1#egg=nova-2013.1-py2.6-dev
oauth==1.0.1
openstack.nose-plugin==0.11
ordereddict==1.1
pam==0.1.4
paramiko==1.7.5
passlib==1.5.3
pep8==1.4.1
perf==0.1
pretty==0.1
prettytable==0.6.1
progressbar==2.2
psutil==0.4.1
pyOpenSSL==0.10
pycrypto==2.6
pycurl==7.19.0
pygpgme==0.1
pylint==0.21.1
pyparsing==1.5.6
pysendfile==2.0.0
-e git://github.com/openstack/python-cinderclient.git@f0a6dee19f573d260f8028106e66842451f82e21#egg=python_cinderclient-1.0.2.11.gf0a6dee-py2.6-dev
python-dateutil==1.4.1
python-distutils-extra==2.32
python-dmidecode==3.10.13
-e git://github.com/openstack/python-glanceclient.git@ed67c320144c74bd56f64e421ca069c6555771d6#egg=python_glanceclient-0.7.0_12_ged67c32-py2.6-dev
-e git://github.com/openstack/python-keystoneclient.git@92bf8a7af9b742e4b96689cccea1186b38ca41bf#egg=python_keystoneclient-0.2.2_21_g92bf8a7-py2.6-dev
-e git://github.com/openstack/python-novaclient.git@3ca976d4a076c13c7d68de859a8821cc281c9271#egg=python_novaclient-2.10.0_89_g3ca976d-py2.6-dev
-e git://github.com/openstack/python-openstackclient.git@b26cb5bf683e7f4f03d9704524a188b76ac5e9b9#egg=python_openstackclient-b26cb5b-py2.6-dev
-e git://github.com/openstack/python-quantumclient.git@2bca8ee4407aee03a83592395d3191f097c459a5#egg=python_quantumclient-2.1_40_g2bca8ee-py2.6-dev
python-subunit==0.0.9
raidctl==0.0.7
requests==0.14.2
setuptools-git==1.0b1
simplejson==2.0.9
sqlalchemy-migrate==0.7.2
stevedore==0.8
suds==0.4
tablib==0.9.11
termcolor==1.1.0
testrepository==0.0.13
testtools==0.9.27
unittest2==0.5.1
urlgrabber==3.9.1
warlock==0.4.0
websockify==0.2.0
wsgiref==0.1.2
xattr==0.6.4
yum-metadata-parser==1.1.2
yum-presto==0.4.4

[Jay Buffington (jaybuff)]

I suspect the CI tests on jenkins.openstack.org succeeded because it is using keystoneclient 0.2.2 rather than the latest from git.

Commit 3dfb8437 in keystoneclient introduced a flag called _use_keystone_cache in keystoneclient/middleware/auth_token.py (in _cache_store):

        # we need to special-case set() because of the incompatibility between
        # Swift MemcacheRing and python-memcached. See
        # https://bugs.launchpad.net/swift/+bug/1095730
        if self._use_keystone_cache:
            self._cache.set(key,
                            data_to_store,
                            time=self.token_cache_time)
        else:
            self._cache.set(key,
                            data_to_store,
                            timeout=self.token_cache_time)

That flag is set to false in the keystone tests even though they are using "FakeMemcache" which should use the time= kwarg rather than timeout.

Since LP 1095730 has been resolved I think the _use_keystone_cache flag can be removed altogether and this integration bug between keystone and keystoneclient will be resolved.

[Ionuț Arțăriși (mapleoin)]

This was fixed: https://review.openstack.org/#/c/21964/