Keystone client racing on certificate lookups causing 401 Unauthorized on API calls

[Joe Gordon]

DEBUG keystoneclient.middleware.auth_token [-] Token validation failure. _validate_user_token /opt/stack/new/python-keystoneclient/keystoneclient/middleware/auth_token.py:849
TRACE keystoneclient.middleware.auth_token Traceback (most recent call last):
TRACE keystoneclient.middleware.auth_token File "/opt/stack/new/python-keystoneclient/keystoneclient/middleware/auth_token.py", line 836, in _validate_user_token
TRACE keystoneclient.middleware.auth_token verified = self.verify_signed_token(user_token)
TRACE keystoneclient.middleware.auth_token File "/opt/stack/new/python-keystoneclient/keystoneclient/middleware/auth_token.py", line 1275, in verify_signed_token
TRACE keystoneclient.middleware.auth_token if self.is_signed_token_revoked(signed_text):
TRACE keystoneclient.middleware.auth_token File "/opt/stack/new/python-keystoneclient/keystoneclient/middleware/auth_token.py", line 1233, in is_signed_token_revoked
TRACE keystoneclient.middleware.auth_token revocation_list = self.token_revocation_list
TRACE keystoneclient.middleware.auth_token File "/opt/stack/new/python-keystoneclient/keystoneclient/middleware/auth_token.py", line 1329, in token_revocation_list
TRACE keystoneclient.middleware.auth_token self.token_revocation_list = self.fetch_revocation_list()
TRACE keystoneclient.middleware.auth_token File "/opt/stack/new/python-keystoneclient/keystoneclient/middleware/auth_token.py", line 1366, in fetch_revocation_list
TRACE keystoneclient.middleware.auth_token return self.cms_verify(data['signed'])
TRACE keystoneclient.middleware.auth_token File "/opt/stack/new/python-keystoneclient/keystoneclient/middleware/auth_token.py", line 1257, in cms_verify
TRACE keystoneclient.middleware.auth_token self.signing_ca_file_name)
TRACE keystoneclient.middleware.auth_token File "/opt/stack/new/python-keystoneclient/keystoneclient/common/cms.py", line 134, in cms_verify
TRACE keystoneclient.middleware.auth_token raise exceptions.CertificateConfigError(err)
TRACE keystoneclient.middleware.auth_token CertificateConfigError: Unable to load certificate. Ensure your system is configured properly.
TRACE keystoneclient.middleware.auth_token
DEBUG keystoneclient.middleware.auth_token [-] Marking token a961b45e3f117dd58b4afc6564d556fa as unauthorized in memcache _cache_store_invalid /opt/stack/new/python-keystoneclient/keystoneclient/middleware/auth_token.py:1170
WARNING keystoneclient.middleware.auth_token [-] Authorization failed for token a961b45e3f117dd58b4afc6564d556fa
INFO keystoneclient.middleware.auth_token [-] Invalid user token - rejecting request
INFO eventlet.wsgi.server [-] 127.0.0.1 - - [27/Feb/2014 16:50:36] "POST /v1/4ef47f119bc04d6dae054a5035359641/volumes HTTP/1.1" 401 191 0.299349

http://logs.openstack.org/35/75535/1/gate/gate-grenade-dsvm/3c8e07e/logs/new/screen-c-api.txt.gz?#_2014-02-27_16_50_36_158

logstash query: message:"CertificateConfigError: Unable to load certificate. Ensure your system is configured properly." AND NOT filename:"logs/screen-n-api.txt"

[Matt Riedemann (mriedem)]

message:"CertificateConfigError: Unable to load certificate. Ensure your system is configured properly." AND filename:logs*screen-c-api.txt

http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOlwiQ2VydGlmaWNhdGVDb25maWdFcnJvcjogVW5hYmxlIHRvIGxvYWQgY2VydGlmaWNhdGUuIEVuc3VyZSB5b3VyIHN5c3RlbSBpcyBjb25maWd1cmVkIHByb3Blcmx5LlwiIEFORCBmaWxlbmFtZTpsb2dzKnNjcmVlbi1jLWFwaS50eHQiLCJmaWVsZHMiOltdLCJvZmZzZXQiOjAsInRpbWVmcmFtZSI6IjYwNDgwMCIsImdyYXBobW9kZSI6ImNvdW50IiwidGltZSI6eyJ1c2VyX2ludGVydmFsIjowfSwic3RhbXAiOjEzOTM1MjkzNDM3MDZ9

[Joe Gordon (jogo)]

This appears to be new, this bug started happening on Feb 23rd

[Matt Riedemann (mriedem)]

From logstash this started showing around 2/23.

It also hits heat:

http://logs.openstack.org/55/59655/23/check/check-tempest-dsvm-postgres-full/5684a8a/logs/screen-h-api.txt

e-r query patch here:

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

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/77215
Committed: https://git.openstack.org/cgit/openstack/python-keystoneclient/commit/?id=b935741f6c93abae1c7aac41da92b475bbe14815
Submitter: Jenkins
Branch: master

commit b935741f6c93abae1c7aac41da92b475bbe14815
Author: Adam Young <email address hidden>
Date: Fri Feb 28 11:28:01 2014 -0500

    Atomic write of certificate files and revocation list

    Using a rename from a temporary file to avoid having partial writes.

    Closes-Bug: #1285833

    Change-Id: I3e70c795be357ceab8e5a1d12202c04fd88a02b8

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/78448
Committed: https://git.openstack.org/cgit/openstack/python-keystoneclient/commit/?id=8efb0211669f344812ae9a7d2b5435a68a9a2687
Submitter: Jenkins
Branch: master

commit 8efb0211669f344812ae9a7d2b5435a68a9a2687
Author: Morgan Fainberg <email address hidden>
Date: Wed Mar 5 15:15:15 2014 -0800

    Log the command output on CertificateConfigError

    In auth_token middleware if the CertificateConfigError is raise for a reason
    other than the certificate file missing or the ca cert file missing, log the
    actual output from the verify comment to aid in correcting the issue.

    Related-Bug: #1285833
    Change-Id: I6b469b9037b7ef59993132f87a75152149ee6310

[Sean Dague (sdague)]

Seeing this again in Heat tests in the gate - http://logs.openstack.org/75/84475/1/check/check-tempest-dsvm-neutron-heat-slow/b130a0d/logs/screen-h-api.txt.gz?level=INFO#_2014-04-07_11_05_57_832

[Attila Fazekas (afazekas)]

Another heat case: http://logs.openstack.org/34/81834/8/check/check-tempest-dsvm-neutron-heat-slow/0976a2d/logs/screen-h-api.txt.gz#_2014-04-08_13_26_47_942

[Sean Dague (sdague)]

This is currently the #1 race bug in the gate. Making it critical on Heat and Keystone.

[Adam Young (ayoung)]

This is not the same issue. For example; one retry reported against this bug has this log:

http://logs.openstack.org/57/85757/2/check/check-tempest-dsvm-neutron-heat-slow/4744995/logs/tempest.txt.gz

the 401 does not happen on the first attempt to authenticate, rather it happens later, and is likely a result of a different auth failure.

Search for POST http://10.6.188.15:8004/v1/15ded6033b2d4b08ba8e2f0fc03646a1

and you will see it completes successfully.

[Adam Young (ayoung)]

2014-04-08 13:26:47.942 24160 TRACE keystoneclient.middleware.auth_token self.signing_ca_file_name)
2014-04-08 13:26:47.942 24160 TRACE keystoneclient.middleware.auth_token File "/opt/stack/new/python-keystoneclient/keystoneclient/common/cms.py", line 134, in cms_verify
2014-04-08 13:26:47.942 24160 TRACE keystoneclient.middleware.auth_token raise exceptions.CertificateConfigError(err)
2014-04-08 13:26:47.942 24160 TRACE keystoneclient.middleware.auth_token CertificateConfigError: Unable to load certificate. Ensure your system is configured properly.
2014-04-08 13:26:47.942 24160 TRACE keystoneclient.middleware.auth_token

That stack trace shows this to be a different error: an exception thrown by cmy.py is not properly being caught by auth_token.py

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

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

[Dolph Mathews (dolph)]

To add to Adam's comment above, this is *another* race condition with the exact same symptoms as the one we previously fixed - this is not a regression of the previous issue, but it's closely related.

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/86321
Committed: https://git.openstack.org/cgit/openstack/python-keystoneclient/commit/?id=ebfaf10357a0ff5f635e9ff9092adae1338f7415
Submitter: Jenkins
Branch: master

commit ebfaf10357a0ff5f635e9ff9092adae1338f7415
Author: Dolph Mathews <email address hidden>
Date: Wed Apr 9 08:09:09 2014 -0500

    eliminate race condition fetching certs

    There's a race between the time that a CertificateConfigError is raised,
    and when we check to see what caused it. Eliminating the checks and
    unconditionally fetching certificates eliminates the race.

    Giant thanks to Jamie Lennox for identifying the root cause described
    above!

    Co-Authored-By: David Stanek <email address hidden>
    Change-Id: I19113496ceaecdc03e209d550e0db156df95f9b8
    Closes-Bug: 1285833

[Steve Baker (steve-stevebaker)]

No longer affects heat, fixed in released python-keystoneclient

[Joe Gordon (jogo)]

This appears to be back: message:"CertificateConfigError: Unable to load certificate. Ensure your system is configured properly."

has 2 hits

[Joe Gordon (jogo)]

And fixed.

[Adam Huffman (adam-huffman)]

I'm seeing this with Glance:

python-glance-2014.1-2.el6.noarch
openstack-glance-2014.1-2.el6.noarch
python-glanceclient-0.12.0-1.el6.noarch

python-keystoneclient-0.9.0-1.el6.noarch
python-keystone-2014.1.1-1.el6.noarch
openstack-keystone-2014.1.1-1.el6.noarch

2014-07-14 17:06:58.418 6033 DEBUG urllib3.connectionpool [-] "GET /v3/OS-SIMPLE-CERT/certificates HTTP/1.1" 404 93 _make_request /usr/lib/python2.6/site-packages/urllib3/connectionpool.py:295
2014-07-14 17:06:58.420 6033 DEBUG keystoneclient.middleware.auth_token [-] Token validation failure. _validate_user_token /usr/lib/python2.6/site-packages/keystoneclient/middleware/auth_token.py:943
2014-07-14 17:06:58.420 6033 TRACE keystoneclient.middleware.auth_token Traceback (most recent call last):
2014-07-14 17:06:58.420 6033 TRACE keystoneclient.middleware.auth_token File "/usr/lib/python2.6/site-packages/keystoneclient/middleware/auth_token.py", line 930, in _validate_user_token
2014-07-14 17:06:58.420 6033 TRACE keystoneclient.middleware.auth_token verified = self.verify_signed_token(user_token, token_ids)
2014-07-14 17:06:58.420 6033 TRACE keystoneclient.middleware.auth_token File "/usr/lib/python2.6/site-packages/keystoneclient/middleware/auth_token.py", line 1347, in verify_signed_token
2014-07-14 17:06:58.420 6033 TRACE keystoneclient.middleware.auth_token if self.is_signed_token_revoked(token_ids):
2014-07-14 17:06:58.420 6033 TRACE keystoneclient.middleware.auth_token File "/usr/lib/python2.6/site-packages/keystoneclient/middleware/auth_token.py", line 1299, in is_signed_token_revoked
2014-07-14 17:06:58.420 6033 TRACE keystoneclient.middleware.auth_token if self._is_token_id_in_revoked_list(token_id):
2014-07-14 17:06:58.420 6033 TRACE keystoneclient.middleware.auth_token File "/usr/lib/python2.6/site-packages/keystoneclient/middleware/auth_token.py", line 1306, in _is_token_id_in_revoked_list
2014-07-14 17:06:58.420 6033 TRACE keystoneclient.middleware.auth_token revocation_list = self.token_revocation_list
2014-07-14 17:06:58.420 6033 TRACE keystoneclient.middleware.auth_token File "/usr/lib/python2.6/site-packages/keystoneclient/middleware/auth_token.py", line 1413, in token_revocation_list
2014-07-14 17:06:58.420 6033 TRACE keystoneclient.middleware.auth_token self.token_revocation_list = self.fetch_revocation_list()
2014-07-14 17:06:58.420 6033 TRACE keystoneclient.middleware.auth_token File "/usr/lib/python2.6/site-packages/keystoneclient/middleware/auth_token.py", line 1459, in fetch_revocation_list
2014-07-14 17:06:58.420 6033 TRACE keystoneclient.middleware.auth_token return self.cms_verify(data['signed'])
2014-07-14 17:06:58.420 6033 TRACE keystoneclient.middleware.auth_token File "/usr/lib/python2.6/site-packages/keystoneclient/middleware/auth_token.py", line 1333, in cms_verify
2014-07-14 17:06:58.420 6033 TRACE keystoneclient.middleware.auth_token self.fetch_signing_cert()
2014-07-14 17:06:58.420 6033 TRACE keystoneclient.middleware.auth_token File "/usr/lib/python2.6/site-packages/keystoneclient/middleware/auth_token.py", line 1477, in fetch_signing_cert
2014-07-14 17:06:58.420 6033 TRACE keystoneclient.middleware.auth_t...