Bug 1728282

This is about a race condition and fixing it is not trivial [1]. In fact, we concluded that changes to
fix it are higher risk than letting it happen. Nothing is breaking other than the exception
that we see in the logs of the test. And the test actually does not fail either. ;)

What is happening is that a transaction is modifying a row that is also being part of an event.
The row in this particular case is from the Port_Binding table and the column that is being modified
is datapath, which is a strong reference to the Datapath_Binding table. Being a strong reference,
the event handling thread correctly assumes that datapath column should be available [2].

Keeping this bug as low risk and priority and working under the assumption that as long as it remain
that way, the proper action here is to simply leave it alone.

[1]: https://review.opendev.org/#/c/713675/

[2]: https://github.com/openstack/networking-ovn/blob/5238616c7bd7b38c7da7eced0ca6abae68b3a135/networking_ovn/ovsdb/ovsdb_monitor.py#L151-L153

This message still in the logs (16.2) and looks very unprofessional to leave
this kind of error in a production service log.

Can you increase the priority of this issue ?

Attila, I agree it looks bad. However, there is no impact on functionality. Please see comment 8 that justifies the priority.

What we could do is that we can swallow the exception or just issue a warning instead.

Is ovsdb is responded with a row which volatile strong integrity requirements ?

No transaction expected to commit with a strong reference to non existing record . (Assume 0 UUID does not exists).

Monitor notification should not be sent before integrity verification.
"   Subsequently, when changes to the specified tables are committed, the
   changes are automatically sent to the client using the "update"
   monitor notification (see Section 4.1.6)."

Transaction are all or nothing, You should not see incomplete state.

"The set of operations is executed as a single
   atomic, consistent, isolated transaction.  The transaction is
   committed if and only if every operation succeeds. "

Monitor notification mandated to include the monitored columns.
"For
      "modify" updates, the prior value of each monitored column whose
      value has changed is included (monitored columns that have not
      changed are represented in "new")."

I suggest creating a tcp dump (tcp:*:6642), which could prove the ovsdb put an invalid (00000000-0000-0000-0000-000000000000)
reference on the wire (not in an error message), together with a full "OVN_Southbound" dump before and after the incident,
 but while the tcpdump is running.
Would be better to also capture "all" monitor -ing start event..


BTW, in case an insert op forgets to specify the field, the ovsdb refuses to commit with:
$ ovsdb-client transact tcp:<my_ip>:6642 '["OVN_Southbound", {"op": "insert", "table": "Port_Binding", "row": { "tunnel_key": 1} }]'
[{"uuid":["uuid","b12337cc-8e27-4c94-9a5e-7e1647bf9a6c"]},{"details":"Table Port_Binding column datapath row b12337cc-8e27-4c94-9a5e-7e1647bf9a6c references nonexistent row 00000000-0000-0000-0000-000000000000 in table Datapath_Binding.","error":"referential integrity violation"}]

In case/when it proven the ovsdb sent back invalid reference (not in an error message), please create an ovs(db) bug.

In case cannot be proven the ovsdb sent the bad response, the issue likely on neutron side.
tcpdump can decide which party misbehaved, and fix the right thing ..

Fixed in upstream OVS: https://github.com/openvswitch/ovs/commit/64b8c1d9ade2a9abc09a6472af5badddd600a3f8

I still can see the error in the log : 
/var/log/extra/errors.txt.txt:2021-04-07 13:08:18.271 ERROR /var/log/containers/neutron/server.log: 33 ERROR ovsdbapp.event [req-bb3ece0d-9ab6-4f6d-be96-7e2f3ac1f7b6 - - - - -] Unexpected exception in notify_loop: AttributeError: 'Atom' object has no attribute 'external_ids'
/var/log/extra/errors.txt.txt:2021-04-07 13:08:18.271 ERROR /var/log/containers/neutron/server.log: 33 ERROR ovsdbapp.event AttributeError: 'Atom' object has no attribute 'external_ids'
[root@controller-0 ~]# rpm -qa | grep openvs
openvswitch-selinux-extra-policy-1.0-28.el8fdp.noarch
rhosp-openvswitch-2.13-8.el8ost.noarch
network-scripts-openvswitch2.13-2.13.0-98.el8fdp.x86_64
openvswitch2.13-2.13.0-98.el8fdp.x86_64

(In reply to Eran Kuris from comment #16)
> I still can see the error in the log : 
> /var/log/extra/errors.txt.txt:2021-04-07 13:08:18.271 ERROR
> /var/log/containers/neutron/server.log: 33 ERROR ovsdbapp.event
> [req-bb3ece0d-9ab6-4f6d-be96-7e2f3ac1f7b6 - - - - -] Unexpected exception in
> notify_loop: AttributeError: 'Atom' object has no attribute 'external_ids'
> /var/log/extra/errors.txt.txt:2021-04-07 13:08:18.271 ERROR
> /var/log/containers/neutron/server.log: 33 ERROR ovsdbapp.event
> AttributeError: 'Atom' object has no attribute 'external_ids'
> [root@controller-0 ~]# rpm -qa | grep openvs
> openvswitch-selinux-extra-policy-1.0-28.el8fdp.noarch
> rhosp-openvswitch-2.13-8.el8ost.noarch
> network-scripts-openvswitch2.13-2.13.0-98.el8fdp.x86_64
> openvswitch2.13-2.13.0-98.el8fdp.x86_64

Since the patch is in python code of OVS - is it possible the OVS version is different inside of the neutron_api container? I double-checked -96 version contains the patch from upstream.

It looks like the openvswitch in openstack-neutron-server, at least in 16.1.5 (I have no idea how to check the 16.2 containers since they aren't on the catalog), at the time of @Eran's comment was -79 which wouldn't have had the fix. So it would be good to verify if the latest runs that hopefully include the python-ovs fix still produce the error. I can say that that, at least in the last 7 days, there have been no logstash entries for this particular log message.

Still seeing this error happen under openvswitch2.13-2.13.0-98.el8fdp.x86_64 
So, I'm removing openvswitch2.13-2.13.0-96.el8fdp as a fixed in version to avoid further confusion.


---

commit bb107a7f7f27a7f3ad77cebc15049606e63568c2 (tag: private-ktraynor-bz1938162.1-start, tag: private-ktraynor-bz1938162-start)
Merge: 6b3ca4b028 fc8444fb1d
Author: Open vSwitch CI <ovs-team>
Date:   Mon Mar 15 20:59:13 2021 -0400

    Merging upstream branch-2.13

    Commit list:
    fc8444fb1d python: Send notifications after the transaction ends.
...

We haven't seen this issue in a while. Please feel free to re-open if it pops up again.