[FT] Failure of "test_floatingip_mac_bindings"

[Rodolfo Alonso]

Failure of functional test "test_floatingip_mac_bindings".

Logs: https://d77e4dc62d62e32415c2-4170471c7bb0f477055c0cecff564bc8.ssl.cf2.rackcdn.com/821271/3/check/neutron-functional-with-uwsgi/d2e2877/testr_results.html

Snippet: https://paste.opendev.org/show/811716/

[Mamatisa Nurmatov (isabek)]

New occurrence:

Log: https://storage.gra.cloud.ovh.net/v1/AUTH_dcaab5e32b234d56b626f72581e3644c/zuul_opendev_logs_f76/825521/3/gate/neutron-functional-with-uwsgi/f76cef6/testr_results.html

Snippet: https://paste.opendev.org/show/812328/

[Slawek Kaplonski (slaweq)]

I today compared logs from the failed (https://storage.gra.cloud.ovh.net/v1/AUTH_dcaab5e32b234d56b626f72581e3644c/zuul_opendev_logs_f76/825521/3/gate/neutron-functional-with-uwsgi/f76cef6/controller/logs/dsvm-functional-logs/neutron.tests.functional.plugins.ml2.drivers.ovn.mech_driver.ovsdb.test_ovsdb_monitor.TestNBDbMonitorOverTcp.test_floatingip_mac_bindings/) and good (https://storage.gra.cloud.ovh.net/v1/AUTH_dcaab5e32b234d56b626f72581e3644c/zuul_opendev_logs_f76/825521/3/gate/neutron-functional-with-uwsgi/f76cef6/controller/logs/dsvm-functional-logs/neutron.tests.functional.plugins.ml2.drivers.ovn.mech_driver.ovsdb.test_ovsdb_monitor.TestNBDbMonitor.test_floatingip_mac_bindings/) runs. Here's what I found:

- In the SB logs, there is difference like:

* in good run we have:
2022-01-23T19:28:26.309Z|00140|jsonrpc|DBG|unix#3: send notification, method="update2", params=["a220fbde-7c82-11ec-9a03-4fce359daaf8",{"Datapath_Binding":{"2c98db7e-84ad-4782-9d87-24eafae1700e":{"insert":{"tunnel_key":1,"external_ids":["map",[["logical-switch","5b801987-900b-4b79-aa3b-05c5fdc422eb"],["name","neutron-2d726047-4990-446b-9f1b-9dc6403adb3e"],["name2","network1"]]]}}}}]
2022-01-23T19:28:26.330Z|00141|poll_loop|DBG|wakeup due to [POLLIN] on fd 17 (/tmp/tmp8aro35_w/ovnsb_db.sock<->) at lib/stream-fd.c:157
2022-01-23T19:28:26.330Z|00142|jsonrpc|DBG|unix#3: received request, method="transact", params=["OVN_Southbound",{"uuid-name":"rowdebd1810_12e4_4ae8_9bcd_a18781f1b986","table":"MAC_Binding","op":"insert","row":{"ip":"100.0.0.21","datapath":["uuid","2c98db7e-84ad-4782-9d87-24eafae1700e"]}}], id=1260
2022-01-23T19:28:26.330Z|00143|jsonrpc|DBG|unix#3: send reply, result=[{"uuid":["uuid","e514d19c-7371-4d1b-9958-25ffd612b68b"]}], id=1260
2022-01-23T19:28:26.330Z|00144|jsonrpc|DBG|unix#4: send notification, method="update3", params=[["monid","OVN_Southbound"],"00000000-0000-0000-0000-000000000000",{"MAC_Binding":{"e514d19c-7371-4d1b-9958-25ffd612b68b":{"insert":{"ip":"100.0.0.21","datapath":["uuid","2c98db7e-84ad-4782-9d87-24eafae1700e"]}}}}]
2022-01-23T19:28:26.460Z|00145|poll_loop|DBG|wakeup due to [POLLIN] on fd 18 (/tmp/tmp8aro35_w/ovnsb_db.sock<->) at lib/stream-fd.c:157

but in failed run there is only:

2022-01-23T19:28:46.868Z|00156|jsonrpc|DBG|tcp:127.0.0.1:33296: send notification, method="update2", params=["ae7bd9c6-7c82-11ec-9a03-4fce359daaf8",{"Connection":{"83c29962-a6e2-4f3c-9fc7-888cf46540ed":{"modify":{"is_connected":true,"status":["map",[["bound_port","42597"],["n_connections","2"],["sec_since_connect","0"],["sec_since_disconnect","0"]]]}}},"Datapath_Binding":{"15003f80-2b91-44d6-8b9d-f8d217285fb3":{"insert":{"tunnel_key":1,"external_ids":["map",[["logical-switch","70caa880-3fed-4f9b-9558-f624c0d2c469"],["name","neutron-51ac15e4-24cc-4348-85c3-fe3a51cfcaec"],["name2","network1"]]]}}}}]
2022-01-23T19:28:49.369Z|00157|poll_loop|DBG|wakeup due to 2500-ms timeout at ovsdb/ovsdb-server.c:296 (0% CPU usage)
2022-01-23T19:28:51.872Z|00158|poll_loop|DBG|wakeup due to 2503-ms timeout at ovsdb/ovsdb-server.c:296 (0% CPU usage)
2022-01-23T19:28:54.373Z|00159|poll_loop|DBG|wakeup due to 2501-ms timeout at ovsdb/ovsdb-server.c:296 (0% CPU usage)

and nothi...

[Rodolfo Alonso (rodolfo-alonso-hernandez)]

The ovsdb error is stopping the test:
2022-01-23 19:28:46.875 54853 ERROR ovsdbapp.backend.ovs_idl.vlog [-] tcp:127.0.0.1:42597: error parsing update: ovsdb error: Modify non-existing row: ovs.db.error.Error: ovsdb error: Modify non-existing row

After this line, the test is just stopping the controllers and the DB servers.

I think we should implement [1] but for all FT tests, that means in "TestOVNFunctionalBase" and not only for the NB but for the SB too. In the DB log I see the connection is updated AFTER the network creation command "network1" has been committed:
2022-01-23T19:28:46.868Z|00156|jsonrpc|DBG|tcp:127.0.0.1:33296: send notification, method="update2", params=["ae7bd9c6-7c82-11ec-9a03-4fce359daaf8",{"Connection":{"83c29962-a6e2-4f3c-9fc7-888cf46540ed":{"modify":{"is_connected":true,"status":["map",[["bound_port","42597"],["n_connections","2"],["sec_since_connect","0"],["sec_since_disconnect","0"]]]}}},"Datapath_Binding":{"15003f80-2b91-44d6-8b9d-f8d217285fb3":{"insert":{"tunnel_key":1,"external_ids":["map",[["logical-switch","70caa880-3fed-4f9b-9558-f624c0d2c469"],["name","neutron-51ac15e4-24cc-4348-85c3-fe3a51cfcaec"],["name2","network1"]]]}}}}]

In any case, what I think is failing is the connection to the OVS DB, not the NB or SB DBs.

[0]https://review.opendev.org/q/Id84bf17953527c415d611bfc198038fb6f811de3
[1]https://review.opendev.org/c/openstack/neutron/+/825530/8/neutron/tests/functional/plugins/ml2/drivers/ovn/mech_driver/ovsdb/test_ovn_db_resources.py#32

[Rodolfo Alonso (rodolfo-alonso-hernandez)]

Closing this bug because this error is not being reproduce in the CI.

[Rodolfo Alonso (rodolfo-alonso-hernandez)]

New occurence: https://storage.bhs.cloud.ovh.net/v1/AUTH_dcaab5e32b234d56b626f72581e3644c/zuul_opendev_logs_66f/866225/4/check/neutron-functional-with-uwsgi/66fa82b/testr_results.html

This time the error is different: https://paste.opendev.org/show/bFLxtBIVP9akE2h61pw7/

[yatin (yatinkarel)]

Seen again with same traces as last comment:- https://storage.gra.cloud.ovh.net/v1/AUTH_dcaab5e32b234d56b626f72581e3644c/zuul_opendev_logs_d7d/periodic/opendev.org/openstack/neutron/master/neutron-functional/d7df0d0/testr_results.html

[Rodolfo Alonso (rodolfo-alonso-hernandez)]

It seems that there is a problem in the "_check_mac_binding_exists" call, when executing the "ovsdb-client" command, as seen in c#5 [1] and c#6 [2]. I'll add a tenacity decorator on this method to retry in case of timeout.

[1]https://paste.opendev.org/show/bFLxtBIVP9akE2h61pw7/
[2]https://paste.opendev.org/show/bPc63NVDvSwAlED3zsnm/

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.opendev.org/c/openstack/neutron/+/906474

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/2023.2
Review: https://review.opendev.org/c/openstack/neutron/+/907235

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/2023.1
Review: https://review.opendev.org/c/openstack/neutron/+/907236

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/zed
Review: https://review.opendev.org/c/openstack/neutron/+/907237

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/c/openstack/neutron/+/906474
Committed: https://opendev.org/openstack/neutron/commit/64fddf4f2d18b134b5cc8348049a3c4f10f69a28
Submitter: "Zuul (22348)"
Branch: master

commit 64fddf4f2d18b134b5cc8348049a3c4f10f69a28
Author: Rodolfo Alonso Hernandez <email address hidden>
Date: Fri Jan 19 11:41:15 2024 +0000

    [OVN][FT] Retry in case of timeout when executing "ovsdb-client".

    The shell command "ovsdb-client", in the functional tests, is prone to
    timeouts. This patch adds a tenacity decorator and sets the command
    timeout to 3 seconds, that should be more than enough to retrieve one
    single register.

    Closes-Bug: #1955008
    Change-Id: I38626835ca809cc3f2894e5f81fab55cf3f40071

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/c/openstack/neutron/+/907235
Committed: https://opendev.org/openstack/neutron/commit/0526fb868ef16b2725d1a7d0cf737d01fe9d78d0
Submitter: "Zuul (22348)"
Branch: stable/2023.2

commit 0526fb868ef16b2725d1a7d0cf737d01fe9d78d0
Author: Rodolfo Alonso Hernandez <email address hidden>
Date: Fri Jan 19 11:41:15 2024 +0000

    [OVN][FT] Retry in case of timeout when executing "ovsdb-client".

    The shell command "ovsdb-client", in the functional tests, is prone to
    timeouts. This patch adds a tenacity decorator and sets the command
    timeout to 3 seconds, that should be more than enough to retrieve one
    single register.

    Closes-Bug: #1955008
    Change-Id: I38626835ca809cc3f2894e5f81fab55cf3f40071
    (cherry picked from commit 64fddf4f2d18b134b5cc8348049a3c4f10f69a28)

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/c/openstack/neutron/+/907236
Committed: https://opendev.org/openstack/neutron/commit/2f678b980cfd9fbd6fdcda18af1a140916630055
Submitter: "Zuul (22348)"
Branch: stable/2023.1

commit 2f678b980cfd9fbd6fdcda18af1a140916630055
Author: Rodolfo Alonso Hernandez <email address hidden>
Date: Fri Jan 19 11:41:15 2024 +0000

    [OVN][FT] Retry in case of timeout when executing "ovsdb-client".

    The shell command "ovsdb-client", in the functional tests, is prone to
    timeouts. This patch adds a tenacity decorator and sets the command
    timeout to 3 seconds, that should be more than enough to retrieve one
    single register.

    Closes-Bug: #1955008
    Change-Id: I38626835ca809cc3f2894e5f81fab55cf3f40071
    (cherry picked from commit 64fddf4f2d18b134b5cc8348049a3c4f10f69a28)

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/c/openstack/neutron/+/907237
Committed: https://opendev.org/openstack/neutron/commit/1f5ce18a14bc3b3d3884c3dc50daf1c8062605b6
Submitter: "Zuul (22348)"
Branch: stable/zed

commit 1f5ce18a14bc3b3d3884c3dc50daf1c8062605b6
Author: Rodolfo Alonso Hernandez <email address hidden>
Date: Fri Jan 19 11:41:15 2024 +0000

    [OVN][FT] Retry in case of timeout when executing "ovsdb-client".

    The shell command "ovsdb-client", in the functional tests, is prone to
    timeouts. This patch adds a tenacity decorator and sets the command
    timeout to 3 seconds, that should be more than enough to retrieve one
    single register.

    Closes-Bug: #1955008
    Change-Id: I38626835ca809cc3f2894e5f81fab55cf3f40071
    (cherry picked from commit 64fddf4f2d18b134b5cc8348049a3c4f10f69a28)

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/neutron 24.0.0.0rc1 release candidate.

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/neutron 21.2.1 release.

[yatin (yatinkarel)]

Seen in stable/2023.1 https://storage.gra.cloud.ovh.net/v1/AUTH_dcaab5e32b234d56b626f72581e3644c/zuul_opendev_logs_e4e/921942/1/gate/neutron-functional-with-uwsgi/e4e2d01/testr_results.html

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/neutron 22.2.0 release.

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/neutron 23.2.0 release.