yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1278843] [NEW] Neutron doesn't report using a stale CA certificate

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Piotr Wachowicz <1278843@xxxxxxxxxxxxxxxxxx>
Date: Tue, 11 Feb 2014 12:11:01 -0000
Reply-to: Bug 1278843 <1278843@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Public bug reported:

It seems that when the CA certificate cashed locally by Neutron in
/var/lib/neutron/keystone-signing/ is stale (does not match the current
CA cert used by keystone), it is not possible to start a new instance.
This is  understandable. However, the stacktrace error you get while
trying to start as instance in such a situation is a hugely misleading:

"ERROR: Error: unsupported operand type(s) for +: 'NoneType' and 'str'"

It's rather tricky to debug the issue.

To reproduce just redo the pki-setup for keystone on a deployed and
otherwise healthy openstack cluster. This will create a new CA cert for
keystone, however neutron-server will be completely oblivious to this
fact and will still insist on using it's local copy of the cacert.

I'm using Havana.

----------
/var/log/nova/compute.log  on the compute node when trying to start a vm

OpenStack (nova:4668) ERROR: Instance failed network setup after 1 attempt(s)
2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager Traceback (most recent call last):
2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 1238, in _allocate_network_async
2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager     dhcp_options=dhcp_options)
2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager   File "/usr/lib/python2.6/site-packages/nova/network/api.py", line 49, in wrapper
2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager     res = f(self, context, *args, **kwargs)
2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager   File "/usr/lib/python2.6/site-packages/nova/network/neutronv2/api.py", line 358, in allocate_for_instance
2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager     LOG.exception(msg, port_id)
2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager   File "/usr/lib/python2.6/site-packages/nova/network/neutronv2/api.py", line 323, in allocate_for_instance
2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager     port_req_body)
2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager   File "/usr/lib/python2.6/site-packages/nova/network/neutronv2/api.py", line 392, in _populate_neutron_extension_values
2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager     self._refresh_neutron_extensions_cache()
2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager   File "/usr/lib/python2.6/site-packages/nova/network/neutronv2/api.py", line 376, in _refresh_neutron_extensions_cache
2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager     extensions_list = neutron.list_extensions()['extensions']
2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager   File "/usr/lib/python2.6/site-packages/neutronclient/v2_0/client.py", line 108, in with_params
2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager     ret = self.function(instance, *args, **kwargs)
2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager   File "/usr/lib/python2.6/site-packages/neutronclient/v2_0/client.py", line 286, in list_extensions
2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager     return self.get(self.extensions_path, params=_params)
2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager   File "/usr/lib/python2.6/site-packages/neutronclient/v2_0/client.py", line 1183, in get
2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager     headers=headers, params=params)
2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager   File "/usr/lib/python2.6/site-packages/neutronclient/v2_0/client.py", line 1168, in retry_request
2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager     headers=headers, params=params)
2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager   File "/usr/lib/python2.6/site-packages/neutronclient/v2_0/client.py", line 1103, in do_request
2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager     resp, replybody = self.httpclient.do_request(action, method, body=body)
2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager   File "/usr/lib/python2.6/site-packages/neutronclient/client.py", line 188, in do_request
2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager     self.authenticate()
2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager   File "/usr/lib/python2.6/site-packages/neutronclient/client.py", line 224, in authenticate
2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager     token_url = self.auth_url + "/tokens"
2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager TypeError: unsupported operand type(s) for +: 'NoneType' and 'str'
2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager 


----------------
/var/log/neutron/server.log on the controller when trying to start a vm

OpenStack (neutron:29274) DEBUG: Removing headers from request environment: X-Identity-Status,X-Domain-Id,X-Domain-Name,X-Project-Id,X-Project-Name,X-Project-Domain-Id,X-Project-Domain-Name,X-User-Id,X-User-
Name,X-User-Domain-Id,X-User-Domain-Name,X-Roles,X-Service-Catalog,X-User,X-Tenant-Id,X-Tenant-Name,X-Tenant,X-Role
OpenStack (neutron:29274) INFO: Starting new HTTP connection (1): openstack
OpenStack (neutron:29274) DEBUG: received {u'_context_roles': [u'admin'], u'_context_read_deleted': u'no', u'_context_tenant_id': None, u'args': {u'agent_state': {u'agent_state': {u'topic': u'N/A', u'binary'
: u'neutron-openvswitch-agent', u'host': u'node001', u'agent_type': u'Open vSwitch agent', u'configurations': {u'tunnel_types': [], u'tunneling_ip': u'', u'bridge_mappings': {u'ph-eth0': u'br0'}, u'l2_popula
tion': False, u'devices': 0}}}, u'time': u'2014-02-11T12:06:32.434133'}, u'namespace': None, u'_unique_id': u'ae5c6b608f6547f7b630dace2c5411bd', u'_context_is_admin': True, u'version': u'1.0', u'_context_pro
ject_id': None, u'_context_timestamp': u'2014-02-11 12:00:14.386557', u'_context_user_id': None, u'method': u'report_state'}
OpenStack (neutron:29274) DEBUG: unpacked context: {'user_id': None, 'roles': [u'admin'], 'tenant_id': None, 'is_admin': True, 'timestamp': u'2014-02-11 12:00:14.386557', 'project_id': None, 'read_deleted': u'no'}
OpenStack (neutron:29274) DEBUG: "GET /v2.0/tokens/revoked HTTP/1.1" 200 1234
OpenStack (neutron:29274) WARNING: Verify error: Command 'openssl' returned non-zero exit status 4
OpenStack (neutron:29274) DEBUG: Token validation failure.
Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/keystoneclient/middleware/auth_token.py", line 808, in _validate_user_token
    verified = self.verify_signed_token(user_token)
  File "/usr/lib/python2.6/site-packages/keystoneclient/middleware/auth_token.py", line 1165, in verify_signed_token
    if self.is_signed_token_revoked(signed_text):
  File "/usr/lib/python2.6/site-packages/keystoneclient/middleware/auth_token.py", line 1127, in is_signed_token_revoked
    revocation_list = self.token_revocation_list
  File "/usr/lib/python2.6/site-packages/keystoneclient/middleware/auth_token.py", line 1217, in token_revocation_list
    self.token_revocation_list = self.fetch_revocation_list()
  File "/usr/lib/python2.6/site-packages/keystoneclient/middleware/auth_token.py", line 1247, in fetch_revocation_list
    return self.cms_verify(data['signed'])
  File "/usr/lib/python2.6/site-packages/keystoneclient/middleware/auth_token.py", line 1160, in cms_verify
    raise err
CalledProcessError: Command 'openssl' returned non-zero exit status 4
OpenStack (neutron:29274) DEBUG: Marking token c5e1c4ed4d0ab0db8bbaffbb33e139ba as unauthorized in memcache
OpenStack (neutron:29274) WARNING: Authorization failed for token c5e1c4ed4d0ab0db8bbaffbb33e139ba
OpenStack (neutron:29274) INFO: Invalid user token - rejecting request

** Affects: neutron
     Importance: Undecided
         Status: New


** Tags: instance neutron

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to neutron.
https://bugs.launchpad.net/bugs/1278843

Title:
  Neutron doesn't report using a stale CA certificate

Status in OpenStack Neutron (virtual network service):
  New

Bug description:
  It seems that when the CA certificate cashed locally by Neutron in
  /var/lib/neutron/keystone-signing/ is stale (does not match the
  current CA cert used by keystone), it is not possible to start a new
  instance. This is  understandable. However, the stacktrace error you
  get while trying to start as instance in such a situation is a hugely
  misleading:

  "ERROR: Error: unsupported operand type(s) for +: 'NoneType' and
  'str'"

  It's rather tricky to debug the issue.

  To reproduce just redo the pki-setup for keystone on a deployed and
  otherwise healthy openstack cluster. This will create a new CA cert
  for keystone, however neutron-server will be completely oblivious to
  this fact and will still insist on using it's local copy of the
  cacert.

  I'm using Havana.

  ----------
  /var/log/nova/compute.log  on the compute node when trying to start a vm

  OpenStack (nova:4668) ERROR: Instance failed network setup after 1 attempt(s)
  2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager Traceback (most recent call last):
  2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 1238, in _allocate_network_async
  2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager     dhcp_options=dhcp_options)
  2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager   File "/usr/lib/python2.6/site-packages/nova/network/api.py", line 49, in wrapper
  2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager     res = f(self, context, *args, **kwargs)
  2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager   File "/usr/lib/python2.6/site-packages/nova/network/neutronv2/api.py", line 358, in allocate_for_instance
  2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager     LOG.exception(msg, port_id)
  2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager   File "/usr/lib/python2.6/site-packages/nova/network/neutronv2/api.py", line 323, in allocate_for_instance
  2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager     port_req_body)
  2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager   File "/usr/lib/python2.6/site-packages/nova/network/neutronv2/api.py", line 392, in _populate_neutron_extension_values
  2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager     self._refresh_neutron_extensions_cache()
  2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager   File "/usr/lib/python2.6/site-packages/nova/network/neutronv2/api.py", line 376, in _refresh_neutron_extensions_cache
  2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager     extensions_list = neutron.list_extensions()['extensions']
  2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager   File "/usr/lib/python2.6/site-packages/neutronclient/v2_0/client.py", line 108, in with_params
  2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager     ret = self.function(instance, *args, **kwargs)
  2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager   File "/usr/lib/python2.6/site-packages/neutronclient/v2_0/client.py", line 286, in list_extensions
  2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager     return self.get(self.extensions_path, params=_params)
  2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager   File "/usr/lib/python2.6/site-packages/neutronclient/v2_0/client.py", line 1183, in get
  2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager     headers=headers, params=params)
  2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager   File "/usr/lib/python2.6/site-packages/neutronclient/v2_0/client.py", line 1168, in retry_request
  2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager     headers=headers, params=params)
  2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager   File "/usr/lib/python2.6/site-packages/neutronclient/v2_0/client.py", line 1103, in do_request
  2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager     resp, replybody = self.httpclient.do_request(action, method, body=body)
  2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager   File "/usr/lib/python2.6/site-packages/neutronclient/client.py", line 188, in do_request
  2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager     self.authenticate()
  2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager   File "/usr/lib/python2.6/site-packages/neutronclient/client.py", line 224, in authenticate
  2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager     token_url = self.auth_url + "/tokens"
  2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager TypeError: unsupported operand type(s) for +: 'NoneType' and 'str'
  2014-02-11 13:02:38.429 4668 TRACE nova.compute.manager 


  ----------------
  /var/log/neutron/server.log on the controller when trying to start a vm

  OpenStack (neutron:29274) DEBUG: Removing headers from request environment: X-Identity-Status,X-Domain-Id,X-Domain-Name,X-Project-Id,X-Project-Name,X-Project-Domain-Id,X-Project-Domain-Name,X-User-Id,X-User-
  Name,X-User-Domain-Id,X-User-Domain-Name,X-Roles,X-Service-Catalog,X-User,X-Tenant-Id,X-Tenant-Name,X-Tenant,X-Role
  OpenStack (neutron:29274) INFO: Starting new HTTP connection (1): openstack
  OpenStack (neutron:29274) DEBUG: received {u'_context_roles': [u'admin'], u'_context_read_deleted': u'no', u'_context_tenant_id': None, u'args': {u'agent_state': {u'agent_state': {u'topic': u'N/A', u'binary'
  : u'neutron-openvswitch-agent', u'host': u'node001', u'agent_type': u'Open vSwitch agent', u'configurations': {u'tunnel_types': [], u'tunneling_ip': u'', u'bridge_mappings': {u'ph-eth0': u'br0'}, u'l2_popula
  tion': False, u'devices': 0}}}, u'time': u'2014-02-11T12:06:32.434133'}, u'namespace': None, u'_unique_id': u'ae5c6b608f6547f7b630dace2c5411bd', u'_context_is_admin': True, u'version': u'1.0', u'_context_pro
  ject_id': None, u'_context_timestamp': u'2014-02-11 12:00:14.386557', u'_context_user_id': None, u'method': u'report_state'}
  OpenStack (neutron:29274) DEBUG: unpacked context: {'user_id': None, 'roles': [u'admin'], 'tenant_id': None, 'is_admin': True, 'timestamp': u'2014-02-11 12:00:14.386557', 'project_id': None, 'read_deleted': u'no'}
  OpenStack (neutron:29274) DEBUG: "GET /v2.0/tokens/revoked HTTP/1.1" 200 1234
  OpenStack (neutron:29274) WARNING: Verify error: Command 'openssl' returned non-zero exit status 4
  OpenStack (neutron:29274) DEBUG: Token validation failure.
  Traceback (most recent call last):
    File "/usr/lib/python2.6/site-packages/keystoneclient/middleware/auth_token.py", line 808, in _validate_user_token
      verified = self.verify_signed_token(user_token)
    File "/usr/lib/python2.6/site-packages/keystoneclient/middleware/auth_token.py", line 1165, in verify_signed_token
      if self.is_signed_token_revoked(signed_text):
    File "/usr/lib/python2.6/site-packages/keystoneclient/middleware/auth_token.py", line 1127, in is_signed_token_revoked
      revocation_list = self.token_revocation_list
    File "/usr/lib/python2.6/site-packages/keystoneclient/middleware/auth_token.py", line 1217, in token_revocation_list
      self.token_revocation_list = self.fetch_revocation_list()
    File "/usr/lib/python2.6/site-packages/keystoneclient/middleware/auth_token.py", line 1247, in fetch_revocation_list
      return self.cms_verify(data['signed'])
    File "/usr/lib/python2.6/site-packages/keystoneclient/middleware/auth_token.py", line 1160, in cms_verify
      raise err
  CalledProcessError: Command 'openssl' returned non-zero exit status 4
  OpenStack (neutron:29274) DEBUG: Marking token c5e1c4ed4d0ab0db8bbaffbb33e139ba as unauthorized in memcache
  OpenStack (neutron:29274) WARNING: Authorization failed for token c5e1c4ed4d0ab0db8bbaffbb33e139ba
  OpenStack (neutron:29274) INFO: Invalid user token - rejecting request

To manage notifications about this bug go to:
https://bugs.launchpad.net/neutron/+bug/1278843/+subscriptions
Follow ups

[Bug 1278843] Re: Neutron doesn't report using a stale CA certificate
From: Adam Young, 2014-08-11
[Bug 1278843] [NEW] Neutron doesn't report using a stale CA certificate
From: Piotr Wachowicz, 2014-02-11
References

[Bug 1278843] [NEW] Neutron doesn't report using a stale CA certificate
From: Piotr Wachowicz, 2014-02-11