Intermittent failure in n-api connecting to neutron to list ports after TLS was enabled in CI

[Matt Riedemann]

Seen here:

http://logs.openstack.org/00/382000/2/check/gate-tempest-dsvm-neutron-full-ubuntu-xenial/07e5243/logs/screen-n-api.txt.gz?level=TRACE#_2016-10-05_14_35_04_333

2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack [req-c1bbc78f-89e4-4de2-956d-9b71f8ad1a87 tempest-TestNetworkAdvancedServerOps-960076899 tempest-TestNetworkAdvancedServerOps-960076899] Caught error: Unable to establish connection to https://127.0.0.1:9696/v2.0/ports.json?device_id=bf9a5908-ebdd-4f67-aae4-a0a3e0cf0d09
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack Traceback (most recent call last):
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack File "/opt/stack/new/nova/nova/api/openstack/__init__.py", line 89, in __call__
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack return req.get_response(self.application)
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/webob/request.py", line 1299, in send
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack application, catch_exc_info=False)
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/webob/request.py", line 1263, in call_application
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack app_iter = application(self.environ, start_response)
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack return resp(environ, start_response)
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/webob/dec.py", line 130, in __call__
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack resp = self.call_func(req, *args, **self.kwargs)
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/webob/dec.py", line 195, in call_func
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack return self.func(req, *args, **kwargs)
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/keystonemiddleware/auth_token/__init__.py", line 323, in __call__
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack response = req.get_response(self._app)
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/webob/request.py", line 1299, in send
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack application, catch_exc_info=False)
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/webob/request.py", line 1263, in call_application
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack app_iter = application(self.environ, start_response)
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack return resp(environ, start_response)
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack return resp(environ, start_response)
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/routes/middleware.py", line 141, in __call__
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack response = self.app(environ, start_response)
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack return resp(environ, start_response)
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/webob/dec.py", line 130, in __call__
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack resp = self.call_func(req, *args, **self.kwargs)
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/webob/dec.py", line 195, in call_func
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack return self.func(req, *args, **kwargs)
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack File "/opt/stack/new/nova/nova/api/openstack/wsgi.py", line 607, in __call__
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack content_type, body, accept)
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack File "/opt/stack/new/nova/nova/api/openstack/wsgi.py", line 687, in _process_stack
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack request, action_args)
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack File "/opt/stack/new/nova/nova/api/openstack/wsgi.py", line 553, in process_extensions
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack **action_args)
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack File "/opt/stack/new/nova/nova/api/openstack/compute/security_groups.py", line 489, in show
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack return self._show(req, resp_obj)
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack File "/opt/stack/new/nova/nova/api/openstack/compute/security_groups.py", line 485, in _show
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack self._extend_servers(req, [resp_obj.obj['server']])
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack File "/opt/stack/new/nova/nova/api/openstack/compute/security_groups.py", line 467, in _extend_servers
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack servers))
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack File "/opt/stack/new/nova/nova/network/security_group/neutron_driver.py", line 380, in get_instances_security_groups_bindings
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack ports = self._get_ports_from_server_list(servers, neutron)
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack File "/opt/stack/new/nova/nova/network/security_group/neutron_driver.py", line 339, in _get_ports_from_server_list
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack ports.extend(neutron.list_ports(**search_opts).get('ports'))
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack File "/opt/stack/new/nova/nova/network/neutronv2/api.py", line 96, in wrapper
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack ret = obj(*args, **kwargs)
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line 742, in list_ports
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack **_params)
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack File "/opt/stack/new/nova/nova/network/neutronv2/api.py", line 96, in wrapper
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack ret = obj(*args, **kwargs)
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line 375, in list
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack for r in self._pagination(collection, path, **params):
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line 390, in _pagination
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack res = self.get(path, params=params)
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack File "/opt/stack/new/nova/nova/network/neutronv2/api.py", line 96, in wrapper
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack ret = obj(*args, **kwargs)
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line 360, in get
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack headers=headers, params=params)
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack File "/opt/stack/new/nova/nova/network/neutronv2/api.py", line 96, in wrapper
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack ret = obj(*args, **kwargs)
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line 337, in retry_request
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack headers=headers, params=params)
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack File "/opt/stack/new/nova/nova/network/neutronv2/api.py", line 96, in wrapper
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack ret = obj(*args, **kwargs)
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line 288, in do_request
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack resp, replybody = self.httpclient.do_request(action, method, body=body)
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/neutronclient/client.py", line 311, in do_request
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack return self.request(url, method, **kwargs)
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/neutronclient/client.py", line 299, in request
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack resp = super(SessionClient, self).request(*args, **kwargs)
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/keystoneauth1/adapter.py", line 112, in request
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack return self.session.request(url, method, **kwargs)
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/positional/__init__.py", line 101, in inner
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack return wrapped(*args, **kwargs)
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/keystoneauth1/session.py", line 555, in request
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack resp = send(**kwargs)
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/keystoneauth1/session.py", line 599, in _send_request
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack raise exceptions.ConnectFailure(msg)
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack ConnectFailure: Unable to establish connection to https://127.0.0.1:9696/v2.0/ports.json?device_id=bf9a5908-ebdd-4f67-aae4-a0a3e0cf0d09
2016-10-05 14:35:04.333 18048 ERROR nova.api.openstack

http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22ConnectFailure%3A%20Unable%20to%20establish%20connection%20to%20https%3A%2F%2F127.0.0.1%3A9696%2Fv2.0%2F%5C%22%20AND%20tags%3A%5C%22screen-n-api.txt%5C%22%20AND%20voting%3A1&from=10d

According to logstash this started happening around 9/27, which lines up with when TLS was enabled in ocata (master) branch jobs:

https://review.openstack.org/#/c/375776/

So I assume those are related.

[Matt Riedemann (mriedem)]

Also failing in n-cpu:

http://logs.openstack.org/10/331810/5/gate/gate-tempest-dsvm-neutron-full-ubuntu-xenial/49cb6d7/logs/screen-n-cpu.txt.gz?level=TRACE#_2016-10-11_20_51_11_229

[Matt Riedemann (mriedem)]

Looks like we can also hit this when going from neutron to nova for sending external events:

http://logs.openstack.org/23/371523/5/check/gate-tempest-dsvm-neutron-full-ubuntu-xenial/773b57f/logs/screen-q-svc.txt.gz#_2016-10-18_11_58_39_790

2016-10-18 11:58:39.790 2470 ERROR neutron.notifiers.nova [-] Failed to notify nova on events: [{'status': 'completed', 'tag': u'33f6ef2e-dcac-4f4b-8da2-747726c24d5c', 'name': 'network-vif-plugged', 'server_uuid': u'bd23ba0c-a73a-48d5-a491-d1ae489667fe'}]
2016-10-18 11:58:39.790 2470 ERROR neutron.notifiers.nova Traceback (most recent call last):
2016-10-18 11:58:39.790 2470 ERROR neutron.notifiers.nova File "/opt/stack/new/neutron/neutron/notifiers/nova.py", line 260, in send_events
2016-10-18 11:58:39.790 2470 ERROR neutron.notifiers.nova batched_events)
2016-10-18 11:58:39.790 2470 ERROR neutron.notifiers.nova File "/usr/local/lib/python2.7/dist-packages/novaclient/v2/contrib/server_external_events.py", line 39, in create
2016-10-18 11:58:39.790 2470 ERROR neutron.notifiers.nova return_raw=True)
2016-10-18 11:58:39.790 2470 ERROR neutron.notifiers.nova File "/usr/local/lib/python2.7/dist-packages/novaclient/base.py", line 356, in _create
2016-10-18 11:58:39.790 2470 ERROR neutron.notifiers.nova resp, body = self.api.client.post(url, body=body)
2016-10-18 11:58:39.790 2470 ERROR neutron.notifiers.nova File "/usr/local/lib/python2.7/dist-packages/keystoneauth1/adapter.py", line 205, in post
2016-10-18 11:58:39.790 2470 ERROR neutron.notifiers.nova return self.request(url, 'POST', **kwargs)
2016-10-18 11:58:39.790 2470 ERROR neutron.notifiers.nova File "/usr/local/lib/python2.7/dist-packages/novaclient/client.py", line 107, in request
2016-10-18 11:58:39.790 2470 ERROR neutron.notifiers.nova **kwargs)
2016-10-18 11:58:39.790 2470 ERROR neutron.notifiers.nova File "/usr/local/lib/python2.7/dist-packages/keystoneauth1/adapter.py", line 356, in request
2016-10-18 11:58:39.790 2470 ERROR neutron.notifiers.nova resp = super(LegacyJsonAdapter, self).request(*args, **kwargs)
2016-10-18 11:58:39.790 2470 ERROR neutron.notifiers.nova File "/usr/local/lib/python2.7/dist-packages/keystoneauth1/adapter.py", line 124, in request
2016-10-18 11:58:39.790 2470 ERROR neutron.notifiers.nova return self.session.request(url, method, **kwargs)
2016-10-18 11:58:39.790 2470 ERROR neutron.notifiers.nova File "/usr/local/lib/python2.7/dist-packages/positional/__init__.py", line 101, in inner
2016-10-18 11:58:39.790 2470 ERROR neutron.notifiers.nova return wrapped(*args, **kwargs)
2016-10-18 11:58:39.790 2470 ERROR neutron.notifiers.nova File "/usr/local/lib/python2.7/dist-packages/keystoneauth1/session.py", line 592, in request
2016-10-18 11:58:39.790 2470 ERROR neutron.notifiers.nova resp = send(**kwargs)
2016-10-18 11:58:39.790 2470 ERROR neutron.notifiers.nova File "/usr/local/lib/python2.7/dist-packages/keystoneauth1/session.py", line 642, in _send_request
2016-10-18 11:58:39.790 2470 ERROR neutron.notifiers.nova raise exceptions.ConnectFailure(msg)
2016-10-18 11:58:39.790 2470 ERROR neutron.notifiers.nova ConnectFailure: Unable to establish connection to https://127...

[Clark Boylan (cboylan)]

One theory was that the default ubuntu mpm event settings to only allow 150 connections at a time were being hit. I have since gotten a patch into devstack that allows for up to 1024 connections and this issue persists. I think we may want to consider bumping log levels in apache (at least temporarily or in a throw away change) and work with the clients to get more specific information on what is failing.

[Clark Boylan (cboylan)]

Oh forgot to mention that I jumped on an instance running devstack and confirmed that the 1024 connection limit is in place (and not somehow continuing to use the 150 connection default).

[Jordan Pittier (jordan-pittier)]

This is well documented over the Internet [1], [2], [3]. This has to do with how httplib in Python handles HTTP persistent connection. I can reproduce locally, but it takes times.

In Python3, the exception raised in clearer:
requests.exceptions.ConnectionError: ('Connection aborted.', RemoteDisconnected('Remote end closed connection without response'

[1] https://bugs.python.org/issue8450
[2] https://bugs.python.org/issue3566
[3] https://github.com/locustio/locust/issues/308

[Jordan Pittier (jordan-pittier)]

https://review.openstack.org/#/c/433738/ fixed it.

[Ihar Hrachyshka (ihar-hrachyshka)]

I am seeing that still happening with keystone token fetch. It just hit this Ocata patch: https://review.openstack.org/#/c/460909/

In http://logs.openstack.org/09/460909/2/check/gate-tempest-dsvm-neutron-linuxbridge-ubuntu-xenial/67904c9/logs/apache/tls-proxy_error.txt.gz we see:

[Fri Apr 28 12:46:47.763965 2017] [proxy_http:error] [pid 30068:tid 140271090042624] (20014)Internal error (specific information not available): [client 104.130.119.120:50002] [frontend 104.130.119.120:443] AH01102: error reading status line from remote server 104.130.119.120:80
[Fri Apr 28 12:46:47.764003 2017] [proxy:error] [pid 30068:tid 140271090042624] [client 104.130.119.120:50002] [frontend 104.130.119.120:443] AH00898: Error reading from remote server returned by /identity_admin/v3/auth/tokens

The request that triggered the failure doesn't seem to show up in keystone log.

[Matt Riedemann (mriedem)]

@Ihar, you should probably close this one and report a new bug then because the fix for this was backported to stable/ocata so it's probably something else.

[Jordan Pittier (jordan-pittier)]

@Ihar, what you are seing now is https://bugs.launchpad.net/tempest/+bug/1681866 IMO.