loopingcall logging ERROR for HTTPBadRequest

[Lucas Alvares Gomes]

When deploying a node even if everything went well one ERROR still being logged which may cause some confusion. For some operations the HTTPBadRequest is not an error, but part of the workflow. For e.g:

As part of the spawn() process unplug_vif() will be called and Nova Ironic Driver will then send a request to the Ironic API asking it to remove the extra/vif_port_id attribute of the node, but the attribute may not be set, so it will return a HTTPBadRequest which should be handled and just 'passed'... As this exception happens inside a loopingcall loop it will then log it as an error.

2014-04-14 11:00:55.500 DEBUG ironicclient.common.http [-]
HTTP/1.0 400 Bad Request
date: Mon, 14 Apr 2014 10:00:55 GMT
content-length: 187
content-type: application/json
server: WSGIServer/0.1 Python/2.7.5

{"error_message": "{\"debuginfo\": null, \"faultcode\": \"Client\", \"faultstring\": \"Couldn't apply patch '[{'path': '/extra/vif_port_id', 'op': 'remove'}]'. Reason: u'vif_port_id'\"}"}
 from (pid=12177) log_http_response /opt/stack/python-ironicclient/ironicclient/common/http.py:105
2014-04-14 11:00:55.500 WARNING ironicclient.common.http [-] Request returned failure status.
2014-04-14 11:00:55.500 ERROR nova.openstack.common.loopingcall [-] in fixed duration looping call
2014-04-14 11:00:55.500 TRACE nova.openstack.common.loopingcall Traceback (most recent call last):
2014-04-14 11:00:55.500 TRACE nova.openstack.common.loopingcall File "/opt/stack/nova/nova/openstack/common/loopingcall.py", line 78, in _inner
2014-04-14 11:00:55.500 TRACE nova.openstack.common.loopingcall self.f(*self.args, **self.kw)
2014-04-14 11:00:55.500 TRACE nova.openstack.common.loopingcall File "/opt/stack/ironic/ironic/nova/virt/ironic/driver.py", line 170, in _request_api
2014-04-14 11:00:55.500 TRACE nova.openstack.common.loopingcall func(*args)
2014-04-14 11:00:55.500 TRACE nova.openstack.common.loopingcall File "/opt/stack/python-ironicclient/ironicclient/v1/port.py", line 57, in update
2014-04-14 11:00:55.500 TRACE nova.openstack.common.loopingcall return self._update(self._path(port_id), patch)
2014-04-14 11:00:55.500 TRACE nova.openstack.common.loopingcall File "/opt/stack/python-ironicclient/ironicclient/common/base.py", line 68, in _update
2014-04-14 11:00:55.500 TRACE nova.openstack.common.loopingcall resp, body = self.api.json_request(method, url, body=body)
2014-04-14 11:00:55.500 TRACE nova.openstack.common.loopingcall File "/opt/stack/python-ironicclient/ironicclient/common/http.py", line 186, in json_request
2014-04-14 11:00:55.500 TRACE nova.openstack.common.loopingcall resp, body_iter = self._http_request(url, method, **kwargs)
2014-04-14 11:00:55.500 TRACE nova.openstack.common.loopingcall File "/opt/stack/python-ironicclient/ironicclient/common/http.py", line 169, in _http_request
2014-04-14 11:00:55.500 TRACE nova.openstack.common.loopingcall error_json.get('debuginfo'))
2014-04-14 11:00:55.500 TRACE nova.openstack.common.loopingcall HTTPBadRequest: Couldn't apply patch '[{'path': '/extra/vif_port_id', 'op': 'remove'}]'. Reason: u'vif_port_id'
2014-04-14 11:00:55.500 TRACE nova.openstack.common.loopingcall

[Openstack Gerrit (openstack-gerrit)]

Reviewed: https://review.openstack.org/86993
Committed: https://git.openstack.org/cgit/openstack/ironic/commit/?id=2291251b3dc99b18e4b29c6e75d60e320ef023f8
Submitter: Jenkins
Branch: master

commit 2291251b3dc99b18e4b29c6e75d60e320ef023f8
Author: David Shrewsbury <email address hidden>
Date: Fri Apr 11 14:46:00 2014 -0400

    Complete wrapping ironic client calls

    This makes all ironic client calls use the new client wrapper that
    encapsulates the retry logic.

    Change-Id: I3dcbacee4c88704b8c2553a2f39cbcc32e8c306e
    Closes-Bug: #1295870
    Closes-Bug: #1307589