Attachment 869828 Details for Bug 1071806 – log of the failed action

log of the failed action

failed_instance_snapshot.log (text/x-log), 17.54 KB, created by Yogev Rabl on 2014-03-03 08:21:37 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Yogev Rabl

Created: 2014-03-03 08:21:37 UTC

Size: 17.54 KB

patch

obsolete

>nova compute stand alone log:
>
>2014-03-03 09:58:59.431 2084 AUDIT nova.compute.manager [req-56466568-87d2-479b-8b03-1ee43fd5ca36 4e57b7e28746483fa422e84a98c8769c d58d96c5074042aeb8d8823d904fc41c] [instance: 1a2cb42f-23bc-465c-914d-deb678018000] instance snapshotting
>2014-03-03 09:58:59.725 2084 INFO nova.virt.libvirt.driver [req-56466568-87d2-479b-8b03-1ee43fd5ca36 4e57b7e28746483fa422e84a98c8769c d58d96c5074042aeb8d8823d904fc41c] [instance: 1a2cb42f-23bc-465c-914d-deb678018000] Beginning live snapshot process
>2014-03-03 09:59:00.183 2084 INFO nova.virt.libvirt.driver [req-56466568-87d2-479b-8b03-1ee43fd5ca36 4e57b7e28746483fa422e84a98c8769c d58d96c5074042aeb8d8823d904fc41c] [instance: 1a2cb42f-23bc-465c-914d-deb678018000] Snapshot extracted, beginning image upload
>2014-03-03 09:59:00.802 2084 ERROR nova.openstack.common.rpc.amqp [req-56466568-87d2-479b-8b03-1ee43fd5ca36 4e57b7e28746483fa422e84a98c8769c d58d96c5074042aeb8d8823d904fc41c] Exception during message handling
>2014-03-03 09:59:00.802 2084 TRACE nova.openstack.common.rpc.amqp Traceback (most recent call last):
>2014-03-03 09:59:00.802 2084 TRACE nova.openstack.common.rpc.amqp   File "/usr/lib/python2.6/site-packages/nova/openstack/common/rpc/amqp.py", line 461, in _process_data
>2014-03-03 09:59:00.802 2084 TRACE nova.openstack.common.rpc.amqp     **args)
>2014-03-03 09:59:00.802 2084 TRACE nova.openstack.common.rpc.amqp   File "/usr/lib/python2.6/site-packages/nova/openstack/common/rpc/dispatcher.py", line 172, in dispatch
>2014-03-03 09:59:00.802 2084 TRACE nova.openstack.common.rpc.amqp     result = getattr(proxyobj, method)(ctxt, **kwargs)
>2014-03-03 09:59:00.802 2084 TRACE nova.openstack.common.rpc.amqp   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 353, in decorated_function
>2014-03-03 09:59:00.802 2084 TRACE nova.openstack.common.rpc.amqp     return function(self, context, *args, **kwargs)
>2014-03-03 09:59:00.802 2084 TRACE nova.openstack.common.rpc.amqp   File "/usr/lib/python2.6/site-packages/nova/exception.py", line 90, in wrapped
>2014-03-03 09:59:00.802 2084 TRACE nova.openstack.common.rpc.amqp     payload)
>2014-03-03 09:59:00.802 2084 TRACE nova.openstack.common.rpc.amqp   File "/usr/lib/python2.6/site-packages/nova/exception.py", line 73, in wrapped
>2014-03-03 09:59:00.802 2084 TRACE nova.openstack.common.rpc.amqp     return f(self, context, *args, **kw)
>2014-03-03 09:59:00.802 2084 TRACE nova.openstack.common.rpc.amqp   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 243, in decorated_function
>2014-03-03 09:59:00.802 2084 TRACE nova.openstack.common.rpc.amqp     pass
>2014-03-03 09:59:00.802 2084 TRACE nova.openstack.common.rpc.amqp   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 229, in decorated_function
>2014-03-03 09:59:00.802 2084 TRACE nova.openstack.common.rpc.amqp     return function(self, context, *args, **kwargs)
>2014-03-03 09:59:00.802 2084 TRACE nova.openstack.common.rpc.amqp   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 271, in decorated_function
>2014-03-03 09:59:00.802 2084 TRACE nova.openstack.common.rpc.amqp     e, sys.exc_info())
>2014-03-03 09:59:00.802 2084 TRACE nova.openstack.common.rpc.amqp   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 258, in decorated_function
>2014-03-03 09:59:00.802 2084 TRACE nova.openstack.common.rpc.amqp     return function(self, context, *args, **kwargs)
>2014-03-03 09:59:00.802 2084 TRACE nova.openstack.common.rpc.amqp   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 319, in decorated_function
>2014-03-03 09:59:00.802 2084 TRACE nova.openstack.common.rpc.amqp     % image_id, instance=instance)
>2014-03-03 09:59:00.802 2084 TRACE nova.openstack.common.rpc.amqp   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 309, in decorated_function
>2014-03-03 09:59:00.802 2084 TRACE nova.openstack.common.rpc.amqp     *args, **kwargs)
>2014-03-03 09:59:00.802 2084 TRACE nova.openstack.common.rpc.amqp   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 2308, in snapshot_instance
>2014-03-03 09:59:00.802 2084 TRACE nova.openstack.common.rpc.amqp     task_states.IMAGE_SNAPSHOT)
>2014-03-03 09:59:00.802 2084 TRACE nova.openstack.common.rpc.amqp   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 2339, in _snapshot_instance
>2014-03-03 09:59:00.802 2084 TRACE nova.openstack.common.rpc.amqp     update_task_state)
>2014-03-03 09:59:00.802 2084 TRACE nova.openstack.common.rpc.amqp   File "/usr/lib/python2.6/site-packages/nova/virt/libvirt/driver.py", line 1408, in snapshot
>2014-03-03 09:59:00.802 2084 TRACE nova.openstack.common.rpc.amqp     image_format)
>2014-03-03 09:59:00.802 2084 TRACE nova.openstack.common.rpc.amqp   File "/usr/lib/python2.6/site-packages/nova/virt/libvirt/driver.py", line 1512, in _live_snapshot
>2014-03-03 09:59:00.802 2084 TRACE nova.openstack.common.rpc.amqp     self._conn.defineXML(xml)
>2014-03-03 09:59:00.802 2084 TRACE nova.openstack.common.rpc.amqp   File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 179, in doit
>2014-03-03 09:59:00.802 2084 TRACE nova.openstack.common.rpc.amqp     result = proxy_call(self._autowrap, f, *args, **kwargs)
>2014-03-03 09:59:00.802 2084 TRACE nova.openstack.common.rpc.amqp   File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 139, in proxy_call
>2014-03-03 09:59:00.802 2084 TRACE nova.openstack.common.rpc.amqp     rv = execute(f,*args,**kwargs)
>2014-03-03 09:59:00.802 2084 TRACE nova.openstack.common.rpc.amqp   File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 77, in tworker
>2014-03-03 09:59:00.802 2084 TRACE nova.openstack.common.rpc.amqp     rv = meth(*args,**kwargs)
>2014-03-03 09:59:00.802 2084 TRACE nova.openstack.common.rpc.amqp   File "/usr/lib64/python2.6/site-packages/libvirt.py", line 2680, in defineXML
>2014-03-03 09:59:00.802 2084 TRACE nova.openstack.common.rpc.amqp     if ret is None:raise libvirtError('virDomainDefineXML() failed', conn=self)
>2014-03-03 09:59:00.802 2084 TRACE nova.openstack.common.rpc.amqp libvirtError: block copy still active: domain has active block copy job
>2014-03-03 09:59:00.802 2084 TRACE nova.openstack.common.rpc.amqp 
>2014-03-03 09:59:25.543 2084 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources
>2014-03-03 09:59:25.795 2084 AUDIT nova.compute.resource_tracker [-] Free ram (MB): 29540
>2014-03-03 09:59:25.795 2084 AUDIT nova.compute.resource_tracker [-] Free disk (GB): 841
>2014-03-03 09:59:25.796 2084 AUDIT nova.compute.resource_tracker [-] Free VCPUS: 5
>2014-03-03 09:59:25.878 2084 INFO nova.compute.resource_tracker [-] Compute_service record updated for cougar07.scl.lab.tlv.redhat.com:cougar07.scl.lab.tlv.redhat.com
>
>Cloud Controller logs: 
>
>==> /var/log/nova/api.log <==
>2014-03-03 09:58:58.573 2465 INFO nova.osapi_compute.wsgi.server [-] (2465) accepted ('10.35.160.133', 52494)
>
>2014-03-03 09:58:58.576 2465 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): 10.35.160.133
>2014-03-03 09:58:59.259 2465 INFO nova.osapi_compute.wsgi.server [req-56466568-87d2-479b-8b03-1ee43fd5ca36 4e57b7e28746483fa422e84a98c8769c d58d96c5074042aeb8d8823d904fc41c] 10.35.160.133 "POST /v2/d58d96c5074042aeb8d8823d904fc41c/servers/1a2cb42f-23bc-465c-914d-deb678018000/action HTTP/1.1" status: 202 len: 302 time: 0.6839709
>
>2014-03-03 09:58:59.261 2463 INFO nova.osapi_compute.wsgi.server [-] (2463) accepted ('10.35.160.133', 52499)
>
>2014-03-03 09:58:59.264 2463 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): 10.35.160.133
>2014-03-03 09:58:59.358 2463 INFO nova.osapi_compute.wsgi.server [req-3395a1e0-26f6-4850-afe6-a00e1582ae21 4e57b7e28746483fa422e84a98c8769c d58d96c5074042aeb8d8823d904fc41c] 10.35.160.133 "GET /v2/d58d96c5074042aeb8d8823d904fc41c/servers/1a2cb42f-23bc-465c-914d-deb678018000 HTTP/1.1" status: 200 len: 1918 time: 0.0960419
>
>
>==> /var/log/nova/compute.log <==
>2014-03-03 09:59:32.113 2366 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources
>2014-03-03 09:59:32.265 2366 AUDIT nova.compute.resource_tracker [-] Free ram (MB): 31588
>2014-03-03 09:59:32.266 2366 AUDIT nova.compute.resource_tracker [-] Free disk (GB): 901
>2014-03-03 09:59:32.266 2366 AUDIT nova.compute.resource_tracker [-] Free VCPUS: 6
>2014-03-03 09:59:32.341 2366 INFO nova.compute.resource_tracker [-] Compute_service record updated for cougar06.scl.lab.tlv.redhat.com:cougar06.scl.lab.tlv.redhat.com
>2014-03-03 09:59:33.029 2366 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources
>2014-03-03 09:59:33.178 2366 AUDIT nova.compute.resource_tracker [-] Free ram (MB): 31588
>2014-03-03 09:59:33.178 2366 AUDIT nova.compute.resource_tracker [-] Free disk (GB): 901
>2014-03-03 09:59:33.178 2366 AUDIT nova.compute.resource_tracker [-] Free VCPUS: 6
>2014-03-03 09:59:33.258 2366 INFO nova.compute.resource_tracker [-] Compute_service record updated for cougar06.scl.lab.tlv.redhat.com:cougar06.scl.lab.tlv.redhat.com
>
>
>Glance stand alone logs:
>
>==> /var/log/glance/api.log <==
>2014-03-03 09:58:58.838 2064 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): 10.35.160.133
>
>==> /var/log/glance/registry.log <==
>2014-03-03 09:58:58.887 2050 INFO glance.registry.api.v1.images [1f1224ef-bd99-46d1-9393-56bb7ea8028e 4e57b7e28746483fa422e84a98c8769c d58d96c5074042aeb8d8823d904fc41c] Successfully retrieved image 7c88b2d6-c852-4f01-a471-1b6b1a68a1e3
>
>==> /var/log/glance/api.log <==
>2014-03-03 09:58:58.897 2055 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): 10.35.160.133
>
>==> /var/log/glance/registry.log <==
>2014-03-03 09:58:58.946 2050 INFO glance.registry.api.v1.images [dfc2f8c8-be96-4a35-8216-5f35328c8787 4e57b7e28746483fa422e84a98c8769c d58d96c5074042aeb8d8823d904fc41c] Successfully retrieved image 7c88b2d6-c852-4f01-a471-1b6b1a68a1e3
>
>==> /var/log/glance/api.log <==
>2014-03-03 09:58:58.959 2060 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): 10.35.160.133
>
>==> /var/log/glance/registry.log <==
>2014-03-03 09:58:59.106 2050 INFO glance.registry.api.v1.images [ccb3d47f-0245-44ad-8690-148a3d7c2afd 4e57b7e28746483fa422e84a98c8769c d58d96c5074042aeb8d8823d904fc41c] Successfully created image None
>
>==> /var/log/glance/api.log <==
>2014-03-03 09:58:59.130 2060 INFO glance.notifier.notify_qpid [213b0ea5-f415-4679-8db7-b97723e0afd7 4e57b7e28746483fa422e84a98c8769c d58d96c5074042aeb8d8823d904fc41c] Connected to AMQP server on 10.35.160.133:5672
>2014-03-03 09:58:59.439 2068 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): 10.35.160.133
>2014-03-03 09:58:59.471 2059 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): 10.35.160.133
>
>==> /var/log/glance/registry.log <==
>2014-03-03 09:58:59.483 2050 INFO glance.registry.api.v1.images [60ea7b86-31c4-4ad7-8f4f-cac33b479db7 4e57b7e28746483fa422e84a98c8769c d58d96c5074042aeb8d8823d904fc41c] Successfully retrieved image 7c88b2d6-c852-4f01-a471-1b6b1a68a1e3
>
>==> /var/log/glance/api.log <==
>2014-03-03 09:58:59.493 2062 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): 10.35.160.133
>
>==> /var/log/glance/registry.log <==
>2014-03-03 09:58:59.547 2050 INFO glance.registry.api.v1.images [3e760f12-9a02-41b5-9cea-66af9db796ee 4e57b7e28746483fa422e84a98c8769c d58d96c5074042aeb8d8823d904fc41c] Returning detailed image list
>2014-03-03 09:58:59.566 2050 INFO glance.registry.api.v1.images [b34a1d03-c59d-49a6-9f5e-84040e8cc509 4e57b7e28746483fa422e84a98c8769c d58d96c5074042aeb8d8823d904fc41c] Successfully retrieved image 7c88b2d6-c852-4f01-a471-1b6b1a68a1e3
>
>==> /var/log/glance/api.log <==
>2014-03-03 09:58:59.578 2058 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): 10.35.160.133
>
>==> /var/log/glance/registry.log <==
>2014-03-03 09:58:59.628 2050 INFO glance.registry.api.v1.images [ecf159f4-94fe-48a7-9cb2-efb9f9c62860 4e57b7e28746483fa422e84a98c8769c d58d96c5074042aeb8d8823d904fc41c] Successfully retrieved image e0703c40-b5d5-439a-ab3b-938a1017df6d
>
>==> /var/log/glance/api.log <==
>2014-03-03 09:58:59.639 2057 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): 10.35.160.133
>
>==> /var/log/glance/registry.log <==
>2014-03-03 09:58:59.685 2050 INFO glance.registry.api.v1.images [a1bd3494-18d3-4eb0-8af4-5999948f4147 4e57b7e28746483fa422e84a98c8769c d58d96c5074042aeb8d8823d904fc41c] Successfully retrieved image e0703c40-b5d5-439a-ab3b-938a1017df6d
>
>==> /var/log/glance/api.log <==
>2014-03-03 09:59:00.188 2063 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): 10.35.160.133
>2014-03-03 09:59:00.239 2061 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): 10.35.160.133
>
>==> /var/log/glance/registry.log <==
>2014-03-03 09:59:00.239 2050 INFO glance.registry.api.v1.images [6a360a61-c90b-4fd4-b784-bf4d50fb5694 4e57b7e28746483fa422e84a98c8769c d58d96c5074042aeb8d8823d904fc41c] Successfully retrieved image e0703c40-b5d5-439a-ab3b-938a1017df6d
>2014-03-03 09:59:00.332 2050 INFO glance.registry.api.v1.images [d488844e-4c96-495d-bb3a-da44dd2f9c5d 4e57b7e28746483fa422e84a98c8769c d58d96c5074042aeb8d8823d904fc41c] Updating metadata for image e0703c40-b5d5-439a-ab3b-938a1017df6d
>2014-03-03 09:59:00.351 2050 INFO glance.registry.api.v1.images [f9d9175e-b858-4570-974d-18f59c12be02 4e57b7e28746483fa422e84a98c8769c d58d96c5074042aeb8d8823d904fc41c] Successfully retrieved image e0703c40-b5d5-439a-ab3b-938a1017df6d
>2014-03-03 09:59:00.444 2050 INFO glance.registry.api.v1.images [268d5917-3d70-4787-88bf-43e8bd8e828c 4e57b7e28746483fa422e84a98c8769c d58d96c5074042aeb8d8823d904fc41c] Successfully deleted image e0703c40-b5d5-439a-ab3b-938a1017df6d
>
>==> /var/log/glance/api.log <==
>2014-03-03 09:59:00.466 2063 INFO glance.notifier.notify_qpid [ab0c20c5-ff9d-4b4f-9a48-d69c7c4e5ed8 4e57b7e28746483fa422e84a98c8769c d58d96c5074042aeb8d8823d904fc41c] Connected to AMQP server on 10.35.160.133:5672
>
>
>Cinder stand alone logs:
>
>==> /var/log/cinder/api.log <==
>2014-03-03 09:58:59.564 1666 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): 10.35.160.133
>2014-03-03 09:58:59.595 1666 INFO cinder.api.openstack.wsgi [req-f4b04673-58c8-4e00-9cfa-44af42a9987c 4e57b7e28746483fa422e84a98c8769c d58d96c5074042aeb8d8823d904fc41c] GET http://10.35.160.91:8776/v1/d58d96c5074042aeb8d8823d904fc41c/snapshots/detail
>2014-03-03 09:58:59.607 1666 INFO cinder.api.openstack.wsgi [req-f4b04673-58c8-4e00-9cfa-44af42a9987c 4e57b7e28746483fa422e84a98c8769c d58d96c5074042aeb8d8823d904fc41c] http://10.35.160.91:8776/v1/d58d96c5074042aeb8d8823d904fc41c/snapshots/detail returned with HTTP 200
>2014-03-03 09:58:59.622 1666 INFO cinder.api.openstack.wsgi [req-10a97b4e-92b2-4605-8a37-62d20be0c9a0 4e57b7e28746483fa422e84a98c8769c d58d96c5074042aeb8d8823d904fc41c] GET http://10.35.160.91:8776/v1/d58d96c5074042aeb8d8823d904fc41c/volumes/detail
>2014-03-03 09:58:59.642 1666 AUDIT cinder.api.v1.volumes [req-10a97b4e-92b2-4605-8a37-62d20be0c9a0 4e57b7e28746483fa422e84a98c8769c d58d96c5074042aeb8d8823d904fc41c] vol={'migration_status': None, 'availability_zone': u'nova', 'terminated_at': None, 'updated_at': datetime.datetime(2014, 3, 2, 15, 33, 54), 'provider_geometry': None, 'snapshot_id': None, 'ec2_id': None, 'mountpoint': None, 'deleted_at': None, 'id': u'c49f069c-eebb-40f5-b586-4fc2bc53d4ff', 'size': 4L, 'user_id': u'4e57b7e28746483fa422e84a98c8769c', 'attach_time': None, 'attached_host': None, 'display_description': u'auto-created_from_restore_from_backup', 'volume_admin_metadata': [], 'encryption_key_id': None, 'project_id': u'd58d96c5074042aeb8d8823d904fc41c', 'launched_at': datetime.datetime(2014, 3, 2, 15, 32, 24), 'scheduled_at': datetime.datetime(2014, 3, 2, 15, 32, 23), 'status': u'available', 'volume_type_id': None, 'deleted': False, 'provider_location': u'netapp.qa.lab.tlv.redhat.com:/vol/vol_rhos_iscsi/volume-c49f069c-eebb-40f5-b586-4fc2bc53d4ff', 'host': u'cougar01.scl.lab.tlv.redhat.com', 'source_volid': None, 'provider_auth': None, 'display_name': u'restore_backup_ba18d4bf-463c-4961-95d5-fcf4fe6f6c54', 'instance_uuid': None, 'bootable': False, 'created_at': datetime.datetime(2014, 3, 2, 15, 32, 23), 'attach_status': u'detached', 'volume_type': None, '_name_id': None, 'volume_metadata': []}
>2014-03-03 09:58:59.642 1666 AUDIT cinder.api.v1.volumes [req-10a97b4e-92b2-4605-8a37-62d20be0c9a0 4e57b7e28746483fa422e84a98c8769c d58d96c5074042aeb8d8823d904fc41c] vol={'migration_status': None, 'availability_zone': u'nova', 'terminated_at': None, 'updated_at': datetime.datetime(2014, 3, 2, 15, 6, 3), 'provider_geometry': None, 'snapshot_id': None, 'ec2_id': None, 'mountpoint': None, 'deleted_at': None, 'id': u'712df103-7eba-45a3-be24-579c1b43f78d', 'size': 4L, 'user_id': u'4e57b7e28746483fa422e84a98c8769c', 'attach_time': None, 'attached_host': None, 'display_description': None, 'volume_admin_metadata': [<cinder.db.sqlalchemy.models.VolumeAdminMetadata object at 0x37126d0>], 'encryption_key_id': None, 'project_id': u'd58d96c5074042aeb8d8823d904fc41c', 'launched_at': datetime.datetime(2014, 3, 2, 13, 20, 28), 'scheduled_at': datetime.datetime(2014, 3, 2, 13, 19, 6), 'status': u'available', 'volume_type_id': None, 'deleted': False, 'provider_location': u'netapp.qa.lab.tlv.redhat.com:/vol/vol_rhos_iscsi/volume-712df103-7eba-45a3-be24-579c1b43f78d', 'host': u'cougar01.scl.lab.tlv.redhat.com', 'source_volid': None, 'provider_auth': None, 'display_name': None, 'instance_uuid': None, 'bootable': True, 'created_at': datetime.datetime(2014, 3, 2, 13, 19, 6), 'attach_status': u'detached', 'volume_type': None, '_name_id': None, 'volume_metadata': [], 'metadata': {u'readonly': u'False'}}
>2014-03-03 09:58:59.700 1666 INFO cinder.api.openstack.wsgi [req-10a97b4e-92b2-4605-8a37-62d20be0c9a0 4e57b7e28746483fa422e84a98c8769c d58d96c5074042aeb8d8823d904fc41c] http://10.35.160.91:8776/v1/d58d96c5074042aeb8d8823d904fc41c/volumes/detail returned with HTTP 200
>
>
>
>

Actions: View

Attachments on bug 1071806: 869828