Nova backup image fails

Bug #1065053 reported by Édouard Thuleau on 2012-10-10
14
This bug affects 2 people
Affects Status Importance Assigned to Milestone
OpenStack Compute (nova)
Medium
Édouard Thuleau
Folsom
Medium
Vish Ishaya
nova (Ubuntu)
Undecided
Unassigned
Quantal
Undecided
Unassigned

Bug Description

I use Folsom releale.
I set OpenStack with Glance.

When I try to do a backup image of an instance, I get an error in nova-compute logs and in Glance log.

I use this API request to do a backup :
curl -i http://192.168.146.6:8774/v2/83a649b306f64942a3068f6a4fcf0eda/servers/8cc97452-f176-4c8a-b670-8dd40b8f944f/action -X POST -H "X-Auth-Project-Id: admin" -H "User-Agent: python-novaclient" -H "Content-Type: application/json" -H "Accept: application/json" -H "X-Auth-Token: 2cb3661781174a97864f8abe5612da2a" -d '{"createBackup": {"name": "Backup 1", "backup_type": "daily", "rotation": 2}}'
The snapshot is created but the older backup are not deleted.

I opened two bug, this one for Nova and another one for Glance:
https://bugs.launchpad.net/glance/+bug/1065060

Nova-compute logs :

2012-10-10 16:04:28 DEBUG nova.manager [-] Running periodic task ComputeManager._poll_unconfirmed_resizes from (pid=18795) periodic_tasks /opt/stack/nova/nova/manager.py:172
DEBUG:nova.manager:Running periodic task ComputeManager._poll_unconfirmed_resizes
2012-10-10 16:04:30 DEBUG nova.openstack.common.rpc.amqp [-] received {u'_context_roles': [u'admin', u'KeystoneAdmin', u'KeystoneServiceAdmin'], u'_context_request_id': u'req-e930
892e-6788-49dc-a482-b1073adb9c1a', u'_context_quota_class': None, u'_context_project_name': u'admin', u'_context_service_catalog': [{u'endpoints': [{u'adminURL': u'http://192.168.
146.6:8776/v1/83a649b306f64942a3068f6a4fcf0eda', u'region': u'RegionOne', u'internalURL': u'http://192.168.146.6:8776/v1/83a649b306f64942a3068f6a4fcf0eda', u'id': u'4fc5eca8b3044d
b4b8e0934e995a02e3', u'publicURL': u'http://192.168.146.6:8776/v1/83a649b306f64942a3068f6a4fcf0eda'}], u'endpoints_links': [], u'type': u'volume', u'name': u'cinder'}, {u'endpoint
s': [{u'adminURL': u'http://192.168.146.6:9292', u'region': u'RegionOne', u'internalURL': u'http://192.168.146.6:9292', u'id': u'5e9d743af281468cae10b320640f1473', u'publicURL': u
'http://192.168.146.6:9292'}], u'endpoints_links': [], u'type': u'image', u'name': u'glance'}, {u'endpoints': [{u'adminURL': u'http://192.168.146.6:8774/v2/83a649b306f64942a3068f6
a4fcf0eda', u'region': u'RegionOne', u'internalURL': u'http://192.168.146.6:8774/v2/83a649b306f64942a3068f6a4fcf0eda', u'id': u'bf7028de9c1448ad9d6f2991a8512d03', u'publicURL': u'
http://192.168.146.6:8774/v2/83a649b306f64942a3068f6a4fcf0eda'}], u'endpoints_links': [], u'type': u'compute', u'name': u'nova'}, {u'endpoints': [{u'adminURL': u'http://192.168.14
6.6:8773/services/Admin', u'region': u'RegionOne', u'internalURL': u'http://192.168.146.6:8773/services/Cloud', u'id': u'5a2ca0bde45e44b787d2ecd59b8d0bd3', u'publicURL': u'http://
192.168.146.6:8773/services/Cloud'}], u'endpoints_links': [], u'type': u'ec2', u'name': u'ec2'}, {u'endpoints': [{u'adminURL': u'http://192.168.146.6:35357/v2.0', u'region': u'Reg
ionOne', u'internalURL': u'http://192.168.146.6:5000/v2.0', u'id': u'cbcd12b6a016456585d93bbd88643780', u'publicURL': u'http://192.168.146.6:5000/v2.0'}], u'endpoints_links': [],
u'type': u'identity', u'name': u'keystone'}], u'_context_user_name': u'admin', u'_context_auth_token': '<SANITIZED>', u'args': {u'image_type': u'backup', u'instance': {u'vm_state'
: u'active', u'availability_zone': None, u'terminated_at': None, u'ephemeral_gb': 0, u'instance_type_id': 2, u'user_data': None, u'vm_mode': None, u'deleted_at': None, u'reservati
on_id': u'r-9sxd7oy1', u'id': 4, u'security_groups': [{u'deleted_at': None, u'user_id': u'0729338e3e4e473496778822e78c8fd3', u'name': u'default', u'deleted': False, u'created_at':
 u'2012-10-08T15:26:00.000000', u'updated_at': None, u'rules': [{u'from_port': 22, u'protocol': u'tcp', u'group_id': None, u'deleted': False, u'created_at': u'2012-10-08T15:27:29.
000000', u'updated_at': None, u'to_port': 22, u'parent_group_id': 1, u'cidr': u'0.0.0.0/0', u'deleted_at': None, u'id': 1}], u'project_id': u'83a649b306f64942a3068f6a4fcf0eda', u'
id': 1, u'description': u'default'}], u'disable_terminate': False, u'user_id': u'0729338e3e4e473496778822e78c8fd3', u'uuid': u'8cc97452-f176-4c8a-b670-8dd40b8f944f', u'server_name
': None, u'default_swap_device': None, u'info_cache': {u'instance_uuid': u'8cc97452-f176-4c8a-b670-8dd40b8f944f', u'deleted': False, u'created_at': u'2012-10-10T13:28:56.000000',
u'updated_at': u'2012-10-10T13:30:01.000000', u'network_info': u'[{"network": {"bridge": "br1000", "subnets": [{"ips": [{"meta": {}, "version": 4, "type": "fixed", "floating_ips":
 [{"meta": {}, "version": 4, "type": "floating", "address": "192.168.146.48"}], "address": "172.16.0.3"}], "version": 4, "meta": {"dhcp_server": "172.16.0.4"}, "dns": [], "routes"
: [], "cidr": "172.16.0.0/24", "gateway": {"meta": {}, "version": 4, "type": "gateway", "address": "172.16.0.1"}}, {"ips": [], "version": null, "meta": {"dhcp_server": "172.16.0.4
"}, "dns": [], "routes": [], "cidr": null, "gateway": {"meta": {}, "version": null, "type": "gateway", "address": null}}], "meta": {"multi_host": true, "should_create_bridge": tru
e, "bridge_interface": "eth1", "tenant_id": "83a649b306f64942a3068f6a4fcf0eda", "vlan": 1000, "should_create_vlan": true}, "id": "a581fcfb-5248-447d-8205-b7ecd86ac0de", "label": "
private_0"}, "meta": {}, "id": "77fc30cf-4034-4c83-ad75-01ae226cdd85", "address": "fa:16:3e:79:5d:40"}]', u'deleted_at': None, u'id': 4}, u'hostname': u'test', u'launched_on': u'g
argamel', u'display_description': u'test', u'key_data': u'ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAAAgQDM3n/MyErlJ6rK6EulDx3/2/WzzN8184uz73tSmVZieoLCjSknSglbPJs1PmN8UFjPCArJ72so687OSAvRN
gq40qLzthisDzVFR42Se6RVwpJzM5Xmc5iGRrDg1kdVQCkcmFtKXrLFTTUBIUvN8GoajE79QOSaM17vFHbwN2o6Dw== Generated by Nova\n', u'kernel_id': u'2fbe9821-366e-4cd6-bb64-c917238bcc9f', u'power_st
ate': 1, u'default_ephemeral_device': None, u'progress': 0, u'project_id': u'83a649b306f64942a3068f6a4fcf0eda', u'launched_at': u'2012-10-10T13:29:16.000000', u'scheduled_at': u'2
012-10-10T13:28:56.000000', u'ramdisk_id': u'18312c9e-d1ea-4927-be5f-9d4e65bf0f29', u'access_ip_v6': None, u'access_ip_v4': None, u'deleted': False, u'key_name': u'test', u'update
d_at': u'2012-10-10T13:57:28.000000', u'host': u'gargamel', u'display_name': u'test', u'task_state': None, u'shutdown_terminate': False, u'architecture': None, u'root_gb': 0, u'lo
cked': False, u'name': u'instance-00000004', u'created_at': u'2012-10-10T13:28:56.000000', u'launch_index': 0, u'metadata': [], u'memory_mb': 512, u'instance_type': {u'disabled':
False, u'root_gb': 0, u'deleted_at': None, u'name': u'm1.tiny', u'deleted': False, u'created_at': None, u'ephemeral_gb': 0, u'updated_at': None, u'memory_mb': 512, u'vcpus': 1, u'
swap': 0, u'rxtx_factor': 1.0, u'is_public': True, u'flavorid': u'1', u'vcpu_weight': None, u'id': 2}, u'vcpus': 1, u'image_ref': u'd62a18f6-5279-4087-a689-dccedfa15fca', u'root_d
evice_name': u'/dev/vda', u'auto_disk_config': None, u'os_type': None, u'config_drive': u''}, u'backup_type': u'daily', u'rotation': 2, u'image_id': u'3d4c6bb8-ff93-4cbb-8828-7cd5
9c6bc8c1'}, u'_context_instance_lock_checked': False, u'_context_is_admin': True, u'version': u'2.0', u'_context_project_id': u'83a649b306f64942a3068f6a4fcf0eda', u'_context_times
tamp': u'2012-10-10T14:04:29.893069', u'_context_read_deleted': u'no', u'_context_user_id': u'0729338e3e4e473496778822e78c8fd3', u'method': u'snapshot_instance', u'_context_remote
_address': u'192.168.146.6'} from (pid=18795) _safe_log /opt/stack/nova/nova/openstack/common/rpc/common.py:195
DEBUG:nova.openstack.common.rpc.amqp:received {u'_context_roles': [u'admin', u'KeystoneAdmin', u'KeystoneServiceAdmin'], u'_context_request_id': u'req-e930892e-6788-49dc-a482-b107
3adb9c1a', u'_context_quota_class': None, u'_context_project_name': u'admin', u'_context_service_catalog': [{u'endpoints': [{u'adminURL': u'http://192.168.146.6:8776/v1/83a649b306
f64942a3068f6a4fcf0eda', u'region': u'RegionOne', u'internalURL': u'http://192.168.146.6:8776/v1/83a649b306f64942a3068f6a4fcf0eda', u'id': u'4fc5eca8b3044db4b8e0934e995a02e3', u'p
ublicURL': u'http://192.168.146.6:8776/v1/83a649b306f64942a3068f6a4fcf0eda'}], u'endpoints_links': [], u'type': u'volume', u'name': u'cinder'}, {u'endpoints': [{u'adminURL': u'htt
p://192.168.146.6:9292', u'region': u'RegionOne', u'internalURL': u'http://192.168.146.6:9292', u'id': u'5e9d743af281468cae10b320640f1473', u'publicURL': u'http://192.168.146.6:92
92'}], u'endpoints_links': [], u'type': u'image', u'name': u'glance'}, {u'endpoints': [{u'adminURL': u'http://192.168.146.6:8774/v2/83a649b306f64942a3068f6a4fcf0eda', u'region': u
'RegionOne', u'internalURL': u'http://192.168.146.6:8774/v2/83a649b306f64942a3068f6a4fcf0eda', u'id': u'bf7028de9c1448ad9d6f2991a8512d03', u'publicURL': u'http://192.168.146.6:877
4/v2/83a649b306f64942a3068f6a4fcf0eda'}], u'endpoints_links': [], u'type': u'compute', u'name': u'nova'}, {u'endpoints': [{u'adminURL': u'http://192.168.146.6:8773/services/Admin'
, u'region': u'RegionOne', u'internalURL': u'http://192.168.146.6:8773/services/Cloud', u'id': u'5a2ca0bde45e44b787d2ecd59b8d0bd3', u'publicURL': u'http://192.168.146.6:8773/servi
ces/Cloud'}], u'endpoints_links': [], u'type': u'ec2', u'name': u'ec2'}, {u'endpoints': [{u'adminURL': u'http://192.168.146.6:35357/v2.0', u'region': u'RegionOne', u'internalURL':
 u'http://192.168.146.6:5000/v2.0', u'id': u'cbcd12b6a016456585d93bbd88643780', u'publicURL': u'http://192.168.146.6:5000/v2.0'}], u'endpoints_links': [], u'type': u'identity', u'
name': u'keystone'}], u'_context_user_name': u'admin', u'_context_auth_token': '<SANITIZED>', u'args': {u'image_type': u'backup', u'instance': {u'vm_state': u'active', u'availabil
ity_zone': None, u'terminated_at': None, u'ephemeral_gb': 0, u'instance_type_id': 2, u'user_data': None, u'vm_mode': None, u'deleted_at': None, u'reservation_id': u'r-9sxd7oy1', u
'id': 4, u'security_groups': [{u'deleted_at': None, u'user_id': u'0729338e3e4e473496778822e78c8fd3', u'name': u'default', u'deleted': False, u'created_at': u'2012-10-08T15:26:00.0
00000', u'updated_at': None, u'rules': [{u'from_port': 22, u'protocol': u'tcp', u'group_id': None, u'deleted': False, u'created_at': u'2012-10-08T15:27:29.000000', u'updated_at': None, u'to_port': 22, u'parent_group_id': 1, u'cidr': u'0.0.0.0/0', u'deleted_at': None, u'id': 1}], u'project_id': u'83a649b306f64942a3068f6a4fcf0eda', u'id': 1, u'description': u'default'}], u'disable_terminate': False, u'user_id': u'0729338e3e4e473496778822e78c8fd3', u'uuid': u'8cc97452-f176-4c8a-b670-8dd40b8f944f', u'server_name': None, u'default_swap_device': None, u'info_cache': {u'instance_uuid': u'8cc97452-f176-4c8a-b670-8dd40b8f944f', u'deleted': False, u'created_at': u'2012-10-10T13:28:56.000000', u'updated_at': u'2012-10-10T13:30:01.000000', u'network_info': u'[{"network": {"bridge": "br1000", "subnets": [{"ips": [{"meta": {}, "version": 4, "type": "fixed", "floating_ips": [{"meta": {}, "version": 4, "type": "floating", "address": "192.168.146.48"}], "address": "172.16.0.3"}], "version": 4, "meta": {"dhcp_server": "172.16.0.4"}, "dns": [], "routes": [], "cidr": "172.16.0.0/24", "gateway": {"meta": {}, "version": 4, "type": "gateway", "address": "172.16.0.1"}}, {"ips": [], "version": null, "meta": {"dhcp_server": "172.16.0.4"}, "dns": [], "routes": [], "cidr": null, "gateway": {"meta": {}, "version": null, "type": "gateway", "address": null}}], "meta": {"multi_host": true, "should_create_bridge": true, "bridge_interface": "eth1", "tenant_id": "83a649b306f64942a3068f6a4fcf0eda", "vlan": 1000, "should_create_vlan": true}, "id": "a581fcfb-5248-447d-8205-b7ecd86ac0de", "label": "private_0"}, "meta": {}, "id": "77fc30cf-4034-4c83-ad75-01ae226cdd85", "address": "fa:16:3e:79:5d:40"}]', u'deleted_at': None, u'id': 4}, u'hostname': u'test', u'launched_on': u'gargamel', u'display_description': u'test', u'key_data': u'ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAAAgQDM3n/MyErlJ6rK6EulDx3/2/WzzN8184uz73tSmVZieoLCjSknSglbPJs1PmN8UFjPCArJ72so687OSAvRNgq40qLzthisDzVFR42Se6RVwpJzM5Xmc5iGRrDg1kdVQCkcmFtKXrLFTTUBIUvN8GoajE79QOSaM17vFHbwN2o6Dw== Generated by Nova\n', u'kernel_id': u'2fbe9821-366e-4cd6-bb64-c917238bcc9f', u'power_state': 1, u'default_ephemeral_device': None, u'progress': 0, u'project_id': u'83a649b306f64942a3068f6a4fcf0eda', u'launched_at': u'2012-10-10T13:29:16.000000', u'scheduled_at': u'2012-10-10T13:28:56.000000', u'ramdisk_id': u'18312c9e-d1ea-4927-be5f-9d4e65bf0f29', u'access_ip_v6': None, u'access_ip_v4': None, u'deleted': False, u'key_name': u'test', u'updated_at': u'2012-10-10T13:57:28.000000', u'host': u'gargamel', u'display_name': u'test', u'task_state': None, u'shutdown_terminate': False, u'architecture': None, u'root_gb': 0, u'locked': False, u'name': u'instance-00000004', u'created_at': u'2012-10-10T13:28:56.000000', u'launch_index': 0, u'metadata': [], u'memory_mb': 512, u'instance_type': {u'disabled': False, u'root_gb': 0, u'deleted_at': None, u'name': u'm1.tiny', u'deleted': False, u'created_at': None, u'ephemeral_gb': 0, u'updated_at': None, u'memory_mb': 512, u'vcpus': 1, u'swap': 0, u'rxtx_factor': 1.0, u'is_public': True, u'flavorid': u'1', u'vcpu_weight': None, u'id': 2}, u'vcpus': 1, u'image_ref': u'd62a18f6-5279-4087-a689-dccedfa15fca', u'root_device_name': u'/dev/vda', u'auto_disk_config': None, u'os_type': None, u'config_drive': u''}, u'backup_type': u'daily', u'rotation': 2, u'image_id': u'3d4c6bb8-ff93-4cbb-8828-7cd59c6bc8c1'}, u'_context_instance_lock_checked': False, u'_context_is_admin': True, u'version': u'2.0', u'_context_project_id': u'83a649b306f64942a3068f6a4fcf0eda', u'_context_timestamp': u'2012-10-10T14:04:29.893069', u'_context_read_deleted': u'no', u'_context_user_id': u'0729338e3e4e473496778822e78c8fd3', u'method': u'snapshot_instance', u'_context_remote_address': u'192.168.146.6'}
2012-10-10 16:04:30 DEBUG nova.openstack.common.rpc.amqp [-] unpacked context: {'project_name': u'admin', 'user_id': u'0729338e3e4e473496778822e78c8fd3', 'roles': [u'admin', u'KeystoneAdmin', u'KeystoneServiceAdmin'], 'timestamp': u'2012-10-10T14:04:29.893069', 'auth_token': '<SANITIZED>', 'remote_address': u'192.168.146.6', 'quota_class': None, 'is_admin': True, 'service_catalog': [{u'endpoints_links': [], u'endpoints': [{u'adminURL': u'http://192.168.146.6:8776/v1/83a649b306f64942a3068f6a4fcf0eda', u'region': u'RegionOne', u'publicURL': u'http://192.168.146.6:8776/v1/83a649b306f64942a3068f6a4fcf0eda', u'internalURL': u'http://192.168.146.6:8776/v1/83a649b306f64942a3068f6a4fcf0eda', u'id': u'4fc5eca8b3044db4b8e0934e995a02e3'}], u'type': u'volume', u'name': u'cinder'}, {u'endpoints_links': [], u'endpoints': [{u'adminURL': u'http://192.168.146.6:9292', u'region': u'RegionOne', u'publicURL': u'http://192.168.146.6:9292', u'internalURL': u'http://192.168.146.6:9292', u'id': u'5e9d743af281468cae10b320640f1473'}], u'type': u'image', u'name': u'glance'}, {u'endpoints_links': [], u'endpoints': [{u'adminURL': u'http://192.168.146.6:8774/v2/83a649b306f64942a3068f6a4fcf0eda', u'region': u'RegionOne', u'publicURL': u'http://192.168.146.6:8774/v2/83a649b306f64942a3068f6a4fcf0eda', u'internalURL': u'http://192.168.146.6:8774/v2/83a649b306f64942a3068f6a4fcf0eda', u'id': u'bf7028de9c1448ad9d6f2991a8512d03'}], u'type': u'compute', u'name': u'nova'}, {u'endpoints_links': [], u'endpoints': [{u'adminURL': u'http://192.168.146.6:8773/services/Admin', u'region': u'RegionOne', u'publicURL': u'http://192.168.146.6:8773/services/Cloud', u'internalURL': u'http://192.168.146.6:8773/services/Cloud', u'id': u'5a2ca0bde45e44b787d2ecd59b8d0bd3'}], u'type': u'ec2', u'name': u'ec2'}, {u'endpoints_links': [], u'endpoints': [{u'adminURL': u'http://192.168.146.6:35357/v2.0', u'region': u'RegionOne', u'publicURL': u'http://192.168.146.6:5000/v2.0', u'internalURL': u'http://192.168.146.6:5000/v2.0', u'id': u'cbcd12b6a016456585d93bbd88643780'}], u'type': u'identity', u'name': u'keystone'}], 'request_id': u'req-e930892e-6788-49dc-a482-b1073adb9c1a', 'instance_lock_checked': False, 'project_id': u'83a649b306f64942a3068f6a4fcf0eda', 'user_name': u'admin', 'read_deleted': u'no'} from (pid=18795) _safe_log /opt/stack/nova/nova/openstack/common/rpc/common.py:195
DEBUG:nova.openstack.common.rpc.amqp:unpacked context: {'project_name': u'admin', 'user_id': u'0729338e3e4e473496778822e78c8fd3', 'roles': [u'admin', u'KeystoneAdmin', u'KeystoneS
erviceAdmin'], 'timestamp': u'2012-10-10T14:04:29.893069', 'auth_token': '<SANITIZED>', 'remote_address': u'192.168.146.6', 'quota_class': None, 'is_admin': True, 'service_catalog
': [{u'endpoints_links': [], u'endpoints': [{u'adminURL': u'http://192.168.146.6:8776/v1/83a649b306f64942a3068f6a4fcf0eda', u'region': u'RegionOne', u'publicURL': u'http://192.168
.146.6:8776/v1/83a649b306f64942a3068f6a4fcf0eda', u'internalURL': u'http://192.168.146.6:8776/v1/83a649b306f64942a3068f6a4fcf0eda', u'id': u'4fc5eca8b3044db4b8e0934e995a02e3'}], u
'type': u'volume', u'name': u'cinder'}, {u'endpoints_links': [], u'endpoints': [{u'adminURL': u'http://192.168.146.6:9292', u'region': u'RegionOne', u'publicURL': u'http://192.168
.146.6:9292', u'internalURL': u'http://192.168.146.6:9292', u'id': u'5e9d743af281468cae10b320640f1473'}], u'type': u'image', u'name': u'glance'}, {u'endpoints_links': [], u'endpoi
nts': [{u'adminURL': u'http://192.168.146.6:8774/v2/83a649b306f64942a3068f6a4fcf0eda', u'region': u'RegionOne', u'publicURL': u'http://192.168.146.6:8774/v2/83a649b306f64942a3068f
6a4fcf0eda', u'internalURL': u'http://192.168.146.6:8774/v2/83a649b306f64942a3068f6a4fcf0eda', u'id': u'bf7028de9c1448ad9d6f2991a8512d03'}], u'type': u'compute', u'name': u'nova'}
, {u'endpoints_links': [], u'endpoints': [{u'adminURL': u'http://192.168.146.6:8773/services/Admin', u'region': u'RegionOne', u'publicURL': u'http://192.168.146.6:8773/services/Cl
oud', u'internalURL': u'http://192.168.146.6:8773/services/Cloud', u'id': u'5a2ca0bde45e44b787d2ecd59b8d0bd3'}], u'type': u'ec2', u'name': u'ec2'}, {u'endpoints_links': [], u'endp
oints': [{u'adminURL': u'http://192.168.146.6:35357/v2.0', u'region': u'RegionOne', u'publicURL': u'http://192.168.146.6:5000/v2.0', u'internalURL': u'http://192.168.146.6:5000/v2
.0', u'id': u'cbcd12b6a016456585d93bbd88643780'}], u'type': u'identity', u'name': u'keystone'}], 'request_id': u'req-e930892e-6788-49dc-a482-b1073adb9c1a', 'instance_lock_checked'
: False, 'project_id': u'83a649b306f64942a3068f6a4fcf0eda', 'user_name': u'admin', 'read_deleted': u'no'}
2012-10-10 16:04:30 DEBUG nova.compute.manager [req-e930892e-6788-49dc-a482-b1073adb9c1a admin admin] [instance: 8cc97452-f176-4c8a-b670-8dd40b8f944f] Checking state from (pid=187
95) _get_power_state /opt/stack/nova/nova/compute/manager.py:334
DEBUG:nova.compute.manager:Checking state
2012-10-10 16:04:31 DEBUG nova.utils [req-e930892e-6788-49dc-a482-b1073adb9c1a admin admin] Got semaphore "compute_resources" for method "update_usage"... from (pid=18795) inner /
opt/stack/nova/nova/utils.py:713
DEBUG:nova.utils:Got semaphore "compute_resources" for method "update_usage"...
2012-10-10 16:04:31 AUDIT nova.compute.manager [req-e930892e-6788-49dc-a482-b1073adb9c1a admin admin] [instance: 8cc97452-f176-4c8a-b670-8dd40b8f944f] instance snapshotting
AUDIT:nova.compute.manager:instance snapshotting
2012-10-10 16:04:38 DEBUG nova.utils [req-e930892e-6788-49dc-a482-b1073adb9c1a admin admin] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf qemu-img snapshot
-c ce34e05276dc4634aca95f9b9a029f1b /opt/stack/data/nova/instances/instance-00000004/disk from (pid=18795) execute /opt/stack/nova/nova/utils.py:176
DEBUG:nova.utils:Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf qemu-img snapshot -c ce34e05276dc4634aca95f9b9a029f1b /opt/stack/data/nova/instances/instance
-00000004/disk
2012-10-10 16:04:39 DEBUG nova.utils [req-e930892e-6788-49dc-a482-b1073adb9c1a admin admin] Result was 0 from (pid=18795) execute /opt/stack/nova/nova/utils.py:191
DEBUG:nova.utils:Result was 0
2012-10-10 16:04:39 DEBUG nova.utils [req-e930892e-6788-49dc-a482-b1073adb9c1a admin admin] Running cmd (subprocess): qemu-img convert -f qcow2 -O raw -s ce34e05276dc4634aca95f9b9
a029f1b /opt/stack/data/nova/instances/instance-00000004/disk /opt/stack/data/nova/instances/snapshots/tmpY7BbQt/ce34e05276dc4634aca95f9b9a029f1b from (pid=18795) execute /opt/sta
ck/nova/nova/utils.py:176
DEBUG:nova.utils:Running cmd (subprocess): qemu-img convert -f qcow2 -O raw -s ce34e05276dc4634aca95f9b9a029f1b /opt/stack/data/nova/instances/instance-00000004/disk /opt/stack/da
ta/nova/instances/snapshots/tmpY7BbQt/ce34e05276dc4634aca95f9b9a029f1b
2012-10-10 16:04:39 DEBUG nova.utils [req-e930892e-6788-49dc-a482-b1073adb9c1a admin admin] Result was 0 from (pid=18795) execute /opt/stack/nova/nova/utils.py:191
DEBUG:nova.utils:Result was 0
2012-10-10 16:04:39 DEBUG nova.utils [req-e930892e-6788-49dc-a482-b1073adb9c1a admin admin] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf qemu-img snapshot
-d ce34e05276dc4634aca95f9b9a029f1b /opt/stack/data/nova/instances/instance-00000004/disk from (pid=18795) execute /opt/stack/nova/nova/utils.py:176
DEBUG:nova.utils:Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf qemu-img snapshot -d ce34e05276dc4634aca95f9b9a029f1b /opt/stack/data/nova/instances/instance
-00000004/disk
2012-10-10 16:04:39 DEBUG nova.utils [req-e930892e-6788-49dc-a482-b1073adb9c1a admin admin] Result was 0 from (pid=18795) execute /opt/stack/nova/nova/utils.py:191
DEBUG:nova.utils:Result was 0
2012-10-10 16:04:45 DEBUG nova.utils [req-e930892e-6788-49dc-a482-b1073adb9c1a admin admin] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf tee /sys/class/net
/vnet0/brport/hairpin_mode from (pid=18795) execute /opt/stack/nova/nova/utils.py:176
DEBUG:nova.utils:Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf tee /sys/class/net/vnet0/brport/hairpin_mode
2012-10-10 16:04:45 DEBUG nova.utils [req-e930892e-6788-49dc-a482-b1073adb9c1a admin admin] Result was 0 from (pid=18795) execute /opt/stack/nova/nova/utils.py:191
DEBUG:nova.utils:Result was 0
2012-10-10 16:04:46 DEBUG nova.utils [req-e930892e-6788-49dc-a482-b1073adb9c1a admin admin] Got semaphore "compute_resources" for method "update_usage"... from (pid=18795) inner /
opt/stack/nova/nova/utils.py:713
DEBUG:nova.utils:Got semaphore "compute_resources" for method "update_usage"...
ERROR:glanceclient.common.http:Request returned failure status.
ERROR:root:Original exception being dropped: ['Traceback (most recent call last):\n', ' File "/opt/stack/nova/nova/compute/manager.py", line 196, in decorated_function\n retur
n function(self, context, *args, **kwargs)\n', ' File "/opt/stack/nova/nova/compute/manager.py", line 1218, in _rotate_backups\n images = fetch_images()\n', ' File "/opt/stac
k/nova/nova/compute/manager.py", line 1206, in fetch_images\n marker=marker, sort_key=\'created_at\', sort_dir=\'desc\')\n', ' File "/opt/stack/nova/nova/image/glance.py", lin
e 169, in detail\n for image in images:\n', ' File "/opt/stack/python-glanceclient/glanceclient/v1/images.py", line 130, in paginate\n images = self._list(url, "images")\n', ' File "/opt/stack/python-glanceclient/glanceclient/common/base.py", line 53, in _list\n resp, body = self.api.json_request(\'GET\', url)\n', ' File "/opt/stack/python-glanceclient/glanceclient/common/http.py", line 187, in json_request\n resp, body_iter = self._http_request(url, method, **kwargs)\n', ' File "/opt/stack/python-glanceclient/glanceclient/common/http.py", line 171, in _http_request\n raise exc.from_response(resp)\n', 'HTTPBadRequest: HTTPBadRequest (HTTP 400)\n']
2012-10-10 16:04:47 DEBUG nova.utils [req-e930892e-6788-49dc-a482-b1073adb9c1a admin admin] Got semaphore "compute_resources" for method "update_usage"... from (pid=18795) inner /opt/stack/nova/nova/utils.py:713
DEBUG:nova.utils:Got semaphore "compute_resources" for method "update_usage"...
2012-10-10 16:04:47 ERROR nova.openstack.common.rpc.amqp [-] Exception during message handling
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp Traceback (most recent call last):
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/openstack/common/rpc/amqp.py", line 275, in _process_data
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp rval = self.proxy.dispatch(ctxt, version, method, **args)
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/openstack/common/rpc/dispatcher.py", line 145, in dispatch
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp return getattr(proxyobj, method)(ctxt, **kwargs)
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/exception.py", line 117, in wrapped
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp temp_level, payload)
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp self.gen.next()
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/exception.py", line 92, in wrapped
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp return f(*args, **kw)
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/compute/manager.py", line 181, in decorated_function
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp pass
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp self.gen.next()
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/compute/manager.py", line 167, in decorated_function
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp return function(self, context, *args, **kwargs)
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/compute/manager.py", line 202, in decorated_function
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp kwargs['instance']['uuid'], e, sys.exc_info())
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp self.gen.next()
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/compute/manager.py", line 196, in decorated_function
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp return function(self, context, *args, **kwargs)
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/compute/manager.py", line 1178, in snapshot_instance
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp self._rotate_backups(context, instance, backup_type, rotation)
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/compute/manager.py", line 202, in decorated_function
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp kwargs['instance']['uuid'], e, sys.exc_info())
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp KeyError: 'instance'
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp
ERROR:nova.openstack.common.rpc.amqp:Exception during message handling
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp Traceback (most recent call last):
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/openstack/common/rpc/amqp.py", line 275, in _process_data
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp rval = self.proxy.dispatch(ctxt, version, method, **args)
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/openstack/common/rpc/dispatcher.py", line 145, in dispatch
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp return getattr(proxyobj, method)(ctxt, **kwargs)
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/exception.py", line 117, in wrapped
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp temp_level, payload)
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp self.gen.next()
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/exception.py", line 92, in wrapped
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp return f(*args, **kw)
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/compute/manager.py", line 181, in decorated_function
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp pass
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp self.gen.next()
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/compute/manager.py", line 167, in decorated_function
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp return function(self, context, *args, **kwargs)
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/compute/manager.py", line 202, in decorated_function
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp kwargs['instance']['uuid'], e, sys.exc_info())
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp self.gen.next()
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/compute/manager.py", line 196, in decorated_function
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp return function(self, context, *args, **kwargs)
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/compute/manager.py", line 1178, in snapshot_instance
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp self._rotate_backups(context, instance, backup_type, rotation)
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/compute/manager.py", line 202, in decorated_function
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp kwargs['instance']['uuid'], e, sys.exc_info())
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp KeyError: 'instance'
2012-10-10 16:04:47 TRACE nova.openstack.common.rpc.amqp

summary: - Nova backup image fail
+ Nova backup image fails
description: updated
Édouard Thuleau (ethuleau) wrote :

I investigated the problem and I think it's not only a Glance bug.

When we make a backup on VM through the compute API, Nova requests Glance to get the list of images precedently backuped for this instance. And with this list, Nova must clean backuped images according to rotation parameter.

The problem occurs when Nova request this backup images list from Glance.

Nova use the 'marker' and 'limit' parameters to get the metadata list page by page. And the first request to get the first page of the list, Nova sets the 'marker' parameter to 'None' and limit to '20' (see function https://github.com/openstack/nova/blob/master/nova/compute/manager.py#L1203).
But Glance doesn't accept requests with the parameter 'marker' seted to 'None' and reponds with 400 'Invalid: 400 Bad Request'.
And Nova doesn't catch this error. So the function '/opt/stack/nova/nova/compute/manager.py", line 1189, in _rotate_backups' fails.

I don't know if it's only a Nova Bug or if Glance should accept requests with 'marker' parameter seted to 'None' or 'none' like it accepts it for the 'is_public' parameter. But in any case, Nova should catch and raise correctly errors sended by Glance.

Brian Waldon (bcwaldon) wrote :

We shouldn't be sending a marker of None from Nova - Glance is doing the right thing.

Loic Dachary (dachary) wrote :

Unless glance in essex gracefully copes with this, the same problem will happen with nova in essex ( https://github.com/openstack/nova/blob/stable/essex/nova/compute/manager.py#L1007 )

Tiantian Gao (gtt116) on 2012-10-16
Changed in nova:
assignee: nobody → TianTian Gao (gtt116)
status: New → In Progress
Loic Dachary (dachary) wrote :
Édouard Thuleau (ethuleau) wrote :

I can propose another patch to correct this bug.

The Nova Glance wrapper returns all images metadata
if the parameter 'limit' is not define. It doesn't
split the image metadata list.

So the sub method fetch_image is no more needed.
We can delete it.

I added a check in Nova Glance wrapper to be sure
the parameter 'marker' or another one aren't set
to 'None'.

Changed in nova:
importance: Undecided → Medium

Reviewed: https://review.openstack.org/14471
Committed: http://github.com/openstack/nova/commit/d23cf2096fe62c1e575e79c4ff0af3f1fb7830ad
Submitter: Jenkins
Branch: master

commit d23cf2096fe62c1e575e79c4ff0af3f1fb7830ad
Author: TianTian Gao <gtt116@126.com>
Date: Tue Oct 16 15:17:31 2012 +0800

    Check parameter 'marker' before make request to glance

    fix bug: 1065053

    Since glance need parameter 'marker' to be a image-id, can not
    be None. check 'marker' before make request to glance.

    Change-Id: I7fc063ea74ae3be71e2effdc0b62432ebdd52c27

Changed in nova:
status: In Progress → Fix Committed

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

Changed in nova:
assignee: TianTian Gao (gtt116) → Édouard Thuleau (ethuleau)
status: Fix Committed → In Progress

Reviewed: https://review.openstack.org/14770
Committed: http://github.com/openstack/nova/commit/17149f688d22e4f4938674f7179a03caeafbfc93
Submitter: Jenkins
Branch: master

commit 17149f688d22e4f4938674f7179a03caeafbfc93
Author: Édouard Thuleau <email address hidden>
Date: Wed Oct 24 18:08:49 2012 +0200

    fetch_images() method no more needed

    The Nova Glance wrapper returns all images metadata
    if the parameter 'limit' is not define. It doesn't
    split the image metadata list.

    So the sub method fetch_image is no more needed.
    We can delete it.

    I added a check in Nova Glance wrapper to be sure
    the parameter 'marker' or another one aren't set
    to 'None' (like in bug #1065053).

    Fixes LP bug #1070904

    Change-Id: I24ecc4adf158401f60b508aa3a20bd4c91bfa92b

Changed in nova:
status: In Progress → Fix Committed
Thierry Carrez (ttx) on 2012-11-21
Changed in nova:
milestone: none → grizzly-1
status: Fix Committed → Fix Released
tags: removed: folsom-backport-potential

Fix proposed to branch: stable/folsom
Review: https://review.openstack.org/16978

Reviewed: https://review.openstack.org/16978
Committed: http://github.com/openstack/nova/commit/102c76b83d2d8bbb751f7febc279382ddc76f4eb
Submitter: Jenkins
Branch: stable/folsom

commit 102c76b83d2d8bbb751f7febc279382ddc76f4eb
Author: TianTian Gao <gtt116@126.com>
Date: Tue Oct 16 15:17:31 2012 +0800

    Check parameter 'marker' before make request to glance

    fix bug: 1065053

    Since glance need parameter 'marker' to be a image-id, can not
    be None. check 'marker' before make request to glance.

    Change-Id: I7fc063ea74ae3be71e2effdc0b62432ebdd52c27
    (cherry picked from commit d23cf2096fe62c1e575e79c4ff0af3f1fb7830ad)

Changed in nova (Ubuntu):
status: New → Fix Released
Changed in nova (Ubuntu Quantal):
status: New → Confirmed

Hello Édouard, or anyone else affected,

Accepted nova into quantal-proposed. The package will build now and be available at http://launchpad.net/ubuntu/+source/nova/2012.2.1+stable-20121212-a99a802e-0ubuntu1 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation how to enable and use -proposed. Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested, and change the tag from verification-needed to verification-done. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed. In either case, details of your testing will help us make a better decision.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance!

Changed in nova (Ubuntu Quantal):
status: Confirmed → Fix Committed
tags: added: verification-needed
Launchpad Janitor (janitor) wrote :
Download full text (8.3 KiB)

This bug was fixed in the package nova - 2012.2.1+stable-20121212-a99a802e-0ubuntu1

---------------
nova (2012.2.1+stable-20121212-a99a802e-0ubuntu1) quantal-proposed; urgency=low

  * Ubuntu updates:
    - debian/control: Ensure novaclient is upgraded with nova,
      require python-keystoneclient >= 1:2.9.0. (LP: #1073289)
    - d/p/avoid_setuptools_git_dependency.patch: Refresh.
  * Dropped patches, applied upstream:
    - debian/patches/CVE-2012-5625.patch: [a99a802]
  * Resynchronize with stable/folsom (b55014ca) (LP: #1085255):
    - [a99a802] create_lvm_image allocates dirty blocks (LP: #1070539)
    - [670b388] RPC exchange name defaults to 'openstack' (LP: #1083944)
    - [3ede373] disassociate_floating_ip with multi_host=True fails
      (LP: #1074437)
    - [22d7c3b] libvirt imagecache should handle shared image storage
      (LP: #1075018)
    - [e787786] Detached and deleted RBD volumes remain associated with insance
      (LP: #1083818)
    - [9265eb0] live_migration missing migrate_data parameter in Hyper-V driver
      (LP: #1066513)
    - [3d99848] use_single_default_gateway does not function correctly
      (LP: #1075859)
    - [65a2d0a] resize does not migrate DHCP host information (LP: #1065440)
    - [102c76b] Nova backup image fails (LP: #1065053)
    - [48a3521] Fix config-file overrides for nova-dhcpbridge
    - [69663ee] Cloudpipe in Folsom: no such option: cnt_vpn_clients
      (LP: #1069573)
    - [6e47cc8] DisassociateAddress can cause Internal Server Error
      (LP: #1080406)
    - [22c3d7b] API calls to dis-associate an auto-assigned floating IP should
      return proper warning (LP: #1061499)
    - [bd11d15] libvirt: if exception raised during volume_detach, volume state
      is inconsistent (LP: #1057756)
    - [dcb59c3] admin can't describe all images in ec2 api (LP: #1070138)
    - [78de622] Incorrect Exception raised during Create server when metadata
      over 255 characters (LP: #1004007)
    - [c313de4] Fixed IP isn't released before updating DHCP host file
      (LP: #1078718)
    - [f4ab42d] Enabling Return Reservation ID with XML create server request
      returns no body (LP: #1061124)
    - [3db2a38] 'BackupCreate' should accept rotation parameter greater than or
      equal to zero (LP: #1071168)
    - [f7e5dde] libvirt reboot sometimes fails to reattach volumes
      (LP: #1073720)
    - [ff776d4] libvirt: detaching volume may fail while terminating other
      instances on the same host concurrently (LP: #1060836)
    - [85a8bc2] Used instance uuid rather than id in remove-fixed-ip
    - [42a85c0] Fix error on invalid delete_on_termination value
    - [6a17579] xenapi migrations fail w/ swap (LP: #1064083)
    - [97649b8] attach-time field for volumes is not updated for detach volume
      (LP: #1056122)
    - [8f6a718] libvirt: rebuild is not using kernel and ramdisk associated with
      the new image (LP: #1060925)
    - [fbe835f] live-migration and volume host assignement (LP: #1066887)
    - [c2a9150] typo prevents volume_tmp_dir flag from working (LP: #1071536)
    - [93efa21] Instances deleted during spawn leak network allocations
      (LP: #1068716)
    - [ebabd02] After restartin...

Read more...

Changed in nova (Ubuntu Quantal):
status: Fix Committed → Fix Released
Thierry Carrez (ttx) on 2013-04-04
Changed in nova:
milestone: grizzly-1 → 2013.1
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers