safe_header raises AttributeError if X-Auth-Token is None

[hougangliu]

When trying to live migrate a VM by calling the compute RPC API directly (i.e., not via the novaclient) coupled with the elevated admin context [1], the destination compute service tries to call glance to retrieve the image [2]. However, the destination compute service erroneously raises an exception [4].

This problem was introduced via the following patch:
https://review.openstack.org/#/c/121692

It also appears that a similar problem exists within nova too [3].

#############################################################

[1]
from nova import compute
ctxt = context.get_admin_context()
self.compute_api = compute.API()
self.compute_api.live_migrate(
            ctxt.elevated(), inst, False, False, host_dict)

#############################################################

[2]
def _create_glance_client(context, host, port, use_ssl, version=1):
    """Instantiate a new glanceclient.Client object."""
    params = {}
    if use_ssl:
        scheme = 'https'
        # https specific params
        params['insecure'] = CONF.glance.api_insecure
        params['ssl_compression'] = False
        if CONF.ssl.cert_file:
            params['cert_file'] = CONF.ssl.cert_file
        if CONF.ssl.key_file:
            params['key_file'] = CONF.ssl.key_file
        if CONF.ssl.ca_file:
            params['cacert'] = CONF.ssl.ca_file
    else:
        scheme = 'http'

    if CONF.auth_strategy == 'keystone':
        # NOTE(isethi): Glanceclient <= 0.9.0.49 accepts only
        # keyword 'token', but later versions accept both the
        # header 'X-Auth-Token' and 'token'
        params['token'] = context.auth_token
        params['identity_headers'] = generate_identity_headers(context) <<<<<<<<<would return {'X-Auth-Token': None, ....}
    if utils.is_valid_ipv6(host):
        # if so, it is ipv6 address, need to wrap it with '[]'
        host = '[%s]' % host
    endpoint = '%s://%s:%s' % (scheme, host, port)
    return glanceclient.Client(str(version), endpoint, **params) <<<<<<<<<<<<<<<params=={'identity_headers':{{'X-Auth-Token': None, ....}}...}

#############################################################

[3]
novaclient.client.py:
    def http_log_req(self, method, url, kwargs):
        if not self.http_log_debug:
            return

        string_parts = ['curl -i']

        if not kwargs.get('verify', True):
            string_parts.append(' --insecure')

        string_parts.append(" '%s'" % url)
        string_parts.append(' -X %s' % method)

        headers = copy.deepcopy(kwargs['headers'])
        self._redact(headers, ['X-Auth-Token']) >>>>>>>>>>>>>>>>>>>here
        # because dict ordering changes from 2 to 3
        keys = sorted(headers.keys())
        for name in keys:
            value = headers[name]
            header = ' -H "%s: %s"' % (name, value)
            string_parts.append(header)

        if 'data' in kwargs:
            data = json.loads(kwargs['data'])
            self._redact(data, ['auth', 'passwordCredentials', 'password'])
            string_parts.append(" -d '%s'" % json.dumps(data))
        self._logger.debug("REQ: %s" % "".join(string_parts))

#############################################################

[4]
2014-10-14 00:42:10.699 31346 INFO nova.compute.manager [-] [instance: aa68237f-e669-4025-b16e-f4b50926f7a5] During the sync_power process the instance has moved from host cmo-comp5.ibm.com to host cmo-comp4.ibm.com
2014-10-14 00:42:10.913 31346 INFO nova.compute.manager [req-7be58838-3ec2-43d4-afd1-23d6b3d5e3de None] [instance: aa68237f-e669-4025-b16e-f4b50926f7a5] Post operation of migration started
2014-10-14 00:42:11.148 31346 ERROR oslo.messaging.rpc.dispatcher [req-7be58838-3ec2-43d4-afd1-23d6b3d5e3de ] Exception during message handling: 'NoneType' object has no attribute 'encode'
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher Traceback (most recent call last):
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 134, in _dispatch_and_reply
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher incoming.message))
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 177, in _dispatch
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher return self._do_dispatch(endpoint, method, ctxt, args)
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 123, in _do_dispatch
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher result = getattr(endpoint, method)(ctxt, **new_args)
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 418, in decorated_function
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher return function(self, context, *args, **kwargs)
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/nova/exception.py", line 88, in wrapped
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher payload)
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 82, in __exit__
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher six.reraise(self.type_, self.value, self.tb)
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/nova/exception.py", line 71, in wrapped
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher return f(self, context, *args, **kw)
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 330, in decorated_function
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher kwargs['instance'], e, sys.exc_info())
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 82, in __exit__
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher six.reraise(self.type_, self.value, self.tb)
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 318, in decorated_function
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher return function(self, context, *args, **kwargs)
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 5224, in post_live_migration_at_destination
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher block_migration, block_device_info)
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/nova/virt/libvirt/driver.py", line 5635, in post_live_migration_at_destination
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher write_to_disk=True)
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/nova/virt/libvirt/driver.py", line 4132, in _get_guest_xml
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher context, self._image_api, image_ref, instance)
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/nova/compute/utils.py", line 242, in get_image_metadata
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher image = image_api.get(context, image_id_or_uri)
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/nova/image/api.py", line 89, in get
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher include_locations=include_locations)
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/nova/image/glance.py", line 311, in show
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher _reraise_translated_image_exception(image_id)
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/nova/image/glance.py", line 309, in show
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher image = self._client.call(context, version, 'get', image_id)
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/nova/image/glance.py", line 232, in call
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher return getattr(client.images, method)(*args, **kwargs)
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/glanceclient/v1/images.py", line 126, in get
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher % urlparse.quote(str(image_id)))
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/glanceclient/common/http.py", line 248, in head
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher return self._request('HEAD', url, **kwargs)
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/glanceclient/common/http.py", line 192, in _request
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher self.log_curl_request(method, conn_url, headers, data, kwargs)
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/glanceclient/common/http.py", line 99, in log_curl_request
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher header = '-H \'%s: %s\'' % safe_header(key, value)
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/glanceclient/common/utils.py", line 394, in safe_header
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher v = value.encode('utf-8')
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher AttributeError: 'NoneType' object has no attribute 'encode'
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher
2014-10-14 00:42:11.152 31346 ERROR oslo.messaging._drivers.common [req-7be58838-3ec2-43d4-afd1-23d6b3d5e3de ] Returning exception 'NoneType' object has no attribute 'encode' to caller

[Joe Gordon (jogo)]

The nature of this bug report is unclear to me. Are you adding out of tree code to the nova codebase (snippet 1) that is failing? How can I reproduce this bug?

[hougangliu (liuhoug)]

this bug occurs when 3rd-party wants to live-migration a VM to a host by call compute API directly ( not by novaclient ) with context by context.get_admin_context().elevated, the change below can simulate it.(restart conductor service after change nova/conductor/tasks/live_migrate.py and then do live-migration operation)

nova/conductor/tasks/live_migrate.py:

class LiveMigrationTask(object):
    def __init__(self, context, instance, destination,
                 block_migration, disk_over_commit):

        self.context = context
        from nova import context
        self.context = context.get_admin_context().elevated() >>>>>>>>>>>add this two line

[hougangliu (liuhoug)]

when we try to call nova.compute.utils.get_image_metadata with context.get_admin_context(), it would raise excetption.
refer to https://review.openstack.org/#/c/101005/

nova/compute/utils.py:
def get_image_metadata(context, image_api, image_id_or_uri, instance):
    image_system_meta = {}
    # In case of boot from volume, image_id_or_uri may be None
    if image_id_or_uri is not None:
        # If the base image is still available, get its metadata
        try:
            image = image_api.get(context, image_id_or_uri)
        except (exception.ImageNotAuthorized, >>>>>>>>>>cannot get all exception
                exception.ImageNotFound,
                exception.Invalid) as e:
            LOG.warning(_LW("Can't access image %(image_id)s: %(error)s"),
                        {"image_id": image_id_or_uri, "error": e},
                        instance=instance)
        else:
            flavor = flavors.extract_flavor(instance)
            image_system_meta = utils.get_system_metadata_from_image(image,
                                                                     flavor)

    # Get the system metadata from the instance
    system_meta = utils.instance_sys_meta(instance)

    # Merge the metadata from the instance with the image's, if any
    system_meta.update(image_system_meta)

    # Convert the system metadata to image metadata
    return utils.get_image_from_system_metadata(system_meta)

[hougangliu (liuhoug)]

I think we should mask token only if the token value is string-like type for the robustness of the code.
for example in the file of https://review.openstack.org/#/c/121692/2/glanceclient/common/http.py,
 we should use code below to replace line 98, (the check is in need, as line 106 and 112 are)

if not isinstance(value, six.string_types):
    value = '*' * 3
header = '-H \'%s: %s\'' % safe_header(key, value)

[Joe Cropper (jwcroppe)]

jogo - I tried to update the description to make it a little more clear as I understood what was being suggested. In a nutshell, it sounds like when using the RPC APIs, one can't call live migration using the admin context (even when elevated) without getting an encoding error.

[Joe Cropper (jwcroppe)]

Is this a nova problem or a glanceclient problem? Or both?

[Joe Cropper (jwcroppe)]

Looping in glance-client team due to the snippet from [4] in the description:

2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/glanceclient/common/utils.py", line 394, in safe_header
2014-10-14 00:42:11.148 31346 TRACE oslo.messaging.rpc.dispatcher v = value.encode('utf-8')

Though, not sure if this is just due to nova not sending in the right details either...

[Matt Riedemann (mriedem)]

What's the key in the request header to glanceclient that has the null value, x-auth-token? I see this change:

https://review.openstack.org/#/c/121692/2/glanceclient/common/utils.py

And in safe_header how it doesn't check if value is None, but what is the key? Can you debug to the point of figuring what that header key is so we can figure out if nova is doing something incorrectly or what the bug in glanceclient is?

[Matt Riedemann (mriedem)]

Assuming the null value is for the x-auth-token key, the glanceclient http connection doesn't enforce that auth token is set, it just tries to get it if provided and put's it in the header:

http://git.openstack.org/cgit/openstack/python-glanceclient/tree/glanceclient/common/http.py?id=0.14.1#n52

And in the nova.image.glance._create_glance_client code, if auth_strategy isn't keystone (which it is by default but I guess you could not use keystone), then the token isn't set on the client connection and if you're not using ssl that's how you could get into this state (since the glance client http connection isn't requiring an auth token):

http://git.openstack.org/cgit/openstack/nova/tree/nova/image/glance.py?id=2014.2#n150

In this case, are you using auth_strategy=keystone in your nova.conf? I guess it doesn't matter since we still have an exposure here, and we definitely don't test any non-keystone auth strategies in the community CI.

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/129289
Committed: https://git.openstack.org/cgit/openstack/python-glanceclient/commit/?id=8c159a2eb4d61f2b9691fbfa1288bcda2156f3f1
Submitter: Jenkins
Branch: master

commit 8c159a2eb4d61f2b9691fbfa1288bcda2156f3f1
Author: Matt Riedemann <email address hidden>
Date: Fri Oct 17 07:53:05 2014 -0700

    Don't set X-Auth-Token key in http session header if no token provided

    Commit f980fc549247fa2deb87dfacebc6d8d13ccd45d1 changed how the
    X-Auth-Token header was scrubbed when logging the request, but
    effectively made the value required which can lead to an AttributeError
    if the value for the header is None.

    The value can be None if you're using Nova but don't have Nova
    configured with auth_strategy='keystone' (see
    nova.image.glance._create_glance_client for details).

    This patch simply checks if the auth_token is set in the http client
    object and if not, it doesn't set the X-Auth-Token key in the session
    header.

    Closes-Bug: #1381295

    Change-Id: Ie285d5253df28a9f0f964147a53c99ceaa919c5c