API attempt to get non-existing floating shows error in log

Bug #977536 reported by David Kranz
12
This bug affects 2 people
Affects Status Importance Assigned to Milestone
OpenStack Compute (nova)
Fix Released
Low
Sulochan Acharya

Bug Description

Tempest has a number of negative test cases that check for failure codes from the API calls. But some of these are treated as errors with tracebacks in the log. Here are two examples from the floating ip tests. I have been struggling with this general issue while stress testing nova. There needs to be some way to scan a log file, or use publish_errors, and understand if the system is misbehaving. Use of the ERROR log level would be a good way to do that but there are too many places where log.error or log.exception is called that should really be DEBUG or INFO. I think this is as a huge problem for testing.

/var/log/nova/nova-network.log:2012-04-09 15:06:32 ERROR nova.rpc.amqp [req-90cca942-5980-4ebe-8139-282a6567e6f9 5b963fedd517476f899bd73a7fad4d06 18cdc649708644a68030088165282e05] Exception during message handling
/var/log/nova/nova-network.log:2012-04-09 15:06:32 ERROR nova.rpc.amqp [req-90cca942-5980-4ebe-8139-282a6567e6f9 5b963fedd517476f899bd73a7fad4d06 18cdc649708644a68030088165282e05] Returning exception Floating ip not found for id 99923926838806. to caller
/var/log/nova/nova-network.log:2012-04-09 15:06:32 ERROR nova.rpc.amqp [req-90cca942-5980-4ebe-8139-282a6567e6f9 5b963fedd517476f899bd73a7fad4d06 18cdc649708644a68030088165282e05] ['Traceback (most recent call last):\n', ' File "/usr/lib/python2.7/dist-packages/nova/rpc/amqp.py", line 252, in _process_data\n rval = node_func(context=ctxt, **node_args)\n', ' File "/usr/lib/python2.7/dist-packages/nova/network/manager.py", line 258, in wrapped\n return func(self, context, *args, **kwargs)\n', ' File "/usr/lib/python2.7/dist-packages/nova/network/manager.py", line 555, in get_floating_ip\n return dict(self.db.floating_ip_get(context, id).iteritems())\n', ' File "/usr/lib/python2.7/dist-packages/nova/db/api.py", line 232, in floating_ip_get\n return IMPL.floating_ip_get(context, id)\n', ' File "/usr/lib/python2.7/dist-packages/nova/db/sqlalchemy/api.py", line 120, in wrapper\n return f(*args, **kwargs)\n', ' File "/usr/lib/python2.7/dist-packages/nova/db/sqlalchemy/api.py", line 613, in floating_ip_get\n raise exception.FloatingIpNotFound(id=id)\n', 'FloatingIpNotFound: Floating ip not found for id 99923926838806.\n']

/var/log/nova/nova-network.log:2012-04-09 15:06:32 ERROR nova.rpc.amqp [req-a9345519-8aab-4591-8c1b-532416b0e2ac 5b963fedd517476f899bd73a7fad4d06 18cdc649708644a68030088165282e05] Exception during message handling
/var/log/nova/nova-network.log:2012-04-09 15:06:32 ERROR nova.rpc.amqp [req-a9345519-8aab-4591-8c1b-532416b0e2ac 5b963fedd517476f899bd73a7fad4d06 18cdc649708644a68030088165282e05] Returning exception Floating ip not found for address 0.0.0.0. to caller
/var/log/nova/nova-network.log:2012-04-09 15:06:32 ERROR nova.rpc.amqp [req-a9345519-8aab-4591-8c1b-532416b0e2ac 5b963fedd517476f899bd73a7fad4d06 18cdc649708644a68030088165282e05] ['Traceback (most recent call last):\n', ' File "/usr/lib/python2.7/dist-packages/nova/rpc/amqp.py", line 252, in _process_data\n rval = node_func(context=ctxt, **node_args)\n', ' File "/usr/lib/python2.7/dist-packages/nova/network/manager.py", line 258, in wrapped\n return func(self, context, *args, **kwargs)\n', ' File "/usr/lib/python2.7/dist-packages/nova/network/manager.py", line 567, in get_floating_ip_by_address\n address).iteritems())\n', ' File "/usr/lib/python2.7/dist-packages/nova/db/api.py", line 304, in floating_ip_get_by_address\n return IMPL.floating_ip_get_by_address(context, address)\n', ' File "/usr/lib/python2.7/dist-packages/nova/db/sqlalchemy/api.py", line 120, in wrapper\n return f(*args, **kwargs)\n', ' File "/usr/lib/python2.7/dist-packages/nova/db/sqlalchemy/api.py", line 774, in floating_ip_get_by_address\n raise exception.FloatingIpNotFoundForAddress(address=address)\n', 'FloatingIpNotFoundForAddress: Floating ip not found for address 0.0.0.0.\n']
/

Revision history for this message
David Kranz (david-kranz) wrote :

Or maybe CRITICAL should be used for internal errors.

Tom Fifield (fifieldt)
Changed in nova:
status: New → Confirmed
Revision history for this message
Thierry Carrez (ttx) wrote :

Things that can be triggered from black box testing shouldn't trigger ERRORs. I think the right way to fix that is to catch all abusive ERRORs and turn them into "normal" cases.

This bug should be turned into a list of specific actions, or replaced by a set of bugs.

Changed in nova:
status: Confirmed → Incomplete
Revision history for this message
David Kranz (david-kranz) wrote :

Agreed. I changed the title of this bug to be for this specific case.

summary: - Traceback in log for ERROR that is not an error
+ API attempt to get non-existing floating shows error in log
Thierry Carrez (ttx)
Changed in nova:
importance: Undecided → Low
status: Incomplete → Confirmed
Changed in nova:
assignee: nobody → Sulochan Acharya (sulochan-acharya)
Changed in nova:
status: Confirmed → In Progress
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/13132

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

Reviewed: https://review.openstack.org/13132
Committed: http://github.com/openstack/nova/commit/9a303f2cc231f5d43257ebced5b1167c08d32648
Submitter: Jenkins
Branch: master

commit 9a303f2cc231f5d43257ebced5b1167c08d32648
Author: Sulochan Acharya <email address hidden>
Date: Mon Sep 17 11:42:07 2012 -0500

    Catch NotFound exception in FloatingIP add/remove

    Catch the FloatingIPNotFoundForAddress exception for add/remove
    operations in floating ip extension for non existing floating ips.

    Fixes bug 977536

    Change-Id: Ied450aa56ef7a52a015c6d78a099d445ab6258b6

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