ERROR backtraces in n-net log after good tempset run

Bug #1084707 reported by David Kranz
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
OpenStack Compute (nova)
Fix Released
Medium
Dan Smith
oslo-incubator
Fix Released
Medium
Dan Smith
Grizzly
Fix Released
Medium
Dan Smith

Bug Description

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

2012-11-29 19:19:41 29656 DEBUG nova.openstack.common.rpc.amqp [-] unpacked context: {'project_name': u'FloatingIPsTestJSON-tenant', 'user_id': u'fa3413c9b9dd4119bf50a50bf5fe7449', 'roles': [u''], 'timestamp': u'2012-11-29T19:19:41.059491', 'auth_token': '<SANITIZED>', 'remote_address': u'127.0.0.1', 'quota_class': None, 'is_admin': False, 'service_catalog': [{u'endpoints_links': [], u'endpoints': [{u'adminURL': u'http://127.0.0.1:8774/v2/27b624e2bea2467e971eef6d0e4ac16c', u'region': u'RegionOne', u'publicURL': u'http://127.0.0.1:8774/v2/27b624e2bea2467e971eef6d0e4ac16c', u'internalURL': u'http://127.0.0.1:8774/v2/27b624e2bea2467e971eef6d0e4ac16c', u'id': u'd889e2fbbaca4d009be75267783682b1'}], u'type': u'compute', u'name': u'nova'}, {u'endpoints_links': [], u'endpoints': [{u'adminURL': u'http://127.0.0.1:3333', u'region': u'RegionOne', u'publicURL': u'http://127.0.0.1:3333', u'internalURL': u'http://127.0.0.1:3333', u'id': u'f369608e9c6c42c689590edc121634fe'}], u'type': u's3', u'name': u's3'}, {u'endpoints_links': [], u'endpoints': [{u'adminURL': u'http://127.0.0.1:9292', u'region': u'RegionOne', u'publicURL': u'http://127.0.0.1:9292', u'internalURL': u'http://127.0.0.1:9292', u'id': u'aa369e043ff04de4a02fefe123939a47'}], u'type': u'image', u'name': u'glance'}, {u'endpoints_links': [], u'endpoints': [{u'adminURL': u'http://127.0.0.1:8776/v1/27b624e2bea2467e971eef6d0e4ac16c', u'region': u'RegionOne', u'publicURL': u'http://127.0.0.1:8776/v1/27b624e2bea2467e971eef6d0e4ac16c', u'internalURL': u'http://127.0.0.1:8776/v1/27b624e2bea2467e971eef6d0e4ac16c', u'id': u'07993a46122c449b84f66c6ff86335a4'}], u'type': u'volume', u'name': u'cinder'}, {u'endpoints_links': [], u'endpoints': [{u'adminURL': u'http://127.0.0.1:8773/services/Admin', u'region': u'RegionOne', u'publicURL': u'http://127.0.0.1:8773/services/Cloud', u'internalURL': u'http://127.0.0.1:8773/services/Cloud', u'id': u'ba4043d14cfb463db11e19aeba875916'}], u'type': u'ec2', u'name': u'ec2'}, {u'endpoints_links': [], u'endpoints': [{u'adminURL': u'http://127.0.0.1:8080', u'region': u'RegionOne', u'publicURL': u'http://127.0.0.1:8080/v1/AUTH_27b624e2bea2467e971eef6d0e4ac16c', u'internalURL': u'http://127.0.0.1:8080/v1/AUTH_27b624e2bea2467e971eef6d0e4ac16c', u'id': u'b029107031a14887a7cc897733a1fe6d'}], u'type': u'object-store', u'name': u'swift'}, {u'endpoints_links': [], u'endpoints': [{u'adminURL': u'http://127.0.0.1:35357/v2.0', u'region': u'RegionOne', u'publicURL': u'http://127.0.0.1:5000/v2.0', u'internalURL': u'http://127.0.0.1:5000/v2.0', u'id': u'a5bb735eb41f48709cb76a0bb879d6bf'}], u'type': u'identity', u'name': u'keystone'}], 'request_id': u'req-924c4c46-3693-42e1-8d87-69d2e44f8255', 'instance_lock_checked': False, 'project_id': u'27b624e2bea2467e971eef6d0e4ac16c', 'user_name': u'FloatingIPsTestJSON-user', 'read_deleted': u'no'} _safe_log /opt/stack/nova/nova/openstack/common/rpc/common.py:195
2012-11-29 19:19:41 29656 ERROR nova.openstack.common.rpc.amqp [-] Exception during message handling
2012-11-29 19:19:41 29656 TRACE nova.openstack.common.rpc.amqp Traceback (most recent call last):
2012-11-29 19:19:41 29656 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:19:41 29656 TRACE nova.openstack.common.rpc.amqp rval = self.proxy.dispatch(ctxt, version, method, **args)
2012-11-29 19:19:41 29656 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/openstack/common/rpc/dispatcher.py", line 145, in dispatch
2012-11-29 19:19:41 29656 TRACE nova.openstack.common.rpc.amqp return getattr(proxyobj, method)(ctxt, **kwargs)
2012-11-29 19:19:41 29656 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/network/manager.py", line 266, in wrapped
2012-11-29 19:19:41 29656 TRACE nova.openstack.common.rpc.amqp return func(self, context, *args, **kwargs)
2012-11-29 19:19:41 29656 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/network/manager.py", line 655, in get_floating_ip
2012-11-29 19:19:41 29656 TRACE nova.openstack.common.rpc.amqp return dict(self.db.floating_ip_get(context, id).iteritems())
2012-11-29 19:19:41 29656 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/db/api.py", line 242, in floating_ip_get
2012-11-29 19:19:41 29656 TRACE nova.openstack.common.rpc.amqp return IMPL.floating_ip_get(context, id)
2012-11-29 19:19:41 29656 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/db/sqlalchemy/api.py", line 127, in wrapper
2012-11-29 19:19:41 29656 TRACE nova.openstack.common.rpc.amqp return f(*args, **kwargs)
2012-11-29 19:19:41 29656 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/db/sqlalchemy/api.py", line 639, in floating_ip_get
2012-11-29 19:19:41 29656 TRACE nova.openstack.common.rpc.amqp raise exception.FloatingIpNotFound(id=id)
2012-11-29 19:19:41 29656 TRACE nova.openstack.common.rpc.amqp FloatingIpNotFound: Floating ip not found for id 2.
2012-11-29 19:19:41 29656 TRACE nova.openstack.common.rpc.amqp
2012-11-29 19:19:41 29656 ERROR nova.openstack.common.rpc.common [-] Returning exception Floating ip not found for id 2. to caller
2012-11-29 19:19:41 29656 ERROR nova.openstack.common.rpc.common [-] ['Traceback (most recent call last):\n', ' File "/opt/stack/nova/nova/openstack/common/rpc/amqp.py", line 276, in _process_data\n rval = self.proxy.dispatch(ctxt, version, method, **args)\n', ' File "/opt/stack/nova/nova/openstack/common/rpc/dispatcher.py", line 145, in dispatch\n return getattr(proxyobj, method)(ctxt, **kwargs)\n', ' File "/opt/stack/nova/nova/network/manager.py", line 266, in wrapped\n return func(self, context, *args, **kwargs)\n', ' File "/opt/stack/nova/nova/network/manager.py", line 655, in get_floating_ip\n return dict(self.db.floating_ip_get(context, id).iteritems())\n', ' File "/opt/stack/nova/nova/db/api.py", line 242, in floating_ip_get\n return IMPL.floating_ip_get(context, id)\n', ' File "/opt/stack/nova/nova/db/sqlalchemy/api.py", line 127, in wrapper\n return f(*args, **kwargs)\n', ' File "/opt/stack/nova/nova/db/sqlalchemy/api.py", line 639, in floating_ip_get\n raise exception.FloatingIpNotFound(id=id)\n', 'FloatingIpNotFound: Floating ip not found for id 2.\n']
2012-11-29 19:19:41 29656 DEBUG nova.openstack.common.rpc.amqp [-] received {u'_context_roles': [u''], u'_msg_id': u'd149170eae0d46789a1df72ee2931af1', u'_context_quota_class': None, u'_context_request_id': u'req-4bf07f50-79d7-4355-88f5-090eb63a5954', u'_context_service_catalog': [{u'endpoints': [{u'adminURL': u'http://127.0.0.1:8774/v2/27b624e2bea2467e971eef6d0e4ac16c', u'region': u'RegionOne', u'internalURL': u'http://127.0.0.1:8774/v2/27b624e2bea2467e971eef6d0e4ac16c', u'id': u'd889e2fbbaca4d009be75267783682b1', u'publicURL': u'http://127.0.0.1:8774/v2/27b624e2bea2467e971eef6d0e4ac16c'}], u'endpoints_links': [], u'type': u'compute', u'name': u'nova'}, {u'endpoints': [{u'adminURL': u'http://127.0.0.1:3333', u'region': u'RegionOne', u'internalURL': u'http://127.0.0.1:3333', u'id': u'f369608e9c6c42c689590edc121634fe', u'publicURL': u'http://127.0.0.1:3333'}], u'endpoints_links': [], u'type': u's3', u'name': u's3'}, {u'endpoints': [{u'adminURL': u'http://127.0.0.1:9292', u'region': u'RegionOne', u'internalURL': u'http://127.0.0.1:9292', u'id': u'aa369e043ff04de4a02fefe123939a47', u'publicURL': u'http://127.0.0.1:9292'}], u'endpoints_links': [], u'type': u'image', u'name': u'glance'}, {u'endpoints': [{u'adminURL': u'http://127.0.0.1:8776/v1/27b624e2bea2467e971eef6d0e4ac16c', u'region': u'RegionOne', u'internalURL': u'http://127.0.0.1:8776/v1/27b624e2bea2467e971eef6d0e4ac16c', u'id': u'07993a46122c449b84f66c6ff86335a4', u'publicURL': u'http://127.0.0.1:8776/v1/27b624e2bea2467e971eef6d0e4ac16c'}], u'endpoints_links': [], u'type': u'volume', u'name': u'cinder'}, {u'endpoints': [{u'adminURL': u'http://127.0.0.1:8773/services/Admin', u'region': u'RegionOne', u'internalURL': u'http://127.0.0.1:8773/services/Cloud', u'id': u'ba4043d14cfb463db11e19aeba875916', u'publicURL': u'http://127.0.0.1:8773/services/Cloud'}], u'endpoints_links': [], u'type': u'ec2', u'name': u'ec2'}, {u'endpoints': [{u'adminURL': u'http://127.0.0.1:8080', u'region': u'RegionOne', u'internalURL': u'http://127.0.0.1:8080/v1/AUTH_27b624e2bea2467e971eef6d0e4ac16c', u'id': u'b029107031a14887a7cc897733a1fe6d', u'publicURL': u'http://127.0.0.1:8080/v1/AUTH_27b624e2bea2467e971eef6d0e4ac16c'}], u'endpoints_links': [], u'type': u'object-store', u'name': u'swift'}, {u'endpoints': [{u'adminURL': u'http://127.0.0.1:35357/v2.0', u'region': u'RegionOne', u'internalURL': u'http://127.0.0.1:5000/v2.0', u'id': u'a5bb735eb41f48709cb76a0bb879d6bf', u'publicURL': u'http://127.0.0.1:5000/v2.0'}], u'endpoints_links': [], u'type': u'identity', u'name': u'keystone'}], u'_context_user_name': u'FloatingIPsTestJSON-user', u'_context_auth_token': '<SANITIZED>', u'args': {u'id': u'999533623'}, u'_context_instance_lock_checked': False, u'_context_project_name': u'FloatingIPsTestJSON-tenant', u'_context_is_admin': False, u'version': u'1.0', u'_context_project_id': u'27b624e2bea2467e971eef6d0e4ac16c', u'_context_timestamp': u'2012-11-29T19:19:41.383112', u'_context_read_deleted': u'no', u'_context_user_id': u'fa3413c9b9dd4119bf50a50bf5fe7449', u'method': u'get_floating_ip', u'_context_remote_address': u'127.0.0.1'} _safe_log /opt/stack/nova/nova/openstack/common/rpc/common.py:195
2012-11-29 19:19:41 29656 DEBUG nova.openstack.common.rpc.amqp [-] unpacked context: {'project_name': u'FloatingIPsTestJSON-tenant', 'user_id': u'fa3413c9b9dd4119bf50a50bf5fe7449', 'roles': [u''], 'timestamp': u'2012-11-29T19:19:41.383112', 'auth_token': '<SANITIZED>', 'remote_address': u'127.0.0.1', 'quota_class': None, 'is_admin': False, 'service_catalog': [{u'endpoints_links': [], u'endpoints': [{u'adminURL': u'http://127.0.0.1:8774/v2/27b624e2bea2467e971eef6d0e4ac16c', u'region': u'RegionOne', u'publicURL': u'http://127.0.0.1:8774/v2/27b624e2bea2467e971eef6d0e4ac16c', u'internalURL': u'http://127.0.0.1:8774/v2/27b624e2bea2467e971eef6d0e4ac16c', u'id': u'd889e2fbbaca4d009be75267783682b1'}], u'type': u'compute', u'name': u'nova'}, {u'endpoints_links': [], u'endpoints': [{u'adminURL': u'http://127.0.0.1:3333', u'region': u'RegionOne', u'publicURL': u'http://127.0.0.1:3333', u'internalURL': u'http://127.0.0.1:3333', u'id': u'f369608e9c6c42c689590edc121634fe'}], u'type': u's3', u'name': u's3'}, {u'endpoints_links': [], u'endpoints': [{u'adminURL': u'http://127.0.0.1:9292', u'region': u'RegionOne', u'publicURL': u'http://127.0.0.1:9292', u'internalURL': u'http://127.0.0.1:9292', u'id': u'aa369e043ff04de4a02fefe123939a47'}], u'type': u'image', u'name': u'glance'}, {u'endpoints_links': [], u'endpoints': [{u'adminURL': u'http://127.0.0.1:8776/v1/27b624e2bea2467e971eef6d0e4ac16c', u'region': u'RegionOne', u'publicURL': u'http://127.0.0.1:8776/v1/27b624e2bea2467e971eef6d0e4ac16c', u'internalURL': u'http://127.0.0.1:8776/v1/27b624e2bea2467e971eef6d0e4ac16c', u'id': u'07993a46122c449b84f66c6ff86335a4'}], u'type': u'volume', u'name': u'cinder'}, {u'endpoints_links': [], u'endpoints': [{u'adminURL': u'http://127.0.0.1:8773/services/Admin', u'region': u'RegionOne', u'publicURL': u'http://127.0.0.1:8773/services/Cloud', u'internalURL': u'http://127.0.0.1:8773/services/Cloud', u'id': u'ba4043d14cfb463db11e19aeba875916'}], u'type': u'ec2', u'name': u'ec2'}, {u'endpoints_links': [], u'endpoints': [{u'adminURL': u'http://127.0.0.1:8080', u'region': u'RegionOne', u'publicURL': u'http://127.0.0.1:8080/v1/AUTH_27b624e2bea2467e971eef6d0e4ac16c', u'internalURL': u'http://127.0.0.1:8080/v1/AUTH_27b624e2bea2467e971eef6d0e4ac16c', u'id': u'b029107031a14887a7cc897733a1fe6d'}], u'type': u'object-store', u'name': u'swift'}, {u'endpoints_links': [], u'endpoints': [{u'adminURL': u'http://127.0.0.1:35357/v2.0', u'region': u'RegionOne', u'publicURL': u'http://127.0.0.1:5000/v2.0', u'internalURL': u'http://127.0.0.1:5000/v2.0', u'id': u'a5bb735eb41f48709cb76a0bb879d6bf'}], u'type': u'identity', u'name': u'keystone'}], 'request_id': u'req-4bf07f50-79d7-4355-88f5-090eb63a5954', 'instance_lock_checked': False, 'project_id': u'27b624e2bea2467e971eef6d0e4ac16c', 'user_name': u'FloatingIPsTestJSON-user', 'read_deleted': u'no'} _safe_log /opt/stack/nova/nova/openstack/common/rpc/common.py:195
2012-11-29 19:19:41 29656 ERROR nova.openstack.common.rpc.amqp [-] Exception during message handling
2012-11-29 19:19:41 29656 TRACE nova.openstack.common.rpc.amqp Traceback (most recent call last):
2012-11-29 19:19:41 29656 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:19:41 29656 TRACE nova.openstack.common.rpc.amqp rval = self.proxy.dispatch(ctxt, version, method, **args)
2012-11-29 19:19:41 29656 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/openstack/common/rpc/dispatcher.py", line 145, in dispatch
2012-11-29 19:19:41 29656 TRACE nova.openstack.common.rpc.amqp return getattr(proxyobj, method)(ctxt, **kwargs)
2012-11-29 19:19:41 29656 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/network/manager.py", line 266, in wrapped
2012-11-29 19:19:41 29656 TRACE nova.openstack.common.rpc.amqp return func(self, context, *args, **kwargs)
2012-11-29 19:19:41 29656 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/network/manager.py", line 655, in get_floating_ip
2012-11-29 19:19:41 29656 TRACE nova.openstack.common.rpc.amqp return dict(self.db.floating_ip_get(context, id).iteritems())
2012-11-29 19:19:41 29656 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/db/api.py", line 242, in floating_ip_get
2012-11-29 19:19:41 29656 TRACE nova.openstack.common.rpc.amqp return IMPL.floating_ip_get(context, id)
2012-11-29 19:19:41 29656 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/db/sqlalchemy/api.py", line 127, in wrapper
2012-11-29 19:19:41 29656 TRACE nova.openstack.common.rpc.amqp return f(*args, **kwargs)
2012-11-29 19:19:41 29656 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/db/sqlalchemy/api.py", line 639, in floating_ip_get
2012-11-29 19:19:41 29656 TRACE nova.openstack.common.rpc.amqp raise exception.FloatingIpNotFound(id=id)
2012-11-29 19:19:41 29656 TRACE nova.openstack.common.rpc.amqp FloatingIpNotFound: Floating ip not found for id 999533623.
2012-11-29 19:19:41 29656 TRACE nova.openstack.common.rpc.amqp
20

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

I believe the root cause of this is the same as https://bugs.launchpad.net/nova/+bug/1084706. There are some exceptions that are normal and just need to be passed back to the rpc caller without logging them as an ERROR on the rpc manager side.

Changed in nova:
status: New → Confirmed
importance: Undecided → Medium
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to nova (master)

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

Changed in nova:
assignee: nobody → Dan Smith (danms)
status: Confirmed → In Progress
Revision history for this message
Mark McLoughlin (markmc) wrote :
Changed in oslo:
status: New → In Progress
importance: Undecided → Medium
assignee: nobody → Dan Smith (danms)
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to oslo-incubator (master)

Reviewed: https://review.openstack.org/17555
Committed: http://github.com/openstack/oslo-incubator/commit/15ae704d927ba2ecd97d29195d30d5587987e2ad
Submitter: Jenkins
Branch: master

commit 15ae704d927ba2ecd97d29195d30d5587987e2ad
Author: Dan Smith <email address hidden>
Date: Wed Dec 5 12:22:40 2012 -0800

    Allow 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 adds a client_exceptions decorator common/rpc/common.py,
    which allows RPC services to declare the list of expected exceptions
    for each method. If such an exception is raised during the RPC
    dispatch, it is wrapped in a ClientException so that the RPC layer
    can gracefully pass it back without overly-verbose logging.

    This will allow us to fix nova bug 1084707

    Change-Id: I4e7b19dc730342091fd70a717065741d56da4555

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

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

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

Reviewed: https://review.openstack.org/17865
Committed: http://github.com/openstack/nova/commit/f2df5304f1de961ea2c9e1f4101f201b7b99ff53
Submitter: Jenkins
Branch: master

commit f2df5304f1de961ea2c9e1f4101f201b7b99ff53
Author: Dan Smith <email address hidden>
Date: Tue Dec 11 09:32:36 2012 -0800

    Allow rpc-silent FloatingIP exceptions in n-net

    This patch uses the new client_exceptions functionality to squelch
    some errant exception dumps in the RPC layer.

    Fixes bug 1084707

    Change-Id: I31a783a67d7722751fcfeafab40e781dc762dd65

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 oslo:
milestone: none → grizzly-2
status: Fix Committed → Fix Released
Thierry Carrez (ttx)
Changed in nova:
milestone: grizzly-2 → 2013.1
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.