Additional logging fixes, primarily in brcm_openomci_onu:

- Fix issues with wrong number of positional parameters to logging calls

- Don't use 'msg' as a key in logging calls as logging uses that
  internally, overwriting the value

- Don't use 'key' as a key in logging calls as kafkaloghandler uses that
  as the kafka key.

Change-Id: I9b4fedaf0cd247ece54570a289e81bbce5247a0e
diff --git a/voltha/adapters/brcm_openomci_onu/brcm_openomci_onu_handler.py b/voltha/adapters/brcm_openomci_onu/brcm_openomci_onu_handler.py
index c96b27a..6453d52 100644
--- a/voltha/adapters/brcm_openomci_onu/brcm_openomci_onu_handler.py
+++ b/voltha/adapters/brcm_openomci_onu/brcm_openomci_onu_handler.py
@@ -578,7 +578,8 @@
                                        field=_field, in_port=_in_port)
                         if _field.type == fd.VLAN_VID:
                             _set_vlan_vid = _field.vlan_vid & 0xfff
-                            self.log.debug('set-field-type-vlan-vid', _set_vlan_vid)
+                            self.log.debug('set-field-type-vlan-vid',
+                                           vlan_vid=_set_vlan_vid)
                         else:
                             self.log.error('unsupported-action-set-field-type',
                                            field_type=_field.type)
@@ -892,7 +893,7 @@
 
                 for entity_id in veip_list:
                     veip_value = config.veip_entities[entity_id]
-                    self.log.debug("discovered-veip", key=entity_id, value=veip_value)
+                    self.log.debug("discovered-veip", entity_id=entity_id, value=veip_value)
 
                 for entity_id in uni_list:
                     uni_value = config.uni_g_entities[entity_id]
@@ -906,7 +907,8 @@
                         self._add_uni_port(entity_id, uni_type=UniType.VEIP)
                         break
                     else:
-                        self.log.warn("unable-to-find-uni-in-pptp-or-veip", key=entity_id, value=uni_value)
+                        self.log.warn("unable-to-find-uni-in-pptp-or-veip",
+                                      entity_id=entity_id, value=uni_value)
 
                 self._qos_flexibility = config.qos_configuration_flexibility or 0
                 self._omcc_version = config.omcc_version or OMCCVersion.Unknown
diff --git a/voltha/adapters/brcm_openomci_onu/omci/brcm_mib_download_task.py b/voltha/adapters/brcm_openomci_onu/omci/brcm_mib_download_task.py
index e597d76..14041a4 100644
--- a/voltha/adapters/brcm_openomci_onu/omci/brcm_mib_download_task.py
+++ b/voltha/adapters/brcm_openomci_onu/omci/brcm_mib_download_task.py
@@ -156,8 +156,10 @@
         failed_mask = omci_msg.get('failed_attributes_mask', 'n/a')
         unsupported_mask = omci_msg.get('unsupported_attributes_mask', 'n/a')
 
-        self.log.debug("OMCI Result:", operation, omci_msg=omci_msg, status=status, error_mask=error_mask,
-                       failed_mask=failed_mask, unsupported_mask=unsupported_mask)
+        self.log.debug("OMCI Result: %s", operation,
+                       omci_msg=omci_msg, status=status,
+                       error_mask=error_mask, failed_mask=failed_mask,
+                       unsupported_mask=unsupported_mask)
 
         if status == RC.Success:
             self.strobe_watchdog()
@@ -231,7 +233,7 @@
                 max_gem_payload_size=self._max_gem_payload
             )
             frame = msg.create()
-            self.log.debug('openomci-msg', msg=msg)
+            self.log.debug('openomci-msg', omci_msg=msg)
             results = yield omci_cc.send(frame)
             self.check_status_and_state(results, 'create-gal-ethernet-profile')
 
@@ -260,7 +262,7 @@
                 attributes
             )
             frame = msg.create()
-            self.log.debug('openomci-msg', msg=msg)
+            self.log.debug('openomci-msg', omci_msg=msg)
             results = yield omci_cc.send(frame)
             self.check_status_and_state(results, 'create-mac-bridge-service-profile')
 
@@ -277,7 +279,7 @@
 
             msg = Ieee8021pMapperServiceProfileFrame(self._ieee_mapper_service_profile_entity_id)
             frame = msg.create()
-            self.log.debug('openomci-msg', msg=msg)
+            self.log.debug('openomci-msg', omci_msg=msg)
             results = yield omci_cc.send(frame)
             self.check_status_and_state(results, 'create-8021p-mapper-service-profile')
 
@@ -305,7 +307,7 @@
                 tp_pointer=self._ieee_mapper_service_profile_entity_id  # TP ID, 8021p mapper ID
             )
             frame = msg.create()
-            self.log.debug('openomci-msg', msg=msg)
+            self.log.debug('openomci-msg', omci_msg=msg)
             results = yield omci_cc.send(frame)
             self.check_status_and_state(results, 'create-mac-bridge-port-configuration-data-part-1')
 
@@ -326,7 +328,7 @@
                 forward_operation=0x10
             )
             frame = msg.create()
-            self.log.debug('openomci-msg', msg=msg)
+            self.log.debug('openomci-msg', omci_msg=msg)
             results = yield omci_cc.send(frame)
             self.check_status_and_state(results, 'create-vlan-tagging-filter-data')
 
@@ -361,7 +363,7 @@
                 tp_pointer=self._uni_port.entity_id  # Ethernet UNI ID
             )
             frame = msg.create()
-            self.log.debug('openomci-msg', msg=msg)
+            self.log.debug('openomci-msg', omci_msg=msg)
             results = yield omci_cc.send(frame)
             self.check_status_and_state(results, 'create-mac-bridge-port-configuration-data-part-2')
 
@@ -470,7 +472,7 @@
                 interwork_tp_pointers=gem_entity_ids  # Interworking TP IDs
             )
             frame = msg.set()
-            self.log.debug('openomci-msg', msg=msg)
+            self.log.debug('openomci-msg', omci_msg=msg)
             results = yield omci_cc.send(frame)
             self.check_status_and_state(results, 'set-8021p-mapper-service-profile')
 
@@ -512,7 +514,7 @@
             )
 
             frame = msg.create()
-            self.log.debug('openomci-msg', msg=msg)
+            self.log.debug('openomci-msg', omci_msg=msg)
             results = yield omci_cc.send(frame)
             self.check_status_and_state(results, 'create-extended-vlan-tagging-operation-configuration-data')
 
@@ -571,7 +573,7 @@
             )
 
             frame = msg.set()
-            self.log.debug('openomci-msg', msg=msg)
+            self.log.debug('openomci-msg', omci_msg=msg)
             results = yield omci_cc.send(frame)
             self.check_status_and_state(results, 'set-extended-vlan-tagging-operation-configuration-data-table')
 
@@ -618,10 +620,10 @@
                 self.log.warn('unknown-uni-type', uni_port=uni_port)
 
             if msg:
-                frame = msg.set()
-                self.log.debug('openomci-msg', msg=msg)
-                results = yield omci_cc.send(frame)
-                self.check_status_and_state(results, 'set-pptp-ethernet-uni-lock-restore')
+               frame = msg.set()
+               self.log.debug('openomci-msg', omci_msg=msg)
+               results = yield omci_cc.send(frame)
+               self.check_status_and_state(results, 'set-pptp-ethernet-uni-lock-restore')
 
         except TimeoutError as e:
             self.log.warn('rx-timeout', e=e)
diff --git a/voltha/adapters/brcm_openomci_onu/omci/brcm_vlan_filter_task.py b/voltha/adapters/brcm_openomci_onu/omci/brcm_vlan_filter_task.py
index 9d22723..cf2e112 100644
--- a/voltha/adapters/brcm_openomci_onu/omci/brcm_vlan_filter_task.py
+++ b/voltha/adapters/brcm_openomci_onu/omci/brcm_vlan_filter_task.py
@@ -200,7 +200,8 @@
         failed_mask = omci_msg.get('failed_attributes_mask', 'n/a')
         unsupported_mask = omci_msg.get('unsupported_attributes_mask', 'n/a')
 
-        self.log.debug("OMCI Result:", operation, omci_msg=omci_msg, status=status, error_mask=error_mask,
+        self.log.debug("OMCI Result: %s", operation, omci_msg=omci_msg,
+                       status=status, error_mask=error_mask,
                        failed_mask=failed_mask, unsupported_mask=unsupported_mask)
 
         if status == RC.Success:
diff --git a/voltha/adapters/brcm_openomci_onu/onu_gem_port.py b/voltha/adapters/brcm_openomci_onu/onu_gem_port.py
index a7403ed..571de78 100644
--- a/voltha/adapters/brcm_openomci_onu/onu_gem_port.py
+++ b/voltha/adapters/brcm_openomci_onu/onu_gem_port.py
@@ -301,7 +301,7 @@
                 attributes=attributes
             )
             frame = msg.create()
-            self.log.debug('openomci-msg', msg=msg)
+            self.log.debug('openomci-msg', omci_msg=msg)
             results = yield omci.send(frame)
             self.check_status_and_state(results, 'create-gem-port-network-ctp')
 
@@ -321,7 +321,7 @@
                 gal_profile_pointer=gal_enet_profile_entity_id
             )
             frame = msg.create()
-            self.log.debug('openomci-msg', msg=msg)
+            self.log.debug('openomci-msg', omci_msg=msg)
             results = yield omci.send(frame)
             self.check_status_and_state(results, 'create-gem-interworking-tp')
 
@@ -339,7 +339,7 @@
         try:
             msg = GemInterworkingTpFrame(self.entity_id)
             frame = msg.delete()
-            self.log.debug('openomci-msg', msg=msg)
+            self.log.debug('openomci-msg', omci_msg=msg)
             results = yield omci.send(frame)
             self.check_status_and_state(results, 'delete-gem-port-network-ctp')
         except Exception as e:
@@ -349,7 +349,7 @@
         try:
             msg = GemPortNetworkCtpFrame(self.entity_id)
             frame = msg.delete()
-            self.log.debug('openomci-msg', msg=msg)
+            self.log.debug('openomci-msg', omci_msg=msg)
             results = yield omci.send(frame)
             self.check_status_and_state(results, 'delete-gem-interworking-tp')
         except Exception as e:
@@ -366,7 +366,8 @@
         failed_mask = omci_msg.get('failed_attributes_mask', 'n/a')
         unsupported_mask = omci_msg.get('unsupported_attributes_mask', 'n/a')
 
-        self.log.debug("OMCI Result:", operation, omci_msg=omci_msg, status=status, error_mask=error_mask,
+        self.log.debug("OMCI Result: %s", operation, omci_msg=omci_msg,
+                       status=status, error_mask=error_mask,
                        failed_mask=failed_mask, unsupported_mask=unsupported_mask)
 
         if status == RC.Success:
diff --git a/voltha/adapters/brcm_openomci_onu/onu_tcont.py b/voltha/adapters/brcm_openomci_onu/onu_tcont.py
index c1f5a89..91c3b36 100644
--- a/voltha/adapters/brcm_openomci_onu/onu_tcont.py
+++ b/voltha/adapters/brcm_openomci_onu/onu_tcont.py
@@ -82,7 +82,7 @@
             #msg = TcontFrame(self.entity_id, self.alloc_id, self.q_sched_policy)
             msg = TcontFrame(self.entity_id, self.alloc_id)
             frame = msg.set()
-            self.log.debug('openomci-msg', msg=msg)
+            self.log.debug('openomci-msg', omci_msg=msg)
             results = yield omci.send(frame)
             self.check_status_and_state(results, 'set-tcont')
 
@@ -103,7 +103,7 @@
         try:
             msg = TcontFrame(self.entity_id, 0xFFFF)
             frame = msg.set()
-            self.log.debug('openomci-msg', msg=msg)
+            self.log.debug('openomci-msg', omci_msg=msg)
             results = yield omci.send(frame)
             self.check_status_and_state(results, 'delete-tcont')
 
@@ -121,7 +121,8 @@
         failed_mask = omci_msg.get('failed_attributes_mask', 'n/a')
         unsupported_mask = omci_msg.get('unsupported_attributes_mask', 'n/a')
 
-        self.log.debug("OMCI Result:", operation, omci_msg=omci_msg, status=status, error_mask=error_mask,
+        self.log.debug("OMCI Result: %s", operation, omci_msg=omci_msg,
+                       status=status, error_mask=error_mask,
                        failed_mask=failed_mask, unsupported_mask=unsupported_mask)
 
         if status == RC.Success:
diff --git a/voltha/coordinator.py b/voltha/coordinator.py
index aaf8f77..61fee26 100644
--- a/voltha/coordinator.py
+++ b/voltha/coordinator.py
@@ -595,7 +595,7 @@
                 log.debug('result-received', result=result)
                 returnValue((False, result))
             except TimeOutError as e:
-                log.debug('timeout-or-no-data-change', key=key)
+                log.debug('timeout-or-no-data-change', consul_key=key)
             except Exception as e:
                 log.exception('exception', e=e)
         except Exception as e:
diff --git a/voltha/coordinator_etcd.py b/voltha/coordinator_etcd.py
index 99baacc..9550744 100644
--- a/voltha/coordinator_etcd.py
+++ b/voltha/coordinator_etcd.py
@@ -612,7 +612,7 @@
                 log.debug('result-received', result=result)
                 returnValue((False, result))
             except TimeOutError as e:
-                log.debug('timeout-or-no-data-change', key=key)
+                log.debug('timeout-or-no-data-change', etcd_key=key)
             except Exception as e:
                 log.exception('exception', e=e)
         except Exception as e:
diff --git a/voltha/extensions/omci/state_machines/performance_intervals.py b/voltha/extensions/omci/state_machines/performance_intervals.py
index 0b8d9c4..73e145b 100644
--- a/voltha/extensions/omci/state_machines/performance_intervals.py
+++ b/voltha/extensions/omci/state_machines/performance_intervals.py
@@ -584,7 +584,8 @@
             class_id = key[0]
             entity_id = key[1]
 
-            self.log.debug("in-enter-collect-data", key=key, retries=self._pm_me_collect_retries[key])
+            self.log.debug("in-enter-collect-data", data_key=key,
+                           retries=self._pm_me_collect_retries[key])
 
             # Collect the data ?
             if self._pm_me_collect_retries[key] > 0:
@@ -606,12 +607,13 @@
 
                 # start the task
                 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])
+                    self.log.debug('collect-extended-info-found', data_key=key,
+                                   extended_info=self._pm_me_extended_info[key])
                     parent_class_id = self._pm_me_extended_info[key][0]
                     parent_entity_id = self._pm_me_extended_info[key][1]
                     upstream = self._pm_me_extended_info[key][2]
                 else:
-                    self.log.debug('collect-extended-info-not-found', key=key)
+                    self.log.debug('collect-extended-info-not-found', data_key=key)
                     parent_class_id = None
                     parent_entity_id = None
                     upstream = None