Tempest test test_schedule_to_all_nodes is failed

Are you sure that you attached the right snapshot? because I can't find even the uuid of the failed server there.

Sergey, I'm shure.

I can't reproduce it manually. Also I'm still thinking that snapshot was created from some other env because:

1. according to snapshot logs 'test_schedule_to_all_nodes' passed:

$ grep -irn "test_schedule_to_all_nodes"
nailgun.test.domain.local/root/log.log:1888:{1} tempest.scenario.test_server_multinode.TestServerMultinode.test_schedule_to_all_nodes [64.947272s] ... ok
node-5/root/log.log:1888:{1} tempest.scenario.test_server_multinode.TestServerMultinode.test_schedule_to_all_nodes [64.947272s] ... ok

2. I can't find the error message or server uuid in logs:

nik@snikitin: fuel-snapshot-2016-07-26_09-04-51$ grep -irn "OVS configuration failed"
nik@snikitin: fuel-snapshot-2016-07-26_09-04-51$

nik@snikitin: fuel-snapshot-2016-07-26_09-04-51$ grep -irn "ada719f3-b9a7-43e3-9c13-d61e3edc60e5"
nik@snikitin:fuel-snapshot-2016-07-26_09-04-51$

3. according logs from snaphot env have the following nodes:

'slave-01_controller_mongo'
'slave-02_controller_mongo'
'slave-03_controller_mongo'
'slave-04_compute_cinder'
'slave-05_compute_cinder'
'slave-06_ironic'

In the bug description mentioned only 4 nodes: "controller, compute, ironic,cinder, Telemetry - MongoDB"

Or the description is incorrect?

So I mark bug as incomplete till it will be reproduced on CI again or the correct snapshot will be attached.

Can't reproduce manual. Reproduce only on CI
snapshot: https://drive.google.com/a/mirantis.com/file/d/0BxPLDs6wcpbDMW1mb1VtTE1VYUk/view?usp=sharing

node-2/var/log/nova/nova-compute.log
Nova tries to create port by command:

sudo nova-rootwrap /etc/nova/rootwrap.conf ovs-vsctl --timeout=120 -- --if-exists del-port qvo8e5a0737-a6 -- add-port br-int qvo8e5a0737-a6 -- set Interface qvo8e5a0737-a6 external-ids:iface-id=8e5a0737-a6d3-4d70-83c5-af9fb69e420d external-ids:iface-status=active external-ids:attached-mac=fa:16:3e:19:4e:93 external-ids:vm-uuid=2bed27c1-70b6-4db7-b03a-fbcf34d51215

but OVS command failed by timeout after 2 minutes:
nailgun.test.domain.local/var/log/remote/node-2.test.domain.local/ovs-vsctl.log

2016-08-01T08:32:55.158210+00:00 notice: ovs|00001|vsctl|INFO|Called as /usr/bin/ovs-vsctl --timeout=120 -- --if-exists del-port qvo28267e0a-5d -- add-port br-int qvo28267e0a-5d -- set Interface qvo28267e0a-5d external-ids:iface-id=28267e0a-5d1c-4795-aa03-461c3f93b319 external-ids:iface-status=active external-ids:attached-mac=fa:16:3e:87:1e:a4 external-ids:vm-uuid=0208dfc4-6a9b-4f55-9650-83d625a9222b

2016-08-01T08:34:55.160326+00:00 warning:
ovs|00002|fatal_signal|WARN|terminating with signal 14 (Alarm clock)

It's NOT a timeout of waiting event from neutron. It's a timeout of execution of ovs-vsctl command.

Looks like some openvswitch issue which is hard to debug without openvswitch logs (no openvswitch/ dir on compute nodes in the snapshot). Need snapshot with openvswitch logs (var/log/openvswitch/) or live repro for further debugging.

What is reproducibility of the bug?

Oleg Bondarev, it is how often this test is failed. if this test fail again I can give you access to environment

Let's keep it 'incomplete' until next failure then

Reassigning this bug to Sofia since we are waiting live env from QA side.

Can't reproduce manual and on CI

Reproduce manual and on CI
9.1 snapshot #294

Traceback (most recent call last):
  File "tempest/test.py", line 107, in wrapper
    return f(self, *func_args, **func_kwargs)
  File "tempest/scenario/test_server_multinode.py", line 71, in test_schedule_to_all_nodes
    wait_until='ACTIVE')
  File "tempest/scenario/manager.py", line 205, in create_server
    image_id=image_id, **kwargs)
  File "tempest/common/compute.py", line 168, in create_test_server
    % server['id'])
  File "/root/.rally/tempest/for-deployment-c63cd82f-4352-4a78-99a3-e52392edb324/.venv/local/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
    self.force_reraise()
  File "/root/.rally/tempest/for-deployment-c63cd82f-4352-4a78-99a3-e52392edb324/.venv/local/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
    six.reraise(self.type_, self.value, self.tb)
  File "tempest/common/compute.py", line 150, in create_test_server
    clients.servers_client, server['id'], wait_until)
  File "tempest/common/waiters.py", line 95, in wait_for_server_status
    raise exceptions.TimeoutException(message)
tempest.exceptions.TimeoutException: Request timed out
Details: (TestServerMultinode:test_schedule_to_all_nodes) Server d394f3e9-c4d7-48ca-bd3c-fc6e52cebc3f failed to reach ACTIVE status and task state "None" within the required time (300 s). Current status: BUILD. Current task state: scheduling.

On the env where the issue was reproduced ^^ I see one compute node in down state. Looking at tempest test code I see that it doesn't check the state of the node when spawning a VM on all nodes - most probably the instance stays in DOWN state because of down compute node.

Confirmed that the test fails due to down compute node

Reproduced on 9.1 snapshot #355
Trace:
Trace:

Traceback (most recent call last):

  File "tempest/test.py", line 107, in wrapper

    return f(self, *func_args, **func_kwargs)

  File "tempest/scenario/test_server_multinode.py", line 70, in test_schedule_to_all_nodes

    wait_until='ACTIVE')

  File "tempest/scenario/manager.py", line 205, in create_server

    image_id=image_id, **kwargs)

  File "tempest/common/compute.py", line 168, in create_test_server

    % server['id'])

  File "/root/.rally/tempest/for-deployment-ef1438d4-5231-4bae-83d1-117caa2049b6/.venv/local/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__

    self.force_reraise()

  File "/root/.rally/tempest/for-deployment-ef1438d4-5231-4bae-83d1-117caa2049b6/.venv/local/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise

    six.reraise(self.type_, self.value, self.tb)

  File "tempest/common/compute.py", line 150, in create_test_server

    clients.servers_client, server['id'], wait_until)

  File "tempest/common/waiters.py", line 75, in wait_for_server_status

    server_id=server_id)

tempest.exceptions.BuildErrorException: Server 4596f713-036c-4d30-ad8d-bc78195fea5e failed to build and is in ERROR status

Details: {u'message': u'OVS configuration failed with: Unexpected error while running command.\nCommand: sudo nova-rootwrap /etc/nova/rootwrap.conf ovs-vsctl --timeout=120 -- --if-exists del-port qvo0bf8be3f-73 -- add-port br-int qvo0bf8be3f-73 -- set Interface qvo0bf8be3f-73 ext', u'code': 500, u'details': u' File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 1926, in _do_build_and_run_instance\n filter_properties)\n File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 2116, in _build_and_run_instance\n instance_uuid=instance.uuid, reason=six.text_type(e))\n', u'created': u'2016-10-07T02:24:12Z'

Snapshot:
https://drive.google.com/a/mirantis.com/file/d/0BxPLDs6wcpbDc2pIWnhPWl9tVUU/view?usp=sharing

General problem with ovs on node-6 (compute) leads to VMs faling to spawn, dvr routers not functioning correctly, overall connectivity problems of all kinds.

root@node-6:~# vi /var/log/openvswitch/ovs-vswitchd.log:

2016-10-07T02:05:30.501Z|00001|ovs_rcu(urcu3)|WARN|blocked 1000 ms waiting for main to quiesce
2016-10-07T02:05:31.501Z|00002|ovs_rcu(urcu3)|WARN|blocked 2000 ms waiting for main to quiesce
2016-10-07T02:05:33.501Z|00003|ovs_rcu(urcu3)|WARN|blocked 4000 ms waiting for main to quiesce
2016-10-07T02:05:37.501Z|00004|ovs_rcu(urcu3)|WARN|blocked 8000 ms waiting for main to quiesce
2016-10-07T02:05:45.501Z|00005|ovs_rcu(urcu3)|WARN|blocked 16000 ms waiting for main to quiesce
2016-10-07T02:06:01.502Z|00006|ovs_rcu(urcu3)|WARN|blocked 32001 ms waiting for main to quiesce
2016-10-07T02:06:33.501Z|00007|ovs_rcu(urcu3)|WARN|blocked 64000 ms waiting for main to quiesce
2016-10-07T02:07:37.501Z|00008|ovs_rcu(urcu3)|WARN|blocked 128000 ms waiting for main to quiesce
2016-10-07T02:09:45.501Z|00009|ovs_rcu(urcu3)|WARN|blocked 256000 ms waiting for main to quiesce
2016-10-07T02:14:01.501Z|00010|ovs_rcu(urcu3)|WARN|blocked 512000 ms waiting for main to quiesce
2016-10-07T02:22:33.501Z|00011|ovs_rcu(urcu3)|WARN|blocked 1024001 ms waiting for main to quiesce
2016-10-07T02:39:37.501Z|00012|ovs_rcu(urcu3)|WARN|blocked 2048000 ms waiting for main to quiesce
2016-10-07T03:13:45.501Z|00013|ovs_rcu(urcu3)|WARN|blocked 4096000 ms waiting for main to quiesce
2016-10-07T04:22:01.501Z|00014|ovs_rcu(urcu3)|WARN|blocked 8192000 ms waiting for main to quiesce
2016-10-07T06:38:33.501Z|00015|ovs_rcu(urcu3)|WARN|blocked 16384000 ms waiting for main to quiesce
2016-10-07T11:11:37.501Z|00016|ovs_rcu(urcu3)|WARN|blocked 32768000 ms waiting for main to quiesce

ovs problem to be investigated

OVS issue can be fixed by restart: service openvswitch-switch restart;
Then need to restart neutron-ovs-agent and things get back to normal.

OVS issue is some kind of a race condition in rare circumstances.
Lower to Medium and moving to 9.2.

9.2 should have OVS 2.5.1, need to check if the issue is still there with new OVS version. Marking as incomplete for now.

Hi Sofia, could you please take a look and update the status for 9.2?

Hi, now this test fail regularly, but with other error.

Trace:

Traceback (most recent call last):

  File "tempest/test.py", line 100, in wrapper

    return f(self, *func_args, **func_kwargs)

  File "tempest/scenario/test_server_multinode.py", line 78, in test_schedule_to_all_nodes

    wait_until='ACTIVE')

  File "tempest/scenario/manager.py", line 206, in create_server

    image_id=image_id, **kwargs)

  File "tempest/common/compute.py", line 167, in create_test_server

    % server['id'])

  File "/root/.rally/tempest/for-deployment-265362ef-e144-4b52-9571-4ea6c994547f/.venv/local/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__

    self.force_reraise()

  File "/root/.rally/tempest/for-deployment-265362ef-e144-4b52-9571-4ea6c994547f/.venv/local/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise

    six.reraise(self.type_, self.value, self.tb)

  File "tempest/common/compute.py", line 149, in create_test_server

    clients.servers_client, server['id'], wait_until)

  File "tempest/common/waiters.py", line 75, in wait_for_server_status

    server_id=server_id)

tempest.exceptions.BuildErrorException: Server a022fa1a-5abf-4906-bb60-66a83fb70097 failed to build and is in ERROR status

Details: {u'message': u'No free port available for instance a022fa1a-5abf-4906-bb60-66a83fb70097.', u'code': 500, u'details': u' File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 1926, in _do_build_and_run_instance\n filter_properties)\n File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 2116, in _build_and_run_instance\n instance_uuid=instance.uuid, reason=six.text_type(e))\n', u'created': u'2016-11-22T01:52:55Z'}

snapshot: https://drive.google.com/a/mirantis.com/file/d/0BxPLDs6wcpbDVmhTQWoxUXFPeEk/view?usp=sharing

Test failed with trace: http://paste.openstack.org/show/590094/

nova-compute log: http://paste.openstack.org/show/590096/

From log, we can see that nova tries to boot instance on ironic node using fake driver.
if disable ironic-compute, test will pass.(nova service-disable <hostname> <binary>): http://paste.openstack.org/show/590097/

Sofiia,

I checked the logs and Nova code and see that this exception is raised when the node an instance is scheduled to does not have MAC addresses available - Ironic is special in this case as we can't simply allocate any port in Neutron - we must use the ports available on this specific node. Which brings me to my question, how do enroll an Ironic node to be provisioned? Are sure you also register ports on this node via "ironic port-create" (http://developer.openstack.org/api-ref/baremetal/?expanded=create-port-detail)?

Roman,

We don't have port for this node, because it is fake node and we can't boot instance on it. This node created only for basic ironic tests.

When I deleted node, error was changed: http://paste.openstack.org/show/590312/

The environment was incorrectly prepared. We should enroll Ironic nodes before trying to spawn instances on baremetal, otherwise tests will fail and it is expected behaviour.

Only one tempest test is affected, Oleksiy is going to check the configuration of the cloud to make sure it is correct.