yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1706772] Re: InternalServerError: Internal Server Error (HTTP 500) in n-cpu logs on startup with Ironic driver

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Matt Riedemann <mriedem.os@xxxxxxxxx>
Date: Wed, 26 Jul 2017 22:03:22 -0000
Reply-to: Bug 1706772 <1706772@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Looks like the failure is in ironic-api on startup:

http://logs.openstack.org/80/461480/5/check/gate-tempest-dsvm-ironic-
ipa-wholedisk-bios-agent_ipmitool-tinyipa-ubuntu-xenial-nv/834477a/logs
/screen-ir-api.txt.gz#_Jul_19_03_34_01_680460

Jul 19 03:34:01.678194 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]: WARNING keystoneauth.identity.generic.base [-] Failed to discover available identity versions when contacting http://10.0.1.4/identity. Attempting to parse version from URL.: ConnectFailure: Unable to establish connection to http://10.0.1.4/identity: HTTPConnectionPool(host='10.0.1.4', port=80): Max retries exceeded with url: /identity (Caused by NewConnectionError('<urllib3.connection.HTTPConnection object at 0x7f06c5d86050>: Failed to establish a new connection: [Errno 111] ECONNREFUSED',))
Jul 19 03:34:01.680460 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]: INFO eventlet.wsgi.server [-] Traceback (most recent call last):
Jul 19 03:34:01.680615 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:   File "/usr/local/lib/python2.7/dist-packages/eventlet/wsgi.py", line 490, in handle_one_response
Jul 19 03:34:01.680747 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:     result = self.application(self.environ, start_response)
Jul 19 03:34:01.680907 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:   File "/opt/stack/new/ironic/ironic/api/app.py", line 114, in __call__
Jul 19 03:34:01.681047 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:     return self.v1(environ, start_response)
Jul 19 03:34:01.681215 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:   File "/usr/local/lib/python2.7/dist-packages/webob/dec.py", line 131, in __call__
Jul 19 03:34:01.681359 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:     resp = self.call_func(req, *args, **self.kwargs)
Jul 19 03:34:01.681488 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:   File "/usr/local/lib/python2.7/dist-packages/webob/dec.py", line 196, in call_func
Jul 19 03:34:01.681622 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:     return self.func(req, *args, **kwargs)
Jul 19 03:34:01.681747 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:   File "/usr/local/lib/python2.7/dist-packages/oslo_middleware/base.py", line 131, in __call__
Jul 19 03:34:01.681871 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:     response = req.get_response(self.application)
Jul 19 03:34:01.682003 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:   File "/usr/local/lib/python2.7/dist-packages/webob/request.py", line 1316, in send
Jul 19 03:34:01.682142 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:     application, catch_exc_info=False)
Jul 19 03:34:01.682279 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:   File "/usr/local/lib/python2.7/dist-packages/webob/request.py", line 1280, in call_application
Jul 19 03:34:01.682408 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:     app_iter = application(self.environ, start_response)
Jul 19 03:34:01.682541 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:   File "/opt/stack/new/ironic/ironic/api/middleware/auth_token.py", line 59, in __call__
Jul 19 03:34:01.682666 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:     return super(AuthTokenMiddleware, self).__call__(env, start_response)
Jul 19 03:34:01.682790 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:   File "/usr/local/lib/python2.7/dist-packages/webob/dec.py", line 131, in __call__
Jul 19 03:34:01.682913 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:     resp = self.call_func(req, *args, **self.kwargs)
Jul 19 03:34:01.683038 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:   File "/usr/local/lib/python2.7/dist-packages/webob/dec.py", line 196, in call_func
Jul 19 03:34:01.683176 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:     return self.func(req, *args, **kwargs)
Jul 19 03:34:01.683302 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:   File "/usr/local/lib/python2.7/dist-packages/keystonemiddleware/auth_token/__init__.py", line 332, in __call__
Jul 19 03:34:01.683440 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:     response = self.process_request(req)
Jul 19 03:34:01.683565 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:   File "/usr/local/lib/python2.7/dist-packages/keystonemiddleware/auth_token/__init__.py", line 623, in process_request
Jul 19 03:34:01.683692 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:     resp = super(AuthProtocol, self).process_request(request)
Jul 19 03:34:01.683823 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:   File "/usr/local/lib/python2.7/dist-packages/keystonemiddleware/auth_token/__init__.py", line 405, in process_request
Jul 19 03:34:01.683952 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:     allow_expired=allow_expired)
Jul 19 03:34:01.684104 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:   File "/usr/local/lib/python2.7/dist-packages/keystonemiddleware/auth_token/__init__.py", line 435, in _do_fetch_token
Jul 19 03:34:01.684232 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:     data = self.fetch_token(token, **kwargs)
Jul 19 03:34:01.684357 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:   File "/usr/local/lib/python2.7/dist-packages/keystonemiddleware/auth_token/__init__.py", line 762, in fetch_token
Jul 19 03:34:01.684494 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:     allow_expired=allow_expired)
Jul 19 03:34:01.684618 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:   File "/usr/local/lib/python2.7/dist-packages/keystonemiddleware/auth_token/_identity.py", line 217, in verify_token
Jul 19 03:34:01.684753 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:     auth_ref = self._request_strategy.verify_token(
Jul 19 03:34:01.684900 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:   File "/usr/local/lib/python2.7/dist-packages/keystonemiddleware/auth_token/_identity.py", line 168, in _request_strategy
Jul 19 03:34:01.685029 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:     strategy_class = self._get_strategy_class()
Jul 19 03:34:01.685167 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:   File "/usr/local/lib/python2.7/dist-packages/keystonemiddleware/auth_token/_identity.py", line 190, in _get_strategy_class
Jul 19 03:34:01.685294 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:     if self._adapter.get_endpoint(version=klass.AUTH_VERSION):
Jul 19 03:34:01.685434 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:   File "/usr/local/lib/python2.7/dist-packages/keystoneauth1/adapter.py", line 193, in get_endpoint
Jul 19 03:34:01.685568 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:     return self.session.get_endpoint(auth or self.auth, **kwargs)
Jul 19 03:34:01.685698 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:   File "/usr/local/lib/python2.7/dist-packages/keystoneauth1/session.py", line 856, in get_endpoint
Jul 19 03:34:01.685827 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:     return auth.get_endpoint(self, **kwargs)
Jul 19 03:34:01.685956 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:   File "/usr/local/lib/python2.7/dist-packages/keystoneauth1/identity/base.py", line 215, in get_endpoint
Jul 19 03:34:01.686093 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:     service_catalog = self.get_access(session).service_catalog
Jul 19 03:34:01.686230 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:   File "/usr/local/lib/python2.7/dist-packages/keystoneauth1/identity/base.py", line 136, in get_access
Jul 19 03:34:01.686361 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:     self.auth_ref = self.get_auth_ref(session)
Jul 19 03:34:01.686486 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:   File "/usr/local/lib/python2.7/dist-packages/keystoneauth1/identity/generic/base.py", line 196, in get_auth_ref
Jul 19 03:34:01.686616 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:     self._plugin = self._do_create_plugin(session)
Jul 19 03:34:01.686751 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:   File "/usr/local/lib/python2.7/dist-packages/keystoneauth1/identity/generic/base.py", line 191, in _do_create_plugin
Jul 19 03:34:01.686882 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]:     raise exceptions.DiscoveryFailure('Could not determine a suitable URL '
Jul 19 03:34:01.687011 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]: DiscoveryFailure: Could not determine a suitable URL for the plugin
Jul 19 03:34:01.687147 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]: 
Jul 19 03:34:01.689718 ubuntu-xenial-citycloud-la1-9927584 ironic-api[16734]: INFO eventlet.wsgi.server [-] 10.0.1.4 "GET /v1/nodes/detail HTTP/1.1" status: 500  len: 139 time: 0.0134780

** Also affects: ironic
   Importance: Undecided
       Status: New

** Changed in: ironic
       Status: New => Confirmed

** Changed in: nova
       Status: Confirmed => Invalid

-- 
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/1706772

Title:
  InternalServerError: Internal Server Error (HTTP 500) in n-cpu logs on
  startup with Ironic driver

Status in Ironic:
  Confirmed
Status in OpenStack Compute (nova):
  Invalid

Bug description:
  The init_host stacktraces on startup, killing the thread:

  http://logs.openstack.org/49/484949/14/check/gate-tempest-dsvm-ironic-
  ipa-wholedisk-bios-agent_ipmitool-tinyipa-ubuntu-xenial-
  nv/69b18d7/logs/screen-n-cpu.txt.gz?level=TRACE

  Jul 24 22:26:26.423871 ubuntu-xenial-osic-cloud1-disk-10052658 nova-compute[13755]: ERROR oslo_service.service [None req-414af81a-44e7-4a67-9cbd-74e549deb41b None None] Error starting thread.: InternalServerError: Internal Server Error (HTTP 500)
  Jul 24 22:26:26.423993 ubuntu-xenial-osic-cloud1-disk-10052658 nova-compute[13755]: ERROR oslo_service.service Traceback (most recent call last):
  Jul 24 22:26:26.424084 ubuntu-xenial-osic-cloud1-disk-10052658 nova-compute[13755]: ERROR oslo_service.service   File "/usr/local/lib/python2.7/dist-packages/oslo_service/service.py", line 721, in run_service
  Jul 24 22:26:26.424167 ubuntu-xenial-osic-cloud1-disk-10052658 nova-compute[13755]: ERROR oslo_service.service     service.start()
  Jul 24 22:26:26.424250 ubuntu-xenial-osic-cloud1-disk-10052658 nova-compute[13755]: ERROR oslo_service.service   File "/opt/stack/new/nova/nova/service.py", line 143, in start
  Jul 24 22:26:26.424330 ubuntu-xenial-osic-cloud1-disk-10052658 nova-compute[13755]: ERROR oslo_service.service     self.manager.init_host()
  Jul 24 22:26:26.424417 ubuntu-xenial-osic-cloud1-disk-10052658 nova-compute[13755]: ERROR oslo_service.service   File "/opt/stack/new/nova/nova/compute/manager.py", line 1100, in init_host
  Jul 24 22:26:26.424498 ubuntu-xenial-osic-cloud1-disk-10052658 nova-compute[13755]: ERROR oslo_service.service     self.driver.init_host(host=self.host)
  Jul 24 22:26:26.424638 ubuntu-xenial-osic-cloud1-disk-10052658 nova-compute[13755]: ERROR oslo_service.service   File "/opt/stack/new/nova/nova/virt/ironic/driver.py", line 449, in init_host
  Jul 24 22:26:26.424717 ubuntu-xenial-osic-cloud1-disk-10052658 nova-compute[13755]: ERROR oslo_service.service     self._refresh_cache()
  Jul 24 22:26:26.424798 ubuntu-xenial-osic-cloud1-disk-10052658 nova-compute[13755]: ERROR oslo_service.service   File "/opt/stack/new/nova/nova/virt/ironic/driver.py", line 608, in _refresh_cache
  Jul 24 22:26:26.425096 ubuntu-xenial-osic-cloud1-disk-10052658 nova-compute[13755]: ERROR oslo_service.service     for node in self._get_node_list(detail=True, limit=0):
  Jul 24 22:26:26.425187 ubuntu-xenial-osic-cloud1-disk-10052658 nova-compute[13755]: ERROR oslo_service.service   File "/opt/stack/new/nova/nova/virt/ironic/driver.py", line 527, in _get_node_list
  Jul 24 22:26:26.425278 ubuntu-xenial-osic-cloud1-disk-10052658 nova-compute[13755]: ERROR oslo_service.service     node_list = self.ironicclient.call("node.list", **kwargs)
  Jul 24 22:26:26.425359 ubuntu-xenial-osic-cloud1-disk-10052658 nova-compute[13755]: ERROR oslo_service.service   File "/opt/stack/new/nova/nova/virt/ironic/client_wrapper.py", line 146, in call
  Jul 24 22:26:26.425440 ubuntu-xenial-osic-cloud1-disk-10052658 nova-compute[13755]: ERROR oslo_service.service     return self._multi_getattr(client, method)(*args, **kwargs)
  Jul 24 22:26:26.425536 ubuntu-xenial-osic-cloud1-disk-10052658 nova-compute[13755]: ERROR oslo_service.service   File "/usr/local/lib/python2.7/dist-packages/ironicclient/v1/node.py", line 143, in list
  Jul 24 22:26:26.425614 ubuntu-xenial-osic-cloud1-disk-10052658 nova-compute[13755]: ERROR oslo_service.service     limit=limit)
  Jul 24 22:26:26.425708 ubuntu-xenial-osic-cloud1-disk-10052658 nova-compute[13755]: ERROR oslo_service.service   File "/usr/local/lib/python2.7/dist-packages/ironicclient/common/base.py", line 149, in _list_pagination
  Jul 24 22:26:26.425788 ubuntu-xenial-osic-cloud1-disk-10052658 nova-compute[13755]: ERROR oslo_service.service     resp, body = self.api.json_request('GET', url)
  Jul 24 22:26:26.425866 ubuntu-xenial-osic-cloud1-disk-10052658 nova-compute[13755]: ERROR oslo_service.service   File "/usr/local/lib/python2.7/dist-packages/ironicclient/common/http.py", line 558, in json_request
  Jul 24 22:26:26.425945 ubuntu-xenial-osic-cloud1-disk-10052658 nova-compute[13755]: ERROR oslo_service.service     resp = self._http_request(url, method, **kwargs)
  Jul 24 22:26:26.426027 ubuntu-xenial-osic-cloud1-disk-10052658 nova-compute[13755]: ERROR oslo_service.service   File "/usr/local/lib/python2.7/dist-packages/ironicclient/common/http.py", line 188, in wrapper
  Jul 24 22:26:26.426114 ubuntu-xenial-osic-cloud1-disk-10052658 nova-compute[13755]: ERROR oslo_service.service     return func(self, url, method, **kwargs)
  Jul 24 22:26:26.426198 ubuntu-xenial-osic-cloud1-disk-10052658 nova-compute[13755]: ERROR oslo_service.service   File "/usr/local/lib/python2.7/dist-packages/ironicclient/common/http.py", line 540, in _http_request
  Jul 24 22:26:26.426277 ubuntu-xenial-osic-cloud1-disk-10052658 nova-compute[13755]: ERROR oslo_service.service     error_json.get('debuginfo'), method, url)
  Jul 24 22:26:26.426355 ubuntu-xenial-osic-cloud1-disk-10052658 nova-compute[13755]: ERROR oslo_service.service InternalServerError: Internal Server Error (HTTP 500)
  Jul 24 22:26:26.426437 ubuntu-xenial-osic-cloud1-disk-10052658 nova-compute[13755]: ERROR oslo_service.service

  I guess the Ironic API service isn't yet up at that point?

To manage notifications about this bug go to:
https://bugs.launchpad.net/ironic/+bug/1706772/+subscriptions
References

[Bug 1706772] [NEW] InternalServerError: Internal Server Error (HTTP 500) in n-cpu logs on startup with Ironic driver
From: Matt Riedemann, 2017-07-26