ConnectionFailed: Connection to XXXXXX failed: 'HTTPSConnectionPool' object has no attribute 'insecure'

[Paul Ward]

While compute manager was trying to authenticate with neutronclient, we see the following:

2014-08-28 05:03:33.052 29982 TRACE powervc_nova.compute.manager Traceback (most recent call last):
2014-08-28 05:03:33.052 29982 TRACE powervc_nova.compute.manager File "/usr/lib/python2.7/site-packages/powervc_nova/compute/manager.py", line 672, in _populate_admin_context
2014-08-28 05:03:33.052 29982 TRACE powervc_nova.compute.manager nclient.authenticate()
2014-08-28 05:03:33.052 29982 TRACE powervc_nova.compute.manager File "/usr/lib/python2.7/site-packages/neutronclient/client.py", line 231, in authenticate
2014-08-28 05:03:33.052 29982 TRACE powervc_nova.compute.manager self._authenticate_keystone()
2014-08-28 05:03:33.052 29982 TRACE powervc_nova.compute.manager File "/usr/lib/python2.7/site-packages/neutronclient/client.py", line 209, in _authenticate_keystone
2014-08-28 05:03:33.052 29982 TRACE powervc_nova.compute.manager allow_redirects=True)
2014-08-28 05:03:33.052 29982 TRACE powervc_nova.compute.manager File "/usr/lib/python2.7/site-packages/neutronclient/client.py", line 113, in _cs_request
2014-08-28 05:03:33.052 29982 TRACE powervc_nova.compute.manager raise exceptions.ConnectionFailed(reason=e)
2014-08-28 05:03:33.052 29982 TRACE powervc_nova.compute.manager ConnectionFailed: Connection to neutron failed: 'HTTPSConnectionPool' object has no attribute 'insecure'

Setting a pdb breakpoint and stepping into the code, I see that the requests library is getting a connection object from a pool. The interesting thing is that the connection object is actually from glanceclient.common.https.HTTPSConnectionPool. It seems odd to me that neutronclient is using a connection object from glanceclient pool, but I do not know this requests code. Here is the stack just before failure:

  /usr/lib/python2.7/site-packages/neutronclient/client.py(234)authenticate()
-> self._authenticate_keystone()
  /usr/lib/python2.7/site-packages/neutronclient/client.py(212)_authenticate_keystone()
-> allow_redirects=True)
  /usr/lib/python2.7/site-packages/neutronclient/client.py(106)_cs_request()
-> resp, body = self.request(*args, **kargs)
  /usr/lib/python2.7/site-packages/neutronclient/client.py(151)request()
-> **kwargs)
  /usr/lib/python2.7/site-packages/requests/api.py(44)request()
-> return session.request(method=method, url=url, **kwargs)
  /usr/lib/python2.7/site-packages/requests/sessions.py(335)request()
-> resp = self.send(prep, **send_kwargs)
  /usr/lib/python2.7/site-packages/requests/sessions.py(438)send()
-> r = adapter.send(request, **kwargs)
  /usr/lib/python2.7/site-packages/requests/adapters.py(292)send()
-> timeout=timeout
  /usr/lib/python2.7/site-packages/urllib3/connectionpool.py(454)urlopen()
-> conn = self._get_conn(timeout=pool_timeout)
  /usr/lib/python2.7/site-packages/urllib3/connectionpool.py(272)_get_conn()
-> return conn or self._new_conn()
> /usr/lib/python2.7/site-packages/glanceclient/common/https.py(100)_new_conn()
-> return VerifiedHTTPSConnection(host=self.host,

The code about to run there is this:

class HTTPSConnectionPool(connectionpool.HTTPSConnectionPool):
    """
    HTTPSConnectionPool will be instantiated when a new
    connection is requested to the HTTPSAdapter.This
    implementation overwrites the _new_conn method and
    returns an instances of glanceclient's VerifiedHTTPSConnection
    which handles no compression.

    ssl_compression is hard-coded to False because this will
    be used just when the user sets --no-ssl-compression.
    """

    scheme = 'https'

    def _new_conn(self):
        self.num_connections += 1
        return VerifiedHTTPSConnection(host=self.host,
                                       port=self.port,
                                       key_file=self.key_file,
                                       cert_file=self.cert_file,
                                       cacert=self.ca_certs,
                                       insecure=self.insecure,
                                       ssl_compression=False)

Note the self.insecure, which does not exist here. I see the following fairly recent change in the glanceclient.common.https code that added this:

https://github.com/openstack/python-glanceclient/commit/dbb242b776908ca50ed8557ebfe7cfcd879366c8#diff-524c1a0b226fa8e5fb4df6ff5574e153R104

I do not understand this whole flow and if self.insecure was supposed to have been initialized somewhere else, but it's obviously not.

[Eugene Nikanorov (enikanorov)]

Not sure how neutron client depends on glance client.

There is no such dependency in upstream python-neutronclient.

Could you please clarify?

[Paul Ward (wpward)]

I don't know how/why there would be that interdependence either. It's been a while, but I think I was just seeing that the neutron client was getting a connection object from the pool (via requests library), and apparently the object it got was actually one created by glance. Is this just one big pool that ALL clients throw their connection objects into when done to be reused by anyone? Or is it wrong that neutronclient somehow got a hold of a glanceclient connection object?

I will see if I can still reproduce this. We've since rebased on Juno and perhaps it has changed.

[Simon (xchenum)]

I am seeing exactly the same issue running nova trunk:

2014-09-26 19:54:47.605 636477 TRACE nova.api.openstack File "/opt/stack/deploy/nova/06ce4ba4-8a2a-461a-90e9-f2021d198f7e/local/lib/python2.7/site-packages/nova/network/security_group/neutron_driver.py", line 305, in _get_ports_from_server_list
2014-09-26 19:54:47.605 636477 TRACE nova.api.openstack ports.extend(neutron.list_ports(**search_opts).get('ports'))
2014-09-26 19:54:47.605 636477 TRACE nova.api.openstack File "/opt/stack/deploy/nova/06ce4ba4-8a2a-461a-90e9-f2021d198f7e/local/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 98, in with_params
2014-09-26 19:54:47.605 636477 TRACE nova.api.openstack ret = self.function(instance, *args, **kwargs)
2014-09-26 19:54:47.605 636477 TRACE nova.api.openstack File "/opt/stack/deploy/nova/06ce4ba4-8a2a-461a-90e9-f2021d198f7e/local/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 312, in list_ports
2014-09-26 19:54:47.605 636477 TRACE nova.api.openstack **_params)
2014-09-26 19:54:47.605 636477 TRACE nova.api.openstack File "/opt/stack/deploy/nova/06ce4ba4-8a2a-461a-90e9-f2021d198f7e/local/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 1335, in list
2014-09-26 19:54:47.605 636477 TRACE nova.api.openstack for r in self._pagination(collection, path, **params):
2014-09-26 19:54:47.605 636477 TRACE nova.api.openstack File "/opt/stack/deploy/nova/06ce4ba4-8a2a-461a-90e9-f2021d198f7e/local/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 1348, in _pagination
2014-09-26 19:54:47.605 636477 TRACE nova.api.openstack res = self.get(path, params=params)
2014-09-26 19:54:47.605 636477 TRACE nova.api.openstack File "/opt/stack/deploy/nova/06ce4ba4-8a2a-461a-90e9-f2021d198f7e/local/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 1321, in get
2014-09-26 19:54:47.605 636477 TRACE nova.api.openstack headers=headers, params=params)
2014-09-26 19:54:47.605 636477 TRACE nova.api.openstack File "/opt/stack/deploy/nova/06ce4ba4-8a2a-461a-90e9-f2021d198f7e/local/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 1298, in retry_request
2014-09-26 19:54:47.605 636477 TRACE nova.api.openstack headers=headers, params=params)
2014-09-26 19:54:47.605 636477 TRACE nova.api.openstack File "/opt/stack/deploy/nova/06ce4ba4-8a2a-461a-90e9-f2021d198f7e/local/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 1241, in do_request
2014-09-26 19:54:47.605 636477 TRACE nova.api.openstack content_type=self.content_type())
2014-09-26 19:54:47.605 636477 TRACE nova.api.openstack File "/opt/stack/deploy/nova/06ce4ba4-8a2a-461a-90e9-f2021d198f7e/local/lib/python2.7/site-packages/neutronclient/client.py", line 181, in do_request
2014-09-26 19:54:47.605 636477 TRACE nova.api.openstack **kwargs)
2014-09-26 19:54:47.605 636477 TRACE nova.api.openstack File "/opt/stack/deploy/nova/06ce4ba4-8a2a-461a-90e9-f2021d198f7e/local/lib/python2.7/site-packages/neutronclient/client.py", line 134, in _cs_request
2014-09-26 19:54:47.605 636477 TRACE nova.api.openstack raise exceptions.ConnectionFailed(reason=e)
2014-09-26 19:54:47.605 636477 ...

[Andrea Rosa (andrea-rosa-m)]

This is not a but in neutron client but in the glance client.
There is a bug opened against the glance client for this issue: https://bugs.launchpad.net/python-glanceclient/+bug/1347150
Regards

[Nikhil Komawar (nikhil-komawar)]

https://review.openstack.org/#/c/110574/9

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/110574
Committed: https://git.openstack.org/cgit/openstack/python-glanceclient/commit/?id=052904ba32f6e6075b023065bff684042c640c6a
Submitter: Jenkins
Branch: master

commit 052904ba32f6e6075b023065bff684042c640c6a
Author: Flavio Percoco <email address hidden>
Date: Wed Jul 30 10:57:46 2014 +0200

    Don't replace the https handler in the poolmanager

    In order to keep the support for `--ssl-nocompression` it was decided to
    overwrite the https HTTPAdapter in `requests` poolmanager. Although this
    seemed to work correctly, it was causing some issues when using
    glanceclient from other services that rely on requests and that were
    also configured to use TLS.

    THis patch changes implements a different strategy by using
    `glance+https` as the scheme to use when `no-compression` is requested.

    Closes-bug: #1350251
    Closes-bug: #1347150
    Closes-bug: #1362766

    Change-Id: Ib25237ba821ee20a561a163b79402d1375ebed0b

[Tom Verdaat (tom-verdaat)]

Running Juno I'm getting the error below in nova-api.log after enabling SSL for neutron server. Set nova.conf [neutron] section variables url= to https, and tried setting ca_certificates_file and api_insecure, but those don't seem to make a difference.

Seems like this bug hasn't been fixed or am I wrong?

2015-03-16 13:42:09.381 32053 TRACE nova.api.openstack Traceback (most recent call last):
2015-03-16 13:42:09.381 32053 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/nova/api/openstack/__init__.py", line 124, in __call__
2015-03-16 13:42:09.381 32053 TRACE nova.api.openstack return req.get_response(self.application)
2015-03-16 13:42:09.381 32053 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1320, in send
2015-03-16 13:42:09.381 32053 TRACE nova.api.openstack application, catch_exc_info=False)
2015-03-16 13:42:09.381 32053 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1284, in call_application
2015-03-16 13:42:09.381 32053 TRACE nova.api.openstack app_iter = application(self.environ, start_response)
2015-03-16 13:42:09.381 32053 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2015-03-16 13:42:09.381 32053 TRACE nova.api.openstack return resp(environ, start_response)
2015-03-16 13:42:09.381 32053 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/keystonemiddleware/auth_token.py", line 661, in __call__
2015-03-16 13:42:09.381 32053 TRACE nova.api.openstack return self._app(env, start_response)
2015-03-16 13:42:09.381 32053 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2015-03-16 13:42:09.381 32053 TRACE nova.api.openstack return resp(environ, start_response)
2015-03-16 13:42:09.381 32053 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2015-03-16 13:42:09.381 32053 TRACE nova.api.openstack return resp(environ, start_response)
2015-03-16 13:42:09.381 32053 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/routes/middleware.py", line 131, in __call__
2015-03-16 13:42:09.381 32053 TRACE nova.api.openstack response = self.app(environ, start_response)
2015-03-16 13:42:09.381 32053 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2015-03-16 13:42:09.381 32053 TRACE nova.api.openstack return resp(environ, start_response)
2015-03-16 13:42:09.381 32053 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 130, in __call__
2015-03-16 13:42:09.381 32053 TRACE nova.api.openstack resp = self.call_func(req, *args, **self.kwargs)
2015-03-16 13:42:09.381 32053 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 195, in call_func
2015-03-16 13:42:09.381 32053 TRACE nova.api.openstack return self.func(req, *args, **kwargs)
2015-03-16 13:42:09.381 32053 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/nova/api/openstack/wsgi.py", line 910, in __call__
2015-03-16 13:42:09.381 32053 TR...

[Sam Morrison (sorrison)]

I'm getting this in nova-api too, we don't use neutron.

I get it when I do a nova list or nova show. Restarting nova-api fixed it for a while but then it comes back again.

==> /var/log/nova/nova-api.log <==
2015-03-27 13:56:06.649 10962 WARNING keystonemiddleware.auth_token [-] Retrying on HTTP connection exception: 'HTTPSConnectionPool' object has no attribute 'insecure'
2015-03-27 13:56:07.153 10962 WARNING keystonemiddleware.auth_token [-] Retrying on HTTP connection exception: 'HTTPSConnectionPool' object has no attribute 'insecure'
2015-03-27 13:56:08.156 10962 WARNING keystonemiddleware.auth_token [-] Retrying on HTTP connection exception: 'HTTPSConnectionPool' object has no attribute 'insecure'
2015-03-27 13:56:10.159 10962 ERROR keystonemiddleware.auth_token [-] HTTP connection exception: 'HTTPSConnectionPool' object has no attribute 'insecure'
2015-03-27 13:56:10.161 10962 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2015-03-27 13:56:10.162 10962 INFO nova.osapi_compute.wsgi.server [-] 128.250.116.173,172.26.9.144 "GET /v1.1/0bdf024c921848c4b74d9e69af9edf08/servers/detail HTTP/1.1" status: 401 len: 282 time: 3.5197592

[Davanum Srinivas (DIMS) (dims-v)]

please run "pip freeze" and send us the output for the different pythonclients and keystone components as well.

[Sam Morrison (sorrison)]

Hi,

I'm not using pip, this is using the ubuntu cloud archive juno packages

[Davanum Srinivas (DIMS) (dims-v)]

Hey Sam,

can you try patching keystonemiddleware/auth_token.py to print where exactly the exception is thrown from? LOG.exception('got an exception') should do the trick

thanks,
dims

[Sam Morrison (sorrison)]

OK I turned on keystonemiddleware DEBUG and get the below stack trace, I also ran it through PDB and it fails when it's getting the revocation list. It works the first time and then requests work, when it goes to get it again it the consistently fails from then onwards.

Keystone is definitely working and responding to requests. The weird thing is that restarting nova-api fixes it and will work for several requests before going back to the broken state.

2015-03-31 10:01:41.042 30520 WARNING keystonemiddleware.auth_token [-] Retrying on HTTP connection exception: 'HTTPSConnectionPool' object has no attribute 'insecure'
2015-03-31 10:01:41.545 30520 WARNING keystonemiddleware.auth_token [-] Retrying on HTTP connection exception: 'HTTPSConnectionPool' object has no attribute 'insecure'
2015-03-31 10:01:42.547 30520 WARNING keystonemiddleware.auth_token [-] Retrying on HTTP connection exception: 'HTTPSConnectionPool' object has no attribute 'insecure'
2015-03-31 10:01:44.549 30520 ERROR keystonemiddleware.auth_token [-] HTTP connection exception: 'HTTPSConnectionPool' object has no attribute 'insecure'
2015-03-31 10:01:44.550 30520 DEBUG keystonemiddleware.auth_token [-] Token validation failure. _validate_user_token /usr/lib/python2.7/dist-packages/keystonemiddleware/auth_token.py:922
2015-03-31 10:01:44.550 30520 TRACE keystonemiddleware.auth_token Traceback (most recent call last):
2015-03-31 10:01:44.550 30520 TRACE keystonemiddleware.auth_token File "/usr/lib/python2.7/dist-packages/keystonemiddleware/auth_token.py", line 913, in _validate_user_token
2015-03-31 10:01:44.550 30520 TRACE keystonemiddleware.auth_token verified = self._verify_signed_token(user_token, token_ids)
2015-03-31 10:01:44.550 30520 TRACE keystonemiddleware.auth_token File "/usr/lib/python2.7/dist-packages/keystonemiddleware/auth_token.py", line 1185, in _verify_signed_token
2015-03-31 10:01:44.550 30520 TRACE keystonemiddleware.auth_token if self._is_signed_token_revoked(token_ids):
2015-03-31 10:01:44.550 30520 TRACE keystonemiddleware.auth_token File "/usr/lib/python2.7/dist-packages/keystonemiddleware/auth_token.py", line 1137, in _is_signed_token_revoked
2015-03-31 10:01:44.550 30520 TRACE keystonemiddleware.auth_token if self._is_token_id_in_revoked_list(token_id):
2015-03-31 10:01:44.550 30520 TRACE keystonemiddleware.auth_token File "/usr/lib/python2.7/dist-packages/keystonemiddleware/auth_token.py", line 1144, in _is_token_id_in_revoked_list
2015-03-31 10:01:44.550 30520 TRACE keystonemiddleware.auth_token revocation_list = self._token_revocation_list
2015-03-31 10:01:44.550 30520 TRACE keystonemiddleware.auth_token File "/usr/lib/python2.7/dist-packages/keystonemiddleware/auth_token.py", line 1251, in _token_revocation_list
2015-03-31 10:01:44.550 30520 TRACE keystonemiddleware.auth_token self._token_revocation_list = self._fetch_revocation_list()
2015-03-31 10:01:44.550 30520 TRACE keystonemiddleware.auth_token File "/usr/lib/python2.7/dist-packages/keystonemiddleware/auth_token.py", line 1286, in _fetch_revocation_list
2015-03-31 10:01:44.550 30520 TRACE keystonemiddleware.auth_token additional_headers=headers)
2015-03...

[Sam Morrison (sorrison)]

I debugged it further and looks like something in python-requests, juno cloud archive has 2.3.0-1~cloud0

[Sam Morrison (sorrison)]

Also can confirm changing my nova.conf so that it connects to keystone over http as opposed to https fixes the issue

[Sam Morrison (sorrison)]

Changing back to new as details given

[Sean Dague (sdague)]

pip freeze will return distro installed packages as well, please provide that output.

[Sean Dague (sdague)]

I think this is probably still in glanceclient, so putting to incomplete in Nova until the pip results are in.

[Sam Morrison (sorrison)]

Ah OK didn't realise this, here are the results. I'll try patching glanceclient to see if that fixes it.

Babel==1.3
Cheetah==2.4.4
FormEncode==1.2.6
Jinja2==2.7.2
M2Crypto==0.21.1
Mako==0.9.1
MarkupSafe==0.18
MySQL-python==1.2.3
PAM==0.4.2
Paste==1.7.5.1
PasteDeploy==1.5.2
PyYAML==3.10
Routes==2.0
SQLAlchemy==0.9.7
Tempita==0.5.2
Twisted-Core==13.2.0
Twisted-Names==13.2.0
Twisted-Web==13.2.0
WSME==0.6
WebOb==1.3.1
alembic==0.6.5
amqp==1.4.5
amqplib==1.0.2
anyjson==0.3.3
apt-xapian-index==0.45
argparse==1.2.1
boto==2.20.1
bzr-etckeeper==0.0.0
chardet==2.0.1
cinder==1-2014.2.2-a22-g7b415fa-trusty-1
cliff==1.7.0
cloud-init==0.7.5
cmd2==0.6.7
colorama==0.2.5
configobj==4.7.2
decorator==3.4.0
dogpile.cache==0.5.4
dogpile.core==0.4.1
ecdsa==0.11
eventlet==0.15.2
futures==2.1.6
glance==2014.2.2
glance-store==0.1.8
greenlet==0.4.2
html5lib==0.999
httplib2==0.8
ipaddr==2.1.10
iso8601==0.1.10
jsonpatch==1.3
jsonpointer==1.0
jsonschema==2.3.0
keystone==1-2014.2.2-a17-gb06a63a-trusty-4
keystonemiddleware==1.0.0
kombu==3.0.7
ldappool==1.0
librabbitmq==1.0.3
lockfile==0.8
lxml==3.3.3
mock==1.0.1
netaddr==0.7.12
networkx==1.8.1
nova==2014.2.1-a74-g9256373-trusty
oauth==1.0.1
oauthlib==0.6.1
oslo.config==1.4.0.0
oslo.db==1.0.0
oslo.i18n==1.0.0
oslo.messaging==1.5.1-a1-g06c67fb-trusty-1
oslo.middleware==0.2.0
oslo.rootwrap==1.3.0
oslo.serialization==1.0.0
oslo.utils==1.0.0
oslo.vmware==0.6.0
osprofiler==0.3.0
paramiko==1.15.1
passlib==1.5.3
pbr==0.10.0
posix-ipc==0.9.8
prettytable==0.7.2
pyOpenSSL==0.13
pyasn1==0.1.7
pycadf==0.6.0
pycrypto==2.6.1
pycurl==7.19.3
pydns==2.3.6
pyparsing==2.0.1
pyserial==2.6
python-apt==0.9.3.5ubuntu1
python-barbicanclient==2.2.1
python-cinderclient==1.1.0
python-debian==0.1.21-nmu2ubuntu2
python-glanceclient==0.14.0
python-keystoneclient==0.10.1
python-ldap==2.4.10
python-memcached==1.53
python-neutronclient==2.3.8
python-novaclient==2.19.0
python-swiftclient==2.3.0
pytz==2012c
repoze.lru==0.6
requests==2.3.0
retrying==1.2.3
rfc3986==0.2.0
simplegeneric==0.8.1
simplejson==3.3.1
six==1.7.3
sqlalchemy-migrate==0.9.1
ssh-import-id==3.21
stevedore==1.1.0
suds==0.4.1
taskflow==0.3.21
urllib3==1.7.1
warlock==1.1.0
wsgiref==0.1.2
zope.interface==4.0.5

[Sam Morrison (sorrison)]

OK I can confirm this is a glanceclient issue, sorry for the noise nova.

To fix I installed the glanceclient package available in vivid. 1:0.15.0-0ubuntu1

This affects Juno Ubuntu installs

[Sam Morrison (sorrison)]

Fixed in 0.14.2

[Sam Morrison (sorrison)]

This bug is in the version of glance client in the juno cloud archive.

[Ian Cordasco (icordasc)]

Sam Morrison, how is a stack trace that seems entirely located in keystonemiddleware a bug in glanceclient?

[Sam Morrison (sorrison)]

I'm not entirely sure, but glance client is doing something with the underlying connection pool classes that keystonemiddleware and nova also use I think.

I don't understand it myself but I do know that by using a newer glanceclient the problem goes away.

I'm hoping someone who knows more than me will chime in :-)

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.

[Steve Martinelli (stevemar)]

looks like this has been resolved for a while, and the fix was in glanceclient, marking keystonemiddleware as invalid, please comment if anyone feels differently.

[Chuck Short (zulcss)]

This should be fixed in Ubuntu now.