OpenStack Identity (keystone)

memcache raising "too many values to unpack"

Bug #1600394 reported by Eric Brown on 2016-07-08

This bug affects 4 people

Affects		Status	Importance	Assigned to	Milestone
	OpenStack Identity (keystone)	Fix Released	Medium	Brant Knudson	OpenStack Identity (keystone) newton-3 "n3"

Bug Description

Found the following error in the keystone logs of our Mitaka deployment.

2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi [req-b256411d-ba72-4076-b644-ef08a5400ab2 66725b90caea4963b1b4f91f90ab1dee ab149973d5b84459bd3ece44074ec2aa - default default] too many values to unpack
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi Traceback (most recent call last):
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/keystone/common/wsgi.py", line 249, in __call__
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi result = method(context, **params)
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/keystone/common/controller.py", line 156, in inner
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi context['subject_token_id']))
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/keystone/common/manager.py", line 124, in wrapped
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi __ret_val = __f(*args, **kwargs)
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/keystone/token/provider.py", line 208, in validate_token
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi token = self._validate_token(unique_id)
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/dogpile/cache/region.py", line 1053, in decorate
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi should_cache_fn)
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/dogpile/cache/region.py", line 657, in get_or_create
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi async_creator) as value:
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/dogpile/core/dogpile.py", line 158, in __enter__
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi return self._enter()
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/dogpile/core/dogpile.py", line 98, in _enter
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi generated = self._enter_create(createdtime)
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/dogpile/core/dogpile.py", line 149, in _enter_create
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi created = self.creator()
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/dogpile/cache/region.py", line 625, in gen_value
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi created_value = creator()
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/dogpile/cache/region.py", line 1049, in creator
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi return fn(*arg, **kw)
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/keystone/token/provider.py", line 298, in _validate_token
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi return self.driver.validate_non_persistent_token(token_id)
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/keystone/token/providers/common.py", line 772, in validate_non_persistent_token
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi audit_info=audit_ids)
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/keystone/token/providers/common.py", line 526, in get_token_data
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi project_id, trust)
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/keystone/token/providers/common.py", line 469, in _populate_service_catalog
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi user_id, project_id)
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/keystone/common/manager.py", line 124, in wrapped
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi __ret_val = __f(*args, **kwargs)
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/dogpile/cache/region.py", line 1053, in decorate
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi should_cache_fn)
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/dogpile/cache/region.py", line 657, in get_or_create
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi async_creator) as value:
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/dogpile/core/dogpile.py", line 158, in __enter__
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi return self._enter()
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/dogpile/core/dogpile.py", line 91, in _enter
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi value = value_fn()
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/dogpile/cache/region.py", line 610, in get_value
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi value = self.backend.get(key)
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/keystone/common/cache/_context_cache.py", line 96, in get
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi value = self.proxied.get(key)
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/dogpile/cache/backends/memcached.py", line 161, in get
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi value = self.client.get(key)
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/oslo_cache/backends/memcache_pool.py", line 36, in _run_method
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi return getattr(client, __name)(*args, **kwargs)
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/memcache.py", line 1093, in get
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi return self._get('get', key)
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/memcache.py", line 1077, in _get
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi return _unsafe_get()
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/memcache.py", line 1059, in _unsafe_get
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi server, raise_exception=True
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/memcache.py", line 1211, in _expectvalue
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi resp, rkey, flags, len = line.split()
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi ValueError: too many values to unpack
2016-07-06 05:14:30.311 18314 ERROR keystone.common.wsgi
2016-07-06 05:14:30.321 18314 INFO eventlet.wsgi.server [req-b256411d-ba72-4076-b644-ef08a5400ab2 66725b90caea4963b1b4f91f90ab1dee ab149973d5b84459bd3ece44074ec2aa - default default] 10.111.109.87,10.111.109.89 - - [06/Jul/2016 05:14:30] "GET /v3/auth/tokens HTTP/1.1" 500 400 0.115269

And another...

2016-07-06 05:15:06.273 18314 DEBUG keystone.middleware.auth [req-de5f209c-27a5-4fdb-81af-34e01c2ca43a - - - - -] There is either no auth token in the request or the certificate issuer is not trusted. No auth context will be set. _build_auth_context /usr/lib/python2.7/dist-packages/keystone/middleware/auth.py:71
2016-07-06 05:15:06.276 18314 INFO keystone.common.wsgi [req-de5f209c-27a5-4fdb-81af-34e01c2ca43a - - - - -] POST http://10.111.109.81:35357/v2.0/tokens
2016-07-06 05:15:06.385 18314 ERROR keystone.common.wsgi [req-de5f209c-27a5-4fdb-81af-34e01c2ca43a - - - - -] too many values to unpack
2016-07-06 05:15:06.385 18314 ERROR keystone.common.wsgi Traceback (most recent call last):
2016-07-06 05:15:06.385 18314 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/keystone/common/wsgi.py", line 249, in __call__
2016-07-06 05:15:06.385 18314 ERROR keystone.common.wsgi result = method(context, **params)
2016-07-06 05:15:06.385 18314 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/oslo_log/versionutils.py", line 165, in wrapped
2016-07-06 05:15:06.385 18314 ERROR keystone.common.wsgi return func_or_cls(*args, **kwargs)
2016-07-06 05:15:06.385 18314 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/keystone/token/controllers.py", line 130, in authenticate
2016-07-06 05:15:06.385 18314 ERROR keystone.common.wsgi user_ref['id'], tenant_ref['id'])
2016-07-06 05:15:06.385 18314 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/keystone/common/manager.py", line 124, in wrapped
2016-07-06 05:15:06.385 18314 ERROR keystone.common.wsgi __ret_val = __f(*args, **kwargs)
2016-07-06 05:15:06.385 18314 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/dogpile/cache/region.py", line 1053, in decorate
2016-07-06 05:15:06.385 18314 ERROR keystone.common.wsgi should_cache_fn)
2016-07-06 05:15:06.385 18314 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/dogpile/cache/region.py", line 657, in get_or_create
2016-07-06 05:15:06.385 18314 ERROR keystone.common.wsgi async_creator) as value:
2016-07-06 05:15:06.385 18314 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/dogpile/core/dogpile.py", line 158, in __enter__
2016-07-06 05:15:06.385 18314 ERROR keystone.common.wsgi return self._enter()
2016-07-06 05:15:06.385 18314 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/dogpile/core/dogpile.py", line 91, in _enter
2016-07-06 05:15:06.385 18314 ERROR keystone.common.wsgi value = value_fn()
2016-07-06 05:15:06.385 18314 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/dogpile/cache/region.py", line 610, in get_value
2016-07-06 05:15:06.385 18314 ERROR keystone.common.wsgi value = self.backend.get(key)
2016-07-06 05:15:06.385 18314 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/keystone/common/cache/_context_cache.py", line 96, in get
2016-07-06 05:15:06.385 18314 ERROR keystone.common.wsgi value = self.proxied.get(key)
2016-07-06 05:15:06.385 18314 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/dogpile/cache/backends/memcached.py", line 161, in get
2016-07-06 05:15:06.385 18314 ERROR keystone.common.wsgi value = self.client.get(key)
2016-07-06 05:15:06.385 18314 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/oslo_cache/backends/memcache_pool.py", line 36, in _run_method
2016-07-06 05:15:06.385 18314 ERROR keystone.common.wsgi return getattr(client, __name)(*args, **kwargs)
2016-07-06 05:15:06.385 18314 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/memcache.py", line 1093, in get
2016-07-06 05:15:06.385 18314 ERROR keystone.common.wsgi return self._get('get', key)
2016-07-06 05:15:06.385 18314 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/memcache.py", line 1077, in _get
2016-07-06 05:15:06.385 18314 ERROR keystone.common.wsgi return _unsafe_get()
2016-07-06 05:15:06.385 18314 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/memcache.py", line 1059, in _unsafe_get
2016-07-06 05:15:06.385 18314 ERROR keystone.common.wsgi server, raise_exception=True
2016-07-06 05:15:06.385 18314 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/memcache.py", line 1211, in _expectvalue
2016-07-06 05:15:06.385 18314 ERROR keystone.common.wsgi resp, rkey, flags, len = line.split()
2016-07-06 05:15:06.385 18314 ERROR keystone.common.wsgi ValueError: too many values to unpack
2016-07-06 05:15:06.385 18314 ERROR keystone.common.wsgi
2016-07-06 05:15:06.390 18314 INFO eventlet.wsgi.server [req-de5f209c-27a5-4fdb-81af-34e01c2ca43a - - - - -] 10.111.109.191,10.111.109.89 - - [06/Jul/2016 05:15:06] "POST /v2.0/tokens HTTP/1.1" 500 400 0.118120

Revision history for this message

David Stanek (dstanek) wrote on 2016-07-11:

This is a very strange error. On the surface it looks like memcached is returning an unexpected VALUE line. Are you able to dig into memcache and look for the same key? I'm curious as to what response you get. Below is an example telnet session where I set a key named 'key' to the value 'test' and then read it out of the cache. I also look for a key 'not_there' which is a key that is not in memcached.

    telnet localhost 11211
    Trying 127.0.0.1...
    Connected to localhost.
    Escape character is '^]'.
    set key 0 60 4
    test
    STORED
    get key
    VALUE key 0 4
    test
    END
    get not_there
    END
    quit
    Connection closed by foreign host.

Changed in keystone:
status:	New → Incomplete

Revision history for this message

Jakub Pavlik (pavlk-jakub) wrote on 2016-08-03:

Hello, I have same error. I tested against rally scenario 100 create and delete user. 2% fails

+-------------------------------------------------------------------------------------------------------------------------+
| Response Times (sec) |
+----------------------+-----------+--------------+--------------+--------------+-----------+-----------+---------+-------+
| Action | Min (sec) | Median (sec) | 90%ile (sec) | 95%ile (sec) | Max (sec) | Avg (sec) | Success | Count |
+----------------------+-----------+--------------+--------------+--------------+-----------+-----------+---------+-------+
| keystone.create_user | 0.16 | 0.358 | 1.638 | 2.72 | 3.678 | 0.736 | 98.0% | 100 |
| keystone.delete_user | 0.072 | 0.139 | 0.197 | 0.234 | 0.305 | 0.14 | 100.0% | 98 |
| total | 0.254 | 0.543 | 1.798 | 2.872 | 3.839 | 0.877 | 98.0% | 100 |
+----------------------+-----------+--------------+--------------+--------------+-----------+-----------+---------+-------+

Revision history for this message

Jakub Pavlik (pavlk-jakub) wrote on 2016-08-03:

Download full text (4.4 KiB)

There is log:

2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi [req-0c28644a-799b-41ea-af15-fd9039557ce9 - - - - -] too many values to unpack
2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi Traceback (most recent call last):
2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/keystone/common/wsgi.py", line 249, in __call__
2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi result = method(context, **params)
2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/oslo_log/versionutils.py", line 165, in wrapped
2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi return func_or_cls(*args, **kwargs)
2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/keystone/token/controllers.py", line 100, in authenticate
2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi context, auth)

There is log:

2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi [req-0c28644a-799b-41ea-af15-fd9039557ce9 - - - - -] too many values to unpack
2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi Traceback (most recent call last):
2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/dist-packages/keystone/common/wsgi.py", line 249, in __call__
2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi     result = method(context, **params)
2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/dist-packages/oslo_log/versionutils.py", line 165, in wrapped
2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi     return func_or_cls(*args, **kwargs)
2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/dist-packages/keystone/token/controllers.py", line 100, in authenticate
2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi     context, auth)

2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/dist-packages/keystone/token/controllers.py", line 309, in _authenticate_local                    [332/9850]
2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi     user_id, tenant_id)
2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/dist-packages/keystone/token/controllers.py", line 390, in _get_project_roles_and_ref
2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi     user_id, tenant_id)
2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/dist-packages/keystone/common/manager.py", line 124, in wrapped
2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi     __ret_val = __f(*args, **kwargs)
2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/dist-packages/dogpile/cache/region.py", line 1053, in decorate
2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi     should_cache_fn)
2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/dist-packages/dogpile/cache/region.py", line 657, in get_or_create
2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi     async_creator) as value:
2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/dist-packages/dogpile/core/dogpile.py", line 158, in __enter__
2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi     return self._enter()
2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/dist-packages/dogpile/core/dogpile.py", line 91, in _enter
2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi     value = value_fn()
2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/dist-packages/dogpile/cache/region.py", line 610, in get_value
2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi     value = self.backend.get(key)
2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/dist-packages/keystone/common/cache/_context_cache.py", line 96, in get
2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi     value = self.proxied.get(key)
2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/dist-packages/dogpile/cache/backends/memcached.py", line 161, in get
2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi     value = self.client.get(key)
2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/dist-packages/oslo_cache/backends/memcache_pool.py", line 36, in _run_method
2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi     return getattr(client, __name)(*args, **kwargs)
2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/dist-packages/memcache.py", line 1093, in get
2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi     return self._get('get', key)
2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/dist-packages/memcache.py", line 1077, in _get
2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi     return _unsafe_get()
2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/dist-packages/memcache.py", line 1059, in _unsafe_get
2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi     server, raise_exception=True
2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/dist-packages/memcache.py", line 1211, in _expectvalue
2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi     resp, rkey, flags, len = line.split()
2016-08-03 12:43:31.578 341 ERROR keystone.common.wsgi ValueError: too many values to unpack

Steve Martinelli (stevemar) on 2016-08-04

Changed in keystone:
status:	Incomplete → Confirmed

Revision history for this message

Brant Knudson (blk-u) wrote on 2016-08-04:

We hit this exact same issue in our own testing (on master).

Steve Martinelli (stevemar) on 2016-08-04

Changed in keystone:
importance:	Undecided → High
milestone:	none → newton-3

Steve Martinelli (stevemar) on 2016-08-04

summary:	- ValueError: too many values to unpack + memcache raising "too many values to unpack"
Changed in keystone:
importance:	High → Critical

Steve Martinelli (stevemar) on 2016-08-15

Changed in keystone:
assignee:	nobody → David Stanek (dstanek)

Revision history for this message

Brant Knudson (blk-u) wrote on 2016-08-24:

I actually hit this in a dev environment so I can set breakpoints and stuff. Will gather as much info as I can.

Note that I've got python-memcached==1.53 while the latest is python-memcached 1.58

Revision history for this message

Brant Knudson (blk-u) wrote on 2016-08-24:

Here's an example where I've added more debug info:

http://paste.openstack.org/show/563150/ -- output in the keystone log when there's an error. Shows that value that it got for the given key.

http://paste.openstack.org/show/563151/ -- displayed when I do get <key> on memcache.

So it looks like what keystone is seeing is missing a good chunk of the start of the value and that's confusing it.

Revision history for this message

Brant Knudson (blk-u) wrote on 2016-08-25:

What seems to work is setting enable-threads = False in the uwsgi config file.

I tried setting threads = 1 and still saw failures.

Revision history for this message

Brant Knudson (blk-u) wrote on 2016-08-25:

After adding some debug statements, I can see that what the keystone process is seeing as coming from memcache is the expected value but missing a large chunk at the front of it which causes an error of course.

When I disable threading for the wsgi container I don't hit this error.

So I'm going to propose disabling threading to fix this bug. Then we can have a follow-on story to investigate why threading causes a problem, because it shouldn't. Also, I was never able to recreate on a devstack system, so maybe it's got a fixed version of something memcache related.

Here's the debug statements that I added:

in /opt/bbc/openstack-11.0-master/keystone/local/lib/python2.7/site-packages/memcache.py, about line 1247:

            try:
              resp, rkey, flags, len = line.split()
            except Exception:
              raise Exception("error parsing line, line is %s" % line)

Then in /opt/bbc/openstack-11.0-master/keystone/local/lib/python2.7/site-packages/dogpile/cache/region.py, about line 781, in get_value():

        def get_value():
            try:
              value = self.backend.get(key)
            except Exception as e:
              raise Exception('key %r for %r gave %s' % (key, orig_key, e))

Here's the test I ran to show the problem: https://github.com/brantlk/keystone_samples/blob/master/revocation_event_test.py

I ran it in several windows at once:

./revocation_event_test.py --url https://10.10.0.11:5000/ --insecure --password <password>

Revision history for this message

Brant Knudson (blk-u) wrote on 2016-08-25:

Also, it's pretty easy to get the actual value from memcache, for example:

>>> import memcache
>>> mc = memcache.Client(['127.0.0.1:11211'], debug=0)
>>> len(mc.get('1921523d6734d44e88ed58dfc76ef681a36b8e9b')[0])
911

Revision history for this message

Steve Martinelli (stevemar) wrote on 2016-08-30:

#10

There is no patch for this bug so I am removing it from the milestone-3 target. I have also unassigned David.

Changed in keystone:
assignee:	David Stanek (dstanek) → nobody
milestone:	newton-3 → next
importance:	Critical → High

Revision history for this message

Brant Knudson (blk-u) wrote on 2016-08-31:

#11

This looks like it was caused by code where there were some sockets opened to memcached before uwsgi forked the different instances of the server. This caused different processes to be reading from / writing to the same socket and stomping on each other.

With http://git.openstack.org/cgit/openstack/keystone/commit/keystone/common/cache/core.py?id=42eda48c78f1153081b4c193dc13c88561409fd3 , I don't see memcache connections being opened before forking, so this problem should be fixed by that change.

I need to try this out some more but I think this is fixed.

Revision history for this message

Steve Martinelli (stevemar) wrote on 2016-08-31:

#12

Lowering severity since http://git.openstack.org/cgit/openstack/keystone/commit/keystone/common/cache/core.py?id=42eda48c78f1153081b4c193dc13c88561409fd3 may have resolved the issue.

Changed in keystone:
importance:	High → Medium

Revision history for this message

Brant Knudson (blk-u) wrote on 2016-08-31:

#13

Another way to fix this is to ensure that keystone is not forked after it's initialized. This can be done in uwsgi by setting lazy-apps=true (see https://review.openstack.org/#/c/357539/10/templates/keystone-uwsgi.ini.j2 )

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2016-08-31: Related fix proposed to keystone (master)

#14

Related fix proposed to branch: master
Review: https://review.openstack.org/363929

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2016-09-01: Related fix merged to keystone (master)

#15

Reviewed: https://review.openstack.org/363929
Committed: https://git.openstack.org/cgit/openstack/keystone/commit/?id=cc3e797bca464e75165c31db6e6c19e2b4db2fc4
Submitter: Jenkins
Branch: master

commit cc3e797bca464e75165c31db6e6c19e2b4db2fc4
Author: Brant Knudson <email address hidden>
Date: Wed Aug 31 15:41:21 2016 -0500

Update sample uwsgi config for lazy-apps

    Keystone had a problem where there was a memcached socket
    opened very early on startup which then got shared between
    worker processes when running under uwsgi. Since we don't have
    a test or a way to ensure that no sockets are opened too early
    for uwsgi, let's recommend setting lazy-apps to avoid issues.

Change-Id: I8b46c5424094d3abe9a986da4ee1143f72a91a4d
Related-Bug: 1600394

Revision history for this message

Steve Martinelli (stevemar) wrote on 2016-09-15:

#16

Brant, any feedback on whether or not changing the uwsgi setting solved the issue?

Changed in keystone:
milestone:	next → none

Revision history for this message

Brant Knudson (blk-u) wrote on 2016-09-19:

#17

Yes, in our environment we've changed the uwsgi setting and have not seen the problem.

Revision history for this message

Steve Martinelli (stevemar) wrote on 2016-09-19:

#18

Marking this as fix-released, the related change went into Mitaka-3

Changed in keystone:
milestone:	none → newton-3
assignee:	nobody → Brant Knudson (blk-u)
status:	Confirmed → Fix Released

Report a bug

This report contains Public information

Everyone can see this information.

You are

Subscribing...

Edit bug mail

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.