ERROR stacktraces in n-cond log after good tempest run

Bug #1084706 reported by David Kranz
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
OpenStack Compute (nova)
Fix Released
High
Dan Smith

Bug Description

From http://logs.openstack.org/periodic/periodic-tempest-devstack-vm-check-hourly/404/logs/screen-n-cond.txt
There are lots of these.

2012-11-29 19:17:30 29815 DEBUG nova.manager [-] Running periodic task ConductorManager.publish_service_capabilities periodic_tasks /opt/stack/nova/nova/manager.py:172
2012-11-29 19:17:34 29815 DEBUG nova.openstack.common.rpc.amqp [-] received {u'_context_roles': [], u'_msg_id': u'971480bb48574994aebce24c9d2c4e68', u'_context_quota_class': None, u'_context_request_id': u'req-5acd8b17-cd50-4e52-9877-be572eda2c3b', u'_context_service_catalog': None, u'_context_user_name': None, u'_context_auth_token': '<SANITIZED>', u'args': {u'instance_uuid': u'cec91bce-bfb5-4544-9bd6-1d43aff47b19'}, u'_context_instance_lock_checked': False, u'_context_project_name': None, u'_context_is_admin': True, u'version': u'1.2', u'_context_project_id': None, u'_context_timestamp': u'2012-11-29T19:17:27.770893', u'_context_read_deleted': u'no', u'_context_user_id': None, u'method': u'instance_get_by_uuid', u'_context_remote_address': None} _safe_log /opt/stack/nova/nova/openstack/common/rpc/common.py:195
2012-11-29 19:17:34 29815 DEBUG nova.openstack.common.rpc.amqp [-] unpacked context: {'project_name': None, 'user_id': None, 'roles': [], 'timestamp': u'2012-11-29T19:17:27.770893', 'auth_token': '<SANITIZED>', 'remote_address': None, 'quota_class': None, 'is_admin': True, 'service_catalog': None, 'request_id': u'req-5acd8b17-cd50-4e52-9877-be572eda2c3b', 'instance_lock_checked': False, 'project_id': None, 'user_name': None, 'read_deleted': u'no'} _safe_log /opt/stack/nova/nova/openstack/common/rpc/common.py:195
2012-11-29 19:17:34 29815 ERROR nova.openstack.common.rpc.amqp [-] Exception during message handling
2012-11-29 19:17:34 29815 TRACE nova.openstack.common.rpc.amqp Traceback (most recent call last):
2012-11-29 19:17:34 29815 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/openstack/common/rpc/amqp.py", line 276, in _process_data
2012-11-29 19:17:34 29815 TRACE nova.openstack.common.rpc.amqp rval = self.proxy.dispatch(ctxt, version, method, **args)
2012-11-29 19:17:34 29815 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/openstack/common/rpc/dispatcher.py", line 145, in dispatch
2012-11-29 19:17:34 29815 TRACE nova.openstack.common.rpc.amqp return getattr(proxyobj, method)(ctxt, **kwargs)
2012-11-29 19:17:34 29815 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/conductor/manager.py", line 66, in instance_get_by_uuid
2012-11-29 19:17:34 29815 TRACE nova.openstack.common.rpc.amqp self.db.instance_get_by_uuid(context, instance_uuid))
2012-11-29 19:17:34 29815 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/db/api.py", line 570, in instance_get_by_uuid
2012-11-29 19:17:34 29815 TRACE nova.openstack.common.rpc.amqp return IMPL.instance_get_by_uuid(context, uuid)
2012-11-29 19:17:34 29815 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/db/sqlalchemy/api.py", line 127, in wrapper
2012-11-29 19:17:34 29815 TRACE nova.openstack.common.rpc.amqp return f(*args, **kwargs)
2012-11-29 19:17:34 29815 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/db/sqlalchemy/api.py", line 1493, in instance_get_by_uuid
2012-11-29 19:17:34 29815 TRACE nova.openstack.common.rpc.amqp raise exception.InstanceNotFound(instance_id=uuid)
2012-11-29 19:17:34 29815 TRACE nova.openstack.common.rpc.amqp InstanceNotFound: Instance cec91bce-bfb5-4544-9bd6-1d43aff47b19 could not be found.
2012-11-29 19:17:34 29815 TRACE nova.openstack.common.rpc.amqp

Tags: conductor
Revision history for this message
Russell Bryant (russellb) wrote :

It looks like what's happening here is that we are raising an exception, but it's not an ERROR. We need a way to tell rpc not to log exceptions that are expected and we just want to pass back to the caller to handle (and maybe log over there if they want to).

Changed in nova:
status: New → Confirmed
importance: Undecided → High
Revision history for this message
Russell Bryant (russellb) wrote :
Changed in nova:
assignee: nobody → Dan Smith (danms)
Revision history for this message
Mark McLoughlin (markmc) wrote :

If we think the root cause is the same as bug #1084707, we can just mark this as a duplicate

Revision history for this message
Mark McLoughlin (markmc) wrote :

My bad marking the bugs as duplicates - since we're going to approach this by silently passing individual exceptions, it does make sense for individual cases of this to be filed as separate bugs.

Changed in nova:
status: Confirmed → In Progress
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to nova (master)

Reviewed: https://review.openstack.org/17415
Committed: http://github.com/openstack/nova/commit/405c67b1c0b8154dbaec8d6cc838bc32125ce634
Submitter: Jenkins
Branch: master

commit 405c67b1c0b8154dbaec8d6cc838bc32125ce634
Author: Dan Smith <email address hidden>
Date: Mon Dec 3 12:37:57 2012 -0800

    Allow conductor exceptions to pass over RPC silently

    When one service performs an operation on behalf of another, the
    act of passing back an exception (even a known one) causes a lot
    of scary log messages about the (presumed to be) error case.

    This patch applies the new client_exceptions decorator to methods
    in the conductor manager to prevent excess logging for known
    situations.

    Fixes bug 1084706

    Change-Id: I56e472b0f08d584f5bbe5181ca909f2c11352120

Changed in nova:
status: In Progress → Fix Committed
Thierry Carrez (ttx)
Changed in nova:
milestone: none → grizzly-2
status: Fix Committed → Fix Released
Thierry Carrez (ttx)
Changed in nova:
milestone: grizzly-2 → 2013.1
Revision history for this message
David Kranz (david-kranz) wrote :
Changed in nova:
status: Fix Released → New
Revision history for this message
Russell Bryant (russellb) wrote :

It's the same log file, but a new problem. This should really be a new bug report ...

tags: added: conductor
Revision history for this message
David Kranz (david-kranz) wrote :
Changed in nova:
status: New → Fix Released
Revision history for this message
OpenStack Infra (hudson-openstack) wrote :

Reviewed: https://review.openstack.org/49245
Committed: http://github.com/openstack/nova/commit/3a5e1faee04671f2e88b28d805b191b480054254
Submitter: Jenkins
Branch: master

commit 3a5e1faee04671f2e88b28d805b191b480054254
Author: Dan Smith <email address hidden>
Date: Tue Oct 1 12:12:13 2013 -0700

    Avoid spamming conductor logs with object exceptions

    Conductor's logs should include tracebacks only when something
    unexpected happened, which is why we have the client_exceptions()
    decorator. The object_action() and object_class_action() methods
    are used for direct remoting of object methods, and thus really
    should forward *any* exception to the client.

    This patch does that, and also adds missing tests for these two
    methods to verify the normal and exception-wrapped behavior.

    Closes-bug: #1233789
    Closes-bug: #1084706
    Change-Id: I505462fa429a6aa68e7b8a08ec2b704bf18d029c

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to nova (milestone-proposed)

Fix proposed to branch: milestone-proposed
Review: https://review.openstack.org/51075

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to nova (milestone-proposed)

Reviewed: https://review.openstack.org/51075
Committed: http://github.com/openstack/nova/commit/b64ea7c2cb76c476a178deeed6ab9e83676faf05
Submitter: Jenkins
Branch: milestone-proposed

commit b64ea7c2cb76c476a178deeed6ab9e83676faf05
Author: Dan Smith <email address hidden>
Date: Tue Oct 1 12:12:13 2013 -0700

    Avoid spamming conductor logs with object exceptions

    Conductor's logs should include tracebacks only when something
    unexpected happened, which is why we have the client_exceptions()
    decorator. The object_action() and object_class_action() methods
    are used for direct remoting of object methods, and thus really
    should forward *any* exception to the client.

    This patch does that, and also adds missing tests for these two
    methods to verify the normal and exception-wrapped behavior.

    Closes-bug: #1233789
    Closes-bug: #1084706
    Change-Id: I505462fa429a6aa68e7b8a08ec2b704bf18d029c
    (cherry picked from commit 3a5e1faee04671f2e88b28d805b191b480054254)

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.