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 -- Mailing list: https://launchpad.net/~yahoo-eng-team Post to : yahoo-eng-team@lists.launchpad.net Unsubscribe : https://launchpad.net/~yahoo-eng-team More help : https://help.launchpad.net/ListHelp