Bug #1268274 “KeyError in _get_server_ip” : Bugs : tempest

Revision history for this message

Armando Migliaccio (armando-migliaccio) wrote on 2014-02-22:

#1

This might be triggered by Neutron but there's no good excuse for Tempest to spit out a KeyError like this.

Revision history for this message

Armando Migliaccio (armando-migliaccio) wrote on 2014-02-22:

#2

Similar stacktrace:

Traceback (most recent call last):
  File "tempest/scenario/test_security_groups_basic_ops.py", line 173, in setUp
    self._verify_mac_addr(self.primary_tenant)
  File "tempest/scenario/test_security_groups_basic_ops.py", line 456, in _verify_mac_addr
    server_ip = self._get_server_ip(tenant.access_point)
  File "tempest/scenario/test_security_groups_basic_ops.py", line 324, in _get_server_ip
    return server.networks[network_name][0]
KeyError: u'network-smoke--2062576759'

Occurrence here:

http://logs.openstack.org/88/67288/15/gate/gate-tempest-dsvm-neutron-pg/d7a3cc5/logs/testr_results.html.gz

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2014-02-22: Related fix proposed to tempest (master)

#3

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

Armando Migliaccio (armando-migliaccio) on 2014-02-22

Changed in tempest:
status:	New → In Progress
assignee:	nobody → Armando Migliaccio (armando-migliaccio)

Revision history for this message

Armando Migliaccio (armando-migliaccio) wrote on 2014-02-22:

#5

Download full text (7.2 KiB)

I think this fails because when the server boots up, a call to Nova to show the Server details returns no network information:

RESP BODY: {"server": {"status": "ACTIVE", "updated": "2014-02-22T02:49:14Z", "hostId": "b6b929e9b38fe925dd96096914de11b6931941fbff8157352696bb07", "addresses": {}, "links": [{"href": "http://127.0.0.1:8774/v2/2889867c5b1e4e179468e0335bd7f60e/servers/56a1c377-ff6b-4b84-954c-e9bc7df34915", "rel": "self"}, {"href": "http://127.0.0.1:8774/2889867c5b1e4e179468e0335bd7f60e/servers/56a1c377-ff6b-4b84-954c-e9bc7df34915", "rel": "bookmark"}], "key_name": "keypair-smoke--1833441024", "image": {"id": "d6a7eadc-beb7-48ee-ac12-2c450822fba3", "links": [{"href": "http://127.0.0.1:8774/2889867c5b1e4e179468e0335bd7f60e/images/d6a7eadc-beb7-48ee-ac12-2c450822fba3", "rel": "bookmark"}]}, "OS-EXT-STS:task_state": null, "OS-EXT-STS:vm_state": "active", "OS-SRV-USG:launched_at": "2014-02-22T02:49:14.000000", "flavor": {"id": "42", "links": [{"href": "http://127.0.0.1:8774/2889867c5b1e4e179468e0335bd7f60e/flavors/42", "rel": "bookmark"}]}, "id": "56a1c377-ff6b-4b84-954c-e9bc7df34915", "security_groups": [{"name": "secgroup_access--1740712187"}, {"name": "secgroup_general--1734494704"}], "OS-SRV-USG:terminated_at": null, "OS-EXT-AZ:availability_zone": "nova", "user_id": "6dba13b494db45a2bf3748fd78561183", "name": "server-TestSecurityGroupsBasicOps-773273890-access_point--1654550048", "created": "2014-02-22T02:49:09Z", "tenant_id": "2889867c5b1e4e179468e0335bd7f60e", "OS-DCF:diskConfig": "MANUAL", "os-extended-volumes:volumes_attached": [], "accessIPv4": "", "accessIPv6": "", "progress": 0, "OS-EXT-STS:power_state": 1, "config_drive": "", "metadata": {}}}

See in particular:

"accessIPv4": "", "accessIPv6": "",

Looking at the nova-api log, it shows that the cache is updated with empty values:

2014-02-22 02:49:40.701 DEBUG nova.network.neutronv2.api [req-f2d4697c-81ac-4c86-bc81-9f214f8a1fef None None] get_instance_nw_info() for server-TestSecurityGroupsBasicOps-773273890-access_point--1654550048 _get_instance_nw_info /opt/stack/new/nova/nova/network/neutronv2/api.py:452
2014-02-22 02:49:40.702 10897 DEBUG neutronclient.client [-]
REQ: curl -i http://127.0.0.1:35357/v2.0/tokens -X POST -H "Content-Type: application/json" -H "Accept: application/json" -H "User-Agent: python-neutronclient" -d '{"auth": {"tenantName": "service", "passwordCredentials": {"username": "neutron", "password": "REDACTED"}}}'
http_log_req /opt/stack/new/python-neutronclient/neutronclient/common/utils.py:173
2014-02-22 02:49:40.861 10897 DEBUG neutronclient.client [-] RESP:{'date': 'Sat, 22 Feb 2014 02:49:40 GMT', 'vary': 'X-Auth-Token', 'content-length': '11103', 'status': '200', 'content-type': 'application/json'} {"access": {"token": {"issued_at": "2014-02-22T02:49:40.805621", "expires": "2014-02-22T03:49:40Z", "id": PweI3glfY1abptlwkIYdQS0d4rl2VMwYhACyZZuM55INXOIOf57bvD0LvCd0rkItxtfEK4q-AQj4YLkc-V--t2Tl8u+ss523qxinHdNVv+806XQsE=" -H "Content-Type: application/json" -H "Accept: application/json" -H "User-Agent: python-neutronclient"
http_log_req /opt/stack/new/python-neutronclient/neutronclient/common/utils.py:173
2014-02-22 02:49:41.044 10897 DEBUG neutronclient...

I think this fails because when the server boots up, a call to Nova to show the Server details returns no network information:

RESP BODY: {"server": {"status": "ACTIVE", "updated": "2014-02-22T02:49:14Z", "hostId": "b6b929e9b38fe925dd96096914de11b6931941fbff8157352696bb07", "addresses": {}, "links": [{"href": "http://127.0.0.1:8774/v2/2889867c5b1e4e179468e0335bd7f60e/servers/56a1c377-ff6b-4b84-954c-e9bc7df34915", "rel": "self"}, {"href": "http://127.0.0.1:8774/2889867c5b1e4e179468e0335bd7f60e/servers/56a1c377-ff6b-4b84-954c-e9bc7df34915", "rel": "bookmark"}], "key_name": "keypair-smoke--1833441024", "image": {"id": "d6a7eadc-beb7-48ee-ac12-2c450822fba3", "links": [{"href": "http://127.0.0.1:8774/2889867c5b1e4e179468e0335bd7f60e/images/d6a7eadc-beb7-48ee-ac12-2c450822fba3", "rel": "bookmark"}]}, "OS-EXT-STS:task_state": null, "OS-EXT-STS:vm_state": "active", "OS-SRV-USG:launched_at": "2014-02-22T02:49:14.000000", "flavor": {"id": "42", "links": [{"href": "http://127.0.0.1:8774/2889867c5b1e4e179468e0335bd7f60e/flavors/42", "rel": "bookmark"}]}, "id": "56a1c377-ff6b-4b84-954c-e9bc7df34915", "security_groups": [{"name": "secgroup_access--1740712187"}, {"name": "secgroup_general--1734494704"}], "OS-SRV-USG:terminated_at": null, "OS-EXT-AZ:availability_zone": "nova", "user_id": "6dba13b494db45a2bf3748fd78561183", "name": "server-TestSecurityGroupsBasicOps-773273890-access_point--1654550048", "created": "2014-02-22T02:49:09Z", "tenant_id": "2889867c5b1e4e179468e0335bd7f60e", "OS-DCF:diskConfig": "MANUAL", "os-extended-volumes:volumes_attached": [], "accessIPv4": "", "accessIPv6": "", "progress": 0, "OS-EXT-STS:power_state": 1, "config_drive": "", "metadata": {}}}

See in particular:

"accessIPv4": "", "accessIPv6": "",

Looking at the nova-api log, it shows that the cache is updated with empty values:

2014-02-22 02:49:40.701 DEBUG nova.network.neutronv2.api [req-f2d4697c-81ac-4c86-bc81-9f214f8a1fef None None] get_instance_nw_info() for server-TestSecurityGroupsBasicOps-773273890-access_point--1654550048 _get_instance_nw_info /opt/stack/new/nova/nova/network/neutronv2/api.py:452
2014-02-22 02:49:40.702 10897 DEBUG neutronclient.client [-] 
REQ: curl -i http://127.0.0.1:35357/v2.0/tokens -X POST -H "Content-Type: application/json" -H "Accept: application/json" -H "User-Agent: python-neutronclient" -d '{"auth": {"tenantName": "service", "passwordCredentials": {"username": "neutron", "password": "REDACTED"}}}'
 http_log_req /opt/stack/new/python-neutronclient/neutronclient/common/utils.py:173
2014-02-22 02:49:40.861 10897 DEBUG neutronclient.client [-] RESP:{'date': 'Sat, 22 Feb 2014 02:49:40 GMT', 'vary': 'X-Auth-Token', 'content-length': '11103', 'status': '200', 'content-type': 'application/json'} {"access": {"token": {"issued_at": "2014-02-22T02:49:40.805621", "expires": "2014-02-22T03:49:40Z", "id": PweI3glfY1abptlwkIYdQS0d4rl2VMwYhACyZZuM55INXOIOf57bvD0LvCd0rkItxtfEK4q-AQj4YLkc-V--t2Tl8u+ss523qxinHdNVv+806XQsE=" -H "Content-Type: application/json" -H "Accept: application/json" -H "User-Agent: python-neutronclient"
 http_log_req /opt/stack/new/python-neutronclient/neutronclient/common/utils.py:173
2014-02-22 02:49:41.044 10897 DEBUG neutronclient.client [-] RESP:{'status': '200', 'content-length': '770', 'content-location': 'http://127.0.0.1:9696/v2.0/ports.json?tenant_id=2889867c5b1e4e179468e0335bd7f60e&device_id=56a1c377-ff6b-4b84-954c-e9bc7df34915', 'date': 'Sat, 22 Feb 2014 02:49:41 GMT', 'content-type': 'application/json; charset=UTF-8', 'x-openstack-request-id': 'req-83c43368-3570-41a7-9ddf-50c3a50502d9'} {"ports": [{"status": "ACTIVE", "binding:host_id": "devstack-precise-rax-iad-1544972.slave.openstack.org", "name": "", "allowed_address_pairs": [], "admin_state_up": true, "network_id": "199dbbef-5c2c-486f-9820-be24507dab79", "tenant_id": "2889867c5b1e4e179468e0335bd7f60e", "extra_dhcp_opts": [], "binding:vnic_type": "normal", "binding:vif_type": "ovs", "device_owner": "compute:None", "binding:capabilities": {"port_filter": true}, "mac_address": "fa:16:3e:17:85:ea", "fixed_ips": [{"subnet_id": "6ee7a2fd-85bd-4e27-819b-83be3c9bf04c", "ip_address": "10.100.0.2"}], "id": "31359295-58a6-423b-82d9-7c03ab732214", "security_groups": ["39365abb-9835-48a4-8521-da873e0e7150", "bae6b784-e0c5-4665-8a1d-03e68320e8f2"], "device_id": "56a1c377-ff6b-4b84-954c-e9bc7df34915"}]}
 http_log_resp /opt/stack/new/python-neutronclient/neutronclient/common/utils.py:179
2014-02-22 02:49:41.044 10897 DEBUG neutronclient.client [-] 
REQ: curl -i http://127.0.0.1:9696/v2.0/networks.json?tenant_id=2889867c5b1e4e179468e0335bd7f60e&shared=False -X GET -H "X-Auth-Token: MIeI3glfY1abptlwkIYdQS0d4rl2VMwYhACyZZuM55INXOIOf57bvD0LvCd0rkItxtfEK4q-AQj4YLkc-V--t2Tl8u+ss523qxinHdNVv+806XQsE=" -H "Content-Type: application/json" -H "Accept: application/json" -H "User-Agent: python-neutronclient"
 http_log_req /opt/stack/new/python-neutronclient/neutronclient/common/utils.py:173
2014-02-22 02:49:41.070 10897 DEBUG neutronclient.client [-] RESP:{'status': '200', 'content-length': '788', 'content-location': 'http://127.0.0.1:9696/v2.0/networks.json?tenant_id=2889867c5b1e4e179468e0335bd7f60e&shared=False', 'date': 'Sat, 22 Feb 2014 02:49:41 GMT', 'content-type': 'application/json; charset=UTF-8', 'x-openstack-request-id': 'req-8a85deda-f944-4f46-85f7-02cf4b78e5d5'} {"networks": [{"status": "ACTIVE", "subnets": ["c9d4660b-119e-4373-87bf-c57f1916d040"], "name": "TestSecurityGroupsBasicOps-2111281772-network", "provider:physical_network": null, "admin_state_up": true, "tenant_id": "2889867c5b1e4e179468e0335bd7f60e", "provider:network_type": "local", "router:external": false, "shared": false, "id": "9c164247-e2d4-44f0-a72e-8d915cc90fad", "provider:segmentation_id": null}, {"status": "ACTIVE", "subnets": ["6ee7a2fd-85bd-4e27-819b-83be3c9bf04c"], "name": "network-smoke--2062576759", "provider:physical_network": null, "admin_state_up": true, "tenant_id": "2889867c5b1e4e179468e0335bd7f60e", "provider:network_type": "local", "router:external": false, "shared": false, "id": "199dbbef-5c2c-486f-9820-be24507dab79", "provider:segmentation_id": null}]}
 http_log_resp /opt/stack/new/python-neutronclient/neutronclient/common/utils.py:179
2014-02-22 02:49:41.070 10897 DEBUG neutronclient.client [-] 
REQ: curl -i http://127.0.0.1:9696/v2.0/networks.json?shared=True -X GET -H "X-Auth-Token: MIITVwYJKoZIhvcNAQcCoIITSDCCE0QCAQExCTAHBgUrDgMCGjCCEa0GCSqGSIb3DQEHAaCCEZ4EghGaeyJhY2Nlc3MiOiB7InRva2VuIjogeyJpc3N1ZWRfHdNVv+806XQsE=" -H "Content-Type: application/json" -H "Accept: application/json" -H "User-Agent: python-neutronclient"
 http_log_req /opt/stack/new/python-neutronclient/neutronclient/common/utils.py:173
2014-02-22 02:49:41.078 10897 DEBUG neutronclient.client [-] RESP:{'status': '200', 'content-length': '16', 'content-location': 'http://127.0.0.1:9696/v2.0/networks.json?shared=True', 'date': 'Sat, 22 Feb 2014 02:49:41 GMT', 'content-type': 'application/json; charset=UTF-8', 'x-openstack-request-id': 'req-6c4059aa-0895-4bbd-b79c-0b6c70cfc0f0'} {"networks": []}
 http_log_resp /opt/stack/new/python-neutronclient/neutronclient/common/utils.py:179
2014-02-22 02:49:41.079 DEBUG nova.network.api [req-f2d4697c-81ac-4c86-bc81-9f214f8a1fef None None] Updating cache with info: [] update_instance_cache_with_nw_info /opt/stack/new/nova/nova/network/api.py:70

Why that is, remains the usual mistery...

Revision history for this message

Armando Migliaccio (armando-migliaccio) wrote on 2014-02-22:

#6

Ultimately this might be yet another manifestation of issues related to Neutron, Nova and instance cache

Revision history for this message

Matt Riedemann (mriedem) wrote on 2014-02-22:

#7

http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOlwicmV0dXJuIHNlcnZlci5uZXR3b3Jrc1tuZXR3b3JrX25hbWVdWzBdXCIgQU5EIGZpbGVuYW1lOlwiY29uc29sZS5odG1sXCIiLCJmaWVsZHMiOltdLCJvZmZzZXQiOjAsInRpbWVmcmFtZSI6IjYwNDgwMCIsImdyYXBobW9kZSI6ImNvdW50IiwidGltZSI6eyJ1c2VyX2ludGVydmFsIjowfSwic3RhbXAiOjEzOTMxMDM2OTUyODR9

tags:

added: network testing

Revision history for this message

Matt Riedemann (mriedem) wrote on 2014-02-22:

#8

e-r query is here: https://review.openstack.org/#/c/75649/

Revision history for this message

Armando Migliaccio (armando-migliaccio) wrote on 2014-02-22:

#9

Nice, thanks Matt!

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2014-02-24: Related fix merged to tempest (master)

#10

Reviewed: https://review.openstack.org/75610
Committed: https://git.openstack.org/cgit/openstack/tempest/commit/?id=d03f26409761a9a40222668e208bbf66016dd777
Submitter: Jenkins
Branch: master

commit d03f26409761a9a40222668e208bbf66016dd777
Author: armando-migliaccio <email address hidden>
Date: Fri Feb 21 19:55:50 2014 -0800

Avoid masking an assert failure with a KeyError Exception

    This patch does not address the underlying issue as to
    why the key was not in the data dictionary, but it serves
    the purpose of getting a better error message due to the
    failure in meeting the pre-conditions to the test.

Change-Id: I507a34456e8d047728bb7c1d1e5d189e3d00e7c1
Related-bug: #1268274

Revision history for this message

Joe Gordon (jogo) wrote on 2014-02-26:

#11

what is the nova issue here? the keyerror appears to becoming from tempest.

Changed in nova:
status:	New → Incomplete

Revision history for this message

Armando Migliaccio (armando-migliaccio) wrote on 2014-02-27:

#12

Joe, please refer to comment #6.

Revision history for this message

Armando Migliaccio (armando-migliaccio) wrote on 2014-02-27:

#13

This bug would've not manifested itself if it wasn't for Nova not reporting the port information correctly.

Changed in tempest:
status:	In Progress → Fix Committed

Joe Gordon (jogo) on 2014-03-12

Changed in neutron:
status:	New → Invalid

Revision history for this message

Aaron Rosen (arosen) wrote on 2014-03-21:

#14

No hits here: http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOlwicmV0dXJuIHNlcnZlci5uZXR3b3Jrc1tuZXR3b3JrX25hbWVdWzBdXCIgQU5EIGZpbGVuYW1lOlwiY29uc29sZS5odG1sXCIiLCJmaWVsZHMiOltdLCJvZmZzZXQiOjAsInRpbWVmcmFtZSI6IjYwNDgwMCIsImdyYXBobW9kZSI6ImNvdW50IiwidGltZSI6eyJ1c2VyX2ludGVydmFsIjowfSwic3RhbXAiOjEzOTMxMDM2OTUyODR9 for the past 7 days. CLosing.

no longer affects:

nova

Matthew Treinish (treinish) on 2014-09-09

Changed in tempest:
status:	Fix Committed → Fix Released

Affects		Status	Importance	Assigned to	Milestone
	neutron	Invalid	Undecided	Unassigned
	tempest	Fix Released	Undecided	Armando Migliaccio

tempest

KeyError in _get_server_ip

Bug Description

Other bug subscribers

Remote bug watches