AttributeError: 'NoneType' object has no attribute 'db_find_rows' during neutron-server startup

[Krzysztof Klimonda]

openstack/ussuri deployment

neutron: 16.1.0
ovn: 20.06.2
ovs: 2.13.1

When starting neutron-server, the following traceback is showing up:

--8<--8<--8<--
2020-09-18 08:18:47.934 47 ERROR ovsdbapp.event [-] Unexpected exception in notify_loop: AttributeError: 'NoneType' object has no attribute 'db_find_rows'
2020-09-18 08:18:47.934 47 ERROR ovsdbapp.event Traceback (most recent call last):
2020-09-18 08:18:47.934 47 ERROR ovsdbapp.event File "/var/lib/kolla/venv/lib/python3.6/site-packages/ovsdbapp/event.py", line 143, in notify_loop
2020-09-18 08:18:47.934 47 ERROR ovsdbapp.event match.run(event, row, updates)
2020-09-18 08:18:47.934 47 ERROR ovsdbapp.event File "/var/lib/kolla/venv/lib/python3.6/site-packages/neutron/plugins/ml2/drivers/ovn/mech_driver/ovsdb/ovsdb_monitor.py", line 346, in run
2020-09-18 08:18:47.934 47 ERROR ovsdbapp.event self.driver.delete_mac_binding_entries(row.external_ip)
2020-09-18 08:18:47.934 47 ERROR ovsdbapp.event File "/var/lib/kolla/venv/lib/python3.6/site-packages/neutron/plugins/ml2/drivers/ovn/mech_driver/mech_driver.py", line 957, in delete_mac_binding_entries
2020-09-18 08:18:47.934 47 ERROR ovsdbapp.event mac_binds = self._sb_ovn.db_find_rows(
2020-09-18 08:18:47.934 47 ERROR ovsdbapp.event AttributeError: 'NoneType' object has no attribute 'db_find_rows'
--8<--8<--8<--

[Hongbin Lu (hongbin.lu)]

Please provide the reproducing steps and post the relevant neutron config files.

I am going to set the status to "incompleted". Please feel free to reset the status to "new" once more information is provided.

[Krzysztof Klimonda (kklimonda)]

I don't have any reproducing steps (other than enabling OVN ML2 driver), but that seems to be happening just after neutron-server starting.
Looking at the code it seems that `delete_mac_binding_entries` is being called before `post_fork_initialize` finishes and sets self._sb_ovn.

To confirm that I've patched mech_driver.py like that:
```
diff --git a/neutron/plugins/ml2/drivers/ovn/mech_driver/mech_driver.py b/neutron/plugins/ml2/drivers/ovn/mech_driver/mech_driver.py
index eb8e0d5829..e04d236e67 100644
--- a/neutron/plugins/ml2/drivers/ovn/mech_driver/mech_driver.py
+++ b/neutron/plugins/ml2/drivers/ovn/mech_driver/mech_driver.py
@@ -223,6 +223,7 @@ class OVNMechanismDriver(api.MechanismDriver):
     def post_fork_initialize(self, resource, event, trigger, payload=None):
         # NOTE(rtheis): This will initialize all workers (API, RPC,
         # plugin service and OVN) with OVN IDL connections.
+ LOG.info("KK: post_fork_initialize() called")
         self._post_fork_event.clear()
         self._ovn_client_inst = None

@@ -235,6 +236,7 @@ class OVNMechanismDriver(api.MechanismDriver):

         self._nb_ovn, self._sb_ovn = impl_idl_ovn.get_ovn_idls(
             self, trigger, binding_events=not is_maintenance)
+ LOG.info("KK: post_fork_initialize() setting self._sb_ovn")

         if self._sb_ovn.is_table_present('Chassis_Private'):
             self.agent_chassis_table = 'Chassis_Private'
```

and observed logs after restarting neutron-server:

```
2020-09-22 12:36:26.383 21 INFO neutron.plugins.ml2.drivers.ovn.mech_driver.mech_driver [-] KK: post_fork_initialize() called
2020-09-22 12:36:26.384 22 INFO neutron.plugins.ml2.drivers.ovn.mech_driver.mech_driver [-] KK: post_fork_initialize() called
2020-09-22 12:36:26.386 23 INFO neutron.plugins.ml2.drivers.ovn.mech_driver.mech_driver [-] KK: post_fork_initialize() called
2020-09-22 12:36:26.388 24 INFO neutron.plugins.ml2.drivers.ovn.mech_driver.mech_driver [-] KK: post_fork_initialize() called
2020-09-22 12:36:26.389 25 INFO neutron.plugins.ml2.drivers.ovn.mech_driver.mech_driver [-] KK: post_fork_initialize() called
2020-09-22 12:36:26.399 26 INFO neutron.plugins.ml2.drivers.ovn.mech_driver.mech_driver [-] KK: post_fork_initialize() called
2020-09-22 12:36:26.402 27 INFO neutron.plugins.ml2.drivers.ovn.mech_driver.mech_driver [-] KK: post_fork_initialize() called
2020-09-22 12:36:26.403 28 INFO neutron.plugins.ml2.drivers.ovn.mech_driver.mech_driver [-] KK: post_fork_initialize() called
2020-09-22 12:36:26.410 29 INFO neutron.plugins.ml2.drivers.ovn.mech_driver.mech_driver [-] KK: post_fork_initialize() called
2020-09-22 12:36:26.416 30 INFO neutron.plugins.ml2.drivers.ovn.mech_driver.mech_driver [-] KK: post_fork_initialize() called
2020-09-22 12:36:26.420 31 INFO neutron.plugins.ml2.drivers.ovn.mech_driver.mech_driver [-] KK: post_fork_initialize() called
2020-09-22 12:36:26.426 32 INFO neutron.plugins.ml2.drivers.ovn.mech_driver.mech_driver [-] KK: post_fork_initialize() called
2020-09-22 12:36:26.433 33 INFO neutron.plugins.ml2.drivers.ovn.mech_driver.mech_driver [-] KK: post_fork_initialize() called
2020-09-22 12:36:31.772 29 ERROR ovsdbapp.event [-] Unexpected excep...

[Jakub Libosvar (libosvar)]

I saw this error when a connection was broken between neutron-server and OVN databases, ovsdbapp bails out after 3 attempts to reconnect, which should be fixed by https://review.opendev.org/#/c/752092/

Are you sure that your connection string to OVN dbs is correct? Can you run queries using cli on the same address?

e.g. if your ovn-remote is <url> then try "ovn-nbctl --db=<url> show" from the place where your neutron-server is running.

[Krzysztof Klimonda (kklimonda)]

It seems to be working fine:

```
# grep ovn_nb_conn /etc/kolla/neutron-server/ml2_conf.ini
ovn_nb_connection = tcp:10.129.10.11:6641,tcp:10.129.10.12:6641,tcp:10.129.10.13:6641
# docker exec -it ovn_nb_db ovn-nbctl --db=tcp:10.129.10.11:6641,tcp:10.129.10.12:6641,tcp:10.129.10.13:6641 show |wc -l
2760
#
```

Also, from the logs:

```
2020-09-22 12:41:49.300 21 INFO neutron.plugins.ml2.drivers.ovn.mech_driver.mech_driver [-] KK: post_fork_initialize() called
2020-09-22 12:41:49.307 22 INFO neutron.plugins.ml2.drivers.ovn.mech_driver.mech_driver [-] KK: post_fork_initialize() called
2020-09-22 12:41:49.384 21 INFO ovsdbapp.backend.ovs_idl.vlog [req-cd13b2c4-3a59-4fa5-90e8-a410b93e4c2e - - - - -] tcp:10.129.10.11:6641: connecting...
2020-09-22 12:41:49.384 21 INFO ovsdbapp.backend.ovs_idl.vlog [req-cd13b2c4-3a59-4fa5-90e8-a410b93e4c2e - - - - -] tcp:10.129.10.11:6641: connected
2020-09-22 12:41:49.391 22 INFO ovsdbapp.backend.ovs_idl.vlog [req-97257c29-9619-4bd5-b391-67f5a10ad372 - - - - -] tcp:10.129.10.11:6641: connecting...
2020-09-22 12:41:49.391 22 INFO ovsdbapp.backend.ovs_idl.vlog [req-97257c29-9619-4bd5-b391-67f5a10ad372 - - - - -] tcp:10.129.10.11:6641: connected
2020-09-22 12:41:54.173 21 ERROR ovsdbapp.event [-] Unexpected exception in notify_loop: AttributeError: 'NoneType' object has no attribute 'db_find_rows'
2020-09-22 12:41:54.173 21 ERROR ovsdbapp.event Traceback (most recent call last):
2020-09-22 12:41:54.173 21 ERROR ovsdbapp.event File "/var/lib/kolla/venv/lib/python3.6/site-packages/ovsdbapp/event.py", line 143, in notify_loop
2020-09-22 12:41:54.173 21 ERROR ovsdbapp.event match.run(event, row, updates)
2020-09-22 12:41:54.173 21 ERROR ovsdbapp.event File "/var/lib/kolla/venv/lib/python3.6/site-packages/neutron/plugins/ml2/drivers/ovn/mech_driver/ovsdb/ovsdb_monitor.py", line 346, in run
2020-09-22 12:41:54.173 21 ERROR ovsdbapp.event self.driver.delete_mac_binding_entries(row.external_ip)
2020-09-22 12:41:54.173 21 ERROR ovsdbapp.event File "/var/lib/kolla/venv/lib/python3.6/site-packages/neutron/plugins/ml2/drivers/ovn/mech_driver/mech_driver.py", line 959, in delete_mac_binding_entries
2020-09-22 12:41:54.173 21 ERROR ovsdbapp.event mac_binds = self._sb_ovn.db_find_rows(
2020-09-22 12:41:54.173 21 ERROR ovsdbapp.event AttributeError: 'NoneType' object has no attribute 'db_find_rows'
2020-09-22 12:41:54.173 21 ERROR ovsdbapp.event
2020-09-22 12:41:54.175 21 ERROR ovsdbapp.event [-] Unexpected exception in notify_loop: AttributeError: 'NoneType' object has no attribute 'db_find_rows'
2020-09-22 12:41:54.175 21 ERROR ovsdbapp.event Traceback (most recent call last):
2020-09-22 12:41:54.175 21 ERROR ovsdbapp.event File "/var/lib/kolla/venv/lib/python3.6/site-packages/ovsdbapp/event.py", line 143, in notify_loop
2020-09-22 12:41:54.175 21 ERROR ovsdbapp.event match.run(event, row, updates)
2020-09-22 12:41:54.175 21 ERROR ovsdbapp.event File "/var/lib/kolla/venv/lib/python3.6/site-packages/neutron/plugins/ml2/drivers/ovn/mech_driver/ovsdb/ovsdb_monitor.py", line 346, in run
2020-09-22 12:41:54.175 21 ERROR ovsdbapp.event self.driver.delete_mac_binding_entries(row.external_ip)
2020-09-22 12:41:...

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.opendev.org/758391

[Rodolfo Alonso (rodolfo-alonso-hernandez)]

Hello Krzysztof:

Before this error, do you see in the logs the message "Getting OvsdbNbOvnIdl for WorkerService with retry"? This is where the idl connections are created.https://review.opendev.org/#/c/752092/

As Jakub said, https://review.opendev.org/#/c/752092/ should improve the connection process. Did you try it?

Regards.

[Michal Nasiadka (mnasiadka)]

Hello Rodolfo, it also affects me - and the change you pointed out does not help.
I have ovsdbapp 1.2.2 and neutron code from stable/ussuri git branch (not point release).