OpenStack Compute (nova)

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

  1. Series ocata
  2. Bug #1632403
Bug #1632403 reported by Thomas Bechtold
10
This bug affects 2 people
Affects Status Importance Assigned to Milestone
OpenStack Compute (nova)
Fix Released
Medium
Thomas Bechtold
Ocata
New
Undecided
Unassigned

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

Revision history for this message
Matt Riedemann (mriedem) wrote :

Is this intermittent or repeatable? Does it happen on newton?

Revision history for this message
Thomas Bechtold (toabctl) wrote :

it is happening with Newton. Not always, but pretty often (~50%)

Revision history for this message
Thomas Bechtold (toabctl) wrote :

I think this patch is responsible for the error: https://review.openstack.org/#/c/357494/

The instance is already deleted when trying to refresh the cache.

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to nova (stable/newton)

Fix proposed to branch: stable/newton
Review: https://review.openstack.org/398307

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Change abandoned on nova (stable/newton)

Change abandoned by Thomas Bechtold (<email address hidden>) on branch: stable/newton
Review: https://review.openstack.org/398307
Reason: wrong branch.sorry

Changed in nova:
assignee: nobody → Thomas Bechtold (toabctl)
status: New → In Progress
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to nova (master)

Fix proposed to branch: master
Review: https://review.openstack.org/398308

Matt Riedemann (mriedem)
Changed in nova:
importance: Undecided → Medium
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Change abandoned on nova (master)

Change abandoned by Sean Dague (<email address hidden>) on branch: master
Review: https://review.openstack.org/398308
Reason: This review is > 4 weeks without comment, and is not mergable in it's current state. We are abandoning this for now. Feel free to reactivate the review by pressing the restore button and leaving a 'recheck' comment to get fresh test results.

Revision history for this message
Sean Dague (sdague) wrote :

There are no currently open reviews on this bug, changing the status back to the previous state and unassigning. If there are active reviews related to this bug, please include links in comments.

Changed in nova:
status: In Progress → New
assignee: Thomas Bechtold (toabctl) → nobody
Revision history for this message
Sean Dague (sdague) wrote :

Is this still a real issue? It's pretty old

Changed in nova:
status: New → Incomplete
Revision history for this message
Stefan Nica (stefan.nica) wrote :

I can confirm that this is still a real issue. Moreover, it's now reproducible with Ocata too (same symptoms).

Thomas Bechtold (toabctl)
Changed in nova:
status: Incomplete → Confirmed
Revision history for this message
Thomas Bechtold (toabctl) wrote :

Fix is still https://review.openstack.org/#/c/398308/

Changed in nova:
assignee: nobody → Thomas Bechtold (toabctl)
status: Confirmed → In Progress
Matt Riedemann (mriedem)
no longer affects: nova/mitaka
no longer affects: nova/newton
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to nova (master)

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

commit d3bc8c4c58160c4b7e6b86034ca9a3a174767f3b
Author: Thomas Bechtold <email address hidden>
Date: Wed Nov 16 12:39:23 2016 +0100

    Handle deleted instances when refreshing the info_cache

    Commit cdb9b6820dc1 added code to refresh Neutron's info_cache after
    a associated floating IP was deleted. This fails in case the instance
    itself is deleted. The failure is then:

    InstanceInfoCacheNotFound: Info cache for instance $UUID could not \
                               be found.

    So when refreshing the cache, catch the InstanceInfoCacheNotFound
    exception.

    Change-Id: I560b28f3ec9e017f6a178bf5120534e21d0b9800
    Closes-Bug: #1632403

Changed in nova:
status: In Progress → Fix Released
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to nova (stable/pike)

Fix proposed to branch: stable/pike
Review: https://review.openstack.org/506183

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to nova (stable/pike)

Reviewed: https://review.openstack.org/506183
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=51edffd1cb4cd470bb4d98b219ba2b6ff311c8e5
Submitter: Jenkins
Branch: stable/pike

commit 51edffd1cb4cd470bb4d98b219ba2b6ff311c8e5
Author: Thomas Bechtold <email address hidden>
Date: Wed Nov 16 12:39:23 2016 +0100

    Handle deleted instances when refreshing the info_cache

    Commit cdb9b6820dc1 added code to refresh Neutron's info_cache after
    a associated floating IP was deleted. This fails in case the instance
    itself is deleted. The failure is then:

    InstanceInfoCacheNotFound: Info cache for instance $UUID could not \
                               be found.

    So when refreshing the cache, catch the InstanceInfoCacheNotFound
    exception.

    Change-Id: I560b28f3ec9e017f6a178bf5120534e21d0b9800
    Closes-Bug: #1632403
    (cherry picked from commit d3bc8c4c58160c4b7e6b86034ca9a3a174767f3b)

tags: added: in-stable-pike
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix included in openstack/nova 17.0.0.0b1

This issue was fixed in the openstack/nova 17.0.0.0b1 development milestone.

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix included in openstack/nova 16.0.2

This issue was fixed in the openstack/nova 16.0.2 release.

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.