Update logging in Python to use module-level logger

All logging in Python so far was done with the root logger, resulting
in logs like: `ERROR:Exception calling application:`. With module-level
loggers, the logs will instead include the module in which the
exception is raised: `ERROR:grpc._server:Exception calling application:`

src/python/grpcio/grpc/_channel.py

@@ -24,6 +24,8 @@ from grpc import _grpcio_metadata
 from grpc._cython import cygrpc
 from grpc.framework.foundation import callable_util
 
+_LOGGER = logging.getLogger(__name__)
+
 _USER_AGENT = 'grpc-python/{}'.format(_grpcio_metadata.__version__)
 
 _EMPTY_FLAGS = 0
@@ -181,7 +183,7 @@ def _consume_request_iterator(request_iterator, state, call, request_serializer,
             except Exception:  # pylint: disable=broad-except
                 code = grpc.StatusCode.UNKNOWN
                 details = 'Exception iterating requests!'
-                logging.exception(details)
+                _LOGGER.exception(details)
                 call.cancel(_common.STATUS_CODE_TO_CYGRPC_STATUS_CODE[code],
                             details)
                 _abort(state, code, details)

src/python/grpcio/grpc/_common.py

@@ -20,6 +20,8 @@ import six
 import grpc
 from grpc._cython import cygrpc
 
+_LOGGER = logging.getLogger(__name__)
+
 CYGRPC_CONNECTIVITY_STATE_TO_CHANNEL_CONNECTIVITY = {
     cygrpc.ConnectivityState.idle:
     grpc.ChannelConnectivity.IDLE,
@@ -73,7 +75,7 @@ def decode(b):
         try:
             return b.decode('utf8')
         except UnicodeDecodeError:
-            logging.exception('Invalid encoding on %s', b)
+            _LOGGER.exception('Invalid encoding on %s', b)
             return b.decode('latin1')
 
 
@@ -84,7 +86,7 @@ def _transform(message, transformer, exception_message):
         try:
             return transformer(message)
         except Exception:  # pylint: disable=broad-except
-            logging.exception(exception_message)
+            _LOGGER.exception(exception_message)
             return None
 
 

src/python/grpcio/grpc/_cython/_cygrpc/grpc_string.pyx.pxi

@@ -14,6 +14,7 @@
 
 import logging
 
+_LOGGER = logging.getLogger(__name__)
 
 # This function will ascii encode unicode string inputs if neccesary.
 # In Python3, unicode strings are the default str type.
@@ -49,5 +50,5 @@ cdef str _decode(bytes bytestring):
         try:
             return bytestring.decode('utf8')
         except UnicodeDecodeError:
-            logging.exception('Invalid encoding on %s', bytestring)
+            _LOGGER.exception('Invalid encoding on %s', bytestring)
             return bytestring.decode('latin1')

src/python/grpcio/grpc/_cython/_cygrpc/server.pyx.pxi

@@ -18,6 +18,8 @@ import logging
 import time
 import grpc
 
+_LOGGER = logging.getLogger(__name__)
+
 cdef grpc_ssl_certificate_config_reload_status _server_cert_config_fetcher_wrapper(
         void* user_data, grpc_ssl_server_certificate_config **config) with gil:
   # This is a credentials.ServerCertificateConfig
@@ -34,13 +36,13 @@ cdef grpc_ssl_certificate_config_reload_status _server_cert_config_fetcher_wrapp
     try:
       cert_config_wrapper = user_cb()
     except Exception:
-      logging.exception('Error fetching certificate config')
+      _LOGGER.exception('Error fetching certificate config')
       return GRPC_SSL_CERTIFICATE_CONFIG_RELOAD_FAIL
     if cert_config_wrapper is None:
       return GRPC_SSL_CERTIFICATE_CONFIG_RELOAD_UNCHANGED
     elif not isinstance(
         cert_config_wrapper, grpc.ServerCertificateConfiguration):
-      logging.error(
+      _LOGGER.error(
           'Error fetching certificate configuration: certificate '
           'configuration must be of type grpc.ServerCertificateConfiguration, '
           'not %s' % type(cert_config_wrapper).__name__)

src/python/grpcio/grpc/_plugin_wrapping.py

@@ -20,6 +20,8 @@ import grpc
 from grpc import _common
 from grpc._cython import cygrpc
 
+_LOGGER = logging.getLogger(__name__)
+
 
 class _AuthMetadataContext(
         collections.namedtuple('AuthMetadataContext', (
@@ -76,7 +78,7 @@ class _Plugin(object):
                                   _AuthMetadataPluginCallback(
                                       callback_state, callback))
         except Exception as exception:  # pylint: disable=broad-except
-            logging.exception(
+            _LOGGER.exception(
                 'AuthMetadataPluginCallback "%s" raised exception!',
                 self._metadata_plugin)
             with callback_state.lock:

src/python/grpcio/grpc/_server.py

@@ -27,6 +27,8 @@ from grpc import _interceptor
 from grpc._cython import cygrpc
 from grpc.framework.foundation import callable_util
 
+_LOGGER = logging.getLogger(__name__)
+
 _SHUTDOWN_TAG = 'shutdown'
 _REQUEST_CALL_TAG = 'request_call'
 
@@ -279,7 +281,7 @@ class _Context(grpc.ServicerContext):
     def abort(self, code, details):
         # treat OK like other invalid arguments: fail the RPC
         if code == grpc.StatusCode.OK:
-            logging.error(
+            _LOGGER.error(
                 'abort() called with StatusCode.OK; returning UNKNOWN')
             code = grpc.StatusCode.UNKNOWN
             details = ''
@@ -390,7 +392,7 @@ def _call_behavior(rpc_event, state, behavior, argument, request_deserializer):
                        b'RPC Aborted')
             elif exception not in state.rpc_errors:
                 details = 'Exception calling application: {}'.format(exception)
-                logging.exception(details)
+                _LOGGER.exception(details)
                 _abort(state, rpc_event.call, cygrpc.StatusCode.unknown,
                        _common.encode(details))
         return None, False
@@ -408,7 +410,7 @@ def _take_response_from_response_iterator(rpc_event, state, response_iterator):
                        b'RPC Aborted')
             elif exception not in state.rpc_errors:
                 details = 'Exception iterating responses: {}'.format(exception)
-                logging.exception(details)
+                _LOGGER.exception(details)
                 _abort(state, rpc_event.call, cygrpc.StatusCode.unknown,
                        _common.encode(details))
         return None, False
@@ -617,7 +619,7 @@ def _handle_call(rpc_event, generic_handlers, interceptor_pipeline, thread_pool,
                                                   interceptor_pipeline)
         except Exception as exception:  # pylint: disable=broad-except
             details = 'Exception servicing handler: {}'.format(exception)
-            logging.exception(details)
+            _LOGGER.exception(details)
             return _reject_rpc(rpc_event, cygrpc.StatusCode.unknown,
                                b'Error in service handler!'), None
         if method_handler is None:

src/python/grpcio/grpc/framework/foundation/callable_util.py

@@ -21,6 +21,8 @@ import logging
 
 import six
 
+_LOGGER = logging.getLogger(__name__)
+
 
 class Outcome(six.with_metaclass(abc.ABCMeta)):
     """A sum type describing the outcome of some call.
@@ -53,7 +55,7 @@ def _call_logging_exceptions(behavior, message, *args, **kwargs):
         return _EasyOutcome(Outcome.Kind.RETURNED, behavior(*args, **kwargs),
                             None)
     except Exception as e:  # pylint: disable=broad-except
-        logging.exception(message)
+        _LOGGER.exception(message)
         return _EasyOutcome(Outcome.Kind.RAISED, None, e)
 
 

src/python/grpcio/grpc/framework/foundation/logging_pool.py

@@ -17,6 +17,8 @@ import logging
 
 from concurrent import futures
 
+_LOGGER = logging.getLogger(__name__)
+
 
 def _wrap(behavior):
     """Wraps an arbitrary callable behavior in exception-logging."""
@@ -25,7 +27,7 @@ def _wrap(behavior):
         try:
             return behavior(*args, **kwargs)
         except Exception:
-            logging.exception(
+            _LOGGER.exception(
                 'Unexpected exception from %s executed in logging pool!',
                 behavior)
             raise

src/python/grpcio/grpc/framework/foundation/stream_util.py

@@ -19,6 +19,7 @@ import threading
 from grpc.framework.foundation import stream
 
 _NO_VALUE = object()
+_LOGGER = logging.getLogger(__name__)
 
 
 class TransformingConsumer(stream.Consumer):
@@ -103,7 +104,7 @@ class ThreadSwitchingConsumer(stream.Consumer):
                 else:
                     sink.consume(value)
             except Exception as e:  # pylint:disable=broad-except
-                logging.exception(e)
+                _LOGGER.exception(e)
 
             with self._lock:
                 if terminate:

src/python/grpcio_testing/grpc_testing/_channel/_invocation.py

@@ -18,6 +18,7 @@ import threading
 import grpc
 
 _NOT_YET_OBSERVED = object()
+_LOGGER = logging.getLogger(__name__)
 
 
 def _cancel(handler):
@@ -248,7 +249,7 @@ def consume_requests(request_iterator, handler):
                 break
             except Exception:  # pylint: disable=broad-except
                 details = 'Exception iterating requests!'
-                logging.exception(details)
+                _LOGGER.exception(details)
                 handler.cancel(grpc.StatusCode.UNKNOWN, details)
 
     consumption = threading.Thread(target=_consume)

src/python/grpcio_testing/grpc_testing/_server/_rpc.py

@@ -18,6 +18,8 @@ import threading
 import grpc
 from grpc_testing import _common
 
+_LOGGER = logging.getLogger(__name__)
+
 
 class Rpc(object):
 
@@ -47,7 +49,7 @@ class Rpc(object):
                 try:
                     callback()
                 except Exception:  # pylint: disable=broad-except
-                    logging.exception('Exception calling server-side callback!')
+                    _LOGGER.exception('Exception calling server-side callback!')
 
         callback_calling_thread = threading.Thread(target=call_back)
         callback_calling_thread.start()
@@ -86,7 +88,7 @@ class Rpc(object):
     def application_exception_abort(self, exception):
         with self._condition:
             if exception not in self._rpc_errors:
-                logging.exception('Exception calling application!')
+                _LOGGER.exception('Exception calling application!')
                 self._abort(
                     grpc.StatusCode.UNKNOWN,
                     'Exception calling application: {}'.format(exception))

src/python/grpcio_testing/grpc_testing/_time.py

@@ -21,13 +21,15 @@ import time as _time
 import grpc
 import grpc_testing
 
+_LOGGER = logging.getLogger(__name__)
+
 
 def _call(behaviors):
     for behavior in behaviors:
         try:
             behavior()
         except Exception:  # pylint: disable=broad-except
-            logging.exception('Exception calling behavior "%r"!', behavior)
+            _LOGGER.exception('Exception calling behavior "%r"!', behavior)
 
 
 def _call_in_thread(behaviors):

src/python/grpcio_tests/tests/interop/server.py

@@ -26,6 +26,7 @@ from tests.interop import resources
 from tests.unit import test_common
 
 _ONE_DAY_IN_SECONDS = 60 * 60 * 24
+_LOGGER = logging.getLogger(__name__)
 
 
 def serve():
@@ -52,14 +53,14 @@ def serve():
         server.add_insecure_port('[::]:{}'.format(args.port))
 
     server.start()
-    logging.info('Server serving.')
+    _LOGGER.info('Server serving.')
     try:
         while True:
             time.sleep(_ONE_DAY_IN_SECONDS)
     except BaseException as e:
-        logging.info('Caught exception "%s"; stopping server...', e)
+        _LOGGER.info('Caught exception "%s"; stopping server...', e)
         server.stop(None)
-        logging.info('Server stopped; exiting.')
+        _LOGGER.info('Server stopped; exiting.')
 
 
 if __name__ == '__main__':