I'm running an HA cluster with 3 controllers on MOS v5.1.1.
When snapshotting large instances which take 30 minutes or more to create the image files, it fails to upload the image to glance with the following error in nova-all.log:
<179>Dec 29 16:09:22 node-31 nova-compute 2014-12-29 16:09:22.858 29291 ERROR glanceclient.common.http [req-74c01181-2c37-4127-9731-6552baf38d36 ] Request returned failure status.
<179>Dec 29 16:09:29 node-31 nova-compute 2014-12-29 16:09:29.060 29291 ERROR glanceclient.common.http [req-74c01181-2c37-4127-9731-6552baf38d36 ] Request returned failure status.
<179>Dec 29 16:09:29 node-31 nova-compute 2014-12-29 16:09:29.060 29291 ERROR nova.compute.manager [req-74c01181-2c37-4127-9731-6552baf38d36 None] [instance: e3ba1dba-1ecd-4c43-ae10-7e842679ccfd] Error while trying to clean up image 63d7c11c-06d0-4f2f-b42f-d8ee660180a8
2014-12-29 16:09:29.060 29291 TRACE nova.compute.manager [instance: e3ba1dba-1ecd-4c43-ae10-7e842679ccfd] Traceback (most recent call last):
2014-12-29 16:09:29.060 29291 TRACE nova.compute.manager [instance: e3ba1dba-1ecd-4c43-ae10-7e842679ccfd] File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 358, in decorated_function
2014-12-29 16:09:29.060 29291 TRACE nova.compute.manager [instance: e3ba1dba-1ecd-4c43-ae10-7e842679ccfd] image_service.delete(context, image_id)
2014-12-29 16:09:29.060 29291 TRACE nova.compute.manager [instance: e3ba1dba-1ecd-4c43-ae10-7e842679ccfd] File "/usr/lib/python2.6/site-packages/nova/image/glance.py", line 390, in delete
2014-12-29 16:09:29.060 29291 TRACE nova.compute.manager [instance: e3ba1dba-1ecd-4c43-ae10-7e842679ccfd] self._client.call(context, 1, 'delete', image_id)
2014-12-29 16:09:29.060 29291 TRACE nova.compute.manager [instance: e3ba1dba-1ecd-4c43-ae10-7e842679ccfd] File "/usr/lib/python2.6/site-packages/nova/image/glance.py", line 209, in call
2014-12-29 16:09:29.060 29291 TRACE nova.compute.manager [instance: e3ba1dba-1ecd-4c43-ae10-7e842679ccfd] return getattr(client.images, method)(*args, **kwargs)
2014-12-29 16:09:29.060 29291 TRACE nova.compute.manager [instance: e3ba1dba-1ecd-4c43-ae10-7e842679ccfd] File "/usr/lib/python2.6/site-packages/glanceclient/v1/images.py", line 226, in delete
2014-12-29 16:09:29.060 29291 TRACE nova.compute.manager [instance: e3ba1dba-1ecd-4c43-ae10-7e842679ccfd] self._delete("/v1/images/%s" % base.getid(image))
2014-12-29 16:09:29.060 29291 TRACE nova.compute.manager [instance: e3ba1dba-1ecd-4c43-ae10-7e842679ccfd] File "/usr/lib/python2.6/site-packages/glanceclient/common/base.py", line 62, in _delete
2014-12-29 16:09:29.060 29291 TRACE nova.compute.manager [instance: e3ba1dba-1ecd-4c43-ae10-7e842679ccfd] self.api.raw_request('DELETE', url)
2014-12-29 16:09:29.060 29291 TRACE nova.compute.manager [instance: e3ba1dba-1ecd-4c43-ae10-7e842679ccfd] File "/usr/lib/python2.6/site-packages/glanceclient/common/http.py", line 289, in raw_request
2014-12-29 16:09:29.060 29291 TRACE nova.compute.manager [instance: e3ba1dba-1ecd-4c43-ae10-7e842679ccfd] return self._http_request(url, method, **kwargs)
2014-12-29 16:09:29.060 29291 TRACE nova.compute.manager [instance: e3ba1dba-1ecd-4c43-ae10-7e842679ccfd] File "/usr/lib/python2.6/site-packages/glanceclient/common/http.py", line 249, in _http_request
2014-12-29 16:09:29.060 29291 TRACE nova.compute.manager [instance: e3ba1dba-1ecd-4c43-ae10-7e842679ccfd] raise exc.from_response(resp, body_str)
2014-12-29 16:09:29.060 29291 TRACE nova.compute.manager [instance: e3ba1dba-1ecd-4c43-ae10-7e842679ccfd] HTTPUnauthorized: 401 Unauthorized
2014-12-29 16:09:29.060 29291 TRACE nova.compute.manager [instance: e3ba1dba-1ecd-4c43-ae10-7e842679ccfd] This server could not verify that you are authorized to access the document you requested. Either you supplied the wrong credentials (e.g., bad password), or your browser does not understand how to supply the credentials required.
2014-12-29 16:09:29.060 29291 TRACE nova.compute.manager [instance: e3ba1dba-1ecd-4c43-ae10-7e842679ccfd] (HTTP 401)
2014-12-29 16:09:29.060 29291 TRACE nova.compute.manager [instance: e3ba1dba-1ecd-4c43-ae10-7e842679ccfd]
<179>Dec 29 16:09:29 node-31 nova-compute 2014-12-29 16:09:29.203 29291 ERROR oslo.messaging.rpc.dispatcher [req-74c01181-2c37-4127-9731-6552baf38d36 ] Exception during message handling: Not authorized for image 63d7c11c-06d0-4f2f-b42f-d8ee660180a8.
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher Traceback (most recent call last):
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 133, in _dispatch_and_reply
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher incoming.message))
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 176, in _dispatch
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher return self._do_dispatch(endpoint, method, ctxt, args)
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 122, in _do_dispatch
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher result = getattr(endpoint, method)(ctxt, **new_args)
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/nova/exception.py", line 88, in wrapped
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher payload)
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher six.reraise(self.type_, self.value, self.tb)
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/nova/exception.py", line 71, in wrapped
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher return f(self, context, *args, **kw)
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 282, in decorated_function
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher pass
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher six.reraise(self.type_, self.value, self.tb)
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 268, in decorated_function
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher return function(self, context, *args, **kwargs)
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 311, in decorated_function
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher e, sys.exc_info())
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher six.reraise(self.type_, self.value, self.tb)
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 298, in decorated_function
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher return function(self, context, *args, **kwargs)
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 361, in decorated_function
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher % image_id, instance=instance)
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher six.reraise(self.type_, self.value, self.tb)
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 351, in decorated_function
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher *args, **kwargs)
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 2761, in snapshot_instance
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher task_states.IMAGE_SNAPSHOT)
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 2792, in _snapshot_instance
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher update_task_state)
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/nova/virt/libvirt/driver.py", line 1607, in snapshot
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher image_file)
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/nova/image/glance.py", line 377, in update
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher _reraise_translated_image_exception(image_id)
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/nova/image/glance.py", line 375, in update
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher image_id, **image_meta)
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/nova/image/glance.py", line 209, in call
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher return getattr(client.images, method)(*args, **kwargs)
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/glanceclient/v1/images.py", line 291, in update
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher 'PUT', url, headers=hdrs, body=image_data)
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/glanceclient/common/http.py", line 289, in raw_request
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher return self._http_request(url, method, **kwargs)
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/glanceclient/common/http.py", line 249, in _http_request
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher raise exc.from_response(resp, body_str)
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher ImageNotAuthorized: Not authorized for image 63d7c11c-06d0-4f2f-b42f-d8ee660180a8.
2014-12-29 16:09:29.203 29291 TRACE oslo.messaging.rpc.dispatcher
<179>Dec 29 16:09:29 node-31 nova-compute 2014-12-29 16:09:29.206 29291 ERROR oslo.messaging._drivers.common [req-74c01181-2c37-4127-9731-6552baf38d36 ] Returning exception Not authorized for image 63d7c11c-06d0-4f2f-b42f-d8ee660180a8. to caller
<179>Dec 29 16:09:29 node-31 nova-compute 2014-12-29 16:09:29.206 29291 ERROR oslo.messaging._drivers.common [req-74c01181-2c37-4127-9731-6552baf38d36 ] ['Traceback (most recent call last):\n', ' File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 133, in _dispatch_and_reply\n incoming.message))\n', ' File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 176, in _dispatch\n return self._do_dispatch(endpoint, method, ctxt, args)\n', ' File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 122, in _do_dispatch\n result = getattr(endpoint, method)(ctxt, **new_args)\n', ' File "/usr/lib/python2.6/site-packages/nova/exception.py", line 88, in wrapped\n payload)\n', ' File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__\n six.reraise(self.type_, self.value, self.tb)\n', ' File "/usr/lib/python2.6/site-packages/nova/exception.py", line 71, in wrapped\n return f(self, context, *args, **kw)\n', ' File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 282, in decorated_function\n pass\n', ' File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__\n six.reraise(self.type_, self.value, self.tb)\n', ' File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 268, in decorated_function\n return function(self, context, *args, **kwargs)\n', ' File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 311, in decorated_function\n e, sys.exc_info())\n', ' File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__\n six.reraise(self.type_, self.value, self.tb)\n', ' File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 298, in decorated_function\n return function(self, context, *args, **kwargs)\n', ' File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 361, in decorated_function\n % image_id, instance=instance)\n', ' File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__\n six.reraise(self.type_, self.value, self.tb)\n', ' File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 351, in decorated_function\n *args, **kwargs)\n', ' File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 2761, in snapshot_instance\n task_states.IMAGE_SNAPSHOT)\n', ' File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 2792, in _snapshot_instance\n update_task_state)\n', ' File "/usr/lib/python2.6/site-packages/nova/virt/libvirt/driver.py", line 1607, in snapshot\n image_file)\n', ' File "/usr/lib/python2.6/site-packages/nova/image/glance.py", line 377, in update\n _reraise_translated_image_exception(image_id)\n', ' File "/usr/lib/python2.6/site-packages/nova/image/glance.py", line 375, in update\n image_id, **image_meta)\n', ' File "/usr/lib/python2.6/site-packages/nova/image/glance.py", line 209, in call\n return getattr(client.images, method)(*args, **kwargs)\n', ' File "/usr/lib/python2.6/site-packages/glanceclient/v1/images.py", line 291, in update\n \'PUT\', url, headers=hdrs, body=image_data)\n', ' File "/usr/lib/python2.6/site-packages/glanceclient/common/http.py", line 289, in raw_request\n return self._http_request(url, method, **kwargs)\n', ' File "/usr/lib/python2.6/site-packages/glanceclient/common/http.py", line 249, in _http_request\n raise exc.from_response(resp, body_str)\n', 'ImageNotAuthorized: Not authorized for image 63d7c11c-06d0-4f2f-b42f-d8ee660180a8.\n']
At the same time, the keystone logs show an error when trying to locate a token:
<188>Dec 29 16:02:50 node-28 keystone-all 2014-12-29 16:02:50.784 21757 WARNING keystone.common.wsgi [-] Could not find token, eccf82b733604ee08e664ef715ca47e0.
<188>Dec 29 16:09:29 node-28 keystone-all 2014-12-29 16:09:29.039 21757 WARNING keystone.common.wsgi [-] Could not find token, eccf82b733604ee08e664ef715ca47e0.
I'm not sure if this is related, but upon investigation into the database, there are NO tokens in the 'token' table.
Snapshots of other instances ranging from 1 to about 15G seem to work fine, but it appears that anything more than that fails. Has anyone seen anything like this before? Thanks in advance.
