I could triage it to non-atomic instance info cache update. It seems heal_instance_info_cache periodic
task runs in parallel with these API calls and due to race condition between these two, the info
cache is getting corrupted.
I put in a debug statement to print stack track for each cache update and in the following failed case you could see that the "_heal_instance_info_cache" periodic task overwrote the info-cache incorrectly and hence corrupted it.
I could triage it to non-atomic instance info cache update. It seems heal_instance_ info_cache periodic
task runs in parallel with these API calls and due to race condition between these two, the info
cache is getting corrupted.
I put in a debug statement to print stack track for each cache update and in the following failed case you could see that the "_heal_ instance_ info_cache" periodic task overwrote the info-cache incorrectly and hence corrupted it.
------ ubuntu- 1204-server: ~/devstack$ grep -A 1 "Updating cache" /opt/stack/ logs/screen/ screen- n-cpu.log | grep -A 4 1aea47a5- 8677-4a68- aec6-74c8573dde 52 base_api [req-8a4531a0- 1b8c-4c2d- 815d-0e126515d4 46 demo demo] Updating cache with info: [VIF({' ovs_interfaceid ': u'9a697bd9- d2fb-4924- 8298-b76c8d1c7c 4f', 'network': Network({'bridge': 'br-int', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': 'fixed', 'floating_ips': [], 'address': u'192.168.1.2'})], 'version': 4, 'meta': {'dhcp_server': u'192.168.1.3'}, 'dns': [], 'routes': [], 'cidr': u'192.168.1.0/24', 'gateway': IP({'meta': {}, 'version': 4, 'type': 'gateway', 'address': u'192.168. 1.1'})} )], 'meta': {'injected': False, 'tenant_id': u'adeb5c20087c4 2ccb7f4561a7d9c ba6e'}, 'id': u'a8159f6d- dc4a-4eab- a6e2-b9d3a626f4 f2', 'label': u'testnet1'}), 'devname': u'tap9a697bd9-d2', 'qbh_params': None, 'meta': {}, 'details': {u'port_filter': True, u'ovs_hybrid_plug': True}, 'address': u'fa:16: 3e:d1:50: 3f', 'active': True, 'type': u'ovs', 'id': u'9a697bd9- d2fb-4924- 8298-b76c8d1c7c 4f', 'qbg_params': None}), VIF({'ovs_ interfaceid' : u'1aea47a5- 8677-4a68- aec6-74c8573dde 52', 'network': Network({'bridge': 'br-int', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': 'fixed', 'floating_ips': [], 'address': u'192.168. 2.143'} )], 'version': 4, 'meta': {'dhcp_server': u'192.168.2.3'}, 'dns': [], 'routes': [], 'cidr': u'192.168.2.0/24', 'gateway': IP({'meta': {}, 'version': 4, 'type': 'gateway', 'address': u'192.168. 2.1'})} )], 'meta': {'injected': False, 'tenant_id': u'adeb5c20087c4 2ccb7f4561a7d9c ba6e'}, 'id': u'1f411a5a- 4664-4383- a44a-9d83bef7c1 ca', 'label': u'testnet2'}), 'devname': u'tap1aea47a5-86', 'qbh_params': None, 'meta': {}, 'details': {u'port_filter': True, u'ovs_hybrid_plug': True}, 'address': u'fa:16: 3e:12:24: fc', 'active': False, 'type': u'ovs', 'id': u'1aea47a5- 8677-4a68- aec6-74c8573dde 52', 'qbg_params': None})] from (pid=5206) update_ instance_ cache_with_ nw_info /opt/stack/ nova/nova/ network/ base_api. py:38 base_api [req-8a4531a0- 1b8c-4c2d- 815d-0e126515d4 46 demo demo] traceback: [('/usr/ local/lib/ python2. 7/dist- packages/ eventlet/ greenthread. py', 194, 'main', 'result = function(*args, **kwargs)'), ('/usr/ local/lib/ python2. 7/dist- packages/ oslo/messaging/ rpc/dispatcher. py', 129, '<lambda>', 'yield lambda: self._dispatch_ and_reply( incoming) '), ('/usr/ local/lib/ python2. 7/dist- packages/ oslo/messaging/ rpc/dispatcher. py', 134, '_dispatch_ and_reply' , 'incoming. message) )'), ('/usr/ local/lib/ python2. 7/dist- packages/ oslo/messaging/ rpc/dispatcher. py', 177, '_dispatch', 'return self._do_ dispatch( endpoint, method, ctxt, args)'), ('/usr/ local/lib/ python2. 7/dist- packages/ oslo/messaging/ rpc/dispatcher. py', 123, '_do_dispatch', 'result = getattr(endpoint, method)(ctxt, **new_args)'), ('/opt/ stack/nova/ nova/compute/ manager. py', 401, 'decorated_ function' , 'return function(self, context, *args, **kwargs)'), ('/opt/ stack/nova/ nova/compute/ manager. py', 4388, 'attach_interface', 'context, instance, port_id, network_id, requested_ip)'), ('/opt/ stack/nova/ nova/network/ neutronv2/ api.py' , 436, 'allocate_ port_for_ instance' , 'requested_ networks= [(network_ id, requested_ip, port_id)])'), ('/opt/ stack/nova/ nova/network/ neutronv2/ api.py' , 360, 'allocate_ for_instance' , 'port_ids= ports_in_ requested_ order)' ), ('/opt/ stack/nova/ nova/network/ neutronv2/ api.py' , 471, 'get_instance_ nw_info' , 'result, update_ cells=False) '), ('/opt/ stack/nova/ nova/network/ base_api. py', 39, 'update_ instance_ cache_with_ nw_info' , "LOG.debug( 'traceback: %s', traceback. extract_ stack() )")] from (pid=5206) update_ instance_ cache_with_ nw_info /opt/stack/ nova/nova/ network/ base_api. py:39 base_api [-] Updating cache with info: [VIF({' ovs_interfaceid ': u'9a697bd9- d2fb-4924- 8298-b76c8d1c7c 4f', 'network': Network({'bridge': 'br-int', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': 'fixed', 'floating_ips': [], 'address': u'192.168.1.2'})], 'version': 4, 'meta': {'dhcp_server': u'192.168.1.3'}, 'dns': [], 'routes': [], 'cidr': u'192.168.1.0/24', 'gateway': IP({'meta': {}, 'version': 4, 'type': 'gateway', 'address': u'192.168. 1.1'})} )], 'meta': {'injected': False, 'tenant_id': u'adeb5c20087c4 2ccb7f4561a7d9c ba6e'}, 'id': u'a8159f6d- dc4a-4eab- a6e2-b9d3a626f4 f2', 'label': u'testnet1'}), 'devname': u'tap9a697bd9-d2', 'qbh_params': None, 'meta': {}, 'details': {u'port_filter': True, u'ovs_hybrid_plug': True}, 'address': u'fa:16: 3e:d1:50: 3f', 'active': True, 'type': u'ovs', 'id': u'9a697bd9- d2fb-4924- 8298-b76c8d1c7c 4f', 'qbg_params': None})] from (pid=5206) update_ instance_ cache_with_ nw_info /opt/stack/ nova/nova/ network/ base_api. py:38 base_api [-] traceback: [('/usr/ local/lib/ python2. 7/dist- packages/ eventlet/ greenthread. py', 194, 'main', 'result = function(*args, **kwargs)'), ('/opt/ stack/nova/ nova/openstack/ common/ loopingcall. py', 123, '_inner', 'idle = self.f(*self.args, **self.kw)'), ('/opt/ stack/nova/ nova/service. py', 304, 'periodic_tasks', 'return self.manager. periodic_ tasks(ctxt, raise_on_ error=raise_ on_error) '), ('/opt/ stack/nova/ nova/manager. py', 81, 'periodic_tasks', 'return self.run_ periodic_ tasks(context, raise_on_ error=raise_ on_error) '), ('/opt/ stack/nova/ nova/openstack/ common/ periodic_ task.py' , 175, 'run_periodic_ tasks', 'task(self, context)'), ('/opt/ stack/nova/ nova/compute/ manager. py', 4910, '_heal_ instance_ info_cache' , 'self._ get_instance_ nw_info( context, instance, use_slave=True)'), ('/opt/ stack/nova/ nova/compute/ manager. py', 1142, '_get_instance_ nw_info' , 'instance)'), ('/opt/ stack/nova/ nova/network/ neutronv2/ api.py' , 471, 'get_instance_ nw_info' , 'result, update_ cells=False) '), ('/opt/ stack/nova/ nova/network/ base_api. py', 39, 'update_ instance_ cache_with_ nw_info' , "LOG.debug( 'traceback: %s', traceback. extract_ stack() )")] from (pid=5206) update_ instance_ cache_with_ nw_info /opt/stack/ nova/nova/ network/ base_api. py:39
aviuser@
2014-06-03 17:13:27.870 DEBUG nova.network.
2014-06-03 17:13:27.871 DEBUG nova.network.
--
2014-06-03 17:13:27.936 DEBUG nova.network.
2014-06-03 17:13:27.937 DEBUG nova.network.