neutron

[neutron][api] test_log_deleted_with_corresponding_security_group failing randomly

Bug #1971569 reported by yatin
10
This bug affects 2 people
Affects Status Importance Assigned to Milestone
neutron
Fix Released
High
yatin

Bug Description

test_log_deleted_with_corresponding_security_group api tests randomly failing with below Trace:-

Traceback (most recent call last):
  File "/opt/stack/tempest/.tox/tempest/lib/python3.8/site-packages/neutron_tempest_plugin/api/admin/test_logging.py", line 99, in test_log_deleted_with_corresponding_security_group
    self.assertRaises(exceptions.NotFound,
  File "/opt/stack/tempest/.tox/tempest/lib/python3.8/site-packages/testtools/testcase.py", line 467, in assertRaises
    self.assertThat(our_callable, matcher)
  File "/opt/stack/tempest/.tox/tempest/lib/python3.8/site-packages/testtools/testcase.py", line 480, in assertThat
    raise mismatch_error
testtools.matchers._impl.MismatchError: <function NetworkClientJSON._shower.<locals>._show at 0x7f784dd443a0> returned {'log': {'id': '4360d06d-7bd2-42e8-9468-2e760b1b246a', 'name': 'tempest-test-log-1596006254', 'resource_type': 'security_group', 'resource_id': '1df2df30-4901-4e41-b58f-bbef3b0c48ee', 'target_id': None, 'event': 'ALL', 'enabled': True, 'revision_number': 0, 'description': '', 'created_at': '2022-05-04T10:17:44Z', 'updated_at': '2022-05-04T10:17:44Z'}}

Example logs:-
    https://c1d005e52a45f1c42de5-a40b9478ae1bd073dc32f331038fe6d7.ssl.cf1.rackcdn.com/839477/1/check/neutron-tempest-plugin-api/825f39d/testr_results.html
    https://9a2b40b9abe499183777-8788f9c43324a469e03ac2bb48dfb234.ssl.cf2.rackcdn.com/837301/1/check/neutron-tempest-plugin-api-yoga/f0c7ad9/testr_results.html
    https://5fb6cfbc0c5c1a5be079-29e820dbac3fa779e4aa716d6c5c5850.ssl.cf1.rackcdn.com/839477/2/gate/neutron-tempest-plugin-api/929ff45/testr_results.html

From neutron api:

May 04 10:17:44.536866 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: DEBUG ovsdbapp.backend.ovs_idl.transaction [None req-69db86bc-5bbd-4b78-a6bc-00e84d0f5e88 None None] Running txn n=1 command(idx=14): DbSetCommand(table=ACL, record=8f71b6eb-d4cf-4e64-8bbb-709c99dc3ad8, col_values=(('log', False), ('meter', []), ('name', []), ('severity', []))) {{(pid=98372) do_commit /usr/local/lib/python3.8/dist-packages/ovsdbapp/backend/ovs_idl/transaction.py:90}}
May 04 10:17:44.541908 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR ovsdbapp.backend.ovs_idl.transaction [None req-d1699144-a926-431c-8202-470b285baa8a tempest-LoggingTestJSON-1873065189 tempest-LoggingTestJSON-1873065189-project] Traceback (most recent call last):
May 04 10:17:44.541908 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: File "/usr/local/lib/python3.8/dist-packages/ovsdbapp/backend/ovs_idl/connection.py", line 131, in run
May 04 10:17:44.541908 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: txn.results.put(txn.do_commit())
May 04 10:17:44.541908 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: File "/usr/local/lib/python3.8/dist-packages/ovsdbapp/backend/ovs_idl/transaction.py", line 93, in do_commit
May 04 10:17:44.541908 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: command.run_idl(txn)
May 04 10:17:44.541908 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: File "/usr/local/lib/python3.8/dist-packages/ovsdbapp/backend/ovs_idl/command.py", line 139, in run_idl
May 04 10:17:44.541908 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: record = self.api.lookup(self.table, self.record)
May 04 10:17:44.541908 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: File "/usr/local/lib/python3.8/dist-packages/ovsdbapp/backend/ovs_idl/__init__.py", line 181, in lookup
May 04 10:17:44.541908 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: return self._lookup(table, record)
May 04 10:17:44.541908 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: File "/usr/local/lib/python3.8/dist-packages/ovsdbapp/backend/ovs_idl/__init__.py", line 200, in _lookup
May 04 10:17:44.541908 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: raise idlutils.RowNotFound(table=table, col='uuid',
May 04 10:17:44.541908 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ovsdbapp.backend.ovs_idl.idlutils.RowNotFound: Cannot find ACL with uuid=8f71b6eb-d4cf-4e64-8bbb-709c99dc3ad8
May 04 10:17:44.541908 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]:
May 04 10:17:44.544980 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR neutron.services.logapi.drivers.manager [None req-d1699144-a926-431c-8202-470b285baa8a tempest-LoggingTestJSON-1873065189 tempest-LoggingTestJSON-1873065189-project] Extension driver 'ovn' failed in delete_log: ovsdbapp.backend.ovs_idl.idlutils.RowNotFound: Cannot find ACL with uuid=8f71b6eb-d4cf-4e64-8bbb-709c99dc3ad8
May 04 10:17:44.544980 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR neutron.services.logapi.drivers.manager Traceback (most recent call last):
May 04 10:17:44.544980 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR neutron.services.logapi.drivers.manager File "/opt/stack/neutron/neutron/services/logapi/drivers/manager.py", line 116, in call
May 04 10:17:44.544980 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR neutron.services.logapi.drivers.manager getattr(driver, method_name)(*args, **kwargs)
May 04 10:17:44.544980 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR neutron.services.logapi.drivers.manager File "/opt/stack/neutron/neutron/services/logapi/drivers/ovn/driver.py", line 331, in delete_log
May 04 10:17:44.544980 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR neutron.services.logapi.drivers.manager ovn_txn.add(self.ovn_nb.meter_del(self.meter_name,
May 04 10:17:44.544980 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR neutron.services.logapi.drivers.manager File "/usr/lib/python3.8/contextlib.py", line 120, in __exit__
May 04 10:17:44.544980 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR neutron.services.logapi.drivers.manager next(self.gen)
May 04 10:17:44.544980 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR neutron.services.logapi.drivers.manager File "/opt/stack/neutron/neutron/plugins/ml2/drivers/ovn/mech_driver/ovsdb/impl_idl_ovn.py", line 269, in transaction
May 04 10:17:44.544980 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR neutron.services.logapi.drivers.manager yield t
May 04 10:17:44.544980 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR neutron.services.logapi.drivers.manager File "/usr/lib/python3.8/contextlib.py", line 120, in __exit__
May 04 10:17:44.544980 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR neutron.services.logapi.drivers.manager next(self.gen)
May 04 10:17:44.544980 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR neutron.services.logapi.drivers.manager File "/usr/local/lib/python3.8/dist-packages/ovsdbapp/api.py", line 110, in transaction
May 04 10:17:44.544980 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR neutron.services.logapi.drivers.manager del self._nested_txns_map[cur_thread_id]
May 04 10:17:44.544980 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR neutron.services.logapi.drivers.manager File "/usr/local/lib/python3.8/dist-packages/ovsdbapp/api.py", line 61, in __exit__
May 04 10:17:44.544980 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR neutron.services.logapi.drivers.manager self.result = self.commit()
May 04 10:17:44.544980 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR neutron.services.logapi.drivers.manager File "/usr/local/lib/python3.8/dist-packages/ovsdbapp/backend/ovs_idl/transaction.py", line 65, in commit
May 04 10:17:44.544980 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR neutron.services.logapi.drivers.manager raise result.ex
May 04 10:17:44.544980 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR neutron.services.logapi.drivers.manager File "/usr/local/lib/python3.8/dist-packages/ovsdbapp/backend/ovs_idl/connection.py", line 131, in run
May 04 10:17:44.544980 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR neutron.services.logapi.drivers.manager txn.results.put(txn.do_commit())
May 04 10:17:44.544980 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR neutron.services.logapi.drivers.manager File "/usr/local/lib/python3.8/dist-packages/ovsdbapp/backend/ovs_idl/transaction.py", line 93, in do_commit
May 04 10:17:44.544980 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR neutron.services.logapi.drivers.manager command.run_idl(txn)
May 04 10:17:44.544980 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR neutron.services.logapi.drivers.manager File "/usr/local/lib/python3.8/dist-packages/ovsdbapp/backend/ovs_idl/command.py", line 139, in run_idl
May 04 10:17:44.544980 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR neutron.services.logapi.drivers.manager record = self.api.lookup(self.table, self.record)
May 04 10:17:44.544980 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR neutron.services.logapi.drivers.manager File "/usr/local/lib/python3.8/dist-packages/ovsdbapp/backend/ovs_idl/__init__.py", line 181, in lookup
May 04 10:17:44.544980 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR neutron.services.logapi.drivers.manager return self._lookup(table, record)
May 04 10:17:44.544980 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR neutron.services.logapi.drivers.manager File "/usr/local/lib/python3.8/dist-packages/ovsdbapp/backend/ovs_idl/__init__.py", line 200, in _lookup
May 04 10:17:44.544980 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR neutron.services.logapi.drivers.manager raise idlutils.RowNotFound(table=table, col='uuid',
May 04 10:17:44.544980 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR neutron.services.logapi.drivers.manager ovsdbapp.backend.ovs_idl.idlutils.RowNotFound: Cannot find ACL with uuid=8f71b6eb-d4cf-4e64-8bbb-709c99dc3ad8
May 04 10:17:44.544980 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR neutron.services.logapi.drivers.manager
May 04 10:17:44.550840 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR neutron_lib.callbacks.manager [None req-d1699144-a926-431c-8202-470b285baa8a tempest-LoggingTestJSON-1873065189 tempest-LoggingTestJSON-1873065189-project] Error during notification for neutron.services.logapi.logging_plugin.LoggingPlugin._clean_logs_by_resource_id-70942 security_group, after_delete: neutron_lib.exceptions.DriverCallError
May 04 10:17:44.550840 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR neutron_lib.callbacks.manager Traceback (most recent call last):
May 04 10:17:44.550840 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR neutron_lib.callbacks.manager File "/usr/local/lib/python3.8/dist-packages/neutron_lib/callbacks/manager.py", line 181, in _notify_loop
May 04 10:17:44.550840 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR neutron_lib.callbacks.manager callback(resource, event, trigger, payload=payload)
May 04 10:17:44.550840 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR neutron_lib.callbacks.manager File "/opt/stack/neutron/neutron/services/logapi/logging_plugin.py", line 63, in _clean_logs_by_resource_id
May 04 10:17:44.550840 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR neutron_lib.callbacks.manager self._clean_logs(payload.context.elevated(), sg_id=payload.resource_id)
May 04 10:17:44.550840 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR neutron_lib.callbacks.manager File "/opt/stack/neutron/neutron/services/logapi/logging_plugin.py", line 58, in _clean_logs
May 04 10:17:44.550840 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR neutron_lib.callbacks.manager self.delete_log(context, log['id'])
May 04 10:17:44.550840 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR neutron_lib.callbacks.manager File "/opt/stack/neutron/neutron/services/logapi/logging_plugin.py", line 136, in delete_log
May 04 10:17:44.550840 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR neutron_lib.callbacks.manager self.driver_manager.call(
May 04 10:17:44.550840 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR neutron_lib.callbacks.manager File "/opt/stack/neutron/neutron/services/logapi/drivers/manager.py", line 125, in call
May 04 10:17:44.550840 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR neutron_lib.callbacks.manager raise exceptions.DriverCallError(exc_list=exc_list)
May 04 10:17:44.550840 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR neutron_lib.callbacks.manager neutron_lib.exceptions.DriverCallError
May 04 10:17:44.550840 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: ERROR neutron_lib.callbacks.manager
May 04 10:17:44.552939 ubuntu-focal-rax-ord-0029540090 neutron-server[98372]: DEBUG neutron_lib.callbacks.manager [None req-d1699144-a926-431c-8202-470b285baa8a tempest-LoggingTestJSON-1873065189 tempest-LoggingTestJSON-1873065189-project] Publish callbacks [] for security_group (None), before_response {{(pid=98372) _notify_loop /usr/local/lib/python3.8/dist-packages/neutron_lib/callbacks/manager.py:176}}

Fails at:- https://opendev.org/openstack/neutron/src/branch/master/neutron/services/logapi/drivers/ovn/driver.py#L330

yatin (yatinkarel)
tags: added: api gate-failure tempest
Elvira García Ruiz (elviragr)
Changed in neutron:
status: New → Confirmed
Elvira García Ruiz (elviragr)
Changed in neutron:
importance: Undecided → High
yatin (yatinkarel)
Changed in neutron:
assignee: nobody → yatin (yatinkarel)
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to neutron (master)

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

Changed in neutron:
status: Confirmed → In Progress
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to neutron (master)

Reviewed: https://review.opendev.org/c/openstack/neutron/+/841094
Committed: https://opendev.org/openstack/neutron/commit/1471f531b86eef8928756d5e927f710a5683e6ad
Submitter: "Zuul (22348)"
Branch: master

commit 1471f531b86eef8928756d5e927f710a5683e6ad
Author: yatinkarel <email address hidden>
Date: Mon May 9 15:34:49 2022 +0530

    [OVN] Handle missing acls during log removal

    During log delete we fetch all the acls for
    all the pgs if there is only one log object
    and do clear log of all these acls, but if
    one or more acls of any of the pgs is removed
    concurrently, db_set fails as acl is not found.

    This patch proposes to only do log clear of those
    acls which are available and add log message for the
    acls which were deleted concurrently.

    Also add a unit test for this case where one of
    the acl get's missing.

    Closes-Bug: #1971569
    Change-Id: I58487024c8d0352776307f0185f0812bb00036ae

Changed in neutron:
status: In Progress → Fix Released
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to neutron (stable/yoga)

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

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to neutron (stable/xena)

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

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to neutron (stable/wallaby)

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

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to neutron (stable/yoga)

Reviewed: https://review.opendev.org/c/openstack/neutron/+/841943
Committed: https://opendev.org/openstack/neutron/commit/61f01cdf728052dc4ac00e6515e2e092460c6f5c
Submitter: "Zuul (22348)"
Branch: stable/yoga

commit 61f01cdf728052dc4ac00e6515e2e092460c6f5c
Author: yatinkarel <email address hidden>
Date: Mon May 9 15:34:49 2022 +0530

    [OVN] Handle missing acls during log removal

    During log delete we fetch all the acls for
    all the pgs if there is only one log object
    and do clear log of all these acls, but if
    one or more acls of any of the pgs is removed
    concurrently, db_set fails as acl is not found.

    This patch proposes to only do log clear of those
    acls which are available and add log message for the
    acls which were deleted concurrently.

    Also add a unit test for this case where one of
    the acl get's missing.

    Closes-Bug: #1971569
    Change-Id: I58487024c8d0352776307f0185f0812bb00036ae
    (cherry picked from commit 1471f531b86eef8928756d5e927f710a5683e6ad)

tags: added: in-stable-yoga
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to neutron (stable/xena)

Reviewed: https://review.opendev.org/c/openstack/neutron/+/841944
Committed: https://opendev.org/openstack/neutron/commit/20d48bbb9dc140e89a6464dc520ebed1bc3a1762
Submitter: "Zuul (22348)"
Branch: stable/xena

commit 20d48bbb9dc140e89a6464dc520ebed1bc3a1762
Author: yatinkarel <email address hidden>
Date: Mon May 9 15:34:49 2022 +0530

    [OVN] Handle missing acls during log removal

    During log delete we fetch all the acls for
    all the pgs if there is only one log object
    and do clear log of all these acls, but if
    one or more acls of any of the pgs is removed
    concurrently, db_set fails as acl is not found.

    This patch proposes to only do log clear of those
    acls which are available and add log message for the
    acls which were deleted concurrently.

    Also add a unit test for this case where one of
    the acl get's missing.

    Closes-Bug: #1971569
    Change-Id: I58487024c8d0352776307f0185f0812bb00036ae
    (cherry picked from commit 1471f531b86eef8928756d5e927f710a5683e6ad)

tags: added: in-stable-xena
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to neutron (stable/wallaby)

Reviewed: https://review.opendev.org/c/openstack/neutron/+/841945
Committed: https://opendev.org/openstack/neutron/commit/9bb95609673e1aeefc1c486a812028722a3840ac
Submitter: "Zuul (22348)"
Branch: stable/wallaby

commit 9bb95609673e1aeefc1c486a812028722a3840ac
Author: yatinkarel <email address hidden>
Date: Mon May 9 15:34:49 2022 +0530

    [OVN] Handle missing acls during log removal

    During log delete we fetch all the acls for
    all the pgs if there is only one log object
    and do clear log of all these acls, but if
    one or more acls of any of the pgs is removed
    concurrently, db_set fails as acl is not found.

    This patch proposes to only do log clear of those
    acls which are available and add log message for the
    acls which were deleted concurrently.

    Also add a unit test for this case where one of
    the acl get's missing.

    Closes-Bug: #1971569
    Change-Id: I58487024c8d0352776307f0185f0812bb00036ae
    (cherry picked from commit 1471f531b86eef8928756d5e927f710a5683e6ad)

tags: added: in-stable-wallaby
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix included in openstack/neutron 18.4.0

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

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix included in openstack/neutron 19.3.0

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

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix included in openstack/neutron 20.1.0

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

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix included in openstack/neutron 21.0.0.0rc1

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

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.