nova-compute: instance created in self-referencing secgroup produces KeyError

[Brano Zarnovican]

Hi,

Steps to reproduce:

1) create a security group that is referencing itself, for example
euca-create-group test2
euca-authorize test2 -P tcp -p 22 -s 0.0.0.0/0
euca-authorize test2 -P tcp -p 6666 -o test2

2) create any instance in this security group

euca-run-instance .. -g test2 ..

Expected result:
no stackstrace to be thrown
Actual result:
stacktrace with KeyError appears in the log. The iptable rules are created correctly and instance ends up in running state.

File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 390, in refresh_instance_security_rules
  return self.driver.refresh_instance_security_rules(instance)
File "/usr/lib/python2.6/site-packages/nova/virt/libvirt/driver.py", line 2269, in refresh_instance_security_rules
  self.firewall_driver.refresh_instance_security_rules(instance)
File "/usr/lib/python2.6/site-packages/nova/virt/firewall.py", line 440, in refresh_instance_security_rules
  self.do_refresh_instance_rules(instance)
File "/usr/lib/python2.6/site-packages/nova/virt/firewall.py", line 457, in do_refresh_instance_rules
  network_info = self.network_infos[instance['id']]
KeyError: 4168

It seems that self.network_infos is accessed in wrong order for the security group that is referencing itself. The stacktrace is from 'do_refresh_instance_rules' which expects network info to be already present for the instance that is being created. Reported KeyError is the id of newly created instance. The dictionary entry is added few seconds later processing the same request.

Fortunately, this issue does not appear to have any negative impact aside the stacktrace in the log.

Openstack version: Folsom 2012.2.4

Attaching verbose log from nova-compute.

Regards,

Brano Zarnovican

[Avinash Prasad (avinash-prasad)]

I am not able to re-produce the stack-trace on stable/grizzly at all. It works correctly for me.
I ran the following,

euca-add-group test3 -d test3
GROUP test3 test3

euca-authorize test3 -P tcp -p 22 -s 0.0.0.0/0
GROUP test3
PERMISSION test3 ALLOWS tcp 22 22 FROM CIDR 0.0.0.0/0

euca-authorize test3 -P tcp -p 6666 -o test3
GROUP test3
PERMISSION test3 ALLOWS tcp 6666 6666 GRPNAME test3 FROM CIDR 0.0.0.0/0

euca-run-instances <image_id> -g test3
gives all teh relevant information about the instance and its status

[Brano Zarnovican (zarnovican)]

Unfortunately, I'm not able to test it on Grizzly. I'm able to reproduce it consistently also on Folsom build from EPEL.

# rpm -qi openstack-nova
Name : openstack-nova Relocations: (not relocatable)
Version : 2012.2.3 Vendor: Fedora Project
Release : 1.el6 Build Date: Mon 04 Feb 2013 03:00:18 PM CET
Install Date: Thu 23 May 2013 09:23:27 AM CEST Build Host: ppc12.phx2.fedoraproject.org
Group : Applications/System Source RPM: openstack-nova-2012.2.3-1.el6.src.rpm
...

[Adin Scannell (amscanne)]

I am also seeing this bug (or something very similar) on Grizzly:

2013-05-28 07:58:33.969 ERROR nova.openstack.common.rpc.amqp [req-8d5edb8b-ba0c-4552-9e8b-e6ec47f2fa75 e5195d7000ab4f55a1b542d311a59506 5dc6d827aeef43c4b5165e3e045e42c2] Exception during message handling
2013-05-28 07:58:33.969 27617 TRACE nova.openstack.common.rpc.amqp Traceback (most recent call last):
2013-05-28 07:58:33.969 27617 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.7/dist-packages/nova/openstack/common/rpc/amqp.py", line 430, in _process_data
2013-05-28 07:58:33.969 27617 TRACE nova.openstack.common.rpc.amqp rval = self.proxy.dispatch(ctxt, version, method, **args)
2013-05-28 07:58:33.969 27617 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.7/dist-packages/nova/openstack/common/rpc/dispatcher.py", line 133, in dispatch
2013-05-28 07:58:33.969 27617 TRACE nova.openstack.common.rpc.amqp return getattr(proxyobj, method)(ctxt, **kwargs)
2013-05-28 07:58:33.969 27617 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.7/dist-packages/nova/exception.py", line 117, in wrapped
2013-05-28 07:58:33.969 27617 TRACE nova.openstack.common.rpc.amqp temp_level, payload)
2013-05-28 07:58:33.969 27617 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2013-05-28 07:58:33.969 27617 TRACE nova.openstack.common.rpc.amqp self.gen.next()
2013-05-28 07:58:33.969 27617 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.7/dist-packages/nova/exception.py", line 94, in wrapped
2013-05-28 07:58:33.969 27617 TRACE nova.openstack.common.rpc.amqp return f(self, context, *args, **kw)
2013-05-28 07:58:33.969 27617 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 657, in refresh_instance_security_rules
2013-05-28 07:58:33.969 27617 TRACE nova.openstack.common.rpc.amqp return _sync_refresh()
2013-05-28 07:58:33.969 27617 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.7/dist-packages/nova/openstack/common/lockutils.py", line 242, in inner
2013-05-28 07:58:33.969 27617 TRACE nova.openstack.common.rpc.amqp retval = f(*args, **kwargs)
2013-05-28 07:58:33.969 27617 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 656, in _sync_refresh
2013-05-28 07:58:33.969 27617 TRACE nova.openstack.common.rpc.amqp return self.driver.refresh_instance_security_rules(instance)
2013-05-28 07:58:33.969 27617 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py", line 2778, in refresh_instance_security_rules
2013-05-28 07:58:33.969 27617 TRACE nova.openstack.common.rpc.amqp self.firewall_driver.refresh_instance_security_rules(instance)
2013-05-28 07:58:33.969 27617 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.7/dist-packages/nova/virt/firewall.py", line 453, in refresh_instance_security_rules
2013-05-28 07:58:33.969 27617 TRACE nova.openstack.common.rpc.amqp self.do_refresh_instance_rules(instance)
2013-05-28 07:58:33.969 27617 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/...

[Matt Riedemann (mriedem)]

I see it right here in a stable/icehouse nova-network jenkins run:

http://logs.openstack.org/69/100469/1/check/check-tempest-dsvm-postgres-full/ed1c6cc/logs/screen-n-cpu.txt.gz?level=TRACE#_2014-06-17_11_06_07_182

It actually shows up quite a bit:

http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOlwiZG9fcmVmcmVzaF9zZWN1cml0eV9ncm91cF9ydWxlc1wiIEFORCBtZXNzYWdlOlwiS2V5RXJyb3JcIiBBTkQgdGFnczpcInNjcmVlbi1uLWNwdS50eHRcIiIsImZpZWxkcyI6W10sIm9mZnNldCI6MCwidGltZWZyYW1lIjoiNjA0ODAwIiwiZ3JhcGhtb2RlIjoiY291bnQiLCJ0aW1lIjp7InVzZXJfaW50ZXJ2YWwiOjB9LCJzdGFtcCI6MTQwMzAxMzk4MzY2M30=

[Matt Riedemann (mriedem)]

As pointed out in the bug description, this doesn't appear to cause issues. The logstash query proves that, there is still a 94% success rate on the job when this shows up.

[Matt Riedemann (mriedem)]

Patch is here: https://review.openstack.org/#/c/104325/

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/icehouse
Review: https://review.openstack.org/104335

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/104325
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=72dd81343e73baf838bc58d413413f0d57018f15
Submitter: Jenkins
Branch: master

commit 72dd81343e73baf838bc58d413413f0d57018f15
Author: Dan Smith <email address hidden>
Date: Wed Jul 2 12:44:48 2014 -0700

    Avoid referencing stale instance/network_info dicts in firewall

    This makes the virt.firewall code cleaner in terms of referencing
    the cached instance and network_info code it stores. Before this
    patch, concurrent instance operations could modify these two dicts
    so that while we're iterating instances, the network_info dict
    is suddenly missing information we need.

    The right fix for this is to use instance objects and their
    associated info_cache objects, but that's a larger fix and one
    not as well-suited to backporting to previous releases which
    suffer from this as well.

    The approach taken here is that we store the instance and
    network_info cache together in the same dict that we can pop()
    from atomically (this is not really necessary, but helps to
    prevent introducing more of these cases). When we iterate over
    the contents, we iterate over a copy of the keys, being careful
    not to let a suddenly-missing key break us, and passing the
    details all the way down the stack instead of having deeper calls
    hit the cache dicts again.

    Change-Id: I33366f50024a82451842d045b830ab19b59879c3
    Closes-bug: #1182131

[Sean Dague (sdague)]

I think this bug is fixed, however the underlying races in firewall manip seem to still be there.

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.openstack.org/104581

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/104581
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=6aa368b99249d01f8fd7183c15d11986ad6a6fb7
Submitter: Jenkins
Branch: master

commit 6aa368b99249d01f8fd7183c15d11986ad6a6fb7
Author: Dan Smith <email address hidden>
Date: Thu Jul 3 08:09:39 2014 -0700

    Avoid re-adding iptables rules for instances that have disappeared

    The remove_filters_for_instance() method fails silently if the
    instance's chain is gone (i.e. it's been deleted). If this
    happens while we're refreshing security group rules, we will
    not notice this case and re-add stale rules for an old instance,
    breaking our firewall for new instances.

    This adds a quick check after we've captured the lock to see if
    the associated chain exists, and bails if it doesn't.

    Change-Id: Ic75988939f82de49735d85fe99a9eecd4baf45c9
    Related-bug: #1182131

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: stable/icehouse
Review: https://review.openstack.org/106792

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/104335
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=9f5d2a6a65edb2a5862c7f07b29ac700cec61f84
Submitter: Jenkins
Branch: stable/icehouse

commit 9f5d2a6a65edb2a5862c7f07b29ac700cec61f84
Author: Dan Smith <email address hidden>
Date: Wed Jul 2 12:44:48 2014 -0700

    Avoid referencing stale instance/network_info dicts in firewall

    This makes the virt.firewall code cleaner in terms of referencing
    the cached instance and network_info code it stores. Before this
    patch, concurrent instance operations could modify these two dicts
    so that while we're iterating instances, the network_info dict
    is suddenly missing information we need.

    The right fix for this is to use instance objects and their
    associated info_cache objects, but that's a larger fix and one
    not as well-suited to backporting to previous releases which
    suffer from this as well.

    The approach taken here is that we store the instance and
    network_info cache together in the same dict that we can pop()
    from atomically (this is not really necessary, but helps to
    prevent introducing more of these cases). When we iterate over
    the contents, we iterate over a copy of the keys, being careful
    not to let a suddenly-missing key break us, and passing the
    details all the way down the stack instead of having deeper calls
    hit the cache dicts again.

    Conflicts:
     nova/virt/firewall.py

    Change-Id: Ib1cfd68fca7789ca4a3602c25e6b8a956303fff9
    Closes-bug: #1182131
    (cherry picked from commit 72dd81343e73baf838bc58d413413f0d57018f15)

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/106792
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=132d5a2064cfdc579a2e51f07e10e8eafbdf6327
Submitter: Jenkins
Branch: stable/icehouse

commit 132d5a2064cfdc579a2e51f07e10e8eafbdf6327
Author: Dan Smith <email address hidden>
Date: Thu Jul 3 08:09:39 2014 -0700

    Avoid re-adding iptables rules for instances that have disappeared

    The remove_filters_for_instance() method fails silently if the
    instance's chain is gone (i.e. it's been deleted). If this
    happens while we're refreshing security group rules, we will
    not notice this case and re-add stale rules for an old instance,
    breaking our firewall for new instances.

    This adds a quick check after we've captured the lock to see if
    the associated chain exists, and bails if it doesn't.

    Change-Id: Ic75988939f82de49735d85fe99a9eecd4baf45c9
    Related-bug: #1182131
    (cherry picked from commit 6aa368b99249d01f8fd7183c15d11986ad6a6fb7)

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/havana
Review: https://review.openstack.org/115267

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: stable/havana
Review: https://review.openstack.org/115268

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/115268
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=d469733e59872a897737db6ed5fd92d57986aee4
Submitter: Jenkins
Branch: stable/havana

commit d469733e59872a897737db6ed5fd92d57986aee4
Author: Dan Smith <email address hidden>
Date: Thu Jul 3 08:09:39 2014 -0700

    Avoid re-adding iptables rules for instances that have disappeared

    The remove_filters_for_instance() method fails silently if the
    instance's chain is gone (i.e. it's been deleted). If this
    happens while we're refreshing security group rules, we will
    not notice this case and re-add stale rules for an old instance,
    breaking our firewall for new instances.

    This adds a quick check after we've captured the lock to see if
    the associated chain exists, and bails if it doesn't.

    Conflicts:
     nova/virt/firewall.py

    Required changes:
    - unit test was updated because in Havana, IptablesFirewallDriver has
      .instances instead of .instance_infos, and a separate .network_infos
      attribute.

    Change-Id: Ic75988939f82de49735d85fe99a9eecd4baf45c9
    Related-bug: #1182131
    (cherry picked from commit 6aa368b99249d01f8fd7183c15d11986ad6a6fb7)
    (cherry picked from commit 132d5a2064cfdc579a2e51f07e10e8eafbdf6327)

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/115267
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=8e2d6963cafcead0fe61673ece354f646de0f630
Submitter: Jenkins
Branch: stable/havana

commit 8e2d6963cafcead0fe61673ece354f646de0f630
Author: Dan Smith <email address hidden>
Date: Wed Jul 2 12:44:48 2014 -0700

    Avoid referencing stale instance/network_info dicts in firewall

    This makes the virt.firewall code cleaner in terms of referencing
    the cached instance and network_info code it stores. Before this
    patch, concurrent instance operations could modify these two dicts
    so that while we're iterating instances, the network_info dict
    is suddenly missing information we need.

    The right fix for this is to use instance objects and their
    associated info_cache objects, but that's a larger fix and one
    not as well-suited to backporting to previous releases which
    suffer from this as well.

    The approach taken here is that we store the instance and
    network_info cache together in the same dict that we can pop()
    from atomically (this is not really necessary, but helps to
    prevent introducing more of these cases). When we iterate over
    the contents, we iterate over a copy of the keys, being careful
    not to let a suddenly-missing key break us, and passing the
    details all the way down the stack instead of having deeper calls
    hit the cache dicts again.

    Conflicts:
     nova/virt/firewall.py

    Change-Id: Ib1cfd68fca7789ca4a3602c25e6b8a956303fff9
    Closes-bug: #1182131
    (cherry picked from commit 72dd81343e73baf838bc58d413413f0d57018f15)
    (cherry picked from commit 9f5d2a6a65edb2a5862c7f07b29ac700cec61f84)