multiple deletes in firewall tempest case: "test_create_show_delete_firewall" cause l3-agent throws unexpected exception: "FirewallNotFound".
I am running tempest against kilo release, after running the neutron case: "test_create_show_delete_firewall", my l3-agent reports the following errors and exceptions:
In this tempest case:
I found delete firewall will be called twice, the second delete_firewall(in the method addCleanup), will be called immediately after the first(self.client.delete_firewall).
This looks like an async call locking problem, I don't know if the current log/implementation/behavior is expected or unexpected.
==
Tempest test case in the file: tempest/api/network/test_fwaas_extensions.py:
==
def test_create_show_delete_firewall(self):
...
self.addCleanup(self._try_delete_firewall, firewall_id)
...
self.client.delete_firewall(firewall_id)
==
my l3-agent log:
==
2015-08-25 08:34:00.420 31255 INFO neutron.wsgi [req-9cc36e3b-e209-4d95-bb40-9e1012a89621 ] 10.133.5.167 - - [25/Aug/2015 08:34:00] "DELETE /v2.0/fw/firewalls/2b3102d9-1925-47b3-bca3-a8cd0296cc8c HTTP/1.1" 204 168 0.237354 <- First Delete FW call
...
2015-08-25 08:34:00.725 31255 INFO neutron.wsgi [req-795bcbcf-5fde-43d6-8a66-5e2b3fdad44f ] 10.133.5.167 - - [25/Aug/2015 08:34:00] "DELETE /v2.0/fw/firewalls/2b3102d9-1925-47b3-bca3-a8cd0296cc8c HTTP/1.1" 204 168 0.299331 <- Second Delete FW call
...
2015-08-25 08:34:01.069 31255 DEBUG neutron_fwaas.db.firewall.firewall_db [req-9cc36e3b-e209-4d95-bb40-9e1012a89621 ] delete_firewall() called delete_firewall /usr/lib/python2.7/site-packages/neutron_fwaas/db/firewall/firewall_db.py:318 <- First Delete FW database operation
...
2015-08-25 08:34:01.098 31255 ERROR oslo_messaging.rpc.dispatcher [req-9cc36e3b-e209-4d95-bb40-9e1012a89621 ] Exception during message handling: Firewall 2b3102d9-1925-47b3-bca3-a8cd0296cc8c could not be found. <-- Second Delete FW throw exception
2015-08-25 08:34:01.098 31255 TRACE oslo_messaging.rpc.dispatcher Traceback (most recent call last):
2015-08-25 08:34:01.098 31255 TRACE oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 142, in _dispatch_and_reply
2015-08-25 08:34:01.098 31255 TRACE oslo_messaging.rpc.dispatcher executor_callback))
2015-08-25 08:34:01.098 31255 TRACE oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 186, in _dispatch
2015-08-25 08:34:01.098 31255 TRACE oslo_messaging.rpc.dispatcher executor_callback)
2015-08-25 08:34:01.098 31255 TRACE oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 130, in _do_dispatch
2015-08-25 08:34:01.098 31255 TRACE oslo_messaging.rpc.dispatcher result = func(ctxt, **new_args)
2015-08-25 08:34:01.098 31255 TRACE oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/neutron_fwaas/services/firewall/fwaas_plugin.py", line 67, in firewall_deleted
2015-08-25 08:34:01.098 31255 TRACE oslo_messaging.rpc.dispatcher fw_db = self.plugin._get_firewall(context, firewall_id)
2015-08-25 08:34:01.098 31255 TRACE oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/neutron_fwaas/db/firewall/firewall_db.py", line 101, in _get_firewall
2015-08-25 08:34:01.098 31255 TRACE oslo_messaging.rpc.dispatcher raise fw_ext.FirewallNotFound(firewall_id=id)
2015-08-25 08:34:01.098 31255 TRACE oslo_messaging.rpc.dispatcher FirewallNotFound: Firewall 2b3102d9-1925-47b3-bca3-a8cd0296cc8c could not be found.
2015-08-25 08:34:01.098 31255 TRACE oslo_messaging.rpc.dispatcher
2015-08-25 08:34:01.098 31255 ERROR oslo_messaging._drivers.common [req-9cc36e3b-e209-4d95-bb40-9e1012a89621 ] Returning exception Firewall 2b3102d9-1925-47b3-bca3-a8cd0296cc8c could not be found. to caller
2015-08-25 08:34:01.099 31255 ERROR oslo_messaging._drivers.common [req-9cc36e3b-e209-4d95-bb40-9e1012a89621 ] ['Traceback (most recent call last):\n', ' File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 142, in _dispatch_and_reply\n executor_callback))\n', ' File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 186, in _dispatch\n executor_callback)\n', ' File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 130, in _do_dispatch\n result = func(ctxt, **new_args)\n', ' File "/usr/lib/python2.7/site-packages/neutron_fwaas/services/firewall/fwaas_plugin.py", line 67, in firewall_deleted\n fw_db = self.plugin._get_firewall(context, firewall_id)\n', ' File "/usr/lib/python2.7/site-packages/neutron_fwaas/db/firewall/firewall_db.py", line 101, in _get_firewall\n raise fw_ext.FirewallNotFound(firewall_id=id)\n', 'FirewallNotFound: Firewall 2b3102d9-1925-47b3-bca3-a8cd0296cc8c could not be found.\n']
multiple deletes in firewall tempest case: "test_create_ show_delete_ firewall" cause l3-agent throws unexpected exception: "FirewallNotFound".
I am running tempest against kilo release, after running the neutron case: "test_create_ show_delete_ firewall" , my l3-agent reports the following errors and exceptions:
In this tempest case: client. delete_ firewall) . ion/behavior is expected or unexpected.
I found delete firewall will be called twice, the second delete_firewall(in the method addCleanup), will be called immediately after the first(self.
This looks like an async call locking problem, I don't know if the current log/implementat
== api/network/ test_fwaas_ extensions. py: show_delete_ firewall( self): addCleanup( self._try_ delete_ firewall, firewall_id) client. delete_ firewall( firewall_ id)
Tempest test case in the file: tempest/
==
def test_create_
...
self.
...
self.
== e209-4d95- bb40-9e1012a896 21 ] 10.133.5.167 - - [25/Aug/2015 08:34:00] "DELETE /v2.0/fw/ firewalls/ 2b3102d9- 1925-47b3- bca3-a8cd0296cc 8c HTTP/1.1" 204 168 0.237354 <- First Delete FW call 5fde-43d6- 8a66-5e2b3fdad4 4f ] 10.133.5.167 - - [25/Aug/2015 08:34:00] "DELETE /v2.0/fw/ firewalls/ 2b3102d9- 1925-47b3- bca3-a8cd0296cc 8c HTTP/1.1" 204 168 0.299331 <- Second Delete FW call fwaas.db. firewall. firewall_ db [req-9cc36e3b- e209-4d95- bb40-9e1012a896 21 ] delete_firewall() called delete_firewall /usr/lib/ python2. 7/site- packages/ neutron_ fwaas/db/ firewall/ firewall_ db.py:318 <- First Delete FW database operation rpc.dispatcher [req-9cc36e3b- e209-4d95- bb40-9e1012a896 21 ] Exception during message handling: Firewall 2b3102d9- 1925-47b3- bca3-a8cd0296cc 8c could not be found. <-- Second Delete FW throw exception rpc.dispatcher Traceback (most recent call last): rpc.dispatcher File "/usr/lib/ python2. 7/site- packages/ oslo_messaging/ rpc/dispatcher. py", line 142, in _dispatch_and_reply rpc.dispatcher executor_callback)) rpc.dispatcher File "/usr/lib/ python2. 7/site- packages/ oslo_messaging/ rpc/dispatcher. py", line 186, in _dispatch rpc.dispatcher executor_callback) rpc.dispatcher File "/usr/lib/ python2. 7/site- packages/ oslo_messaging/ rpc/dispatcher. py", line 130, in _do_dispatch rpc.dispatcher result = func(ctxt, **new_args) rpc.dispatcher File "/usr/lib/ python2. 7/site- packages/ neutron_ fwaas/services/ firewall/ fwaas_plugin. py", line 67, in firewall_deleted rpc.dispatcher fw_db = self.plugin. _get_firewall( context, firewall_id) rpc.dispatcher File "/usr/lib/ python2. 7/site- packages/ neutron_ fwaas/db/ firewall/ firewall_ db.py", line 101, in _get_firewall rpc.dispatcher raise fw_ext. FirewallNotFoun d(firewall_ id=id) rpc.dispatcher FirewallNotFound: Firewall 2b3102d9- 1925-47b3- bca3-a8cd0296cc 8c could not be found. rpc.dispatcher _drivers. common [req-9cc36e3b- e209-4d95- bb40-9e1012a896 21 ] Returning exception Firewall 2b3102d9- 1925-47b3- bca3-a8cd0296cc 8c could not be found. to caller _drivers. common [req-9cc36e3b- e209-4d95- bb40-9e1012a896 21 ] ['Traceback (most recent call last):\n', ' File "/usr/lib/ python2. 7/site- packages/ oslo_messaging/ rpc/dispatcher. py", line 142, in _dispatch_ and_reply\ n executor_ callback) )\n', ' File "/usr/lib/ python2. 7/site- packages/ oslo_messaging/ rpc/dispatcher. py", line 186, in _dispatch\n executor_ callback) \n', ' File "/usr/lib/ python2. 7/site- packages/ oslo_messaging/ rpc/dispatcher. py", line 130, in _do_dispatch\n result = func(ctxt, **new_args)\n', ' File "/usr/lib/ python2. 7/site- packages/ neutron_ fwaas/services/ firewall/ fwaas_plugin. py", line 67, in firewall_deleted\n fw_db = self.plugin. _get_firewall( context, firewall_id)\n', ' File "/usr/lib/ python2. 7/site- packages/ neutron_ fwaas/db/ firewall/ firewall_ db.py", line 101, in _get_firewall\n raise fw_ext. FirewallNotFoun d(firewall_ id=id)\ n', 'FirewallNotFound: Firewall 2b3102d9- 1925-47b3- bca3-a8cd0296cc 8c could not be found.\n']
my l3-agent log:
==
2015-08-25 08:34:00.420 31255 INFO neutron.wsgi [req-9cc36e3b-
...
2015-08-25 08:34:00.725 31255 INFO neutron.wsgi [req-795bcbcf-
...
2015-08-25 08:34:01.069 31255 DEBUG neutron_
...
2015-08-25 08:34:01.098 31255 ERROR oslo_messaging.
2015-08-25 08:34:01.098 31255 TRACE oslo_messaging.
2015-08-25 08:34:01.098 31255 TRACE oslo_messaging.
2015-08-25 08:34:01.098 31255 TRACE oslo_messaging.
2015-08-25 08:34:01.098 31255 TRACE oslo_messaging.
2015-08-25 08:34:01.098 31255 TRACE oslo_messaging.
2015-08-25 08:34:01.098 31255 TRACE oslo_messaging.
2015-08-25 08:34:01.098 31255 TRACE oslo_messaging.
2015-08-25 08:34:01.098 31255 TRACE oslo_messaging.
2015-08-25 08:34:01.098 31255 TRACE oslo_messaging.
2015-08-25 08:34:01.098 31255 TRACE oslo_messaging.
2015-08-25 08:34:01.098 31255 TRACE oslo_messaging.
2015-08-25 08:34:01.098 31255 TRACE oslo_messaging.
2015-08-25 08:34:01.098 31255 TRACE oslo_messaging.
2015-08-25 08:34:01.098 31255 ERROR oslo_messaging.
2015-08-25 08:34:01.099 31255 ERROR oslo_messaging.