The tempest gating job unfortunately runs with allow_resize=False so this has not been seen. Running the tempest test_server_actions.py tests for these actions on the current devstack will sometimes fail with the error 'Instance has not been resized.' I see this message in the API log but nothing obvious in the c-cpu log. Perhaps this is a race condition where the server state becomes visible through the API as VERIFY_RESIZE before it is ready to receive a resize-confirm or resize-revert.
I also saw that when the test tries to delete the server after this occurs, it gets an AdminRequired thrown back. There is an entry in both logs for that which I will include. Look for -------------------------------> in the api log.
Portion of api.log:
2012-10-12 16:26:17 INFO nova.api.openstack.wsgi [req-c4ec2bb0-093c-4c6e-86e4-38c60d408399 ServerActionsTestJSON-user Server\
ActionsTestJSON-tenant] POST http://172.18.0.156:8774/v2/08f0c0f1cf8c4215bdc96810207fa636/servers/babe025a-0250-4bc7-8a0c-2d\
e1396fb9f5/action
----------------------------------------------------> the primary error
2012-10-12 16:26:17 INFO nova.api.openstack.wsgi [req-c4ec2bb0-093c-4c6e-86e4-38c60d408399 ServerActionsTestJSON-user Server\
ActionsTestJSON-tenant] HTTP exception thrown: Instance has not been resized.
2012-10-12 16:26:17 INFO nova.api.openstack.wsgi [req-c4ec2bb0-093c-4c6e-86e4-38c60d408399 ServerActionsTestJSON-user Server\
ActionsTestJSON-tenant] http://172.18.0.156:8774/v2/08f0c0f1cf8c4215bdc96810207fa636/servers/babe025a-0250-4bc7-8a0c-2de1396\
fb9f5/action returned with HTTP 400
2012-10-12 16:26:17 INFO nova.osapi_compute.wsgi.server [req-c4ec2bb0-093c-4c6e-86e4-38c60d408399 ServerActionsTestJSON-user\
ServerActionsTestJSON-tenant] 172.18.0.156 - - [12/Oct/2012 16:26:17] "POST /v2/08f0c0f1cf8c4215bdc96810207fa636/servers/ba\
be025a-0250-4bc7-8a0c-2de1396fb9f5/action HTTP/1.1" 400 270 0.158310
2012-10-12 16:26:17 INFO nova.api.openstack.wsgi [req-5d25aceb-a39b-4c1b-8a8f-c592baabd263 ServerActionsTestJSON-user Server\
ActionsTestJSON-tenant] DELETE http://172.18.0.156:8774/v2/08f0c0f1cf8c4215bdc96810207fa636/servers/babe025a-0250-4bc7-8a0c-\
2de1396fb9f5
2012-10-12 16:26:17 DEBUG nova.api.openstack.wsgi [req-5d25aceb-a39b-4c1b-8a8f-c592baabd263 ServerActionsTestJSON-user Serve\
rActionsTestJSON-tenant] No Content-Type provided in request from (pid=12905) get_body /opt/stack/nova/nova/api/openstack/ws\
gi.py:783
2012-10-12 16:26:17 DEBUG nova.compute.api [req-5d25aceb-a39b-4c1b-8a8f-c592baabd263 ServerActionsTestJSON-user ServerAction\
sTestJSON-tenant] [instance: babe025a-0250-4bc7-8a0c-2de1396fb9f5] Going to try to terminate instance from (pid=12905) delet\
e /opt/stack/nova/nova/compute/api.py:943
2012-10-12 16:26:18 DEBUG nova.quota [req-5d25aceb-a39b-4c1b-8a8f-c592baabd263 ServerActionsTestJSON-user ServerActionsTestJ\
SON-tenant] Created reservations ['d7a8604d-64b7-4190-895e-fbb8d63ea6f5', 'd2141fd0-7388-405f-8194-cc69d91a5e47', '2f270370-\
ef9a-4668-83af-05dfbe0afd8b'] from (pid=12905) reserve /opt/stack/nova/nova/quota.py:697
2012-10-12 16:26:18 DEBUG nova.openstack.common.rpc.amqp [-] Making asynchronous call on compute.xg08eth0.qrclab.com ... fro\
m (pid=12905) multicall /opt/stack/nova/nova/openstack/common/rpc/amqp.py:351
2012-10-12 16:26:18 DEBUG nova.openstack.common.rpc.amqp [-] MSG_ID is 6ab607203f2740c7abb777b05c0ea1b7 from (pid=12905) mul\
ticall /opt/stack/nova/nova/openstack/common/rpc/amqp.py:354
-------------------------------------------------------------> The failing delete
2012-10-12 16:26:18 INFO nova.api.openstack.wsgi [req-5d25aceb-a39b-4c1b-8a8f-c592baabd263 ServerActionsTestJSON-user Server\
ActionsTestJSON-tenant] http://172.18.0.156:8774/v2/08f0c0f1cf8c4215bdc96810207fa636/servers/babe025a-0250-4bc7-8a0c-2de1396\
fb9f5 returned with HTTP 403
2012-10-12 16:26:18 INFO nova.osapi_compute.wsgi.server [req-5d25aceb-a39b-4c1b-8a8f-c592baabd263 ServerActionsTestJSON-user\
ServerActionsTestJSON-tenant] 172.18.0.156 - - [12/Oct/2012 16:26:18] "DELETE /v2/08f0c0f1cf8c4215bdc96810207fa636/servers/\
babe025a-0250-4bc7-8a0c-2de1396fb9f5 HTTP/1.1" 403 1711 0.685447
Portion of cpu log from around the time the errors showed up in the api log:
2012-10-12 16:26:14 DEBUG nova.utils [req-71a80aa1-12d9-4b17-8328-678a71ffe585 ServerActionsTestJSON-user ServerActionsTestJ\
SON-tenant] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf tee /sys/class/net/vnet0/brport/hairpin_mod\
e from (pid=13011) execute /opt/stack/nova/nova/utils.py:183
2012-10-12 16:26:14 DEBUG nova.utils [req-71a80aa1-12d9-4b17-8328-678a71ffe585 ServerActionsTestJSON-user ServerActionsTestJ\
SON-tenant] Result was 0 from (pid=13011) execute /opt/stack/nova/nova/utils.py:199
2012-10-12 16:26:16 INFO nova.virt.libvirt.driver [-] [instance: babe025a-0250-4bc7-8a0c-2de1396fb9f5] Instance running succ\
essfully.
2012-10-12 16:26:17 DEBUG nova.utils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /opt/stack/data/nova/in\
stances/instance-00000011/disk from (pid=13011) execute /opt/stack/nova/nova/utils.py:183
2012-10-12 16:26:17 DEBUG nova.utils [-] Result was 0 from (pid=13011) execute /opt/stack/nova/nova/utils.py:199
2012-10-12 16:26:17 DEBUG nova.utils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /opt/stack/data/nova/in\
stances/instance-00000011/disk from (pid=13011) execute /opt/stack/nova/nova/utils.py:183
2012-10-12 16:26:17 DEBUG nova.utils [-] Result was 0 from (pid=13011) execute /opt/stack/nova/nova/utils.py:199
2012-10-12 16:26:17 DEBUG nova.compute.resource_tracker [-] Hypervisor: free ram (MB): 46436 from (pid=13011) _report_hyperv\
isor_resource_view /opt/stack/nova/nova/compute/resource_tracker.py:434
2012-10-12 16:26:17 DEBUG nova.compute.resource_tracker [-] Hypervisor: free disk (GB): 86 from (pid=13011) _report_hypervis\
or_resource_view /opt/stack/nova/nova/compute/resource_tracker.py:435
2012-10-12 16:26:17 DEBUG nova.compute.resource_tracker [-] Hypervisor: free VCPUs: 16 from (pid=13011) _report_hypervisor_r\
esource_view /opt/stack/nova/nova/compute/resource_tracker.py:440
2012-10-12 16:26:17 AUDIT nova.compute.resource_tracker [-] Free ram (MB): 45607
2012-10-12 16:26:17 AUDIT nova.compute.resource_tracker [-] Free disk (GB): 71
2012-10-12 16:26:17 AUDIT nova.compute.resource_tracker [-] Free VCPUS: 15
2012-10-12 16:26:17 INFO nova.compute.resource_tracker [-] Compute_service record updated for xg08eth0.qrclab.com
2012-10-12 16:26:17 DEBUG nova.utils [req-71a80aa1-12d9-4b17-8328-678a71ffe585 ServerActionsTestJSON-user ServerActionsTestJ\
SON-tenant] Got semaphore "compute_resources" for method "update_usage"... from (pid=13011) inner /opt/stack/nova/nova/utils\
.py:721
2012-10-12 16:26:17 DEBUG nova.manager [-] Running periodic task ComputeManager._poll_rebooting_instances from (pid=13011) p\
eriodic_tasks /opt/stack/nova/nova/manager.py:172
2012-10-12 16:26:17 DEBUG nova.manager [-] Skipping ComputeManager._cleanup_running_deleted_instances, 11 ticks left until n\
ext run from (pid=13011) periodic_tasks /opt/stack/nova/nova/manager.py:167
2012-10-12 16:26:17 DEBUG nova.manager [-] Running periodic task ComputeManager._check_instance_build_time from (pid=13011) \
periodic_tasks /opt/stack/nova/nova/manager.py:172
2012-10-12 16:26:17 DEBUG nova.manager [-] Running periodic task ComputeManager._heal_instance_info_cache from (pid=13011) p\
eriodic_tasks /opt/stack/nova/nova/manager.py:172
2012-10-12 16:26:18 DEBUG nova.openstack.common.rpc.amqp [-] Making asynchronous call on network ... from (pid=13011) multic\
all /opt/stack/nova/nova/openstack/common/rpc/amqp.py:351
2012-10-12 16:26:18 DEBUG nova.openstack.common.rpc.amqp [-] MSG_ID is faeba273caab4b59872143255554b691 from (pid=13011) mul\
ticall /opt/stack/nova/nova/openstack/common/rpc/amqp.py:354
2012-10-12 16:26:18 DEBUG nova.openstack.common.rpc.amqp [-] received {u'_context_roles': [u'', u'admin'], u'_msg_id': u'6ab\
607203f2740c7abb777b05c0ea1b7', u'_context_quota_class': None, u'_context_request_id': u'req-5d25aceb-a39b-4c1b-8a8f-c592baa\
bd263', u'_context_service_catalog': [{u'endpoints': [{u'adminURL': u'http://172.18.0.156:8774/v2/08f0c0f1cf8c4215bdc9681020\
7fa636', u'region': u'RegionOne', u'internalURL': u'http://172.18.0.156:8774/v2/08f0c0f1cf8c4215bdc96810207fa636', u'id': u'\
9e4c28daf0c34dc6bac1c3d0df60be90', u'publicURL': u'http://172.18.0.156:8774/v2/08f0c0f1cf8c4215bdc96810207fa636'}], u'endpoi\
nts_links': [], u'type': u'compute', u'name': u'nova'}, {u'endpoints': [{u'adminURL': u'http://172.18.0.156:3333', u'region'\
: u'RegionOne', u'internalURL': u'http://172.18.0.156:3333', u'id': u'15d7fb5f8a274548a948abd5f1041bb1', u'publicURL': u'htt\
p://172.18.0.156:3333'}], u'endpoints_links': [], u'type': u's3', u'name': u's3'}, {u'endpoints': [{u'adminURL': u'http://17\
2.18.0.156:9292', u'region': u'RegionOne', u'internalURL': u'http://172.18.0.156:9292', u'id': u'46d3dad6915d4e9f869d03e2f09\
903ae', u'publicURL': u'http://172.18.0.156:9292'}], u'endpoints_links': [], u'type': u'image', u'name': u'glance'}, {u'endp\
oints': [{u'adminURL': u'http://172.18.0.156:8776/v1/08f0c0f1cf8c4215bdc96810207fa636', u'region': u'RegionOne', u'internalU\
RL': u'http://172.18.0.156:8776/v1/08f0c0f1cf8c4215bdc96810207fa636', u'id': u'178b19edb2004dfcaf4f686873c9e6b6', u'publicUR\
L': u'http://172.18.0.156:8776/v1/08f0c0f1cf8c4215bdc96810207fa636'}], u'endpoints_links': [], u'type': u'volume', u'name': \
u'volume'}, {u'endpoints': [{u'adminURL': u'http://172.18.0.156:8773/services/Admin', u'region': u'RegionOne', u'internalURL\
': u'http://172.18.0.156:8773/services/Cloud', u'id': u'54b376c76fa74eccbd9e39c8f7c41708', u'publicURL': u'http://172.18.0.1\
56:8773/services/Cloud'}], u'endpoints_links': [], u'type': u'ec2', u'name': u'ec2'}, {u'endpoints': [{u'adminURL': u'http:/\
/172.18.0.156:35357/v2.0', u'region': u'RegionOne', u'internalURL': u'http://172.18.0.156:5000/v2.0', u'id': u'210eb7a6880c4\
65e920c1dcca9fb692e', u'publicURL': u'http://172.18.0.156:5000/v2.0'}], u'endpoints_links': [], u'type': u'identity', u'name\
': u'keystone'}], u'_context_user_name': u'ServerActionsTestJSON-user', u'_context_auth_token': '<SANITIZED>', u'args': {u'm\
igration_id': 5, u'instance': {u'vm_state': u'resized', u'availability_zone': None, u'terminated_at': None, u'ephemeral_gb':\
0, u'instance_type_id': 5, u'user_data': None, u'vm_mode': None, u'deleted_at': None, u'reservation_id': u'r-pfolkln9', u'i\
d': 17, u'security_groups': [{u'deleted_at': None, u'user_id': u'ae5714ba5d1749babfdc9322031ab0ca', u'name': u'default', u'd\
eleted': False, u'created_at': u'2012-10-12T20:22:01.000000', u'updated_at': None, u'rules': [], u'project_id': u'08f0c0f1cf\
8c4215bdc96810207fa636', u'id': 3, u'description': u'default'}], u'disable_terminate': False, u'user_id': u'ae5714ba5d1749ba\
bfdc9322031ab0ca', u'uuid': u'babe025a-0250-4bc7-8a0c-2de1396fb9f5', u'server_name': None, u'default_swap_device': None, u'i\
nfo_cache': {u'instance_uuid': u'babe025a-0250-4bc7-8a0c-2de1396fb9f5', u'deleted': False, u'created_at': u'2012-10-12T20:23\
:54.000000', u'updated_at': u'2012-10-12T20:23:59.000000', u'network_info': u'[{"network": {"bridge": "br100", "subnets": [{\
"ips": [{"meta": {}, "version": 4, "type": "fixed", "floating_ips": [], "address": "10.0.0.7"}], "version": 4, "meta": {"dhc\
p_server": "10.0.0.1"}, "dns": [{"meta": {}, "version": 4, "type": "dns", "address": "8.8.4.4"}], "routes": [], "cidr": "10.\
0.0.0/24", "gateway": {"meta": {}, "version": 4, "type": "gateway", "address": "10.0.0.1"}}, {"ips": [], "version": null, "m\
eta": {"dhcp_server": null}, "dns": [], "routes": [], "cidr": null, "gateway": {"meta": {}, "version": null, "type": "gatewa\
y", "address": null}}], "meta": {"tenant_id": null, "should_create_bridge": true, "bridge_interface": "eth0"}, "id": "a67c33\
e1-a71a-4e07-a3fe-d05998652f85", "label": "private"}, "meta": {}, "id": "cc2ed4bc-4415-4ef6-a6cb-39a740385f16", "address": "\
fa:16:3e:74:a7:f1"}]', u'deleted_at': None, u'id': 17}, u'hostname': u'server187794', u'launched_on': u'xg08eth0.qrclab.com'\
, u'display_description': u'server187794', u'key_data': None, u'kernel_id': u'9d23826b-b55e-4451-92f2-4c8f6e0e1b97', u'power\
_state': 1, u'default_ephemeral_device': None, u'progress': 0, u'project_id': u'08f0c0f1cf8c4215bdc96810207fa636', u'launche\
d_at': u'2012-10-12T20:26:16.000000', u'scheduled_at': u'2012-10-12T20:23:55.000000', u'ramdisk_id': u'eb7758a4-d202-40c9-ad\
c5-31c0c51e45c6', u'access_ip_v6': None, u'access_ip_v4': None, u'deleted': False, u'key_name': None, u'updated_at': u'2012-\
10-12T20:26:16.000000', u'host': u'xg08eth0.qrclab.com', u'display_name': u'server187794', u'task_state': None, u'shutdown_t\
erminate': False, u'architecture': None, u'root_gb': 20, u'locked': False, u'name': u'instance-00000011', u'created_at': u'2\
012-10-12T20:23:54.000000', u'launch_index': 0, u'metadata': [], u'memory_mb': 2048, u'instance_type': {u'disabled': False, \
u'root_gb': 20, u'deleted_at': None, u'name': u'm1.small', u'deleted': False, u'created_at': None, u'ephemeral_gb': 0, u'upd\
ated_at': None, u'memory_mb': 2048, u'vcpus': 1, u'swap': 0, u'rxtx_factor': 1.0, u'is_public': True, u'flavorid': u'2', u'v\
cpu_weight': None, u'id': 5}, u'vcpus': 1, u'image_ref': u'8ad9a32f-741d-46a1-be80-67ea7ff666a9', u'root_device_name': u'/de\
v/vda', u'auto_disk_config': None, u'os_type': None, u'config_drive': u''}, u'reservations': None}, u'_context_instance_lock\
_checked': False, u'_context_project_name': u'ServerActionsTestJSON-tenant', u'_context_is_admin': False, u'version': u'2.0'\
, u'_context_project_id': u'08f0c0f1cf8c4215bdc96810207fa636', u'_context_timestamp': u'2012-10-12T20:26:17.743361', u'_cont\
ext_read_deleted': u'no', u'_context_user_id': u'ae5714ba5d1749babfdc9322031ab0ca', u'method': u'confirm_resize', u'_context\
_remote_address': u'172.18.0.156'} from (pid=13011) _safe_log /opt/stack/nova/nova/openstack/common/rpc/common.py:195
2012-10-12 16:26:18 DEBUG nova.openstack.common.rpc.amqp [-] unpacked context: {'project_name': u'ServerActionsTestJSON-tena\
nt', 'user_id': u'ae5714ba5d1749babfdc9322031ab0ca', 'roles': [u'', u'admin'], 'timestamp': u'2012-10-12T20:26:17.743361', '\
auth_token': '<SANITIZED>', 'remote_address': u'172.18.0.156', 'quota_class': None, 'is_admin': False, 'service_catalog': [{\
u'endpoints_links': [], u'endpoints': [{u'adminURL': u'http://172.18.0.156:8774/v2/08f0c0f1cf8c4215bdc96810207fa636', u'regi\
on': u'RegionOne', u'publicURL': u'http://172.18.0.156:8774/v2/08f0c0f1cf8c4215bdc96810207fa636', u'internalURL': u'http://1\
72.18.0.156:8774/v2/08f0c0f1cf8c4215bdc96810207fa636', u'id': u'9e4c28daf0c34dc6bac1c3d0df60be90'}], u'type': u'compute', u'\
name': u'nova'}, {u'endpoints_links': [], u'endpoints': [{u'adminURL': u'http://172.18.0.156:3333', u'region': u'RegionOne',\
u'publicURL': u'http://172.18.0.156:3333', u'internalURL': u'http://172.18.0.156:3333', u'id': u'15d7fb5f8a274548a948abd5f1\
041bb1'}], u'type': u's3', u'name': u's3'}, {u'endpoints_links': [], u'endpoints': [{u'adminURL': u'http://172.18.0.156:9292\
', u'region': u'RegionOne', u'publicURL': u'http://172.18.0.156:9292', u'internalURL': u'http://172.18.0.156:9292', u'id': u\
'46d3dad6915d4e9f869d03e2f09903ae'}], u'type': u'image', u'name': u'glance'}, {u'endpoints_links': [], u'endpoints': [{u'adm\
inURL': u'http://172.18.0.156:8776/v1/08f0c0f1cf8c4215bdc96810207fa636', u'region': u'RegionOne', u'publicURL': u'http://172\
.18.0.156:8776/v1/08f0c0f1cf8c4215bdc96810207fa636', u'internalURL': u'http://172.18.0.156:8776/v1/08f0c0f1cf8c4215bdc968102\
07fa636', u'id': u'178b19edb2004dfcaf4f686873c9e6b6'}], u'type': u'volume', u'name': u'volume'}, {u'endpoints_links': [], u'\
endpoints': [{u'adminURL': u'http://172.18.0.156:8773/services/Admin', u'region': u'RegionOne', u'publicURL': u'http://172.1\
8.0.156:8773/services/Cloud', u'internalURL': u'http://172.18.0.156:8773/services/Cloud', u'id': u'54b376c76fa74eccbd9e39c8f\
7c41708'}], u'type': u'ec2', u'name': u'ec2'}, {u'endpoints_links': [], u'endpoints': [{u'adminURL': u'http://172.18.0.156:3\
5357/v2.0', u'region': u'RegionOne', u'publicURL': u'http://172.18.0.156:5000/v2.0', u'internalURL': u'http://172.18.0.156:5\
000/v2.0', u'id': u'210eb7a6880c465e920c1dcca9fb692e'}], u'type': u'identity', u'name': u'keystone'}], 'request_id': u'req-5\
d25aceb-a39b-4c1b-8a8f-c592baabd263', 'instance_lock_checked': False, 'project_id': u'08f0c0f1cf8c4215bdc96810207fa636', 'us\
er_name': u'ServerActionsTestJSON-user', 'read_deleted': u'no'} from (pid=13011) _safe_log /opt/stack/nova/nova/openstack/co\
mmon/rpc/common.py:195
2012-10-12 16:26:18 ERROR nova.openstack.common.rpc.amqp [-] Exception during message handling
2012-10-12 16:26:18 TRACE nova.openstack.common.rpc.amqp Traceback (most recent call last):
2012-10-12 16:26:18 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/openstack/common/rpc/amqp.py", line 27\
5, in _process_data
2012-10-12 16:26:18 TRACE nova.openstack.common.rpc.amqp rval = self.proxy.dispatch(ctxt, version, method, **args)
2012-10-12 16:26:18 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/openstack/common/rpc/dispatcher.py", l\
ine 145, in dispatch
2012-10-12 16:26:18 TRACE nova.openstack.common.rpc.amqp return getattr(proxyobj, method)(ctxt, **kwargs)
2012-10-12 16:26:18 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/exception.py", line 117, in wrapped
2012-10-12 16:26:18 TRACE nova.openstack.common.rpc.amqp temp_level, payload)
2012-10-12 16:26:18 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2012-10-12 16:26:18 TRACE nova.openstack.common.rpc.amqp self.gen.next()
2012-10-12 16:26:18 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/exception.py", line 92, in wrapped
2012-10-12 16:26:18 TRACE nova.openstack.common.rpc.amqp return f(*args, **kw)
2012-10-12 16:26:18 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/compute/manager.py", line 199, in deco\
rated_function
2012-10-12 16:26:18 TRACE nova.openstack.common.rpc.amqp kwargs['instance']['uuid'], e, sys.exc_info())
2012-10-12 16:26:18 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2012-10-12 16:26:18 TRACE nova.openstack.common.rpc.amqp self.gen.next()
2012-10-12 16:26:18 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/compute/manager.py", line 193, in deco\
rated_function
2012-10-12 16:26:18 TRACE nova.openstack.common.rpc.amqp return function(self, context, *args, **kwargs)
2012-10-12 16:26:18 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/compute/manager.py", line 1394, in con\
firm_resize
2012-10-12 16:26:18 TRACE nova.openstack.common.rpc.amqp migration_ref = self.db.migration_get(context, migration_id)
2012-10-12 16:26:18 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/db/api.py", line 401, in migration_get
2012-10-12 16:26:18 TRACE nova.openstack.common.rpc.amqp return IMPL.migration_get(context, migration_id)
2012-10-12 16:26:18 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/db/sqlalchemy/api.py", line 110, in wr\
apper
2012-10-12 16:26:18 TRACE nova.openstack.common.rpc.amqp raise exception.AdminRequired()
2012-10-12 16:26:18 TRACE nova.openstack.common.rpc.amqp AdminRequired: User does not have admin privileges
2012-10-12 16:26:18 TRACE nova.openstack.common.rpc.amqp
2012-10-12 16:26:18 ERROR nova.openstack.common.rpc.common [-] Returning exception User does not have admin privileges to ca\
ller
2012-10-12 16:26:18 ERROR nova.openstack.common.rpc.common [-] ['Traceback (most recent call last):\n', ' File "/opt/stack/\
nova/nova/openstack/common/rpc/amqp.py", line 275, in _process_data\n rval = self.proxy.dispatch(ctxt, version, method, *\
*args)\n', ' File "/opt/stack/nova/nova/openstack/common/rpc/dispatcher.py", line 145, in dispatch\n return getattr(prox\
yobj, method)(ctxt, **kwargs)\n', ' File "/opt/stack/nova/nova/exception.py", line 117, in wrapped\n temp_level, payload\
)\n', ' File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__\n self.gen.next()\n', ' File "/opt/stack/nova/nov\
a/exception.py", line 92, in wrapped\n return f(*args, **kw)\n', ' File "/opt/stack/nova/nova/compute/manager.py", line \
199, in decorated_function\n kwargs[\'instance\'][\'uuid\'], e, sys.exc_info())\n', ' File "/usr/lib/python2.7/contextli\
b.py", line 24, in __exit__\n self.gen.next()\n', ' File "/opt/stack/nova/nova/compute/manager.py", line 193, in decorat\
ed_function\n return function(self, context, *args, **kwargs)\n', ' File "/opt/stack/nova/nova/compute/manager.py", line\
1394, in confirm_resize\n migration_ref = self.db.migration_get(context, migration_id)\n', ' File "/opt/stack/nova/nova\
/db/api.py", line 401, in migration_get\n return IMPL.migration_get(context, migration_id)\n', ' File "/opt/stack/nova/n\
ova/db/sqlalchemy/api.py", line 110, in wrapper\n raise exception.AdminRequired()\n', 'AdminRequired: User does not have \
admin privileges\n']
Thanks for the report David
Couple of housekeeping things - you don't mention the version, so I'm going to assume it's somewhere around commit faa47fef9. Also, I'm ignoring the AdminRequired thing but it might be worth a separate bug.
Now, interestingly enough, the MigrationNotFound exception can be raised by db.migration_get() or db.migration_ update( ) if a migration by the given ID cannot be found in the DB:
@require_ admin_context get(context, id, session=None): context, models.Migration, session=session,
read_ deleted= "yes"). \
filter_ by(id=id) .\
first( )
def migration_
result = model_query(
if not result: MigrationNotFou nd(migration_ id=id)
raise exception.
return result
confirm_resize in nova.compute.api does this:
rpcapi. confirm_ resize( migration_ id=migration_ ref['id' ])
db.migration_ update( migration_ ref['id' ], {'status': 'confirmed'})
So, the first question is whether it's the migration_get() on the compute side or the migration_update() on the api side is failing
If it was the compute side, I think I'd expect to see something logged in the compute log (since we wouldn't be silently passing the exception because of e.g. bug #1084706) and for an instance fault to be in the output of 'nova show'
OTOH, I really can't think of a reason why the migration_update() would fail on the api side
So, please reproduce again and:
1) Include the output of 'nova show' for that instance
2) Attach the full compute and api logs from that time
3) If you can, add some debugging to get a traceback of the MigrationNotFound exception
4) Tell us exactly what version of Nova you're using