+++ This bug was initially created as a clone of Bug #2178618 +++

Description of problem:
LoggingTestJSON.test_log_deleted_with_corresponding_security_group from
python3-neutron-tests-tempest-2.1.0-1.20230222141314.021ce91 ,
randomly failing .

Version-Release number of selected component (if applicable):
RHOS-17.1-RHEL-9-20230313.n.2

How reproducible:
With a single thread test load not really.
With heavier load seams easy.

Steps to Reproduce:
Assuming you have tempest configured with the plugin with $HOME/tempest-dir directory.
git clone https://github.com/openstack/tempest-stress
cd tempest-stress
sudo python setup.py install
cp tempest_stress/etc/logging_stress.conf.sample ../tempest-dir/etc/logging.conf

cat >$HOME/tempest-dir/etc/tests.json <<EOF
[{"action": "tempest_stress.actions.unit_test.UnitTest",
"threads": 32,
"use_admin": true,
"use_isolated_tenants": true,
"kwargs":

{"test_method": "neutron_tempest_plugin.api.admin.test_logging.LoggingTestJSON.test_log_deleted_with_corresponding_security_group", "class_setup_per": "action"}

}
]
EOF

while true; do OS_STDOUT_CAPTURE=0 OS_STDERR_CAPTURE=0 OS_LOG_CAPTURE=0 run-tempest-stress -S -c /home/stack/tempest-dir/etc/ -t /home/stack/tempest-dir/etc/tests.json -d 600; date; done

Additional info:

The security group deleted with 204 response,
it means subsequent GETs are not supposed to show it again,
and reasonable user assumption the related Entities also deleted in the same transaction.
In case the sync deletion is not an expected behavior it should be documented.

Response - Headers:

{'content-type': 'application/json', 'content-length': '452', 'x-openstack-request-id': 'req-c334365e-d6c5-48a5-8893-1b5a16e73523', 'date': 'Tue, 14 Mar 2023 16:13:06 GMT', 'connection': 'close', 'status': '200', 'content-location': 'http://10.0.0.104:9696/v2.0/log/logs/9247b381-00bf-4dac-81fc-81b016ee9512'}

Body: b'{"log": {"id": "9247b381-00bf-4dac-81fc-81b016ee9512", "project_id": "91d4f36d7413412ab187accc11e2692b", "name": "tempest-test-log-1515065427", "resource_type": "security_group", "resource_id": "b8ecf787-1a32-4e4a-8341-0f8eb666bd78", "target_id": null, "event": "ALL", "enabled": true, "revision_number": 0, "description": "", "created_at": "2023-03-14T16:13:06Z", "updated_at": "2023-03-14T16:13:06Z", "tenant_id": "91d4f36d7413412ab187accc11e2692b"}}'
2023-03-14 16:13:06,770 192626 INFO [tempest.lib.common.rest_client] Request (LoggingTestJSON:test_log_deleted_with_corresponding_security_group): 204 DELETE http://10.0.0.104:9696/v2.0/security-groups/b8ecf787-1a32-4e4a-8341-0f8eb666bd78 0.245s
2023-03-14 16:13:06,770 192626 DEBUG [tempest.lib.common.rest_client] Request - Headers:

{'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}

Body: None
Response - Headers:

{'x-openstack-request-id': 'req-41c171e0-c844-46ef-b875-130158c33538', 'date': 'Tue, 14 Mar 2023 16:13:06 GMT', 'connection': 'close', 'status': '204', 'content-location': 'http://10.0.0.104:9696/v2.0/security-groups/b8ecf787-1a32-4e4a-8341-0f8eb666bd78'}

Body: b''
2023-03-14 16:13:06,795 192626 INFO [tempest.lib.common.rest_client] Request (LoggingTestJSON:test_log_deleted_with_corresponding_security_group): 200 GET http://10.0.0.104:9696/v2.0/log/logs/9247b381-00bf-4dac-81fc-81b016ee9512 0.023s
2023-03-14 16:13:06,795 192626 DEBUG [tempest.lib.common.rest_client] Request - Headers:

{'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}

Body: None
Response - Headers:

{'content-type': 'application/json', 'content-length': '353', 'x-openstack-request-id': 'req-138e88c0-0a59-4c05-bb90-0335f5fbfab1', 'date': 'Tue, 14 Mar 2023 16:13:06 GMT', 'connection': 'close', 'status': '200', 'content-location': 'http://10.0.0.104:9696/v2.0/log/logs/9247b381-00bf-4dac-81fc-81b016ee9512'}

Body: b'{"log": {"id": "9247b381-00bf-4dac-81fc-81b016ee9512", "name": "tempest-test-log-1515065427", "resource_type": "security_group", "resource_id": "b8ecf787-1a32-4e4a-8341-0f8eb666bd78", "target_id": null, "event": "ALL", "enabled": true, "revision_number": 0, "description": "", "created_at": "2023-03-14T16:13:06Z", "updated_at": "2023-03-14T16:13:06Z"}}'
}}}

Traceback (most recent call last):
File "/usr/lib/python3.9/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 "/usr/lib/python3.9/site-packages/testtools/testcase.py", line 465, in assertRaises
self.assertThat(our_callable, matcher)
File "/usr/lib/python3.9/site-packages/testtools/testcase.py", line 478, in assertThat
raise mismatch_error
testtools.matchers._impl.MismatchError: <function NetworkClientJSON._shower.<locals>._show at 0x7f8bb6e82430> returned {'log': {'id': '9247b381-00bf-4dac-81fc-81b016ee9512', 'name': 'tempest-test-log-1515065427', 'resource_type': 'security_group', 'resource_id': 'b8ecf787-1a32-4e4a-8341-0f8eb666bd78', 'target_id': None, 'event': 'ALL', 'enabled': True, 'revision_number': 0, 'description': '', 'created_at': '2023-03-14T16:13:06Z', 'updated_at': '2023-03-14T16:13:06Z'}}

— Additional comment from Attila Fazekas on 2023-03-15 12:51:42 UTC —

https://rhos-ci-jenkins.lab.eng.tlv2.redhat.com/view/QE/view/OSP17.1/job/phase2-17.1_compact-director-rhel-9.2-virthost-3cont_2comp-ipv4-geneve-lvm-octavia/19/testReport/junit/neutron_tempest_plugin.api.admin.test_logging/LoggingTestJSON/test_log_deleted_with_corresponding_security_group_id_1ab4eb2a_76f5_45b9_816b_1aa497a71eea_/
https://rhos-ci-jenkins.lab.eng.tlv2.redhat.com/view/QE/view/OSP17.1/job/phase2-17.1_compact-director-rhel-9.2-virthost-3cont_2comp-ipv4-geneve-lvm-octavia/19/
http://rhos-ci-logs.lab.eng.tlv2.redhat.com/logs/rcj/phase2-17.1_compact-director-rhel-9.2-virthost-3cont_2comp-ipv4-geneve-lvm-octavia/19/

— Additional comment from Elvira on 2023-03-28 16:12:22 UTC —

From the neutron server log at the same time that the deletion fails:

2023-03-14 16:13:39.715 18 ERROR ovsdbapp.backend.ovs_idl.vlog [req-bad5a5c7-d016-4e7a-8f57-2a72d25134d1 - - - - -] attempting to write bad value to column networks (ovsdb error: 0 values when type requires between 1 and 9223372036854775807): ovs.db.error.Error: ovsdb error: 0 values when type requires between 1 and 9223372036854775807

— Additional comment from Elvira on 2023-03-28 16:30:11 UTC —

The core reason behind this seems to be that the ACL is already deleted:

2023-03-14 16:13:06.756 18 ERROR neutron.services.logapi.drivers.manager [req-41c171e0-c844-46ef-b875-130158c33538 24d20c30f3ae41b881ad674e1b74f5f0 b343705e70ef488892122743d656bb9c - default default] Extension driver 'ovn' failed in delete_log: ovsdbapp.backend.ovs_idl.idlutils.RowNotFound: Cannot find ACL with uuid=673558bb-88cf-4079-99d6-710592c9c941
2023-03-14 16:13:06.756 18 ERROR neutron.services.logapi.drivers.manager Traceback (most recent call last):
2023-03-14 16:13:06.756 18 ERROR neutron.services.logapi.drivers.manager File "/usr/lib/python3.9/site-packages/neutron/services/logapi/drivers/manager.py", line 116, in call
2023-03-14 16:13:06.756 18 ERROR neutron.services.logapi.drivers.manager getattr(driver, method_name)(*args, **kwargs)
2023-03-14 16:13:06.756 18 ERROR neutron.services.logapi.drivers.manager File "/usr/lib/python3.9/site-packages/neutron/services/logapi/drivers/ovn/driver.py", line 395, in delete_log
2023-03-14 16:13:06.756 18 ERROR neutron.services.logapi.drivers.manager ovn_txn.add(self.ovn_nb.meter_del(self.meter_name,
2023-03-14 16:13:06.756 18 ERROR neutron.services.logapi.drivers.manager File "/usr/lib64/python3.9/contextlib.py", line 126, in _exit_
2023-03-14 16:13:06.756 18 ERROR neutron.services.logapi.drivers.manager next(self.gen)
2023-03-14 16:13:06.756 18 ERROR neutron.services.logapi.drivers.manager File "/usr/lib/python3.9/site-packages/neutron/plugins/ml2/drivers/ovn/mech_driver/ovsdb/impl_idl_ovn.py", line 269, in transaction
2023-03-14 16:13:06.756 18 ERROR neutron.services.logapi.drivers.manager yield t
2023-03-14 16:13:06.756 18 ERROR neutron.services.logapi.drivers.manager File "/usr/lib64/python3.9/contextlib.py", line 126, in _exit_
2023-03-14 16:13:06.756 18 ERROR neutron.services.logapi.drivers.manager next(self.gen)
2023-03-14 16:13:06.756 18 ERROR neutron.services.logapi.drivers.manager File "/usr/lib/python3.9/site-packages/ovsdbapp/api.py", line 110, in transaction
2023-03-14 16:13:06.756 18 ERROR neutron.services.logapi.drivers.manager del self._nested_txns_map[cur_thread_id]
2023-03-14 16:13:06.756 18 ERROR neutron.services.logapi.drivers.manager File "/usr/lib/python3.9/site-packages/ovsdbapp/api.py", line 61, in _exit_
2023-03-14 16:13:06.756 18 ERROR neutron.services.logapi.drivers.manager self.result = self.commit()
2023-03-14 16:13:06.756 18 ERROR neutron.services.logapi.drivers.manager File "/usr/lib/python3.9/site-packages/ovsdbapp/backend/ovs_idl/transaction.py", line 64, in commit
2023-03-14 16:13:06.756 18 ERROR neutron.services.logapi.drivers.manager raise result.ex
2023-03-14 16:13:06.756 18 ERROR neutron.services.logapi.drivers.manager File "/usr/lib/python3.9/site-packages/ovsdbapp/backend/ovs_idl/connection.py", line 118, in run
2023-03-14 16:13:06.756 18 ERROR neutron.services.logapi.drivers.manager txn.results.put(txn.do_commit())
2023-03-14 16:13:06.756 18 ERROR neutron.services.logapi.drivers.manager File "/usr/lib/python3.9/site-packages/ovsdbapp/backend/ovs_idl/transaction.py", line 92, in do_commit
2023-03-14 16:13:06.756 18 ERROR neutron.services.logapi.drivers.manager command.run_idl(txn)
2023-03-14 16:13:06.756 18 ERROR neutron.services.logapi.drivers.manager File "/usr/lib/python3.9/site-packages/ovsdbapp/backend/ovs_idl/command.py", line 344, in run_idl
2023-03-14 16:13:06.756 18 ERROR neutron.services.logapi.drivers.manager record = self.api.lookup(self.table, self.record)
2023-03-14 16:13:06.756 18 ERROR neutron.services.logapi.drivers.manager File "/usr/lib/python3.9/site-packages/ovsdbapp/backend/ovs_idl/_init_.py", line 208, in lookup
2023-03-14 16:13:06.756 18 ERROR neutron.services.logapi.drivers.manager return self._lookup(table, record)
2023-03-14 16:13:06.756 18 ERROR neutron.services.logapi.drivers.manager File "/usr/lib/python3.9/site-packages/ovsdbapp/backend/ovs_idl/_init_.py", line 240, in _lookup
2023-03-14 16:13:06.756 18 ERROR neutron.services.logapi.drivers.manager raise idlutils.RowNotFound(table=table, col='uuid',
2023-03-14 16:13:06.756 18 ERROR neutron.services.logapi.drivers.manager ovsdbapp.backend.ovs_idl.idlutils.RowNotFound: Cannot find ACL with uuid=673558bb-88cf-4079-99d6-710592c9c941

I'm currently thinking on a way to fix this.

— Additional comment from RHEL Program Management on 2023-03-28 16:30:19 UTC —

This item has been properly Triaged and planned for the release, and Target Release is now set to match the release flag.