keystonemiddleware

AttributeError while logging use of a token already cached as invalid

Bug #1584289 reported by Brian Cline on 2016-05-21

This bug affects 1 person

Affects		Status	Importance	Assigned to	Milestone
	keystonemiddleware	Fix Released	Critical	Brian Cline

Bug Description

Starting with keystonemiddleware v4.5.0 (specifically, commit f54ff06c1f5e274ea31ffac5faf1f57557fe586a), if a token is found to be cached but is cached with an invalid state, the middleware attempts to log a debug message indicating as much. However, the logger it attempts to use does not exist and results in an AttributeError. As a result, this yields HTTP 500 responses once the invalid token gets cached, rather than 401s.

To reproduce (in my case, with Swift using keystonemiddleware in the pipeline):

1. As expected, this fails with a 401:

    (py27) root@saio:~/keystonemiddleware# http -v GET localhost/v1/AUTH_test/ x-auth-token:wat
    GET /v1/AUTH_test/ HTTP/1.1
    Accept: */*
    Accept-Encoding: gzip, deflate
    Connection: keep-alive
    Host: localhost
    User-Agent: HTTPie/0.9.3
    x-auth-token: wat

    HTTP/1.1 401 Unauthorized
    Connection: keep-alive
    Content-Length: 131
    Content-Type: text/html; charset=UTF-8
    Date: Sat, 21 May 2016 05:53:13 GMT
    WWW-Authenticate: Keystone uri='http://10.0.2.15:35357/'
    Www-Authenticate: Swift realm="AUTH_test"
    X-Trans-Id: tx7ee1359f7e4e46cc9fa5a-00573ff7c9

<html><h1>Unauthorized</h1><p>This server could not verify that you are authorized to access the document you requested.</p></html>

2. This should return a 401 as well, just slightly quicker than the first.

    HTTP/1.1 500 Internal Error
    Connection: keep-alive
    Content-Length: 17
    Content-Type: text/plain
    Date: Sat, 21 May 2016 05:53:17 GMT
    X-Trans-Id: txaa05ce4bdf9a40e5bfa34-00573ff7cd

An error occurred

The Swift proxy logs showing the precise reason for the 500:

    May 21 05:46:55 saio proxy-server: Error: An error occurred:
    Traceback (most recent call last):
      File "/usr/local/lib/python2.7/dist-packages/swift/common/middleware/catch_errors.py", line 41, in handle_request
        resp = self._app_call(env)
      File "/usr/local/lib/python2.7/dist-packages/swift/common/wsgi.py", line 1038, in _app_call
        resp = self.app(env, self._start_response)
      File "/usr/local/lib/python2.7/dist-packages/swift/common/middleware/gatekeeper.py", line 99, in __call__
        return self.app(env, gatekeeper_response)
      File "/usr/local/lib/python2.7/dist-packages/swift/common/middleware/healthcheck.py", line 57, in __call__
        return self.app(env, start_response)
      File "/usr/local/lib/python2.7/dist-packages/swift/common/middleware/proxy_logging.py", line 346, in __call__
        six.reraise(exc_type, exc_value, exc_traceback)
      File "/usr/local/lib/python2.7/dist-packages/swift/common/middleware/proxy_logging.py", line 338, in __call__
        iterable = self.app(env, my_start_response)
      File "/usr/local/lib/python2.7/dist-packages/swift/common/middleware/memcache.py", line 109, in __call__
        return self.app(env, start_response)
      File "/usr/local/lib/python2.7/dist-packages/swift/common/swob.py", line 1386, in _wsgify_self
        return func(self, Request(env))(env, start_response)
      File "/usr/local/lib/python2.7/dist-packages/swift/common/middleware/tempurl.py", line 346, in __call__
        return self.app(env, start_response)
      File "/usr/local/lib/python2.7/dist-packages/swift/common/middleware/formpost.py", line 239, in __call__
        return self.app(env, start_response)
      File "/usr/local/lib/python2.7/dist-packages/webob/dec.py", line 130, in __call__
        resp = self.call_func(req, *args, **self.kwargs)
      File "/usr/local/lib/python2.7/dist-packages/webob/dec.py", line 195, in call_func
        return self.func(req, *args, **kwargs)
      File "/usr/local/lib/python2.7/dist-packages/keystonemiddleware/auth_token/__init__.py", line 469, in __call__
        response = self.process_request(req)
      File "/usr/local/lib/python2.7/dist-packages/keystonemiddleware/auth_token/__init__.py", line 738, in process_request
        resp = super(AuthProtocol, self).process_request(request)
      File "/usr/local/lib/python2.7/dist-packages/keystonemiddleware/auth_token/__init__.py", line 497, in process_request
        data, user_auth_ref = self._do_fetch_token(request.user_token)
      File "/usr/local/lib/python2.7/dist-packages/keystonemiddleware/auth_token/__init__.py", line 537, in _do_fetch_token
        data = self.fetch_token(token)
      File "/usr/local/lib/python2.7/dist-packages/keystonemiddleware/auth_token/__init__.py", line 851, in fetch_token
        self.log.debug('Cached token is marked unauthorized')
        AttributeError: 'AuthProtocol' object has no attribute '_LOG' (txn: tx3f7e3d36d87044c4a96b5-00573ff64f)

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2016-05-21: Fix proposed to keystonemiddleware (master)

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

Changed in keystonemiddleware:
assignee:	nobody → Brian Cline (briancline)
status:	New → In Progress

Revision history for this message

Brian Cline (briancline) wrote on 2016-05-21:

As usual, Launchpad mangled the crap out of my bug report. Here's a readable copy with the stack trace:
https://gist.github.com/briancline/f425684f01bde0a40094d049f8009a33

Jamie Lennox (jamielennox) on 2016-05-22

Changed in keystonemiddleware:
importance:	Undecided → Critical

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2016-05-23: Fix merged to keystonemiddleware (master)

Reviewed: https://review.openstack.org/319527
Committed: https://git.openstack.org/cgit/openstack/keystonemiddleware/commit/?id=f55b0334b919f89fee0b2cfe0a9994fd08c9966c
Submitter: Jenkins
Branch: master

commit f55b0334b919f89fee0b2cfe0a9994fd08c9966c
Author: Brian Cline <email address hidden>
Date: Sat May 21 01:13:29 2016 -0500

Fix AttributeError on cached-invalid token checks

    Starting with v4.5.0, if a token is found to be cached, but is cached
    with an invalid state, the middleware attempts to log a debug message
    indicating as much.

    However, the logger it attempts to use does not exist and results in
    an AttributeError. As a result, this yields HTTP 500 responses once
    the invalid token gets cached and is attempted to be used again,
    rather than the expected 401.

    This fixes the reference and adds a test to ensure the expected log
    entry ends up in the logger so that this condition in
    AuthProtocol.fetch_token now gets coverage.

Change-Id: Ie391973ea5893531c0b590ffba2d9de7f7f19d94
Closes-bug: #1584289

Changed in keystonemiddleware:
status:	In Progress → Fix Released

Revision history for this message

Doug Hellmann (doug-hellmann) wrote on 2016-05-23: Fix included in openstack/keystonemiddleware 4.5.1

This issue was fixed in the openstack/keystonemiddleware 4.5.1 release.

Report a bug

This report contains Public information

Everyone can see this information.

You are

Subscribing...

Edit bug mail

Other bug subscribers

Remote bug watches

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