placement api log entries have mismatched request ids

Bug #1626493 reported by Chris Dent
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
OpenStack Compute (nova)
Fix Released
Low
Chris Dent

Bug Description

The placement (v 1.0) API's service logs get confused about request id. The following is one request:

```
2016-09-22 10:54:54.372 22919 DEBUG nova.api.openstack.placement.requestlog [req-93669abf-57c5-4415-a734-1affc816a9ae admin admin] Starting request: 10.0.2.15 "GET /placement/resource_providers/fastidious" __call__ /opt/stack/nova/nova/api/openstack/placement/requestlog.py:36
2016-09-22 10:54:54.414 22919 INFO nova.api.openstack.placement.requestlog [req-7312f440-2c66-4483-a514-eaf3602b50e6 admin admin] 10.0.2.15 "GET /placement/resource_providers/fastidious" status: 404 len: 80
```

This is probably because the request id middleware is not being called first.

Chris Dent (cdent)
tags: added: api placement scheduler
Changed in nova:
assignee: nobody → Chris Dent (cdent)
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to nova (master)

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

Changed in nova:
status: New → In Progress
Changed in nova:
importance: Undecided → Low
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to nova (master)

Reviewed: https://review.openstack.org/374833
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=0b9b8981f2802f21999325e028605157f0b1f11d
Submitter: Jenkins
Branch: master

commit 0b9b8981f2802f21999325e028605157f0b1f11d
Author: Chris Dent <email address hidden>
Date: Thu Sep 22 13:47:49 2016 +0000

    [placement] reorder middleware to correct logging context

    The initial bug was that the initial 'Starting' log provided by
    requestlog had a different request id from the rest of the log
    messages for the same request. The initial assumption was that this
    was because a request id was not initially available, causing one
    to be generated for the first log entry that later was replaced
    by the request id middleware.

    In the process of debugging that it became clear that the id was
    in fact the request id of the previous request because the context
    was being reused under the covers in oslo_log and olso_context.

    Therefore the auth, context and request id middlewares are now
    changed to be active in the middleware stack before the request log
    middleware. The unfortunate side effect of this is that the Starting
    message and final request logging is no longer actually bounding the
    full request: it misses three critical middlewares.

    Change-Id: Ifa412973037193e4e67a0c9d2c71c7a4847980a9
    Closes-Bug: #1626493

Changed in nova:
status: In Progress → Fix Released
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix included in openstack/nova 15.0.0.0b1

This issue was fixed in the openstack/nova 15.0.0.0b1 development milestone.

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

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