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

Actually this wasn't caused by the migrate instance flavors change mentioned above, it was happening before that as well:

http://logs.openstack.org/80/461480/5/check/gate-tempest-dsvm-ironic-ipa-wholedisk-bios-agent_ipmitool-tinyipa-ubuntu-xenial-nv/834477a/logs/screen-n-cpu.txt.gz?level=TRACE#_Jul_19_03_34_01_687299

So something has thrown off the timing of when nova-compute starts up and when the ironic-api is available.

This wasn't an issue in Ocata. From Ocata CI logs, the init_host in the driver happens around here:

http://logs.openstack.org/63/485263/2/check/gate-tempest-dsvm-ironic-ipa-wholedisk-bios-agent_ipmitool-tinyipa-ubuntu-xenial-nv/de2c924/logs/screen-n-cpu.txt.gz#_2017-07-21_12_07_20_885

And then get_available_nodes is here:

http://logs.openstack.org/63/485263/2/check/gate-tempest-dsvm-ironic-ipa-wholedisk-bios-agent_ipmitool-tinyipa-ubuntu-xenial-nv/de2c924/logs/screen-n-cpu.txt.gz#_2017-07-21_12_07_21_167

So that's not blowing up like init_host is blowing up in Pike.

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.682...

http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22DiscoveryFailure%3A%20Could%20not%20determine%20a%20suitable%20URL%20for%20the%20plugin%5C%22%20AND%20tags%3A%5C%22screen-ir-api.txt%5C%22&from=7d

The reason is someone restarting apache at that moment -- http://logs.openstack.org/49/484949/14/check/gate-tempest-dsvm-ironic-ipa-wholedisk-bios-agent_ipmitool-tinyipa-ubuntu-xenial-nv/69b18d7/logs/apache/error.txt.gz. We need to come up with an idea how to work around this (again)

Fix proposed to branch: master
Review: https://review.openstack.org/487925

Note that this fix only smooths the behavior in the ironic driver so that it doesn't crash when this happens.

Fix proposed to branch: stable/ocata
Review: https://review.openstack.org/491835

Reviewed: https://review.openstack.org/487925
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=c2d33c3271370358d48553233b41bf9119d834fb
Submitter: Jenkins
Branch: master

commit c2d33c3271370358d48553233b41bf9119d834fb
Author: EdLeafe <email address hidden>
Date: Wed Jul 26 23:07:38 2017 +0000

    Handle ironicclient failures in Ironic driver

    The ironic driver uses ironicclient to get the list of nodes from the
    Ironic service. If that service is not running, or something otherwise
    prevents the ironicclient's call from succeeding, and unhandled
    exception will occur. This patch adds a generic exception handler for
    this call, logging an error and continuing.

    Co-Authored-By: Lucas Alvares Gomes <email address hidden>

    Closes-Bug: #1706772

    Change-Id: I4ebebcf221dfe29e2aa125f5956aec10108f8fbe

We're also hitting this issue on our grenade job on ocata http://logs.openstack.org/04/480904/10/check/gate-grenade-dsvm-ironic-ubuntu-xenial/a13a964/logs/new/screen-n-cpu.txt.gz. In this case, placement start causes apache restart, and compute is started at the same time. Will propose a patch to grenade and see if it'll break anything.

This issue was fixed in the openstack/nova 16.0.0.0rc1 release candidate.

Reviewed: https://review.openstack.org/491835
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=c46f037a0f57710553b5ff8f02bc08ebedf3c5fb
Submitter: Jenkins
Branch: stable/ocata

commit c46f037a0f57710553b5ff8f02bc08ebedf3c5fb
Author: EdLeafe <email address hidden>
Date: Wed Jul 26 23:07:38 2017 +0000

    Handle ironicclient failures in Ironic driver

    The ironic driver uses ironicclient to get the list of nodes from the
    Ironic service. If that service is not running, or something otherwise
    prevents the ironicclient's call from succeeding, and unhandled
    exception will occur. This patch adds a generic exception handler for
    this call, logging an error and continuing.

    Co-Authored-By: Lucas Alvares Gomes <email address hidden>

    Closes-Bug: #1706772

    Conflicts:
          nova/tests/unit/virt/ironic/test_driver.py

    NOTE(mriedem): The conflicts in the tests can be ignored since they
    were just around some boot from volume and flavor migration tests
    in Pike which don't exist in Ocata. Also, the _LE translation marker
    has to be added back in for LOG.error in Ocata due to hacking checks.

    Change-Id: I4ebebcf221dfe29e2aa125f5956aec10108f8fbe
    (cherry picked from commit c2d33c3271370358d48553233b41bf9119d834fb)

This issue was fixed in the openstack/nova 15.0.7 release.