The ironic driver needs to scale back how many errors it traces out

[Matt Riedemann]

The amount of tracing in this n-cpu log is a bit much:

http://logs.openstack.org/93/255793/3/gate/gate-tempest-dsvm-ironic-agent_ssh/25175ed/logs/screen-n-cpu.txt.gz?level=TRACE

Like these warnings:

http://logs.openstack.org/93/255793/3/gate/gate-tempest-dsvm-ironic-agent_ssh/25175ed/logs/screen-n-cpu.txt.gz?level=TRACE#_2015-12-10_16_11_48_799

2015-12-10 16:11:48.798 WARNING ironicclient.common.http [req-94077ab9-5adf-4720-9fb8-2e027dde9b72 tempest-BaremetalBasicOps-1285004585 tempest-BaremetalBasicOps-1966762451] Request returned failure status.
2015-12-10 16:11:48.799 WARNING ironicclient.common.http [req-94077ab9-5adf-4720-9fb8-2e027dde9b72 tempest-BaremetalBasicOps-1285004585 tempest-BaremetalBasicOps-1966762451] Error contacting Ironic server: Node 1 is locked by host localhost, please retry after the current operation is completed.
Traceback (most recent call last):

  File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/server.py", line 150, in inner
    return func(*args, **kwargs)

  File "/opt/stack/new/ironic/ironic/conductor/manager.py", line 1519, in update_port
    purpose='port update') as task:

  File "/opt/stack/new/ironic/ironic/conductor/task_manager.py", line 152, in acquire
    driver_name=driver_name, purpose=purpose)

  File "/opt/stack/new/ironic/ironic/conductor/task_manager.py", line 222, in __init__
    self.release_resources()

  File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 204, in __exit__
    six.reraise(self.type_, self.value, self.tb)

  File "/opt/stack/new/ironic/ironic/conductor/task_manager.py", line 203, in __init__
    self._lock()

  File "/opt/stack/new/ironic/ironic/conductor/task_manager.py", line 243, in _lock
    reserve_node()

  File "/usr/local/lib/python2.7/dist-packages/retrying.py", line 49, in wrapped_f
    return Retrying(*dargs, **dkw).call(f, *args, **kw)

  File "/usr/local/lib/python2.7/dist-packages/retrying.py", line 212, in call
    raise attempt.get()

  File "/usr/local/lib/python2.7/dist-packages/retrying.py", line 247, in get
    six.reraise(self.value[0], self.value[1], self.value[2])

  File "/usr/local/lib/python2.7/dist-packages/retrying.py", line 200, in call
    attempt = Attempt(fn(*args, **kwargs), attempt_number, False)

  File "/opt/stack/new/ironic/ironic/conductor/task_manager.py", line 236, in reserve_node
    self.node_id)

  File "/opt/stack/new/ironic/ironic/objects/node.py", line 260, in reserve
    db_node = cls.dbapi.reserve_node(tag, node_id)

  File "/opt/stack/new/ironic/ironic/db/sqlalchemy/api.py", line 226, in reserve_node
    host=node['reservation'])

NodeLocked: Node 1 is locked by host localhost, please retry after the current operation is completed.
 (HTTP 409). Attempt 1 of 61

UPD from dtantsur:
The traceback has nothing to do with ironic client or driver. It gets added somewhere between ironic conductor and API levels.

[Matt Riedemann (mriedem)]

I see ironicclient logging errors/warnings here:

https://github.com/openstack/python-ironicclient/blob/master/ironicclient/common/http.py#L183

But I'm not sure where the stacktrace is coming from, unless ironic is sending that off in the error details somehow?

[Matt Riedemann (mriedem)]

Looks like this is where the traceback is:

https://github.com/openstack/python-ironicclient/blob/master/ironicclient/exc.py#L47

Which is passed in here:

https://github.com/openstack/python-ironicclient/blob/master/ironicclient/common/http.py#L355

And then logged here:

https://github.com/openstack/python-ironicclient/blob/master/ironicclient/common/http.py#L192

When the error is converted to a string.

[Dmitry Tantsur (divius)]

Actually it's even more interesting: traceback comes from ironic as part of message instead of details. Investigating on...

[Dmitry Tantsur (divius)]

More intriguing details: exception is normal on the conductor side, but gets traceback appended after passing through RPC. Will chat with Oslo folks to figure out.

[OpenStack Infra (hudson-openstack)]

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

[Dmitry Tantsur (divius)]

oslo.messaging actually does it: https://github.com/openstack/oslo.messaging/blob/master/oslo_messaging/_drivers/common.py#L208

we should probably strip it on API level

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/256375
Committed: https://git.openstack.org/cgit/openstack/python-ironicclient/commit/?id=8224859c02f525fa3b7dbe917d56b889b0dbb073
Submitter: Jenkins
Branch: master

commit 8224859c02f525fa3b7dbe917d56b889b0dbb073
Author: Dmitry Tantsur <email address hidden>
Date: Fri Dec 11 12:38:39 2015 +0100

    Scale back on how many warnings we issue

    * Remove "Request returned failure status" warning, it does not carry
      any helpful information for an operator (or anyone).
    * Demote retry warnings to debug level. Retrying is essentially a normal
      thing in the real world, and currently we're spamming logs with warnings.
      http://logs.openstack.org/93/255793/3/gate/gate-tempest-dsvm-ironic-agent_ssh/25175ed/logs/screen-n-cpu.txt.gz?level=TRACE

    Change-Id: I6c40581b9dc5ab1fe3af4b882ede17a13edacc66
    Closes-Bug: #1525002

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/liberty
Review: https://review.openstack.org/257955

[Michael Davies (mrda)]

Do we think there is any work to be done in Nova for this? Or is it all covered by the changes to ironic/ironic-client?

[Dmitry Tantsur (divius)]

I suspect ironic changes should be enough. We should review our logging in the ironic driver, but that's another story

[OpenStack Infra (hudson-openstack)]

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

commit bd60603e443ec79b0783bebe2cda48a6b9c89ced
Author: Jim Rollenhagen <email address hidden>
Date: Fri Dec 11 10:03:09 2015 -0800

    Don't return tracebacks in API response in debug mode

    The API should not return tracebacks in a production environment. As
    deployers often run services in debug mode, because OpenStack is hard to
    debug, we should not return tracebacks in debug mode. To allow
    developers etc to continue to use this feature, add a new config option
    'debug_tracebacks_in_api' that maintains this behavior.

    Also add to troubleshooting docs.

    Change-Id: Idbbf7efc45140e9e3d8b9491edd58905cbba0363
    Closes-Bug: #1525002

[Michael Davies (mrda)]

Removed "Nova" as we think this is sufficiently addressed by the ironic and ironicclient changes.

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/257955
Committed: https://git.openstack.org/cgit/openstack/python-ironicclient/commit/?id=ae2c0995adbc71b6eed03fd11087b93acf01446a
Submitter: Jenkins
Branch: stable/liberty

commit ae2c0995adbc71b6eed03fd11087b93acf01446a
Author: Dmitry Tantsur <email address hidden>
Date: Fri Dec 11 12:38:39 2015 +0100

    Scale back on how many warnings we issue

    * Remove "Request returned failure status" warning, it does not carry
      any helpful information for an operator (or anyone).
    * Demote retry warnings to debug level. Retrying is essentially a normal
      thing in the real world, and currently we're spamming logs with warnings.
      http://logs.openstack.org/93/255793/3/gate/gate-tempest-dsvm-ironic-agent_ssh/25175ed/logs/screen-n-cpu.txt.gz?level=TRACE

    Change-Id: I6c40581b9dc5ab1fe3af4b882ede17a13edacc66
    Closes-Bug: #1525002
    (cherry picked from commit 8224859c02f525fa3b7dbe917d56b889b0dbb073)

[Doug Hellmann (doug-hellmann)]

This issue was fixed in the openstack/python-ironicclient 1.1.0 release.

[Doug Hellmann (doug-hellmann)]

This issue was fixed in the openstack/ironic 5.0.0 release.

[Doug Hellmann (doug-hellmann)]

This issue was fixed in the openstack/python-ironicclient 0.8.2 release.

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/python-ironicclient 0.8.2 release.