yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1534066] [NEW] Resize failed when instance get large

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: leehom <feli5@xxxxxxxxx>
Date: Thu, 14 Jan 2016 09:15:18 -0000
Reply-to: Bug 1534066 <1534066@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Public bug reported:

I'm using OpenStack Juno rel
$ rpm -qa |grep nova
python-nova-2014.2.2-1.el7.noarch
openstack-nova-scheduler-2014.2.2-1.el7.noarch
python-novaclient-2.20.0-1.el7.centos.noarch
openstack-nova-common-2014.2.2-1.el7.noarch
openstack-nova-api-2014.2.2-1.el7.noarch
openstack-nova-cert-2014.2.2-1.el7.noarch
openstack-nova-console-2014.2.2-1.el7.noarch
openstack-nova-conductor-2014.2.2-1.el7.noarch
openstack-nova-novncproxy-2014.2.2-1.el7.noarch

Describe about the problem
1. At first, /usr/lib/python2.7/site-packages/neutronclient/client.py:do_request() is failed with exceptions.Unauthorized
    -> Token is not expired, but after checking keystone's log, it is somehow deleted
2. When try to do authenticate(), it's failed with exceptions.NoAuthURLProvided()


Here is log found from nova-compute

2016-01-07 16:08:42.396 1334 DEBUG neutronclient.client [req-7d95c82d-b26a-4584-851b-95de5c99f17c ]
REQ: curl -i https://hf1-neutron.qa.webex.com:443/v2.0/extensions.json -X GET -H "X-Auth-Token: 119b7628442f4e19b4bd1041d05c2afa" -H "User-Agent: python-neutronclient"
 http_log_req /usr/lib/python2.7/site-packages/neutronclient/common/utils.py:140
2016-01-07 16:08:42.473 1334 DEBUG neutronclient.client [req-7d95c82d-b26a-4584-851b-95de5c99f17c ] RESP:401 {'content-length': '23', 'www-authenticate': "Keystone uri='https://hf1-keystone-srv.qa.webex.com:443/v2.0'", 'connection': 'keep-alive', 'date': 'Thu, 07 Jan 2016 16:08:42 GMT', 'content-type': 'text/plain', 'x-openstack-request-id': 'req-36035958-9e5d-44db-a12a-0ed0764a7d0e'} Authentication required
 http_log_resp /usr/lib/python2.7/site-packages/neutronclient/common/utils.py:149
2016-01-07 16:08:42.474 1334 ERROR nova.compute.manager [req-7d95c82d-b26a-4584-851b-95de5c99f17c None] [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127] Setting instance vm_state to ERROR
2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127] Traceback (most recent call last):
2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 3904, in finish_resize
2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]     disk_info, image)
2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 3843, in _finish_resize
2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]     migration_p)
2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]   File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 1241, in migrate_instance_finish
2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]     if not self._has_port_binding_extension(context, refresh_cache=True):
2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]   File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 471, in _has_port_binding_extension
2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]     self._refresh_neutron_extensions_cache(context)
2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]   File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 463, in _refresh_neutron_extensions_cache
2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]     extensions_list = neutron.list_extensions()['extensions']
2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]   File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 98, in with_params
2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]     ret = self.function(instance, *args, **kwargs)
2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]   File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 300, in list_extensions
2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]     return self.get(self.extensions_path, params=_params)
2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]   File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 1320, in get
2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]     headers=headers, params=params)
2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]   File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 1297, in retry_request
2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]     headers=headers, params=params)
2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]   File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 1240, in do_request
2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]     content_type=self.content_type())
2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]   File "/usr/lib/python2.7/site-packages/neutronclient/client.py", line 183, in do_request
2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]     self.authenticate()
2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]   File "/usr/lib/python2.7/site-packages/neutronclient/client.py", line 247, in authenticate
2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]     self._authenticate_keystone()
2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]   File "/usr/lib/python2.7/site-packages/neutronclient/client.py", line 220, in _authenticate_keystone
2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]     raise exceptions.NoAuthURLProvided()
2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127] NoAuthURLProvided: auth_url was not provided to the Neutron client
2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]


Here is the log found from keystone

# zcat /var/log/keystone/keystone.log-20160110.gz | grep 119b7628442f4e19b4bd1041d05c2afa
2016-01-07 04:48:13.474 20083 DEBUG keystone.common.wsgi [-] arg_dict: {'token_id': u'119b7628442f4e19b4bd1041d05c2afa'} __call__ /usr/lib/python2.7/site-packages/keystone/common/wsgi.py:191
2016-01-07 04:48:13.475 20083 DEBUG keystone.common.controller [-] RBAC: Authorizing identity:validate_token(token_id=119b7628442f4e19b4bd1041d05c2afa) _build_policy_check_credentials /usr/lib/python2.7/site-packages/keystone/common/controller.py:55
2016-01-07 04:48:13.485 20083 INFO eventlet.wsgi.server [-] 10.224.241.140,10.224.236.93 - - [07/Jan/2016 04:48:13] "GET /v2.0/tokens/119b7628442f4e19b4bd1041d05c2afa HTTP/1.1" 200 2157 0.023179
2016-01-07 05:27:10.502 20083 DEBUG keystone.common.wsgi [-] arg_dict: {'token_id': u'119b7628442f4e19b4bd1041d05c2afa'} __call__ /usr/lib/python2.7/site-packages/keystone/common/wsgi.py:191
2016-01-07 05:27:10.503 20083 DEBUG keystone.common.controller [-] RBAC: Authorizing identity:validate_token(token_id=119b7628442f4e19b4bd1041d05c2afa) _build_policy_check_credentials /usr/lib/python2.7/site-packages/keystone/common/controller.py:55
2016-01-07 05:27:10.513 20083 INFO eventlet.wsgi.server [-] 10.224.241.141,10.224.236.93 - - [07/Jan/2016 05:27:10] "GET /v2.0/tokens/119b7628442f4e19b4bd1041d05c2afa HTTP/1.1" 200 2157 0.022409


And here is found token from databse
| id                                                                         | expires                            | extra  | valid | trust_id | user_id                          |                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                             
| 119b7628442f4e19b4bd1041d05c2afa | 2016-01-08 04:47:23 | {"bind": null, "token_data": {"access": {"token": {"issued_at": "2016-01-07T04:48:10.638860", "expires": "2016-01-08T04:47:23Z", ...  |     0 | NULL     | e35c77abe1384bf2a1f50363d870b44f |

** Affects: nova
     Importance: Undecided
         Status: New

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to OpenStack Compute (nova).
https://bugs.launchpad.net/bugs/1534066

Title:
  Resize failed when instance get large

Status in OpenStack Compute (nova):
  New

Bug description:
  I'm using OpenStack Juno rel
  $ rpm -qa |grep nova
  python-nova-2014.2.2-1.el7.noarch
  openstack-nova-scheduler-2014.2.2-1.el7.noarch
  python-novaclient-2.20.0-1.el7.centos.noarch
  openstack-nova-common-2014.2.2-1.el7.noarch
  openstack-nova-api-2014.2.2-1.el7.noarch
  openstack-nova-cert-2014.2.2-1.el7.noarch
  openstack-nova-console-2014.2.2-1.el7.noarch
  openstack-nova-conductor-2014.2.2-1.el7.noarch
  openstack-nova-novncproxy-2014.2.2-1.el7.noarch

  Describe about the problem
  1. At first, /usr/lib/python2.7/site-packages/neutronclient/client.py:do_request() is failed with exceptions.Unauthorized
      -> Token is not expired, but after checking keystone's log, it is somehow deleted
  2. When try to do authenticate(), it's failed with exceptions.NoAuthURLProvided()


  Here is log found from nova-compute

  2016-01-07 16:08:42.396 1334 DEBUG neutronclient.client [req-7d95c82d-b26a-4584-851b-95de5c99f17c ]
  REQ: curl -i https://hf1-neutron.qa.webex.com:443/v2.0/extensions.json -X GET -H "X-Auth-Token: 119b7628442f4e19b4bd1041d05c2afa" -H "User-Agent: python-neutronclient"
   http_log_req /usr/lib/python2.7/site-packages/neutronclient/common/utils.py:140
  2016-01-07 16:08:42.473 1334 DEBUG neutronclient.client [req-7d95c82d-b26a-4584-851b-95de5c99f17c ] RESP:401 {'content-length': '23', 'www-authenticate': "Keystone uri='https://hf1-keystone-srv.qa.webex.com:443/v2.0'", 'connection': 'keep-alive', 'date': 'Thu, 07 Jan 2016 16:08:42 GMT', 'content-type': 'text/plain', 'x-openstack-request-id': 'req-36035958-9e5d-44db-a12a-0ed0764a7d0e'} Authentication required
   http_log_resp /usr/lib/python2.7/site-packages/neutronclient/common/utils.py:149
  2016-01-07 16:08:42.474 1334 ERROR nova.compute.manager [req-7d95c82d-b26a-4584-851b-95de5c99f17c None] [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127] Setting instance vm_state to ERROR
  2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127] Traceback (most recent call last):
  2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 3904, in finish_resize
  2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]     disk_info, image)
  2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 3843, in _finish_resize
  2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]     migration_p)
  2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]   File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 1241, in migrate_instance_finish
  2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]     if not self._has_port_binding_extension(context, refresh_cache=True):
  2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]   File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 471, in _has_port_binding_extension
  2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]     self._refresh_neutron_extensions_cache(context)
  2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]   File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 463, in _refresh_neutron_extensions_cache
  2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]     extensions_list = neutron.list_extensions()['extensions']
  2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]   File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 98, in with_params
  2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]     ret = self.function(instance, *args, **kwargs)
  2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]   File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 300, in list_extensions
  2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]     return self.get(self.extensions_path, params=_params)
  2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]   File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 1320, in get
  2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]     headers=headers, params=params)
  2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]   File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 1297, in retry_request
  2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]     headers=headers, params=params)
  2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]   File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 1240, in do_request
  2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]     content_type=self.content_type())
  2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]   File "/usr/lib/python2.7/site-packages/neutronclient/client.py", line 183, in do_request
  2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]     self.authenticate()
  2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]   File "/usr/lib/python2.7/site-packages/neutronclient/client.py", line 247, in authenticate
  2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]     self._authenticate_keystone()
  2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]   File "/usr/lib/python2.7/site-packages/neutronclient/client.py", line 220, in _authenticate_keystone
  2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]     raise exceptions.NoAuthURLProvided()
  2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127] NoAuthURLProvided: auth_url was not provided to the Neutron client
  2016-01-07 16:08:42.474 1334 TRACE nova.compute.manager [instance: fc8d35d5-874d-4c09-9f23-9bf7587b2127]


  Here is the log found from keystone

  # zcat /var/log/keystone/keystone.log-20160110.gz | grep 119b7628442f4e19b4bd1041d05c2afa
  2016-01-07 04:48:13.474 20083 DEBUG keystone.common.wsgi [-] arg_dict: {'token_id': u'119b7628442f4e19b4bd1041d05c2afa'} __call__ /usr/lib/python2.7/site-packages/keystone/common/wsgi.py:191
  2016-01-07 04:48:13.475 20083 DEBUG keystone.common.controller [-] RBAC: Authorizing identity:validate_token(token_id=119b7628442f4e19b4bd1041d05c2afa) _build_policy_check_credentials /usr/lib/python2.7/site-packages/keystone/common/controller.py:55
  2016-01-07 04:48:13.485 20083 INFO eventlet.wsgi.server [-] 10.224.241.140,10.224.236.93 - - [07/Jan/2016 04:48:13] "GET /v2.0/tokens/119b7628442f4e19b4bd1041d05c2afa HTTP/1.1" 200 2157 0.023179
  2016-01-07 05:27:10.502 20083 DEBUG keystone.common.wsgi [-] arg_dict: {'token_id': u'119b7628442f4e19b4bd1041d05c2afa'} __call__ /usr/lib/python2.7/site-packages/keystone/common/wsgi.py:191
  2016-01-07 05:27:10.503 20083 DEBUG keystone.common.controller [-] RBAC: Authorizing identity:validate_token(token_id=119b7628442f4e19b4bd1041d05c2afa) _build_policy_check_credentials /usr/lib/python2.7/site-packages/keystone/common/controller.py:55
  2016-01-07 05:27:10.513 20083 INFO eventlet.wsgi.server [-] 10.224.241.141,10.224.236.93 - - [07/Jan/2016 05:27:10] "GET /v2.0/tokens/119b7628442f4e19b4bd1041d05c2afa HTTP/1.1" 200 2157 0.022409

  
  And here is found token from databse
  | id                                                                         | expires                            | extra  | valid | trust_id | user_id                          |                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                             
  | 119b7628442f4e19b4bd1041d05c2afa | 2016-01-08 04:47:23 | {"bind": null, "token_data": {"access": {"token": {"issued_at": "2016-01-07T04:48:10.638860", "expires": "2016-01-08T04:47:23Z", ...  |     0 | NULL     | e35c77abe1384bf2a1f50363d870b44f |

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

[Bug 1534066] Re: Resize failed when instance get large
From: Markus Zoeller (markus_z), 2016-01-22