Clean up service/provider logging (#284)

* Enhance Codec logging

Codec service logging now shows where the encode/decode operation
starts and where it is completed.  Also, the codec provider doesn't
log an identity (object) any more.  Logging the object reference wasn't
particularly informative.

* Enhance CRUD service logging

CRUD service logging now shows where an operation starts and where it is
completed.

* Enhance executor service logging

Executor service logging now shows where an execute_rpc operation starts
and where it is completed.

* Rename executor service logger

Executor service now uses module name for the logger (__name__).  Naming
is consistent with the logger for the other services.

* Use module as the logger name

Brings consistency to logger names.  All loggers now use the Python
module name (__name__).

* Fix NETCONF disconnect log message

Disconnect message doesn't show port as 'None' when the default port
(830) is being used.  If port is left unspecified when the session is
opened, logging doesn't try to specify the port explicitly when
disconnecting.

sdk/python/core/ydk/providers/_decoder.py

@@ -193,7 +193,7 @@ def _to_real_union_type_helper(cls, rt, member, entity):
                     float(rt[0].text)
                     return Decimal64(rt[0].text)
                 except ValueError:
-                    ydk_logger = logging.getLogger('ydk.providers.NetconfServiceProvider')
+                    ydk_logger = logging.getLogger(__name__)
                     ydk_logger.error('Got a ValueError converting a Decimal64 type to float')
                 pass
             elif contained_member.ptype == 'Empty' and rt[0].text is None:
@@ -217,7 +217,7 @@ def _bind_to_enum_helper(elem, member):
         meta_info = enum_clazz._meta_info()
         enum_literal_key = elem.text
         if enum_literal_key not in meta_info.literal_map:
-            sp_logger = logging.getLogger('ydk.providers.NetconfServiceProvider')
+            sp_logger = logging.getLogger(__name__)
             values = ','.join(meta_info.literal_map)
             sp_logger.error('Cannot find enum literal with name %s in enum clazz %s(%s) trying with different case',
                             enum_literal_key, member.clazz_name, values)
@@ -254,7 +254,7 @@ def _bind_to_identity_helper(elem, member, entity):
         py_mod_name = None
         if not (identity_mod_name, identity_name) in _yang_ns._identity_map:
             # this is a hack on some platforms the identity mod_name is not available
-            sp_logger = logging.getLogger('ydk.providers.NetconfServiceProvider')
+            sp_logger = logging.getLogger(__name__)
             sp_logger.error('Could not find identity tuple (%s, %s) in identity_map, trying secondary mechanism', identity_mod_name, identity_name)
             identities_with_name = [(x, y) for (x, y) in _yang_ns._identity_map if y == identity_name]
             if len(identities_with_name) == 0:

sdk/python/core/ydk/providers/_provider_plugin.py

@@ -104,7 +104,7 @@ def __init__(self, timeout, use_native_client):
             self.ydk_client = None
         else:
             self._nc_manager = None
-        self.netconf_sp_logger = logging.getLogger('ydk.providers.NetconfServiceProvider')
+        self.netconf_sp_logger = logging.getLogger(__name__)
         self.timeout = timeout
 
     def encode(self, entity, operation, only_config):

sdk/python/core/ydk/providers/_validator.py

@@ -236,7 +236,7 @@ def _validate_number(meta, value, parent, errors):
     return value
 
 def _handle_error(meta, parent, errors, errmsg=None, errcode=None):
-    services_logger = logging.getLogger('ydk.providers.NetconfServiceProvider')
+    services_logger = logging.getLogger(__name__)
     path = '%s.%s' % (parent.i_meta.name, meta.presentation_name)
 
     if errcode is None:

sdk/python/core/ydk/providers/_value_encoder.py

@@ -82,6 +82,6 @@ def encode(self, member, NSMAP, value):
         elif member.ptype == 'int' and isinstance(value, (int, long)):
             text = str(value)
         else:
-            ydk_logger = logging.getLogger('ydk.providers.NetconfServiceProvider')
+            ydk_logger = logging.getLogger(__name__)
             ydk_logger.info('Could not encode leaf {0}, type: {1}, {2} value: {3}'.format(member.name, member.mtype, member.ptype, value))
         return text

sdk/python/core/ydk/providers/codec_provider.py

@@ -55,7 +55,6 @@ def __init__(self, **kwargs):
 
     def _encode(self, entity):
         """ Encodes the entity into the desired encoding format """
-        self.logger.info('Encoding object: \n{0}'.format(entity))
         payload = self.encoder.encode(entity)
         self.logger.info('Result of encoding: \n{0}'.format(payload))
         return payload

sdk/python/core/ydk/providers/native_netconf_provider.py

@@ -77,8 +77,12 @@ def _connect(self):
     def close(self):
         """ Closes the netconf session """
         self.sp_instance.disconnect()
-        self.netconf_sp_logger.info('NativeNetconfServiceProvider disconnected from %s:%s using %s'
-                               % (self.address, self.port, self.protocol))
+        if self.port is not None:
+            self.netconf_sp_logger.info('NativeNetconfServiceProvider disconnected from %s:%s using %s'
+                                        % (self.address, self.port, self.protocol))
+        else:
+            self.netconf_sp_logger.info('NativeNetconfServiceProvider disconnected from %s using %s'
+                                        % (self.address, self.protocol))
 
     def encode(self, entity, operation, only_config=False):
         return self.sp_instance.encode(entity, operation, only_config)

sdk/python/core/ydk/providers/netconf_provider.py

@@ -77,8 +77,12 @@ def _connect(self):
     def close(self):
         """ Closes the netconf session """
         self.sp_instance.disconnect()
-        self.netconf_sp_logger.info('\nNetconfServiceProvider disconnected from %s:%s using %s'
-                               % (self.address, self.port, self.protocol))
+        if self.port is not None:
+            self.netconf_sp_logger.info('NetconfServiceProvider disconnected from %s:%s using %s'
+                                        % (self.address, self.port, self.protocol))
+        else:
+            self.netconf_sp_logger.info('NetconfServiceProvider disconnected from %s using %s'
+                                        % (self.address, self.protocol))
 
     def encode(self, entity, operation, only_config=False):
         return self.sp_instance.encode(entity, operation, only_config)

sdk/python/core/ydk/services/codec_service.py

@@ -36,16 +36,18 @@ def encode(self, encoder, entity):
         if None in (encoder, entity):
             msg = "'encoder' and 'entity' cannot be None"
             raise YPYServiceError(error_msg=msg)
+        self.service_logger.info('Encoding operation initiated')
         payload = self.operate_on_object_or_dictionary(entity, CodecService._encode_entity, [encoder])
-        self.service_logger.info('Encoding operation completed\n')
+        self.service_logger.info('Encoding operation completed')
         return payload
 
     def decode(self, decoder, payload):
         if None in (decoder, payload):
             msg = "'decoder' and 'payload' cannot be None"
             raise YPYServiceError(error_msg=msg)
+        self.service_logger.info('Decoding operation initiated')
         entity = self.operate_on_object_or_dictionary(payload, CodecService._decode_payload, [decoder])
-        self.service_logger.info('Decoding operation completed\n')
+        self.service_logger.info('Decoding operation completed')
         return entity
 
     @staticmethod

sdk/python/core/ydk/services/crud_service.py

@@ -157,6 +157,7 @@ def _execute_crud_operation_on_provider(self, provider, entity, operation, only_
             err_msg = "'provider', 'entity', 'operation', and 'only_config' cannot be None"
             raise YPYServiceError(error_msg=err_msg)
         try:
+            self.service_logger.info('{0} operation initiated'.format(operation))
             return self.execute_payload(
                                         provider,
                                         provider.encode(

sdk/python/core/ydk/services/executor_service.py

@@ -28,7 +28,7 @@
 class ExecutorService(Service):
     """ Executor Service class for executing RPCs containing entities """
     def __init__(self):
-        self.service_logger = logging.getLogger('ydk.services.NetconfService')
+        self.service_logger = logging.getLogger(__name__)
 
     def execute_rpc(self, provider, rpc):
         """ Execute the RPC
@@ -52,9 +52,10 @@ def execute_rpc(self, provider, rpc):
             raise YPYServiceError(error_msg=err_msg)
         try:
             rpc = MetaService.normalize_meta(provider._get_capabilities(), rpc)
+            self.service_logger.info('Executor operation initiated')
             return provider.execute(
                                     provider.sp_instance.encode_rpc(rpc),
                                     ''
                                     )
         finally:
-            self.service_logger.info('Netconf operation completed')
+            self.service_logger.info('Executor operation completed')