Public bug reported:

In kilo or icehouse release: 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']

** Affects: neutron
     Importance: Undecided
         Status: New


** Tags: l3 sg-fw

** Description changed:

- multiple deletes in firewall tempest case:
+ In kilo or icehouse release: 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)
- 
+     ...
+     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']

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to neutron.
https://bugs.launchpad.net/bugs/1488771

Title:
  multiple deletes in firewall tempest case:
  "test_create_show_delete_firewall" cause l3-agent throws unexpected
  exception: "FirewallNotFound".

Status in neutron:
  New

Bug description:
  In kilo or icehouse release: 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']

To manage notifications about this bug go to:
https://bugs.launchpad.net/neutron/+bug/1488771/+subscriptions

-- 
Mailing list: https://launchpad.net/~yahoo-eng-team
Post to     : yahoo-eng-team@lists.launchpad.net
Unsubscribe : https://launchpad.net/~yahoo-eng-team
More help   : https://help.launchpad.net/ListHelp

Reply via email to