Fuel for OpenStack

[ostf] timeout during creating instance

Bug #1610209 reported by Andrey Lavrentyev
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Fuel for OpenStack
Fix Committed
Medium
MOS Oslo
Fuel for OpenStack 10.0
Mitaka
Fix Released
Medium
Dmitry Mescheryakov
Fuel for OpenStack 9.2

Bug Description

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

Tags: area-ostf
Ivan Ponomarev (ivanzipfer)
Changed in fuel:
status: New → Confirmed
importance: Undecided → High
assignee: nobody → Fuel Sustaining (fuel-sustaining-team)
milestone: none → 9.1
tags: added: area-library
Dmitry Pyzhov (dpyzhov)
Changed in fuel:
milestone: 9.1 → 10.0
Revision history for this message
Oleksiy Molchanov (omolchanov) wrote :

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}]}

Changed in fuel:
assignee: Fuel Sustaining (fuel-sustaining-team) → Fuel QA Team (fuel-qa)
Oleksiy Molchanov (omolchanov)
tags: added: area-qa
removed: area-library
Revision history for this message
Andrey Lavrentyev (alavrentyev) wrote :

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

Revision history for this message
Dmitry Belyaninov (dbelyaninov) wrote :

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/

Nastya Urlapova (aurlapova)
tags: added: area-ostf
removed: area-qa
Changed in fuel:
importance: High → Medium
Revision history for this message
Tatyanka (tatyana-leontovich) wrote :

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

Revision history for this message
Tatyanka (tatyana-leontovich) wrote :

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

Revision history for this message
Tatyanka (tatyana-leontovich) wrote :

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

Revision history for this message
Tatyanka (tatyana-leontovich) wrote :

so move to dev team

Changed in fuel:
assignee: Fuel QA Team (fuel-qa) → MOS Oslo (mos-oslo)
Revision history for this message
Dmitry Mescheryakov (dmitrymex) wrote :

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.

Revision history for this message
Dmitry Mescheryakov (dmitrymex) wrote :

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

Changed in fuel:
status: Confirmed → Fix Committed
TatyanaGladysheva (tgladysheva)
tags: added: on-verification
Revision history for this message
TatyanaGladysheva (tgladysheva) wrote :

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.

tags: removed: on-verification
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.