VOL-1323: Log message cleanup of OpenOMCI code

Change-Id: I4826b5ef80992fb41021ab0092404355f05361a7
diff --git a/voltha/extensions/omci/state_machines/alarm_sync.py b/voltha/extensions/omci/state_machines/alarm_sync.py
index dee6d83..4f4de31 100644
--- a/voltha/extensions/omci/state_machines/alarm_sync.py
+++ b/voltha/extensions/omci/state_machines/alarm_sync.py
@@ -305,7 +305,7 @@
         self._task_deferred.addCallbacks(success, failure)
 
     def reconcile_alarm_table(self, results):
-        self.log.info('alarm-reconcile', state=self.state, results=results)
+        self.log.debug('alarm-reconcile', state=self.state, results=results)
 
         onu_only = results['onu-only']
         olt_only = results['olt-only']
@@ -390,7 +390,7 @@
         :param _topic: (str) OMCI-RX topic
         :param msg: (dict) Dictionary with 'rx-response' and 'tx-request' (if any)
         """
-        self.log.info('on-alarm-update-response', state=self.state, msg=msg)
+        self.log.debug('on-alarm-update-response', state=self.state, msg=msg)
 
         if self._omci_cc_subscriptions[RxEvent.Get_ALARM_Get]:
             if self.state == 'disabled':
@@ -404,7 +404,7 @@
                         isinstance(response.fields.get('omci_message'), OmciGetAllAlarmsResponse):
                     # ONU will reset its last alarm sequence number to 0 on receipt of the
                     # Get All Alarms request
-                    self.log.info('received alarm response')
+                    self.log.debug('received-alarm-response')
                     self.reset_alarm_sequence()
 
             except Exception as e:
@@ -419,7 +419,7 @@
                     TX_REQUEST_KEY  -> None (this is an autonomous msg)
                     RX_RESPONSE_KEY -> OmciMessage (Alarm notification frame)
         """
-        self.log.info('on-alarm-update-response', state=self.state, msg=msg)
+        self.log.debug('on-alarm-update-response', state=self.state, msg=msg)
 
         alarm_msg = msg.get(RX_RESPONSE_KEY)
         if alarm_msg is not None:
diff --git a/voltha/extensions/omci/state_machines/mib_sync.py b/voltha/extensions/omci/state_machines/mib_sync.py
index b63e36b..16f29b2 100644
--- a/voltha/extensions/omci/state_machines/mib_sync.py
+++ b/voltha/extensions/omci/state_machines/mib_sync.py
@@ -170,6 +170,11 @@
                                queued=True,
                                name='{}-{}'.format(self.__class__.__name__,
                                                    device_id))
+        try:
+            import logging
+            logging.getLogger('transitions').setLevel(logging.WARNING)
+        except Exception as e:
+            self.log.exception('log-level-failed', e=e)
 
     def _cancel_deferred(self):
         d1, self._deferred = self._deferred, None
@@ -843,7 +848,7 @@
                         if modified:
                             self.increment_mib_data_sync()
 
-            except KeyError as e:
+            except KeyError as _e:
                 pass            # NOP
             except Exception as e:
                 self.log.exception('set', e=e)
diff --git a/voltha/extensions/omci/state_machines/performance_intervals.py b/voltha/extensions/omci/state_machines/performance_intervals.py
index 8144a56..0b8d9c4 100644
--- a/voltha/extensions/omci/state_machines/performance_intervals.py
+++ b/voltha/extensions/omci/state_machines/performance_intervals.py
@@ -182,6 +182,12 @@
                                ignore_invalid_triggers=True,
                                name='{}-{}'.format(self.__class__.__name__,
                                                    device_id))
+        try:
+            import logging
+            logging.getLogger('transitions').setLevel(logging.WARNING)
+        except Exception as e:
+            self.log.exception('log-level-failed', e=e)
+
 
     def _cancel_deferred(self):
         d1, self._deferred = self._deferred, None
@@ -411,7 +417,7 @@
                         instances[entity_id] = (cid, eid)
 
         except Exception as e:
-            self.log.exception('pm-me-setup', e=e)
+            self.log.exception('pm-me-setup', class_id=class_id, e=e)
 
         # Got to synchronize_time state
         self._deferred = reactor.callLater(0, self.tick)
@@ -562,7 +568,7 @@
         """
 
         if self._next_interval is not None and self._next_interval > datetime.utcnow():
-            self.log.info('wait-next-interval')
+            self.log.debug('wait-next-interval')
             # Not ready for next interval, transition back to idle and we should get
             # called again after a short delay
             reactor.callLater(0, self.success)
@@ -578,14 +584,14 @@
             class_id = key[0]
             entity_id = key[1]
 
-            self.log.info("in-enter-collect-data", key=key, retries=self._pm_me_collect_retries[key])
+            self.log.debug("in-enter-collect-data", key=key, retries=self._pm_me_collect_retries[key])
 
             # Collect the data ?
             if self._pm_me_collect_retries[key] > 0:
                 def success(results):
-                    self.log.info('collect-success', results=results,
-                                  class_id=results.get('class_id'),
-                                  entity_id=results.get('entity_id'))
+                    self.log.debug('collect-success', results=results,
+                                   class_id=results.get('class_id'),
+                                   entity_id=results.get('entity_id'))
                     self._current_task = None
                     self._pm_me_collect_retries[key] = 0
                     self._deferred = reactor.callLater(0, self.success)
@@ -599,8 +605,6 @@
                     return reason   # Halt callback processing
 
                 # start the task
-                self.log.info('collect-task-start')
-
                 if key in self._pm_me_extended_info:
                     self.log.debug('collect-extended-info-found', key=key, extended_info=self._pm_me_extended_info[key])
                     parent_class_id = self._pm_me_extended_info[key][0]
@@ -624,7 +628,7 @@
 
         # Here if all intervals have been collected (we are up to date)
         self._next_interval = self.get_next_interval
-        self.log.info('collect-calculate-next', next=self._next_interval)
+        self.log.debug('collect-calculate-next', next=self._next_interval)
 
         self._pm_me_collect_retries = dict.fromkeys(self._pm_me_collect_retries, self._collect_attempts)
         reactor.callLater(0, self.success)
diff --git a/voltha/extensions/omci/tasks/alarm_resync_task.py b/voltha/extensions/omci/tasks/alarm_resync_task.py
index 1007724..a16f3a2 100644
--- a/voltha/extensions/omci/tasks/alarm_resync_task.py
+++ b/voltha/extensions/omci/tasks/alarm_resync_task.py
@@ -116,7 +116,7 @@
         During the alarm upload process, the maximum time between alarm upload next
         requests is 1 minute.
         """
-        self.log.info('perform-alarm-resync')
+        self.log.debug('perform-alarm-resync')
 
         try:
             self.strobe_watchdog()
diff --git a/voltha/extensions/omci/tasks/get_mds_task.py b/voltha/extensions/omci/tasks/get_mds_task.py
index 325fa1a..1560c83 100644
--- a/voltha/extensions/omci/tasks/get_mds_task.py
+++ b/voltha/extensions/omci/tasks/get_mds_task.py
@@ -75,7 +75,7 @@
         """
         Get the 'mib_data_sync' attribute of the ONU
         """
-        self.log.info('perform-get-mds')
+        self.log.debug('perform-get-mds')
 
         try:
             device = self.omci_agent.get_device(self.device_id)
diff --git a/voltha/extensions/omci/tasks/interval_data_task.py b/voltha/extensions/omci/tasks/interval_data_task.py
index 369f817..d41c1d0 100644
--- a/voltha/extensions/omci/tasks/interval_data_task.py
+++ b/voltha/extensions/omci/tasks/interval_data_task.py
@@ -186,7 +186,8 @@
                     final_results[attribute] = omci_msg['data'].get(attribute)
 
             except TimeoutError as e:
-                self.log.warn('interval-get-timeout', e=e, class_id=self._class_id)
+                self.log.warn('interval-get-timeout', e=e, class_id=self._class_id,
+                              entity_id=self._entity_id, attributes=attributes)
                 self.deferred.errback(failure.Failure(e))
 
             except Exception as e:
diff --git a/voltha/extensions/omci/tasks/mib_resync_task.py b/voltha/extensions/omci/tasks/mib_resync_task.py
index 52cf0b0..ef9c531 100644
--- a/voltha/extensions/omci/tasks/mib_resync_task.py
+++ b/voltha/extensions/omci/tasks/mib_resync_task.py
@@ -122,7 +122,7 @@
         During the mib upload process, the maximum time between mib upload next
         requests is 1 minute.
         """
-        self.log.info('perform-mib-resync')
+        self.log.debug('perform-mib-resync')
 
         try:
             results = yield self.snapshot_mib()
diff --git a/voltha/extensions/omci/tasks/mib_upload.py b/voltha/extensions/omci/tasks/mib_upload.py
index 639f8fd..4afd234 100644
--- a/voltha/extensions/omci/tasks/mib_upload.py
+++ b/voltha/extensions/omci/tasks/mib_upload.py
@@ -85,7 +85,7 @@
         """
         Perform the MIB Upload sequence
         """
-        self.log.info('perform-mib-upload')
+        self.log.debug('perform-mib-upload')
 
         seq_no = 0
         number_of_commands = 0
diff --git a/voltha/extensions/omci/tasks/omci_delete_pm_task.py b/voltha/extensions/omci/tasks/omci_delete_pm_task.py
index 7906a83..adf1ce2 100644
--- a/voltha/extensions/omci/tasks/omci_delete_pm_task.py
+++ b/voltha/extensions/omci/tasks/omci_delete_pm_task.py
@@ -71,7 +71,7 @@
     @inlineCallbacks
     def perform_delete(self):
         """ Perform the delete requests """
-        self.log.info('perform-delete')
+        self.log.debug('perform-delete')
 
         try:
             for me in self._me_tuples:
@@ -90,7 +90,7 @@
                 results = yield self._device.omci_cc.send(frame)
 
                 status = results.fields['omci_message'].fields['success_code']
-                self.log.info('perform-delete-status', status=status)
+                self.log.debug('perform-delete-status', status=status)
 
                 # Did it fail, it instance does not exist, not an error
                 if status != RC.Success.value and status != RC.UnknownInstance.value:
diff --git a/voltha/extensions/omci/tasks/omci_get_request.py b/voltha/extensions/omci/tasks/omci_get_request.py
index 0a5b1ec..45c1db4 100644
--- a/voltha/extensions/omci/tasks/omci_get_request.py
+++ b/voltha/extensions/omci/tasks/omci_get_request.py
@@ -148,7 +148,7 @@
         """
         Perform the initial get request
         """
-        self.log.info('perform-get')
+        self.log.debug('perform-get')
 
         try:
             frame = MEFrame(self._entity_class, self._entity_id, self._attributes).get()
@@ -156,7 +156,7 @@
             results = yield self._device.omci_cc.send(frame)
 
             status = results.fields['omci_message'].fields['success_code']
-            self.log.info('perform-get-status', status=status)
+            self.log.debug('perform-get-status', status=status)
 
             # Success?
             if status == RC.Success.value:
@@ -192,7 +192,7 @@
             else:
                 raise GetException('Get failed with status code: {}'.format(status))
 
-            self.log.info('get-completed')
+            self.log.debug('get-completed')
             self.deferred.callback(self)
 
         except TimeoutError as e:
@@ -215,7 +215,7 @@
 
         :param missing_attr: (set) Missing attributes
         """
-        self.log.info('perform-get-missing', attrs=missing_attr)
+        self.log.debug('perform-get-missing', attrs=missing_attr)
 
         results_omci = self._results.fields['omci_message'].fields
 
@@ -265,7 +265,7 @@
         :param attributes:
         :return:
         """
-        self.log.info('perform-get-failed', attrs=attributes)
+        self.log.debug('perform-get-failed', attrs=attributes)
 
         for attr in attributes:
             try:
@@ -277,7 +277,7 @@
                 status = results.fields['omci_message'].fields['success_code']
 
                 if status == RC.AttributeFailure.value:
-                    self.log.info('unknown-or-invalid-attribute', attr=attr, status=status)
+                    self.log.debug('unknown-or-invalid-attribute', attr=attr, status=status)
                     self._failed_or_unknown_attributes.add(attr)
 
                 elif status != RC.Success.value:
diff --git a/voltha/extensions/omci/tasks/omci_modify_request.py b/voltha/extensions/omci/tasks/omci_modify_request.py
index 27dfb3d..da7bff5 100644
--- a/voltha/extensions/omci/tasks/omci_modify_request.py
+++ b/voltha/extensions/omci/tasks/omci_modify_request.py
@@ -151,14 +151,14 @@
         """
         Perform the request
         """
-        self.log.info('perform-request')
+        self.log.debug('perform-request')
 
         try:
             self.strobe_watchdog()
             self._results = yield self._device.omci_cc.send(self._frame)
 
             status = self._results.fields['omci_message'].fields['success_code']
-            self.log.info('response-status', status=status)
+            self.log.debug('response-status', status=status)
 
             # Success?
             if status in (RC.Success.value, RC.InstanceExists):
diff --git a/voltha/extensions/omci/tasks/onu_capabilities_task.py b/voltha/extensions/omci/tasks/onu_capabilities_task.py
index e93d0ed..048382c 100644
--- a/voltha/extensions/omci/tasks/onu_capabilities_task.py
+++ b/voltha/extensions/omci/tasks/onu_capabilities_task.py
@@ -134,7 +134,7 @@
         Then a loop is entered and get-next commands are sent for each sequence
         requested.
         """
-        self.log.info('perform-get')
+        self.log.debug('perform-get')
 
         try:
             self.strobe_watchdog()
diff --git a/voltha/extensions/omci/tasks/sync_time_task.py b/voltha/extensions/omci/tasks/sync_time_task.py
index 7686cb4..b5b1dc9 100644
--- a/voltha/extensions/omci/tasks/sync_time_task.py
+++ b/voltha/extensions/omci/tasks/sync_time_task.py
@@ -75,7 +75,7 @@
         """
         Sync the time
         """
-        self.log.info('perform-sync-time')
+        self.log.debug('perform-sync-time')
 
         try:
             device = self.omci_agent.get_device(self.device_id)