** Changed in: neutron
Status: New => Fix Released
--
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to neutron.
https://bugs.launchpad.net/bugs/2080072
Title:
Failed to delete vpnaas ipsec-site-connections with 502 error, ORM
session: SQL execution without transaction in progress
Status in neutron:
Fix Released
Bug description:
This was triggered in gate here:
https://storage.gra.cloud.ovh.net/v1/AUTH_dcaab5e32b234d56b626f72581e3644c/zuul_opendev_logs_5e9/928461/4/check/neutron-
tempest-plugin-vpnaas/5e965fe/testr_results.html
The test traceback:
ft1.1: tearDownClass
(neutron_tempest_plugin.vpnaas.scenario.test_vpnaas.Vpnaas6in6)testtools.testresult.real._StringException:
Traceback (most recent call last):
File "/opt/stack/tempest/tempest/test.py", line 246, in tearDownClass
raise value.with_traceback(trace)
File "/opt/stack/tempest/tempest/test.py", line 210, in tearDownClass
teardown()
File
"/opt/stack/tempest/.tox/tempest/lib/python3.10/site-packages/neutron_tempest_plugin/vpnaas/api/base_vpnaas.py",
line 51, in resource_cleanup
cls._try_delete_resource(
File
"/opt/stack/tempest/.tox/tempest/lib/python3.10/site-packages/neutron_tempest_plugin/api/base.py",
line 332, in _try_delete_resource
delete_callable(*args, **kwargs)
File
"/opt/stack/tempest/.tox/tempest/lib/python3.10/site-packages/neutron_tempest_plugin/services/network/json/network_client.py",
line 112, in _delete
resp, body = self.delete(uri)
File "/opt/stack/tempest/tempest/lib/common/rest_client.py", line 359, in
delete
return self.request('DELETE', url, extra_headers, headers, body)
File "/opt/stack/tempest/tempest/lib/common/rest_client.py", line 762, in
request
self._error_checker(resp, resp_body)
File "/opt/stack/tempest/tempest/lib/common/rest_client.py", line 856, in
_error_checker
raise exceptions.UnexpectedContentType(str(resp.status),
tempest.lib.exceptions.UnexpectedContentType: Unexpected content type provided
Details: 502
The request is:
2024-09-09 16:55:44.459 89493 INFO tempest.lib.common.rest_client [-] Request
(Vpnaas6in6:tearDownClass): 502 DELETE
https://10.209.0.221/networking/v2.0/vpn/ipsec-site-connections/f5ce2f15-6b6d-4323-8c79-efeab2c06ad6
300.098s
2024-09-09 16:55:44.460 89493 DEBUG tempest.lib.common.rest_client [-]
Request - Headers: {'Content-Type': 'application/json', 'Accept':
'application/json', 'X-Auth-Token': '<omitted>'}
Body: None
Response - Headers: {'date': 'Mon, 09 Sep 2024 16:50:44 GMT', 'server':
'Apache/2.4.52 (Ubuntu)', 'content-length': '420', 'connection': 'close',
'content-type': 'text/html; charset=iso-8859-1', 'status': '502',
'content-location':
'https://10.209.0.221/networking/v2.0/vpn/ipsec-site-connections/f5ce2f15-6b6d-4323-8c79-efeab2c06ad6'}
Body: b'<!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML
2.0//EN">\n<html><head>\n<title>502 Proxy
Error</title>\n</head><body>\n<h1>Proxy Error</h1>\n<p>The proxy server
received an invalid\r\nresponse from an upstream server.<br />\r\nThe proxy
server could not handle the request<p>Reason: <strong>Error reading from remote
server</strong></p></p>\n<hr>\n<address>Apache/2.4.52 (Ubuntu) Server at
10.209.0.221 Port 443</address>\n</body></html>\n' _log_request_full
/opt/stack/tempest/tempest/lib/common/rest_client.py:484
neutron log is filled with these for the duration of the (eventually
failed) request - 5mins:
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
WARNING neutron.objects.base [None req-a3a367f8-aeb8-4767-a96b-69b1c05a6a38
tempest-Vpnaas6in6-389378637 tempest-Vpnaas6in6-389378637-project-member] ORM
session: SQL execution without transaction in progress, traceback:
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
File "/opt/stack/data/venv/lib/python3.10/site-packages/paste/urlmap.py", line
211, in __call__
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
return app(environ, start_response)
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line
129, in __call__
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
resp = self.call_func(req, *args, **kw)
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line
193, in call_func
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
return self.func(req, *args, **kwargs)
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
File
"/opt/stack/data/venv/lib/python3.10/site-packages/oslo_middleware/base.py",
line 124, in __call__
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
response = req.get_response(self.application)
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/request.py", line
1313, in send
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
status, headers, app_iter = self.call_application(
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/request.py", line
1278, in call_application
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
app_iter = application(self.environ, start_response)
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line
129, in __call__
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
resp = self.call_func(req, *args, **kw)
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line
193, in call_func
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
return self.func(req, *args, **kwargs)
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
File
"/opt/stack/data/venv/lib/python3.10/site-packages/oslo_middleware/base.py",
line 124, in __call__
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
response = req.get_response(self.application)
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/request.py", line
1313, in send
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
status, headers, app_iter = self.call_application(
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/request.py", line
1278, in call_application
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
app_iter = application(self.environ, start_response)
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line
129, in __call__
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
resp = self.call_func(req, *args, **kw)
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line
193, in call_func
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
return self.func(req, *args, **kwargs)
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
File
"/opt/stack/data/venv/lib/python3.10/site-packages/oslo_middleware/request_id.py",
line 58, in __call__
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
response = req.get_response(self.application)
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/request.py", line
1313, in send
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
status, headers, app_iter = self.call_application(
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/request.py", line
1278, in call_application
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
app_iter = application(self.environ, start_response)
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line
129, in __call__
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
resp = self.call_func(req, *args, **kw)
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line
193, in call_func
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
return self.func(req, *args, **kwargs)
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
File
"/opt/stack/data/venv/lib/python3.10/site-packages/oslo_middleware/catch_errors.py",
line 40, in __call__
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
response = req.get_response(self.application)
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/request.py", line
1313, in send
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
status, headers, app_iter = self.call_application(
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/request.py", line
1278, in call_application
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
app_iter = application(self.environ, start_response)
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line
129, in __call__
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
resp = self.call_func(req, *args, **kw)
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line
193, in call_func
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
return self.func(req, *args, **kwargs)
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
File "/opt/stack/data/venv/lib/python3.10/site-packages/osprofiler/web.py",
line 111, in __call__
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
return request.get_response(self.application)
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/request.py", line
1313, in send
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
status, headers, app_iter = self.call_application(
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/request.py", line
1278, in call_application
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
app_iter = application(self.environ, start_response)
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line
129, in __call__
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
resp = self.call_func(req, *args, **kw)
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line
193, in call_func
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
return self.func(req, *args, **kwargs)
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
File
"/opt/stack/data/venv/lib/python3.10/site-packages/keystonemiddleware/auth_token/__init__.py",
line 340, in __call__
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
response = req.get_response(self._app)
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/request.py", line
1313, in send
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
status, headers, app_iter = self.call_application(
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/request.py", line
1278, in call_application
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
app_iter = application(self.environ, start_response)
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line
143, in __call__
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
return resp(environ, start_response)
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line
143, in __call__
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
return resp(environ, start_response)
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
File "/opt/stack/data/venv/lib/python3.10/site-packages/routes/middleware.py",
line 153, in __call__
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
response = self.app(environ, start_response)
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line
143, in __call__
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
return resp(environ, start_response)
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line
129, in __call__
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
resp = self.call_func(req, *args, **kw)
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line
193, in call_func
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
return self.func(req, *args, **kwargs)
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
File "/opt/stack/neutron/neutron/api/v2/resource.py", line 97, in resource
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
result = method(request=request, **args)
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
File "/opt/stack/neutron/neutron/api/v2/base.py", line 578, in delete
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
return self._delete(request, id, **kwargs)
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
File "/opt/stack/data/venv/lib/python3.10/site-packages/neutron_lib/db/api.py",
line 135, in wrapped
Sep 09 16:50:44.375166 np0038439257 [email protected][60639]:
return f(*args, **kwargs)
Sep 09 16:50:44.381363 np0038439257 [email protected][60639]:
File "/opt/stack/data/venv/lib/python3.10/site-packages/oslo_db/api.py", line
142, in wrapper
Sep 09 16:50:44.381363 np0038439257 [email protected][60639]:
return f(*args, **kwargs)
Sep 09 16:50:44.381363 np0038439257 [email protected][60639]:
File "/opt/stack/data/venv/lib/python3.10/site-packages/neutron_lib/db/api.py",
line 181, in wrapped
Sep 09 16:50:44.381363 np0038439257 [email protected][60639]:
return f(*dup_args, **dup_kwargs)
Sep 09 16:50:44.381363 np0038439257 [email protected][60639]:
File "/opt/stack/neutron/neutron/api/v2/base.py", line 587, in _delete
Sep 09 16:50:44.381363 np0038439257 [email protected][60639]:
obj = self._item(request, id, parent_id=parent_id)
Sep 09 16:50:44.381363 np0038439257 [email protected][60639]:
File "/opt/stack/neutron/neutron/api/v2/base.py", line 353, in _item
Sep 09 16:50:44.381363 np0038439257 [email protected][60639]:
obj = obj_getter(request.context, id, **kwargs)
Sep 09 16:50:44.381363 np0038439257 [email protected][60639]:
File "/opt/stack/neutron-vpnaas/neutron_vpnaas/db/vpn/vpn_db.py", line 268, in
get_ipsec_site_connection
Sep 09 16:50:44.381363 np0038439257 [email protected][60639]:
ipsec_site_conn_db = self._get_ipsec_site_connection(
Sep 09 16:50:44.381363 np0038439257 [email protected][60639]:
File "/opt/stack/neutron-vpnaas/neutron_vpnaas/db/vpn/vpn_db.py", line 263, in
_get_ipsec_site_connection
Sep 09 16:50:44.381363 np0038439257 [email protected][60639]:
return self._get_resource(
Sep 09 16:50:44.381363 np0038439257 [email protected][60639]:
File "/opt/stack/neutron-vpnaas/neutron_vpnaas/db/vpn/vpn_db.py", line 68, in
_get_resource
Sep 09 16:50:44.381363 np0038439257 [email protected][60639]:
r = model_query.get_by_id(context, model, v_id)
Sep 09 16:50:44.381363 np0038439257 [email protected][60639]:
File
"/opt/stack/data/venv/lib/python3.10/site-packages/neutron_lib/db/model_query.py",
line 211, in get_by_id
Sep 09 16:50:44.381363 np0038439257 [email protected][60639]:
return query.filter(model.id == object_id).one()
Sep 09 16:50:44.381363 np0038439257 [email protected][60639]:
File
"/opt/stack/data/venv/lib/python3.10/site-packages/sqlalchemy/orm/query.py",
line 2778, in one
Sep 09 16:50:44.381363 np0038439257 [email protected][60639]:
return self._iter().one() # type: ignore
Sep 09 16:50:44.381363 np0038439257 [email protected][60639]:
File
"/opt/stack/data/venv/lib/python3.10/site-packages/sqlalchemy/orm/query.py",
line 2827, in _iter
Sep 09 16:50:44.381363 np0038439257 [email protected][60639]:
result: Union[ScalarResult[_T], Result[_T]] = self.session.execute(
Sep 09 16:50:44.381363 np0038439257 [email protected][60639]:
File
"/opt/stack/data/venv/lib/python3.10/site-packages/sqlalchemy/orm/session.py",
line 2362, in execute
Sep 09 16:50:44.381363 np0038439257 [email protected][60639]:
return self._execute_internal(
Sep 09 16:50:44.381363 np0038439257 [email protected][60639]:
File
"/opt/stack/data/venv/lib/python3.10/site-packages/sqlalchemy/orm/session.py",
line 2207, in _execute_internal
Sep 09 16:50:44.381363 np0038439257 [email protected][60639]:
fn_result: Optional[Result[Any]] = fn(orm_exec_state)
Sep 09 16:50:44.381363 np0038439257 [email protected][60639]:
Sep 09 16:50:54.387442 np0038439257 [email protected][60639]:
DEBUG dbcounter [-] [60639] Writing DB stats
neutron:SELECT=609,neutron:DELETE=36,neutron:UPDATE=8 {{(pid=60639) stat_writer
/opt/stack/data/venv/lib/python3.10/site-packages/dbcounter.py:115}}
Sep 09 16:51:27.918858 np0038439257 [email protected][60639]:
DEBUG dbcounter [-] [60639] Writing DB stats neutron:SELECT=25 {{(pid=60639)
stat_writer /opt/stack/data/venv/lib/python3.10/site-packages/dbcounter.py:115}}
Sep 09 16:51:34.397983 np0038439257 [email protected][60639]:
DEBUG neutron_lib.db.api [None req-a3a367f8-aeb8-4767-a96b-69b1c05a6a38
tempest-Vpnaas6in6-389378637 tempest-Vpnaas6in6-389378637-project-member] Retry
wrapper got retriable exception: (pymysql.err.OperationalError) (1205, 'Lock
wait timeout exceeded; try restarting transaction')
Sep 09 16:51:34.397983 np0038439257 [email protected][60639]:
[SQL: DELETE FROM ipsec_site_connections WHERE ipsec_site_connections.id =
%(id)s]
Sep 09 16:51:34.397983 np0038439257 [email protected][60639]:
[parameters: {'id': 'f5ce2f15-6b6d-4323-8c79-efeab2c06ad6'}]
Sep 09 16:51:34.397983 np0038439257 [email protected][60639]:
(Background on this error at: https://sqlalche.me/e/20/e3q8) {{(pid=60639)
wrapped
/opt/stack/data/venv/lib/python3.10/site-packages/neutron_lib/db/api.py:185}}
Sep 09 16:51:34.398761 np0038439257 [email protected][60639]:
DEBUG oslo_db.api [None req-a3a367f8-aeb8-4767-a96b-69b1c05a6a38
tempest-Vpnaas6in6-389378637 tempest-Vpnaas6in6-389378637-project-member]
Performing DB retry for function neutron.api.v2.base.Controller._delete
{{(pid=60639) wrapper
/opt/stack/data/venv/lib/python3.10/site-packages/oslo_db/api.py:155}}
Looks like a programming error somewhere in re: transaction handling
for sqlalchemy.
To manage notifications about this bug go to:
https://bugs.launchpad.net/neutron/+bug/2080072/+subscriptions
--
Mailing list: https://launchpad.net/~yahoo-eng-team
Post to : [email protected]
Unsubscribe : https://launchpad.net/~yahoo-eng-team
More help : https://help.launchpad.net/ListHelp
