Maintenance task: Enhance debug logging

This patch is enhancing the maintenance task debug logs by:

* Logging a summary with the number of failures on each resource type
* Logging the UUID and type of the resource being fixed at that time
* Changing the prefix of the maintenance logs for easy grepping

Closes-Bug: #1837003
Change-Id: I0faa19ef48f2dc5591c0337ae5a0599abc2e4168
Signed-off-by: Lucas Alvares Gomes <lucasagomes@gmail.com>

networking_ovn/common/maintenance.py

@@ -20,6 +20,7 @@ from futurist import periodics
 from neutron_lib import constants as n_const
 from neutron_lib import context as n_context
 from neutron_lib import exceptions as n_exc
+from oslo_config import cfg
 from oslo_log import log
 from oslo_utils import timeutils
 
@@ -30,9 +31,12 @@ from networking_ovn.db import maintenance as db_maint
 from networking_ovn.db import revision as db_rev
 from networking_ovn import ovn_db_sync
 
+CONF = cfg.CONF
 LOG = log.getLogger(__name__)
 
 DB_CONSISTENCY_CHECK_INTERVAL = 300  # 5 minutes
+INCONSISTENCY_TYPE_CREATE_UPDATE = 'create/update'
+INCONSISTENCY_TYPE_DELETE = 'delete'
 
 
 class MaintenanceThread(object):
@@ -224,6 +228,30 @@ class DBInconsistenciesPeriodics(object):
         nb_sync.migrate_to_port_groups(admin_context)
         raise periodics.NeverAgain()
 
+    def _log_maintenance_inconsistencies(self, create_update_inconsistencies,
+                                         delete_inconsistencies):
+        if not CONF.debug:
+            return
+
+        def _log(inconsistencies, type_):
+            if not inconsistencies:
+                return
+
+            c = {}
+            for f in inconsistencies:
+                if f.resource_type not in c:
+                    c[f.resource_type] = 1
+                else:
+                    c[f.resource_type] += 1
+
+            fail_str = ', '.join('{}={}'.format(k, v) for k, v in c.items())
+            LOG.debug('Maintenance task: Number of inconsistencies '
+                      'found at %(type_)s: %(fail_str)s',
+                      {'type_': type_, 'fail_str': fail_str})
+
+        _log(create_update_inconsistencies, INCONSISTENCY_TYPE_CREATE_UPDATE)
+        _log(delete_inconsistencies, INCONSISTENCY_TYPE_DELETE)
+
     @periodics.periodic(spacing=DB_CONSISTENCY_CHECK_INTERVAL,
                         run_immediately=True)
     def check_for_inconsistencies(self):
@@ -235,13 +263,22 @@ class DBInconsistenciesPeriodics(object):
         create_update_inconsistencies = db_maint.get_inconsistent_resources()
         delete_inconsistencies = db_maint.get_deleted_resources()
         if not any([create_update_inconsistencies, delete_inconsistencies]):
+            LOG.debug('Maintenance task: No inconsistencies found. Skipping')
             return
+
         LOG.debug('Maintenance task: Synchronizing Neutron '
                   'and OVN databases')
+        self._log_maintenance_inconsistencies(create_update_inconsistencies,
+                                              delete_inconsistencies)
         self._sync_timer.restart()
 
+        dbg_log_msg = ('Maintenance task: Fixing resource %(res_uuid)s '
+                       '(type: %(res_type)s) at %(type_)s')
         # Fix the create/update resources inconsistencies
         for row in create_update_inconsistencies:
+            LOG.debug(dbg_log_msg, {'res_uuid': row.resource_uuid,
+                                    'res_type': row.resource_type,
+                                    'type_': INCONSISTENCY_TYPE_CREATE_UPDATE})
             try:
                 # NOTE(lucasagomes): The way to fix subnets is bit
                 # different than other resources. A subnet in OVN language
@@ -254,26 +291,29 @@ class DBInconsistenciesPeriodics(object):
                 else:
                     self._fix_create_update(row)
             except Exception:
-                LOG.exception('Failed to fix resource %(res_uuid)s '
-                              '(type: %(res_type)s)',
+                LOG.exception('Maintenance task: Failed to fix resource '
+                              '%(res_uuid)s (type: %(res_type)s)',
                               {'res_uuid': row.resource_uuid,
                                'res_type': row.resource_type})
 
         # Fix the deleted resources inconsistencies
         for row in delete_inconsistencies:
+            LOG.debug(dbg_log_msg, {'res_uuid': row.resource_uuid,
+                                    'res_type': row.resource_type,
+                                    'type_': INCONSISTENCY_TYPE_DELETE})
             try:
                 if row.resource_type == ovn_const.TYPE_SUBNETS:
                     self._ovn_client.delete_subnet(row.resource_uuid)
                 else:
                     self._fix_delete(row)
             except Exception:
-                LOG.exception('Failed to fix deleted resource %(res_uuid)s '
-                              '(type: %(res_type)s)',
+                LOG.exception('Maintenance task: Failed to fix deleted '
+                              'resource %(res_uuid)s (type: %(res_type)s)',
                               {'res_uuid': row.resource_uuid,
                                'res_type': row.resource_type})
 
         self._sync_timer.stop()
-        LOG.info('Maintenance task synchronization finished '
+        LOG.info('Maintenance task: Synchronization finished '
                  '(took %.2f seconds)', self._sync_timer.elapsed())
 
     def _create_lrouter_port(self, port):

networking_ovn/tests/unit/common/test_maintenance.py

@@ -19,6 +19,7 @@ from futurist import periodics
 from neutron.tests.unit.plugins.ml2 import test_security_group as test_sg
 from neutron_lib.db import api as db_api
 
+from networking_ovn.common import config as ovn_config
 from networking_ovn.common import constants
 from networking_ovn.common import maintenance
 from networking_ovn.common import utils
@@ -229,3 +230,41 @@ class TestDBInconsistenciesPeriodics(db_base.DBTestCase,
         l3_mock.add_router_interface.assert_called_once_with(
             mock.ANY, port['device_id'], {'port_id': port['id']},
             may_exist=True)
+
+    @mock.patch.object(maintenance.LOG, 'debug')
+    def test__log_maintenance_inconsistencies(self, mock_log):
+        ovn_config.cfg.CONF.set_override('debug', True)
+
+        # Create fake inconsistencies: 2 networks, 4 subnets and 8 ports
+        incst = []
+        incst += [mock.Mock(resource_type=constants.TYPE_NETWORKS)] * 2
+        incst += [mock.Mock(resource_type=constants.TYPE_SUBNETS)] * 4
+        incst += [mock.Mock(resource_type=constants.TYPE_PORTS)] * 8
+
+        # Create fake inconsistencies for delete: 3 routers and 6 router ports
+        incst_del = []
+        incst_del += [mock.Mock(resource_type=constants.TYPE_ROUTERS)] * 3
+        incst_del += [mock.Mock(resource_type=constants.TYPE_ROUTER_PORTS)] * 6
+
+        self.periodic._log_maintenance_inconsistencies(incst, incst_del)
+
+        # Assert LOG.debug was called twice
+        self.assertEqual(2, len(mock_log.call_args_list))
+
+        # Assert the log matches the number of inconsistencies
+        fail_str_create_update = mock_log.call_args_list[0][0][1]['fail_str']
+        self.assertIn('networks=2', fail_str_create_update)
+        self.assertIn('subnets=4', fail_str_create_update)
+        self.assertIn('ports=8', fail_str_create_update)
+
+        fail_str_delete = mock_log.call_args_list[1][0][1]['fail_str']
+        self.assertIn('routers=3', fail_str_delete)
+        self.assertIn('router_ports=6', fail_str_delete)
+
+    @mock.patch.object(maintenance.LOG, 'debug')
+    def test__log_maintenance_inconsistencies_debug_disabled(self, mock_log):
+        ovn_config.cfg.CONF.set_override('debug', False)
+
+        incst = [mock.Mock(resource_type=constants.TYPE_NETWORKS)] * 2
+        self.periodic._log_maintenance_inconsistencies(incst, [])
+        self.assertFalse(mock_log.called)