UnexpectedResponseCode: Unexpected response code received from api.compute tempest tests

[Rafael Folco]

ft4.3: tempest.api.compute.servers.test_attach_interfaces.AttachInterfacesTestJSON.test_create_list_show_delete_interfaces_by_network_port[id-73fe8f02-590d-4bf1-b184-e9ca81065051,network]_StringException: pythonlogging:'': {{{
2018-03-28 03:12:20,699 22178 INFO [tempest.lib.common.rest_client] Request (AttachInterfacesTestJSON:test_create_list_show_delete_interfaces_by_network_port): 201 POST http://192.168.24.11:5000//v3/auth/tokens
2018-03-28 03:12:20,701 22178 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json'}
        Body: <omitted>
    Response - Headers: {'status': '201', u'content-length': '9051', 'content-location': 'http://192.168.24.11:5000//v3/auth/tokens', u'x-subject-token': '<omitted>', u'vary': 'X-Auth-Token', u'server': 'Apache', u'connection': 'close', u'date': 'Wed, 28 Mar 2018 03:12:20 GMT', u'content-type': 'application/json', u'x-openstack-request-id': 'req-7f656cb0-6c02-4b42-b0db-7956d6e4948d'}
        Body: {"token": {"is_domain": false, "methods": ["password"], "roles": [{"id": "dd311a9d40c6410ab57cf057c4289e9c", "name": "Member"}], "expires_at": "2018-03-28T04:12:20.000000Z", "project": {"domain": {"id": "default", "name": "Default"}, "id": "6bd66492ceb2470b933afa3f3c78ecd5", "name": "tempest-AttachInterfacesTestJSON-1568649043"}, "catalog": [{"endpoints": [{"region_id": "regionOne", "url": "http://192.168.24.11:8776/v1/6bd66492ceb2470b933afa3f3c78ecd5", "region": "regionOne", "interface": "admin", "id": "2e9db9560abe4b719b43ab4eba35944b"}, {"region_id": "regionOne", "url": "http://192.168.24.11:8776/v1/6bd66492ceb2470b933afa3f3c78ecd5", "region": "regionOne", "interface": "public", "id": "562a093b96854f61b162c405a9d90038"}, {"region_id": "regionOne", "url": "http://192.168.24.11:8776/v1/6bd66492ceb2470b933afa3f3c78ecd5", "region": "regionOne", "interface": "internal", "id": "d9798948ea9f463e967a4e32c5de652a"}], "type": "volume", "id": "0e1f7fec3eec4f8fb8cdd23c307e818b", "name": "cinder"}, {"endpoints": [{"region_id": "regionOne", "url": "http://192.168.24.11:8776/v3/6bd66492ceb2470b933afa3f3c78ecd5", "region": "regionOne", "interface": "internal", "id": "0d19416fa949460c9a30577d6cb987ac"}, {"region_id": "regionOne", "url": "http://192.168.24.11:8776/v3/6bd66492ceb2470b933afa3f3c78ecd5", "region": "regionOne", "interface": "public", "id": "5bdb9448a5e94ad6af8b1e1bd016be7d"}, {"region_id": "regionOne", "url": "http://192.168.24.11:8776/v3/6bd66492ceb2470b933afa3f3c78ecd5", "region": "regionOne", "interface": "admin", "id": "ece28d067bcd482bb7339be93d969f43"}], "type": "volumev3", "id": "18029522e5864cbc99ddac62d2a86c86", "name": "cinderv3"}, {"endpoints": [], "type": "metering", "id": "1ed9ed83865940e8ab7106ef610b1417", "name": "ceilometer"}, {"endpoints": [{"region_id": "regionOne", "url": "http://192.168.24.11:8000/v1", "region": "regionOne", "interface": "internal", "id": "557036597fd048288436e7f1939c1cc1"}, {"region_id": "regionOne", "url": "http://192.168.24.11:8000/v1", "region": "regionOne", "interface": "admin", "id": "f2ad443b32a04bbc8f1b531e97e2ef3f"}, {"region_id": "regionOne", "url": "http://192.168.24.11:8000/v1", "region": "regionOne", "interface": "public", "id": "fd50f0707bf1469185954c314182801b"}], "type": "cloudformation", "id": "3552151f90564c3a886742b31ac0e00e", "name": "heat-cfn"}, {"endpoints": [{"region_id": "regionOne", "url": "http://192.168.24.11:9696", "region": "regionOne", "interface": "admin", "id": "342a8d8082234c8ebc4937303c3e50f4"}, {"region_id": "regionOne", "url": "http://192.168.24.11:9696", "region": "regionOne", "interface": "internal", "id": "414d29220fff4008bdae35ee141586dd"}, {"region_id": "regionOne", "url": "http://192.168.24.11:9696", "region": "regionOne", "interface": "public", "id": "785b3be894eb4f2fa2d6eade12935b3f"}], "type": "network", "id": "3b2ef1552a75489699ae153d423af18b", "name": "neutron"}, {"endpoints": [{"region_id": "regionOne", "url": "http://192.168.24.11:8774/v2.1", "region": "regionOne", "interface": "internal", "id": "64395acb2cd04eca9e6faa5a76dc38d9"}, {"region_id": "regionOne", "url": "http://192.168.24.11:8774/v2.1", "region": "regionOne", "interface": "public", "id": "8fdd52428d514269a4af49a6f0320d42"}, {"region_id": "regionOne", "url": "http://192.168.24.11:8774/v2.1", "region": "regionOne", "interface": "admin", "id": "a0d8a865f22e482d81e34e6b543e92fa"}], "type": "compute", "id": "4a180d8ce92747529214b5ff4dbbd04d", "name": "nova"}, {"endpoints": [{"region_id": "regionOne", "url": "http://192.168.24.11:8778/placement", "region": "regionOne", "interface": "internal", "id": "321c861638464b8692307c39aca8b3c6"}, {"region_id": "regionOne", "url": "http://192.168.24.11:8778/placement", "region": "regionOne", "interface": "admin", "id": "532d96bef90e43028d79c95b77561191"}, {"region_id": "regionOne", "url": "http://192.168.24.11:8778/placement", "region": "regionOne", "interface": "public", "id": "e5e3a70b2acb4e8582c13b3e21a15944"}], "type": "placement", "id": "4c8d19f230d34ff8902b1581d7739cd0", "name": "placement"}, {"endpoints": [{"region_id": "regionOne", "url
2018-03-28 03:12:20,702 22178 INFO [tempest.lib.common.fixed_network] (AttachInterfacesTestJSON:test_create_list_show_delete_interfaces_by_network_port) Found network {u'provider:physical_network': None, u'ipv6_address_scope': None, u'revision_number': 3, u'port_security_enabled': True, u'mtu': 1300, u'id': u'e7f8a61a-c079-44af-9119-22e729f187b8', u'router:external': False, u'availability_zone_hints': [], u'availability_zones': [], u'provider:segmentation_id': 29, u'ipv4_address_scope': None, u'shared': False, u'project_id': u'6bd66492ceb2470b933afa3f3c78ecd5', u'status': u'ACTIVE', u'subnets': [], u'description': u'', u'tags': [], u'updated_at': u'2018-03-28T03:08:18Z', u'is_default': False, u'qos_policy_id': None, u'name': u'tempest-AttachInterfacesTestJSON-1138348224-network', u'admin_state_up': True, u'tenant_id': u'6bd66492ceb2470b933afa3f3c78ecd5', u'created_at': u'2018-03-28T03:08:17Z', u'provider:network_type': u'vxlan'} available for tenant
2018-03-28 03:12:20,706 22178 INFO [tempest.lib.common.rest_client] Request (AttachInterfacesTestJSON:test_create_list_show_delete_interfaces_by_network_port): 503 POST http://192.168.24.11:8774/v2.1/servers 0.003s
2018-03-28 03:12:20,706 22178 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: {"server": {"flavorRef": "cc90206a-b0af-4a80-8d48-418ad77cf262", "networks": [{"uuid": "e7f8a61a-c079-44af-9119-22e729f187b8"}], "imageRef": "792721e8-5663-439a-ad5f-fa6afb089765", "name": "tempest-AttachInterfacesTestJSON-server-86708307"}}
    Response - Headers: {'status': '503', u'connection': 'close', u'content-type': 'text/html', 'content-location': 'http://192.168.24.11:8774/v2.1/servers', u'cache-control': 'no-cache'}
        Body: <html><body><h1>503 Service Unavailable</h1>
No server is available to handle this request.
</body></html>
}}}

Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/tempest/common/utils/__init__.py", line 88, in wrapper
    return f(*func_args, **func_kwargs)
  File "/usr/lib/python2.7/site-packages/tempest/api/compute/servers/test_attach_interfaces.py", line 189, in test_create_list_show_delete_interfaces_by_network_port
    server, ifs = self._create_server_get_interfaces()
  File "/usr/lib/python2.7/site-packages/tempest/api/compute/servers/test_attach_interfaces.py", line 96, in _create_server_get_interfaces
    server = self.create_test_server(wait_until='ACTIVE')
  File "/usr/lib/python2.7/site-packages/tempest/api/compute/base.py", line 200, in create_test_server
    **kwargs)
  File "/usr/lib/python2.7/site-packages/tempest/common/compute.py", line 191, in create_test_server
    **kwargs)
  File "/usr/lib/python2.7/site-packages/tempest/lib/services/compute/servers_client.py", line 89, in create_server
    resp, body = self.post('servers', post_body)
  File "/usr/lib/python2.7/site-packages/tempest/lib/common/rest_client.py", line 279, in post
    return self.request('POST', url, extra_headers, headers, body, chunked)
  File "/usr/lib/python2.7/site-packages/tempest/lib/services/compute/base_compute_client.py", line 48, in request
    method, url, extra_headers, headers, body, chunked)
  File "/usr/lib/python2.7/site-packages/tempest/lib/common/rest_client.py", line 668, in request
    self._error_checker(resp, resp_body)
  File "/usr/lib/python2.7/site-packages/tempest/lib/common/rest_client.py", line 849, in _error_checker
    resp=resp)
tempest.lib.exceptions.UnexpectedResponseCode: Unexpected response code received
Details: 503

https://logs.rdoproject.org/openstack-periodic/periodic-tripleo-ci-centos-7-ovb-1ctlr_1comp-featureset020-master/3c288f5/tempest.html.gz

suspicious errors in

2018-03-28 03:14:28.974 ERROR /var/log/containers/ceilometer/compute.log: 27 ERROR ceilometer.polling.manager UnicodeEncodeError: 'ascii' codec can't encode character u'\u20a1' in position 25: ordinal not in range(128)

https://logs.rdoproject.org/openstack-periodic/periodic-tripleo-ci-centos-7-ovb-1ctlr_1comp-featureset020-master/3c288f5/overcloud-novacompute-0/var/log/extra/errors.txt.gz#_2018-03-28_03_14_28_974

timeouts etc..

https://logs.rdoproject.org/openstack-periodic/periodic-tripleo-ci-centos-7-ovb-1ctlr_1comp-featureset020-master/3c288f5/overcloud-controller-0/var/log/extra/errors.txt.gz#_2018-03-28_03_12_20_533

[OpenStack Infra (hudson-openstack)]

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

[Alex Schultz (alex-schultz)]

the nova_osapi endpoint goes down (or is unavailable)

https://logs.rdoproject.org/24/557424/1/openstack-experimental/gate-tripleo-ci-centos-7-ovb-1ctlr_1comp-featureset020-master/Z5a2df7deb1104f2399ad2daeb489de22/overcloud-controller-0/var/log/journal.txt.gz#_Mar_28_18_36_01

Mar 28 18:36:01 overcloud-controller-0 haproxy[32399]: Server nova_osapi/overcloud-controller-0.internalapi.localdomain is DOWN, reason: Layer7 timeout, check duration: 10000ms. 0 active and 0 backup servers left. 5 sessions active, 0 requeued, 0 remaining in queue.
Mar 28 18:36:01 overcloud-controller-0 haproxy[32399]: proxy nova_osapi has no server available!
Mar 28 18:36:01 overcloud-controller-0 haproxy[32399]: Connect from 192.168.24.1:50146 to 192.168.24.10:5000 (keystone_public/HTTP)

[Alex Schultz (alex-schultz)]

Ah this seems to stem from a messaging timeout

https://logs.rdoproject.org/24/557424/1/openstack-experimental/gate-tripleo-ci-centos-7-ovb-1ctlr_1comp-featureset020-master/Z5a2df7deb1104f2399ad2daeb489de22/overcloud-controller-0/var/log/containers/nova/nova-api.log.1.gz

2018-03-28 18:35:02.366 17 DEBUG nova.api.openstack.wsgi [req-9f35d770-27d2-4ef9-991f-4a2546cda214 5fadd605b3fa42fdacd3ffbf9bb15298 7b0b99453bf7455eba902bea58611edc - default default] Action: 'create', calling method: <bound method InterfaceAttachmentController.create of <nova.api.openstack.compute.attach_interfaces.InterfaceAttachmentController object at 0x7f6f92ed89d0>>, body: {"interfaceAttachment": {"fixed_ips": [{"ip_address": "10.100.0.14"}], "net_id": "a451c53f-ba6b-49d1-bd81-f778ca161189"}} _process_stack /usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py:615
2018-03-28 18:35:02.372 17 DEBUG nova.compute.api [req-9f35d770-27d2-4ef9-991f-4a2546cda214 5fadd605b3fa42fdacd3ffbf9bb15298 7b0b99453bf7455eba902bea58611edc - default default] [instance: 2bb5cd3f-32d8-4187-b341-6110849f6ee7] Fetching instance by UUID get /usr/lib/python2.7/site-packages/nova/compute/api.py:2315
2018-03-28 18:35:02.390 17 DEBUG oslo_concurrency.lockutils [req-9f35d770-27d2-4ef9-991f-4a2546cda214 5fadd605b3fa42fdacd3ffbf9bb15298 7b0b99453bf7455eba902bea58611edc - default default] Lock "dc24769a-25df-4ef0-aac3-97c1df883823" acquired by "nova.context.get_or_set_cached_cell_and_set_connections" :: waited 0.000s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:273
2018-03-28 18:35:02.391 17 DEBUG oslo_concurrency.lockutils [req-9f35d770-27d2-4ef9-991f-4a2546cda214 5fadd605b3fa42fdacd3ffbf9bb15298 7b0b99453bf7455eba902bea58611edc - default default] Lock "dc24769a-25df-4ef0-aac3-97c1df883823" released by "nova.context.get_or_set_cached_cell_and_set_connections" :: held 0.000s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:285
2018-03-28 18:36:02.469 17 ERROR nova.api.openstack.wsgi [req-9f35d770-27d2-4ef9-991f-4a2546cda214 5fadd605b3fa42fdacd3ffbf9bb15298 7b0b99453bf7455eba902bea58611edc - default default] Unexpected exception in API method: MessagingTimeout: Timed out waiting for a reply to message ID 506c5cd2ae494dfbadec04b38a55150e
2018-03-28 18:36:02.469 17 ERROR nova.api.openstack.wsgi Traceback (most recent call last):
2018-03-28 18:36:02.469 17 ERROR nova.api.openstack.wsgi File "/usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 801, in wrapped
2018-03-28 18:36:02.469 17 ERROR nova.api.openstack.wsgi return f(*args, **kwargs)
2018-03-28 18:36:02.469 17 ERROR nova.api.openstack.wsgi File "/usr/lib/python2.7/site-packages/nova/api/validation/__init__.py", line 110, in wrapper
2018-03-28 18:36:02.469 17 ERROR nova.api.openstack.wsgi return func(*args, **kwargs)
2018-03-28 18:36:02.469 17 ERROR nova.api.openstack.wsgi File "/usr/lib/python2.7/site-packages/nova/api/validation/__init__.py", line 110, in wrapper
2018-03-28 18:36:02.469 17 ERROR nova.api.openstack.wsgi return func(*args, **kwargs)
2018-03-28 18:36:02.469 17 ERROR nova.api.openstack.wsgi File "/usr/lib/python2.7/site-packages/nova/api/openstack/compu...

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/557354
Committed: https://git.openstack.org/cgit/openstack/tripleo-quickstart-extras/commit/?id=a0de810b69b60cc6092ae1cb5258c7ccc2f370e1
Submitter: Zuul
Branch: master

commit a0de810b69b60cc6092ae1cb5258c7ccc2f370e1
Author: Rafael Folco <email address hidden>
Date: Wed Mar 28 11:38:18 2018 -0300

    Temporarily add tempest failures to skip list

    fs020 full tempest has performance regressions and concurrency
    issues that are under investigation.

    Change-Id: I883979a78423297a1051c40846c5b0cd798b628c
    Related-Bug: #1759583
    Related-Bug: #1758932

[chen.gengkun (chen-gengkun)]

in my environment
tempest.api.compute.servers.test_attach_interfaces.AttachInterfacesTestJSON.test_create_list_show_delete_interfaces_by_network_port was success
tempest.api.compute.servers.test_attach_interfaces.AttachInterfacesTestJSON.test_create_list_show_delete_interfaces_by_fixed_ip was failure, and message:
Traceback (most recent call last):
  File "tempest/lib/services/network/ports_client.py", line 59, in delete_port
    return self.delete_resource(uri)
  File "tempest/lib/services/network/base.py", line 41, in delete_resource
    resp, body = self.delete(req_uri)
  File "tempest/lib/common/rest_client.py", line 310, in delete
    return self.request('DELETE', url, extra_headers, headers, body)
  File "tempest/lib/common/rest_client.py", line 668, in request
    self._error_checker(resp, resp_body)
  File "tempest/lib/common/rest_client.py", line 774, in _error_checker
    raise exceptions.NotFound(resp_body, resp=resp)
tempest.lib.exceptions.NotFound: Object not found
Details: {u'message': u'Port 55c62dc5-9516-4fe6-8af8-1c1f212153a6 could not be found.', u'type': u'PortNotFound', u'detail': u''}

In my tempest config file, compute.fixed_network_name was setted as a shared network, the second interface
was not attached, and the exception was just thrown away.
then, guest was attached another interface with fixed ip address.
finally, ifs[1] was delete, and the port was delete too.
The result was addCleanup raising exception PortNotFount.

In addition, six.text_type(e) was
u"Bad request\nDetails: {u'message': u'Multiple possible networks found, use a Network ID to be more specific.', u'code': 400}",
"six.text_type(e) == msg" was wrong

[Matt Young (halcyondude)]

this job is passing now...flipping to fix released