request-ids aren't being logged for any cinder.api.openstack.wsgi [-]

[Joe Gordon]

 request-ids aren't being logged for any cinder.api.openstack.wsgi [-]

Although request ids are logged for things like:

2015-03-19 02:18:09.900 5394 INFO cinder.api.v2.volumes [req-31f27442-7b3e-4bcb-84f7-2d84ff65f3f1 9039ff7c560e4b6591f34f629fe978f4 0c28fcc6ceac4288a51bb05721563d2c - - -] Create volume of 1 GB

They are missing for most of the cinder logs in cinder-api:

2015-03-19 02:18:09.899 5394 INFO cinder.api.openstack.wsgi [-] POST http://127.0.0.1:8776/v2/0c28fcc6ceac4288a51bb05721563d2c/volumes

http://logs.openstack.org/16/165616/2/check/check-tempest-dsvm-postgres-full/5cd3197/logs/screen-c-api.txt.gz?#_2015-03-19_02_28_04_252

This makes debugging failures signifanctly harder since you can't match the req-id from a failed command to the relevant cinder logs.

[Joe Gordon (jogo)]

Looks like heat returns a req-d but isn't logging it at all.

Heat returning a req-id to tempest:

2015-03-19 20:56:50.107 6523 DEBUG tempest_lib.common.rest_client [req-991d3a33-9cd1-4b6b-a695-bbc974d72329 ] Request (TemplateAWSNegativeTestJSON:test_validate_template_url): 400 POST http://10.0.3.227:8004/v1/cba288d959c7496fae645149aa00d518/validate 0.704s

Heat log without a request id being logged:

2015-03-19 02:19:31.720 5809 DEBUG eventlet.wsgi.server [-] 104.130.154.158 - - [19/Mar/2015 02:19:31] "GET /v1/69c7ac4c4ffc48c58abd1ca1b2b4e37b/stacks/heat-898236319/b72f742b-2cfe-4d25-b55d-45fc2b9038eb HTTP/1.1" 200 1043 0.444083 write /opt/stack/new/heat/heat/common/wsgi.py:182

[Joe Gordon (jogo)]

IMHO this bug is release critical for both cinder and heat, since returning request ids without logging the request id defeats the purpose of request ids.

[Matthew Treinish (treinish)]

Keystone doesn't log the request ids either:

http://logs.openstack.org/48/165548/4/gate/gate-tempest-dsvm-neutron-full/5cbdc8e/logs/apache/keystone.txt.gz?level=INFO#_2015-03-19_20_35_44_383968

request ids were only recently added to keystone with: https://review.openstack.org/#/c/155901/ I think to get the logging working we need to switch keystone from it's internal AuthContext dict to use OsloContext instead.

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/167080
Committed: https://git.openstack.org/cgit/openstack/cinder/commit/?id=19f2f2833adb484d30d120de3dc154fad4fe9f3d
Submitter: Jenkins
Branch: master

commit 19f2f2833adb484d30d120de3dc154fad4fe9f3d
Author: John Griffith <email address hidden>
Date: Tue Mar 24 03:08:15 2015 +0000

    Enable request-id in cinder API logs

    Using common.local:store.context doesn't work correctly with
    the new oslo_log module. This change removes the calls to
    common.local and removes the file altogether which allows the
    proper settings to be passed in to the logging module and give
    us back our request-id in the API logs.

    Change-Id: If312f419fb465c9128bcfa0a280d6c35a46cb29b
    Closes-Bug: #1435588

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/167070
Committed: https://git.openstack.org/cgit/openstack/heat/commit/?id=5eea2226e08905cf1e4064caeef12da2ebef9c61
Submitter: Jenkins
Branch: master

commit 5eea2226e08905cf1e4064caeef12da2ebef9c61
Author: Angus Salkeld <email address hidden>
Date: Tue Mar 24 11:28:31 2015 +1000

    Don't use a different thread local store to oslo.log

    Context logging does not work if we don't do it in a way that
    oslo.log can pick up the context.

    - Use the thread local storage from the base RequestContext class.
    - Use the helper method context.get_current() as appropriate
    - Update the custom_backend_auth.
    - Remove heat/openstack/common/local.py as it is now not used.

    Change-Id: I64f6af5090e98579b93a616bc79f4aaa6cd2b2ee
    Closes-bug: 1435588

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/167071
Committed: https://git.openstack.org/cgit/openstack/heat/commit/?id=f898c2c24dd8f946d9b01589923e0af81de1d4b5
Submitter: Jenkins
Branch: master

commit f898c2c24dd8f946d9b01589923e0af81de1d4b5
Author: Angus Salkeld <email address hidden>
Date: Tue Mar 24 11:38:26 2015 +1000

    Use oslo.log in wsgi.py

    - Use WritebleLogger from olso.log
    - Use oslo.log calls directly instead of the system logger.
    - logging.set_default() with no arguments is pointless.

    Change-Id: Ife0d3ff71d0b431cc88dcdf12a58b5104b318af4
    Related-bug: 1435588

[Morgan Fainberg (mdrnstm)]

Moving keystone to oslocontext would be a much larger endeavor than I think is warranted this late in a cycle. I do think we can provide the request id information in the current context in a way that would be useful.

[Steve Martinelli (stevemar)]

this was fixed in keystone in the liberty release, see: https://bugs.launchpad.net/keystone/+bug/1485604 and https://github.com/openstack/keystone/commit/8719f5a7d0a8eda22291c7c905b0a849ecf4fffa