Created attachment 918210 [details] /var/log and /etc/ logs from automation Description of problem: ALL in one setup. Ceph backend configured for glance and cinder at the same time . Running automation tests tempest code . failed tests : tempest.api.volume.test_volumes_actions.VolumesActionsTest.test_volume_upload From volume logs : Encoding: chunked' -H 'X-Auth-Token: MIIPigYJKoZIhvcNAQcCoIIPezCCD3cCAQExCTAHBgUrDgMCGjCCDeAGCSqGSIb3DQEHAaCCDdEEgg3NeyJhY2Nlc3MiOiB7InRva2VuIjogeyJpc3N1ZWRfYXQiOiAiMjAxNC0wNy0xNVQxNDoxMTo0OC44NTAzNzQiLCAiZXhwaXJlcyI6ICIyMDE0LTA3LTE1VDE1OjExOjQ4WiIsICJpZCI6ICJwbGFjZWhvbGRlciIsICJ0ZW5hbnQiOiB7ImRlc2NyaXB0aW9uIjogIlZvbHVtZXNBY3Rpb25zVGVzdFhNTC0xMDk1MzU0NjUzLWRlc2MiLCAiZW5hYmxlZCI6IHRydWUsICJpZCI6ICI4ZDQ0ZDNjMGIxMTE0NjIxYjMwNjUzY2I0OTA2M2Q5OSIsICJuYW1lIjogIlZvbHVtZXNBY3Rpb25zVGVzdFhNTC0xMDk1MzU0NjUzIn19LCAic2VydmljZUNhdGFsb2ciOiBbeyJlbmRwb2ludHMiOiBbeyJhZG1pblVSTCI6ICJodHRwOi8vMTkyLjE2OC4yLjIwOjg3NzQvdjIvOGQ0NGQzYzBiMTExNDYyMWIzMDY1M2NiNDkwNjNkOTkiLCAicmVnaW9uIjogIlJlZ2lvbk9uZSIsICJpbnRlcm5hbFVSTCI6ICJodHRwOi8vMTkyLjE2OC4yLjIwOjg3NzQvdjIvOGQ0NGQzYzBiMTExNDYyMWIzMDY1M2NiNDkwNjNkOTkiLCAiaWQiOiAiMTU4OGUwMjhmM2YzNGJhMmI1NGQ2ZjBjNmNmOTQzMmYiLCAicHVibGljVVJMIjogImh0dHA6Ly8xOTIuMTY4LjIuMjA6ODc3NC92Mi84ZDQ0ZDNjMGIxMTE0NjIxYjMwNjUzY2I0OTA2M2Q5OSJ9XSwgImVuZHBvaW50c19saW5rcyI6IFtdLCAidHlwZSI6ICJjb21wdXRlIiwgIm5hbWUiOiAibm92YSJ9LCB7ImVuZHBvaW50cyI6IFt7ImFkbWluVVJMIjogImh0dHA6Ly8xOTIuMTY4LjIuMjA6OTY5Ni8iLCAicmVnaW9uIjogIlJlZ2lvbk9uZSIsICJpbnRlcm5hbFVSTCI6ICJodHRwOi8vMTkyLjE2OC4yLjIwOjk2OTYvIiwgImlkIjogIjNmY2U3NWY2ODk5MjRkMTlhMDBkN2M1ZThjNjUzNzM4IiwgInB1YmxpY1VSTCI6ICJodHRwOi8vMTkyLjE2OC4yLjIwOjk2OTYvIn1dLCAiZW5kcG9pbnRzX2xpbmtzIjogW10sICJ0eXBlIjogIm5ldHdvcmsiLCAibmFtZSI6ICJuZXV0cm9uIn0sIHsiZW5kcG9pbnRzIjogW3siYWRtaW5VUkwiOiAiaHR0cDovLzE5Mi4xNjguMi4yMDo4Nzc2L3YyLzhkNDRkM2MwYjExMTQ2MjFiMzA2NTNjYjQ5MDYzZDk5IiwgInJlZ2lvbiI6ICJSZWdpb25PbmUiLCAiaW50ZXJuYWxVUkwiOiAiaHR0cDovLzE5Mi4xNjguMi4yMDo4Nzc2L3YyLzhkNDRkM2MwYjExMTQ2MjFiMzA2NTNjYjQ5MDYzZDk5IiwgImlkIjogIjVlYzMwMTNmMTczMjRkODE5MjgzMmExYzE3YWMxNzJmIiwgInB1YmxpY1VSTCI6ICJodHRwOi8vMTkyLjE2OC4yLjIwOjg3NzYvdjIvOGQ0NGQzYzBiMTExNDYyMWIzMDY1M2NiNDkwNjNkOTkifV0sICJlbmRwb2ludHNfbGlua3MiOiBbXSwgInR5cGUiOiAidm9sdW1ldjIiLCAibmFtZSI6ICJjaW5kZXJfdjIifSwgeyJlbmRwb2ludHMiOiBbeyJhZG1pblVSTCI6ICJodHRwOi8vMTkyLjE2OC4yLjIwOjgwODAiLCAicmVnaW9uIjogIlJlZ2lvbk9uZSIsICJpbnRlcm5hbFVSTCI6ICJodHRwOi8vMTkyLjE2OC4yLjIwOjgwODAiLCAiaWQiOiAiNGRiMGRlZTExOGI0NGRhYjliM2ExM2UzNTViNGViOTUiLCAicHVibGljVVJMIjogImh0dHA6Ly8xOTIuMTY4LjIuMjA6ODA4MCJ9XSwgImVuZHBvaW50c19saW5rcyI6IFtdLCAidHlwZSI6ICJzMyIsICJuYW1lIjogInN3aWZ0X3MzIn0sIHsiZW5kcG9pbnRzIjogW3siYWRtaW5VUkwiOiAiaHR0cDovLzE5Mi4xNjguMi4yMDo5MjkyIiwgInJlZ2lvbiI6ICJSZWdpb25PbmUiLCAiaW50ZXJuYWxVUkwiOiAiaHR0cDovLzE5Mi4xNjguMi4yMDo5MjkyIiwgImlkIjogIjIxMmRkMThkZGRlNDQ4ODNiYTExYmFhMTAxNTNhNTgwIiwgInB1YmxpY1VSTCI6ICJodHRwOi8vMTkyLjE2OC4yLjIwOjkyOTIifV0sICJlbmRwb2ludHNfbGlua3MiOiBbXSwgInR5cGUiOiAiaW1hZ2UiLCAibmFtZSI6ICJnbGFuY2UifSwgeyJlbmRwb2ludHMiOiBbeyJhZG1pblVSTCI6ICJodHRwOi8vMTkyLjE2OC4yLjIwOjg3NzYvdjEvOGQ0NGQzYzBiMTExNDYyMWIzMDY1M2NiNDkwNjNkOTkiLCAicmVnaW9uIjogIlJlZ2lvbk9uZSIsICJpbnRlcm5hbFVSTCI6ICJodHRwOi8vMTkyLjE2OC4yLjIwOjg3NzYvdjEvOGQ0NGQzYzBiMTExNDYyMWIzMDY1M2NiNDkwNjNkOTkiLCAiaWQiOiAiMGNkODYwYWQ1ZWM4NGM4YjlmMTVhOWYzMTNiNmI3ZjMiLCAicHVibGljVVJMIjogImh0dHA6Ly8xOTIuMTY4LjIuMjA6ODc3Ni92MS84ZDQ0ZDNjMGIxMTE0NjIxYjMwNjUzY2I0OTA2M2Q5OSJ9XSwgImVuZHBvaW50c19saW5rcyI6IFtdLCAidHlwZSI6ICJ2b2x1bWUiLCAibmFtZSI6ICJjaW5kZXIifSwgeyJlbmRwb2ludHMiOiBbeyJhZG1pblVSTCI6ICJodHRwOi8vMTkyLjE2OC4yLjIwOjg3NzMvc2VydmljZXMvQWRtaW4iLCAicmVnaW9uIjogIlJlZ2lvbk9uZSIsICJpbnRlcm5hbFVSTCI6ICJodHRwOi8vMTkyLjE2OC4yLjIwOjg3NzMvc2VydmljZXMvQ2xvdWQiLCAiaWQiOiAiMDhkMGY4ZTA0NTJkNGMxNDk2ZGEzZDg0ZjNiNzhjYWQiLCAicHVibGljVVJMIjogImh0dHA6Ly8xOTIuMTY4LjIuMjA6ODc3My9zZXJ2aWNlcy9DbG91ZCJ9XSwgImVuZHBvaW50c19saW5rcyI6IFtdLCAidHlwZSI6ICJlYzIiLCAibmFtZSI6ICJub3ZhX2VjMiJ9LCB7ImVuZHBvaW50cyI6IFt7ImFkbWluVVJMIjogImh0dHA6Ly8xOTIuMTY4LjIuMjA6ODA4MC8iLCAicmVnaW9uIjogIlJlZ2lvbk9uZSIsICJpbnRlcm5hbFVSTCI6ICJodHRwOi8vMTkyLjE2OC4yLjIwOjgwODAvdjEvQVVUSF84ZDQ0ZDNjMGIxMTE0NjIxYjMwNjUzY2I0OTA2M2Q5OSIsICJpZCI6ICIwNmZhNjM5MDM4ZGM0YzY4OTkxZjQzMTA2NzVkMDYxMyIsICJwdWJsaWNVUkwiOiAiaHR0cDovLzE5Mi4xNjguMi4yMDo4MDgwL3YxL0FVVEhfOGQ0NGQzYzBiMTExNDYyMWIzMDY1M2NiNDkwNjNkOTkifV0sICJlbmRwb2ludHNfbGlua3MiOiBbXSwgInR5cGUiOiAib2JqZWN0LXN0b3JlIiwgIm5hbWUiOiAic3dpZnQifSwgeyJlbmRwb2ludHMiOiBbeyJhZG1pblVSTCI6ICJodHRwOi8vMTkyLjE2OC4yLjIwOjM1MzU3L3YyLjAiLCAicmVnaW9uIjogIlJlZ2lvbk9uZSIsICJpbnRlcm5hbFVSTCI6ICJodHRwOi8vMTkyLjE2OC4yLjIwOjUwMDAvdjIuMCIsICJpZCI6ICIyNDE4NDVlMjI5ZmE0ZjM4ODNmYTg5ZmYyMzIwNmExOSIsICJwdWJsaWNVUkwiOiAiaHR0cDovLzE5Mi4xNjguMi4yMDo1MDAwL3YyLjAifV0sICJlbmRwb2ludHNfbGlua3MiOiBbXSwgInR5cGUiOiAiaWRlbnRpdHkiLCAibmFtZSI6ICJrZXlzdG9uZSJ9XSwgInVzZXIiOiB7InVzZXJuYW1lIjogIlZvbHVtZXNBY3Rpb25zVGVzdFhNTC0xMTQ4NjU4NTU0IiwgInJvbGVzX2xpbmtzIjogW10sICJpZCI6ICI4ZTE4NWE2MDU1ZDk0NWM5ODA5OGU3MTUxMTM3YjUyZCIsICJyb2xlcyI6IFt7Im5hbWUiOiAiX21lbWJlcl8ifSwgeyJuYW1lIjogIlN3aWZ0T3BlcmF0b3IifV0sICJuYW1lIjogIlZvbHVtZXNBY3Rpb25zVGVzdFhNTC0xMTQ4NjU4NTU0In0sICJtZXRhZGF0YSI6IHsiaXNfYWRtaW4iOiAwLCAicm9sZXMiOiBbIjlmZTJmZjllZTQzODRiMTg5NGE5MDg3OGQzZTkyYmFiIiwgIjcyNTYzZTEzZTQxNDQ2MzA4ZGQ4YTc1NDk1ZTAyNDNjIl19fX0xggGBMIIBfQIBATBcMFcxCzAJBgNVBAYTAlVTMQ4wDAYDVQQIDAVVbnNldDEOMAwGA1UEBwwFVW5zZXQxDjAMBgNVBAoMBVVuc2V0MRgwFgYDVQQDDA93d3cuZXhhbXBsZS5jb20CAQEwBwYFKw4DAhowDQYJKoZIhvcNAQEBBQAEggEADEapCoqzgwAAnAoXW3SUFJuRrdhwGyXeoc+C4kLuIlJUUdZN8rNDr884lldwxlFmmJLDDTpcbSRuskttfciUy0UjeuaMi-SJQrAxiuvKaN-waKsf1UdafCHqNgQF+EuPDfqECpc6i66gNi3alzW2JkzoBcgk7ZndHZAxJ9MOZWD4fEgm2I0Gg0zQGRbmNEMJ6HoQDRIAsY6oogKhURoClE6Z8oAEsdfmK9Vxqa46r3g7Fe5UlTxEidTvN39GoI29waxicJ8nCzmlzBYmO01cYZf4T9KYTYmo3eURGXpSd9u+V9Cml3wiU577dSZ10p+sZvYfF0mCL0RGMKuBUmoLGA==' -H 'Content-Type: application/octet-stream' -H 'User-Agent: python-glanceclient' -d '<open file u'/tmp/volume-f3868ee2-9339-472c-81bc-3d54fd3a46d2-6931741c-53c2-43f5-9983-a8bbcf04bc40', mode 'r' at 0x3ba0540>' http://192.168.2.20:9292/v2/images/6931741c-53c2-43f5-9983-a8bbcf04bc40/file log_curl_request /usr/lib/python2.7/site-packages/glanceclient/common/http.py:142 2014-07-15 10:12:19.357 18558 DEBUG cinder.openstack.common.periodic_task [-] Running periodic task VolumeManager._publish_service_capabilities run_periodic_tasks /usr/lib/python2.7/site-packages/cinder/openstack/common/periodic_task.py:178 2014-07-15 10:12:19.358 18558 DEBUG cinder.manager [-] Notifying Schedulers of capabilities ... _publish_service_capabilities /usr/lib/python2.7/site-packages/cinder/manager.py:128 2014-07-15 10:12:19.372 18558 DEBUG cinder.openstack.common.periodic_task [-] Running periodic task VolumeManager._report_driver_status run_periodic_tasks /usr/lib/python2.7/site-packages/cinder/openstack/common/periodic_task.py:178 2014-07-15 10:12:19.372 18558 INFO cinder.volume.manager [-] Updating volume status 2014-07-15 10:13:19.358 18558 DEBUG cinder.openstack.common.periodic_task [-] Running periodic task VolumeManager._publish_service_capabilities run_periodic_tasks /usr/lib/python2.7/site-packages/cinder/openstack/common/periodic_task.py:178 2014-07-15 10:13:19.359 18558 DEBUG cinder.manager [-] Notifying Schedulers of capabilities ... _publish_service_capabilities /usr/lib/python2.7/site-packages/cinder/manager.py:128 2014-07-15 10:13:19.368 18558 DEBUG cinder.openstack.common.periodic_task [-] Running periodic task VolumeManager._report_driver_status run_periodic_tasks /usr/lib/python2.7/site-packages/cinder/openstack/common/periodic_task.py:178 2014-07-15 10:13:19.369 18558 INFO cinder.volume.manager [-] Updating volume status 2014-07-15 10:14:19.358 18558 DEBUG cinder.openstack.common.periodic_task [-] Running periodic task VolumeManager._publish_service_capabilities run_periodic_tasks /usr/lib/python2.7/site-packages/cinder/openstack/common/periodic_task.py:178 2014-07-15 10:14:19.359 18558 DEBUG cinder.manager [-] Notifying Schedulers of capabilities ... _publish_service_capabilities /usr/lib/python2.7/site-packages/cinder/manager.py:128 2014-07-15 10:14:19.367 18558 DEBUG cinder.openstack.common.periodic_task [-] Running periodic task VolumeManager._report_driver_status run_periodic_tasks /usr/lib/python2.7/site-packages/cinder/openstack/common/periodic_task.py:178 2014-07-15 10:14:19.367 18558 INFO cinder.volume.manager [-] Updating volume status 2014-07-15 10:15:19.359 18558 DEBUG cinder.openstack.common.periodic_task [-] Running periodic task VolumeManager._publish_service_capabilities run_periodic_tasks /usr/lib/python2.7/site-packages/cinder/openstack/common/periodic_task.py:178 2014-07-15 10:15:19.360 18558 DEBUG cinder.manager [-] Notifying Schedulers of capabilities ... _publish_service_capabilities /usr/lib/python2.7/site-packages/cinder/manager.py:128 2014-07-15 10:15:19.364 18558 DEBUG cinder.openstack.common.periodic_task [-] Running periodic task VolumeManager._report_driver_status run_periodic_tasks /usr/lib/python2.7/site-packages/cinder/openstack/common/periodic_task.py:178 2014-07-15 10:15:19.365 18558 INFO cinder.volume.manager [-] Updating volume status 2014-07-15 10:16:19.360 18558 DEBUG cinder.openstack.common.periodic_task [-] Running periodic task VolumeManager._publish_service_capabilities run_periodic_tasks /usr/lib/python2.7/site-packages/cinder/openstack/common/periodic_task.py:178 2014-07-15 10:16:19.360 18558 DEBUG cinder.manager [-] Notifying Schedulers of capabilities ... _publish_service_capabilities /usr/lib/python2.7/site-packages/cinder/manager.py:128 2014-07-15 10:16:19.371 18558 DEBUG cinder.openstack.common.periodic_task [-] Running periodic task VolumeManager._report_driver_status run_periodic_tasks /usr/lib/python2.7/site-packages/cinder/openstack/common/periodic_task.py:178 2014-07-15 10:16:19.372 18558 INFO cinder.volume.manager [-] Updating volume status 2014-07-15 10:17:19.360 18558 DEBUG cinder.openstack.common.periodic_task [-] Running periodic task VolumeManager._publish_service_capabilities run_periodic_tasks /usr/lib/python2.7/site-packages/cinder/openstack/common/periodic_task.py:178 2014-07-15 10:17:19.360 18558 DEBUG cinder.manager [-] Notifying Schedulers of capabilities ... _publish_service_capabilities /usr/lib/python2.7/site-packages/cinder/manager.py:128 2014-07-15 10:17:19.367 18558 DEBUG cinder.openstack.common.periodic_task [-] Running periodic task VolumeManager._report_driver_status run_periodic_tasks /usr/lib/python2.7/site-packages/cinder/openstack/common/periodic_task.py:178 2014-07-15 10:17:19.368 18558 INFO cinder.volume.manager [-] Updating volume status 2014-07-15 10:18:19.362 18558 DEBUG cinder.openstack.common.periodic_task [-] Running periodic task VolumeManager._publish_service_capabilities run_periodic_tasks /usr/lib/python2.7/site-packages/cinder/openstack/common/periodic_task.py:178 2014-07-15 10:18:19.363 18558 DEBUG cinder.manager [-] Notifying Schedulers of capabilities ... _publish_service_capabilities /usr/lib/python2.7/site-packages/cinder/manager.py:128 2014-07-15 10:18:19.371 18558 DEBUG cinder.openstack.common.periodic_task [-] Running periodic task VolumeManager._report_driver_status run_periodic_tasks /usr/lib/python2.7/site-packages/cinder/openstack/common/periodic_task.py:178 2014-07-15 10:18:19.371 18558 INFO cinder.volume.manager [-] Updating volume status 2014-07-15 10:19:19.362 18558 DEBUG cinder.openstack.common.periodic_task [-] Running periodic task VolumeManager._publish_service_capabilities run_periodic_tasks /usr/lib/python2.7/site-packages/cinder/openstack/common/periodic_task.py:178 2014-07-15 10:19:19.363 18558 DEBUG cinder.manager [-] Notifying Schedulers of capabilities ... _publish_service_capabilities /usr/lib/python2.7/site-packages/cinder/manager.py:128 2014-07-15 10:19:19.366 18558 DEBUG cinder.openstack.common.periodic_task [-] Running periodic task VolumeManager._report_driver_status run_periodic_tasks /usr/lib/python2.7/site-packages/cinder/openstack/common/periodic_task.py:178 2014-07-15 10:19:19.367 18558 INFO cinder.volume.manager [-] Updating volume status 2014-07-15 10:20:00.094 18558 DEBUG glanceclient.common.http [req-c954e296-26b5-4e67-98d0-b6ec9eeac3a5 8e185a6055d945c98098e7151137b52d 8d44d3c0b1114621b30653cb49063d99 - - -] HTTP/1.1 410 Gone date: Tue, 15 Jul 2014 14:20:00 GMT content-length: 232 content-type: text/plain; charset=UTF-8 x-openstack-request-id: req-15ecac81-da92-45cd-abb8-76cff563aeed 410 Gone Image 6931741c-53c2-43f5-9983-a8bbcf04bc40 could not be found after upload.The image may have been deleted during the upload: No image found with ID 6931741c-53c2-43f5-9983-a8bbcf04bc40 Cleaning up the chunks uploaded log_http_response /usr/lib/python2.7/site-packages/glanceclient/common/http.py:152 2014-07-15 10:20:00.095 18558 ERROR glanceclient.common.http [req-c954e296-26b5-4e67-98d0-b6ec9eeac3a5 8e185a6055d945c98098e7151137b52d 8d44d3c0b1114621b30653cb49063d99 - - -] Request returned failure status. 2014-07-15 10:20:00.257 18558 ERROR oslo.messaging.rpc.dispatcher [req-c954e296-26b5-4e67-98d0-b6ec9eeac3a5 8e185a6055d945c98098e7151137b52d 8d44d3c0b1114621b30653cb49063d99 - - -] Exception during message handling: 410 Gone Image 6931741c-53c2-43f5-9983-a8bbcf04bc40 could not be found after upload.The image may have been deleted during the upload: No image found with ID 6931741c-53c2-43f5-9983-a8bbcf04bc40 Cleaning up the chunks uploaded (HTTP N/A) 2014-07-15 10:20:00.257 18558 TRACE oslo.messaging.rpc.dispatcher Traceback (most recent call last): 2014-07-15 10:20:00.257 18558 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/oslo/messaging/rpc/dispatcher.py", line 133, in _dispatch_and_reply 2014-07-15 10:20:00.257 18558 TRACE oslo.messaging.rpc.dispatcher incoming.message)) 2014-07-15 10:20:00.257 18558 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/oslo/messaging/rpc/dispatcher.py", line 176, in _dispatch 2014-07-15 10:20:00.257 18558 TRACE oslo.messaging.rpc.dispatcher return self._do_dispatch(endpoint, method, ctxt, args) 2014-07-15 10:20:00.257 18558 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/oslo/messaging/rpc/dispatcher.py", line 122, in _do_dispatch 2014-07-15 10:20:00.257 18558 TRACE oslo.messaging.rpc.dispatcher result = getattr(endpoint, method)(ctxt, **new_args) 2014-07-15 10:20:00.257 18558 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/cinder/volume/manager.py", line 719, in copy_volume_to_image 2014-07-15 10:20:00.257 18558 TRACE oslo.messaging.rpc.dispatcher payload['message'] = unicode(error) 2014-07-15 10:20:00.257 18558 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/cinder/openstack/common/excutils.py", line 68, in __exit__ 2014-07-15 10:20:00.257 18558 TRACE oslo.messaging.rpc.dispatcher six.reraise(self.type_, self.value, self.tb) 2014-07-15 10:20:00.257 18558 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/cinder/volume/manager.py", line 713, in copy_volume_to_image 2014-07-15 10:20:00.257 18558 TRACE oslo.messaging.rpc.dispatcher image_meta) 2014-07-15 10:20:00.257 18558 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/cinder/volume/drivers/rbd.py", line 808, in copy_volume_to_image 2014-07-15 10:20:00.257 18558 TRACE oslo.messaging.rpc.dispatcher image_meta, tmp_file) 2014-07-15 10:20:00.257 18558 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/cinder/image/image_utils.py", line 238, in upload_volume 2014-07-15 10:20:00.257 18558 TRACE oslo.messaging.rpc.dispatcher image_service.update(context, image_id, {}, image_file) 2014-07-15 10:20:00.257 18558 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/cinder/image/glance.py", line 311, in update 2014-07-15 10:20:00.257 18558 TRACE oslo.messaging.rpc.dispatcher _reraise_translated_image_exception(image_id) 2014-07-15 10:20:00.257 18558 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/cinder/image/glance.py", line 306, in update 2014-07-15 10:20:00.257 18558 TRACE oslo.messaging.rpc.dispatcher image_meta['data']) 2014-07-15 10:20:00.257 18558 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/cinder/image/glance.py", line 158, in call 2014-07-15 10:20:00.257 18558 TRACE oslo.messaging.rpc.dispatcher return getattr(client.images, method)(*args, **kwargs) 2014-07-15 10:20:00.257 18558 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/glanceclient/v2/images.py", line 110, in upload 2014-07-15 10:20:00.257 18558 TRACE oslo.messaging.rpc.dispatcher body=image_data) 2014-07-15 10:20:00.257 18558 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/glanceclient/common/http.py", line 289, in raw_request 2014-07-15 10:20:00.257 18558 TRACE oslo.messaging.rpc.dispatcher return self._http_request(url, method, **kwargs) 2014-07-15 10:20:00.257 18558 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/glanceclient/common/http.py", line 249, in _http_request 2014-07-15 10:20:00.257 18558 TRACE oslo.messaging.rpc.dispatcher raise exc.from_response(resp, body_str) 2014-07-15 10:20:00.257 18558 TRACE oslo.messaging.rpc.dispatcher HTTPException: 410 Gone 2014-07-15 10:20:00.257 18558 TRACE oslo.messaging.rpc.dispatcher Image 6931741c-53c2-43f5-9983-a8bbcf04bc40 could not be found after upload.The image may have been deleted during the upload: No image found with ID 6931741c-53c2-43f5-9983-a8bbcf04bc40 Cleaning up the chunks uploaded 2014-07-15 10:20:00.257 18558 TRACE oslo.messaging.rpc.dispatcher (HTTP N/A) 2014-07-15 10:20:00.257 18558 TRACE oslo.messaging.rpc.dispatcher 2014-07-15 10:20:00.279 18558 ERROR oslo.messaging._drivers.common [req-c954e296-26b5-4e67-98d0-b6ec9eeac3a5 8e185a6055d945c98098e7151137b52d 8d44d3c0b1114621b30653cb49063d99 - - -] Returning exception 410 Gone Image 6931741c-53c2-43f5-9983-a8bbcf04bc40 could not be found after upload.The image may have been deleted during the upload: No image found with ID 6931741c-53c2-43f5-9983-a8bbcf04bc40 Cleaning up the chunks uploaded (HTTP N/A) to caller 2014-07-15 10:20:00.279 18558 ERROR oslo.messaging._drivers.common [req-c954e296-26b5-4e67-98d0-b6ec9eeac3a5 8e185a6055d945c98098e7151137b52d 8d44d3c0b1114621b30653cb49063d99 - - -] ['Traceback (most recent call last):\n', ' File "/usr/lib/python2.7/site-packages/oslo/messaging/rpc/dispatcher.py", line 133, in _dispatch_and_reply\n incoming.message))\n', ' File "/usr/lib/python2.7/site-packages/oslo/messaging/rpc/dispatcher.py", line 176, in _dispatch\n return self._do_dispatch(endpoint, method, ctxt, args)\n', ' File "/usr/lib/python2.7/site-packages/oslo/messaging/rpc/dispatcher.py", line 122, in _do_dispatch\n result = getattr(endpoint, method)(ctxt, **new_args)\n', ' File "/usr/lib/python2.7/site-packages/cinder/volume/manager.py", line 719, in copy_volume_to_image\n payload[\'message\'] = unicode(error)\n', ' File "/usr/lib/python2.7/site-packages/cinder/openstack/common/excutils.py", line 68, in __exit__\n six.reraise(self.type_, self.value, self.tb)\n', ' File "/usr/lib/python2.7/site-packages/cinder/volume/manager.py", line 713, in copy_volume_to_image\n image_meta)\n', ' File "/usr/lib/python2.7/site-packages/cinder/volume/drivers/rbd.py", line 808, in copy_volume_to_image\n image_meta, tmp_file)\n', ' File "/usr/lib/python2.7/site-packages/cinder/image/image_utils.py", line 238, in upload_volume\n image_service.update(context, image_id, {}, image_file)\n', ' File "/usr/lib/python2.7/site-packages/cinder/image/glance.py", line 311, in update\n _reraise_translated_image_exception(image_id)\n', ' File "/usr/lib/python2.7/site-packages/cinder/image/glance.py", line 306, in update\n image_meta[\'data\'])\n', ' File "/usr/lib/python2.7/site-packages/cinder/image/glance.py", line 158, in call\n return getattr(client.images, method)(*args, **kwargs)\n', ' File "/usr/lib/python2.7/site-packages/glanceclient/v2/images.py", line 110, in upload\n body=image_data)\n', ' File "/usr/lib/python2.7/site-packages/glanceclient/common/http.py", line 289, in raw_request\n return self._http_request(url, method, **kwargs)\n', ' File "/usr/lib/python2.7/site-packages/glanceclient/common/http.py", line 249, in _http_request\n raise exc.from_response(resp, body_str)\n', 'HTTPException: 410 Gone\nImage 6931741c-53c2-43f5-9983-a8bbcf04bc40 could not be found after upload.The image may have been deleted during the upload: No image found with ID 6931741c-53c2-43f5-9983-a8bbcf04bc40 Cleaning up the chunks uploaded\n (HTTP N/A)\n'] 2014-07-15 10:20:19.366 18558 DEBUG cinder.openstack.common.periodic_task [-] Running periodic task VolumeManager._publish_service_capabilities run_periodic_tasks /usr/lib/python2.7/site-packages/cinder/openstack/common/periodic_task.py:178 Version-Release number of selected component (if applicable): How reproducible: Configure ceph as backend , glance and cinder . Run tempest : the python-client code that fails : def test_volume_upload(self): # NOTE(gfidente): the volume uploaded in Glance comes from setUpClass, # it is shared with the other tests. After it is uploaded in Glance, # there is no way to delete it from Cinder, so we delete it from Glance # using the Glance image_client and from Cinder via tearDownClass. image_name = data_utils.rand_name('Image-') resp, body = self.client.upload_volume(self.volume['id'], image_name, CONF.volume.disk_format) image_id = body["image_id"] self.addCleanup(self.image_client.delete_image, image_id) self.assertEqual(202, resp.status) self.image_client.wait_for_image_status(image_id, 'active') self.client.wait_for_volume_status(self.volume['id'], 'available') Steps to Reproduce: 1. 2. 3. Actual results: Expected results: Additional info:
I think this is a failure on the Glance side... I'm not sure from the log what the exact reason is but it looks like a failure to write data to the rbd backend. It looks like there may be a bug in error handling for this case, though. 2014-07-15 10:19:48.814 18627 DEBUG glance.store.rbd [15ecac81-da92-45cd-abb8-76cff563aeed 8e185a6055d945c98098e7151137b52d 8d44d3c0b1114621b30653cb49063d99 - - -] resizing image to 2097152 KiB add /usr/lib/python2.7/site-packages/glance/store/rbd.py:354 2014-07-15 10:19:49.193 18627 DEBUG glance.store.rbd [15ecac81-da92-45cd-abb8-76cff563aeed 8e185a6055d945c98098e7151137b52d 8d44d3c0b1114621b30653cb49063d99 - - -] writing chunk at offset 2139095040 add /usr/lib/python2.7/site-packages/glance/store/rbd.py:357 2014-07-15 10:19:51.954 18627 DEBUG glance.db.sqlalchemy.api [15ecac81-da92-45cd-abb8-76cff563aeed 8e185a6055d945c98098e7151137b52d 8d44d3c0b1114621b30653cb49063d99 - - -] No image found with ID 6931741c-53c2-43f5-9983-a8bbcf04bc40 _image_get /usr/lib/python2.7/site-packages/glance/db/sqlalchemy/api.py:182 2014-07-15 10:19:51.955 18627 WARNING glance.api.v2.image_data [15ecac81-da92-45cd-abb8-76cff563aeed 8e185a6055d945c98098e7151137b52d 8d44d3c0b1114621b30653cb49063d99 - - -] Image 6931741c-53c2-43f5-9983-a8bbcf04bc40 could not be found after upload.The image may have been deleted during the upload: No image found with ID 6931741c-53c2-43f5-9983-a8bbcf04bc40 Cleaning up the chunks uploaded 2014-07-15 10:20:00.082 18627 ERROR glance.api.v2.image_data [15ecac81-da92-45cd-abb8-76cff563aeed 8e185a6055d945c98098e7151137b52d 8d44d3c0b1114621b30653cb49063d99 - - -] Failed to upload image data due to HTTP error A delete happens somewhere before the _restore() is called which results in: InvalidImageStatusTransition: Image status transition from deleted to queued is not allowed
This is not a Glance issue. TBH, it sounds more like a tempest race condition. I think the scenario causing this issue is: 1. Image created 2. Volume upload called 3. Test ends before the volume upload completes and deletes the image. Here's a chunk of log that supports the above scenario: 2014-07-15 10:18:52.877 18626 DEBUG routes.middleware [afd7910a-653a-49ff-b382-323e21b0b74b 8e185a6055d945c98098e7151137b52d 8d44d3c0b1114621b30653cb49063d99 - - -] Matched DELETE /images/6931741c-53c2-43f5-9983-a8bbcf04bc40 __call__ /usr/lib/python2.7/site-packages/routes/middleware.py:100 2014-07-15 10:18:52.878 18626 DEBUG routes.middleware [afd7910a-653a-49ff-b382-323e21b0b74b 8e185a6055d945c98098e7151137b52d 8d44d3c0b1114621b30653cb49063d99 - - -] Route path: '/images/{id}', defaults: {'action': u'delete', 'controller': <glance.common.wsgi.Resource object at 0x2754710>} __call__ /usr/lib/python2.7/site-packages/routes/middleware.py:102 2014-07-15 10:18:52.878 18626 DEBUG routes.middleware [afd7910a-653a-49ff-b382-323e21b0b74b 8e185a6055d945c98098e7151137b52d 8d44d3c0b1114621b30653cb49063d99 - - -] Match dict: {'action': u'delete', 'controller': <glance.common.wsgi.Resource object at 0x2754710>, 'id': u'6931741c-53c2-43f5-9983-a8bbcf04bc40'} __call__ /usr/lib/python2.7/site-packages/routes/middleware.py:103 2014-07-15 10:18:52.878 18626 DEBUG glance.common.client [afd7910a-653a-49ff-b382-323e21b0b74b 8e185a6055d945c98098e7151137b52d 8d44d3c0b1114621b30653cb49063d99 - - -] Constructed URL: http://0.0.0.0:9191/images/6931741c-53c2-43f5-9983-a8bbcf04bc40 _construct_url /usr/lib/python2.7/site-packages/glance/common/client.py:411 2014-07-15 10:18:52.896 18626 DEBUG glance.registry.client.v1.client [afd7910a-653a-49ff-b382-323e21b0b74b 8e185a6055d945c98098e7151137b52d 8d44d3c0b1114621b30653cb49063d99 - - -] Registry request GET /images/6931741c-53c2-43f5-9983-a8bbcf04bc40 HTTP 200 request id req-db87266e-0eee-4dfe-a07b-66032d1b9de5 do_request /usr/lib/python2.7/site-packages/glance/registry/client/v1/client.py:114 2014-07-15 10:18:52.896 18626 DEBUG glance.registry.client.v1.api [afd7910a-653a-49ff-b382-323e21b0b74b 8e185a6055d945c98098e7151137b52d 8d44d3c0b1114621b30653cb49063d99 - - -] Updating image metadata for image 6931741c-53c2-43f5-9983-a8bbcf04bc40... update_image_metadata /usr/lib/python2.7/site-packages/glance/registry/client/v1/api.py:166 2014-07-15 10:18:52.897 18626 DEBUG glance.common.client [afd7910a-653a-49ff-b382-323e21b0b74b 8e185a6055d945c98098e7151137b52d 8d44d3c0b1114621b30653cb49063d99 - - -] Constructed URL: http://0.0.0.0:9191/images/6931741c-53c2-43f5-9983-a8bbcf04bc40 _construct_url /usr/lib/python2.7/site-packages/glance/common/client.py:411 2014-07-15 10:18:52.925 18626 DEBUG glance.registry.client.v1.client [afd7910a-653a-49ff-b382-323e21b0b74b 8e185a6055d945c98098e7151137b52d 8d44d3c0b1114621b30653cb49063d99 - - -] Registry request PUT /images/6931741c-53c2-43f5-9983-a8bbcf04bc40 HTTP 200 request id req-2f1bded0-0d62-4b3a-916c-936a41647c39 do_request /usr/lib/python2.7/site-packages/glance/registry/client/v1/client.py:114 2014-07-15 10:18:52.925 18626 DEBUG glance.registry.client.v1.api [afd7910a-653a-49ff-b382-323e21b0b74b 8e185a6055d945c98098e7151137b52d 8d44d3c0b1114621b30653cb49063d99 - - -] Deleting image metadata for image 6931741c-53c2-43f5-9983-a8bbcf04bc40... delete_image_metadata /usr/lib/python2.7/site-packages/glance/registry/client/v1/api.py:173 2014-07-15 10:18:52.926 18626 DEBUG glance.common.client [afd7910a-653a-49ff-b382-323e21b0b74b 8e185a6055d945c98098e7151137b52d 8d44d3c0b1114621b30653cb49063d99 - - -] Constructed URL: http://0.0.0.0:9191/images/6931741c-53c2-43f5-9983-a8bbcf04bc40 _construct_url /usr/lib/python2.7/site-packages/glance/common/client.py:411 2014-07-15 10:18:52.945 18626 DEBUG glance.registry.client.v1.client [afd7910a-653a-49ff-b382-323e21b0b74b 8e185a6055d945c98098e7151137b52d 8d44d3c0b1114621b30653cb49063d99 - - -] Registry request DELETE /images/6931741c-53c2-43f5-9983-a8bbcf04bc40 HTTP 200 request id req-59e72df9-c6be-40bd-996d-7c6a1d25faf4 do_request /usr/lib/python2.7/site-packages/glance/registry/client/v1/client.py:114 2014-07-15 10:18:52.946 18626 INFO glance.wsgi.server [afd7910a-653a-49ff-b382-323e21b0b74b 8e185a6055d945c98098e7151137b52d 8d44d3c0b1114621b30653cb49063d99 - - -] 192.168.2.20 - - [15/Jul/2014 10:18:52] "DELETE /v1/images/6931741c-53c2-43f5-9983-a8bbcf04bc40 HTTP/1.1" 200 200 0.072712 2014-07-15 10:18:53.365 18627 DEBUG glance.store.rbd [15ecac81-da92-45cd-abb8-76cff563aeed 8e185a6055d945c98098e7151137b52d 8d44d3c0b1114621b30653cb49063d99 - - -] resizing image to 1851392 KiB add /usr/lib/python2.7/site-packages/glance/store/rbd.py:354 2014-07-15 10:18:53.444 18627 DEBUG glance.store.rbd [15ecac81-da92-45cd-abb8-76cff563aeed 8e185a6055d945c98098e7151137b52d 8d44d3c0b1114621b30653cb49063d99 - - -] writing chunk at offset 1887436800 add /usr/lib/python2.7/site-packages/glance/store/rbd.py:357 2014-07-15 10:18:54.410 18627 DEBUG glance.store.rbd [15ecac81-da92-45cd-abb8-76cff563aeed 8e185a6055d945c98098e7151137b52d 8d44d3c0b1114621b30653cb49063d99 - - -] resizing image to 1859584 KiB add /usr/lib/python2.7/site-packages/glance/store/rbd.py:354 2014-07-15 10:18:55.298 18627 DEBUG glance.store.rbd [15ecac81-da92-45cd-abb8-76cff563aeed 8e185a6055d945c98098e7151137b52d 8d44d3c0b1114621b30653cb49063d99 - - -] writing chunk at offset 1895825408 add /usr/lib/python2.7/site-packages/glance/store/rbd.py:357 2014-07-15 10:18:56.274 18627 DEBUG glance.store.rbd [15ecac81-da92-45cd-abb8-76cff563aeed 8e185a6055d945c98098e7151137b52d 8d44d3c0b1114621b30653cb49063d99 - - -] resizing image to 1867776 KiB add /usr/lib/python2.7/site-packages/glance/store/rbd.py:354 Please, open the bug upstream on tempest to have tempest folks digging into this.