Backup operations fails causing tempest failures

[Slawek Kaplonski]

I found that quite often some tests are failing because of error with volume and/or backup deletion or restore.

Logstash query which I used to find such cases: http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22Invalid%20backup%3A%20Backup%20status%20must%20be%20available%20or%20error%5C%22

Example of such error: http://logs.openstack.org/24/648924/2/gate/tempest-full/9d25d14/testr_results.html.gz

Stacktrace from failed test:
2019-04-02 21:00:47.940342 | controller | ==============================
2019-04-02 21:00:47.940416 | controller | Failed 1 tests - output below:
2019-04-02 21:00:47.940469 | controller | ==============================
2019-04-02 21:00:47.940487 | controller |
2019-04-02 21:00:47.940638 | controller | tempest.api.volume.admin.test_volumes_backup.VolumesBackupsAdminTest.test_volume_backup_export_import[id-a99c54a1-dd80-4724-8a13-13bf58d4068d]
2019-04-02 21:00:47.940758 | controller | ----------------------------------------------------------------------------------------------------------------------------------------------
2019-04-02 21:00:47.940771 | controller |
2019-04-02 21:00:47.940798 | controller | Captured traceback-1:
2019-04-02 21:00:47.940835 | controller | ~~~~~~~~~~~~~~~~~~~~~
2019-04-02 21:00:47.940882 | controller | Traceback (most recent call last):
2019-04-02 21:00:47.940981 | controller | File "tempest/lib/services/volume/v3/volumes_client.py", line 102, in delete_volume
2019-04-02 21:00:47.941042 | controller | resp, body = self.delete(url)
2019-04-02 21:00:47.941103 | controller | File "tempest/lib/common/rest_client.py", line 314, in delete
2019-04-02 21:00:47.941166 | controller | return self.request('DELETE', url, extra_headers, headers, body)
2019-04-02 21:00:47.941235 | controller | File "tempest/lib/services/volume/base_client.py", line 38, in request
2019-04-02 21:00:47.941306 | controller | method, url, extra_headers, headers, body, chunked)
2019-04-02 21:00:47.941371 | controller | File "tempest/lib/common/rest_client.py", line 679, in request
2019-04-02 21:00:47.941414 | controller | self._error_checker(resp, resp_body)
2019-04-02 21:00:47.941479 | controller | File "tempest/lib/common/rest_client.py", line 790, in _error_checker
2019-04-02 21:00:47.941539 | controller | raise exceptions.BadRequest(resp_body, resp=resp)
2019-04-02 21:00:47.941590 | controller | tempest.lib.exceptions.BadRequest: Bad request
2019-04-02 21:00:47.941819 | controller | Details: {u'message': u'Invalid volume: Volume status must be available or error or error_restoring or error_extending or error_managing and must not be migrating, attached, belong to a group, have snapshots or be disassociated from snapshots after volume transfer.', u'code': 400}
2019-04-02 21:00:47.941844 | controller |
2019-04-02 21:00:47.941858 | controller |
2019-04-02 21:00:47.941885 | controller | Captured traceback-2:
2019-04-02 21:00:47.941920 | controller | ~~~~~~~~~~~~~~~~~~~~~
2019-04-02 21:00:47.941986 | controller | Traceback (most recent call last):
2019-04-02 21:00:47.942108 | controller | File "tempest/lib/services/volume/v3/backups_client.py", line 68, in delete_backup
2019-04-02 21:00:47.942186 | controller | resp, body = self.delete('backups/%s' % backup_id)
2019-04-02 21:00:47.942248 | controller | File "tempest/lib/common/rest_client.py", line 314, in delete
2019-04-02 21:00:47.942339 | controller | return self.request('DELETE', url, extra_headers, headers, body)
2019-04-02 21:00:47.942414 | controller | File "tempest/lib/services/volume/base_client.py", line 38, in request
2019-04-02 21:00:47.942468 | controller | method, url, extra_headers, headers, body, chunked)
2019-04-02 21:00:47.942540 | controller | File "tempest/lib/common/rest_client.py", line 679, in request
2019-04-02 21:00:47.942590 | controller | self._error_checker(resp, resp_body)
2019-04-02 21:00:47.942655 | controller | File "tempest/lib/common/rest_client.py", line 790, in _error_checker
2019-04-02 21:00:47.942725 | controller | raise exceptions.BadRequest(resp_body, resp=resp)
2019-04-02 21:00:47.942818 | controller | tempest.lib.exceptions.BadRequest: Bad request
2019-04-02 21:00:47.942909 | controller | Details: {u'message': u'Invalid backup: Backup status must be available or error', u'code': 400}
2019-04-02 21:00:47.942947 | controller |
2019-04-02 21:00:47.942962 | controller |
2019-04-02 21:00:47.942988 | controller | Captured traceback:
2019-04-02 21:00:47.943014 | controller | ~~~~~~~~~~~~~~~~~~~
2019-04-02 21:00:47.943053 | controller | Traceback (most recent call last):
2019-04-02 21:00:47.943140 | controller | File "tempest/api/volume/admin/test_volumes_backup.py", line 115, in test_volume_backup_export_import
2019-04-02 21:00:47.943192 | controller | self.backups_client, backup['id'], 'available')
2019-04-02 21:00:47.943263 | controller | File "tempest/common/waiters.py", line 211, in wait_for_volume_resource_status
2019-04-02 21:00:47.943331 | controller | raise lib_exc.TimeoutException(message)
2019-04-02 21:00:47.943395 | controller | tempest.lib.exceptions.TimeoutException: Request timed out
2019-04-02 21:00:47.943518 | controller | Details: backup e69b23b9-5b83-4f94-8e84-70c2493f6923 failed to reach available status (current restoring) within the required time (196 s).