Category: OpenStack

Some fun with race conditions and threads in OpenStack

Almost a year ago I reported a bug we were hitting in OpenStack using networking-ovn as a network backend. The symptom was that sometimes Tempest tests were failing in the gate when trying to reach a Floating IP of a VM. The failure rate was not really high so a couple of ‘rechecks’ here and there was enough for us to delay chasing down the bug.

Last week I decided to hunt the bug and attempt to find out the root cause of the failure. Why was the FIP unreachable? For a FIP to be reachable from the external network (Tempest), the following high-level steps should happen:

  1. Tempest needs to ARP query the FIP of the VM
  2. A TCP SYN packet is sent out to the FIP
  3. Routing will happen between external network and internal VM network
  4. The packet will reach the VM and it’ll respond back with a SYN/ACK packet to the originating IP (Tempest executor)
  5. Routing will happen between internal VM network and external network
  6. SYN/ACK packet reaches Tempest executor and the connection will get established on its side
  7. ACK sent to the VM

Some of those steps are clearly failing so time to figure out which.

2018-09-18 17:09:17,276 13788 ERROR [tempest.lib.common.ssh] Failed to establish authenticated ssh connection to cirros@ after 15 attempts

As first things come first, let’s start off by checking that we get the ARP response of the FIP. We spawn a tcpdump on the external interface where Tempest runs and check traffic to/from

Sep 18 17:09:17.644405 ubuntu-xenial-ovh-bhs1-0002095917 tcpdump[28445]: 17:09:17.275597 1e:d5:ec:49:df:4f > ff:ff:ff:ff:ff:ff, ethertype ARP (0x0806), length 42: Request who-has tell, length 28

I can see plenty of those ARP requests but not a single reply. Something’s fishy…

In OVN, ARP queries are responded by ovn-controller so they should hit the gateway node. Let’s inspect the flows there to see if they were installed in OVN Ingress table 1 (which corresponds to OpenFlow table 9):

Ingress Table 1: IP Input

These flows reply to ARP requests for the virtual IP
addresses configured in the router for DNAT or load bal‐
ancing. For a configured DNAT IP address or a load bal‐
ancer VIP A, for each router port P with Ethernet address
E, a priority-90 flow matches inport == P && arp.op == 1
&& arp.tpa == A (ARP request) with the following actions:

eth.dst = eth.src;
eth.src = E;
arp.op = 2; /* ARP reply. */
arp.tha = arp.sha;
arp.sha = E;
arp.tpa =; = A;
outport = P;
flags.loopback = 1;

$ sudo ovs-ofctl dump-flows br-int | grep table=9 | grep "arp_tpa="
cookie=0x549ad196, duration=105.055s, table=9, n_packets=0, n_bytes=0, idle_age=105, priority=90,arp,reg14=0x1,metadata=0x87,arp_tpa=,arp_op=1 actions=move:NXM_OF_ETH_SRC[]->NXM_OF_ETH_DST[],load:0x2->NXM_OF_ARP_OP[],move:NXM_NX_ARP_SHA[]->NXM_NX_ARP_THA[],mod_dl_src:fa:16:3e:3d:bf:46,load:0xfa163e3dbf46->NXM_NX_ARP_SHA[],move:NXM_OF_ARP_SPA[]->NXM_OF_ARP_TPA[],load:0xac18050b->NXM_OF_ARP_SPA[],load:0x1->NXM_NX_REG15[],load:0x1->NXM_NX_REG10[0],resubmit(,32)

So the flow for the ARP responder is installed but it has no hits (note n_packets=0). Looks like for some reason the ARP query is not reaching the router pipeline from the public network. Let’s now take a look at the Logical Router:

This is how the Logical Router looks like:

$ ovn-nbctl show
router 71c37cbd-4aa9-445d-a9d1-cb54ee1d3207 (neutron-cc163b42-1fdf-4cfa-a2ff-50c521f04222) (aka tempest-TestSecurityGroupsBasicOps-router-1912572360)
     port lrp-2a1bbf89-adee-4e74-b65e-1ac7a1ba4089
         mac: "fa:16:3e:3d:bf:46"
         networks: [""]
     nat 2eaaa99e-3be8-49ad-b801-ad198a6084fd
         external ip: ""
         logical ip: ""
         type: "snat"
     nat 582bab87-8acb-4905-8723-948651811193
         external ip: ""
         logical ip: ""
         type: "dnat_and_snat"

We can see that we have two NAT entries: one for the FIP ( <-> and one SNAT entry for the gateway which should allow the VM to access the external network.

There’s also one router port which connects the VM subnet to the router but… wait …There’s no gateway port connected to the router!! This means that the FIP is unreachable so at this point we know what’s going on but… WHY? We need to figure out why the gateway port is not added. Time to check the code and logs:

Code wise (see below), the gateway is added upon router creation. It’ll imply creating a router (L9), the gateway port (L26) and adding it to the Logical Switch as you can see here. Afterwards, it’ll add a static route with the next hop to the router (L37). Also, you can see that everything is inside a context manager (L8) where a transaction with OVSDB is created so all the commands are expected to be commited/failed as a whole:

def create_router(self, router, add_external_gateway=True):
    """Create a logical router."""
    context = n_context.get_admin_context()
    external_ids = self._gen_router_ext_ids(router)
    enabled = router.get('admin_state_up')
    lrouter_name = utils.ovn_name(router['id'])
    added_gw_port = None
    with self._nb_idl.transaction(check_error=True) as txn:
        if add_external_gateway:
            networks = self._get_v4_network_of_all_router_ports(
                context, router['id'])
            if router.get(l3.EXTERNAL_GW_INFO) and networks is not None:
                added_gw_port = self._add_router_ext_gw(context, router,
                                                        networks, txn)

def _add_router_ext_gw(self, context, router, networks, txn):
    router_id = router['id']
    # 1. Add the external gateway router port.
    gw_info = self._get_gw_info(context, router)
    gw_port_id = router['gw_port_id']
    port = self._plugin.get_port(context, gw_port_id)
    self._create_lrouter_port(router_id, port, txn=txn)

    columns = {}
    if self._nb_idl.is_col_present('Logical_Router_Static_Route',
        columns['external_ids'] = {
            ovn_const.OVN_ROUTER_IS_EXT_GW: 'true',
            ovn_const.OVN_SUBNET_EXT_ID_KEY: gw_info.subnet_id}

    # 2. Add default route with nexthop as gateway ip
    lrouter_name = utils.ovn_name(router_id)
        lrouter_name, ip_prefix='', nexthop=gw_info.gateway_ip,

    # 3. Add snat rules for tenant networks in lrouter if snat is enabled
    if utils.is_snat_enabled(router) and networks:
        self.update_nat_rules(router, networks, enable_snat=True, txn=txn)
    return port

So, how is it possible that the Logical Router exists while the gateway port does not if everything is under the same transaction? We’re nailing this down and now we need to figure that out by inspecting the transactions in neutron-server logs:

DEBUG ovsdbapp.backend.ovs_idl.transaction [-] Running txn n=1 command(idx=2): AddLRouterCommand(may_exist=True, columns={'external_ids': {'neutron:gw_port_id': u'8dc49792-b37a-48be-926a-af2c76e269a9', 'neutron:router_name': u'tempest-TestSecurityGroupsBasicOps-router-1912572360', 'neutron:revision_number': '2'}, 'enabled': True, 'options': {}}, name=neutron-cc163b42-1fdf-4cfa-a2ff-50c521f04222) {{(pid=32314) do_commit /usr/local/lib/python2.7/dist-packages/ovsdbapp/backend/ovs_idl/}}

The above trace is written when the Logical Router gets created but surprisingly we can see idx=2 meaning that it’s not the first command of a transaction. But… How is this possible? We saw in the code that it was the first command to be executed when creating a router and this is the expected sequence:

  1. AddLRouterCommand
  2. AddLRouterPortCommand
  3. SetLRouterPortInLSwitchPortCommand
  4. AddStaticRouteCommand

Let’s check the other commands in this transaction in the log file:

DEBUG ovsdbapp.backend.ovs_idl.transaction [-] Running txn n=1 command(idx=0): AddLRouterPortCommand(name=lrp-1763c78f-5d0d-41d4-acc7-dda1882b79bd, may_exist=True, lrouter=neutron-d1d3b2f2-42cb-4a86-ac5a-77001da8fee2, columns={'mac': u'fa:16:3e:e7:63:b9', 'external_ids': {'neutron:subnet_ids': u'97d41327-4ea6-4fff-859c-9884f6d1632d', 'neutron:revision_number': '3', 'neutron:router_name': u'd1d3b2f2-42cb-4a86-ac5a-77001da8fee2'}, 'networks': [u'']}) {{(pid=32314) do_commit /usr/local/lib/python2.7/dist-packages/ovsdbapp/backend/ovs_idl/}}

DEBUG ovsdbapp.backend.ovs_idl.transaction [-] Running txn n=1 command(idx=1): SetLRouterPortInLSwitchPortCommand(if_exists=True, lswitch_port=1763c78f-5d0d-41d4-acc7-dda1882b79bd, lrouter_port=lrp-1763c78f-5d0d-41d4-acc7-dda1882b79bd, is_gw_port=False, lsp_address=router) {{(pid=32314) do_commit /usr/local/lib/python2.7/dist-packages/ovsdbapp/backend/ovs_idl/}}

DEBUG ovsdbapp.backend.ovs_idl.transaction [-] Running txn n=1 command(idx=2): AddLRouterCommand(may_exist=True, columns={'external_ids': {'neutron:gw_port_id': u'8dc49792-b37a-48be-926a-af2c76e269a9', 'neutron:router_name': u'tempest-TestSecurityGroupsBasicOps-router-1912572360', 'neutron:revision_number': '2'}, 'enabled': True, 'options': {}}, name=neutron-cc163b42-1fdf-4cfa-a2ff-50c521f04222)

DEBUG ovsdbapp.backend.ovs_idl.transaction [-] Running txn n=1 command(idx=3): AddNATRuleInLRouterCommand(lrouter=neutron-d1d3b2f2-42cb-4a86-ac5a-77001da8fee2, columns={'external_ip': u'', 'type': 'snat', 'logical_ip': ''}) {{(pid=32314) do_commit /usr/local/lib/python2.7/dist-packages/ovsdbapp/backend/ovs_idl/}}

It looks like this:

  1. AddLRouterPortCommand
  2. SetLRouterPortInLSwitchPortCommand
  3. AddLRouterCommand (our faulty router)
  4. AddNATRuleInLRouterCommand

Definitely, number 3 is our command that got in between a totally different transaction from a totally different test being executed concurrently in the gate . Most likely, according to the commands 1, 2 and 4 it’s another test adding a new interface to a different router here. It’ll create a logical router port, add it to the switch and update the SNAT rules. All those debug traces come from the same process ID so the transactions are getting messed up from the two concurrent threads attempting to write into OVSDB.

This is the code that will create a new transaction object in ovsdbapp or, if it was already created, will return the same object. The problem here comes when two different threads/greenthreads attempt to create their own separate transactions concurrently:

    def transaction(self, check_error=False, log_errors=True, **kwargs):
        """Create a transaction context.

        :param check_error: Allow the transaction to raise an exception?
        :type check_error:  bool
        :param log_errors:  Log an error if the transaction fails?
        :type log_errors:   bool
        :returns: Either a new transaction or an existing one.
        :rtype: :class:`Transaction`
        if self._nested_txn:
            yield self._nested_txn
            with self.create_transaction(
                    check_error, log_errors, **kwargs) as txn:
                self._nested_txn = txn
                    yield txn
                    self._nested_txn = None
  1. Test1 will open a new transaction and append  AddLRouterPortCommand and SetLRouterPortInLSwitchPortCommand commands to it.
  2. Test1 will now yield its execution (due to some I/O in the case of greenthreads as eventlet is heavily used in OpenStack).
  3. Test 2 (our failing test!) will attempt to create its own transaction.
  4. As everything happens in the same process, self._nested_txn was previously assigned due to step number 1 and is returned here.
  5. Test 2 will append the  AddLRouterCommand command to it.
  6. At this point Test 2 will also yield its execution. Mainly due to the many debug traces that we have for scheduling a gateway port on the available chassis in OVN so this is one of the most likely parts of the code for the race condition to occur.
  7. Test 1 will append the rest of the commands and commit the transaction to OVSDB.
  8. OVSDB will execute the commands and close the transaction.
  9. When Test 2 appends the rest of its commands, the transaction is closed and will never get commited, ie. only AddLRouterCommand was applied to the DB leaving the gateway port behind in OVN.

The nested transaction mechanism in ovsdbapp was not taking into account that two different threads attempt to open separate transactions so we needed to patch this to make it thread safe. The solution that we came up with was to create a different transaction per thread ID and add the necessary coverage to the unit tests.

Two more questions arise at this point:

  • Why this is not happening in Neutron if they also use ovsdbapp there?

Perhaps it’s happening but they don’t make that much use of multiple commands transactions. Instead, most of the time it’s single command transactions that are less prone to this particular race condition.

  • Why does it happen mostly when creating a gateway port?

Failing to create a gateway port leads to VMs to lose external connectivity so the failure is very obvious. There might be other conditions where this bug happens and we’re not even realizing, producing weird behaviors. However, it’s true that this particular code which creates the gateway port is complex as it implies scheduling the port into the least loaded available chassis so a number of DEBUG traces were added. As commented through the blog post, writing these traces will result in yielding the execution to a different greenthread where the disaster occurs!

This blog post tries to show a top-bottom approach to debugging failures that are not easily reproducible. It requires a solid understanding of the system architecture (OpenStack components, OVN, databases) and its underlying technologies (Python, greenthreads) to be able to tackle this kind of race conditions in an effective way.

OVN – Profiling and optimizing ports creation

One of the most important abstractions to handle virtual networking in OpenStack clouds are definitely ports. A port is basically a connection point for attaching a single device, such as the NIC of a server to a network, a subnet to a router, etc.  They represent entry and exit points for data traffic playing a critical role in OpenStack networking.

Given the importance of ports, it’s clear that any operation on them should perform well, specially at scale and we should be able to catch any regressions ASAP before they land on production environments. Such tests should be done in a periodic fashion and should require doing them on a consistent hardware with enough resources.

In one of our first performance tests using OVN as a backend for OpenStack networking, we found out that port creation would be around 20-30% slower than using ML2/OVS. At this point, those are merely DB operations so there had to be something really odd going on.  First thing I did was to measure the time for a single port creation by creating 800 ports in an empty cloud. Each port would belong to a security group with allowed egress traffic and allowed ingress ICMP and SSH. These are the initial results:

As you can see, the time for creating a single port grows linearly with the number of ports in the cloud.  This is obviously a problem at scale that requires further investigation.

In order to understand how a port gets created in OVN, it’s recommended to take a look at the NorthBound database schema and to this interesting blogpost by my colleague Russel Bryant about how Neutron security groups are implemented in OVN. When a port is first created in OVN, the following DB operations will occur:

  1.  Logical_Switch_Port ‘insert’
  2.  Address_Set ‘modify’
  3.  ACL ‘insert’ x8 (one per ACL)
  4.  Logical_Switch_Port ‘modify’ (to add the new 8 ACLs)
  5.  Logical_Switch_Port ‘modify’ (‘up’ = False)

After a closer look to OVN NB database contents, with 800 ports created, there’ll be a total of 6400 ACLs (8 per port) which look all the same except for the inport/outport fields. A first optimization looks obvious: let’s try to get all those 800 ports into the same group and make the ACLs reference that group avoiding duplication. There’s some details and discussions in OpenvSwitch mailing list here. So far so good; we’ll be cutting down the number of ACLs to 8 in this case no matter how big the number of ports in the system increases. This would reduce the number of DB operations considerably and scale better.

However, I went deeper and wanted to understand this linear growth through profiling. I’d like to write a separate blogpost about how to do the profiling but, so far, what I found is that the ‘modify’ operations on the Logical_Switch table to insert the new 8 ACLs would take longer and longer every time (the same goes to the Address_Set table where a new element is added to it with every new port). As the number of elements grow in those two tables, inserting a new element was more expensive. Digging further in the profiling results, it looks like “__apply_diff()” method is the main culprit, and more precisely, “Datum.to_json()”. Here‘s a link to the actual source code.

Whenever a ‘modify’ operation happens in OVSDB, ovsdb-server will send a JSON  update notification to all clients (it’s actually an update2 notification which is essentially the same but including only the diff with the previous state). This notification is going to be processed by the client (in this case networking-ovn, the OpenStack integration) in the “process_update2” method here and it happens that the Datum.to_json() method is taking most of the execution time. The main questions that came to my mind at this point are:

  1. How is this JSON data later being used?
  2. Why do we need to convert to JSON if the original notification was already in JSON?

For 1, it looks like the JSON data is used to build a Row object which will be then used to notify networking-ovn of the change just in case it’d be monitoring any events:

    def __apply_diff(self, table, row, row_diff):
        old_row_diff_json = {}
        for column_name, datum_diff_json in six.iteritems(row_diff):
            old_row_diff_json[column_name] = row._data[column_name].to_json()
        return old_row_diff_json
old_row_diff_json = self.__apply_diff(table, row,
self.notify(ROW_UPDATE, row,
            Row.from_json(self, table, uuid, old_row_diff_json))

Doesn’t it look pointless to convert data “to_json” and then back “from_json”? As the number of elements in the row grows, it’ll take longer to produce the associated JSON document (linear growth) of the whole column contents (not just the diff) and the same would go the other way around.

I thought of finding a way to build the Row from the data itself before going through the expensive (and useless) JSON conversions. The patch would look something like this:

diff --git a/python/ovs/db/ b/python/ovs/db/
index 60548bcf5..5a4d129c0 100644
--- a/python/ovs/db/
+++ b/python/ovs/db/
@@ -518,10 +518,8 @@ class Idl(object):
             if not row:
                 raise error.Error('Modify non-existing row')
-            old_row_diff_json = self.__apply_diff(table, row,
-                                                  row_update['modify'])
-            self.notify(ROW_UPDATE, row,
-                        Row.from_json(self, table, uuid, old_row_diff_json))
+            old_row = self.__apply_diff(table, row, row_update['modify'])
+            self.notify(ROW_UPDATE, row, Row(self, table, uuid, old_row))
             changed = True
             raise error.Error('<row-update> unknown operation',
@@ -584,7 +582,7 @@ class Idl(object):
                         row_update[] = self.__column_name(column)
     def __apply_diff(self, table, row, row_diff):
-        old_row_diff_json = {}
+        old_row = {}
         for column_name, datum_diff_json in six.iteritems(row_diff):
             column = table.columns.get(column_name)
             if not column:
@@ -601,12 +599,12 @@ class Idl(object):
                           % (column_name,, e))
-            old_row_diff_json[column_name] = row._data[column_name].to_json()
+            old_row[column_name] = row._data[column_name].copy()
             datum = row._data[column_name].diff(datum_diff)
             if datum != row._data[column_name]:
                 row._data[column_name] = datum
-        return old_row_diff_json
+        return old_row
     def __row_update(self, table, row, row_json):
         changed = False

Now that we have everything in place, it’s time to repeat the tests with the new code and compare the results:

The improvement is obvious! Now the time to create a port is mostly constant regardless of the number of ports in the cloud and the best part is that this gain is not specific to port creation but to ANY modify operation taking place in OVSDB that uses the Python implementation of the OpenvSwitch IDL.

The intent of this blogpost is to show how to deal with performance bottlenecks through profiling and debugging in a top-down fashion, first through simple API calls measuring the time they take to complete and then all the way down to the database changes notifications.


OpenStack: Deploying a new containerized service in TripleO

When I first started to work in networking-ovn one of the first tasks I took up was to implement the ability for instances to fetch userdata and metadata at boot, such as the name of the instance, public keys, etc.

This involved introducing a new service which we called networking-ovn-metadata-agent and it’s basically a process running in compute nodes that intercepts requests from instances within network namespaces, adds some headers and forwards those to Nova. While it was fun working on it I soon realized that most of the work would be on the TripleO side and, since I was really new to it, I decided to take the challenge as well!
If you’re interested in the actual code for this feature (not the deployment related code), I sent the following patches to implement it and I plan to write a different blogpost for it:

But implementing this feature didn’t end there and we had to support a way to deploy the new service from TripleO and, YES!, it has to be containerized. I found out that this was not a simple task so I decided to write this post with the steps I took hoping it helps people going through the same process. Before describing those, I want to highlight a few things/tips:

  • It’s highly recommended to have access to a hardware capable of deploying TripleO and not relying only on the gate. This will speed up the development process *a lot* and lower pressure on the gate, which sometimes has really long queues.
  • The jobs running on the upstream CI use one node for the undercloud and one node for the overcloud so it’s not always easy to catch failures when you deploy services on certain roles like in this case where we only want the new service in computes.  CI was green on certain patchsets while I encountered problems on 3 controllers + 3 computes setups due to this. Usually production environments would be HA so it’s best to do the development on a more realistic setups whenever possible.
  • As of today, with containers, there’s no way that you can send a patch on your project (in this case networking-ovn), add a Depends-On in tripleo-* and expect that the new change is tested. Instead, the patch has to get merged, an RDO promotion has to occur so that the RPM with the fix is available and then, the container images get built and ready to be fetched by TripleO jobs. This is a regression when compared to non-containerized jobs and clearly slows down the development process. TripleO folks are doing a great effort to include a mechanism that supports this which will be a huge leap 🙂
  • To overcome the above, I had to go over the process of building my own kolla images and setting them up in the local registry (more info here). This way you can do your own testing without having to wait for the next RDO promotion. Still, your patches won’t be able to merge until it happens but you can keep on developing your stuff.
  • To test any puppet changes, I had to patch the overcloud image (usually mounting it with guestmount and changing the required files) and update it before redeploying. This is handy as well as the ‘virt-customize’ command  which allows you to execute commands directly in the overcloud image, for example, to install a new RPM package (for me usually upgrading OpenvSwitch for testing). This is no different from baremetal deployment but still useful here.

After this long introduction, let me go through the actual code that implements this new service.


1. Getting the package and the container image ready:

At this point we should be able to consume the container image from TripleO. The next step is to configure the new service with the right parameters.

2. New service configuration:


This new service will require some configuration options. Writing those configuration options will be done by puppet and, since it is a networking service, I sent a patch to puppet-neutron to support it:

All the configuration options as well as the service definition are in this file:

As we also want to set a knob which enables/disables the service in the ML2 plugin, I added an option for that here:

The patch also includes unit tests and a release note as we’re introducing a new service.


We want this service to be deployed at step 4 (see OpenStack deployment steps for more information) and also, we want networking-ovn-metadata-agent to be started after ovn-controller is up and running. ovn-controller service will be started after OpenvSwitch so this way we’ll ensure that our service will start at the right moment. For this, I sent a patch to puppet-tripleo:

And later, I found out that I wanted the neutron base profile configuration to be applied to my own service. This way I could benefit from some Neutron common configuration such as logging files, etc.:

3. Actual deployment in tripleo-heat-templates:

This is the high-level work that drives all the above and, initially, I had it in three different patches which I ended up squashing because of the inter-dependencies.

To sum up, this is what this patch does

I hope this help others introducing new services in OpenStack! Feel free to reach out to me for any comments/corrections/suggestions by e-mail or on IRC 🙂