ovsdb native interface timeouts sometimes causing random functional failures

[Miguel Angel Ajo]

Functional tests neutron.tests.functional.agent.test_l2_ovs_agent.TestOVSAgent.test_assert_pings_*(native) fail randomly with:

Traceback (most recent call last):
  File "neutron/tests/base.py", line 115, in func
    return f(self, *args, **kwargs)
  File "neutron/tests/functional/agent/test_l2_ovs_agent.py", line 262, in test_assert_pings_during_br_phys_setup_not_lost_in_vlan_to_flat
    self._test_assert_pings_during_br_phys_setup_not_lost(provider_net)
  File "neutron/tests/functional/agent/test_l2_ovs_agent.py", line 299, in _test_assert_pings_during_br_phys_setup_not_lost
    self.agent.setup_physical_bridges(self.agent.bridge_mappings)
  File "/opt/stack/new/neutron/.tox/dsvm-functional/local/lib/python2.7/site-packages/osprofiler/profiler.py", line 154, in wrapper
    return f(*args, **kwargs)
  File "neutron/plugins/ml2/drivers/openvswitch/agent/ovs_neutron_agent.py", line 1080, in setup_physical_bridges
    ovs_bridges = ovs.get_bridges()
  File "neutron/agent/common/ovs_lib.py", line 139, in get_bridges
    return self.ovsdb.list_br().execute(check_error=True)
  File "neutron/agent/ovsdb/native/commands.py", line 43, in execute
    ctx.reraise = False
  File "/opt/stack/new/neutron/.tox/dsvm-functional/local/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
    self.force_reraise()
  File "/opt/stack/new/neutron/.tox/dsvm-functional/local/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
    six.reraise(self.type_, self.value, self.tb)
  File "neutron/agent/ovsdb/native/commands.py", line 36, in execute
    txn.add(self)
  File "neutron/agent/ovsdb/api.py", line 76, in __exit__
    self.result = self.commit()
  File "neutron/agent/ovsdb/impl_idl.py", line 73, in commit
    'timeout': self.timeout})
neutron.agent.ovsdb.api.TimeoutException: Commands [ListBridgesCommand()] exceeded timeout 10 seconds

or

ft39.16: neutron.tests.functional.agent.test_l2_ovs_agent.TestOVSAgent.test_assert_pings_during_br_int_setup_not_lost(native)_StringException: Empty attachments:
  stderr
  stdout

pythonlogging:'': {{{
DEBUG [stevedore.extension] found extension EntryPoint.parse('zmq = oslo_messaging._drivers.impl_zmq:ZmqDriver')
   DEBUG [stevedore.extension] found extension EntryPoint.parse('fake = oslo_messaging._drivers.impl_fake:FakeDriver')
   DEBUG [stevedore.extension] found extension EntryPoint.parse('pika = oslo_messaging._drivers.impl_pika:PikaDriver')
   DEBUG [stevedore.extension] found extension EntryPoint.parse('amqp = oslo_messaging._drivers.impl_amqp1:ProtonDriver')
   DEBUG [stevedore.extension] found extension EntryPoint.parse('kafka = oslo_messaging._drivers.impl_kafka:KafkaDriver')
   DEBUG [stevedore.extension] found extension EntryPoint.parse('kombu = oslo_messaging._drivers.impl_rabbit:RabbitDriver')
   DEBUG [stevedore.extension] found extension EntryPoint.parse('rabbit = oslo_messaging._drivers.impl_rabbit:RabbitDriver')
   DEBUG [stevedore.extension] found extension EntryPoint.parse('zmq = oslo_messaging._drivers.impl_zmq:ZmqDriver')
   DEBUG [stevedore.extension] found extension EntryPoint.parse('fake = oslo_messaging._drivers.impl_fake:FakeDriver')
   DEBUG [stevedore.extension] found extension EntryPoint.parse('pika = oslo_messaging._drivers.impl_pika:PikaDriver')
   DEBUG [stevedore.extension] found extension EntryPoint.parse('amqp = oslo_messaging._drivers.impl_amqp1:ProtonDriver')
   DEBUG [stevedore.extension] found extension EntryPoint.parse('kafka = oslo_messaging._drivers.impl_kafka:KafkaDriver')
   DEBUG [stevedore.extension] found extension EntryPoint.parse('kombu = oslo_messaging._drivers.impl_rabbit:RabbitDriver')
   DEBUG [stevedore.extension] found extension EntryPoint.parse('rabbit = oslo_messaging._drivers.impl_rabbit:RabbitDriver')
   DEBUG [stevedore.extension] found extension EntryPoint.parse('zmq = oslo_messaging._drivers.impl_zmq:ZmqDriver')
   DEBUG [stevedore.extension] found extension EntryPoint.parse('fake = oslo_messaging._drivers.impl_fake:FakeDriver')
   DEBUG [stevedore.extension] found extension EntryPoint.parse('pika = oslo_messaging._drivers.impl_pika:PikaDriver')
   DEBUG [stevedore.extension] found extension EntryPoint.parse('amqp = oslo_messaging._drivers.impl_amqp1:ProtonDriver')
   DEBUG [stevedore.extension] found extension EntryPoint.parse('kafka = oslo_messaging._drivers.impl_kafka:KafkaDriver')
   DEBUG [stevedore.extension] found extension EntryPoint.parse('kombu = oslo_messaging._drivers.impl_rabbit:RabbitDriver')
   DEBUG [stevedore.extension] found extension EntryPoint.parse('rabbit = oslo_messaging._drivers.impl_rabbit:RabbitDriver')
   DEBUG [stevedore.extension] found extension EntryPoint.parse('zmq = oslo_messaging._drivers.impl_zmq:ZmqDriver')
   DEBUG [stevedore.extension] found extension EntryPoint.parse('fake = oslo_messaging._drivers.impl_fake:FakeDriver')
   DEBUG [stevedore.extension] found extension EntryPoint.parse('pika = oslo_messaging._drivers.impl_pika:PikaDriver')
   DEBUG [stevedore.extension] found extension EntryPoint.parse('amqp = oslo_messaging._drivers.impl_amqp1:ProtonDriver')
   DEBUG [stevedore.extension] found extension EntryPoint.parse('kafka = oslo_messaging._drivers.impl_kafka:KafkaDriver')
   DEBUG [stevedore.extension] found extension EntryPoint.parse('kombu = oslo_messaging._drivers.impl_rabbit:RabbitDriver')
   DEBUG [stevedore.extension] found extension EntryPoint.parse('rabbit = oslo_messaging._drivers.impl_rabbit:RabbitDriver')
   DEBUG [oslo_policy._cache_handler] Reloading cached file /opt/stack/new/neutron/neutron/tests/etc/policy.json
   DEBUG [oslo_policy.policy] Reloaded policy file: /opt/stack/new/neutron/neutron/tests/etc/policy.json
}}}

Traceback (most recent call last):
  File "neutron/tests/base.py", line 115, in func
    return f(self, *args, **kwargs)
  File "neutron/tests/functional/agent/test_l2_ovs_agent.py", line 231, in test_assert_pings_during_br_int_setup_not_lost
    self.agent.setup_integration_br()
  File "/opt/stack/new/neutron/.tox/dsvm-functional/local/lib/python2.7/site-packages/osprofiler/profiler.py", line 154, in wrapper
    return f(*args, **kwargs)
  File "neutron/plugins/ml2/drivers/openvswitch/agent/ovs_neutron_agent.py", line 986, in setup_integration_br
    self.int_br.create()
  File "neutron/agent/common/ovs_lib.py", line 220, in create
    FAILMODE_SECURE))
  File "neutron/agent/ovsdb/api.py", line 76, in __exit__
    self.result = self.commit()
  File "neutron/agent/ovsdb/impl_idl.py", line 73, in commit
    'timeout': self.timeout})
neutron.agent.ovsdb.api.TimeoutException: Commands [AddBridgeCommand(name=br-int8561d717f, may_exist=True, datapath_type=system)] exceeded timeout 10 secon

[Armando Migliaccio (armando-migliaccio)]

Do you have a gate entry?

[Miguel Angel Ajo (mangelajo)]

Hmm, I thought I had linked it, but I apparently got distracted trying to find a kibana query to find occurrences, then I discovered that we don't send functional logs to logstash, it'd be great to do that if we had a way to do it.

I'll scan the patches I was working with to see if I find occurrences of this.