[ostf] timeout during creating instance

[Andrey Lavrentyev]

Detailed bug description:
Several OSTF failures are related to inability to create an instance during some time frame.

AssertionError: Failed 5 OSTF tests; should fail 0 tests. Names of failed tests:
  - Create volume and boot instance from it (failure) Time limit exceeded while waiting for instance becoming 'ACTIVE' to finish. Please refer to OpenStack logs for more details.
  - Create volume and attach it to instance (failure) Time limit exceeded while waiting for instance becoming 'ACTIVE' to finish. Please refer to OpenStack logs for more details.
  - Instance live migration (failure) Time limit exceeded while waiting for image creation to finish. Please refer to OpenStack logs for more details.
  - Check network connectivity from instance via floating IP (failure) Time limit exceeded while waiting for server creation to finish. Please refer to OpenStack logs for more details.
  - Launch instance, create snapshot, launch instance from snapshot (failure) Time limit exceeded while waiting for image booting to finish. Please refer to OpenStack logs for more details.

Auto acceptance failure: https://product-ci.infra.mirantis.net/job/9.x.acceptance.ubuntu.ha_vlan_group_2/3/testReport/%28root%29/cinder_ceph_for_ephemeral/

Steps to reproduce:
Execute 'cinder_ceph_for_ephemeral' test with:
1. Create new environment
2. Choose Neutron, VLAN
3. Choose cinder for volumes and Ceph for ephemeral
4. Add 3 controller
5. Add 2 compute
6. Add 1 cinder
7. Add 3 ceph
8. Verify networks
9. Deploy the environment
10. Verify networks
11. Run OSTF tests

Expected results:
OSTF tests pass

Actual result:
5 OSTF tests failed

Description of the environment:
9.1 snapshot #93
[root@nailgun log]# shotgun2 short-report
cat /etc/fuel_build_id:
 495
cat /etc/fuel_build_number:
 495
cat /etc/fuel_release:
 9.0
cat /etc/fuel_openstack_version:
 mitaka-9.0
rpm -qa | egrep 'fuel|astute|network-checker|nailgun|packetary|shotgun':
 python-packetary-9.0.0-1.mos142.noarch
 fuel-migrate-9.0.0-1.mos8496.noarch
 fuel-release-9.0.0-1.mos6349.noarch
 fuel-bootstrap-cli-9.0.0-1.mos285.noarch
 fuel-openstack-metadata-9.0.0-1.mos8748.noarch
 fuel-ostf-9.0.0-1.mos938.noarch
 nailgun-mcagents-9.0.0-1.mos753.noarch
 shotgun-9.0.0-1.mos90.noarch
 python-fuelclient-9.0.0-1.mos325.noarch
 fuel-9.0.0-1.mos6349.noarch
 fuel-library9.0-9.0.0-1.mos8496.noarch
 fuel-provisioning-scripts-9.0.0-1.mos8748.noarch
 rubygem-astute-9.0.0-1.mos753.noarch
 fuel-setup-9.0.0-1.mos6349.noarch
 network-checker-9.0.0-1.mos74.x86_64
 fuel-agent-9.0.0-1.mos285.noarch
 fuel-misc-9.0.0-1.mos8496.noarch
 fuelmenu-9.0.0-1.mos275.noarch
 fuel-notify-9.0.0-1.mos8496.noarch
 fuel-nailgun-9.0.0-1.mos8748.noarch
 fuel-ui-9.0.0-1.mos2718.noarch
 fuel-mirror-9.0.0-1.mos142.noarch
 fuel-utils-9.0.0-1.mos8496.noarch

MOS_CENTOS_OS_MIRROR_ID: os-2016-06-23-135731
MOS_CENTOS_PROPOSED_MIRROR_ID: proposed-2016-08-04-102320
MOS_CENTOS_UPDATES_MIRROR_ID: updates-2016-06-23-135916
MOS_CENTOS_SECURITY_MIRROR_ID: security-2016-06-23-140002
MOS_CENTOS_HOLDBACK_MIRROR_ID: holdback-2016-06-23-140047
MOS_UBUNTU_MIRROR_ID: 9.0-2016-08-04-084321
UBUNTU_MIRROR_ID: ubuntu-2016-08-03-174238
CENTOS_MIRROR_ID: centos-7.2.1511-2016-05-31-083834

Logs: https://drive.google.com/open?id=0B5HPBFb7K7gXQWwycXlMUFl5WXM

[Oleksiy Molchanov (omolchanov)]

This seems to be related to slow environment,

Nothing fails but proceed very slow:

<183>Aug 5 07:54:04 node-2 nova-api: 2016-08-05 07:54:04.655 4664 DEBUG glanceclient.common.http [req-72b7e937-ff62-4488-ab77-c5c608d92c5f eee68ff7b01a4ca8a4f1c729e5f977ff 2995047a759340478152195ff3111ea8
 - - -]
HTTP/1.1 200 OK
Content-Length: 0
X-Image-Meta-Id: 55c24c41-fe71-4269-9e21-afcfc1888ea1
X-Image-Meta-Deleted: False
X-Image-Meta-Checksum: 88d6c77b58fd40a7cb7f44b62bd5ad98
X-Image-Meta-Status: active
X-Image-Meta-Container_format: bare
X-Image-Meta-Protected: False
X-Image-Meta-Min_disk: 0
X-Image-Meta-Min_ram: 64
X-Image-Meta-Created_at: 2016-08-05T07:49:52.000000
X-Image-Meta-Size: 22581248
Connection: close
Etag: 88d6c77b58fd40a7cb7f44b62bd5ad98
X-Image-Meta-Is_public: True
Date: Fri, 05 Aug 2016 07:54:04 GMT
X-Image-Meta-Owner: db8233dfe80c40a982f6696a750ae029
X-Image-Meta-Updated_at: 2016-08-05T07:49:55.000000
Content-Type: text/html; charset=UTF-8
X-Openstack-Request-Id: req-a751ba85-6791-452e-b56f-f863824913e2
X-Image-Meta-Disk_format: qcow2
X-Image-Meta-Name: TestVM

http://10.109.16.12:9292/v1/images/detail?is_public=none&limit=20 log_curl_request /usr/lib/python2.7/dist-packages/glanceclient/common/http.py:198
<183>Aug 5 07:57:31 node-2 nova-api: 2016-08-05 07:57:31.476 4664 DEBUG glanceclient.common.http [req-6666b820-f963-44bd-9c0b-b0bb61bb8791 eee68ff7b01a4ca8a4f1c729e5f977ff 2995047a759340478152195ff3111ea8 - - -]
HTTP/1.1 200 OK
Date: Fri, 05 Aug 2016 07:57:31 GMT
Connection: close
Content-Type: application/json; charset=UTF-8
Content-Length: 496
X-Openstack-Request-Id: req-185be578-d9dc-4ff4-a622-809cc2a85a37

{"images": [{"status": "active", "deleted_at": null, "name": "TestVM", "deleted": false, "container_format": "bare", "created_at": "2016-08-05T07:49:52.000000", "disk_format": "qcow2", "updated_at": "2016-08-05T07:49:55.000000", "min_disk": 0, "protected": false, "id": "55c24c41-fe71-4269-9e21-afcfc1888ea1", "min_ram": 64, "checksum": "88d6c77b58fd40a7cb7f44b62bd5ad98", "owner": "db8233dfe80c40a982f6696a750ae029", "is_public": true, "virtual_size": null, "properties": {}, "size": 22581248}]}

[Andrey Lavrentyev (alavrentyev)]

@Oleksiy, wouldn't it mean a performance issue?

[Dmitry Belyaninov (dbelyaninov)]

https://product-ci.infra.mirantis.net/job/9.x.system_test.ubuntu.ceph_ha_one_controller/82/testReport/(root)/ceph_ha_one_controller_compact/ceph_ha_one_controller_compact/

[Tatyanka (tatyana-leontovich)]

Folks in logs on nova compute there is the problem as described here https://bugs.launchpad.net/fuel/+bug/1511854

2016-08-05T08:08:32.777702+00:00 debug: 2016-08-05 08:08:32.774 30597 DEBUG nova.block_device [req-f311fdd5-0f5b-449d-bc8a-44889c13a241 eee68ff7b01a4ca8a4f1c729e5f977ff 2995047a759340478152195ff3111ea8 - - -] block_device_list [] volume_in_mapping /usr/lib/python2.7/dist-packages/nova/block_device.py:583
2016-08-05T08:08:32.779451+00:00 info: 2016-08-05 08:08:32.776 30597 INFO nova.virt.libvirt.driver [req-f311fdd5-0f5b-449d-bc8a-44889c13a241 eee68ff7b01a4ca8a4f1c729e5f977ff 2995047a759340478152195ff3111ea8 - - -] [instance: 51d839d6-2f08-4be5-8f92-4ed700a5925a] Creating image
2016-08-05T08:08:32.836945+00:00 debug: 2016-08-05 08:08:32.834340 7f702275e740 -1 librbd::ImageCtx: error finding header: (2) No such file or directory
2016-08-05T08:08:32.839077+00:00 debug: 2016-08-05 08:08:32.834 30597 DEBUG nova.virt.libvirt.storage.rbd_utils [req-f311fdd5-0f5b-449d-bc8a-44889c13a241 eee68ff7b01a4ca8a4f1c729e5f977ff 2995047a759340478152195ff3111ea8 - - -] rbd image 51d839d6-2f08-4be5-8f92-4ed700a5925a_disk does not exist __init__ /usr/lib/python2.7/dist-packages/nova/virt/libvirt/storage/rbd_utils.py:64
2016-08-05T08:08:32.873665+00:00 debug: 2016-08-05 08:08:32.871068 7f702275e740 -1 librbd::ImageCtx: error finding header: (2) No such file or directory
2016-08-05T08:08:32.875548+00:00 debug: 2016-08-05 08:08:32.871 30597 DEBUG nova.virt.libvirt.storage.rbd_utils [req-f311fdd5-0f5b-449d-bc8a-44889c13a241 eee68ff7b01a4ca8a4f1c729e5f977ff 2995047a759340478152195ff3111ea8 - - -] rbd image 51d839d6-2f08-4be5-8f92-4ed700a5925a_disk does not exist __init__ /usr/lib/python2.7/dist-packages/nova/virt/libvirt/storage/rbd_utils.py:64
2016-08-05T08:08:32.880084+00:00 debug: 2016-08-05 08:08:32.877 30597 DEBUG oslo_concurrency.lockutils [req-f311fdd5-0f5b-449d-bc8a-44889c13a241 eee68ff7b01a4ca8a4f1c729e5f977ff 2995047a759340478152195ff3111ea8 - - -] Lock "2f3659645f3065fb53bc9705c86e435cc1ef19b5" acquired by "nova.virt.libvirt.imagebackend.fetch_func_sync" :: waited 0.000s inner /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:270
2016-08-05T08:08:32.885725+00:00 debug: 2016-08-05 08:08:32.882 30597 DEBUG glanceclient.common.http [req-f311fdd5-0f5b-449d-bc8a-44889c13a241 eee68ff7b01a4ca8a4f1c729e5f977ff 2995047a759340478152195ff3111ea8 - - -] curl -g -i -X GET -H 'X-Auth-Token: {SHA1}d54e0f288cee8988de613bb9ea73c5ef4fd19fc9' -H 'Accept-Encoding: gzip, deflate' -H 'X-Tenant-Id: 2995047a759340478152195ff3111ea8' -H 'Accept: */*' -H 'X-Roles: admin' -H 'User-Agent: python-glanceclient' -H 'Connection: keep-alive' -H 'X-User-Id: eee68ff7b01a4ca8a4f1c729e5f977ff' -H 'X-Identity-Status: Confirmed' -H 'Content-Type: application/octet-stream' http://10.109.16.12:9292/v2/images/55c24c41-fe71-4269-9e21-afcfc1888ea1 log_curl_request /usr/lib/python2.7/dist-packages/glanceclient/common/http.py:198

Thats why we have hanging build state for most on instance/volume/snapshots related tests. Re-assign this bug

[Tatyanka (tatyana-leontovich)]

 -1 librbd::ImageCtx: error finding header: (2) No such file or directory

[Tatyanka (tatyana-leontovich)]

and a lot of issue from oslomessaging set_transport_socket_timeout /usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/impl_rabbit.py:868
2016-08-05T07:50:48.290952+00:00 info: 2016-08-05 07:50:48.288 30597 INFO oslo.messaging._drivers.impl_rabbit [-] Reconnected to AMQP server on 10.109.16.7:5673 via [amqp] client
2016-08-05T07:50:48.359913+00:00 info: 2016-08-05 07:50:48.358 30597 INFO oslo.messaging._drivers.impl_rabbit [-] Reconnected to AMQP server on 10.109.16.7:5673 via [amqp] client
2016-08-05T07:51:47.603910+00:00 err: 2016-08-05 07:51:47.599 30597 ERROR oslo_service.periodic_task [req-c8337199-7f6d-4202-bc32-65299b9ef98b - - - - -] Error during ComputeManager._instance_usage_audit
2016-08-05 07:51:47.599 30597 ERROR oslo_service.periodic_task Traceback (most recent call last):
2016-08-05 07:51:47.599 30597 ERROR oslo_service.periodic_task File "/usr/lib/python2.7/dist-packages/oslo_service/periodic_task.py", line 220, in run_periodic_tasks
2016-08-05 07:51:47.599 30597 ERROR oslo_service.periodic_task task(self, context)
2016-08-05 07:51:47.599 30597 ERROR oslo_service.periodic_task File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 5982, in _instance_usage_audit
2016-08-05 07:51:47.599 30597 ERROR oslo_service.periodic_task self.host):
2016-08-05 07:51:47.599 30597 ERROR oslo_service.periodic_task File "/usr/lib/python2.7/dist-packages/nova/objects/base.py", line 377, in wrapper
2016-08-05 07:51:47.599 30597 ERROR oslo_service.periodic_task return fn.__get__(None, obj)(*args, **kwargs)
2016-08-05 07:51:47.599 30597 ERROR oslo_service.periodic_task File "/usr/lib/python2.7/dist-packages/oslo_versionedobjects/base.py", line 174, in wrapper
2016-08-05 07:51:47.599 30597 ERROR oslo_service.periodic_task args, kwargs)
2016-08-05 07:51:47.599 30597 ERROR oslo_service.periodic_task File "/usr/lib/python2.7/dist-packages/nova/conductor/rpcapi.py", line 240, in object_class_action_versions
2016-08-05 07:51:47.599 30597 ERROR oslo_service.periodic_task args=args, kwargs=kwargs)
2016-08-05 07:51:47.599 30597 ERROR oslo_service.periodic_task File "/usr/lib/python2.7/dist-packages/oslo_messaging/rpc/client.py", line 158, in call
2016-08-05 07:51:47.599 30597 ERROR oslo_service.periodic_task retry=self.retry)
2016-08-05 07:51:47.599 30597 ERROR oslo_service.periodic_task File "/usr/lib/python2.7/dist-packages/oslo_messaging/transport.py", line 91, in _send
2016-08-05 07:51:47.599 30597 ERROR oslo_service.periodic_task timeout=timeout, ret
2016-08-05T07:51:47.604739+00:00 debug: 2016-08-05 07:51:47.601 30597 DEBUG oslo_service.periodic_task [req-c833719

[Tatyanka (tatyana-leontovich)]

so move to dev team

[Dmitry Mescheryakov (dmitrymex)]

Tatyana, thanks for spotting this. I have filed a corresponding issue in upstream - https://bugs.launchpad.net/oslo.messaging/+bug/1640773 and currently work on it.

[Dmitry Mescheryakov (dmitrymex)]

The issue is fixed by the latest merge of stable/mitaka https://review.fuel-infra.org/#/c/28682
Since the issue is fixed in upstream Neuton, the fix will be in 10.0 as well.

Specifically, these commits fix the issue in all relevant branches: https://review.openstack.org/#/q/Ifebdd957d403e47039c10f7e55c4e7ef08fba658,n,z

[TatyanaGladysheva (tgladysheva)]

Verified on 9.2 snapshot #556.

Steps to verify:
Launch fuel-qa test 'cinder_ceph_for_ephemeral' manually.

Actual results:
Deploy is finished successfully. All OSTF tests are passed.