resize-confirm and resize-revert don't work sometimes

Bug #1066140 reported by David Kranz
10
This bug affects 2 people
Affects Status Importance Assigned to Milestone
OpenStack Compute (nova)
Fix Released
Medium
wangpan

Bug Description

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']

Revision history for this message
Mark McLoughlin (markmc) wrote :

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
 def migration_get(context, id, session=None):
     result = model_query(context, models.Migration, session=session,
                          read_deleted="yes").\
                      filter_by(id=id).\
                      first()

     if not result:
         raise exception.MigrationNotFound(migration_id=id)

     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

Changed in nova:
status: New → Incomplete
Revision history for this message
wangpan (hzwangpan) wrote :

I run into the first issue with folsom nova, 'Instance has not been resized' error return when confirm a 'VERIFY_RESIZE' instance,
root@Debian:/home/openstack/nova/instance_for_test$ nova list
+--------------------------------------+------------+---------------+-----------------------+
| ID | Name | Status | Networks |
+--------------------------------------+------------+---------------+-----------------------+
| 48abaf16-d534-43e5-b9f2-c403062fd708 | server-001 | VERIFY_RESIZE | private=10.120.32.140 |
| 1bc5f33a-b611-4b94-bf5b-f0dd40feaa88 | server-002 | RESIZE | private=10.120.32.152 |
+--------------------------------------+------------+---------------+-----------------------+
hzfangjh@114-113-199-9:/home/openstack/nova/instance_for_test$ nova resize-confirm 48abaf16-d534-43e5-b9f2-c403062fd708
ERROR: Instance has not been resized. (HTTP 400) (Request-ID: req-128842be-cdec-4947-a394-2fb80938580b)
unfortunately, this is a probabilistic problem, you should resize-confirm the instance as soon as it become to 'VERIFY_RESIZE'.

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to nova (master)

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

Changed in nova:
assignee: nobody → wangpan (hzwangpan)
status: Incomplete → In Progress
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to nova (master)

Reviewed: https://review.openstack.org/18287
Committed: http://github.com/openstack/nova/commit/54928267e8807167fb96c8fe414a482833a39465
Submitter: Jenkins
Branch: master

commit 54928267e8807167fb96c8fe414a482833a39465
Author: Wangpan <email address hidden>
Date: Tue Dec 18 10:06:15 2012 +0800

    Fix race condition of resize confirmation

    Currently, the db update of migration status is after the db update of
    instance's vm_state in _finish_resize, so a race condition occurs when an
    instance's vm_state is updated but the migration status doesn't, and at
    this moment a resize confirmation is performed, then an exception
    'MigrationNotFoundByStatus' is raised.

    Fixes: bug #1066140

    Change-Id: I1dac98cc99d3491c92faaad2b9dcc40d7c0524b5

Changed in nova:
status: In Progress → Fix Committed
Changed in nova:
importance: Undecided → Medium
tags: added: folsom-backport-potential
Thierry Carrez (ttx)
Changed in nova:
milestone: none → grizzly-2
status: Fix Committed → Fix Released
Thierry Carrez (ttx)
Changed in nova:
milestone: grizzly-2 → 2013.1
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

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