test_admin_create_network_keystone_v3 failed with KeyError: 'project_id'

[Ihar Hrachyshka]

ft1.1: neutron.tests.tempest.api.admin.test_networks.NetworksTestAdmin.test_admin_create_network_keystone_v3[id-d3c76044-d067-4cb0-ae47-8cdd875c7f67]_StringException: Empty attachments:
  stderr
  stdout

pythonlogging:'': {{{
2017-03-15 05:06:00,443 8618 INFO [tempest.lib.common.rest_client] Request (NetworksTestAdmin:test_admin_create_network_keystone_v3): 201 POST http://158.69.89.86/identity/v3/auth/tokens
2017-03-15 05:06:00,444 8618 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Accept': 'application/json', 'Content-Type': 'application/json'}
        Body: <omitted>
    Response - Headers: {'content-location': 'http://158.69.89.86/identity/v3/auth/tokens', u'content-length': '3667', u'x-openstack-request-id': 'req-87ad6c4d-f31c-4b0f-9d09-f0dfea7967ef', u'vary': 'X-Auth-Token', u'date': 'Wed, 15 Mar 2017 05:06:00 GMT', u'connection': 'close', u'content-type': 'application/json', u'server': 'Apache/2.4.18 (Ubuntu)', 'status': '201', u'x-subject-token': '<omitted>'}
        Body: {"token": {"is_domain": false, "methods": ["password"], "roles": [{"id": "49586c062a164a0387b2c81ef73f28c2", "name": "admin"}, {"id": "9cca5926cfa14c84a060bf4926657c07", "name": "Member"}], "expires_at": "2017-03-15T06:06:00.000000Z", "project": {"domain": {"id": "default", "name": "Default"}, "id": "0d567c4487d049988d49a79acd159b42", "name": "tempest-NetworksTestAdmin-1042551292"}, "catalog": [{"endpoints": [{"url": "http://158.69.89.86:8080", "interface": "admin", "region": "RegionOne", "region_id": "RegionOne", "id": "0134e566b4a3417bac59232f7581214b"}, {"url": "http://158.69.89.86:8080/v1/AUTH_0d567c4487d049988d49a79acd159b42", "interface": "public", "region": "RegionOne", "region_id": "RegionOne", "id": "62fed52298d6447f81a6caa4aab41254"}], "type": "object-store", "id": "0b9611b345d04326a6fd47661adfd998", "name": "swift"}, {"endpoints": [{"url": "http://158.69.89.86/placement", "interface": "public", "region": "RegionOne", "region_id": "RegionOne", "id": "12e21ad49605441ca3c2b197523905f1"}], "type": "placement", "id": "2cd7d15b20794d21b920e8636dbf590a", "name": "placement"}, {"endpoints": [{"url": "http://158.69.89.86:8776/v1/0d567c4487d049988d49a79acd159b42", "interface": "public", "region": "RegionOne", "region_id": "RegionOne", "id": "c064e8594368493b968a8f3ba91df6ab"}], "type": "volume", "id": "2ce6191d34104ac39017cb0ccc8fbb97", "name": "cinder"}, {"endpoints": [{"url": "http://158.69.89.86:8774/v2.1", "interface": "public", "region": "RegionOne", "region_id": "RegionOne", "id": "e2d7023e14c54fa693919d9bcdcca435"}], "type": "compute", "id": "2cfbccc3ee9848aebcbc32aef3ec351d", "name": "nova"}, {"endpoints": [{"url": "http://158.69.89.86:8774/v2/0d567c4487d049988d49a79acd159b42", "interface": "public", "region": "RegionOne", "region_id": "RegionOne", "id": "3c848f675f1047608ceac0477ab3f3da"}], "type": "compute_legacy", "id": "b8c84ebaf06442a0af3e25fcfe60c962", "name": "nova_legacy"}, {"endpoints": [{"url": "http://158.69.89.86:9292", "interface": "public", "region": "RegionOne", "region_id": "RegionOne", "id": "1b0f3fbd80f344049cb4c3edb7392a18"}], "type": "image", "id": "c759a7968ff74612998aca5343fd8306", "name": "glance"}, {"endpoints": [{"url": "http://158.69.89.86/identity_admin", "interface": "admin", "region": "RegionOne", "region_id": "RegionOne", "id": "01c25a55e10b4c0aab6d6aca140ad66b"}, {"url": "http://158.69.89.86/identity", "interface": "public", "region": "RegionOne", "region_id": "RegionOne", "id": "78397ca9d2214f91b45294f5938b4609"}], "type": "identity", "id": "cf274a9a95c740028d152ae31d904649", "name": "keystone"}, {"endpoints": [{"url": "http://158.69.89.86:8776/v2/0d567c4487d049988d49a79acd159b42", "interface": "public", "region": "RegionOne", "region_id": "RegionOne", "id": "68a27567b8f543c5b4281d2e187a68ec"}], "type": "volumev2", "id": "deaacb06abc94de49358b11acafc90e6", "name": "cinderv2"}, {"endpoints": [{"url": "http://158.69.89.86:8776/v3/0d567c4487d049988d49a79acd159b42", "interface": "public", "region": "RegionOne", "region_id": "RegionOne", "id": "6f91491ad9b645babd22633e1b6d389b"}], "type": "volumev3", "id": "efa1876fbcd74c65959456057ca6d4a9", "name": "cinderv3"}, {"endpoints": [{"url": "http://158.69.89.86:9696/", "interface": "public", "region": "RegionOne", "region_id": "RegionOne", "id": "a5f18abdddf949219731ff2e7da0d2b4"}], "type": "network", "id": "f830c6fe0f5f4e4190b292f45aa212ce", "name": "neutron"}], "user": {"password_expires_at": null, "domain": {"id": "default", "name": "Default"}, "id": "4db7f3cf9e0945bfbbe64e277e3cb563", "name": "tempest-NetworksTestAdmin-1042551292"}, "audit_ids": ["FOAqC8pzQC-V1EcUiggviw"], "issued_at": "2017-03-15T05:06:00.000000Z"}}
2017-03-15 05:06:00,947 8618 INFO [tempest.lib.common.rest_client] Request (NetworksTestAdmin:test_admin_create_network_keystone_v3): 201 POST http://158.69.89.86:9696/v2.0/networks 0.503s
2017-03-15 05:06:00,948 8618 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'X-Auth-Token': '<omitted>', 'Accept': 'application/json', 'Content-Type': 'application/json'}
        Body: {"network": {"project_id": "ed644987161f4d5ca26ffd8ffb64ac5f", "name": "admin-created-with-project_id"}}
    Response - Headers: {u'connection': 'close', 'content-location': 'http://158.69.89.86:9696/v2.0/networks', u'content-type': 'application/json; charset=UTF-8', u'content-length': '679', u'x-openstack-request-id': 'req-17be2d4b-6f53-445e-bd59-3a78f8b18a08', 'status': '201', u'date': 'Wed, 15 Mar 2017 05:06:00 GMT'}
        Body: {"network":{"provider:physical_network":null,"ipv6_address_scope":null,"dns_domain":"","revision_number":3,"port_security_enabled":true,"mtu":1450,"id":"5e574610-775c-4045-8d37-fd522d77f738","router:external":false,"availability_zone_hints":[],"availability_zones":[],"provider:segmentation_id":31,"ipv4_address_scope":null,"shared":false,"project_id":"ed644987161f4d5ca26ffd8ffb64ac5f","status":"ACTIVE","subnets":[],"description":"","tags":[],"updated_at":"2017-03-15T05:06:00Z","qos_policy_id":null,"name":"admin-created-with-project_id","admin_state_up":true,"tenant_id":"ed644987161f4d5ca26ffd8ffb64ac5f","created_at":"2017-03-15T05:06:00Z","provider:network_type":"vxlan"}}
2017-03-15 05:06:01,070 8618 INFO [tempest.lib.common.rest_client] Request (NetworksTestAdmin:test_admin_create_network_keystone_v3): 201 POST http://158.69.89.86/identity/v3/auth/tokens
2017-03-15 05:06:01,071 8618 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Accept': 'application/json', 'Content-Type': 'application/json'}
        Body: <omitted>
    Response - Headers: {'content-location': 'http://158.69.89.86/identity/v3/auth/tokens', u'content-length': '3604', u'x-openstack-request-id': 'req-fca9101a-a46d-4e60-8839-5784abfa2d1e', u'vary': 'X-Auth-Token', u'date': 'Wed, 15 Mar 2017 05:06:00 GMT', u'connection': 'close', u'content-type': 'application/json', u'server': 'Apache/2.4.18 (Ubuntu)', 'status': '201', u'x-subject-token': '<omitted>'}
        Body: {"token": {"is_domain": false, "methods": ["password"], "roles": [{"id": "9cca5926cfa14c84a060bf4926657c07", "name": "Member"}], "expires_at": "2017-03-15T06:06:01.000000Z", "project": {"domain": {"id": "default", "name": "Default"}, "id": "ed644987161f4d5ca26ffd8ffb64ac5f", "name": "tempest-NetworksTestAdmin-663966222"}, "catalog": [{"endpoints": [{"url": "http://158.69.89.86:8080", "interface": "admin", "region": "RegionOne", "region_id": "RegionOne", "id": "0134e566b4a3417bac59232f7581214b"}, {"url": "http://158.69.89.86:8080/v1/AUTH_ed644987161f4d5ca26ffd8ffb64ac5f", "interface": "public", "region": "RegionOne", "region_id": "RegionOne", "id": "62fed52298d6447f81a6caa4aab41254"}], "type": "object-store", "id": "0b9611b345d04326a6fd47661adfd998", "name": "swift"}, {"endpoints": [{"url": "http://158.69.89.86/placement", "interface": "public", "region": "RegionOne", "region_id": "RegionOne", "id": "12e21ad49605441ca3c2b197523905f1"}], "type": "placement", "id": "2cd7d15b20794d21b920e8636dbf590a", "name": "placement"}, {"endpoints": [{"url": "http://158.69.89.86:8776/v1/ed644987161f4d5ca26ffd8ffb64ac5f", "interface": "public", "region": "RegionOne", "region_id": "RegionOne", "id": "c064e8594368493b968a8f3ba91df6ab"}], "type": "volume", "id": "2ce6191d34104ac39017cb0ccc8fbb97", "name": "cinder"}, {"endpoints": [{"url": "http://158.69.89.86:8774/v2.1", "interface": "public", "region": "RegionOne", "region_id": "RegionOne", "id": "e2d7023e14c54fa693919d9bcdcca435"}], "type": "compute", "id": "2cfbccc3ee9848aebcbc32aef3ec351d", "name": "nova"}, {"endpoints": [{"url": "http://158.69.89.86:8774/v2/ed644987161f4d5ca26ffd8ffb64ac5f", "interface": "public", "region": "RegionOne", "region_id": "RegionOne", "id": "3c848f675f1047608ceac0477ab3f3da"}], "type": "compute_legacy", "id": "b8c84ebaf06442a0af3e25fcfe60c962", "name": "nova_legacy"}, {"endpoints": [{"url": "http://158.69.89.86:9292", "interface": "public", "region": "RegionOne", "region_id": "RegionOne", "id": "1b0f3fbd80f344049cb4c3edb7392a18"}], "type": "image", "id": "c759a7968ff74612998aca5343fd8306", "name": "glance"}, {"endpoints": [{"url": "http://158.69.89.86/identity_admin", "interface": "admin", "region": "RegionOne", "region_id": "RegionOne", "id": "01c25a55e10b4c0aab6d6aca140ad66b"}, {"url": "http://158.69.89.86/identity", "interface": "public", "region": "RegionOne", "region_id": "RegionOne", "id": "78397ca9d2214f91b45294f5938b4609"}], "type": "identity", "id": "cf274a9a95c740028d152ae31d904649", "name": "keystone"}, {"endpoints": [{"url": "http://158.69.89.86:8776/v2/ed644987161f4d5ca26ffd8ffb64ac5f", "interface": "public", "region": "RegionOne", "region_id": "RegionOne", "id": "68a27567b8f543c5b4281d2e187a68ec"}], "type": "volumev2", "id": "deaacb06abc94de49358b11acafc90e6", "name": "cinderv2"}, {"endpoints": [{"url": "http://158.69.89.86:8776/v3/ed644987161f4d5ca26ffd8ffb64ac5f", "interface": "public", "region": "RegionOne", "region_id": "RegionOne", "id": "6f91491ad9b645babd22633e1b6d389b"}], "type": "volumev3", "id": "efa1876fbcd74c65959456057ca6d4a9", "name": "cinderv3"}, {"endpoints": [{"url": "http://158.69.89.86:9696/", "interface": "public", "region": "RegionOne", "region_id": "RegionOne", "id": "a5f18abdddf949219731ff2e7da0d2b4"}], "type": "network", "id": "f830c6fe0f5f4e4190b292f45aa212ce", "name": "neutron"}], "user": {"password_expires_at": null, "domain": {"id": "default", "name": "Default"}, "id": "84381566a869473991a400c9f226afee", "name": "tempest-NetworksTestAdmin-663966222"}, "audit_ids": ["1k4X3soeTd214G-XwexC-A"], "issued_at": "2017-03-15T05:06:01.000000Z"}}
2017-03-15 05:06:01,340 8618 INFO [tempest.lib.common.rest_client] Request (NetworksTestAdmin:test_admin_create_network_keystone_v3): 200 GET http://158.69.89.86:9696/v2.0/networks?id=5e574610-775c-4045-8d37-fd522d77f738 0.268s
2017-03-15 05:06:01,340 8618 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'X-Auth-Token': '<omitted>', 'Accept': 'application/json', 'Content-Type': 'application/json'}
        Body: None
    Response - Headers: {u'connection': 'close', 'content-location': 'http://158.69.89.86:9696/v2.0/networks?id=5e574610-775c-4045-8d37-fd522d77f738', u'content-type': 'application/json; charset=UTF-8', u'content-length': '539', u'x-openstack-request-id': 'req-7ee3498f-55da-4738-bb00-39c40e878aad', 'status': '200', u'date': 'Wed, 15 Mar 2017 05:06:01 GMT'}
        Body: {"networks":[{"status":"ACTIVE","router:external":false,"availability_zone_hints":[],"availability_zones":[],"ipv4_address_scope":null,"description":"","port_security_enabled":true,"subnets":[],"updated_at":"2017-03-15T05:06:00Z","tenant_id":"ed644987161f4d5ca26ffd8ffb64ac5f","created_at":"2017-03-15T05:06:00Z","tags":[],"ipv6_address_scope":null,"dns_domain":"","mtu":1450,"qos_policy_id":null,"revision_number":3,"admin_state_up":true,"shared":false,"id":"5e574610-775c-4045-8d37-fd522d77f738","name":"admin-created-with-project_id"}]}
}}}

Traceback (most recent call last):
  File "tempest/test.py", line 121, in wrapper
    return func(*func_args, **func_kwargs)
  File "/opt/stack/new/neutron/neutron/tests/tempest/api/admin/test_networks.py", line 38, in test_admin_create_network_keystone_v3
    self.assertEqual(project_id, lookup_net['project_id'])
KeyError: 'project_id'

http://logs.openstack.org/31/445631/4/check/gate-neutron-dsvm-api-ubuntu-xenial/82c55d3/testr_results.html.gz

[Ihar Hrachyshka (ihar-hrachyshka)]

Tempest logs shows that project_id field was not included in the payload while tenant_id is there. Code inspection for ml2 suggests that it should have been included by virtue of resource_fields calling to attributes.populate_project_info.

In theory, API layer could have filtered that out because of policy checks. The client in question is not admin, but neither get_network:project_id policy exists in policy.json deployed, so the field should not have been filtered by:

https://github.com/openstack/neutron/blob/master/neutron/pecan_wsgi/hooks/policy_enforcement.py#L228

But maybe the field is marked as non-visible in resource map? But then the previous POST request would also not return project_id attribute, but it did. So it's apparently some one-off failure for the specific request.

Of note is, we switched to pecan lately, which may have some lingering bug.

[Ihar Hrachyshka (ihar-hrachyshka)]

Single hit in 7 days: http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22KeyError%3A%20'project_id'%5C%22

[Kevin Benton (kevinbenton)]

Upon further investigation, the fix for 1674517 should prevent this issue.

I've root caused it to determine that without that whitelist entry for project_id in _exclude_attributes_by_policy, we end up hiding project_id *if* that thread has never had a network created on it as well.

Once a network is created, project_id seems to get populated into the attribute map, which will result in no more hiding, which is what leads to the super low failure rate of this bug.

You can reproduce this locally just by restarting the server and doing a network list as a regular tenant and the project_id column will be hidden.