Glance doesn't log all errors

[Sam Morrison]

It seems like there are quite a few cases where glance will return a 500 to the user but no error is displayed in the logs:

Example:

Client output:

glance --os-image-api-version 2 image-list
Request returned failure status.
HTTPInternalServerError (HTTP 500)

Server logging output (verbose=True, debug=True):

==> /var/log/glance/api.log <==
2013-11-01 14:22:11.430 17022 DEBUG glance.api.middleware.version_negotiation [-] Determining version of request: GET //v2/schemas/image Accept: process_request /opt/glance/glance/api/middleware/version_negotiation.py:46
2013-11-01 14:22:11.431 17022 DEBUG glance.api.middleware.version_negotiation [-] Using url versioning process_request /opt/glance/glance/api/middleware/version_negotiation.py:59
2013-11-01 14:22:11.432 17022 DEBUG glance.api.middleware.version_negotiation [-] Matched version: v2 process_request /opt/glance/glance/api/middleware/version_negotiation.py:71
2013-11-01 14:22:11.433 17022 DEBUG glance.api.middleware.version_negotiation [-] new path /v2/schemas/image process_request /opt/glance/glance/api/middleware/version_negotiation.py:72
2013-11-01 14:22:11.434 17022 DEBUG keystoneclient.middleware.auth_token [-] Authenticating user token __call__ /usr/lib/python2.7/dist-packages/keystoneclient/middleware/auth_token.py:526
2013-11-01 14:22:11.434 17022 DEBUG keystoneclient.middleware.auth_token [-] Removing headers from request environment: X-Identity-Status,X-Domain-Id,X-Domain-Name,X-Project-Id,X-Project-Name,X-Project-Domain-Id,X-Project-Domain-Name,X-User-Id,X-User-Name,X-User-Domain-Id,X-User-Domain-Name,X-Roles,X-Service-Catalog,X-User,X-Tenant-Id,X-Tenant-Name,X-Tenant,X-Role _remove_auth_headers /usr/lib/python2.7/dist-packages/keystoneclient/middleware/auth_token.py:585
2013-11-01 14:22:11.831 17022 DEBUG keystoneclient.middleware.auth_token [-] Storing e716eaaa5a641d993fb9f8901c562ede token in memcache _cache_put /usr/lib/python2.7/dist-packages/keystoneclient/middleware/auth_token.py:1036
2013-11-01 14:22:11.833 17022 DEBUG glance.api.policy [-] Loading policy from /etc/glance/policy.json _read_policy_file /opt/glance/glance/api/policy.py:96
2013-11-01 14:22:11.834 17022 DEBUG glance.api.policy [-] Loaded policy rules: {u'context_is_admin': 'role:admin', u'default': '@', u'manage_image_cache': 'role:admin'} load_rules /opt/glance/glance/api/policy.py:75
2013-11-01 14:22:11.842 17022 DEBUG routes.middleware [-] Matched GET /schemas/image __call__ /usr/lib/python2.7/dist-packages/routes/middleware.py:100
2013-11-01 14:22:11.842 17022 DEBUG routes.middleware [-] Route path: '/schemas/image', defaults: {'action': u'image', 'controller': <glance.common.wsgi.Resource object at 0x1c5a8d0>} __call__ /usr/lib/python2.7/dist-packages/routes/middleware.py:102
2013-11-01 14:22:11.842 17022 DEBUG routes.middleware [-] Match dict: {'action': u'image', 'controller': <glance.common.wsgi.Resource object at 0x1c5a8d0>} __call__ /usr/lib/python2.7/dist-packages/routes/middleware.py:103
2013-11-01 14:22:11.851 17022 DEBUG glance.api.middleware.version_negotiation [-] Determining version of request: GET //v2/images Accept: process_request /opt/glance/glance/api/middleware/version_negotiation.py:46
2013-11-01 14:22:11.852 17022 DEBUG glance.api.middleware.version_negotiation [-] Using url versioning process_request /opt/glance/glance/api/middleware/version_negotiation.py:59
2013-11-01 14:22:11.854 17022 DEBUG glance.api.middleware.version_negotiation [-] Matched version: v2 process_request /opt/glance/glance/api/middleware/version_negotiation.py:71
2013-11-01 14:22:11.854 17022 DEBUG glance.api.middleware.version_negotiation [-] new path /v2/images process_request /opt/glance/glance/api/middleware/version_negotiation.py:72
2013-11-01 14:22:11.855 17022 DEBUG keystoneclient.middleware.auth_token [-] Authenticating user token __call__ /usr/lib/python2.7/dist-packages/keystoneclient/middleware/auth_token.py:526
2013-11-01 14:22:11.856 17022 DEBUG keystoneclient.middleware.auth_token [-] Removing headers from request environment: X-Identity-Status,X-Domain-Id,X-Domain-Name,X-Project-Id,X-Project-Name,X-Project-Domain-Id,X-Project-Domain-Name,X-User-Id,X-User-Name,X-User-Domain-Id,X-User-Domain-Name,X-Roles,X-Service-Catalog,X-User,X-Tenant-Id,X-Tenant-Name,X-Tenant,X-Role _remove_auth_headers /usr/lib/python2.7/dist-packages/keystoneclient/middleware/auth_token.py:585
2013-11-01 14:22:11.858 17022 DEBUG keystoneclient.middleware.auth_token [-] Returning cached token e716eaaa5a641d993fb9f8901c562ede _cache_get /usr/lib/python2.7/dist-packages/keystoneclient/middleware/auth_token.py:976
2013-11-01 14:22:11.860 17022 DEBUG glance.api.policy [-] Loaded policy rules: {u'context_is_admin': 'role:admin', u'default': '@', u'manage_image_cache': 'role:admin'} load_rules /opt/glance/glance/api/policy.py:75
2013-11-01 14:22:11.861 17022 DEBUG routes.middleware [-] Matched GET /images __call__ /usr/lib/python2.7/dist-packages/routes/middleware.py:100
2013-11-01 14:22:11.862 17022 DEBUG routes.middleware [-] Route path: '/images', defaults: {'action': u'index', 'controller': <glance.common.wsgi.Resource object at 0x1eaf890>} __call__ /usr/lib/python2.7/dist-packages/routes/middleware.py:102
2013-11-01 14:22:11.862 17022 DEBUG routes.middleware [-] Match dict: {'action': u'index', 'controller': <glance.common.wsgi.Resource object at 0x1eaf890>} __call__ /usr/lib/python2.7/dist-packages/routes/middleware.py:103
2013-11-01 14:22:11.863 17022 DEBUG glance.api.policy [c8982762-cbc6-4ca8-bb53-5c0b6e7938a5 0a01a4d0aa5b430f9dd8a7a0ea80b927 6f1a8103302543d592964de0c826ccae] Loading policy from /etc/glance/policy.json _read_policy_file /opt/glance/glance/api/policy.py:96
2013-11-01 14:22:11.864 17022 DEBUG glance.api.policy [c8982762-cbc6-4ca8-bb53-5c0b6e7938a5 0a01a4d0aa5b430f9dd8a7a0ea80b927 6f1a8103302543d592964de0c826ccae] Loaded policy rules: {u'context_is_admin': 'role:admin', u'default': '@', u'manage_image_cache': 'role:admin'} load_rules /opt/glance/glance/api/policy.py:75

I really have no clue why the V2 endpoint isn't working.....

[Sam Morrison (sorrison)]

Related to https://review.openstack.org/#/c/55787/

[Zhi Yan Liu (lzy-dev)]

There is a related BP: https://blueprints.launchpad.net/glance/+spec/wsgi-servicablity-api-log

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/55787
Committed: http://github.com/openstack/glance/commit/4027cd4e704508889f0a86f5e56c9554fa0863a0
Submitter: Jenkins
Branch: master

commit 4027cd4e704508889f0a86f5e56c9554fa0863a0
Author: Russell Sim <email address hidden>
Date: Mon Nov 11 16:31:07 2013 +1100

    Log unhandled exceptions

    Enable logging of unhandled exceptions within the WSGI server. In the
    case of an internal server error a stacktrace will be logged if glance
    API or registry has the verbose option set to True.

    Partial-Bug: #1246968
    Change-Id: I68390495331ba30dab1cd60584d0ed01357514ae

[Feilong Wang (flwang)]

The patch has been merged which submitted by Russell Sim. See https://review.openstack.org/#/c/55787/