Log exception generated in Controller.prepare_request_body

While implementing some Neutron extension, I noticed that whenever a parameter
that is expected by the API is not entered, we receive an internal error
message. However, from the user/operator/dev calling the API, it might not be
clear what the error is. Therefore, we should at least, log these validation
errors.

This patch proposes to enclose the call to Controller.prepare_request_body with
a try/except block, and then we log the exception in warning level. After
logging the exception, we raise it to allow the normal execution flow to
continue.

Change-Id: I855442ee8c0c4b4f0aff19968a5db07fca898146

neutron/api/v2/base.py

@@ -440,10 +440,15 @@ class Controller(object):
     def _create(self, request, body, **kwargs):
         """Creates a new instance of the requested entity."""
         parent_id = kwargs.get(self._parent_id_name)
-        body = Controller.prepare_request_body(request.context,
+        try:
-                                               body, True,
+            body = Controller.prepare_request_body(
-                                               self._resource, self._attr_info,
+                request.context, body, True, self._resource, self._attr_info,
-                                               allow_bulk=self._allow_bulk)
+                allow_bulk=self._allow_bulk)
+        except Exception as e:
+            LOG.warning("An exception happened while processing the request "
+                        "body. The exception message is [%s].", e)
+            raise e
+
         action = self._plugin_handlers[self.CREATE]
         # Check authz
         if self._collection in body:
@@ -626,10 +631,15 @@ class Controller(object):
 
     @db_api.retry_db_errors
     def _update(self, request, id, body, **kwargs):
-        body = Controller.prepare_request_body(request.context,
+        try:
-                                               body, False,
+            body = Controller.prepare_request_body(
-                                               self._resource, self._attr_info,
+                request.context, body, False, self._resource, self._attr_info,
-                                               allow_bulk=self._allow_bulk)
+                allow_bulk=self._allow_bulk)
+        except Exception as e:
+            LOG.warning("An exception happened while processing the request "
+                        "body. The exception message is [%s].", e)
+            raise e
+
         action = self._plugin_handlers[self.UPDATE]
         # Load object to check authz
         # but pass only attributes in the original body and required
@@ -724,13 +734,20 @@ class Controller(object):
                                                      "not supported"))
                 if not body[collection]:
                     raise webob.exc.HTTPBadRequest(_("Resources required"))
-                bulk_body = [
+                try:
-                    Controller.prepare_request_body(
+                    bulk_body = [
-                        context, item if resource in item
+                        Controller.prepare_request_body(
-                        else {resource: item}, is_create, resource, attr_info,
+                            context, item if resource in item
-                        allow_bulk) for item in body[collection]
+                            else {resource: item}, is_create, resource,
-                ]
+                            attr_info, allow_bulk) for item in body[collection]
-                return {collection: bulk_body}
+                    ]
+                    return {collection: bulk_body}
+                except Exception as e:
+                    LOG.warning(
+                        "An exception happened while processing the request "
+                        "body. The exception message is [%s].", e)
+                    raise e
+
             res_dict = body.get(resource)
         except (AttributeError, TypeError):
             msg = _("Body contains invalid data")

neutron/extensions/quotasv2.py

@@ -20,6 +20,7 @@ from neutron_lib.db import constants as const
 from neutron_lib import exceptions
 from neutron_lib.plugins import directory
 from oslo_config import cfg
+from oslo_log import log as logging
 from oslo_utils import importutils
 import webob
 
@@ -41,6 +42,7 @@ DB_QUOTA_DRIVER = 'neutron.db.quota.driver.DbQuotaDriver'
 EXTENDED_ATTRIBUTES_2_0 = {
     RESOURCE_COLLECTION: {}
 }
+LOG = logging.getLogger(__name__)
 
 
 def validate_policy(context, policy_name):
@@ -118,9 +120,15 @@ class QuotaSetsController(wsgi.Controller):
         validate_policy(request.context, "update_quota")
         if self._update_extended_attributes:
             self._update_attributes()
-        body = base.Controller.prepare_request_body(
+        try:
-            request.context, body, False, self._resource_name,
+            body = base.Controller.prepare_request_body(
-            EXTENDED_ATTRIBUTES_2_0[RESOURCE_COLLECTION])
+                request.context, body, False, self._resource_name,
+                EXTENDED_ATTRIBUTES_2_0[RESOURCE_COLLECTION])
+        except Exception as e:
+            LOG.warning(
+                "An exception happened while processing the request "
+                "body. The exception message is [%s].", e)
+            raise e
         for key, value in body[self._resource_name].items():
             self._driver.update_quota_limit(request.context, id, key, value)
         return {self._resource_name: self._get_quotas(request, id)}

neutron/pecan_wsgi/hooks/body_validation.py

@@ -13,7 +13,9 @@
 #    License for the specific language governing permissions and limitations
 #    under the License.
 
+from oslo_log import log as logging
 from oslo_serialization import jsonutils
+
 from pecan import hooks
 import webob.exc
 
@@ -21,6 +23,8 @@ from neutron._i18n import _
 from neutron.api.v2 import base as v2_base
 from neutron.pecan_wsgi.hooks import utils
 
+LOG = logging.getLogger(__name__)
+
 
 class BodyValidationHook(hooks.PecanHook):
 
@@ -53,13 +57,19 @@ class BodyValidationHook(hooks.PecanHook):
             return
         # Prepare data to be passed to the plugin from request body
         controller = utils.get_controller(state)
-        data = v2_base.Controller.prepare_request_body(
+        try:
-            neutron_context,
+            data = v2_base.Controller.prepare_request_body(
-            json_data,
+                neutron_context,
-            is_create,
+                json_data,
-            resource,
+                is_create,
-            controller.resource_info,
+                resource,
-            allow_bulk=is_create)
+                controller.resource_info,
+                allow_bulk=is_create)
+        except Exception as e:
+            LOG.warning("An exception happened while processing the request "
+                        "body. The exception message is [%s].", e)
+            raise e
+
         if collection in data:
             state.request.context['resources'] = [item[resource] for item in
                                                   data[collection]]