hard to understand the uri printed in the log

[Dave Chen]

In keystone's log file, we can easily find some uri printed like this:
http://127.0.0.1:35357/v3/auth/tokens/auth/tokens/auth/tokens/auth/tokens/auth/tokens/auth/tokens/auth/tokens/auth/tokens/auth/tokens

seems there is something wrong when we are trying to log the uri in the log file.
        LOG.info('%(req_method)s %(uri)s', {
            'req_method': req.environ['REQUEST_METHOD'].upper(),
            'uri': wsgiref.util.request_uri(req.environ),
        })

code is here: https://github.com/openstack/keystone/blob/0debc2fbf448b44574da6f3fef7d457037c59072/keystone/common/wsgi.py#L232 but seems it has already been wrong when the req is passed in.

[Dolph Mathews (dolph)]

I must have just introduced this in https://review.openstack.org/#/c/177427/ but perhaps paste is manipulating the environ somehow? I'm not sure why the application path would be replicated 9 (!) times after the pipeline's endpoint (/v3/)! That's weird. Are there 9 pieces of similar middleware or something in that pipeline? Maybe they're all doing something funky...?

[Lance Bragstad (lbragstad)]

The code linked in the description is in the Application class, which is inherited by every other middleware. I have a funny feeling that if we have duplication, it's happening through the inheritance somewhere. Maybe we can make the code in Application [0] smart enough to know if the path has already been addressed and continue otherwise?

[0] https://github.com/openstack/keystone/blob/0debc2fbf448b44574da6f3fef7d457037c59072/keystone/common/wsgi.py#L232

[Deepti Ramakrishna (dramakri)]

I printed the stack trace and the value of req.environ at the location mentioned above (Application.__call__()) and I see the following:

req.environ dict
----------------------
...
req.environ[SCRIPT_NAME] = /v3/auth/tokens/auth/tokens/auth/tokens/auth/tokens/auth/tokens/auth/tokens/auth/tokens
req.environ[PATH_INFO] = /auth/tokens
...

Stack trace (this stack and the above value of req.environ may have been obtained on different runs)
------------------------------------------------------------------------------------------------------------------------------------------
See http://paste.openstack.org/show/261406/ for the stack trace.

One of the files the stack, namely /usr/local/lib/python2.7/dist-packages/routes/middleware.py, has logic to extract a prefix of the PATH_INFO and append it to SCRIPT_PATH. I suspect that this what is responsible for the growing value of SCRIPT_NAME. Investigating further ...

[Deepti Ramakrishna (dramakri)]

Please review: https://review.openstack.org/#/c/188269

[OpenStack Infra (hudson-openstack)]

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

commit f7385b70b7556c703c96d86223d73d7e9beabd6b
Author: Deepti Ramakrishna <email address hidden>
Date: Wed Jun 3 20:03:18 2015 -0700

    Fix req.environ[SCRIPT_NAME] value.

    The computation done inside
    /usr/local/lib/python2.7/dist-packages/routes/middleware.py
    was leaving req.environ[SCRIPT_NAME] with a wrong value with
    a repeated text block. No code in keystone seems to use the
    value of this variable, hence it has escaped detection until
    https://review.openstack.org/#/c/177427/ which logs req URLs
    by using SCRIPT_NAME in the url construction (via
    wsgiref.util.request_uri()).

    I backtraced the execution flow to the middleware.py file
    from the keystone middleware components. Prepending a '/'
    to the mapper path used in the ExtensionsRouter seems harmless
    as well as seems to fix the problem.

    See log files before and after, from sample Jenkins runs.

    BEFORE: http://goo.gl/YI89e4
    AFTER (for this review): http://goo.gl/I1qVaI

    Closes-Bug:#1454968

    Change-Id: Ia9bf1e1644c996e5aa71ac4e634ead3c4de7edcf

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/kilo
Review: https://review.openstack.org/201708

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/juno
Review: https://review.openstack.org/201726

[OpenStack Infra (hudson-openstack)]

Change abandoned by Dolph Mathews (<email address hidden>) on branch: stable/juno
Review: https://review.openstack.org/201726

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/201708
Committed: https://git.openstack.org/cgit/openstack/keystone/commit/?id=20fd5af10d1551721b9c95f51fbc166977c016ae
Submitter: Jenkins
Branch: stable/kilo

commit 20fd5af10d1551721b9c95f51fbc166977c016ae
Author: Dolph Mathews <email address hidden>
Date: Fri Apr 24 20:05:35 2015 +0000

    Fix WSGI request logging

    This is a backport of two patches that must be carried together. The
    first patch, which is a desirable backport, revealed a problem with
    middleware's handling of SCRIPT_NAME values, and so they must be
    backported together to avoid introducing a regression in a stable
    branch.

    The original commit messages are below.

    ---

    Allow wsgiref to reconstruct URIs per the WSGI spec

    Instead of reimplementing URL reconstruction for logging purposes, and
    getting it wrong over and over and over, let's just use wsgiref.util.

    Change-Id: Ib64877c35ad856bdef8f64f6df44a054eaa2321b
    Closes-Bug: 1448286
    (cherry picked from commit f2a75866319c249e8ebdfb393172ab5ca8816b22)

    ---

    Fix req.environ[SCRIPT_NAME] value.

    The computation done inside
    /usr/local/lib/python2.7/dist-packages/routes/middleware.py
    was leaving req.environ[SCRIPT_NAME] with a wrong value with
    a repeated text block. No code in keystone seems to use the
    value of this variable, hence it has escaped detection until
    https://review.openstack.org/#/c/177427/ which logs req URLs
    by using SCRIPT_NAME in the url construction (via
    wsgiref.util.request_uri()).

    I backtraced the execution flow to the middleware.py file
    from the keystone middleware components. Prepending a '/'
    to the mapper path used in the ExtensionsRouter seems harmless
    as well as seems to fix the problem.

    See log files before and after, from sample Jenkins runs.

    BEFORE: http://goo.gl/YI89e4
    AFTER (for this review): http://goo.gl/I1qVaI

    Closes-Bug:#1454968

    Change-Id: Ia9bf1e1644c996e5aa71ac4e634ead3c4de7edcf
    (cherry picked from commit f7385b70b7556c703c96d86223d73d7e9beabd6b)