ml2: postpone exception logs to when retry mechanism fails to recover

Since Ia2d911a6a90b1baba1d5cc36f7c625e156a2bc33, we use version_id_col
SQLAlchemy feature to routinely bump revision numbers for resources.  By
doing so, SQLAlchemy also enforces the expected number on any UPDATE and
DELETE, which may not be valid when the transaction is actually applied.
In that case, the library will raise StaleDataError:

http://docs.sqlalchemy.org/en/latest/orm/exceptions.html#sqlalchemy.orm.exc.StaleDataError

The exception is then logged by ml2 and bubbles up to API layer where
retry mechanism will correctly catch it and issue another attempt.

If API layer does not retry on exception, it already logs the error,
including the traceback.

In ml2, it's too early to decide if an exception is worth being logged.
Plugin instead should just silently allow all unexpected exceptions to
bubble up and be dealt by API layer.

At the same time, there are some details that are known at the plugin
level only, that are not easily deducible from the API request details.
That's why we save details about the error on the exception object that
bubbles up into API layer, where we are ready to decide if those details
are worth being logged.

Change-Id: I848df0aef5381e50dfb58e46d7a652113ac27a49
Closes-Bug: #1593719

neutron/api/v2/resource.py

@@ -23,6 +23,7 @@ import webob.exc
 
 from neutron._i18n import _LE, _LI
 from neutron.api import api_common
+from neutron.common import utils
 from neutron import wsgi
 
 
@@ -83,7 +84,13 @@ def Resource(controller, faults=None, deserializers=None, serializers=None,
                 LOG.info(_LI('%(action)s failed (client error): %(exc)s'),
                          {'action': action, 'exc': mapped_exc})
             else:
-                LOG.exception(_LE('%s failed'), action)
+                LOG.exception(
+                    _LE('%(action)s failed: %(details)s'),
+                    {
+                        'action': action,
+                        'details': utils.extract_exc_details(e),
+                    }
+                )
             raise mapped_exc
 
         status = action_status.get(action, 200)

neutron/common/utils.py

@@ -660,3 +660,22 @@ class classproperty(object):
 
     def __get__(self, obj, owner):
         return self.func(owner)
+
+
+_NO_ARGS_MARKER = object()
+
+
+def attach_exc_details(e, msg, args=_NO_ARGS_MARKER):
+    e._error_context_msg = msg
+    e._error_context_args = args
+
+
+def extract_exc_details(e):
+    for attr in ('_error_context_msg', '_error_context_args'):
+        if not hasattr(e, attr):
+            return _LE('No details.')
+    details = e._error_context_msg
+    args = e._error_context_args
+    if args is _NO_ARGS_MARKER:
+        return details
+    return details % args

neutron/plugins/ml2/plugin.py

@@ -651,11 +651,12 @@ class Ml2Plugin(db_base_plugin_v2.NeutronDbPluginV2,
                                     'result': result,
                                     'attributes': attrs})
 
-        except Exception:
+        except Exception as e:
             with excutils.save_and_reraise_exception():
-                LOG.exception(_LE("An exception occurred while creating "
-                                  "the %(resource)s:%(item)s"),
-                              {'resource': resource, 'item': item})
+                utils.attach_exc_details(
+                    e, _LE("An exception occurred while creating "
+                           "the %(resource)s:%(item)s"),
+                    {'resource': resource, 'item': item})
 
         try:
             postcommit_op = getattr(self.mechanism_manager,
@@ -797,10 +798,11 @@ class Ml2Plugin(db_base_plugin_v2.NeutronDbPluginV2,
                 # concurrent port deletion can be performed by
                 # release_dhcp_port caused by concurrent subnet_delete
                 LOG.info(_LI("Port %s was deleted concurrently"), port_id)
-            except Exception:
+            except Exception as e:
                 with excutils.save_and_reraise_exception():
-                    LOG.exception(_LE("Exception auto-deleting port %s"),
-                                  port_id)
+                    utils.attach_exc_details(
+                        e,
+                        _LE("Exception auto-deleting port %s"), port_id)
 
     def _delete_subnets(self, context, subnet_ids):
         for subnet_id in subnet_ids:
@@ -809,10 +811,11 @@ class Ml2Plugin(db_base_plugin_v2.NeutronDbPluginV2,
             except (exc.SubnetNotFound, sa_exc.ObjectDeletedError):
                 LOG.info(_LI("Subnet %s was deleted concurrently"),
                          subnet_id)
-            except Exception:
+            except Exception as e:
                 with excutils.save_and_reraise_exception():
-                    LOG.exception(_LE("Exception auto-deleting subnet %s"),
-                                  subnet_id)
+                    utils.attach_exc_details(
+                        e,
+                        _LE("Exception auto-deleting subnet %s"), subnet_id)
 
     @utils.transaction_guard
     def delete_network(self, context, id):
@@ -1059,10 +1062,11 @@ class Ml2Plugin(db_base_plugin_v2.NeutronDbPluginV2,
                     except exc.PortNotFound:
                         # NOTE Attempting to access a.port_id here is an error.
                         LOG.debug("Port %s deleted concurrently", port_id)
-                    except Exception:
+                    except Exception as e:
                         with excutils.save_and_reraise_exception():
-                            LOG.exception(_LE("Exception deleting fixed_ip "
-                                              "from port %s"), port_id)
+                            utils.attach_exc_details(
+                                e, _LE("Exception deleting fixed_ip from "
+                                       "port %s"), port_id)
 
         try:
             self.mechanism_manager.delete_subnet_postcommit(mech_context)

neutron/tests/unit/api/v2/test_resource.py

@@ -21,6 +21,7 @@ import webtest
 
 from neutron._i18n import _
 from neutron.api.v2 import resource as wsgi_resource
+from neutron.common import utils
 from neutron import context
 from neutron.tests import base
 from neutron import wsgi
@@ -280,6 +281,21 @@ class ResourceTestCase(base.BaseTestCase):
         res = resource.get('', extra_environ=environ)
         self.assertEqual(200, res.status_int)
 
+    def _test_unhandled_error_logs_details(self, e, expected_details):
+        with mock.patch.object(wsgi_resource.LOG, 'exception') as log:
+            self._make_request_with_side_effect(side_effect=e)
+        log.assert_called_with(
+            mock.ANY, {'action': mock.ANY, 'details': expected_details})
+
+    def test_unhandled_error_logs_attached_details(self):
+        e = Exception()
+        utils.attach_exc_details(e, 'attached_details')
+        self._test_unhandled_error_logs_details(e, 'attached_details')
+
+    def test_unhandled_error_logs_no_attached_details(self):
+        e = Exception()
+        self._test_unhandled_error_logs_details(e, 'No details.')
+
     def test_status_204(self):
         controller = mock.MagicMock()
         controller.test = lambda request: {'foo': 'bar'}

neutron/tests/unit/common/test_utils.py

@@ -750,3 +750,38 @@ class TestAuthenticIPNetwork(base.BaseTestCase):
         for addr in ('XXXX', 'ypp', 'g3:vvv'):
             with testtools.ExpectedException(netaddr.core.AddrFormatError):
                 utils.AuthenticIPNetwork(addr)
+
+
+class TestExcDetails(base.BaseTestCase):
+
+    def test_attach_exc_details(self):
+        e = Exception()
+        utils.attach_exc_details(e, 'details')
+        self.assertEqual('details', utils.extract_exc_details(e))
+
+    def test_attach_exc_details_with_interpolation(self):
+        e = Exception()
+        utils.attach_exc_details(e, 'details: %s', 'foo')
+        self.assertEqual('details: foo', utils.extract_exc_details(e))
+
+    def test_attach_exc_details_with_None_interpolation(self):
+        e = Exception()
+        utils.attach_exc_details(e, 'details: %s', None)
+        self.assertEqual(
+            'details: %s' % str(None), utils.extract_exc_details(e))
+
+    def test_attach_exc_details_with_multiple_interpolation(self):
+        e = Exception()
+        utils.attach_exc_details(
+            e, 'details: %s, %s', ('foo', 'bar'))
+        self.assertEqual('details: foo, bar', utils.extract_exc_details(e))
+
+    def test_attach_exc_details_with_dict_interpolation(self):
+        e = Exception()
+        utils.attach_exc_details(
+            e, 'details: %(foo)s, %(bar)s', {'foo': 'foo', 'bar': 'bar'})
+        self.assertEqual('details: foo, bar', utils.extract_exc_details(e))
+
+    def test_extract_exc_details_no_details_attached(self):
+        self.assertIsInstance(
+            utils.extract_exc_details(Exception()), six.text_type)