Reduce the number of debug traces emitted by registry callbacks

The tool has become popular beyond my wildest expectations. A typical
run in the gate at debug level yields more than 20K traces in the
neutron-server alone. However, reducing the number of traces is
beneficial across the board and that's the first attempt at bringing
the size of Neutron logs closer to other services'.

Partial-bug: #1620864

Change-Id: I2576e59961ec8928ad71d778253b2d37d470d909

neutron/callbacks/manager.py

@@ -136,22 +136,27 @@ class CallbacksManager(object):
 
     def _notify_loop(self, resource, event, trigger, **kwargs):
         """The notification loop."""
-        LOG.debug("Notify callbacks for %(resource)s, %(event)s",
-                  {'resource': resource, 'event': event})
-
         errors = []
         callbacks = list(self._callbacks[resource].get(event, {}).items())
+        LOG.debug("Notify callbacks %s for %s, %s",
+                  callbacks, resource, events)
         # TODO(armax): consider using a GreenPile
         for callback_id, callback in callbacks:
             try:
-                LOG.debug("Calling callback %s", callback_id)
                 callback(resource, event, trigger, **kwargs)
             except Exception as e:
-                LOG.exception(_LE("Error during notification for "
-                                  "%(callback)s %(resource)s, %(event)s"),
-                              {'callback': callback_id,
-                               'resource': resource,
-                               'event': event})
+                abortable_event = (
+                    event.startswith(events.BEFORE) or
+                    event.startswith(events.PRECOMMIT)
+                )
+                if not abortable_event:
+                    LOG.exception(_LE("Error during notification for "
+                                      "%(callback)s %(resource)s, %(event)s"),
+                                  {'callback': callback_id,
+                                   'resource': resource, 'event': event})
+                else:
+                    LOG.error(_LE("Callback %(callback)s raised %(error)s"),
+                              {'callback': callback_id, 'error': e})
                 errors.append(exceptions.NotificationError(callback_id, e))
         return errors
 

neutron/tests/unit/callbacks/test_manager.py

@@ -228,6 +228,19 @@ class CallBacksManagerTestCase(base.BaseTestCase):
         self.assertEqual(2, callback_1.counter)
         self.assertEqual(1, callback_2.counter)
 
+    @mock.patch("neutron.callbacks.manager.LOG")
+    def test__notify_loop_skip_log_errors(self, _logger):
+        self.manager.subscribe(
+            callback_raise, resources.PORT, events.BEFORE_CREATE)
+        self.manager.subscribe(
+            callback_raise, resources.PORT, events.PRECOMMIT_CREATE)
+        self.manager._notify_loop(
+            resources.PORT, events.BEFORE_CREATE, mock.ANY)
+        self.manager._notify_loop(
+            resources.PORT, events.PRECOMMIT_CREATE, mock.ANY)
+        self.assertFalse(_logger.exception.call_count)
+        self.assertTrue(_logger.error.call_count)
+
     def test_object_instances_as_subscribers(self):
         """Ensures that the manager doesn't think these are equivalent."""
         a = GloriousObjectWithCallback()