yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1632403] [NEW] InstanceInfoCacheNotFound: Info cache for instance 7e3be027-0303-4ed8-8dfc-5c19a419901c could not be found

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Thomas Bechtold <tbechtold@xxxxxxxx>
Date: Tue, 11 Oct 2016 16:51:00 -0000
Reply-to: Bug 1632403 <1632403@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Public bug reported:

* This is with:
- SUSE SLE 12 SP2
- Nova Mitaka (version 13.1.2.dev68 from the stable-mitaka from tarballs.openstack.org)
- neutron+linuxbridge
- nova libvirt+KVM


When running the tempest scenario tests (ostestr -r '^tempest.scenario') I get:

   Traceback (most recent call last):
      File "/var/lib/openstack-tempest-test/tempest/lib/common/utils/test_utils.py", line 83, in call_and_ignore_notfound_exc
        return func(*args, **kwargs)
      File "/var/lib/openstack-tempest-test/tempest/lib/services/compute/floating_ips_client.py", line 62, in delete_floating_ip
        resp, body = self.delete(url)
      File "/var/lib/openstack-tempest-test/tempest/lib/common/rest_client.py", line 290, in delete
        return self.request('DELETE', url, extra_headers, headers, body)
      File "/var/lib/openstack-tempest-test/tempest/lib/services/compute/base_compute_client.py", line 53, in request
        method, url, extra_headers, headers, body)
      File "/var/lib/openstack-tempest-test/tempest/lib/common/rest_client.py", line 642, in request
        resp, resp_body)
      File "/var/lib/openstack-tempest-test/tempest/lib/common/rest_client.py", line 761, in _error_checker
        message=message)
    ServerFault: Got server fault
    Details: Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.
    <class 'nova.exception.InstanceInfoCacheNotFound'>



/var/log/nova/nova-api.log has:

2016-10-11 15:17:20.074 5348 DEBUG nova.osapi_compute.wsgi.server [req-01ff53e9-04d2-42b7-b511-f5b83721cdfc - - - - -] (5348) accepted ('192.168.251.84', 59010) server /usr/lib/python2.7/site-packages/eventlet/wsgi.py:867
2016-10-11 15:17:20.082 5348 DEBUG nova.api.openstack.wsgi [req-4db29700-8188-4184-a628-5a29733ee2d8 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] Calling method '<bound method ServersController.delete of <nova.api.openstack.compute.servers.ServersController object at 0x7fb3a0dbedd0>>' _process_stack /usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py:699
2016-10-11 15:17:20.082 5348 DEBUG nova.compute.api [req-4db29700-8188-4184-a628-5a29733ee2d8 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c] Fetching instance by UUID get /usr/lib/python2.7/site-packages/nova/compute/api.py:2044
2016-10-11 15:17:20.162 5348 DEBUG nova.compute.api [req-4db29700-8188-4184-a628-5a29733ee2d8 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c] Going to try to terminate instance delete /usr/lib/python2.7/site-packages/nova/compute/api.py:1941
2016-10-11 15:17:20.306 5348 DEBUG nova.quota [req-4db29700-8188-4184-a628-5a29733ee2d8 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] Attempting to reserve resources for project f478dc6f6a274ef4a0e8284e9fb46b22 and user 6d03f6736e16470a9050eb1e24f25a76. Deltas: {'instances': -1, 'ram': -128, 'cores': -1} reserve /usr/lib/python2.7/site-packages/nova/quota.py:550
2016-10-11 15:17:20.318 5348 DEBUG nova.quota [req-4db29700-8188-4184-a628-5a29733ee2d8 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] Quota limits for project f478dc6f6a274ef4a0e8284e9fb46b22: {'project_id': u'f478dc6f6a274ef4a0e8284e9fb46b22'} reserve /usr/lib/python2.7/site-packages/nova/quota.py:559
2016-10-11 15:17:20.318 5348 DEBUG nova.quota [req-4db29700-8188-4184-a628-5a29733ee2d8 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] Getting quotas for project f478dc6f6a274ef4a0e8284e9fb46b22. Resources: ['instances', 'ram', 'cores'] _get_quotas /usr/lib/python2.7/site-packages/nova/quota.py:409
2016-10-11 15:17:20.325 5348 DEBUG nova.quota [req-4db29700-8188-4184-a628-5a29733ee2d8 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] Quotas for project f478dc6f6a274ef4a0e8284e9fb46b22 after resource sync: {'instances': 10, 'ram': 51200, 'cores': 20} reserve /usr/lib/python2.7/site-packages/nova/quota.py:565
2016-10-11 15:17:20.327 5348 DEBUG nova.quota [req-4db29700-8188-4184-a628-5a29733ee2d8 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] Getting quotas for user 6d03f6736e16470a9050eb1e24f25a76 and project f478dc6f6a274ef4a0e8284e9fb46b22. Resources: ['instances', 'ram', 'cores'] _get_quotas /usr/lib/python2.7/site-packages/nova/quota.py:401
2016-10-11 15:17:20.350 5348 DEBUG nova.quota [req-4db29700-8188-4184-a628-5a29733ee2d8 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] Quotas for project f478dc6f6a274ef4a0e8284e9fb46b22 and user 6d03f6736e16470a9050eb1e24f25a76 after resource sync: {'instances': 10, 'ram': 51200, 'cores': 20} reserve /usr/lib/python2.7/site-packages/nova/quota.py:573
2016-10-11 15:17:20.389 5348 DEBUG nova.quota [req-4db29700-8188-4184-a628-5a29733ee2d8 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] Created reservations ['17dab2ab-05c0-4cf8-ac10-cf0f5d6bd8da', '47f11182-e1da-457e-8adf-3e60c6f51bf0', '8d883408-d873-4048-841d-1dec24ccb9d0'] reserve /usr/lib/python2.7/site-packages/nova/quota.py:1345
2016-10-11 15:17:20.412 5346 DEBUG nova.osapi_compute.wsgi.server [req-46918002-2351-4561-916d-3e886840a8b7 - - - - -] (5346) accepted ('192.168.251.84', 59016) server /usr/lib/python2.7/site-packages/eventlet/wsgi.py:867
2016-10-11 15:17:20.415 5348 INFO nova.osapi_compute.wsgi.server [req-4db29700-8188-4184-a628-5a29733ee2d8 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] 192.168.251.84 "DELETE /v2.1/f478dc6f6a274ef4a0e8284e9fb46b22/servers/7e3be027-0303-4ed8-8dfc-5c19a419901c HTTP/1.1" status: 204 len: 269 time: 0.3392730
2016-10-11 15:17:20.419 5346 DEBUG nova.api.openstack.wsgi [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] Calling method '<bound method FloatingIPController.delete of <nova.api.openstack.compute.floating_ips.FloatingIPController object at 0x7fb3a0f8fe50>>' _process_stack /usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py:699
2016-10-11 15:17:20.420 5346 DEBUG keystoneauth.session [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] REQ: curl -g -i -X GET http://d52-54-77-77-77-01.vg2.cloud.suse.de:9696/v2.0/floatingips/097e1998-5316-4416-ab9b-79c4b997ea8f.json -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}228810fa07ce0224199bc54d7ea65f023e8ded81" _http_log_request /usr/lib/python2.7/site-packages/keystoneauth1/session.py:225
2016-10-11 15:17:20.440 5346 DEBUG keystoneauth.session [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] RESP: [200] Date: Tue, 11 Oct 2016 15:17:20 GMT Connection: close Content-Type: application/json; charset=UTF-8 Content-Length: 392 X-Openstack-Request-Id: req-9d8de0fb-f8c3-4aaa-821e-54d98dbf20ad 
RESP BODY: {"floatingip": {"router_id": "113f7e40-b6d4-42c5-a36b-6758e0e0cdcb", "status": "ACTIVE", "description": "", "tenant_id": "f478dc6f6a274ef4a0e8284e9fb46b22", "floating_network_id": "1af37c8a-a196-4e33-92c0-afce4c4031c2", "fixed_ip_address": "10.100.0.3", "floating_ip_address": "10.164.193.169", "port_id": "79b2ea47-4a5e-4c7e-a277-63ba71daf593", "id": "097e1998-5316-4416-ab9b-79c4b997ea8f"}}
 _http_log_response /usr/lib/python2.7/site-packages/keystoneauth1/session.py:254
2016-10-11 15:17:20.441 5346 DEBUG keystoneauth.session [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] REQ: curl -g -i -X GET http://d52-54-77-77-77-01.vg2.cloud.suse.de:9696/v2.0/networks/1af37c8a-a196-4e33-92c0-afce4c4031c2.json -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}228810fa07ce0224199bc54d7ea65f023e8ded81" _http_log_request /usr/lib/python2.7/site-packages/keystoneauth1/session.py:225
2016-10-11 15:17:20.577 5346 DEBUG keystoneauth.session [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] RESP: [200] Date: Tue, 11 Oct 2016 15:17:20 GMT Connection: close Content-Type: application/json; charset=UTF-8 Content-Length: 525 X-Openstack-Request-Id: req-59187583-5c2f-4cc9-8468-c36f57b08440 
RESP BODY: {"network": {"status": "ACTIVE", "router:external": true, "availability_zone_hints": [], "availability_zones": ["nova"], "description": "", "subnets": ["be1635d1-bf5d-4222-a85b-6cbccbb1241b"], "tenant_id": "e0052899ed0c4eecbd330d41ae8d4229", "created_at": "2016-10-11T10:26:14", "tags": [], "updated_at": "2016-10-11T10:26:14", "ipv6_address_scope": null, "is_default": false, "admin_state_up": true, "ipv4_address_scope": null, "shared": false, "mtu": 8900, "id": "1af37c8a-a196-4e33-92c0-afce4c4031c2", "name": "floating"}}
 _http_log_response /usr/lib/python2.7/site-packages/keystoneauth1/session.py:254
2016-10-11 15:17:20.578 5346 DEBUG keystoneauth.session [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] REQ: curl -g -i -X GET http://d52-54-77-77-77-01.vg2.cloud.suse.de:9696/v2.0/ports/79b2ea47-4a5e-4c7e-a277-63ba71daf593.json -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}228810fa07ce0224199bc54d7ea65f023e8ded81" _http_log_request /usr/lib/python2.7/site-packages/keystoneauth1/session.py:225
2016-10-11 15:17:20.616 5346 DEBUG keystoneauth.session [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] RESP: [200] Date: Tue, 11 Oct 2016 15:17:20 GMT Connection: close Content-Type: application/json; charset=UTF-8 Content-Length: 671 X-Openstack-Request-Id: req-6e7ebb68-20e2-4f4b-81a5-df643e70d2ec 
RESP BODY: {"port": {"status": "ACTIVE", "created_at": "2016-10-11T15:17:03", "description": "", "allowed_address_pairs": [], "admin_state_up": true, "network_id": "9f9c6b3c-0085-4b77-8f1f-a38e812d5f70", "tenant_id": "f478dc6f6a274ef4a0e8284e9fb46b22", "extra_dhcp_opts": [], "updated_at": "2016-10-11T15:17:07", "name": "", "device_owner": "compute:None", "mac_address": "fa:16:3e:99:15:e4", "binding:vnic_type": "normal", "fixed_ips": [{"subnet_id": "9600e72d-28a8-4350-b993-907c4e202bcf", "ip_address": "10.100.0.3"}], "id": "79b2ea47-4a5e-4c7e-a277-63ba71daf593", "security_groups": ["c29e2129-6410-493d-afe8-2e329dc90c63"], "device_id": "7e3be027-0303-4ed8-8dfc-5c19a419901c"}}
 _http_log_response /usr/lib/python2.7/site-packages/keystoneauth1/session.py:254
2016-10-11 15:17:20.617 5346 DEBUG keystoneauth.session [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] REQ: curl -g -i -X GET http://d52-54-77-77-77-01.vg2.cloud.suse.de:9696/v2.0/floatingips.json?floating_ip_address=10.164.193.169 -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}228810fa07ce0224199bc54d7ea65f023e8ded81" _http_log_request /usr/lib/python2.7/site-packages/keystoneauth1/session.py:225
2016-10-11 15:17:20.638 5346 DEBUG keystoneauth.session [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] RESP: [200] Date: Tue, 11 Oct 2016 15:17:20 GMT Connection: close Content-Type: application/json; charset=UTF-8 Content-Length: 395 X-Openstack-Request-Id: req-1721b4f6-fa1c-46d4-8907-d8edf233d762 
RESP BODY: {"floatingips": [{"router_id": "113f7e40-b6d4-42c5-a36b-6758e0e0cdcb", "status": "ACTIVE", "description": "", "tenant_id": "f478dc6f6a274ef4a0e8284e9fb46b22", "floating_network_id": "1af37c8a-a196-4e33-92c0-afce4c4031c2", "fixed_ip_address": "10.100.0.3", "floating_ip_address": "10.164.193.169", "port_id": "79b2ea47-4a5e-4c7e-a277-63ba71daf593", "id": "097e1998-5316-4416-ab9b-79c4b997ea8f"}]}
 _http_log_response /usr/lib/python2.7/site-packages/keystoneauth1/session.py:254
2016-10-11 15:17:20.638 5346 DEBUG keystoneauth.session [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] REQ: curl -g -i -X GET http://d52-54-77-77-77-01.vg2.cloud.suse.de:9696/v2.0/ports/79b2ea47-4a5e-4c7e-a277-63ba71daf593.json -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}228810fa07ce0224199bc54d7ea65f023e8ded81" _http_log_request /usr/lib/python2.7/site-packages/keystoneauth1/session.py:225
2016-10-11 15:17:20.689 5346 DEBUG keystoneauth.session [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] RESP: [200] Date: Tue, 11 Oct 2016 15:17:20 GMT Connection: close Content-Type: application/json; charset=UTF-8 Content-Length: 671 X-Openstack-Request-Id: req-8de4cc60-6720-41e9-a9e0-e6c8be8b4141 
RESP BODY: {"port": {"status": "ACTIVE", "created_at": "2016-10-11T15:17:03", "description": "", "allowed_address_pairs": [], "admin_state_up": true, "network_id": "9f9c6b3c-0085-4b77-8f1f-a38e812d5f70", "tenant_id": "f478dc6f6a274ef4a0e8284e9fb46b22", "extra_dhcp_opts": [], "updated_at": "2016-10-11T15:17:07", "name": "", "device_owner": "compute:None", "mac_address": "fa:16:3e:99:15:e4", "binding:vnic_type": "normal", "fixed_ips": [{"subnet_id": "9600e72d-28a8-4350-b993-907c4e202bcf", "ip_address": "10.100.0.3"}], "id": "79b2ea47-4a5e-4c7e-a277-63ba71daf593", "security_groups": ["c29e2129-6410-493d-afe8-2e329dc90c63"], "device_id": "7e3be027-0303-4ed8-8dfc-5c19a419901c"}}
 _http_log_response /usr/lib/python2.7/site-packages/keystoneauth1/session.py:254
2016-10-11 15:17:20.689 5346 DEBUG nova.compute.api [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c] Fetching instance by UUID get /usr/lib/python2.7/site-packages/nova/compute/api.py:2044
2016-10-11 15:17:20.813 5346 DEBUG oslo_concurrency.lockutils [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] Acquired semaphore "refresh_cache-7e3be027-0303-4ed8-8dfc-5c19a419901c" lock /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:212
2016-10-11 15:17:20.816 5346 DEBUG keystoneauth.session [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] REQ: curl -g -i -X GET http://d52-54-77-77-77-01.vg2.cloud.suse.de:9696/v2.0/floatingips.json?floating_ip_address=10.164.193.169 -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}228810fa07ce0224199bc54d7ea65f023e8ded81" _http_log_request /usr/lib/python2.7/site-packages/keystoneauth1/session.py:225
2016-10-11 15:17:20.836 5346 DEBUG keystoneauth.session [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] RESP: [200] Date: Tue, 11 Oct 2016 15:17:20 GMT Connection: close Content-Type: application/json; charset=UTF-8 Content-Length: 395 X-Openstack-Request-Id: req-47a98dd4-d072-49b4-9a20-a03788bebe56 
RESP BODY: {"floatingips": [{"router_id": "113f7e40-b6d4-42c5-a36b-6758e0e0cdcb", "status": "ACTIVE", "description": "", "tenant_id": "f478dc6f6a274ef4a0e8284e9fb46b22", "floating_network_id": "1af37c8a-a196-4e33-92c0-afce4c4031c2", "fixed_ip_address": "10.100.0.3", "floating_ip_address": "10.164.193.169", "port_id": "79b2ea47-4a5e-4c7e-a277-63ba71daf593", "id": "097e1998-5316-4416-ab9b-79c4b997ea8f"}]}
 _http_log_response /usr/lib/python2.7/site-packages/keystoneauth1/session.py:254
2016-10-11 15:17:20.837 5346 DEBUG keystoneauth.session [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] REQ: curl -g -i -X DELETE http://d52-54-77-77-77-01.vg2.cloud.suse.de:9696/v2.0/floatingips/097e1998-5316-4416-ab9b-79c4b997ea8f.json -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}228810fa07ce0224199bc54d7ea65f023e8ded81" _http_log_request /usr/lib/python2.7/site-packages/keystoneauth1/session.py:225
2016-10-11 15:17:20.923 5348 DEBUG nova.osapi_compute.wsgi.server [req-01ff53e9-04d2-42b7-b511-f5b83721cdfc - - - - -] (5348) accepted ('192.168.251.84', 59034) server /usr/lib/python2.7/site-packages/eventlet/wsgi.py:867
2016-10-11 15:17:20.942 5348 DEBUG nova.api.openstack.wsgi [req-283362c5-52d9-4eae-bfc0-3a77aab08a49 ab80bf62d3fa481c839331fdf43372df 09fdde1f50174a54b37af389d3f59144 - - -] Calling method '<bound method ServersController.show of <nova.api.openstack.compute.servers.ServersController object at 0x7fb3a0dbedd0>>' _process_stack /usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py:699
2016-10-11 15:17:20.946 5348 DEBUG nova.compute.api [req-283362c5-52d9-4eae-bfc0-3a77aab08a49 ab80bf62d3fa481c839331fdf43372df 09fdde1f50174a54b37af389d3f59144 - - -] [instance: edb3fb97-af89-44bb-93a2-37bf0836a00f] Fetching instance by UUID get /usr/lib/python2.7/site-packages/nova/compute/api.py:2044
2016-10-11 15:17:21.058 5348 DEBUG keystoneauth.session [req-283362c5-52d9-4eae-bfc0-3a77aab08a49 ab80bf62d3fa481c839331fdf43372df 09fdde1f50174a54b37af389d3f59144 - - -] REQ: curl -g -i -X GET http://d52-54-77-77-77-01.vg2.cloud.suse.de:9696/v2.0/ports.json?device_id=edb3fb97-af89-44bb-93a2-37bf0836a00f -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}ba2cdf92ae5d31935ba9b11abe2629b3f0cb9d65" _http_log_request /usr/lib/python2.7/site-packages/keystoneauth1/session.py:225
2016-10-11 15:17:21.256 5348 DEBUG nova.osapi_compute.wsgi.server [req-01ff53e9-04d2-42b7-b511-f5b83721cdfc - - - - -] (5348) accepted ('192.168.251.84', 59040) server /usr/lib/python2.7/site-packages/eventlet/wsgi.py:867
2016-10-11 15:17:21.262 5348 DEBUG nova.api.openstack.wsgi [req-b0c9b559-8fe4-4e87-9a68-dbbf5c6ac5a1 3bb802b643b34dabb231e931337f2340 e0052899ed0c4eecbd330d41ae8d4229 - - -] Action: 'create', calling method: <bound method ServerExternalEventsController.create of <nova.api.openstack.compute.server_external_events.ServerExternalEventsController object at 0x7fb3a0f84b10>>, body: {"events": [{"status": "completed", "tag": "f4d0048f-d18d-463f-9310-553bd5db948b", "name": "network-vif-plugged", "server_uuid": "edb3fb97-af89-44bb-93a2-37bf0836a00f"}, {"status": "completed", "tag": "79b2ea47-4a5e-4c7e-a277-63ba71daf593", "name": "network-vif-unplugged", "server_uuid": "7e3be027-0303-4ed8-8dfc-5c19a419901c"}]} _process_stack /usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py:696
2016-10-11 15:17:21.357 5348 INFO nova.api.openstack.compute.server_external_events [req-b0c9b559-8fe4-4e87-9a68-dbbf5c6ac5a1 3bb802b643b34dabb231e931337f2340 e0052899ed0c4eecbd330d41ae8d4229 - - -] Creating event network-vif-plugged:f4d0048f-d18d-463f-9310-553bd5db948b for instance edb3fb97-af89-44bb-93a2-37bf0836a00f
2016-10-11 15:17:21.380 5348 DEBUG keystoneauth.session [req-283362c5-52d9-4eae-bfc0-3a77aab08a49 ab80bf62d3fa481c839331fdf43372df 09fdde1f50174a54b37af389d3f59144 - - -] RESP: [200] Date: Tue, 11 Oct 2016 15:17:21 GMT Connection: close Content-Type: application/json; charset=UTF-8 Content-Length: 707 X-Openstack-Request-Id: req-bfcf45e2-8420-460c-8de3-78196d3b0912 
RESP BODY: {"ports": [{"status": "ACTIVE", "created_at": "2016-10-11T15:17:12", "description": "", "allowed_address_pairs": [], "admin_state_up": true, "network_id": "77a204a8-f06c-43e4-87cc-5f7f123629f0", "tenant_id": "09fdde1f50174a54b37af389d3f59144", "extra_dhcp_opts": [], "updated_at": "2016-10-11T15:17:19", "name": "tempest-port-quotatest-1791242034", "device_owner": "compute:None", "mac_address": "fa:16:3e:ad:cc:e6", "binding:vnic_type": "normal", "fixed_ips": [{"subnet_id": "0cbe9fe9-65d8-41fb-8584-d6b561c5ea45", "ip_address": "10.100.0.3"}], "id": "f4d0048f-d18d-463f-9310-553bd5db948b", "security_groups": ["481cf3b7-b7bd-4bda-a102-bd5831d8b365"], "device_id": "edb3fb97-af89-44bb-93a2-37bf0836a00f"}]}
 _http_log_response /usr/lib/python2.7/site-packages/keystoneauth1/session.py:254
2016-10-11 15:17:21.381 5348 DEBUG keystoneauth.session [req-283362c5-52d9-4eae-bfc0-3a77aab08a49 ab80bf62d3fa481c839331fdf43372df 09fdde1f50174a54b37af389d3f59144 - - -] REQ: curl -g -i -X GET http://d52-54-77-77-77-01.vg2.cloud.suse.de:9696/v2.0/security-groups.json?id=481cf3b7-b7bd-4bda-a102-bd5831d8b365 -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}ba2cdf92ae5d31935ba9b11abe2629b3f0cb9d65" _http_log_request /usr/lib/python2.7/site-packages/keystoneauth1/session.py:225
2016-10-11 15:17:21.408 5348 INFO nova.api.openstack.compute.server_external_events [req-b0c9b559-8fe4-4e87-9a68-dbbf5c6ac5a1 3bb802b643b34dabb231e931337f2340 e0052899ed0c4eecbd330d41ae8d4229 - - -] Creating event network-vif-unplugged:79b2ea47-4a5e-4c7e-a277-63ba71daf593 for instance 7e3be027-0303-4ed8-8dfc-5c19a419901c
2016-10-11 15:17:21.420 5348 INFO nova.osapi_compute.wsgi.server [req-b0c9b559-8fe4-4e87-9a68-dbbf5c6ac5a1 3bb802b643b34dabb231e931337f2340 e0052899ed0c4eecbd330d41ae8d4229 - - -] 192.168.251.84 "POST /v2.1/e0052899ed0c4eecbd330d41ae8d4229/os-server-external-events HTTP/1.1" status: 200 len: 619 time: 0.1625051
2016-10-11 15:17:21.526 5348 DEBUG keystoneauth.session [req-283362c5-52d9-4eae-bfc0-3a77aab08a49 ab80bf62d3fa481c839331fdf43372df 09fdde1f50174a54b37af389d3f59144 - - -] RESP: [200] Date: Tue, 11 Oct 2016 15:17:21 GMT Connection: close Content-Type: application/json; charset=UTF-8 Content-Length: 1626 X-Openstack-Request-Id: req-5e93e595-96e0-4b41-9946-2e3e679cf048 
RESP BODY: {"security_groups": [{"tenant_id": "09fdde1f50174a54b37af389d3f59144", "description": "Default security group", "id": "481cf3b7-b7bd-4bda-a102-bd5831d8b365", "security_group_rules": [{"direction": "ingress", "protocol": null, "description": "", "port_range_max": null, "id": "f24762b0-1c16-4585-94b1-96a7ee061335", "remote_group_id": "481cf3b7-b7bd-4bda-a102-bd5831d8b365", "remote_ip_prefix": null, "security_group_id": "481cf3b7-b7bd-4bda-a102-bd5831d8b365", "tenant_id": "09fdde1f50174a54b37af389d3f59144", "port_range_min": null, "ethertype": "IPv4"}, {"direction": "egress", "protocol": null, "description": "", "port_range_max": null, "id": "7c7d1340-ccea-4684-8b90-3821729c4577", "remote_group_id": null, "remote_ip_prefix": null, "security_group_id": "481cf3b7-b7bd-4bda-a102-bd5831d8b365", "tenant_id": "09fdde1f50174a54b37af389d3f59144", "port_range_min": null, "ethertype": "IPv4"}, {"direction": "ingress", "protocol": null, "description": "", "port_range_max": null, "id": "cb27eba0-9623-494c-8cbf-fea59de397ac", "remote_group_id": "481cf3b7-b7bd-4bda-a102-bd5831d8b365", "remote_ip_prefix": null, "security_group_id": "481cf3b7-b7bd-4bda-a102-bd5831d8b365", "tenant_id": "09fdde1f50174a54b37af389d3f59144", "port_range_min": null, "ethertype": "IPv6"}, {"direction": "egress", "protocol": null, "description": "", "port_range_max": null, "id": "1c02b335-7949-4070-8ef2-a2052b0cf578", "remote_group_id": null, "remote_ip_prefix": null, "security_group_id": "481cf3b7-b7bd-4bda-a102-bd5831d8b365", "tenant_id": "09fdde1f50174a54b37af389d3f59144", "port_range_min": null, "ethertype": "IPv6"}], "name": "default"}]}
 _http_log_response /usr/lib/python2.7/site-packages/keystoneauth1/session.py:254
2016-10-11 15:17:21.527 5348 DEBUG nova.policy [req-283362c5-52d9-4eae-bfc0-3a77aab08a49 ab80bf62d3fa481c839331fdf43372df 09fdde1f50174a54b37af389d3f59144 - - -] Policy check for os_compute_api:os-extended-server-attributes failed with credentials {'domain': None, 'project_name': u'tempest-TestNetworkBasicOps-2111777401', 'project_domain': None, 'timestamp': '2016-10-11T15:17:20.937250', 'remote_address': '192.168.251.84', 'quota_class': None, 'resource_uuid': None, 'is_admin': False, 'user': u'ab80bf62d3fa481c839331fdf43372df', 'service_catalog': [{u'endpoints': [{u'adminURL': u'http://d52-54-77-77-77-01.vg2.cloud.suse.de:8776/v1/09fdde1f50174a54b37af389d3f59144', u'region': u'CustomRegion', u'internalURL': u'http://d52-54-77-77-77-01.vg2.cloud.suse.de:8776/v1/09fdde1f50174a54b37af389d3f59144', u'publicURL': u'http://10.164.193.2:8776/v1/09fdde1f50174a54b37af389d3f59144'}], u'type': u'volume', u'name': u'cinder'}, {u'endpoints': [{u'adminURL': u'http://d52-54-77-77-77-01.vg2.cloud.suse.de:8776/v2/09fdde1f50174a54b37af389d3f59144', u'region': u'CustomRegion', u'internalURL': u'http://d52-54-77-77-77-01.vg2.cloud.suse.de:8776/v2/09fdde1f50174a54b37af389d3f59144', u'publicURL': u'http://10.164.193.2:8776/v2/09fdde1f50174a54b37af389d3f59144'}], u'type': u'volumev2', u'name': u'cinderv2'}, {u'endpoints': [{u'adminURL': u'http://d52-54-77-77-77-01.vg2.cloud.suse.de:9311', u'region': u'CustomRegion', u'internalURL': u'http://d52-54-77-77-77-01.vg2.cloud.suse.de:9311', u'publicURL': u'http://10.164.193.2:9311'}], u'type': u'key-manager', u'name': u'barbican'}], 'tenant': u'09fdde1f50174a54b37af389d3f59144', 'read_only': False, 'project_id': u'09fdde1f50174a54b37af389d3f59144', 'user_id': u'ab80bf62d3fa481c839331fdf43372df', 'show_deleted': False, 'roles': [u'Member'], 'user_identity': 'ab80bf62d3fa481c839331fdf43372df 09fdde1f50174a54b37af389d3f59144 - - -', 'read_deleted': 'no', 'request_id': 'req-283362c5-52d9-4eae-bfc0-3a77aab08a49', 'instance_lock_checked': False, 'user_domain': None, 'user_name': u'tempest-TestNetworkBasicOps-1018360729'} enforce /usr/lib/python2.7/site-packages/nova/policy.py:107
2016-10-11 15:17:21.528 5348 INFO nova.osapi_compute.wsgi.server [req-283362c5-52d9-4eae-bfc0-3a77aab08a49 ab80bf62d3fa481c839331fdf43372df 09fdde1f50174a54b37af389d3f59144 - - -] 192.168.251.84 "GET /v2.1/09fdde1f50174a54b37af389d3f59144/servers/edb3fb97-af89-44bb-93a2-37bf0836a00f HTTP/1.1" status: 200 len: 1813 time: 0.6017179
2016-10-11 15:17:22.001 5346 DEBUG keystoneauth.session [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] RESP: [204] Date: Tue, 11 Oct 2016 15:17:22 GMT Connection: close Content-Length: 0 X-Openstack-Request-Id: req-0e41c9e5-00e4-45b8-a741-1379d69bd639 _http_log_response /usr/lib/python2.7/site-packages/keystoneauth1/session.py:254
2016-10-11 15:17:22.001 5346 DEBUG nova.network.neutronv2.api [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c] _get_instance_nw_info() _get_instance_nw_info /usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py:927
2016-10-11 15:17:22.006 5346 ERROR nova.network.base_api [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c] Failed storing info cache
2016-10-11 15:17:22.006 5346 ERROR nova.network.base_api [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c] Traceback (most recent call last):
2016-10-11 15:17:22.006 5346 ERROR nova.network.base_api [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c]   File "/usr/lib/python2.7/site-packages/nova/network/base_api.py", line 40, in update_instance_cache_with_nw_info
2016-10-11 15:17:22.006 5346 ERROR nova.network.base_api [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c]     nw_info = impl._get_instance_nw_info(context, instance)
2016-10-11 15:17:22.006 5346 ERROR nova.network.base_api [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c]   File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 931, in _get_instance_nw_info
2016-10-11 15:17:22.006 5346 ERROR nova.network.base_api [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c]     compute_utils.refresh_info_cache_for_instance(context, instance)
2016-10-11 15:17:22.006 5346 ERROR nova.network.base_api [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c]   File "/usr/lib/python2.7/site-packages/nova/compute/utils.py", line 357, in refresh_info_cache_for_instance
2016-10-11 15:17:22.006 5346 ERROR nova.network.base_api [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c]     instance.info_cache.refresh()
2016-10-11 15:17:22.006 5346 ERROR nova.network.base_api [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c]   File "/usr/lib/python2.7/site-packages/oslo_versionedobjects/base.py", line 223, in wrapper
2016-10-11 15:17:22.006 5346 ERROR nova.network.base_api [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c]     return fn(self, *args, **kwargs)
2016-10-11 15:17:22.006 5346 ERROR nova.network.base_api [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c]   File "/usr/lib/python2.7/site-packages/nova/objects/instance_info_cache.py", line 113, in refresh
2016-10-11 15:17:22.006 5346 ERROR nova.network.base_api [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c]     self.instance_uuid)
2016-10-11 15:17:22.006 5346 ERROR nova.network.base_api [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c]   File "/usr/lib/python2.7/site-packages/oslo_versionedobjects/base.py", line 181, in wrapper
2016-10-11 15:17:22.006 5346 ERROR nova.network.base_api [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c]     result = fn(cls, context, *args, **kwargs)
2016-10-11 15:17:22.006 5346 ERROR nova.network.base_api [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c]   File "/usr/lib/python2.7/site-packages/nova/objects/instance_info_cache.py", line 74, in get_by_instance_uuid
2016-10-11 15:17:22.006 5346 ERROR nova.network.base_api [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c]     instance_uuid=instance_uuid)
2016-10-11 15:17:22.006 5346 ERROR nova.network.base_api [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c] InstanceInfoCacheNotFound: Info cache for instance 7e3be027-0303-4ed8-8dfc-5c19a419901c could not be found.
2016-10-11 15:17:22.006 5346 ERROR nova.network.base_api [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c] 
2016-10-11 15:17:22.018 5346 DEBUG oslo_concurrency.lockutils [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] Releasing semaphore "refresh_cache-7e3be027-0303-4ed8-8dfc-5c19a419901c" lock /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:225
2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] Unexpected exception in API method
2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions Traceback (most recent call last):
2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions   File "/usr/lib/python2.7/site-packages/nova/api/openstack/extensions.py", line 478, in wrapped
2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions     return f(*args, **kwargs)
2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions   File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/floating_ips.py", line 173, in delete
2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions     context, instance, floating_ip)
2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions   File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 1564, in disassociate_and_release_floating_ip
2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions     floating_ip)
2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions   File "/usr/lib/python2.7/site-packages/nova/network/base_api.py", line 79, in wrapper
2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions     nw_info=res)
2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions   File "/usr/lib/python2.7/site-packages/nova/hooks.py", line 154, in inner
2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions     rv = f(*args, **kwargs)
2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions   File "/usr/lib/python2.7/site-packages/nova/network/base_api.py", line 53, in update_instance_cache_with_nw_info
2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions     LOG.exception(_LE('Failed storing info cache'), instance=instance)
2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions     self.force_reraise()
2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions     six.reraise(self.type_, self.value, self.tb)
2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions   File "/usr/lib/python2.7/site-packages/nova/network/base_api.py", line 40, in update_instance_cache_with_nw_info
2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions     nw_info = impl._get_instance_nw_info(context, instance)
2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions   File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 931, in _get_instance_nw_info
2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions     compute_utils.refresh_info_cache_for_instance(context, instance)
2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions   File "/usr/lib/python2.7/site-packages/nova/compute/utils.py", line 357, in refresh_info_cache_for_instance
2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions     instance.info_cache.refresh()
2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions   File "/usr/lib/python2.7/site-packages/oslo_versionedobjects/base.py", line 223, in wrapper
2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions     return fn(self, *args, **kwargs)
2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions   File "/usr/lib/python2.7/site-packages/nova/objects/instance_info_cache.py", line 113, in refresh
2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions     self.instance_uuid)
2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions   File "/usr/lib/python2.7/site-packages/oslo_versionedobjects/base.py", line 181, in wrapper
2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions     result = fn(cls, context, *args, **kwargs)
2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions   File "/usr/lib/python2.7/site-packages/nova/objects/instance_info_cache.py", line 74, in get_by_instance_uuid
2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions     instance_uuid=instance_uuid)
2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions InstanceInfoCacheNotFound: Info cache for instance 7e3be027-0303-4ed8-8dfc-5c19a419901c could not be found.
2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions 
2016-10-11 15:17:22.041 5346 INFO nova.api.openstack.wsgi [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] HTTP exception thrown: Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.
<class 'nova.exception.InstanceInfoCacheNotFound'>
2016-10-11 15:17:22.042 5346 DEBUG nova.api.openstack.wsgi [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] Returning 500 to user: Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.
<class 'nova.exception.InstanceInfoCacheNotFound'> __call__ /usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py:1070
2016-10-11 15:17:22.043 5346 INFO nova.osapi_compute.wsgi.server [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] 192.168.251.84 "DELETE /v2.1/f478dc6f6a274ef4a0e8284e9fb46b22/os-floating-ips/097e1998-5316-4416-ab9b-79c4b997ea8f HTTP/1.1" status: 500 len: 511 time: 1.6293600
2016-10-11 15:17:22.059 5348 DEBUG nova.osapi_compute.wsgi.server [req-01ff53e9-04d2-42b7-b511-f5b83721cdfc - - - - -] (5348) accepted ('192.168.251.84', 59046) server /usr/lib/python2.7/site-packages/eventlet/wsgi.py:867
2016-10-11 15:17:22.068 5348 DEBUG nova.api.openstack.wsgi [req-ce3ca9c9-87ad-492e-9e7b-84246227d4f6 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] Calling method '<bound method ServersController.delete of <nova.api.openstack.compute.servers.ServersController object at 0x7fb3a0dbedd0>>' _process_stack /usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py:699
2016-10-11 15:17:22.070 5348 DEBUG nova.compute.api [req-ce3ca9c9-87ad-492e-9e7b-84246227d4f6 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c] Fetching instance by UUID get /usr/lib/python2.7/site-packages/nova/compute/api.py:2044
2016-10-11 15:17:22.189 5348 DEBUG nova.compute.api [req-ce3ca9c9-87ad-492e-9e7b-84246227d4f6 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c] Going to try to terminate instance delete /usr/lib/python2.7/site-packages/nova/compute/api.py:1941
2016-10-11 15:17:22.295 5348 INFO nova.osapi_compute.wsgi.server [req-ce3ca9c9-87ad-492e-9e7b-84246227d4f6 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] 192.168.251.84 "DELETE /v2.1/f478dc6f6a274ef4a0e8284e9fb46b22/servers/7e3be027-0303-4ed8-8dfc-5c19a419901c HTTP/1.1" status: 204 len: 269 time: 0.2338710
2016-10-11 15:17:22.295 5346 DEBUG nova.osapi_compute.wsgi.server [req-46918002-2351-4561-916d-3e886840a8b7 - - - - -] (5346) accepted ('192.168.251.84', 59050) server /usr/lib/python2.7/site-packages/eventlet/wsgi.py:867
2016-10-11 15:17:22.304 5346 DEBUG nova.api.openstack.wsgi [req-23d48f8e-7f62-4847-8d01-90aaa0f487ae 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] Calling method '<bound method ServersController.show of <nova.api.openstack.compute.servers.ServersController object at 0x7fb3a0dbedd0>>' _process_stack /usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py:699
2016-10-11 15:17:22.305 5346 DEBUG nova.compute.api [req-23d48f8e-7f62-4847-8d01-90aaa0f487ae 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c] Fetching instance by UUID get /usr/lib/python2.7/site-packages/nova/compute/api.py:2044
2016-10-11 15:17:22.373 5346 INFO nova.api.openstack.wsgi [req-23d48f8e-7f62-4847-8d01-90aaa0f487ae 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] HTTP exception thrown: Instance 7e3be027-0303-4ed8-8dfc-5c19a419901c could not be found.
2016-10-11 15:17:22.375 5346 DEBUG nova.api.openstack.wsgi [req-23d48f8e-7f62-4847-8d01-90aaa0f487ae 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] Returning 404 to user: Instance 7e3be027-0303-4ed8-8dfc-5c19a419901c could not be found. __call__ /usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py:1070
2016-10-11 15:17:22.379 5348 DEBUG nova.osapi_compute.wsgi.server [req-01ff53e9-04d2-42b7-b511-f5b83721cdfc - - - - -] (5348) accepted ('192.168.251.84', 59054) server /usr/lib/python2.7/site-packages/eventlet/wsgi.py:867
2016-10-11 15:17:22.382 5346 INFO nova.osapi_compute.wsgi.server [req-23d48f8e-7f62-4847-8d01-90aaa0f487ae 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] 192.168.251.84 "GET /v2.1/f478dc6f6a274ef4a0e8284e9fb46b22/servers/7e3be027-0303-4ed8-8dfc-5c19a419901c HTTP/1.1" status: 404 len: 396 time: 0.0852270
2016-10-11 15:17:22.384 5348 DEBUG nova.api.openstack.wsgi [req-907b132d-d02d-476f-83be-2168c06470ba 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] Calling method '<bound method SecurityGroupController.delete of <nova.api.openstack.compute.security_groups.SecurityGroupController object at 0x7fb3a107a510>>' _process_stack /usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py:699
2016-10-11 15:17:22.388 5348 DEBUG keystoneauth.session [req-907b132d-d02d-476f-83be-2168c06470ba 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] REQ: curl -g -i -X GET http://d52-54-77-77-77-01.vg2.cloud.suse.de:9696/v2.0/security-groups/c29e2129-6410-493d-afe8-2e329dc90c63.json -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}228810fa07ce0224199bc54d7ea65f023e8ded81" _http_log_request /usr/lib/python2.7/site-packages/keystoneauth1/session.py:225
2016-10-11 15:17:22.434 5348 DEBUG keystoneauth.session [req-907b132d-d02d-476f-83be-2168c06470ba 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] RESP: [200] Date: Tue, 11 Oct 2016 15:17:22 GMT Connection: close Content-Type: application/json; charset=UTF-8 Content-Length: 1623 X-Openstack-Request-Id: req-3fe49220-4617-4739-b73e-2e4a6c1bc2f6 
RESP BODY: {"security_group": {"tenant_id": "f478dc6f6a274ef4a0e8284e9fb46b22", "description": "tempest-TestServerBasicOps-494331381 description", "id": "c29e2129-6410-493d-afe8-2e329dc90c63", "security_group_rules": [{"direction": "ingress", "protocol": "icmp", "description": "", "port_range_max": null, "id": "1c6b6af1-d01a-49c8-a242-bc72ae5d9a80", "remote_group_id": null, "remote_ip_prefix": "0.0.0.0/0", "security_group_id": "c29e2129-6410-493d-afe8-2e329dc90c63", "tenant_id": "f478dc6f6a274ef4a0e8284e9fb46b22", "port_range_min": null, "ethertype": "IPv4"}, {"direction": "egress", "protocol": null, "description": "", "port_range_max": null, "id": "9db46a71-58fc-4637-aa1d-e283ed19e567", "remote_group_id": null, "remote_ip_prefix": null, "security_group_id": "c29e2129-6410-493d-afe8-2e329dc90c63", "tenant_id": "f478dc6f6a274ef4a0e8284e9fb46b22", "port_range_min": null, "ethertype": "IPv4"}, {"direction": "egress", "protocol": null, "description": "", "port_range_max": null, "id": "0160e537-354b-4716-bc81-76ac1449c054", "remote_group_id": null, "remote_ip_prefix": null, "security_group_id": "c29e2129-6410-493d-afe8-2e329dc90c63", "tenant_id": "f478dc6f6a274ef4a0e8284e9fb46b22", "port_range_min": null, "ethertype": "IPv6"}, {"direction": "ingress", "protocol": "tcp", "description": "", "port_range_max": 22, "id": "dc316241-79d8-4b96-bde9-c3bb673876c3", "remote_group_id": null, "remote_ip_prefix": "0.0.0.0/0", "security_group_id": "c29e2129-6410-493d-afe8-2e329dc90c63", "tenant_id": "f478dc6f6a274ef4a0e8284e9fb46b22", "port_range_min": 22, "ethertype": "IPv4"}], "name": "tempest-TestServerBasicOps-494331381"}}
 _http_log_response /usr/lib/python2.7/site-packages/keystoneauth1/session.py:254
2016-10-11 15:17:22.435 5348 DEBUG keystoneauth.session [req-907b132d-d02d-476f-83be-2168c06470ba 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] REQ: curl -g -i -X DELETE http://d52-54-77-77-77-01.vg2.cloud.suse.de:9696/v2.0/security-groups/c29e2129-6410-493d-afe8-2e329dc90c63.json -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}228810fa07ce0224199bc54d7ea65f023e8ded81" _http_log_request /usr/lib/python2.7/site-packages/keystoneauth1/session.py:225
2016-10-11 15:17:22.558 5348 DEBUG nova.osapi_compute.wsgi.server [req-01ff53e9-04d2-42b7-b511-f5b83721cdfc - - - - -] (5348) accepted ('192.168.251.84', 59062) server /usr/lib/python2.7/site-packages/eventlet/wsgi.py:867
2016-10-11 15:17:22.572 5348 DEBUG nova.api.openstack.wsgi [req-4447a07b-ee79-4ee2-9599-5ac3affd24fb ab80bf62d3fa481c839331fdf43372df 09fdde1f50174a54b37af389d3f59144 - - -] Calling method '<bound method ServersController.show of <nova.api.openstack.compute.servers.ServersController object at 0x7fb3a0dbedd0>>' _process_stack /usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py:699
2016-10-11 15:17:22.573 5348 DEBUG nova.compute.api [req-4447a07b-ee79-4ee2-9599-5ac3affd24fb ab80bf62d3fa481c839331fdf43372df 09fdde1f50174a54b37af389d3f59144 - - -] [instance: edb3fb97-af89-44bb-93a2-37bf0836a00f] Fetching instance by UUID get /usr/lib/python2.7/site-packages/nova/compute/api.py:2044

** Affects: nova
     Importance: Undecided
         Status: New

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to OpenStack Compute (nova).
https://bugs.launchpad.net/bugs/1632403

Title:
  InstanceInfoCacheNotFound: Info cache for instance 7e3be027-0303-4ed8
  -8dfc-5c19a419901c could not be found

Status in OpenStack Compute (nova):
  New

Bug description:
  * This is with:
  - SUSE SLE 12 SP2
  - Nova Mitaka (version 13.1.2.dev68 from the stable-mitaka from tarballs.openstack.org)
  - neutron+linuxbridge
  - nova libvirt+KVM

  
  When running the tempest scenario tests (ostestr -r '^tempest.scenario') I get:

     Traceback (most recent call last):
        File "/var/lib/openstack-tempest-test/tempest/lib/common/utils/test_utils.py", line 83, in call_and_ignore_notfound_exc
          return func(*args, **kwargs)
        File "/var/lib/openstack-tempest-test/tempest/lib/services/compute/floating_ips_client.py", line 62, in delete_floating_ip
          resp, body = self.delete(url)
        File "/var/lib/openstack-tempest-test/tempest/lib/common/rest_client.py", line 290, in delete
          return self.request('DELETE', url, extra_headers, headers, body)
        File "/var/lib/openstack-tempest-test/tempest/lib/services/compute/base_compute_client.py", line 53, in request
          method, url, extra_headers, headers, body)
        File "/var/lib/openstack-tempest-test/tempest/lib/common/rest_client.py", line 642, in request
          resp, resp_body)
        File "/var/lib/openstack-tempest-test/tempest/lib/common/rest_client.py", line 761, in _error_checker
          message=message)
      ServerFault: Got server fault
      Details: Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.
      <class 'nova.exception.InstanceInfoCacheNotFound'>




  /var/log/nova/nova-api.log has:

  2016-10-11 15:17:20.074 5348 DEBUG nova.osapi_compute.wsgi.server [req-01ff53e9-04d2-42b7-b511-f5b83721cdfc - - - - -] (5348) accepted ('192.168.251.84', 59010) server /usr/lib/python2.7/site-packages/eventlet/wsgi.py:867
  2016-10-11 15:17:20.082 5348 DEBUG nova.api.openstack.wsgi [req-4db29700-8188-4184-a628-5a29733ee2d8 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] Calling method '<bound method ServersController.delete of <nova.api.openstack.compute.servers.ServersController object at 0x7fb3a0dbedd0>>' _process_stack /usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py:699
  2016-10-11 15:17:20.082 5348 DEBUG nova.compute.api [req-4db29700-8188-4184-a628-5a29733ee2d8 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c] Fetching instance by UUID get /usr/lib/python2.7/site-packages/nova/compute/api.py:2044
  2016-10-11 15:17:20.162 5348 DEBUG nova.compute.api [req-4db29700-8188-4184-a628-5a29733ee2d8 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c] Going to try to terminate instance delete /usr/lib/python2.7/site-packages/nova/compute/api.py:1941
  2016-10-11 15:17:20.306 5348 DEBUG nova.quota [req-4db29700-8188-4184-a628-5a29733ee2d8 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] Attempting to reserve resources for project f478dc6f6a274ef4a0e8284e9fb46b22 and user 6d03f6736e16470a9050eb1e24f25a76. Deltas: {'instances': -1, 'ram': -128, 'cores': -1} reserve /usr/lib/python2.7/site-packages/nova/quota.py:550
  2016-10-11 15:17:20.318 5348 DEBUG nova.quota [req-4db29700-8188-4184-a628-5a29733ee2d8 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] Quota limits for project f478dc6f6a274ef4a0e8284e9fb46b22: {'project_id': u'f478dc6f6a274ef4a0e8284e9fb46b22'} reserve /usr/lib/python2.7/site-packages/nova/quota.py:559
  2016-10-11 15:17:20.318 5348 DEBUG nova.quota [req-4db29700-8188-4184-a628-5a29733ee2d8 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] Getting quotas for project f478dc6f6a274ef4a0e8284e9fb46b22. Resources: ['instances', 'ram', 'cores'] _get_quotas /usr/lib/python2.7/site-packages/nova/quota.py:409
  2016-10-11 15:17:20.325 5348 DEBUG nova.quota [req-4db29700-8188-4184-a628-5a29733ee2d8 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] Quotas for project f478dc6f6a274ef4a0e8284e9fb46b22 after resource sync: {'instances': 10, 'ram': 51200, 'cores': 20} reserve /usr/lib/python2.7/site-packages/nova/quota.py:565
  2016-10-11 15:17:20.327 5348 DEBUG nova.quota [req-4db29700-8188-4184-a628-5a29733ee2d8 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] Getting quotas for user 6d03f6736e16470a9050eb1e24f25a76 and project f478dc6f6a274ef4a0e8284e9fb46b22. Resources: ['instances', 'ram', 'cores'] _get_quotas /usr/lib/python2.7/site-packages/nova/quota.py:401
  2016-10-11 15:17:20.350 5348 DEBUG nova.quota [req-4db29700-8188-4184-a628-5a29733ee2d8 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] Quotas for project f478dc6f6a274ef4a0e8284e9fb46b22 and user 6d03f6736e16470a9050eb1e24f25a76 after resource sync: {'instances': 10, 'ram': 51200, 'cores': 20} reserve /usr/lib/python2.7/site-packages/nova/quota.py:573
  2016-10-11 15:17:20.389 5348 DEBUG nova.quota [req-4db29700-8188-4184-a628-5a29733ee2d8 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] Created reservations ['17dab2ab-05c0-4cf8-ac10-cf0f5d6bd8da', '47f11182-e1da-457e-8adf-3e60c6f51bf0', '8d883408-d873-4048-841d-1dec24ccb9d0'] reserve /usr/lib/python2.7/site-packages/nova/quota.py:1345
  2016-10-11 15:17:20.412 5346 DEBUG nova.osapi_compute.wsgi.server [req-46918002-2351-4561-916d-3e886840a8b7 - - - - -] (5346) accepted ('192.168.251.84', 59016) server /usr/lib/python2.7/site-packages/eventlet/wsgi.py:867
  2016-10-11 15:17:20.415 5348 INFO nova.osapi_compute.wsgi.server [req-4db29700-8188-4184-a628-5a29733ee2d8 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] 192.168.251.84 "DELETE /v2.1/f478dc6f6a274ef4a0e8284e9fb46b22/servers/7e3be027-0303-4ed8-8dfc-5c19a419901c HTTP/1.1" status: 204 len: 269 time: 0.3392730
  2016-10-11 15:17:20.419 5346 DEBUG nova.api.openstack.wsgi [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] Calling method '<bound method FloatingIPController.delete of <nova.api.openstack.compute.floating_ips.FloatingIPController object at 0x7fb3a0f8fe50>>' _process_stack /usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py:699
  2016-10-11 15:17:20.420 5346 DEBUG keystoneauth.session [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] REQ: curl -g -i -X GET http://d52-54-77-77-77-01.vg2.cloud.suse.de:9696/v2.0/floatingips/097e1998-5316-4416-ab9b-79c4b997ea8f.json -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}228810fa07ce0224199bc54d7ea65f023e8ded81" _http_log_request /usr/lib/python2.7/site-packages/keystoneauth1/session.py:225
  2016-10-11 15:17:20.440 5346 DEBUG keystoneauth.session [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] RESP: [200] Date: Tue, 11 Oct 2016 15:17:20 GMT Connection: close Content-Type: application/json; charset=UTF-8 Content-Length: 392 X-Openstack-Request-Id: req-9d8de0fb-f8c3-4aaa-821e-54d98dbf20ad 
  RESP BODY: {"floatingip": {"router_id": "113f7e40-b6d4-42c5-a36b-6758e0e0cdcb", "status": "ACTIVE", "description": "", "tenant_id": "f478dc6f6a274ef4a0e8284e9fb46b22", "floating_network_id": "1af37c8a-a196-4e33-92c0-afce4c4031c2", "fixed_ip_address": "10.100.0.3", "floating_ip_address": "10.164.193.169", "port_id": "79b2ea47-4a5e-4c7e-a277-63ba71daf593", "id": "097e1998-5316-4416-ab9b-79c4b997ea8f"}}
   _http_log_response /usr/lib/python2.7/site-packages/keystoneauth1/session.py:254
  2016-10-11 15:17:20.441 5346 DEBUG keystoneauth.session [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] REQ: curl -g -i -X GET http://d52-54-77-77-77-01.vg2.cloud.suse.de:9696/v2.0/networks/1af37c8a-a196-4e33-92c0-afce4c4031c2.json -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}228810fa07ce0224199bc54d7ea65f023e8ded81" _http_log_request /usr/lib/python2.7/site-packages/keystoneauth1/session.py:225
  2016-10-11 15:17:20.577 5346 DEBUG keystoneauth.session [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] RESP: [200] Date: Tue, 11 Oct 2016 15:17:20 GMT Connection: close Content-Type: application/json; charset=UTF-8 Content-Length: 525 X-Openstack-Request-Id: req-59187583-5c2f-4cc9-8468-c36f57b08440 
  RESP BODY: {"network": {"status": "ACTIVE", "router:external": true, "availability_zone_hints": [], "availability_zones": ["nova"], "description": "", "subnets": ["be1635d1-bf5d-4222-a85b-6cbccbb1241b"], "tenant_id": "e0052899ed0c4eecbd330d41ae8d4229", "created_at": "2016-10-11T10:26:14", "tags": [], "updated_at": "2016-10-11T10:26:14", "ipv6_address_scope": null, "is_default": false, "admin_state_up": true, "ipv4_address_scope": null, "shared": false, "mtu": 8900, "id": "1af37c8a-a196-4e33-92c0-afce4c4031c2", "name": "floating"}}
   _http_log_response /usr/lib/python2.7/site-packages/keystoneauth1/session.py:254
  2016-10-11 15:17:20.578 5346 DEBUG keystoneauth.session [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] REQ: curl -g -i -X GET http://d52-54-77-77-77-01.vg2.cloud.suse.de:9696/v2.0/ports/79b2ea47-4a5e-4c7e-a277-63ba71daf593.json -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}228810fa07ce0224199bc54d7ea65f023e8ded81" _http_log_request /usr/lib/python2.7/site-packages/keystoneauth1/session.py:225
  2016-10-11 15:17:20.616 5346 DEBUG keystoneauth.session [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] RESP: [200] Date: Tue, 11 Oct 2016 15:17:20 GMT Connection: close Content-Type: application/json; charset=UTF-8 Content-Length: 671 X-Openstack-Request-Id: req-6e7ebb68-20e2-4f4b-81a5-df643e70d2ec 
  RESP BODY: {"port": {"status": "ACTIVE", "created_at": "2016-10-11T15:17:03", "description": "", "allowed_address_pairs": [], "admin_state_up": true, "network_id": "9f9c6b3c-0085-4b77-8f1f-a38e812d5f70", "tenant_id": "f478dc6f6a274ef4a0e8284e9fb46b22", "extra_dhcp_opts": [], "updated_at": "2016-10-11T15:17:07", "name": "", "device_owner": "compute:None", "mac_address": "fa:16:3e:99:15:e4", "binding:vnic_type": "normal", "fixed_ips": [{"subnet_id": "9600e72d-28a8-4350-b993-907c4e202bcf", "ip_address": "10.100.0.3"}], "id": "79b2ea47-4a5e-4c7e-a277-63ba71daf593", "security_groups": ["c29e2129-6410-493d-afe8-2e329dc90c63"], "device_id": "7e3be027-0303-4ed8-8dfc-5c19a419901c"}}
   _http_log_response /usr/lib/python2.7/site-packages/keystoneauth1/session.py:254
  2016-10-11 15:17:20.617 5346 DEBUG keystoneauth.session [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] REQ: curl -g -i -X GET http://d52-54-77-77-77-01.vg2.cloud.suse.de:9696/v2.0/floatingips.json?floating_ip_address=10.164.193.169 -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}228810fa07ce0224199bc54d7ea65f023e8ded81" _http_log_request /usr/lib/python2.7/site-packages/keystoneauth1/session.py:225
  2016-10-11 15:17:20.638 5346 DEBUG keystoneauth.session [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] RESP: [200] Date: Tue, 11 Oct 2016 15:17:20 GMT Connection: close Content-Type: application/json; charset=UTF-8 Content-Length: 395 X-Openstack-Request-Id: req-1721b4f6-fa1c-46d4-8907-d8edf233d762 
  RESP BODY: {"floatingips": [{"router_id": "113f7e40-b6d4-42c5-a36b-6758e0e0cdcb", "status": "ACTIVE", "description": "", "tenant_id": "f478dc6f6a274ef4a0e8284e9fb46b22", "floating_network_id": "1af37c8a-a196-4e33-92c0-afce4c4031c2", "fixed_ip_address": "10.100.0.3", "floating_ip_address": "10.164.193.169", "port_id": "79b2ea47-4a5e-4c7e-a277-63ba71daf593", "id": "097e1998-5316-4416-ab9b-79c4b997ea8f"}]}
   _http_log_response /usr/lib/python2.7/site-packages/keystoneauth1/session.py:254
  2016-10-11 15:17:20.638 5346 DEBUG keystoneauth.session [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] REQ: curl -g -i -X GET http://d52-54-77-77-77-01.vg2.cloud.suse.de:9696/v2.0/ports/79b2ea47-4a5e-4c7e-a277-63ba71daf593.json -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}228810fa07ce0224199bc54d7ea65f023e8ded81" _http_log_request /usr/lib/python2.7/site-packages/keystoneauth1/session.py:225
  2016-10-11 15:17:20.689 5346 DEBUG keystoneauth.session [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] RESP: [200] Date: Tue, 11 Oct 2016 15:17:20 GMT Connection: close Content-Type: application/json; charset=UTF-8 Content-Length: 671 X-Openstack-Request-Id: req-8de4cc60-6720-41e9-a9e0-e6c8be8b4141 
  RESP BODY: {"port": {"status": "ACTIVE", "created_at": "2016-10-11T15:17:03", "description": "", "allowed_address_pairs": [], "admin_state_up": true, "network_id": "9f9c6b3c-0085-4b77-8f1f-a38e812d5f70", "tenant_id": "f478dc6f6a274ef4a0e8284e9fb46b22", "extra_dhcp_opts": [], "updated_at": "2016-10-11T15:17:07", "name": "", "device_owner": "compute:None", "mac_address": "fa:16:3e:99:15:e4", "binding:vnic_type": "normal", "fixed_ips": [{"subnet_id": "9600e72d-28a8-4350-b993-907c4e202bcf", "ip_address": "10.100.0.3"}], "id": "79b2ea47-4a5e-4c7e-a277-63ba71daf593", "security_groups": ["c29e2129-6410-493d-afe8-2e329dc90c63"], "device_id": "7e3be027-0303-4ed8-8dfc-5c19a419901c"}}
   _http_log_response /usr/lib/python2.7/site-packages/keystoneauth1/session.py:254
  2016-10-11 15:17:20.689 5346 DEBUG nova.compute.api [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c] Fetching instance by UUID get /usr/lib/python2.7/site-packages/nova/compute/api.py:2044
  2016-10-11 15:17:20.813 5346 DEBUG oslo_concurrency.lockutils [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] Acquired semaphore "refresh_cache-7e3be027-0303-4ed8-8dfc-5c19a419901c" lock /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:212
  2016-10-11 15:17:20.816 5346 DEBUG keystoneauth.session [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] REQ: curl -g -i -X GET http://d52-54-77-77-77-01.vg2.cloud.suse.de:9696/v2.0/floatingips.json?floating_ip_address=10.164.193.169 -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}228810fa07ce0224199bc54d7ea65f023e8ded81" _http_log_request /usr/lib/python2.7/site-packages/keystoneauth1/session.py:225
  2016-10-11 15:17:20.836 5346 DEBUG keystoneauth.session [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] RESP: [200] Date: Tue, 11 Oct 2016 15:17:20 GMT Connection: close Content-Type: application/json; charset=UTF-8 Content-Length: 395 X-Openstack-Request-Id: req-47a98dd4-d072-49b4-9a20-a03788bebe56 
  RESP BODY: {"floatingips": [{"router_id": "113f7e40-b6d4-42c5-a36b-6758e0e0cdcb", "status": "ACTIVE", "description": "", "tenant_id": "f478dc6f6a274ef4a0e8284e9fb46b22", "floating_network_id": "1af37c8a-a196-4e33-92c0-afce4c4031c2", "fixed_ip_address": "10.100.0.3", "floating_ip_address": "10.164.193.169", "port_id": "79b2ea47-4a5e-4c7e-a277-63ba71daf593", "id": "097e1998-5316-4416-ab9b-79c4b997ea8f"}]}
   _http_log_response /usr/lib/python2.7/site-packages/keystoneauth1/session.py:254
  2016-10-11 15:17:20.837 5346 DEBUG keystoneauth.session [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] REQ: curl -g -i -X DELETE http://d52-54-77-77-77-01.vg2.cloud.suse.de:9696/v2.0/floatingips/097e1998-5316-4416-ab9b-79c4b997ea8f.json -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}228810fa07ce0224199bc54d7ea65f023e8ded81" _http_log_request /usr/lib/python2.7/site-packages/keystoneauth1/session.py:225
  2016-10-11 15:17:20.923 5348 DEBUG nova.osapi_compute.wsgi.server [req-01ff53e9-04d2-42b7-b511-f5b83721cdfc - - - - -] (5348) accepted ('192.168.251.84', 59034) server /usr/lib/python2.7/site-packages/eventlet/wsgi.py:867
  2016-10-11 15:17:20.942 5348 DEBUG nova.api.openstack.wsgi [req-283362c5-52d9-4eae-bfc0-3a77aab08a49 ab80bf62d3fa481c839331fdf43372df 09fdde1f50174a54b37af389d3f59144 - - -] Calling method '<bound method ServersController.show of <nova.api.openstack.compute.servers.ServersController object at 0x7fb3a0dbedd0>>' _process_stack /usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py:699
  2016-10-11 15:17:20.946 5348 DEBUG nova.compute.api [req-283362c5-52d9-4eae-bfc0-3a77aab08a49 ab80bf62d3fa481c839331fdf43372df 09fdde1f50174a54b37af389d3f59144 - - -] [instance: edb3fb97-af89-44bb-93a2-37bf0836a00f] Fetching instance by UUID get /usr/lib/python2.7/site-packages/nova/compute/api.py:2044
  2016-10-11 15:17:21.058 5348 DEBUG keystoneauth.session [req-283362c5-52d9-4eae-bfc0-3a77aab08a49 ab80bf62d3fa481c839331fdf43372df 09fdde1f50174a54b37af389d3f59144 - - -] REQ: curl -g -i -X GET http://d52-54-77-77-77-01.vg2.cloud.suse.de:9696/v2.0/ports.json?device_id=edb3fb97-af89-44bb-93a2-37bf0836a00f -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}ba2cdf92ae5d31935ba9b11abe2629b3f0cb9d65" _http_log_request /usr/lib/python2.7/site-packages/keystoneauth1/session.py:225
  2016-10-11 15:17:21.256 5348 DEBUG nova.osapi_compute.wsgi.server [req-01ff53e9-04d2-42b7-b511-f5b83721cdfc - - - - -] (5348) accepted ('192.168.251.84', 59040) server /usr/lib/python2.7/site-packages/eventlet/wsgi.py:867
  2016-10-11 15:17:21.262 5348 DEBUG nova.api.openstack.wsgi [req-b0c9b559-8fe4-4e87-9a68-dbbf5c6ac5a1 3bb802b643b34dabb231e931337f2340 e0052899ed0c4eecbd330d41ae8d4229 - - -] Action: 'create', calling method: <bound method ServerExternalEventsController.create of <nova.api.openstack.compute.server_external_events.ServerExternalEventsController object at 0x7fb3a0f84b10>>, body: {"events": [{"status": "completed", "tag": "f4d0048f-d18d-463f-9310-553bd5db948b", "name": "network-vif-plugged", "server_uuid": "edb3fb97-af89-44bb-93a2-37bf0836a00f"}, {"status": "completed", "tag": "79b2ea47-4a5e-4c7e-a277-63ba71daf593", "name": "network-vif-unplugged", "server_uuid": "7e3be027-0303-4ed8-8dfc-5c19a419901c"}]} _process_stack /usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py:696
  2016-10-11 15:17:21.357 5348 INFO nova.api.openstack.compute.server_external_events [req-b0c9b559-8fe4-4e87-9a68-dbbf5c6ac5a1 3bb802b643b34dabb231e931337f2340 e0052899ed0c4eecbd330d41ae8d4229 - - -] Creating event network-vif-plugged:f4d0048f-d18d-463f-9310-553bd5db948b for instance edb3fb97-af89-44bb-93a2-37bf0836a00f
  2016-10-11 15:17:21.380 5348 DEBUG keystoneauth.session [req-283362c5-52d9-4eae-bfc0-3a77aab08a49 ab80bf62d3fa481c839331fdf43372df 09fdde1f50174a54b37af389d3f59144 - - -] RESP: [200] Date: Tue, 11 Oct 2016 15:17:21 GMT Connection: close Content-Type: application/json; charset=UTF-8 Content-Length: 707 X-Openstack-Request-Id: req-bfcf45e2-8420-460c-8de3-78196d3b0912 
  RESP BODY: {"ports": [{"status": "ACTIVE", "created_at": "2016-10-11T15:17:12", "description": "", "allowed_address_pairs": [], "admin_state_up": true, "network_id": "77a204a8-f06c-43e4-87cc-5f7f123629f0", "tenant_id": "09fdde1f50174a54b37af389d3f59144", "extra_dhcp_opts": [], "updated_at": "2016-10-11T15:17:19", "name": "tempest-port-quotatest-1791242034", "device_owner": "compute:None", "mac_address": "fa:16:3e:ad:cc:e6", "binding:vnic_type": "normal", "fixed_ips": [{"subnet_id": "0cbe9fe9-65d8-41fb-8584-d6b561c5ea45", "ip_address": "10.100.0.3"}], "id": "f4d0048f-d18d-463f-9310-553bd5db948b", "security_groups": ["481cf3b7-b7bd-4bda-a102-bd5831d8b365"], "device_id": "edb3fb97-af89-44bb-93a2-37bf0836a00f"}]}
   _http_log_response /usr/lib/python2.7/site-packages/keystoneauth1/session.py:254
  2016-10-11 15:17:21.381 5348 DEBUG keystoneauth.session [req-283362c5-52d9-4eae-bfc0-3a77aab08a49 ab80bf62d3fa481c839331fdf43372df 09fdde1f50174a54b37af389d3f59144 - - -] REQ: curl -g -i -X GET http://d52-54-77-77-77-01.vg2.cloud.suse.de:9696/v2.0/security-groups.json?id=481cf3b7-b7bd-4bda-a102-bd5831d8b365 -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}ba2cdf92ae5d31935ba9b11abe2629b3f0cb9d65" _http_log_request /usr/lib/python2.7/site-packages/keystoneauth1/session.py:225
  2016-10-11 15:17:21.408 5348 INFO nova.api.openstack.compute.server_external_events [req-b0c9b559-8fe4-4e87-9a68-dbbf5c6ac5a1 3bb802b643b34dabb231e931337f2340 e0052899ed0c4eecbd330d41ae8d4229 - - -] Creating event network-vif-unplugged:79b2ea47-4a5e-4c7e-a277-63ba71daf593 for instance 7e3be027-0303-4ed8-8dfc-5c19a419901c
  2016-10-11 15:17:21.420 5348 INFO nova.osapi_compute.wsgi.server [req-b0c9b559-8fe4-4e87-9a68-dbbf5c6ac5a1 3bb802b643b34dabb231e931337f2340 e0052899ed0c4eecbd330d41ae8d4229 - - -] 192.168.251.84 "POST /v2.1/e0052899ed0c4eecbd330d41ae8d4229/os-server-external-events HTTP/1.1" status: 200 len: 619 time: 0.1625051
  2016-10-11 15:17:21.526 5348 DEBUG keystoneauth.session [req-283362c5-52d9-4eae-bfc0-3a77aab08a49 ab80bf62d3fa481c839331fdf43372df 09fdde1f50174a54b37af389d3f59144 - - -] RESP: [200] Date: Tue, 11 Oct 2016 15:17:21 GMT Connection: close Content-Type: application/json; charset=UTF-8 Content-Length: 1626 X-Openstack-Request-Id: req-5e93e595-96e0-4b41-9946-2e3e679cf048 
  RESP BODY: {"security_groups": [{"tenant_id": "09fdde1f50174a54b37af389d3f59144", "description": "Default security group", "id": "481cf3b7-b7bd-4bda-a102-bd5831d8b365", "security_group_rules": [{"direction": "ingress", "protocol": null, "description": "", "port_range_max": null, "id": "f24762b0-1c16-4585-94b1-96a7ee061335", "remote_group_id": "481cf3b7-b7bd-4bda-a102-bd5831d8b365", "remote_ip_prefix": null, "security_group_id": "481cf3b7-b7bd-4bda-a102-bd5831d8b365", "tenant_id": "09fdde1f50174a54b37af389d3f59144", "port_range_min": null, "ethertype": "IPv4"}, {"direction": "egress", "protocol": null, "description": "", "port_range_max": null, "id": "7c7d1340-ccea-4684-8b90-3821729c4577", "remote_group_id": null, "remote_ip_prefix": null, "security_group_id": "481cf3b7-b7bd-4bda-a102-bd5831d8b365", "tenant_id": "09fdde1f50174a54b37af389d3f59144", "port_range_min": null, "ethertype": "IPv4"}, {"direction": "ingress", "protocol": null, "description": "", "port_range_max": null, "id": "cb27eba0-9623-494c-8cbf-fea59de397ac", "remote_group_id": "481cf3b7-b7bd-4bda-a102-bd5831d8b365", "remote_ip_prefix": null, "security_group_id": "481cf3b7-b7bd-4bda-a102-bd5831d8b365", "tenant_id": "09fdde1f50174a54b37af389d3f59144", "port_range_min": null, "ethertype": "IPv6"}, {"direction": "egress", "protocol": null, "description": "", "port_range_max": null, "id": "1c02b335-7949-4070-8ef2-a2052b0cf578", "remote_group_id": null, "remote_ip_prefix": null, "security_group_id": "481cf3b7-b7bd-4bda-a102-bd5831d8b365", "tenant_id": "09fdde1f50174a54b37af389d3f59144", "port_range_min": null, "ethertype": "IPv6"}], "name": "default"}]}
   _http_log_response /usr/lib/python2.7/site-packages/keystoneauth1/session.py:254
  2016-10-11 15:17:21.527 5348 DEBUG nova.policy [req-283362c5-52d9-4eae-bfc0-3a77aab08a49 ab80bf62d3fa481c839331fdf43372df 09fdde1f50174a54b37af389d3f59144 - - -] Policy check for os_compute_api:os-extended-server-attributes failed with credentials {'domain': None, 'project_name': u'tempest-TestNetworkBasicOps-2111777401', 'project_domain': None, 'timestamp': '2016-10-11T15:17:20.937250', 'remote_address': '192.168.251.84', 'quota_class': None, 'resource_uuid': None, 'is_admin': False, 'user': u'ab80bf62d3fa481c839331fdf43372df', 'service_catalog': [{u'endpoints': [{u'adminURL': u'http://d52-54-77-77-77-01.vg2.cloud.suse.de:8776/v1/09fdde1f50174a54b37af389d3f59144', u'region': u'CustomRegion', u'internalURL': u'http://d52-54-77-77-77-01.vg2.cloud.suse.de:8776/v1/09fdde1f50174a54b37af389d3f59144', u'publicURL': u'http://10.164.193.2:8776/v1/09fdde1f50174a54b37af389d3f59144'}], u'type': u'volume', u'name': u'cinder'}, {u'endpoints': [{u'adminURL': u'http://d52-54-77-77-77-01.vg2.cloud.suse.de:8776/v2/09fdde1f50174a54b37af389d3f59144', u'region': u'CustomRegion', u'internalURL': u'http://d52-54-77-77-77-01.vg2.cloud.suse.de:8776/v2/09fdde1f50174a54b37af389d3f59144', u'publicURL': u'http://10.164.193.2:8776/v2/09fdde1f50174a54b37af389d3f59144'}], u'type': u'volumev2', u'name': u'cinderv2'}, {u'endpoints': [{u'adminURL': u'http://d52-54-77-77-77-01.vg2.cloud.suse.de:9311', u'region': u'CustomRegion', u'internalURL': u'http://d52-54-77-77-77-01.vg2.cloud.suse.de:9311', u'publicURL': u'http://10.164.193.2:9311'}], u'type': u'key-manager', u'name': u'barbican'}], 'tenant': u'09fdde1f50174a54b37af389d3f59144', 'read_only': False, 'project_id': u'09fdde1f50174a54b37af389d3f59144', 'user_id': u'ab80bf62d3fa481c839331fdf43372df', 'show_deleted': False, 'roles': [u'Member'], 'user_identity': 'ab80bf62d3fa481c839331fdf43372df 09fdde1f50174a54b37af389d3f59144 - - -', 'read_deleted': 'no', 'request_id': 'req-283362c5-52d9-4eae-bfc0-3a77aab08a49', 'instance_lock_checked': False, 'user_domain': None, 'user_name': u'tempest-TestNetworkBasicOps-1018360729'} enforce /usr/lib/python2.7/site-packages/nova/policy.py:107
  2016-10-11 15:17:21.528 5348 INFO nova.osapi_compute.wsgi.server [req-283362c5-52d9-4eae-bfc0-3a77aab08a49 ab80bf62d3fa481c839331fdf43372df 09fdde1f50174a54b37af389d3f59144 - - -] 192.168.251.84 "GET /v2.1/09fdde1f50174a54b37af389d3f59144/servers/edb3fb97-af89-44bb-93a2-37bf0836a00f HTTP/1.1" status: 200 len: 1813 time: 0.6017179
  2016-10-11 15:17:22.001 5346 DEBUG keystoneauth.session [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] RESP: [204] Date: Tue, 11 Oct 2016 15:17:22 GMT Connection: close Content-Length: 0 X-Openstack-Request-Id: req-0e41c9e5-00e4-45b8-a741-1379d69bd639 _http_log_response /usr/lib/python2.7/site-packages/keystoneauth1/session.py:254
  2016-10-11 15:17:22.001 5346 DEBUG nova.network.neutronv2.api [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c] _get_instance_nw_info() _get_instance_nw_info /usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py:927
  2016-10-11 15:17:22.006 5346 ERROR nova.network.base_api [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c] Failed storing info cache
  2016-10-11 15:17:22.006 5346 ERROR nova.network.base_api [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c] Traceback (most recent call last):
  2016-10-11 15:17:22.006 5346 ERROR nova.network.base_api [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c]   File "/usr/lib/python2.7/site-packages/nova/network/base_api.py", line 40, in update_instance_cache_with_nw_info
  2016-10-11 15:17:22.006 5346 ERROR nova.network.base_api [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c]     nw_info = impl._get_instance_nw_info(context, instance)
  2016-10-11 15:17:22.006 5346 ERROR nova.network.base_api [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c]   File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 931, in _get_instance_nw_info
  2016-10-11 15:17:22.006 5346 ERROR nova.network.base_api [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c]     compute_utils.refresh_info_cache_for_instance(context, instance)
  2016-10-11 15:17:22.006 5346 ERROR nova.network.base_api [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c]   File "/usr/lib/python2.7/site-packages/nova/compute/utils.py", line 357, in refresh_info_cache_for_instance
  2016-10-11 15:17:22.006 5346 ERROR nova.network.base_api [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c]     instance.info_cache.refresh()
  2016-10-11 15:17:22.006 5346 ERROR nova.network.base_api [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c]   File "/usr/lib/python2.7/site-packages/oslo_versionedobjects/base.py", line 223, in wrapper
  2016-10-11 15:17:22.006 5346 ERROR nova.network.base_api [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c]     return fn(self, *args, **kwargs)
  2016-10-11 15:17:22.006 5346 ERROR nova.network.base_api [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c]   File "/usr/lib/python2.7/site-packages/nova/objects/instance_info_cache.py", line 113, in refresh
  2016-10-11 15:17:22.006 5346 ERROR nova.network.base_api [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c]     self.instance_uuid)
  2016-10-11 15:17:22.006 5346 ERROR nova.network.base_api [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c]   File "/usr/lib/python2.7/site-packages/oslo_versionedobjects/base.py", line 181, in wrapper
  2016-10-11 15:17:22.006 5346 ERROR nova.network.base_api [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c]     result = fn(cls, context, *args, **kwargs)
  2016-10-11 15:17:22.006 5346 ERROR nova.network.base_api [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c]   File "/usr/lib/python2.7/site-packages/nova/objects/instance_info_cache.py", line 74, in get_by_instance_uuid
  2016-10-11 15:17:22.006 5346 ERROR nova.network.base_api [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c]     instance_uuid=instance_uuid)
  2016-10-11 15:17:22.006 5346 ERROR nova.network.base_api [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c] InstanceInfoCacheNotFound: Info cache for instance 7e3be027-0303-4ed8-8dfc-5c19a419901c could not be found.
  2016-10-11 15:17:22.006 5346 ERROR nova.network.base_api [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c] 
  2016-10-11 15:17:22.018 5346 DEBUG oslo_concurrency.lockutils [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] Releasing semaphore "refresh_cache-7e3be027-0303-4ed8-8dfc-5c19a419901c" lock /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:225
  2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] Unexpected exception in API method
  2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions Traceback (most recent call last):
  2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions   File "/usr/lib/python2.7/site-packages/nova/api/openstack/extensions.py", line 478, in wrapped
  2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions     return f(*args, **kwargs)
  2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions   File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/floating_ips.py", line 173, in delete
  2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions     context, instance, floating_ip)
  2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions   File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 1564, in disassociate_and_release_floating_ip
  2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions     floating_ip)
  2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions   File "/usr/lib/python2.7/site-packages/nova/network/base_api.py", line 79, in wrapper
  2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions     nw_info=res)
  2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions   File "/usr/lib/python2.7/site-packages/nova/hooks.py", line 154, in inner
  2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions     rv = f(*args, **kwargs)
  2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions   File "/usr/lib/python2.7/site-packages/nova/network/base_api.py", line 53, in update_instance_cache_with_nw_info
  2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions     LOG.exception(_LE('Failed storing info cache'), instance=instance)
  2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
  2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions     self.force_reraise()
  2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
  2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions     six.reraise(self.type_, self.value, self.tb)
  2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions   File "/usr/lib/python2.7/site-packages/nova/network/base_api.py", line 40, in update_instance_cache_with_nw_info
  2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions     nw_info = impl._get_instance_nw_info(context, instance)
  2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions   File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 931, in _get_instance_nw_info
  2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions     compute_utils.refresh_info_cache_for_instance(context, instance)
  2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions   File "/usr/lib/python2.7/site-packages/nova/compute/utils.py", line 357, in refresh_info_cache_for_instance
  2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions     instance.info_cache.refresh()
  2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions   File "/usr/lib/python2.7/site-packages/oslo_versionedobjects/base.py", line 223, in wrapper
  2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions     return fn(self, *args, **kwargs)
  2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions   File "/usr/lib/python2.7/site-packages/nova/objects/instance_info_cache.py", line 113, in refresh
  2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions     self.instance_uuid)
  2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions   File "/usr/lib/python2.7/site-packages/oslo_versionedobjects/base.py", line 181, in wrapper
  2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions     result = fn(cls, context, *args, **kwargs)
  2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions   File "/usr/lib/python2.7/site-packages/nova/objects/instance_info_cache.py", line 74, in get_by_instance_uuid
  2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions     instance_uuid=instance_uuid)
  2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions InstanceInfoCacheNotFound: Info cache for instance 7e3be027-0303-4ed8-8dfc-5c19a419901c could not be found.
  2016-10-11 15:17:22.018 5346 ERROR nova.api.openstack.extensions 
  2016-10-11 15:17:22.041 5346 INFO nova.api.openstack.wsgi [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] HTTP exception thrown: Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.
  <class 'nova.exception.InstanceInfoCacheNotFound'>
  2016-10-11 15:17:22.042 5346 DEBUG nova.api.openstack.wsgi [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] Returning 500 to user: Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.
  <class 'nova.exception.InstanceInfoCacheNotFound'> __call__ /usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py:1070
  2016-10-11 15:17:22.043 5346 INFO nova.osapi_compute.wsgi.server [req-911d6b75-3b94-4003-b3ec-232285d69834 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] 192.168.251.84 "DELETE /v2.1/f478dc6f6a274ef4a0e8284e9fb46b22/os-floating-ips/097e1998-5316-4416-ab9b-79c4b997ea8f HTTP/1.1" status: 500 len: 511 time: 1.6293600
  2016-10-11 15:17:22.059 5348 DEBUG nova.osapi_compute.wsgi.server [req-01ff53e9-04d2-42b7-b511-f5b83721cdfc - - - - -] (5348) accepted ('192.168.251.84', 59046) server /usr/lib/python2.7/site-packages/eventlet/wsgi.py:867
  2016-10-11 15:17:22.068 5348 DEBUG nova.api.openstack.wsgi [req-ce3ca9c9-87ad-492e-9e7b-84246227d4f6 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] Calling method '<bound method ServersController.delete of <nova.api.openstack.compute.servers.ServersController object at 0x7fb3a0dbedd0>>' _process_stack /usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py:699
  2016-10-11 15:17:22.070 5348 DEBUG nova.compute.api [req-ce3ca9c9-87ad-492e-9e7b-84246227d4f6 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c] Fetching instance by UUID get /usr/lib/python2.7/site-packages/nova/compute/api.py:2044
  2016-10-11 15:17:22.189 5348 DEBUG nova.compute.api [req-ce3ca9c9-87ad-492e-9e7b-84246227d4f6 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c] Going to try to terminate instance delete /usr/lib/python2.7/site-packages/nova/compute/api.py:1941
  2016-10-11 15:17:22.295 5348 INFO nova.osapi_compute.wsgi.server [req-ce3ca9c9-87ad-492e-9e7b-84246227d4f6 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] 192.168.251.84 "DELETE /v2.1/f478dc6f6a274ef4a0e8284e9fb46b22/servers/7e3be027-0303-4ed8-8dfc-5c19a419901c HTTP/1.1" status: 204 len: 269 time: 0.2338710
  2016-10-11 15:17:22.295 5346 DEBUG nova.osapi_compute.wsgi.server [req-46918002-2351-4561-916d-3e886840a8b7 - - - - -] (5346) accepted ('192.168.251.84', 59050) server /usr/lib/python2.7/site-packages/eventlet/wsgi.py:867
  2016-10-11 15:17:22.304 5346 DEBUG nova.api.openstack.wsgi [req-23d48f8e-7f62-4847-8d01-90aaa0f487ae 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] Calling method '<bound method ServersController.show of <nova.api.openstack.compute.servers.ServersController object at 0x7fb3a0dbedd0>>' _process_stack /usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py:699
  2016-10-11 15:17:22.305 5346 DEBUG nova.compute.api [req-23d48f8e-7f62-4847-8d01-90aaa0f487ae 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] [instance: 7e3be027-0303-4ed8-8dfc-5c19a419901c] Fetching instance by UUID get /usr/lib/python2.7/site-packages/nova/compute/api.py:2044
  2016-10-11 15:17:22.373 5346 INFO nova.api.openstack.wsgi [req-23d48f8e-7f62-4847-8d01-90aaa0f487ae 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] HTTP exception thrown: Instance 7e3be027-0303-4ed8-8dfc-5c19a419901c could not be found.
  2016-10-11 15:17:22.375 5346 DEBUG nova.api.openstack.wsgi [req-23d48f8e-7f62-4847-8d01-90aaa0f487ae 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] Returning 404 to user: Instance 7e3be027-0303-4ed8-8dfc-5c19a419901c could not be found. __call__ /usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py:1070
  2016-10-11 15:17:22.379 5348 DEBUG nova.osapi_compute.wsgi.server [req-01ff53e9-04d2-42b7-b511-f5b83721cdfc - - - - -] (5348) accepted ('192.168.251.84', 59054) server /usr/lib/python2.7/site-packages/eventlet/wsgi.py:867
  2016-10-11 15:17:22.382 5346 INFO nova.osapi_compute.wsgi.server [req-23d48f8e-7f62-4847-8d01-90aaa0f487ae 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] 192.168.251.84 "GET /v2.1/f478dc6f6a274ef4a0e8284e9fb46b22/servers/7e3be027-0303-4ed8-8dfc-5c19a419901c HTTP/1.1" status: 404 len: 396 time: 0.0852270
  2016-10-11 15:17:22.384 5348 DEBUG nova.api.openstack.wsgi [req-907b132d-d02d-476f-83be-2168c06470ba 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] Calling method '<bound method SecurityGroupController.delete of <nova.api.openstack.compute.security_groups.SecurityGroupController object at 0x7fb3a107a510>>' _process_stack /usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py:699
  2016-10-11 15:17:22.388 5348 DEBUG keystoneauth.session [req-907b132d-d02d-476f-83be-2168c06470ba 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] REQ: curl -g -i -X GET http://d52-54-77-77-77-01.vg2.cloud.suse.de:9696/v2.0/security-groups/c29e2129-6410-493d-afe8-2e329dc90c63.json -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}228810fa07ce0224199bc54d7ea65f023e8ded81" _http_log_request /usr/lib/python2.7/site-packages/keystoneauth1/session.py:225
  2016-10-11 15:17:22.434 5348 DEBUG keystoneauth.session [req-907b132d-d02d-476f-83be-2168c06470ba 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] RESP: [200] Date: Tue, 11 Oct 2016 15:17:22 GMT Connection: close Content-Type: application/json; charset=UTF-8 Content-Length: 1623 X-Openstack-Request-Id: req-3fe49220-4617-4739-b73e-2e4a6c1bc2f6 
  RESP BODY: {"security_group": {"tenant_id": "f478dc6f6a274ef4a0e8284e9fb46b22", "description": "tempest-TestServerBasicOps-494331381 description", "id": "c29e2129-6410-493d-afe8-2e329dc90c63", "security_group_rules": [{"direction": "ingress", "protocol": "icmp", "description": "", "port_range_max": null, "id": "1c6b6af1-d01a-49c8-a242-bc72ae5d9a80", "remote_group_id": null, "remote_ip_prefix": "0.0.0.0/0", "security_group_id": "c29e2129-6410-493d-afe8-2e329dc90c63", "tenant_id": "f478dc6f6a274ef4a0e8284e9fb46b22", "port_range_min": null, "ethertype": "IPv4"}, {"direction": "egress", "protocol": null, "description": "", "port_range_max": null, "id": "9db46a71-58fc-4637-aa1d-e283ed19e567", "remote_group_id": null, "remote_ip_prefix": null, "security_group_id": "c29e2129-6410-493d-afe8-2e329dc90c63", "tenant_id": "f478dc6f6a274ef4a0e8284e9fb46b22", "port_range_min": null, "ethertype": "IPv4"}, {"direction": "egress", "protocol": null, "description": "", "port_range_max": null, "id": "0160e537-354b-4716-bc81-76ac1449c054", "remote_group_id": null, "remote_ip_prefix": null, "security_group_id": "c29e2129-6410-493d-afe8-2e329dc90c63", "tenant_id": "f478dc6f6a274ef4a0e8284e9fb46b22", "port_range_min": null, "ethertype": "IPv6"}, {"direction": "ingress", "protocol": "tcp", "description": "", "port_range_max": 22, "id": "dc316241-79d8-4b96-bde9-c3bb673876c3", "remote_group_id": null, "remote_ip_prefix": "0.0.0.0/0", "security_group_id": "c29e2129-6410-493d-afe8-2e329dc90c63", "tenant_id": "f478dc6f6a274ef4a0e8284e9fb46b22", "port_range_min": 22, "ethertype": "IPv4"}], "name": "tempest-TestServerBasicOps-494331381"}}
   _http_log_response /usr/lib/python2.7/site-packages/keystoneauth1/session.py:254
  2016-10-11 15:17:22.435 5348 DEBUG keystoneauth.session [req-907b132d-d02d-476f-83be-2168c06470ba 6d03f6736e16470a9050eb1e24f25a76 f478dc6f6a274ef4a0e8284e9fb46b22 - - -] REQ: curl -g -i -X DELETE http://d52-54-77-77-77-01.vg2.cloud.suse.de:9696/v2.0/security-groups/c29e2129-6410-493d-afe8-2e329dc90c63.json -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}228810fa07ce0224199bc54d7ea65f023e8ded81" _http_log_request /usr/lib/python2.7/site-packages/keystoneauth1/session.py:225
  2016-10-11 15:17:22.558 5348 DEBUG nova.osapi_compute.wsgi.server [req-01ff53e9-04d2-42b7-b511-f5b83721cdfc - - - - -] (5348) accepted ('192.168.251.84', 59062) server /usr/lib/python2.7/site-packages/eventlet/wsgi.py:867
  2016-10-11 15:17:22.572 5348 DEBUG nova.api.openstack.wsgi [req-4447a07b-ee79-4ee2-9599-5ac3affd24fb ab80bf62d3fa481c839331fdf43372df 09fdde1f50174a54b37af389d3f59144 - - -] Calling method '<bound method ServersController.show of <nova.api.openstack.compute.servers.ServersController object at 0x7fb3a0dbedd0>>' _process_stack /usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py:699
  2016-10-11 15:17:22.573 5348 DEBUG nova.compute.api [req-4447a07b-ee79-4ee2-9599-5ac3affd24fb ab80bf62d3fa481c839331fdf43372df 09fdde1f50174a54b37af389d3f59144 - - -] [instance: edb3fb97-af89-44bb-93a2-37bf0836a00f] Fetching instance by UUID get /usr/lib/python2.7/site-packages/nova/compute/api.py:2044

To manage notifications about this bug go to:
https://bugs.launchpad.net/nova/+bug/1632403/+subscriptions
Follow ups

[Bug 1632403] Re: InstanceInfoCacheNotFound: Info cache for instance 7e3be027-0303-4ed8-8dfc-5c19a419901c could not be found
From: OpenStack Infra, 2017-09-21
[Bug 1632403] Re: InstanceInfoCacheNotFound: Info cache for instance 7e3be027-0303-4ed8-8dfc-5c19a419901c could not be found
From: Matt Riedemann, 2017-08-08
[Bug 1632403] Re: InstanceInfoCacheNotFound: Info cache for instance 7e3be027-0303-4ed8-8dfc-5c19a419901c could not be found
From: Matt Riedemann, 2016-11-16