Keystone appears to initiate each new request using the previous' request-id

[Christian Sarrasin]

Environment
~~~~~~~~~~~
* openstack-ansible version: 16.0.2
* Target OS: Ubuntu 16.04 Xenial
* Keystone deployed in containers, running on uWSGI (per OSA defaults)
* Keystone baseline (as provided by OSA): 6a67918f9d5f39564af8eacc57b80cba98242683 # HEAD of "stable/pike" as of 28.09.2017

Symptom
~~~~~~~
When running Keystone with debug=True, one can observe in keystone.log that each incoming request appears to "borrow" the req Id from the previous one served by that particular uWSGI process.

Analysis
~~~~~~~~
This may be just cosmetic but one wonders if this is the indication of smth executing under the wrong context (and hence could have security implications?)

Evidence
~~~~~~~~
In this slightly edited log excerpt from a specific worker (11207): http://paste.openstack.org/show/642496/ one can for instance see that the request incoming at 20:30:38.035 borrows "req-e4456225-01a5-498e-9b73-ad9772a54781" from the previous request that completed execution at 20:30:25.962. The top of the log shows the same pattern and it's consistent throughout

Notes:
1. there's a ~5s delay before 20:30:25.957 which is a different issue (actually the one I was investigating which lead me to notice the pattern reported here
2. The log has been slightly edited: I removed the "UUID1 UUID2 default - default" suffix after the req Id for legibility (both UUIDs were constants); this is what allowed me to spot the issue.

[Colleen Murphy (krinkle)]

I can't quite reproduce this with devstack but I'm seeing a related strange issue where there's no request ID at all for the "Authenticating user token" log: http://paste.openstack.org/show/652190/

Not sure if either of these are caused by keystone or by oslo.middleware. Could you share your keystone-paste.ini file?

[Christian Sarrasin (sxc731)]

Hi Colleen,

keystone-paste.ini pasted below. This is out-of-the-box configuration generated by OSA 16.0.2.

# Keystone PasteDeploy configuration file.

[filter:debug]
use = egg:oslo.middleware#debug

[filter:request_id]
use = egg:oslo.middleware#request_id

[filter:build_auth_context]
use = egg:keystone#build_auth_context

[filter:token_auth]
use = egg:keystone#token_auth

[filter:json_body]
use = egg:keystone#json_body

[filter:cors]
use = egg:oslo.middleware#cors
oslo_config_project = keystone

[filter:http_proxy_to_wsgi]
use = egg:oslo.middleware#http_proxy_to_wsgi

[filter:healthcheck]
use = egg:oslo.middleware#healthcheck

[filter:ec2_extension]
use = egg:keystone#ec2_extension

[filter:ec2_extension_v3]
use = egg:keystone#ec2_extension_v3

[filter:s3_extension]
use = egg:keystone#s3_extension

[filter:url_normalize]
use = egg:keystone#url_normalize

[filter:sizelimit]
use = egg:oslo.middleware#sizelimit

[filter:osprofiler]
use = egg:osprofiler#osprofiler

[app:public_service]
use = egg:keystone#public_service

[app:service_v3]
use = egg:keystone#service_v3

[app:admin_service]
use = egg:keystone#admin_service

[pipeline:public_api]
# The last item in this pipeline must be public_service or an equivalent
# application. It cannot be a filter.
pipeline = healthcheck cors sizelimit http_proxy_to_wsgi osprofiler url_normalize request_id build_auth_context token_auth json_body ec2_extension public_service

[pipeline:admin_api]
# The last item in this pipeline must be admin_service or an equivalent
# application. It cannot be a filter.
pipeline = healthcheck cors sizelimit http_proxy_to_wsgi osprofiler url_normalize request_id build_auth_context token_auth json_body ec2_extension s3_extension admin_service

[pipeline:api_v3]
# The last item in this pipeline must be service_v3 or an equivalent
# application. It cannot be a filter.
pipeline = healthcheck cors sizelimit http_proxy_to_wsgi osprofiler url_normalize request_id build_auth_context token_auth json_body ec2_extension_v3 s3_extension service_v3

[app:public_version_service]
use = egg:keystone#public_version_service

[app:admin_version_service]
use = egg:keystone#admin_version_service

[pipeline:public_version_api]
pipeline = healthcheck cors sizelimit osprofiler url_normalize public_version_service

[pipeline:admin_version_api]
pipeline = healthcheck cors sizelimit osprofiler url_normalize admin_version_service

[composite:main]
use = egg:Paste#urlmap
/v2.0 = public_api
/v3 = api_v3
/ = public_version_api

[composite:admin]
use = egg:Paste#urlmap
/v2.0 = admin_api
/v3 = api_v3
/ = admin_version_api

[Morgan Fainberg (mdrnstm)]

Is this still relevant? marking as incomplete, I'd like confirmation and if so we can work to fix it. Many things have changed since this bug was filed

[Launchpad Janitor (janitor)]

[Expired for OpenStack Identity (keystone) because there has been no activity for 60 days.]

[Lance Bragstad (lbragstad)]

I enabled logging and attempt to recreate this by listing users and listing endpoint. Based on what I can tell, the request IDs are specific to the request being made and aren't carrying over to other requests [0].

Marking this as invalid for the time being. Please feel free to re-open if you suspect this is still an issue.

[0] https://pasted.tech/pastes/7f04af7dd3efe0fb45d87d522e6eb262bf1c658f.raw